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.
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
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
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
$ ./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:
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:
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,
runs this script as python code. As a result, the
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
highlight possible future changes in code. By an all-caps name, these
indicate no changes in these values. The variable
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
the ZeroMQ socket wait until a message appears. This message gets written and then
immediately forced into the log file.
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
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
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.
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.
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.
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.
All the code discussed: PyIoTMessaging in github in the PyIoTMessaging/ch02 directory.