|
|
posted: January 26, 2019
tl;dr: If you can get away with print instead of logging for Python devops jobs, you may save yourself a lot of hassles...
At my last company pretty much the entire backend of our webapp was written in Python. We had to load a significant amount of client data from a variety of databases, social media, and other third party data sources. We wrote a number of Python ETL (Extract, Transform, Load) jobs to accomplish this, and ran them all on a Dockerized Jenkins server in production, although often the job would start out or be modified on a developer laptop. To complicate matters further, sometimes the ETL jobs had to be run in their own Docker containers, but the jobs were all scheduled, orchestrated, and invoked by Jenkins.
In these Python ETL jobs we decided to use simple print statements anytime we wanted to record an event, such as loading an individual data record with an ID, timestamp, and a few other pieces of metadata. Occasionally someone would wonder why we weren’t using Python’s built-in logging module. An attempt was actually made to introduce the logging module into these jobs, but it failed and we reverted back to print statements. That solidified my position that, if you can make print work for your jobs’ runtime environment, stick with print.
The key lessons learned were:
Think about using print if there is no need to separate user output from operator/system output
Print goes to standard output, whereas logging can be sent to different streams, typically files. In cases where a Python program is interacting with a consumer or user, and that user shouldn’t see messages about the performance of the program, it makes sense to separate user output from operator/system output (in fact it is a requirement). But that wasn’t the case with our data load jobs: there was no consumer or user of a data load job. The jobs were pure devops jobs; the standard output of the job mattered only to the people inside the company monitoring the performance of the jobs.
Print output always is captured by Jenkins and developer console terminals, whereas logging files can end up in strange, sometimes hard-to-access places
This is one of the primary reasons the effort to introduce logging failed. For jobs run on Jenkins, Jenkins already knows how to handle standard output: it captures all of it, puts it in a console log file, does log file rotation (we set up Jenkins to save the console logs from the last 100 builds/runs), and provides an easy-to-use Web UI that even non-programmers can use to take a look at the output from a particular job. If the job was passed by Jenkins to a separate Docker container, the standard output from that job running on the separate Docker container was still captured by Jenkins. When a job was run on a developer laptop, it was typically invoked in a console terminal window, which also captures the output from the job. Or that output can easily be piped into a file. All the places where we ran jobs were set up to handle standard output; we didn’t have to jump through any hoops at all.
By contrast, when the attempt was made to use the logging module to produce log files, those logs files ended sometimes ended up in some strange, hard-to-access locations. It wasn’t so bad for the jobs that natively ran in the Jenkins Docker container, but if Jenkins passed the job to a separate Docker container, the log file(s) would end up there. The file systems of Docker containers are, by design, isolated, and it was hard (but not impossible) to move them from the Docker container back onto Jenkins. But we had trouble codifying this in the job itself such that the job would also work on a developer laptop. It was a real pain to get everything to work nicely across all environments. We could have done it eventually, but it just highlighted what we had thrown away by not using standard output. Managing log files hints at the next major problem:
Print output ends up in Jenkins's console logs and utilizes Jenkins's log rotation functionality, whereas logging files need their own log rotation cod
As mentioned Jenkins can be easily set up to do log file rotation for the console logs, and it makes those logs easily viewable via a Web UI. The Python logging module can, with some difficulty, be used to create log files; but then what do you do with them and how do you prevent them from filling up the disk? Additional code needs to be written to do log file rotation.
The log files can be sent to a separate log server such as an ELK stack (Elasticsearch, Logstash, Kibana), but this is more work that needs to be done. We really didn’t need to do sophisticated analysis of these log files: the primary thing we needed to do was take a look at the log for a job which failed, and figure out what had gone wrong in either the code, the environment, or the data source. The automatically rotated console logs on Jenkins were perfectly suitable for this task. We never got around to fully implementing a solution for log file rotation and centralization when the attempt was made to introduce the logging module.
It’s a lot easier to print("Hello, world!") than to survive a black diamond run unscathed
Python’s print function is the bunny slope (for beginners), whereas the logging module is a black diamond run (experts only)
Every single Python programmer knows how to use the print statement/function. It is almost always the first Python function that beginners learn:
print("Hello, world!")
The Python logging module in the standard library is, by contrast, notoriously hard to understand and counterintuitive. Loggers and handlers have to be set up and passed around the code. Properly implementing log message severities is a challenge. As a result there are many blog posts on the Internet trying to explain how to use the logging module, typically relating the pains experienced by the authors.
Yes, Pythonistas can eventually wrap their heads around the logging module and use it successfully, but not everyone is an expert. It was simpler for everyone to just stick with print statements, which anyone could easily add or subtract from the code. We did implement a verbose mode, but it was just a simple command line parameter that became a global variable that could be easily checked before doing a print statement.
I’m far from the only person who believes that the logging module is difficult. Michael Kennedy and Brian Okken, who each have their own Python-oriented podcasts (Talk Python to Me and Test & Code, respectively), also co-host a weekly Python podcast called Python Bytes, where they recently highlighted the loguru library as a much easier-to-use alternative to the logging module. There’s a reason Python developers continue to try to introduce new, easier-to-use logging modules...
The right tool for the job
I’m definitely not saying that just using print statements to create logs is always the right thing to do. As with every engineering decision, it depends on the circumstances. At my last company, with a very small team that had many more important features to implement, and which did not need a sophisticated logging infrastructure for our ETL devops jobs (as compared to the webapp, which did have sophisticated logging), just using print statements and the built-in capabilities of the devops tools we were using, such as Jenkins, was sufficient. Our biggest log problem was not at all a function of the log system we devised. Rather, it was just finding the time to pay attention to the log files that were created. The truth is often right there in the logs, if you just look.