use threadName instead of task_id

7 files changed, 37 insertions, 74 deletions

diff --git a/blocks/blocks/celery_tasks.py b/blocks/blocks/celery_tasks.py
index 16863f03..573bad45 100644
--- a/blocks/blocks/celery_tasks.py
+++ b/blocks/blocks/celery_tasks.py
@@ -32,8 +32,7 @@ class DateChangeFilter(logging.Filter):
 # Define log format
 LOG_FILE = "logs/celery.log"
 
-TASK_LOG_FORMAT = "%(asctime)s - %(levelname)s - [%(task_id)s]: %(message)s"
-WORKER_LOG_FORMAT = "%(asctime)s - %(levelname)s - [%(processName)s]: %(message)s"
+LOG_FORMAT = "%(asctime)s - %(levelname)s - [%(threadName)s]: %(message)s"
 
 LOG_DATE_FORMAT = "%H:%M:%S"
 
@@ -41,12 +40,8 @@ CELERY_LOGGING_CONFIG = {
     "version": 1,
     "disable_existing_loggers": False,
     "formatters": {
-        "task_formatter": {
-            "format": TASK_LOG_FORMAT,
-            "datefmt": LOG_DATE_FORMAT,
-        },
-        "worker_formatter": {
-            "format": WORKER_LOG_FORMAT,
+        "formatter": {
+            "format": LOG_FORMAT,
             "datefmt": LOG_DATE_FORMAT,
         },
     },
@@ -56,42 +51,29 @@ CELERY_LOGGING_CONFIG = {
         },
     },
     "handlers": {
-        "task_console": {
-            "class": "logging.StreamHandler",
-            "formatter": "task_formatter",
-        },
-        "worker_console": {
+        "console": {
             "class": "logging.StreamHandler",
-            "formatter": "worker_formatter",
+            "formatter": "formatter",
             "filters": ["date_change_filter"],
         },
-        "task_file": {
-            "class": "logging.handlers.TimedRotatingFileHandler",
-            "filename": LOG_FILE,
-            "when": "midnight",
-            "interval": 1,
-            "backupCount": 15,
-            "formatter": "task_formatter",
-            "encoding": "utf-8",
-        },
-        "worker_file": {
+        "file": {
             "class": "logging.handlers.TimedRotatingFileHandler",
             "filename": LOG_FILE,
             "when": "midnight",
             "interval": 1,
             "backupCount": 15,
-            "formatter": "worker_formatter",
+            "formatter": "formatter",
             "encoding": "utf-8",
         },
     },
     "loggers": {
         "celery.task": {
-            "handlers": ["task_console", "task_file"],
+            "handlers": ["console", "file"],
             "level": "INFO",
             "propagate": False,
         },
         "celery": {
-            "handlers": ["worker_console", "worker_file"],
+            "handlers": ["console", "file"],
             "level": "INFO",
             "propagate": False,
         },
@@ -100,7 +82,7 @@ CELERY_LOGGING_CONFIG = {
 
 logging.config.dictConfig(CELERY_LOGGING_CONFIG)
 
-worker_logger = logging.getLogger("celery")
+logger = logging.getLogger("celery")
 
 os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'blocks.settings')
 
@@ -118,11 +100,11 @@ def debug_task(self):
 
 @worker_ready.connect
 def startup_code(**kwargs):
-    worker_logger.info("Running global startup code")
+    logger.info("Running global startup code")
     start_threads()
 
 
 @worker_shutdown.connect
 def shutdown_code(**kwargs):
-    worker_logger.info("Running global shutdown code")
+    logger.info("Running global shutdown code")
     stop_threads()
diff --git a/blocks/simulationAPI/helpers/ngspice_helper.py b/blocks/simulationAPI/helpers/ngspice_helper.py
index 17e87e38..c5eb8e71 100644
--- a/blocks/simulationAPI/helpers/ngspice_helper.py
+++ b/blocks/simulationAPI/helpers/ngspice_helper.py
@@ -4,6 +4,7 @@ from os.path import abspath, join, splitext
 import re
 import subprocess
 from celery import current_task
+from celery.utils.log import get_task_logger
 from datetime import datetime
 from pathlib import Path
 from tempfile import mkstemp
@@ -11,7 +12,6 @@ from django.conf import settings
 from django.db.models import Case, F, Value, When
 from django.utils.timezone import now
 
-from simulationAPI.logging_utils import get_task_logger_adapter as get_task_logger
 from simulationAPI.models import Task
 
 logger = get_task_logger(__name__)
@@ -113,7 +113,6 @@ def CreateXcos(file_path, parameters, task_id):
 def ExecXml(task, task_name):
     task_id = task.task_id
     file_path = task.file.path
-    logger.extra = {'task_name': task_name, 'task_id': task_id}
     current_dir = settings.MEDIA_ROOT + '/' + str(task_id)
     try:
         xcosfile = CreateXml(file_path, task.parameters, task_id)
diff --git a/blocks/simulationAPI/helpers/scilab_manager.py b/blocks/simulationAPI/helpers/scilab_manager.py
index fe64f56c..f01caff0 100644
--- a/blocks/simulationAPI/helpers/scilab_manager.py
+++ b/blocks/simulationAPI/helpers/scilab_manager.py
@@ -1,3 +1,4 @@
+from celery.utils.log import get_task_logger
 from datetime import datetime
 from django.conf import settings
 from django.http import FileResponse, Http404, JsonResponse
@@ -6,7 +7,6 @@ from gevent.event import Event
 from gevent.lock import RLock
 import glob
 import json
-import logging
 import os
 from os.path import abspath, exists, isfile, join
 import re
@@ -18,7 +18,6 @@ from time import time
 import unicodedata
 import uuid
 
-from simulationAPI.logging_utils import get_task_logger_adapter as get_task_logger
 from simulationAPI.helpers import config
 
 os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'blocks.settings')
@@ -106,7 +105,6 @@ def remove(filename):
         return False
 
 
-worker_logger = logging.getLogger("celery")
 logger = get_task_logger(__name__)
 
 makedirs(SESSIONDIR, 'top session')
@@ -290,7 +288,7 @@ def start_scilab_instances():
     lssi = min(config.SCILAB_START_INSTANCES,
                config.SCILAB_MAX_INSTANCES - l2) - l1
     if lssi > 0:
-        worker_logger.info('can start %s instances', lssi)
+        logger.info('can start %s instances', lssi)
     return lssi
 
 
@@ -302,7 +300,7 @@ def print_scilab_instances():
         msg += ', free=' + str(l1)
     if l2 > 0:
         msg += ', in use=' + str(l2)
-    worker_logger.info('instance count: %s', msg[2:])
+    logger.info('instance count: %s', msg[2:])
 
 
 FIRST_INSTANCE = True
@@ -473,13 +471,13 @@ def stop_instance(instance, createlogfile=False, removeinstance=True):
 
 def stop_scilab_instances():
     if len(INSTANCES_1) > 0:
-        worker_logger.info('stopping %s idle instances', len(INSTANCES_1))
+        logger.info('stopping %s idle instances', len(INSTANCES_1))
         while len(INSTANCES_1) > 0:
             instance = INSTANCES_1.pop()
             stop_instance(instance, removeinstance=False)
 
     if len(INSTANCES_2) > 0:
-        worker_logger.info('stopping %s busy instances', len(INSTANCES_2))
+        logger.info('stopping %s busy instances', len(INSTANCES_2))
         while len(INSTANCES_2) > 0:
             instance = INSTANCES_2.pop()
             stop_instance(instance, removeinstance=False)
@@ -500,11 +498,11 @@ def reap_scilab_instances():
         if count == 0:
             continue
 
-        worker_logger.info('removing %s stale instances', count)
+        logger.info('removing %s stale instances', count)
         for instance in remove_instances:
             base = instance.base
             if base is None:
-                worker_logger.warning('cannot stop instance %s', instance)
+                logger.warning('cannot stop instance %s', instance)
                 stop_instance(instance)
             elif isinstance(base, Diagram):
                 kill_scilab(base)
@@ -513,7 +511,7 @@ def reap_scilab_instances():
             elif isinstance(base, SciFile):
                 kill_scifile(base)
             else:
-                worker_logger.warning('cannot stop instance %s', instance)
+                logger.warning('cannot stop instance %s', instance)
                 stop_instance(instance)
 
 
@@ -536,15 +534,15 @@ def clean_sessions(final=False):
         if final or time() - ud.timestamp > config.SESSIONTIMEOUT:
             cleanuids.append(uid)
 
-    worker_logger.info('cleaning %s/%s sessions', len(cleanuids), totalcount)
+    logger.info('cleaning %s/%s sessions', len(cleanuids), totalcount)
     for uid in cleanuids:
         current_thread().name = 'Clean-%s' % uid[:6]
         try:
-            worker_logger.info('cleaning')
+            logger.info('cleaning')
             ud = USER_DATA.pop(uid)
             ud.clean()
         except Exception as e:
-            worker_logger.warning('could not clean: %s', str(e))
+            logger.warning('could not clean: %s', str(e))
 
 
 def clean_sessions_thread():
@@ -554,7 +552,7 @@ def clean_sessions_thread():
         try:
             clean_sessions()
         except Exception as e:
-            worker_logger.warning('Exception in clean_sessions: %s', str(e))
+            logger.warning('Exception in clean_sessions: %s', str(e))
 
 
 logfilefdrlock = RLock()
@@ -1404,4 +1402,4 @@ def stop_threads():
     cleaner = None
     clean_sessions(True)
     stop_scilab_instances()
-    worker_logger.info('exiting')
+    logger.info('exiting')
diff --git a/blocks/simulationAPI/logging_utils.py b/blocks/simulationAPI/logging_utils.py
deleted file mode 100644
index cc8a43dc..00000000
--- a/blocks/simulationAPI/logging_utils.py
+++ /dev/null
@@ -1,17 +0,0 @@
-import logging
-from celery.utils.log import get_task_logger
-
-
-class TaskLoggerAdapter(logging.LoggerAdapter):
-    """LoggerAdapter that injects task_name and task_id into log records."""
-    def process(self, msg, kwargs):
-        kwargs["extra"] = kwargs.get("extra", {})
-        kwargs["extra"].setdefault("task_name", self.extra.get("task_name", "UNKNOWN_TASK"))
-        kwargs["extra"].setdefault("task_id", self.extra.get("task_id", "N/A"))
-        return msg, kwargs
-
-
-def get_task_logger_adapter(name):
-    """Returns a LoggerAdapter for Celery tasks."""
-    base_logger = get_task_logger(name)
-    return TaskLoggerAdapter(base_logger, {})
diff --git a/blocks/simulationAPI/serializers.py b/blocks/simulationAPI/serializers.py
index 8a872bf1..9a815b41 100644
--- a/blocks/simulationAPI/serializers.py
+++ b/blocks/simulationAPI/serializers.py
@@ -1,10 +1,10 @@
+from celery.utils.log import get_task_logger
 import json
-import logging
 from rest_framework import serializers
 
 from simulationAPI.models import Task, Session
 
-logger = logging.getLogger("celery")
+logger = get_task_logger(__name__)
 
 
 class SessionSerializer(serializers.ModelSerializer):
diff --git a/blocks/simulationAPI/tasks.py b/blocks/simulationAPI/tasks.py
index a86da1d3..f0478e71 100644
--- a/blocks/simulationAPI/tasks.py
+++ b/blocks/simulationAPI/tasks.py
@@ -1,11 +1,12 @@
 from celery import shared_task, states
 from celery.exceptions import Ignore
+from celery.utils.log import get_task_logger
 from redis import Redis
+from threading import current_thread
 import traceback
 
 from blocks.celery_tasks import app
 from simulationAPI.helpers.ngspice_helper import ExecXml, update_task_status
-from simulationAPI.logging_utils import get_task_logger_adapter as get_task_logger
 from simulationAPI.models import Task
 
 logger = get_task_logger(__name__)
@@ -24,7 +25,7 @@ def release_lock(lock):
 
 @shared_task(bind=True)
 def process_task(self, task_id):
-    logger.extra = {'task_name': self.name, 'task_id': self.request.id}
+    current_thread().name = task_id[:8]
     task = Task.objects.get(task_id=task_id)
     session_id = task.session.session_id
     lock = acquire_lock(session_id)  # Prevent multiple runs per session
diff --git a/blocks/simulationAPI/views.py b/blocks/simulationAPI/views.py
index 4d08c8fc..5d397e5c 100644
--- a/blocks/simulationAPI/views.py
+++ b/blocks/simulationAPI/views.py
@@ -1,18 +1,18 @@
-import os
+from celery.result import AsyncResult
+from celery.utils.log import get_task_logger
 from django.conf import settings
-import logging
+from django.http import StreamingHttpResponse, JsonResponse
+import os
 import time
 import uuid
-from celery.result import AsyncResult
-from django.http import StreamingHttpResponse, JsonResponse
 from rest_framework import status
 from rest_framework.exceptions import ValidationError
 from rest_framework.parsers import MultiPartParser, FormParser
 from rest_framework.permissions import AllowAny
 from rest_framework.response import Response
 from rest_framework.views import APIView
-from blocks.celery_tasks import app
 
+from blocks.celery_tasks import app
 from simulationAPI.models import Task, Session
 from simulationAPI.negotiation import IgnoreClientContentNegotiation
 from simulationAPI.serializers import TaskSerializer
@@ -34,7 +34,7 @@ DATA = 2
 # to indicate there is no line in log file further
 NOLINE = -1
 
-logger = logging.getLogger("celery")
+logger = get_task_logger(__name__)
 
 
 class XmlUploader(APIView):