We learned about automated tests in the last chapter, which is great. Now we can write a comprehensive test that will keep our code healthy forever.

Having said that, it’s hard to write truly comprehensive test code as an indie developer. That’s because your users don’t follow the rules when they use your site. Instead, they browse and upload data in weird postures. But that’s not a bad thing, users are natural testers, and they’re cute enough to help you find a bunch of bugs and keep you up through sleepless nights (along with improved programming).

The question is, how do developers know what problems users are having? Most of your users don’t know you, and they’re all over the world. To make matters worse, when deployed online, DEBUG = False is configured so that the error page does not appear, and users themselves do not know exactly where the bug is.

Django gives you the answer: logs.

Log Composition

A log records the status, time, and errors of a program during its running. That is to output or save the information generated in the process of operation for developers to look up.

Django uses Python’s built-in logging module to handle logging. The Use of this module is discussed in great detail in the Python documentation. If you’ve never used it, this article provides a quick start.

The information flow of log events is as follows:

It doesn’t matter if you don’t understand the diagram. You’ll come back to the log later when you need to use it in depth.

A logging configuration consists of Loggers, Handlers, Filters, and Formatters.

Loggers

Logger is the entry point of the log system. It has three important jobs:

  • Expose several methods to your application (that is, your project) to log messages at run time
  • Determine the message to process based on the severity of the message passed to Logger
  • Pass the message that needs to be processed to all interested processors (Handler)

Every message written to logger is a log record. Each log record also contains a level that represents the severity of the corresponding message. The common levels are as follows:

  • DEBUG: Low-level system information used for troubleshooting, usually used during development
  • INFO: General system information, not a problem
  • WARNING: Describes information about minor problems that occur in the system, but usually do not affect function
  • ERROR: Indicates a major problem that may cause abnormal system functions
  • CRITICAL: Indicates that a serious problem has occurred in the system and the application is at risk of crashing

When a Logger processes a message, it compares its log level to the log level of the message. If the message level matches or exceeds logger’s log level, it is processed further; Otherwise the message will be ignored.

When logger determines that a message needs to be processed, it passes it to Handler.

Handlers

A Handler is a processor whose main function is to determine how to process each message in the Logger, such as output to a screen, file, or Email.

Like loggers, handlers have a concept of levels. If the level of a log does not match or is lower than that of the handler, the log is ignored by the handler.

A Logger can have multiple handlers, and each handler can have a different log level. This allows you to provide different types of output depending on the importance of the message. For example, you can add a handler to send ERROR and CRITICAL messages to your Email, and another handler to save all messages (including ERROR and CRITICAL messages) to a file.

Filters

A Filter is a Filter. Filter is used for additional control during logging from logger to handler. For example, only ERROR messages from a specific source are allowed to be output.

Filter is also used to modify log records before they are output. For example, if certain conditions are met, the log level is reduced from ERROR to WARNING.

Filter can be added to both Logger and handler; Multiple filters can be linked together to perform multiple filtering operations.

Formatters

A Formatter determines the form and content of the final output.

Log Configuration Example

I’ve said so many heads that I’m dizzy. Let’s look at two examples.

A simple example

In Django, you can configure the log for an entire project in the form of a dictionary, in settings.py of course. A simple configuration is as follows:

my_blog/settings.py

...
import os

LOGGING = {
    'version': 1.'disable_existing_loggers': False.'handlers': {
        'file': {
            'level': 'DEBUG'.'class': 'logging.FileHandler'.'filename': os.path.join(BASE_DIR, 'logs/debug.log'),}},'loggers': {
        'django': {
            'handlers': ['file'].'level': 'DEBUG'.'propagate': True,,}}}Copy the code

Version in the dictionary specifies the configured version; Disable_existing_loggers specifies whether to disable loggers configured by default. Loggers and Handlers are normally left untouched, but focus on loggers and Handlers configuration:

  • As mentioned earlier, a message is first passed to logger. Several loggers are built into Django, such as the one used hereDjangoLogger, which receives all messages in the Django hierarchy. And then we define what needs to be handledDEBUGAbove levels of messages, and passes these messages to names namedfileProcessor.'propagate': TrueThis means that messages processed by this logger can be processed by other processors.
  • Now the news comes to be calledfilethehandlersIn the now. This handler defines the message processing level as DEBUG, and defines the class to output the message to a file whose address is the project directorylogs/debug.log.
  • Because there is no configurationfiltersandformatters, so the default Settings will be used.

Note that the log output file directory logs/ must be created in advance and that the project has write permission to this directory.

The logging system is configured! Next, run the project and refresh a few random pages to see if any messages are written to debug.log:

logs/debug.log

(0.001) 
            SELECT name, type FROM sqlite_master
            WHERE type in ('table'.'view') AND NOT name='sqlite_sequence'
            ORDER BY name; args=None
(0.000) SELECT "django_migrations"."app"."django_migrations"."name" FROM "django_migrations"; args=() ... . .Copy the code

A lot of verbose information appears in the debug.log file because the debug level contains all database query records.

By default, DEBUG message logs are displayed only in DEBUG mode. When the system is deployed online, only INFO or higher messages are recorded.

Try something else. Change the logger and handler log levels in the above code to INFO:

LOGGING = {
    ...
    'handlers': {
        'file': {
            'level': 'INFO'. }},'loggers': {
        'django': {
            'level': 'INFO'. }},}Copy the code

Refresh the screen a few more times to see what the output looks like:

"GET/article/article - the list/HTTP / 1.1" 200 14438
"GET/article/article - the detail / 32 / HTTP / 1.1" 200 33364
"GET /accounts/login/ HTTP/1.1" 200 7180.Copy the code

Much cleaner this time, the main output is the page pull information.

Let’s take another look at what an ERROR message looks like. Enter a non-existent article details page address in the address bar:

http://127.0.0.1:8000/article/article-detail/9999/
Copy the code

This will obviously result in an error where the data does not exist:

Internal Server Error: /article/article-detail/9999/
Traceback (most recent call last):
  File "E:\django_project\env\lib\site-packages\django\core\handlers\exception.py", line 34.in inner
    response = get_response(request)
    ...
article.models.ArticlePost.DoesNotExist: ArticlePost matching query does not exist.
"GET/article/article - the detail / 9999 / HTTP / 1.1" 500 80792
Copy the code

The ERROR log outputs a backtrace of the entire bug, exactly as you would in your browser, which is very useful information. Basically, ERROR messages reveal most of the problems that users have with your site; That is to say, every ERROR needs to be solved by you. The ERROR code of the ERROR message is usually 500, which is the code of the internal ERROR of the server.

However, if you think about it, it seems that the inability to find the corresponding resource is not a bug in many cases, but rather that the user has made a mistake when entering the URL. Get (id=id); get_object_or_404(ArticlePost, id=id);

article/views.py

...
from django.shortcuts import get_object_or_404

def article_detail(request, id):
    # fetch the corresponding article
    # article = ArticlePost.objects.get(id=id)
    article = get_object_or_404(ArticlePost, id=id)

    ...
Copy the code

After the server restarts, refresh a non-existent page again and look at the log:

Not Found: /article/article-detail/9999/
"GET/article/article - the detail / 9999 / HTTP / 1.1" 404 1780
Copy the code

Instead of an ERROR message, it is now a WARNING, so there is no backtracking (ERROR code 404 instead of 500). Here’s an important difference between the two approaches; There is no consensus on which project to choose, and it depends on your specific needs.

Complex sample

Let’s look at a more complex logging configuration:

LOGGING = {
    'version': 1.'disable_existing_loggers': False.'formatters': {
        'verbose': {
            'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}'.'style': '{',},'simple': {
            'format': '{levelname} {message}'.'style': '{',}},'filters': {
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',}},'handlers': {
        'console': {
            'level': 'INFO'.'filters': ['require_debug_true'].'class': 'logging.StreamHandler'.'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR'.'class': 'django.utils.log.AdminEmailHandler'.'formatter': 'verbose',},'file': {
            'level': 'WARNING'.'class': 'logging.FileHandler'.'filename': os.path.join(BASE_DIR, 'logs/debug.log'),
            'formatter': 'verbose',}},'loggers': {
        'django': {
            'handlers': ['console'].'propagate': True,},'django.request': {
            'handlers': ['file'.'mail_admins'].'level': 'WARNING'.'propagate': False,}}}Copy the code

Let’s break down this configuration.

Two formatters are defined in the configuration:

  • verbose: verbose formatter that outputs message level, occurrence time, thrown module, process ID, thread ID, prompt
  • simple: a concise formatter that outputs only message levels and prompts

A filter:

  • require_debug_true: Messages using this filter take effect only during debugging

Three processors:

  • console: handlingINFOAbove level messages, output brief information to the command line. This handler only works in debug mode
  • mail_admins: handlingERRORAbove level message, output detailed information to Email
  • file: handlingWARNINGAbove level message, output details to a file

Two recorders:

  • django: forwards all messages django produces toconsoleThe processor
  • django.request: Forwards network request related messages tofile,mail_adminsThese two processors. Notice here'propagate': FalseCauses messages processed by this logger to stopdjangoThe logger is processed again

The reader can try making messages of different levels to see if the logging system works properly. Of course, the most important configuration related to Email must be set up in advance, that is, the following content filled with your:

# SMTP server
EMAIL_HOST = 'your smtp'
# mailbox name
EMAIL_HOST_USER = 'your email'
# Email password
EMAIL_HOST_PASSWORD = 'your password'
# Port to send mail
EMAIL_PORT = 25
Whether to use TLS
EMAIL_USE_TLS = True
The default sender
DEFAULT_FROM_EMAIL = 'your email'
Copy the code

Log segmentation

Now that we can log happily, the next question is how to split the log? If your site is lucky enough to run for ten years, it will eventually become a server-dragging behemoth if you keep logging to the same file.

Ideally, logs should be logged and segmented by natural days. Fortunately, you don’t have to worry about this problem. Python has it figured out for you.

Just change the processor a bit:

my_blog/settings.py

...
LOGGING = {
    ...
    'handlers': {...'file': {...# comment out class
            # 'class': 'logging.FileHandler',
            
            # New content
            'class': 'logging.handlers.TimedRotatingFileHandler'.'when': 'midnight'.'backupCount': 30,}},... }Copy the code
  • TimedRotatingFileHandler: Python’s built-in module for splitting log files over time
  • when: Split time is early morning
  • backupCount: Log files are saved for 30 days

Then set the system time back one day and restart the server:

python manage.py runserver --noreload
Copy the code

Note that this startup is a little different, with the –noreload suffix. This is because normally Django’s debug server starts an overload with it, so it automatically restarts the server whenever it detects a code change, which is pretty convenient. The problem is that splitting the file and reloading the log file at the same time will conflict, so use –noreload to temporarily disable the reload.

Then you can happily swipe a few messages into the file. You will notice that the old log has been renamed to debug.log.2019-07-17 and the new messages are saved in debug.log.

In addition to the TimedRotatingFileHandler described above, Python also provides a RotatingFileHandler split by file size. For those interested, see the official Python documentation

Custom Logs

The built-in configuration actually covers more than 90% of your logging needs, but there will always be times when you want to log in some weird places, which will require you to insert your own custom logging code into your code.

Custom logging is also quite convenient to use:

from my_blog.settings import LOGGING
import logging

logging.config.dictConfig(LOGGING)
logger = logging.getLogger('django.request')

def whatever(request):
    # do something
    logger.warning('Something went wrong! ')
    # do something else
Copy the code

Import the logging framework you just wrote and configure Django. request into a Logger object. Then you can place any level of message anywhere. Message content can be formatted in a variety of ways using strings (str.format()).

So much for getting started with logging, but for those who want to learn more, please continue to read the reference article for this article:

  • Django logging
  • Python 3 logging

conclusion

Similar to the previous chapter, this chapter is full of concepts, and I encourage readers to understand as much as possible, or at the very least, to successfully transplant the journal into your project. Getting a good log is sometimes more important than developing a new feature that doesn’t matter.

In contrast, bloggers say that logging is more important than testing for a blog project, because the user experience is best practice.

But don’t get me wrong. Testing and logging are like two brothers, testing solving problems in development and logging solving problems in maintenance. Combine them organically and your project will be healthy for the long term.

  • If you have any questions please leave a message on Doucet’s personal website and I will reply as soon as possible.
  • Or Email me a private message: [email protected]
  • Project code: Django_blog_tutorial