Django 1.2: comportement de journalisation étrange

Question

J'ai un problème vraiment étrange avec le module de journalisation standard utilisé dans les vues django. Parfois, cela fonctionne parfaitement et parfois, il n'enregistre pas les messages.

Voici la structure de mon 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 

Voici le code de 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 

Voici les parties de téléchargeur/views.py (# ... = Code sauté):

#... 
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']) 

et la partie intéressante de 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" 

Notez que, sauf la journalisation, tout fonctionne correctement. Les données peuvent être retournées correctement au format JSON. Je pense qu'il n'y a pas d'erreur dans le reste du code.

S'il vous plaît demander si vous avez besoin de plus d'informations. Je suis désolé pour le code que j'ai retiré, mais je dois le faire pour des raisons de confidentialité.

Answer 1

Au lieu d'utiliser la syntaxe logging.info('My statement'), je vous suggère d'utiliser quelque chose comme ce qui suit:

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

C'est, appelez vos relevés de journal sur un objet enregistreur, au lieu du module d'enregistrement directement. De même, vous devrez modifier my_logging.py pour configurer que enregistreur:

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

votre point de vue, vous pouvez vous connecter ou contre logging.getLogger('MySite')logging.getLogger('MySite.views'), etc .. Tout enregistreur qui commence par « MySite » héritera votre configuration .

Aussi, alors que vous avez la bonne idée en réglant et en vérifiant is_initialized, je ne crois pas que l'approche fonctionne. Chaque fois que my_logging.py est importé, cette variable sera définie sur False, ce qui annulera son objectif. Vous pouvez utiliser les éléments suivants dans settings.py pour assurer que l'enregistrement est configuré uniquement une fois:

# 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 

Je commence tous mes modules (sauf settings.py) avec les deux lignes suivantes:

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

Si vous rencontrez toujours des problèmes, ajoutez ces lignes, puis publiez l'ordre d'initialisation du module pour votre site. Il peut y avoir une étrange bizarrerie basée sur l'ordre de vos importations.