A More Feature-rich Logging System

Previous chapters have resulted in a minimal logging client-server pair that may work for some applications. They are certainly simple enough to try.

More advanced programmers can even use these two programs as routines in their own code.

The log_cmd_basic offers code trivial to use. Just remember to create the context, then a socket in the mainline. Then pass the socket to other routines where it is needed.

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

The logging code in logging_basic.py should work well for many purposes. I would, however, suggest prefixing all logs with a timestamp.

Serious developers want more. Many useful additions that significantly enhance the usefulness of both server and client.

The items this chapter will address will result in a more useful client-server for logging:

• Add a common configuration file that serves both client and server, both local and remote. Hard-coding port number and IP addresses may be fine for a small number of systems, but as hardware changes and systems change and grow, keeping all the values correct creates a problem.
• Prefix each log with timestamps. This provides information most useful for inspecting exactly when an event occurred.
• Prefix with the client name. With more than one remote client, knowing who sent the log helps.

Begin by copying logging_basic.py to logging_server.py. Also, since we will modify the command line code, copy log_cmd_basic.py to log_cmd.py.

Adding a Timestamp to Logs

For small systems, an easy modification just adds the current date and time to the front of the log before writing:

import sys
from datetime import datetime   # Place after "import sys"
...
while True:
    msg = socket.recv()
    msg_timestamp = '%s %s\n' % (str(datetime.now()), msg)
    log_file_handle.write(msg_timestamp)
    log_file_handle.flush() # Insist on writing immediately

We must import datetime for access to its routines. Place this import near the top of the file after the import sys.

Sticking a timestamp in front of the log requires a string representing “now”. To examine just this logic addition, start a python prompt:

>>> from datetime import datetime
>>> str(datetime.now())
'2017-12-03 11:01:33.412403'
>>> 

The end of “now” has six digits representing milliseconds. If your system does not warrant such precision, edit it out.

With a bit more formatting the message gets logged.

Adding Client Hostname onto Logs

A single client running with a desktop likely does not require that logs be tagged with their source. However, since happiness comes in large quantities, your system likewise will grow.

A log’s origin, hostname, is obtained very easily. On a terminal try the following:

python
>>> import platform
>>> platform.node()
'raspberry1'
>>> 

Perhaps you have never given your raspian system a new host name and are using the default? You can set it by:

1. Type the following command to edit /etc/hostname using vi or nano: sudo vi /etc/hostname . Delete the old name and replace it with your new hostname.
2. Edit /etc/hosts and replace raspberry1 with the new name. “raspberry1” is a few lines down /etc/hosts.
3. The system must be rebooted for the changes to take effect: sudo reboot.
4. When reboot has finished, check that the hostname has been changed. In a terminal: hostname.

By a simple formatting the client’s hostname gets added to every log. On the raspian system in file log_cmd.py:

import platform      # < -- Add this after import sys
...
# REMOVE: log = ' '.join(sys.argv[1: len(sys.argv)])
log = platform.node() + ' ' + ' '.join(sys.argv[1: len(sys.argv)])

WAIT! This log message mangling works perfectly fine for our dumb command line logging. But suppose we want send from anywhere in our code. Do we really want to write this same code everywhere? Of course not.

The solution is to create a function that handles this decoration for us. This function adds the domain to the front of the log. While this send_msg() does not necessarily enhance the log_cmd app, in larger programs this would be the way to send logs.

Log_cmd now looks like:

Question: Why didn't we place the timestamp here as well? We somehow added the timestamp in the logging_server instead of here?

The answer: "It depends...". A timestamp could definitely originate in log_cmd. My thinking was that multiple remotes may have different times on their clocks. This would create difficulties in interpreting log files: which reading of time should I assume is the correct time?

By placing the timestamp into the logging app, logs get stamped in order of receipt.

Log_cmd.py Running on Remote System

When using log_cmd.py on a remote system, a minor one line change transforms the base log_cmd.py.

The magical ZeroMQ sockets need the IP address of the desktop. As before, run ifconfig on the desktop and look "inet 192.168.1.80" under the en01, en02 or similar section. Your IP address will almost certainly be different than 198.168.1.80!

With that IP address, change the socket.connect line:

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

Test this change on the remote by issuing log_cmd a few times. Check that the desktop has your logs. Also, check that the logs have a timestamp, a hostname and the command line args.

The second send_msg() in log_cmd exists only to prove invoking send_msg() works as claimed.

This second send_msg(), the last line in log_cmd.py, may now be removed.

Links

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