Django 1.2 : strange logging behavior

Question

Hello ! I have a really strange problem with the standard logging module used in django views. Sometimes it works perfectly and sometimes it does not log messages.

Here is the structure of my code :

/mysite/ (Django root)
    my_logging.py (logging configuration)
    settings.py
    views.py (global views)
    data_objects.py (objects only containing data, similar to POJO)
    uploader/ (application)
        views.py (uploader views) --> This is where I have problems

Here is the code of my_logging.py :

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

is_initialized = False

def init_logger():
    """
    Initializes the logging for the application. Configure the root
    logger and creates the handlers following the settings. This function should
    not be used directly from outside the module and called only once.
    """
    # Create the logger
    server_logger = logging.getLogger()
    server_logger.setLevel(logging.DEBUG)

     # Set the logging format for files
    files_formatter = logging.Formatter(settings.LOGGING_FORMAT_FILE)

     # Rotating file handler for errors
    error_handler = logging.handlers.RotatingFileHandler(
        settings.LOGGING_ERROR_FILE,
        maxBytes=settings.LOGGING_ERROR_FILE_SIZE,
        backupCount=settings.LOGGING_ERROR_FILE_COUNT,
    )
    error_handler.setLevel(logging.WARNING)
    error_handler.setFormatter(files_formatter)

    # Rotating file handler for info
    info_handler = logging.handlers.RotatingFileHandler(
        settings.LOGGING_INFO_FILE,
        maxBytes=settings.LOGGING_INFO_FILE_SIZE,
        backupCount=settings.LOGGING_INFO_FILE_COUNT,
    )
    info_handler.setLevel(logging.INFO)
    info_handler.setFormatter(files_formatter)

    # Add the handlers to the logger
    server_logger.addHandler(info_handler)
    server_logger.addHandler(error_handler)

# Init once at first import
if not is_initialized:
    init_logger()
    is_initialized = True

Here are parts of uploader/views.py (#... = code skipped):

#...
import mysite.my_logging
import logging
#... 
# The messages in the following view are written correctly :
@login_required
def delete(request, file_id):
    """
    Delete the file corresponding to the given ID and confirm the deletion to
    the user.

    @param request: the HTTP request object
    @type request: django.http.HttpRequest
    @return: django.http.HttpResponse - the response to the client (html)
    """
    # Get the file object form the database and raise a 404 if not found
    f = get_object_or_404(VideoFile, pk=file_id)

    # TODO: check if the deletion is successful

    # Get the video directory
    dir_path = os.path.dirname(f.file.path)

    # Delete the file
    f.delete()

    try:
        # Delete the video directory recursively
        shutil.rmtree(dir_path)
        logging.info("File \"%(file)s\" and its directory have been deleted by %(username)s",{'file': f.title,'username': request.user.username})
        messages.success(request, _('The video file "%s" has been successfully deleted.') % f.title)
    except OSError:
        logging.warning("File \"%(id)d\" directory cannot be completely deleted. Some files may still be there.",{'id': f.id,})
        messages.warning(request, _("The video file \"%s\" has been successfully deleted, but not its directory. There should not be any problem but useless disk usage.") % f.title)

    return HttpResponseRedirect(reverse('mysite.uploader.views.list'))
#...
# The messages in the following view are NOT written at all:
@csrf_exempt
def get_thumblist(request,file_id):
    """
    This view can be called only by POST and with the id of a video
    file ready for the scene editor.

    @param request: the HTTP request object. Must have POST as method.
    @type request: django.http.HttpRequest
    @return: django.http.HttpResponse - the response to the client (json)
    """
    #TODO: Security, TEST

    logging.info("Demand of metadata for file %(id)d received.",{'id': file_id,})

    if request.method == 'POST':

        if file_id:

            # Get the video file object form the database and raise a 404 if not found
            vid = get_object_or_404(VideoFile, pk=file_id)

                # ...

                try:
                    # ... file operations
                except IOError:
                    logging.error("Error when trying to read index file for file %(id)d !",{'id': file_id,})
                except TypeError:
                    logging.error("Error when trying to parse index file JSON for file %(id)d !",{'id': file_id,})

                # ...

                logging.info("Returning metadata for file %(id)d.",{'id': file_id,})
                return HttpResponse(json,content_type="application/json")

            else:
                logging.warning("File %(id)d is not ready",{'id': file_id,})
                return HttpResponseBadRequest('file_not_ready')
        else:
            logging.warning("bad POST parameters")
            return HttpResponseBadRequest('bad_parameters')
    else:
        logging.warning("The GET method is not allowed")
        return HttpResponseNotAllowed(['POST'])

and the interesting part of settings.py:

# ---------------------------------------
# Logging settings
# ---------------------------------------

#: Minimum level for logging messages. If logging.NOTSET, logging is disabled
LOGGING_MIN_LEVEL = logging.DEBUG

#: Error logging file path. Can be relative to the root of the project or absolute.
LOGGING_ERROR_FILE = os.path.join(DIRNAME,"log/error.log")

#: Size (in bytes) of the error files
LOGGING_ERROR_FILE_SIZE = 10485760 # 10 MiB

#: Number of backup error logging files
LOGGING_ERROR_FILE_COUNT = 5

#: Info logging file path. Can be relative to the root of the project or absolute.
LOGGING_INFO_FILE = os.path.join(DIRNAME,"log/info.log")

#: Size (in bytes) of the info files
LOGGING_INFO_FILE_SIZE = 10485760 # 10 MiB

#: Number of backup error info files
LOGGING_INFO_FILE_COUNT = 5

#: Format for the log files
LOGGING_FORMAT_FILE = "%(asctime)s:%(name)s:%(levelname)s:%(message)s"

Note that except logging everything is working fine. The data can be returned correctly in JSON format. I think there is no error in the rest of the code.

Please ask if you need more information. I'm sorry about the code I removed, but I have to because of confidentiality.

Answer 1

Instead of using the logging.info('My statement') syntax, I suggest you use something like the following:

import logging
logger = logging.getLogger('MySite')
logger.info('My statement')

That is, call your log statements against a logger object, instead of the logging module directly. Likewise, you'll have to tweak my_logging.py to configure that logger:

# Create the logger
server_logger = logging.getLogger('MySite')
server_logger.setLevel(logging.DEBUG)

In your views, you can log against logging.getLogger('MySite') or logging.getLogger('MySite.views'), etc.. Any logger which starts with 'MySite' will inherit your configuration.

Also, while you have the right idea by setting and checking is_initialized, I don't believe that approach will work. Each time my_logging.py is imported, that variable will be set to False, thus defeating its purpose. You can use the following in settings.py to ensure that logging is only configured once:

# Init once at first import
if not hasattr(my_logging, 'is_initialized'):
    my_logging.is_initialized = False

if not my_logging.is_initialized:
    my_logging.init_logger()
    my_logging.is_initialized = True

I start all of my modules (except settings.py) with the following two lines:

import logging
logging.getLogger('MySite.ModuleInit').debug('Initializing %s' % str(__name__))

If you are still having trouble, please add those lines and then post the module initialization order for your site. There may be a strange quirk based on the order of your imports.