logging cleanup (#20502)

* switch some uploader messages to debug log

* use allow_sleep

* log when not request or response

* test both with params and without params

common/logging_extra.py

@@ -158,6 +158,8 @@ class SwagLogger(logging.Logger):
     evt.update(kwargs)
     if 'error' in kwargs:
       self.error(evt)
+    if 'debug' in kwargs:
+      self.debug(evt)
     else:
       self.info(evt)
 

selfdrive/athena/athenad.py

@@ -82,6 +82,8 @@ def jsonrpc_handler(end_event):
         send_queue.put_nowait(response.json)
       elif "result" in data and "id" in data:
         log_recv_queue.put_nowait(data)
+      else:
+        raise Exception("not a valid request or response")
     except queue.Empty:
       pass
     except Exception as e:

selfdrive/athena/tests/test_athenad.py

@@ -180,10 +180,15 @@ class TestAthenadMethods(unittest.TestCase):
     thread.daemon = True
     thread.start()
     try:
+      # with params
       athenad.recv_queue.put_nowait(json.dumps({"method": "echo", "params": ["hello"], "jsonrpc": "2.0", "id": 0}))
       resp = athenad.send_queue.get(timeout=3)
       self.assertDictEqual(json.loads(resp), {'result': 'hello', 'id': 0, 'jsonrpc': '2.0'})
-
+      # without params
+      athenad.recv_queue.put_nowait(json.dumps({"method": "getNetworkType", "jsonrpc": "2.0", "id": 0}))
+      resp = athenad.send_queue.get(timeout=3)
+      self.assertDictEqual(json.loads(resp), {'result': 1, 'id': 0, 'jsonrpc': '2.0'})
+      # log forwarding
       athenad.recv_queue.put_nowait(json.dumps({'result': {'success': 1}, 'id': 0, 'jsonrpc': '2.0'}))
       resp = athenad.log_recv_queue.get(timeout=3)
       self.assertDictEqual(json.loads(resp), {'result': {'success': 1}, 'id': 0, 'jsonrpc': '2.0'})

selfdrive/loggerd/uploader.py

@@ -127,10 +127,10 @@ class Uploader():
       url_resp_json = json.loads(url_resp.text)
       url = url_resp_json['url']
       headers = url_resp_json['headers']
-      cloudlog.info("upload_url v1.3 %s %s", url, str(headers))
+      cloudlog.debug("upload_url v1.3 %s %s", url, str(headers))
 
       if fake_upload:
-        cloudlog.info("*** WARNING, THIS IS A FAKE UPLOAD TO %s ***" % url)
+        cloudlog.debug("*** WARNING, THIS IS A FAKE UPLOAD TO %s ***" % url)
 
         class FakeResponse():
           def __init__(self):
@@ -164,7 +164,7 @@ class Uploader():
 
     cloudlog.event("upload", key=key, fn=fn, sz=sz)
 
-    cloudlog.info("checking %r with size %r", key, sz)
+    cloudlog.debug("checking %r with size %r", key, sz)
 
     if sz == 0:
       try:
@@ -174,10 +174,10 @@ class Uploader():
         cloudlog.event("uploader_setxattr_failed", exc=self.last_exc, key=key, fn=fn, sz=sz)
       success = True
     else:
-      cloudlog.info("uploading %r", fn)
+      cloudlog.debug("uploading %r", fn)
       stat = self.normal_upload(key, fn)
       if stat is not None and stat.status_code in (200, 201, 412):
-        cloudlog.event("upload_success" if stat.status_code != 412 else "upload_ignored", key=key, fn=fn, sz=sz)
+        cloudlog.event("upload_success" if stat.status_code != 412 else "upload_ignored", key=key, fn=fn, sz=sz, debug=True)
         try:
           # tag file as uploaded
           setxattr(fn, UPLOAD_ATTR_NAME, UPLOAD_ATTR_VALUE)
@@ -185,14 +185,12 @@ class Uploader():
           cloudlog.event("uploader_setxattr_failed", exc=self.last_exc, key=key, fn=fn, sz=sz)
         success = True
       else:
-        cloudlog.event("upload_failed", stat=stat, exc=self.last_exc, key=key, fn=fn, sz=sz)
+        cloudlog.event("upload_failed", stat=stat, exc=self.last_exc, key=key, fn=fn, sz=sz, debug=True)
         success = False
 
     return success
 
 def uploader_fn(exit_event):
-  cloudlog.info("uploader_fn")
-
   params = Params()
   dongle_id = params.get("DongleId").decode('utf8')
 
@@ -209,8 +207,14 @@ def uploader_fn(exit_event):
   backoff = 0.1
   while not exit_event.is_set():
     sm.update(0)
-    on_wifi = force_wifi or sm['deviceState'].networkType == NetworkType.wifi
     offroad = params.get("IsOffroad") == b'1'
+    network_type = sm['deviceState'].networkType if not force_wifi else NetworkType.wifi
+    if network_type == NetworkType.none:
+      if allow_sleep:
+        time.sleep(60 if offroad else 5)
+      continue
+
+    on_wifi = network_type == NetworkType.wifi
     allow_raw_upload = params.get("IsUploadRawEnabled") != b"0"
 
     d = uploader.next_file_to_upload(with_raw=allow_raw_upload and on_wifi and offroad)
@@ -221,13 +225,12 @@ def uploader_fn(exit_event):
 
     key, fn = d
 
-    cloudlog.event("uploader_netcheck", is_on_wifi=on_wifi)
+    cloudlog.debug("upload %r over %s", d, network_type)
-    cloudlog.info("to upload %r", d)
     success = uploader.upload(key, fn)
     if success:
       backoff = 0.1
     elif allow_sleep:
-      cloudlog.info("backoff %r", backoff)
+      cloudlog.info("upload backoff %r", backoff)
       time.sleep(backoff + random.uniform(0, backoff))
       backoff = min(backoff*2, 120)
     cloudlog.info("upload done, success=%r", success)