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('我的信息') 这种写法，我建议你用下面的方式：

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

也就是说，你应该通过一个日志记录器对象来调用日志语句，而不是直接使用 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__))

如果你仍然遇到问题，请添加这些代码行，然后把你网站的模块初始化顺序发出来。可能会因为导入的顺序而出现一些奇怪的问题。