django database query log linenumber

Question

I am logging my database queries in Django along with the pathname and linenumber.

Right now i am getting these logs:

07/Dec/2018 14:25:00 DEBUG django.db.backends utils **/Users/XXXXX/.idea/lib/python2.7/site-packages/django/db/backends/utils.py:89** (0.340) SELECT "metadata"."metaname", "metadata"."description", "metadata"."attributes" FROM "metadata" WHERE "metadata"."metaname" = 'date_type'; args=('date_type',)

For all queries, I am getting the same path and line number. Is there any way I can capture the line number from my main application instead of the one from utils.

Current logging Implementation:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'color'
        },
    },
    'loggers': {
        'django.db.backends': {
            'handlers': ['console'],
            'level': 'DEBUG',
            'propogate': True,
        }
    }
}

Using python 2.7 and django 1.9

pymen · Answer 1 · 2020-06-23T14:36:20.937

The slightly optimized version from User @will-keeling

Logging configuration for Django for output line numbers for each db request.

Note: If you want to use it for tests you need to set DEBUG=True for tests How do you set DEBUG to True when running a Django test?

import logging
import traceback
from django.conf import settings


class StackInfoHandler(logging.StreamHandler):
    trim = 5

    def emit(self, record):
        super(StackInfoHandler, self).emit(record)
        trace = traceback.format_stack()
        stack1 = [str(row) for row in trace]
        stack2 = [s for s in stack1 if settings.BASE_DIR in s and 'format_stack' not in s]
        stack3 = [s for s in stack2 if 'test' not in s]
        if not stack3:
            stack3 = stack2  # include test call
        if stack3:
            stack4 = ''.join(stack3[-self.trim:])  # take only last records
            stack5 = f"Stack {self.terminator} {''.join(stack4)}"
            self.stream.write(stack5)
            self.stream.write(self.terminator)
            self.flush()

Logging Config (partitial)

LOGGING = {
    'handlers': {
        'db-console': {
            'level': 'DEBUG',
            'class': 'settings.local.StackInfoHandler',  # Reference the custom handler
            'formatter': 'simple',
        },
        'loggers': {
            'django.db.backends': {
                'handlers': ['db-console'],
                'level': 'DEBUG',
                'propagate': False
            },
        }
    }
}

This will show you only stack trace from your Django codebase like below

[2020-05-25 17:49:17,977]: (0.000) INSERT INTO `contacts_contactscount` (`user_id`, `date`, `amount`) VALUES (338, '2020-05-25 17:49:17', 7); args=[338, '2020-05-25 17:49:17', 7]
Stack
   File "<project-root>/api/views/contacts.py", line 164, in create
    Contact.objects.filter(pk__in=to_delete).delete()
  File "<project-root>/<folder>/contacts/models.py", line 54, in delete
    create_deletion_log.delay(obj, deleted_timestamp)
  File "<project-root>/<folder>/contacts/tasks.py", line 31, in create_deletion_log
    contact.save()
  File "<project-root>/<folder>/contacts/models.py", line 118, in save
    Contact.objects.contacts_added_hook(self.user)
  File "<project-root>/<folder>/contacts/models.py", line 67, in contacts_added_hook
    current_total = user.profile.contacts_total
  File "<project-root>/<folder>/profile/models.py", line 631, in contacts_total
    ContactsCount.objects.create(user=self.user, amount=count)

score 1 · Accepted Answer · answered Dec 07 '18 at 21:42

I'm guessing that you're trying to determine which lines in your application are responsible for running which queries.

One way to achieve this would be to create a custom handler that prints out the current stack at the point where Django logs the query. That would allow you to see which line in your application is executing.

You could create a custom handler such as:

import logging
import traceback

class StackInfoHandler(logging.StreamHandler):

    trim = 5

    def emit(self, record):
        super(StackInfoHandler, self).emit(record)
        stack = ''.join(
            str(row) for row in traceback.format_stack()[:-self.trim]
        )
        self.stream.write(stack)

And then in your logging config, you could just switch the handler class to use the StackInfoHandler:

'handlers': {
    'console': {
        'level': 'DEBUG',
        'class': 'my.package.StackInfoHandler',  # Reference the custom handler
        'formatter': 'color'
    },
},

Note that the StackInfoHandler trims 5 lines off the stack so that it doesn't show you stack frames from the logging framework itself. You might need to tweak this number (5 works for me locally).

I was thinking of something similar. But as I am new to Django, I thought there could be some other way. Thanks — archit gupta, Dec 10 '18 at 08:06

django database query log linenumber

2 Answers2