Django 1.2：奇怪的日志记录行为

Question

我在 django 视图中使用的标准日志记录模块有一个非常奇怪的问题。有时它运行良好，有时它不记录消息。

这是我的代码结构：

/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

这是 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

以下是 uploader/views.py 的部分内容（#... = 已跳过代码）：

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

还有 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"

请注意，除了记录之外，一切正常。数据可以以 JSON 格式正确返回。我认为其余代码没有错误。

如果您需要更多信息，请询问。对于我删除的代码，我很抱歉，但出于保密考虑，我必须这样做。

Answer 1

我建议您不要使用logging.info('My statement') 语法，而是使用以下内容：

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

也就是说，针对 logger 对象调用您的日志语句，而不是直接调用 logging 模块。同样，您必须调整 my_logging.py 来配置该记录器：

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

在您看来，您可以针对logging.getLogger('MySite') 或logging.getLogger('MySite.views') 等进行登录。任何以“MySite”开头的记录器都将继承您的配置。

另外，虽然您通过设置和检查is_initialized 有正确的想法，但我不相信这种方法会奏效。每次导入 my_logging.py 时，该变量都会被设置为 False，从而违背了它的目的。您可以在 settings.py 中使用以下内容来确保日志记录只配置一次：

# 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

我用以下两行开始我的所有模块（settings.py 除外）：

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

如果您仍然遇到问题，请添加这些行，然后为您的站点发布模块初始化顺序。根据您的导入顺序，可能会有一个奇怪的怪癖。