DNM lava_callback: improve logging

Signed-off-by: Arnaud Ferraris <[email protected]>

Author: a-wai

src/lava_callback.py

@@ -40,6 +40,9 @@
 app = FastAPI()
 executor = ThreadPoolExecutor(max_workers=16)
 
+logger = logging.getLogger('uvicorn.error')
+logger.setLevel(logging.DEBUG)
+
 
 class ManualCheckout(BaseModel):
     commit: str
@@ -200,7 +203,7 @@ def async_job_submit(api_helper, node_id, job_callback):
     job_node = api_helper.api.node.get(node_id)
     if not job_node:
         metrics.add('lava_callback_late_fail_total', 1)
-        logging.error(f'Node {node_id} not found')
+        logger.error(f'Node {node_id} not found')
         return
     # TODO: Verify lab_name matches job node lab name
     # Also extract job_id and compare with node job_id (future)
@@ -215,14 +218,14 @@ def async_job_submit(api_helper, node_id, job_callback):
     log_txt_url = _upload_log(log_parser, job_node, storage)
     if log_txt_url:
         job_node['artifacts']['lava_log'] = log_txt_url
-        print(f"Log uploaded to {log_txt_url}")
+        logger.debug(f"Log uploaded to {log_txt_url}")
     else:
-        print("Failed to upload log")
+        logger.info("Failed to upload log")
         metrics.add('lava_callback_late_fail_total', 1)
     callback_json_url = _upload_callback_data(callback_data, job_node, storage)
     if callback_json_url:
         job_node['artifacts']['callback_data'] = callback_json_url
-        print(f"Callback data uploaded to {callback_json_url}")
+        logger.debug(f"Callback data uploaded to {callback_json_url}")
     else:
         metrics.add('lava_callback_late_fail_total', 1)
     # failed LAVA job should have result set to 'incomplete'
@@ -234,14 +237,15 @@ def async_job_submit(api_helper, node_id, job_callback):
     if device_id:
         job_node['data']['device'] = device_id
     # add artifacts uploaded from the running LAVA job
+    logger.debug(f"Results: {results}")
     for result in results.keys():
         if result.startswith("artifact-upload:"):
             artifact = result.split(':', 2)
             if len(artifact) != 3:
-                print(f"Failed to extract artifact name and URL from {result}")
+                logger.info(f"Failed to extract artifact name and URL from {result}")
                 continue
             job_node['artifacts'][artifact[1]] = artifact[2]
-            print(f"Artifact {artifact[1]} added with URL {artifact[2]}")
+            logger.debug(f"Artifact {artifact[1]} added with URL {artifact[2]}")
     hierarchy = job_callback.get_hierarchy(results, job_node)
     api_helper.submit_results(hierarchy, job_node)
 
@@ -291,7 +295,7 @@ async def callback(node_id: str, request: Request):
     try:
         data = await request.json()
     except Exception as e:
-        logging.error(f'Error decoding JSON: {e}')
+        logger.error(f'Error decoding JSON: {e}')
         item = {}
         item['message'] = 'Error decoding JSON'
         return JSONResponse(content=item, status_code=400)
@@ -315,7 +319,7 @@ def decode_jwt(jwtstr):
     '''
     secret = SETTINGS.get('jwt', {}).get('secret')
     if not secret:
-        logging.error('No JWT secret configured')
+        logger.error('No JWT secret configured')
         return None
     return jwt.decode(jwtstr, secret, algorithms=['HS256'])
 
@@ -326,17 +330,17 @@ def validate_permissions(jwtoken, permission):
     try:
         decoded = decode_jwt(jwtoken)
     except Exception as e:
-        logging.error(f'Error decoding JWT: {e}')
+        logger.error(f'Error decoding JWT: {e}')
         return False
     if not decoded:
-        logging.error('Invalid JWT')
+        logger.error('Invalid JWT')
         return False
     permissions = decoded.get('permissions')
     if not permissions:
-        logging.error('No permissions in JWT')
+        logger.error('No permissions in JWT')
         return False
     if permission not in permissions:
-        logging.error(f'Permission {permission} not in JWT')
+        logger.error(f'Permission {permission} not in JWT')
         return False
     return decoded
 
@@ -397,7 +401,7 @@ async def jobretry(data: JobRetry, request: Request,
         return JSONResponse(content=item, status_code=401)
 
     email = decoded.get('email')
-    logging.info(f"User {email} is retrying job {data.nodeid}")
+    logger.info(f"User {email} is retrying job {data.nodeid}")
     api_config_name = SETTINGS.get('DEFAULT', {}).get('api_config')
     if not api_config_name:
         item['message'] = 'No default API name set'
@@ -407,7 +411,7 @@ async def jobretry(data: JobRetry, request: Request,
     try:
         node = api_helper.api.node.get(data.nodeid)
     except Exception as e:
-        logging.error(f'Error getting node {data.nodeid}: {e}')
+        logger.error(f'Error getting node {data.nodeid}: {e}')
         item['message'] = 'Error getting node'
         return JSONResponse(content=item, status_code=500)
     if not node:
@@ -446,7 +450,7 @@ async def jobretry(data: JobRetry, request: Request,
     evnode = {'data': knode}
     # Now we can submit custom kbuild node to the API(pub/sub)
     api_helper.api.send_event('node', evnode)
-    logging.info(f"Job retry for node {data.nodeid} submitted")
+    logger.info(f"Job retry for node {data.nodeid} submitted")
     item['message'] = 'OK'
     return JSONResponse(content=item, status_code=200)
 
@@ -533,7 +537,7 @@ async def checkout(data: ManualCheckout, request: Request,
         item['message'] = 'Unauthorized'
         return JSONResponse(content=item, status_code=401)
 
-    logging.info(f"User {email} is checking out {data.nodeid} at custom commit {data.commit}")
+    logger.info(f"User {email} is checking out {data.nodeid} at custom commit {data.commit}")
     api_config_name = SETTINGS.get('DEFAULT', {}).get('api_config')
     if not api_config_name:
         item['message'] = 'No default API name set'
@@ -639,7 +643,7 @@ async def checkout(data: ManualCheckout, request: Request,
         item['message'] = 'Failed to submit checkout node'
         return JSONResponse(content=item, status_code=500)
     else:
-        logging.info(f"Checkout node {r['id']} submitted")
+        logger.info(f"Checkout node {r['id']} submitted")
         item['message'] = 'OK'
         item['node'] = r
         return JSONResponse(content=item, status_code=200)
@@ -668,7 +672,7 @@ async def patchset(data: PatchSet, request: Request,
         item['message'] = 'Unauthorized'
         return JSONResponse(content=item, status_code=401)
 
-    logging.info(f"User {email} is testing patchset on {data.nodeid}")
+    logger.info(f"User {email} is testing patchset on {data.nodeid}")
     api_config_name = SETTINGS.get('DEFAULT', {}).get('api_config')
     if not api_config_name:
         item['message'] = 'No default API name set'
@@ -742,7 +746,7 @@ async def patchset(data: PatchSet, request: Request,
         item['message'] = 'Failed to submit patchset node'
         return JSONResponse(content=item, status_code=500)
     else:
-        logging.info(f"Patchset node {r['id']} submitted")
+        logger.info(f"Patchset node {r['id']} submitted")
         item['message'] = 'OK'
         item['node'] = r
         return JSONResponse(content=item, status_code=200)