Logging

TLDR

  • Use Python’s logging facility to print debug information to (locally) the terminal or (on a server) the server log. This allows you to enable and disable kinds of logging.
  • Twilio → MQTT Gateway’s Flask server file contains an example of Python logging. Look for:
    • logger = logging.getLogger("server") that gets a logger named “server”. This name is displayed in the logs.
    • logger.info uses this logger to print information to (as currently configured) standard output.
    • logging.basicConfig(level=logging.INFO) configures all loggers in this app to display information that is printed via its info(), warn(), error(), and critical() methods, but ignore calls to debug().
  • The files in the mqtt_json subdirectory of Bear-as-a-Service also use a logger.
  • Unlike the practice of temporarily inserting print statements in code during initial development or to spot-check a value, it’s standard practice to leave logging statements in server code forever.
  • Heroku logs may be viewed from the More menu in the Heroku web dashboard.
  • No, this is not an obvious place to look.
  • The log aggregate logs from three different processes running on two different (clusters of) servers: Heroku’s build process (blue), the Heroku router (purple), and the deployed server application (orange).
  • In the terminal, run heroku logs to view the last few lines of this combined log. This log includes anything your deployed application has written recently to standard output or standard error, via print or a logger.
  • Run heroku logs -t to start displaying newly logged information — and never stop, until you stop it. This command watches the log, and continuously echos any new information that the deployed application prints while the heroku logs -t process is running.1

Local versus server debugging

When debugging code on your laptop, a few different strategies are available:

  • Run your code, look at the terminal output, add some print statements, repeat. This is probably the first thing you did in SoftDes. You may not have moved beyond this. I never did!2
  • Step through your code in the wonderful Python Tutor. [^This isn’t really on your laptop, but copy/pasting it there, running it, and copying it back, is popular and almost feels the same.]
  • Use an interactive debugging tool, such as pdb, or the debuggers built into IDEs such as PyCharm, or available for Atom and for Visual Studio Code.

If you still still use the first strategy, you are in luck! This is a basic technique for debugging deployed servers!

Here’s the standard workflow for debugging code that’s running on a server:

  1. Deploy your code to the server.
  2. Do something that breaks it.
  3. Examine the logs.
  4. Discover you need more information. Add more print (or log) statements.
  5. Go to step #1.

This is obviously slow. You should do as much development as possible before deploying code to the server.[^ See the article on webhooks and ngrok.] When something breaks on the server, you should try to reproduce it locally. [^ As well as being a more efficient place to debug, this way you may be able to incorporate the code that breaks it into a test case.]

Still, at some point you will debug code that only fails on the server. Sometimes this is because you’re debugging an issue that’s caused by a configuration difference between your workstation and the server. Sometimes it’s because it’s too difficult to reproduce the full server environment locally. And sometimes…

Log everything

There’s one big difference, and one small difference, between adding print-style debugging on your laptop versus on a server.

The small difference is that lines you add, run with, and remove again, usually use print. Why not? It’s simple, and easy to type. [^Ruby uses p, which is arguably even better. But JavaScript uses console.log.] For server code, you’ll generally create a logger, and use a set of methods logger.info, logger.debug, logger.error, etc.

The big difference is that part about removing the statement once you’ve found the issue. This is more typical of local development than of server development. With server code, very often you’ll leave the logging statement in.

This is partly because it can take so long to deploy code to the server. If you remove logging and find another issue, often you’ll wish you’d just left the logging statement in.

But the main reason is that servers tend to get errors that are difficult to reproduce, and that occur when you, personally, are not interacting with them. You’ll get a bug report from the user, or an alert that the server has crashed, and have to go back and figure out what caused the error.

Normal debugging is a like doctor’s examination, where you can ask the patient questions and ask it to demonstrate its range of motion. Server debugging is an autopsy, or detective work at a crime scene. It’s forensics. You want to set things up — plant recording devices and witnesses in good locations — before the crime, so that you can figure out what happened afterwards.

Think, therefore, of server log statements not as scaffolding that you add in order to build something and remove once you’ve built it. Server logging is an integral part of your program, that you want even if you haven’t run into an issue yet. Incidents tell you where you needed more logs. One benefit of running into an issue may be that you can fix it, but even if you can’t, another benefit can be improved log, for next time.[^ In software development, it is worth closing the barn door after the horses have escaped, because there are always more horses.]

Logger Names

The string argument to logging.getLogger("logger_name") is the name of the logger. Multiple calls to logging.getLogger with the same argument return the same logger; this makes for several modules in a package to use the same logger, where this is appropriate. In Bear-as-a-Service, you can see this in the files in the mqtt_json package.

It’s good to use different loggers, because their names are reported in the log, and this gives you some more information about where the printed information is coming from. This also lets you configure different loggers differently, as we’ll see below.

A good choice for a logger name is the value of the variable __name__. Python binds this variable to the name of the current module; for example, in the file sms_bear_gateway.py, its value would be "sms_bear_gateway".

However — a module that is used as the main entry point to the program sees its name as __main__, instead. For example, if you run sms_bear_gateway.py via python sms_bear_gateway.py, the value of __name__ is "__main__", not "sms_bear_gateway". (This is why the if __name__ == "__main__" idiom works.)

This is okay — in any terminal or log file there’s might be only one main program running, so if we see __main__ in a log, and know that terminal or log file is recording information from the SMS → Bear gateway, we don’t really need to see sms_bear_gateway in the log. Also — the log text should be self-describing anyway.

I like my logs to be standalone; I want to be able to tell what’s running in which terminal from its output, not just my memory; and — this is crucial — some server logs are commingled. For example, on Heroku it’s possible to run some web servers and also some worker services. The default Heroku log combines all their outputs into one stream. It’s possible to ask for finer-grained reporting, but it’s nice to spot check things without having to, and also commingled logs have their own advantage: you can see what’s happening across the system, for events that start in one process and have consequences in another.

Therefore, in the example programs, the modules that are intended to be run from the command line don’t use the logging.getLogger(__module__) pattern.

(Because I was in a hurry when I wrote all this code, and quickly copied and pasted logging from one file to another as I was writing them, many of the files previously used the line logger = logging.getLogger('messages') to get the same —mis-named — logger.)

Configuring Loggers

The other advantage of using distinct loggers to log different kinds of messages, or messages coming from different modules in your application, is that you can configure these loggers separately. Despite what I said about recording “everything”, sometimes “everything” is just too much. This can be because:

  • The logs have too much clutter to efficiently examine for the issue you’re focussed on. (Although longer term, you’ll want to invest in tools and techniques for viewing filtered logs in any case.)
  • Keeping all the logged information is expensive. (This isn’t likely at our scale, though.)
  • Some information that’s necessary to debug an issue is sensitive (PII, PCI, FERPA, HIPAA). You don’t generally want it in the server logs, but you need to turn it on — hopefully in a development or staging environment — in order to debug something.

The Hitchhiker’s Guide to Python describes several different techniques for configuring loggers. The configuration includes the amount of information that is actually logged, the boilerplate that’s used to surround a message, and where the logged information actually goes — we’ve been using standard output, which is often appropriate for development and is the only reasonable option for Heroku, but it can also be directed to a file, and different loggers can be directed to different files.

References

  1. -t is short for —tail. In UNIX, the “tail” of a file is the end, and a file tail off forever. Cf. the UNIX tail command

  2. Embarrassingly, I once managed a team that developed a debugger. To be fair, I did use that one, and I’ve used debuggers for Common Lisp, Smalltalk, and C. I just never picked them up for more recent languages such as Python, JavaScript, and Ruby. Maybe someday…