Loading....

In my last post, Log Levels and How to Properly Use Them: Part 1 – Common Log Levels, I went through the standard log levels [ad], and provided general guidance on how to use them in your code. In this post, let’s go through a simple example.

About the Program

Before we start, let me explain what the example program will do. To illustrate the log levels, I developed a simple Python [ad] script that generates random text and saves it into a file. To generate the text, the program will ask the user for four things:

  • How many lines of text to generate?
  • How many words will each line contain?
  • How long should each word be? In a number of characters.
  • And finally, where to save the file with the resulting text?

The functionality is nothing complex, but the point here is to illustrate the log levels and not to overwhelm you with how the program works. I always find it good to outline the program execution steps before I go and write any code (something I call “think before code”). The more complex the system, the more time you want to spend designing [ad] it. For our simple script, here are the high-level execution steps:

  1. Asks the user to specify the number of lines, line length, and word length.
  2. Ask the user the specify the location for the resulting file.
  3. Generate the random text as follows:
    • Generate the word.
    • Add the word to the line.
    • When enough words are added to the line, add the line to the resulting text.
  4. Write the text into a file (with hardcoded name) into the specified folder.

As you can see, there are four main parts of the program execution and three subparts. Because the main parts are quite simple, I decided to put them all in the main()function and to create separate functions for the word, line, and overall text generation. The source code of the program is available in the devbasics GitHub repository. Let’s look at how I used the log levels throughout this program and explain the reasoning behind the choices.

Log Level: INFO

Lines 110-116are the entry point of the program. The first thing that I want to know is whether the program started executing. Hence, I log an  INFOmessage, immediately after the operating system (OS) [ad] gives control to my program. This happens on line 111. Because this is a sample program without any OS control parameters and resources, the message is quite simple but obviously user-friendly.

Another place where log level INFOis used is the last line of execution, right before the control is handed back to the OS. This is line 116and it logs a message that informs that the random text generation is completed. If this message appears in the log, the assumption is that the program completed its execution without any errors.

Log Level: WARNING

The next log level I would like to look at is the WARNINGlog level. As we mentioned in the previous post, WARNINGis used for things that you may want to pay attention of if they continue to happen. Let’s see how  WARNINGis used in the context of this program.

The only WARNINGlog message is generated by line 82. The lines 73-82deal with user input for the number of lines, the line length, and the word length. As you can see from the code, it asks the user for the input in a continuous loop. The loop ends only if the user enters integer values for all the inputs required. If the user enters something else, for example, letter or symbol, an exception will be thrown. However, I catch the exception and gracefully handle it. Not only that ,but the log message provides additional information about what the warning is about and has context data – logs the error that is raised.

Now, the question arises – if this is an exception, why isn’t it logged as an ERRORinstead? Here is the thought behind it! If I log this as an error, it will mean that something is wrong with the implementation. The meaning of ERRORis that something unexpected is happening during the execution of the program and me, as a developer or system administrator, should take immediate action to remediate it. In our case, I have already anticipated the error behavior of the user and wrote the code in a way to help the user to fix her or his mistake. Thus, I don’t need to raise any alarms for the administrator or developer to immediately look at this issue. In essence, if occasional WARNINGmessages appear here and there in the logs, they can be ignored.

However, imagine that somebody tries to abuse my program and enters all king of character combinations in a short amount of time. In this case, I would like to direct the attention of the system administrator to this behavior. In a case like this, multiple WARNINGlog messages in a short amount of time from the same user require the system administrator to block the user. A good example of this is a SQL [ad] injection attack on your site. You may want to log 404 errors as warnings if somebody mistypes an URL to your site, but if you see a lot of 404 errors in a short amount of time, from the same IP address, and adding garbled strings at the end of the URL, then this is a certain reason for concern.

Nevertheless, if the user types the correct inputs after a few mistakes, the program will print some WARNINGlog messages, but will complete its execution and will produce the desired results.

Log Levels: ERROR and CRITICAL

Let’s look at the lines 96-106! Those are the lines that deal with saving the generated text into a file. The file is placed in a location that is previously inputted by the user. We don’t do any validation on the user input for the directory path, which can be considered a shortcoming of our implementation. Hence, when we try to save the file, and the path is invalid, we receive an error from the OS and the file cannot be written to the disk. We have not written any code that can recover our program from this condition, and the issue will be obvious to the user. Thus, we log the ERRORon line 103and because we cannot recover from this error at that point of the execution, we also log a CRITICALmessage  on line  105and exit the program on line 106. If the program exits abruptly, you will not see the INFOmessage from line 116.

Now, keep in mind that Python [ad] has two ways to log an ERRORmessage: using the error()method and the exception()method. I prefer to use the exception()method because it allows me to also log the exception that is raised.

The errors or exceptions raised by the language are not always user-friendly or understandable. Because you are the one who writes the program, you will need to think about what errors can happen at every point of your program execution and handle those properly. But most importantly, you may need to extract information from the underlying exception, and write a more meaningful log message than just logging the message from the raised exception. I will try to find some examples and write another post about meaningful exception handling.

As mentioned above, there is a better way to implement this functionality and make the program much friendlier and robust. But because we have not done that, we at least made sure that the log messages are following the principles we outlined in Log Levels and How to Properly Use Them: Part 1 – Common Log Levels and the execution is predictable.

Running the Program with Log Level INFO

Normally, INFOis the default log level that programs and applications use in a production setting. Let’s go ahead and run the program with that log level and see what will happen. To do that, you need to modify line 21as follows:

log_level = logging.INFO

If you make no mistake while providing the input values, the log will look something like this:

2020-08-19 23:23:51,892 (random_text_v4 --> <module>[111]) [INFO]: Starting random text generation session...
2020-08-19 23:23:56,499 (random_text_v4 --> <module>[116]) [INFO]: Random text generation completed!

You see that the Python logger is set up to write additional information like the timestamp, the script name, the module, and the line number where the log message is executed. This is very useful information for you as we will see later on.

Let’s try to enter some letters instead of numbers for the lines or the line lengths to see what will happen. You will see something like this in your log file:

2020-08-19 23:28:09,211 (random_text_v4 --> <module>[111]) [INFO]: Starting random text generation session...
2020-08-19 23:28:13,091 (random_text_v4 --> main[82]) [WARNING]: Non number provided by the user: invalid literal for int() with base 10: 'd'
2020-08-19 23:28:26,798 (random_text_v4 --> main[82]) [WARNING]: Non number provided by the user: invalid literal for int() with base 10: 'h'
2020-08-19 23:28:35,040 (random_text_v4 --> main[82]) [WARNING]: Non number provided by the user: invalid literal for int() with base 10: 'r'
2020-08-19 23:28:51,361 (random_text_v4 --> <module>[116]) [INFO]: Random text generation completed!

Here, you can see the WARNINGmessages with additional information about why they were raised. Apparently, the user entered d, h, and r instead numbers.

The third test, we will do is to type a wrong path for the file location. Here is how the log may look like:

2020-08-19 23:43:08,630 (random_text_v4 --> <module>[111]) [INFO]: Starting random text generation session...
2020-08-19 23:43:13,738 (random_text_v4 --> main[82]) [WARNING]: Non number provided by the user: invalid literal for int() with base 10: 'd'
2020-08-19 23:43:21,138 (random_text_v4 --> main[103]) [ERROR]: Invalid directory path.
Traceback (most recent call last):
  File "random_text_v4.py", line 98, in main
    with open(file_path, 'w') as f:
FileNotFoundError: [Errno 2] No such file or directory: '/test/random.txt'
2020-08-19 23:43:21,138 (random_text_v4 --> main[105]) [CRITICAL]: Wrong directory path provided by the user

As you can see, the ERRORand the CRITICALmessages are present in the log file as well as the full exception text. Also, you will not see the second INFOmessage, which means that the program didn’t complete normally.

Note that those three log files are generated without any changes of the log level.

Log Levels: DEBUG and TRACE

DEBUGand TRACElog levels are the ones that, if used correctly, can make your life as a developer very easy. Python doesn’t have the TRACElog level as standard but you can use DEBUGinstead. Here is how I used DEBUGmessages according to the guidelines I’ve outlined in the Log Levels and How to Properly Use Them: Part 1 – Common Log Levels post.

  • Line 72is right before the loop that prompts the user for input. If I used a language or framework that had TRACEas standard log level, I would have used TRACEinstead. The purpose of this message is to tell me where exactly am I in my program execution and not what the context is. In Python, I used DEBUGfor the same purpose. The message is descriptive enough to tell whoever reads the log what is the program supposed to do next.
  • Line 84is an actual DEBUGmessage. It is right after the data has changed by the user, and I print the new values of the data. This will be very helpful information for me if something goes wrong later on in the program because I will know what the user has entered. As you can see, I use a human-readable message with dynamic parameters that are replaced with the values the user has entered.
  • Lines 87and 90have the exact same purpose as the previous two – the first one tells me what will happen after that, while the second one logs the result of the user input. You can argue that the purpose of lines 97and 101is the same – the only difference is that the second one doesn’t have dynamic text.
  • If you take a look at the three functions gen_random_string(), gen_line(), and gen_lines(), you will see that each one of them has a DEBUGmessage as a first statement as well as right before the returnstatement. The first DEBUGlogs the input parameters for the function, which gives me information about the context in which this function is called. The second one logs the return value or some property of the return value, so I know what the function produced. Those are very simple functions, and that is why I don’t have any additional log statements but if it was more complex, I would “sandwich” important sections of code where data is changed or important logic steps are executed with TRACE/DEBUGmessages, similar to the previous bullet points.

Using the above approach, if somebody reads the generated log, she or he will be able to easily follow the program execution flow and easily discover issues if such occur. If you run the program using the expected user input, you will see something similar as log output:

2020-08-20 22:40:49,256 (random_text_v4 --> <module>[111]) [INFO]: Starting random text generation session...
2020-08-20 22:40:49,256 (random_text_v4 --> main[72]) [DEBUG]: Prompting user for input...
2020-08-20 22:40:55,775 (random_text_v4 --> main[84]) [DEBUG]: User input completed! Number of lines: 3; Line length: 4; Word length: 5
2020-08-20 22:40:55,775 (random_text_v4 --> main[87]) [DEBUG]: Prompting user for directory path...
2020-08-20 22:41:05,879 (random_text_v4 --> main[90]) [DEBUG]: File path /Users/toddysm/Documents/Development/Projects/Remote/devbasics/logging-example/random.txt
2020-08-20 22:41:05,880 (random_text_v4 --> gen_lines[64]) [DEBUG]: Generating 3 number of lines with 4 line length and 5 word length
2020-08-20 22:41:05,880 (random_text_v4 --> gen_line[47]) [DEBUG]: Generating line with length 4 and word length 5
2020-08-20 22:41:05,880 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,880 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word RrJkI
2020-08-20 22:41:05,880 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,880 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word Cccze
2020-08-20 22:41:05,880 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word nvZUx
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word shwph
2020-08-20 22:41:05,881 (random_text_v4 --> gen_line[49]) [DEBUG]: Generated line with length 23
2020-08-20 22:41:05,881 (random_text_v4 --> gen_line[47]) [DEBUG]: Generating line with length 4 and word length 5
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word rESne
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word EdOQy
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word mfFTi
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,881 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word xosBR
2020-08-20 22:41:05,881 (random_text_v4 --> gen_line[49]) [DEBUG]: Generated line with length 23
2020-08-20 22:41:05,881 (random_text_v4 --> gen_line[47]) [DEBUG]: Generating line with length 4 and word length 5
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word HjKqz
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word UNPYk
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word ZQuJP
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 5
2020-08-20 22:41:05,882 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word bQXTv
2020-08-20 22:41:05,882 (random_text_v4 --> gen_line[49]) [DEBUG]: Generated line with length 23
2020-08-20 22:41:05,882 (random_text_v4 --> gen_lines[66]) [DEBUG]: Generated random text with length 71
2020-08-20 22:41:05,882 (random_text_v4 --> main[97]) [DEBUG]: Writing random text to file...
2020-08-20 22:41:05,883 (random_text_v4 --> main[101]) [DEBUG]: Writing random text to file completed!
2020-08-20 22:41:05,883 (random_text_v4 --> <module>[116]) [INFO]: Random text generation completed!

Note: To see the DEBUGmessages, you will need to modify line 21as follows:

log_level = logging.DEBUG

By reading the log file above, you can understand what the program does:

  1. Right after the program starts (which is obvious from the first INFOmessage), the main()function is called and we prompt the user for input.
  2. We see that the user entered 3, 4, and 5 for the number of lines, line length, and word length.
  3. Then, the user is prompted to enter the file location, and we see the path that he (that’s me) choose.
  4. Next, the main()function passes the execution to the gen_lines()function to generate 3 lines.
  5. gen_lines()function calls the gen_line()function 3 times.
  6. gen_line()on the other side, calls gen_random_string()4 times for each line. After each line is generated, the control is returned to gen_lines()function, and new call to gen_line()is made.
  7. gen_random_string()generates random “words” with length 5. We can also see in the log the word that is generated. After each word is generated, the control is returned to the gen_line()function, and new call to gen_random_string()is made.
  8. Once all the lines are generated, the gen_lines()function passes the control back to the main()function. The main()function then writes the file and exits the program.

Let’s run the program again and generate some errors. Here is the resulting log file:

2020-08-20 23:12:17,838 (random_text_v4 --> <module>[111]) [INFO]: Starting random text generation session...
2020-08-20 23:12:17,838 (random_text_v4 --> main[72]) [DEBUG]: Prompting user for input...
2020-08-20 23:12:20,474 (random_text_v4 --> main[82]) [WARNING]: Non number provided by the user: invalid literal for int() with base 10: 'sd'
2020-08-20 23:12:30,313 (random_text_v4 --> main[82]) [WARNING]: Non number provided by the user: invalid literal for int() with base 10: 'sd'
2020-08-20 23:12:40,711 (random_text_v4 --> main[84]) [DEBUG]: User input completed! Number of lines: 2; Line length: 3; Word length: 4
2020-08-20 23:12:40,711 (random_text_v4 --> main[87]) [DEBUG]: Prompting user for directory path...
2020-08-20 23:12:43,827 (random_text_v4 --> main[90]) [DEBUG]: File path /test/random.txt
2020-08-20 23:12:43,828 (random_text_v4 --> gen_lines[64]) [DEBUG]: Generating 2 number of lines with 3 line length and 4 word length
2020-08-20 23:12:43,828 (random_text_v4 --> gen_line[47]) [DEBUG]: Generating line with length 3 and word length 4
2020-08-20 23:12:43,828 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 4
2020-08-20 23:12:43,828 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word YYPl
2020-08-20 23:12:43,828 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 4
2020-08-20 23:12:43,828 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word JxRo
2020-08-20 23:12:43,828 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 4
2020-08-20 23:12:43,828 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word bpDl
2020-08-20 23:12:43,829 (random_text_v4 --> gen_line[49]) [DEBUG]: Generated line with length 14
2020-08-20 23:12:43,829 (random_text_v4 --> gen_line[47]) [DEBUG]: Generating line with length 3 and word length 4
2020-08-20 23:12:43,829 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 4
2020-08-20 23:12:43,829 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word czDL
2020-08-20 23:12:43,829 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 4
2020-08-20 23:12:43,829 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word eIRw
2020-08-20 23:12:43,829 (random_text_v4 --> gen_random_string[32]) [DEBUG]: Generating word with length 4
2020-08-20 23:12:43,829 (random_text_v4 --> gen_random_string[34]) [DEBUG]: Generated word tsQd
2020-08-20 23:12:43,829 (random_text_v4 --> gen_line[49]) [DEBUG]: Generated line with length 14
2020-08-20 23:12:43,829 (random_text_v4 --> gen_lines[66]) [DEBUG]: Generated random text with length 29
2020-08-20 23:12:43,829 (random_text_v4 --> main[97]) [DEBUG]: Writing random text to file...
2020-08-20 23:12:43,830 (random_text_v4 --> main[103]) [ERROR]: Invalid directory path.
Traceback (most recent call last):
  File "random_text_v4.py", line 98, in main
    with open(file_path, 'w') as f:
FileNotFoundError: [Errno 2] No such file or directory: '/test/random.txt'
2020-08-20 23:12:43,830 (random_text_v4 --> main[105]) [CRITICAL]: Wrong directory path provided by the user

Can you tell what went wrong? Of course! The user tried twice to enter sdinstead of an integer number for the numeric inputs. Then he (yes, me again!) entered /testas a location where the file should be saved. And, of course, because there is no such directory, saving the file failed and the program did not complete as expected.

The above log files are a good example of how you can write log messages that allow you to understand what the program is going without having the code in front of you. Why is this important? Well, first of all, you will not be always the person who troubleshoots your application. The person who reads the logs should be able to understand what is happening. The more details you provide to her or him, the easier will be for her or him to fix the issue. Second, even if you are the one troubleshooting an issue, you may be dealing with a previous version of your code and what is deployed may not match what you currently have in your code editor. Having detailed log messages will be the only way for you to figure out what is happening with a particular deployment.

Hopefully, this gives you a good idea of why detailed and smart logging implementation is important for every application. Doesn’t matter whether your application is deployed in the cloud [ad], on your server in the basement, or on somebody’s smartphone, sooner or later you will need to use the logs to understand what happened. The sooner you establish good logging practices, the better off you will be as a software developer.

, ,

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Back To Top