A Minimal Logging Example

By implementing a minimal logging application, we begin our journey into messaging by creating a logging app that gets used in almost all subsequent chapters.

By using a strict minimalist approach, ease of understanding builds confidence in the messaging approach. We introduce a fully functional logging system with no bells or whistles to distract the core logic.

A really nice logging application can use this as scaffolding.

Additionally, to prove the logging application works, we provide a minimalist application that sends logs send logs to the logging app.

NOTE: Due to the length of code, please download from PyIoTMessaging. The code discussed in this blog is in the ch02 directory.

Why Logging?

Any non-trivial application I have written has included some kind of logging.

Some reasons to include logging in almost any non-trivial apps:

• Error Resolution: When (not if, when) errors pop up, you may get a stack trace. While helpful, this does not provide a context and history towards the actual error. Additional log information can make resolution much easier.
• Debug Live Systems: Logs provide the way to debug live systems. When no one is around and something goes wrong, how will you know what to fix? Even if someone is around, can you easily collect all the necessary information for debugging? In some cases, yes, you can. In many other cases a error report without a context can be tricky to decipher problems. When your system grows to multiple credit-sized computers, this problem becomes even more daunting.
• Statistical Analysis: If you need any graphs or spreadsheet data from your systems, logging can provide this information.
• Capacity Planning: While not usually a problem with home systems, businesses can use logs to monitor activity that indicates additional resources.
• Diagnostic Logging: What happens when a failure disrupts your system?
• Audit Logging: This can be a business requirement. Logging can capture these parameters and pass them on to auditors and legal teams.
• Profiling information: This can help determine where your code spends time. This could also indicate features not used.
• Unexpected statistics when writing the program: I have been asked to provide graphs of behavior over time. The necessary data may be extracted from the log files with a bit of grep+awk+python ninja tricks.

Logging information can easily turn into an addiction with value without justification. For every situation where logging becomes gratuitous, a targetted information filter could offer more value.

Capturing exception information is a must because it can be very helpful to some extent. But sometimes exception information is not enough. If application user/client can’t report an error with proper information, debugging may be difficult.

Write logging code anticipating that you may one day have to debug a situation where ALL you have is the log file, and doing it right may be the difference between getting fired and getting promoted.

The Minimal Logger

An absolute, but ugly, working logger could look like:

#!/usr/bin/env python
import zmq
log_file_handle = open('./log.txt', 'wa')
context = zmq.Context()
socket = context.socket(zmq.PULL)
socket.bind('tcp://*:5555')
while True:
    msg = socket.recv()
    log_file_handle.write(msg + '\n')
    log_file_handle.flush()

This will work, but any reasonable programmer will object with “UGLY!” (or worse).

Imagine if you used this and six months later had to somehow modify this. Could you remember what all the strange zmq calls did? And how your new changes should fit in? Now give this code to a friend and ask them add your changes. They likely will have troubles understanding what to change and where.

A MUCH Better Minimal Logger

Consider this as a reasonable looking minimal logger:

While four times longer, this code contain documentation to use this app, separate variables for the port and log file name and reasonable comments that clarify what little logic this program uses. Your friend will appreciate this version.

When this code gets run, nothing appears to happen. It looks like it just hangs. However, the infinite loop waits and waits for log messages.

Sending logs to the logger

A logging app remains worthless unless logs can easily be sent to the logging app. While we could show another ugly 10 line log sender, we prefer to show an understandable version:

Demonstrate the Logging App

Let’s perform a demonstration of the code so far. Then we will detail the functioning of all the code.

Open two terminals and in each cd to the directory of the above two files. In one terminal start the logging app:

    python logging_basic.py

After entering this line, nothing appears on the terminal. This is expected behavior. The logging app awaits a log. Specifically, the app waits at the logging line containing socket.recv().

On the other terminal, use log_cmd_basic to enter a few logs as below. The command line arguments become the logged entries so they don’t matter for our purposes.

NOTE: If you chmod a+x in the directory of the source files, you don’t have to prefix each command with python ...

    $ ./log_cmd_basic.py arg1 arg2 arg3
    $ ./log_cmd_basic.py 213 32456 dsf 234
    $ ./log_cmd_basic.py args get logged into log.txt
    $ cat log.txt    # Examine log contents
    arg1 arg2 arg3
    213 32456 dsf 234
    args get logged into log.txt

Let’s notice something else about this code. Courtesy of the powerful ZeroMQ sockets, attempting to log a message when the logger is not running results in log_cmd_basic hanging. It waits until the logger is running.

Kill logging_basic with Ctrl-C if it is still running. Now restart log_cmd_basic. Log_cmd_basic will hang.

After noticing this behavior of waiting, start the logging app: python logging_basic.py. The log_cmd_basic.py will immediately send the log and will terminate.

Is this cool or not?

Details of logging_basic.py

The code starts with a mysterious looking line:

    #!/usr/bin/env python

This line uses the character sequence #!, called “shebang” to inform the linux program loader to interpret the remainder of the line as an interpreter directive. Thus, /usr/bin/env python runs this script as python code. As a result, the python in front of python script names becomes unnecessary.

The comment lines at the top document the purpose of the module and contains details for users to properly use the code. A more practical, enhanced app would detail the various functionalities.

The assignments of LOG_FILENAME and PORT highlight possible future changes in code. By an all-caps name, these indicate no changes in these values. The variable log_file_handle simply records the opening of the log file.

Now the three lines that enable the magic of ZeroMQ sockets.

The context gets created by the zmq.Context(). All ZeroMQ operations depend upon a context. Without a context, ZeroMQ won’t be able to create sockets. You should create and use exactly on context in your process. However, if you fork() or otherwise create another thread, each thread needs its own context.

Creating a socket uses the zmq.PULL variety. ZeroMQ offers multiple types of sockets, each with specific features and requirements. In the log_cmd_basic.py we match this socket with a zmq.PUSH socket.

A socket does not live alone. Without a port, a socket does nothing. A port is an endpoint of communications in an operating system. The logging code “binds” this communications line to a socket and provides the end to receive data. In our example we have chosen port 5555. Any data on port 5555 will be received by the logging program. Any number of apps can send messages to port 5555, but only the app that binds port 5555 will receive the messages.

A simple, infinite loop concludes this code. By calling socket.recv() the ZeroMQ socket wait until a message appears. This message gets written and then immediately forced into the log file.

The flush() command forces whatever has been read into the user specific log file. Without this, the log entries will buildup in a data area, a buffer, until the buffer is full and then the log entries will be dumped. In our case, we want the logs to be written immediately.

Details of log_cmd_basic.py

The log_cmd_basic app gets coded easily with simple logic. A few comments clarify this logic.

This code in the skeleton form:

import sys
import zmq
PORT = 5555
context = zmq.Context()
socket = context.socket(zmq.PUSH)
socket.connect('tcp://localhost:%s' % PORT)
log = ' '.join(sys.argv[1: len(sys.argv)])
socket.send(log)

The two imports at the top bring in sys for the join() and zmq for the messaging logic.

PORT has been factored out to highlight the port number with the intention of easy verification later.

The zmq context gets created. This must exist before any other zmq calls can be performed. One and only one context may exist.

The socket creation uses zmq.PUSH as the socket type. Later we will explain our usage of the various ZeroMQ socket types.

The connect creates a connection with the logging_basic code which uses a bind on the same port.

The specific parameters of a connect:

• “tcp”: Refers to Transmission Control Protocol; one of the main protocols of the internet.
• “localhost”: This defines that the endpoint where the message is on the local computer.
• “PORT”: The port number, 5555.

The soft-coding of this parameter using PORT must be translated into a specific string that gets passed to the zmq connect routine. For our port, this string becomes: ‘tcp://localhost:5555’.

The log message gets taken from the command line arguments. The call to join() takes all the command line arguments and creates a single space-separated line.

To illustrate the behavior of join, start a python prompt and enter:

    >>> args = ['Hello', 'world', 'once', 'again']
    >>> ' '.join(args)
    'Hello world once again'
    >>> '='.join(args)
    'Hello=world=once=again'
     >>> 

In sys.argv the program and command line args get collected as a list. However, when selecting the command line args, we must skip over the program name locate at sys.args[0].

The join returns a string in which the elements of the command line arguments have been joined by a space.

The initial command line arguments, the program name, has been skipped.

Remote Logging

Let’s amp up our basic logger by sending logs from our Raspberry Pi to the desktop. When we know how to send logs with one remove system, we can use the identical code for any number of remote systems.

Using our log_cmd_basic code, a simple one-line change creates this magic.

Refer to our previous instructions on finding the IP of the desktop system. This IP address replaces the “localhost” in the connect. The IP address of 192.168.1.85 must be replaced by your IP address!

In log_cmd_basic.py on the Raspberry Pi system:

     socket.connect('tcp://localhost:%s' % PORT)
     socket.connect('tcp://192.168.1.85:%s' % PORT)

To test this, start the logging app on the desktop. The, on the remote Raspberry Pi system:

    python log_cmd_basic.py Hello world from a remote system

The arguments ‘Hello world from a remote system’ should be logged into you log file on the desktop.

Congratulations! You now can send simple messages from one system to another system with almost no coding. As you can understand this simple framework, you can easily expand and morph this into your own needs.

Summary

The basic logging app has been presented along with a basic app to send logs via the command line to the logging app.

These programs can and will be expanded upon in future blogs. They simply illustrate a useful skeleton logic.

Various trade-offs were made in presenting these two programs. The code needs:

• Remote considerations. A program may wish to live on one system and log to another system. This is easy, but require a bit more logic to provide a stable environment.
• DHCP may create problems due to most home routers sometimes changing IP addresses on reboots.
• Log levels. Not all logs are always interesting.
• Timestamps. A timestamp should prefix each log. This is easy to code, but needs a bit of though because two computer systems may not agree upon the same exact time. For a home system this may not be important.
• Dynamic log levels. Integration testing involves running the entire system, or portions thereof, and injecting tests. A way of changing log level at any time could be useful.
• Log filtering. Examining a text file can be tedious because the current implementation may yield an extremely long text file. Better ways can significantly ease this problem.

Links

All the code discussed: PyIoTMessaging in github in the PyIoTMessaging/ch02 directory.