Django_q async_task and QueueHandler logging : Forums : PythonAnywhere

Django_q async_task and QueueHandler logging

Currently I initiate (from views.py) a long running async_task (in services.py). After it kicks off I redirect to another web template (via views.py) where I want to print logs to the template. The other web template calls a function in utils.py to check on the log queue. Here's a sample froms settings.py where I set up the logging stuff:

# Logging
NBM_QUEUE = Queue()
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'memory': {
            'class': 'logging.handlers.MemoryHandler',
            'capacity': 100,
            'level': 'INFO',
        },
        'console': {
            'class': 'logging.StreamHandler',
        },
        'queue': {
            'class': 'logging.handlers.QueueHandler',
            'queue': NBM_QUEUE,
        },
    },
    'loggers': {
        'nbmApp': {
            'handlers': ['queue','memory','console'],
            'level': 'INFO',
        },
        'django': {
            'handlers': ['console'],
            'level': 'INFO',
        },
    },
}

And here's the wsgi.py for the project where I start a QueueListener (note I tried this same code in views.py as well with the same result.

import logging
from logging.handlers import QueueListener
from django.conf import settings
logger = logging.getLogger('nbmApp')
queue_listener = QueueListener(settings.NBM_QUEUE, *logger.handlers)
queue_listener.start()

The problem that I am having is that if I write to the logger outside of the async_task I see it populate the queue and I can pass it to the web template. But everything logged within the async_task doesn't make it out of the thread. I can verify that it is logging to the queue while in the thread, but what gets retrieved in utils.py is empty.

Here's utils.py

@csrf_protect
def get_task_status(request):
    logger = logging.getLogger('nbmApp')
    logger.info("In get task status")
    print(list(settings.NBM_QUEUE.queue))
    try:
        record = settings.NBM_QUEUE.get(block=False)
    except Empty:
        context = {'logs': ''}
    else:
        logs = record.getMessage()
        context = {'logs': logs}
    print("NEW CONTEXT IS")
    print(context)
    return JsonResponse(context)

So for example the "in get task status" message gets logged to the web template, but nothing from services.py makes it back to utils.py. So somehow it's writing to different queues or loggers.

The method i follow for logging is the same in all of the python scripts and threads

logger = logging.getLogger('nbmApp')
logger.info("message")

Why isn't the logging from the async thread making it into the same queue as the other logger messages, especially when that explicit logger and queue are defined at a high level?

weatherman0516 | 8 posts | March 2, 2023, 3:21 p.m. | permalink

Threading is disabled in web apps, so your threaded code is not running. If you need to run things that are not related to a specific request, run that outside of the web app code: https://help.pythonanywhere.com/pages/AsyncInWebApps/

glenn | 9498 posts | PythonAnywhere staff | March 2, 2023, 5:32 p.m. | permalink

I believe that's what I'm doing. I use django_q to fire off an async_task in views.py like this:

task_id = async_task("forms.services.masterRunner", parsedRequest)

I see the threaded code running in the console using

python manage.py qcluster

And the data is created as I would expect in my defined data directory. I just need to get the output appended to the logger in the thread. The logs are visible in the queue if view the queue in the thread, but not visible outside of the thread.

weatherman0516 | 8 posts | March 2, 2023, 5:45 p.m. | permalink

But you specifically said in your first post that you were starting the queue listener in your wsgi file. That would be a trying to start a thread in your web app.

glenn | 9498 posts | PythonAnywhere staff | March 2, 2023, 5:55 p.m. | permalink

Ok, im definitely new to pythonanywhere and web apps in general so pardon the confusion. Is there somewhere else I can put a listener that would allow me log messages from the threaded task to a queue that I can access from the webapp that spawned the threaded task? Would i start it in another async_task I guess?

Essentially a user submits an html form which starts the long running task on it's own thread, redirects to a status page where I want to print to the screen the log messages as they come in from the thread.

weatherman0516 | 8 posts | March 2, 2023, 5:59 p.m. | permalink

It's not a django example, but your general solution should look similar to https://blog.pythonanywhere.com/198/

fjl | 4352 posts | PythonAnywhere staff | March 3, 2023, 10:31 a.m. | permalink

Ok, I'm not sure that I even need a listener, here's the basics of my current framework and the problem I'm still having is that I can write to the queue with logging inside and outside of the threaded task, but it's apparently not the same queue so the queue in the function triggered by async_task cannot be accessed outside of the thread.

Here's settings.py

MY_QUEUE = queue.Queue()
# Logging
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'queue': {
            'class': 'logging.handlers.QueueHandler',
            'queue': MY_QUEUE,
            'level': 'INFO',
        },
    },
    'loggers': {
        'nbmApp': {
            'handlers': ['queue'],
            'level': 'INFO',
            'propagate': True,
        },
    },
}

And here's views.py which is called upon a form submission and redirects to a status page that I'd like to show the log output on. get_task_status is called by some javascript on the processing_view.html template.

from django.http import HttpResponse, JsonResponse, HttpRequest
from django.views import View
from django.views.decorators.csrf import ensure_csrf_cookie, csrf_protect
from django.shortcuts import render, redirect
from django.urls import reverse
from django_q.tasks import async_task, fetch
from django_q.models import Task
import logging
import time,os,json

from django.conf import settings
from logging.handlers import QueueHandler


logger = logging.getLogger('nbmApp')

@ensure_csrf_cookie
def form_view(request):
    if request.method == 'POST':
        parsedRequest = {
            'uStns': request.POST['stations'],
            'sDate': request.POST['startdate'],
            'eDate': request.POST['enddate']
            }
        loggerName = 'nbmApp'
        parsedRequest['loggerName'] = loggerName
        task_id = async_task("forms.services.masterRunner", parsedRequest)
        return redirect('processing_view', taskID=task_id, loggerName=loggerName)
    return render(request, "run_script.html",{})

@csrf_protect
def processing_view(request, taskID, loggerName):
    context = {
        'theVars': {
            'taskID': taskID,
            'loggerName': loggerName,
            'task': None,
            'logs': None,
        },
    }
    return render(request, "processing_view.html", context)

@csrf_protect
def get_task_status(request, taskID):
    record = settings.MY_QUEUE.get()
    logs = record.getMessage()
    return JsonResponse(json.dumps({"logs":logs}),safe=False)

And here's a trimmed version services.py (to show the general framework) where the long running function is called by async_task.

import re, json, urllib.request, os, gzip, math, sys, copy
from datetime import datetime, timedelta, date

import logging
from logging.handlers import QueueHandler
from django.conf import settings

logger = logging.getLogger('nbmApp')

def masterRunner(parsedDict):
    BulletinDecoder(bulletinDict,hours,stations,dataDir,parsedDict['uStns'],parsedDict['sDate'],parsedDict['eDate'],logger)

class BulletinDecoder:
    def __init__(self,bulletinDict,hours,stations,dataDir,uStns,sDate,eDate,logger):
        self.logger = logger
        self.bulletinDict = bulletinDict
        self.hours = hours
        self.stations = stations
        self.orgData = {}
        self.meshedDict = {}
        self.useStations = uStns.split(",")
        self.dateRange = (sDate,eDate)
        self.dateList = self.makeDateList()
        self.dlBulletin()

    def makeDateList(self):
        dateList = []
        startDate = datetime.strptime(self.dateRange[0],"%Y-%m-%d") - timedelta(days=8)
        endDate = datetime.strptime(self.dateRange[1],"%Y-%m-%d")
        while startDate <= endDate:
            dateList.append(startDate.strftime("%Y%m%d"))
            startDate = startDate + timedelta(days=1)
        return dateList

    def dlBulletin(self):
        self.logger.info("I CANT SEE THIS OUTSIDE OF THE THREAD WHEN CALLED IN VIEWS.PY")

weatherman0516 | 8 posts | March 4, 2023, 6:02 p.m. | permalink

What is not clear in any of this is what you mean by "outside of the thread"? Which thread? Where is that thread started? Which code above is "inside the thread" and which is "outside"

glenn | 9498 posts | PythonAnywhere staff | March 5, 2023, 11:06 a.m. | permalink

Apologies for for the confusing wording, replace thread with asynchronous task. Anything logging in the asynchronous task doesn't appear in the queue when trying to access it in views.py. So the asynchronous task is started in views.py and the task itself is in services.py

weatherman0516 | 8 posts | March 5, 2023, 2:20 p.m. | permalink

Ok. Now what do you mean by "appear in the queue"

glenn | 9498 posts | PythonAnywhere staff | March 5, 2023, 6:50 p.m. | permalink

Any message logged with logger.info in the services.py module can be viewed by printing the MY_QUEUE.queue to the terminal with a print statement. However if I do the same back in views.py, specifically get_task_status none of the logs from services.py are in the MY_QUEUE, but if I log any thing in views.py it will be in MY_QUEUE on the views.py side

weatherman0516 | 8 posts | March 5, 2023, 7:09 p.m. | permalink

In that case, it seems likely that the mechanism that is used to communicate between the queues in the different processes is designed to be used on the same machine. Since your web apps are run on different machines to your consoles and tasks, that is probably what is happening. Check the documentation of django_q to see if there is a mechanism that does not rely on the processes running on the same machine.

glenn | 9498 posts | PythonAnywhere staff | March 6, 2023, 11:09 a.m. | permalink