Ref #817 - Include celery task info in all logs to aid tracing (#828)

Author: mxsasha

checks/tasks/__init__.py

@@ -11,6 +11,7 @@
 
 import unbound
 from internetnl import log
+from timeit import default_timer as timer
 
 
 class SetupUnboundContext(Task):
@@ -114,11 +115,14 @@ def callback(self, data, status, result):
                 data["rcode"] = result.rcode
         data["done"] = True
 
-    def get(self, *args, **kwargs):
+    def get(self, url, *args, **kwargs):
         """
         Perform a HTTP GET request using the stored session
         """
+        start_time = timer()
         if not hasattr(self, "_requests_session"):
             self._requests_session = requests.session()
 
-        return self._requests_session.get(*args, **kwargs)
+        response = self._requests_session.get(url, *args, **kwargs)
+        log.debug(f"HTTP request completed in {timer()-start_time:.06f}s: {url}")
+        return response

checks/tasks/cipher_info.py

@@ -1,15 +1,15 @@
-import logging
 import re
 from collections import OrderedDict
 from enum import Enum
 from math import log, pow
 
+from celery.utils.log import get_task_logger
 from nassl.legacy_ssl_client import LegacySslClient
 from nassl.ssl_client import SslClient
 
 from checks.tasks.tls_connection import DebugConnection, ModernConnection
 
-logger = logging.getLogger("internetnl")
+logger = get_task_logger(__name__)
 
 
 class SecLevel(Enum):

checks/tasks/rpki.py

@@ -7,7 +7,7 @@
 from celery.exceptions import SoftTimeLimitExceeded
 from django.conf import settings
 from django.db import transaction
-import logging
+from celery.utils.log import get_task_logger
 
 from interface import batch, batch_shared_task
 from . import SetupUnboundContext
@@ -36,7 +36,7 @@
 TestName = NewType("TestName", str)
 TestResult = Dict[TestName, List[Dict[str, Union[Dict, List, str]]]]
 
-logger = logging.getLogger("internetnl")
+logger = get_task_logger(__name__)
 
 # mapping services to models
 model_map = dict(

checks/tasks/tls.py

@@ -2,7 +2,6 @@
 # SPDX-License-Identifier: Apache-2.0
 import errno
 import http.client
-import logging
 import socket
 import ssl
 import time
@@ -14,6 +13,7 @@
 import eventlet
 from celery import shared_task
 from celery.exceptions import SoftTimeLimitExceeded
+from celery.utils.log import get_task_logger
 from cryptography.hazmat.backends import default_backend
 from cryptography.hazmat.backends.openssl.dh import _DHPublicKey
 from cryptography.hazmat.backends.openssl.dsa import _DSAPublicKey
@@ -105,7 +105,7 @@
     else:
         raise e
 
-logger = logging.getLogger("internetnl")
+logger = get_task_logger(__name__)
 
 # Based on:
 # hhttps://tools.ietf.org/html/rfc5246#section-7.4.1.4.1 "Signature Algorithms"

checks/tasks/tls_connection.py

@@ -10,6 +10,7 @@
 from io import BytesIO
 from urllib.parse import urlparse
 
+from celery.utils.log import get_task_logger
 from django.conf import settings
 from nassl import _nassl
 from nassl.legacy_ssl_client import LegacySslClient
@@ -21,8 +22,7 @@
 from internetnl import celery_app
 
 # Use a dedicated logger as this logging can be very verbose
-logger = logging.getLogger(__name__)
-sslConnectLogger = logging.getLogger("internetnl.ssl.connect")
+sslConnectLogger = get_task_logger("internetnl.ssl.connect")
 
 HTTPS_READ_CHUNK_SIZE = 8192
 

interface/batch/scheduler.py

@@ -540,11 +540,11 @@ def _run_scheduler():
 
     start_time = timer()
     find_stalled_tests_and_update_db()
-    logger.info("Found stalled tests in {}s".format(timer() - start_time))
+    logger.info("Found stalled tests in {:.06f}s".format(timer() - start_time))
 
     start_time = timer()
     update_batch_request_status()
-    logger.info("Updated batch request status in {}s".format(timer() - start_time))
+    logger.info("Updated batch request status in {:.06f}s".format(timer() - start_time))
 
     submitted_domains = 0
     found_domains = 0
@@ -580,7 +580,7 @@ def _run_scheduler():
                 found_domains += 1
             update_domain_status(batch_domain)
         logger.info(
-            f"Submitted {submitted_domains} domains in {format(timer() - start_time)}s, "
+            f"Submitted {submitted_domains} domains in {format(timer() - start_time):.06f}s, "
             f"{len(live_requests)} users remaining in queue"
         )
     else:

internetnl/__init__.py

@@ -1,9 +1,10 @@
 # Copyright: 2022, ECP, NLnet Labs and the Internet.nl contributors
 # SPDX-License-Identifier: Apache-2.0
-import logging
 
 from internetnl.celery import app as celery_app
 
-log = logging.getLogger(__package__)
+from celery.utils.log import get_task_logger
+
+log = get_task_logger(__package__)
 
 __all__ = ("celery_app",)