In part one of this series I looked at how you can run a script in Python via a Graphical User Interface (GUI). I looked at some of the pros and cons of doing this and then walked through a simple example. If you want to recap or revisit the link is below:
In this second part, I want to look at using a logger, so that every time we run the script we can create a .log file to record what happened. Again, this will be a simple example that you can expand on using real world examples that are more relevant to your challenges. This is new to me and this blog is a documentation of my experiences.
One of the ways that really helps me progress in programming is to debug other people’s code. I have found this to be a pretty common occurrence for me. Documenting and writing easily readable code (one of the reasons for using Python in the first place) makes debugging much easier, but sometimes to really understand what is going on you have to use print statements freely to see what is happening from one line of code to another. Not sure what a variable is? Then print it. This still seems to me to be a reasonable way of working.
Why use a logger?
Why not just use print statements? You can certainly still do that and I try and use print statements to let me or the user know what point the code is currently at. One reason to use a logger though is if you potentially want a record of what happened and have a file that you can refer to post-run. It is not always practical to scroll back through multiple lines in a command prompt and if it crashes for some reason you may have lost these messages. So, using a logger makes more sense. In this example I have built a simple GUI with one button that can be clicked many times, with a logger I can record what goes on.
A simple example
Please do check out the following two videos that are an excellent guide to logging and which I used as a guide and based my example on, using the code in these videos.
In this example I will only be making nomenclature changes in the GUI code file ‘blog_script.py’ (from part 1). All the logging work will be done on the scripting file from the previous blog called ‘some_code.py’. I have made a copy of both these scripts and pasted them into a new folder on my computer. I have renamed ‘some_code.py’ to ‘test_log.py’. Currently the code looks like this:
def test(): x = 0 print ("another go") print ('script running') while x < 10: print ('calculating') x += 1
The first thing I am going to do is to rename this method to def main() and add an if statement that says if this file ‘test_log.py’ is called directly run this main method. This is a common way of setting up a Python script. The file now looks like this:
def main(): x = 0 print ("another go") print ('script running') while x < 10: print ('calculating') x += 1 if __name__ == '__main__': main()
Next, add the import statements for the the logging library (it’s part of the standard Python installation) and datetime. We need the datetime so we can use the time the script is run as part of our log file name. To do this we need to use datetime’s strftime function to create the string, and then assign this to a variable called name_out. Finally I am going to print this variable (which is the filename of the log file to be written) out to the command prompt. The file now looks like this:
from datetime import datetime import logging name_out = (datetime.now().strftime("%Y_%m_%d_%H_%M_%S")+".log") print ("log file being written: ", name_out) def main(): x = 0 print ("another go") print ('script running') while x < 10: print ('calculating') x += 1 if __name__ == '__main__': main()
At this point we haven’t yet done any of the logging, but that is all that we have left to do. I am adapting the code in the videos shared above to change the print statements to log statements. First off I need to define the logger. After the print “log file being written” … line and before the main function, add the following lines:
logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) formatter = logging.Formatter('%(asctime)s:%(name)s:%(message)s') file_handler = logging.FileHandler(name_out) file_handler.setLevel(logging.INFO) file_handler.setFormatter(formatter) logger.addHandler(file_handler)
On the first line we are setting up our logger object. You can read in more detail here why this is a good idea. This is done so that if we have multiple logging objects in the future, we can work out what Python script they are coming from. If we do not do this it will print ‘root’ in the log by default at the start of every log entry.
The second line dictates what logging level we want to set as the default – in this simple example all my logs will be logged as INFO. Again, you can read more about them here. The third line specifies the format each log will take (time stamp, filename and finally, the message). The next three lines are all setting up a FileHandler with its filename, default logging level and the format. I am assigning this to an object called file_handler (but you could call this anything you like). On the last line I am adding this Hander to the logger we created above.
Now all we need to do is add calls in our main() to the logger when we’d like to record something. These take the form (for example) like this:
That is all there is to it. My final script looks like this:
## in acknowledgment of https://www.youtube.com/watch?v=jxmzY9soFXg ## and https://github.com/CoreyMSchafer/code_snippets/blob/master/Logging-Advanced/log-sample.py from datetime import datetime import logging name_out = (datetime.now().strftime("%Y_%m_%d_%H_%M_%S")+".log") print ("log file being written: ", name_out) logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) formatter = logging.Formatter('%(asctime)s:%(name)s:%(message)s') file_handler = logging.FileHandler(name_out) file_handler.setLevel(logging.INFO) file_handler.setFormatter(formatter) logger.addHandler(file_handler) def main(): x = 0 print ("another go") print ('script running') logger.info('script running') while x < 10: print ('calculating') logger.info("Position, %s" % x) x += 1 logger.info("loop closed") if __name__ == '__main__': main()
Now when I run my blog_script.py file and click once on the Click me button I get the a log file with the name of the date and time that I ran the code, and it contains the following:
2019-01-05 12:09:18,311:test_log:script running 2019-01-05 12:09:18,312:test_log:Position, 0 2019-01-05 12:09:18,313:test_log:Position, 1 2019-01-05 12:09:18,313:test_log:Position, 2 2019-01-05 12:09:18,314:test_log:Position, 3 2019-01-05 12:09:18,315:test_log:Position, 4 2019-01-05 12:09:18,316:test_log:Position, 5 2019-01-05 12:09:18,316:test_log:Position, 6 2019-01-05 12:09:18,317:test_log:Position, 7 2019-01-05 12:09:18,317:test_log:Position, 8 2019-01-05 12:09:18,318:test_log:Position, 9 2019-01-05 12:09:18,318:test_log:loop closed
Again the format is defined in the formatter object we created in the script above. Date/time,filename and message.
That was a very simplistic logging example using the basic GUI script from part two. It is worth using logs as your scripts get more complex and involved. I still think that using print statements is very useful, but, and especially if someone else is going to run your code, consider creating log files.
In this post we have looked at creating log files in Python, using a simple GUI as an example. We have:
- Built an info logger with a custom format
- Assigned the time the script is run to the filename of the log file
- Added log statements to the existing code that is called when we click the ‘Click me’ button
Coding is for everyone.
I hope this is useful to someone. It was really useful to me, especially as I hadn’t built a logger in the past and was surprised by how simple it is. The code used is available here
I am a freelancer able to help you with your projects. I offer consultancy, training and writing. I’d be delighted to hear from you. Please check out the books I have written on QGIS 3.4
Image credit https://unsplash.com/photos/kUqqaRjJuw0