Enhancing log_client and log_server

The previous versions of log_client, called “log_cmd”, and log_server were indeed primitive.

While these could be used as they are written, with a few additional options, they could turn into really useful tools.

The log_server could become the core of a solid system much more easily extended to whatever application it lives in. Using log_server in most any application could be as simple as “import log_server” and calling a few routines.

Additions to log_server include adding logs to a database, filtering the logs either before or after storage, a graphical module that reads from either text or database storage, etc.

The log_client should remain as a test and performance utility passing test logs to log_server. Executing log_client from different systems using “host=” and with multiple instances could really exercise system capabilities.

Measuring systems throughput and loading times can result in overall confidence of systems worthiness.

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

More Features for log_client.py

The original log_cmd.py provided one of the simplest programs that could work. Now is the time to turn this into a more useful tool.

Developing code seems to release a never-ending slew of ideas. Because log_client.py provides a test driver of log_server.py, adding features to log_server.py implies log_client.py should provide command line access to new features.

Rename the previous log_server tester from log_cmd.py to log_client.py. log_client still runs from the command line, but the term “client” fits in better with standard message naming conventions.

Add run-time options because the same logging requests can get configured from the command line. This implies a more unix-like operation of a flexible tool. The added options as displayed by the --help option:

./log_client.py --help

Testing utility to send log messages to the server.

This application simulates logs sent to
the logging server.

As a testing utility, this code has more
run-time options that might be expected.

The current hostname prefixes each message.

Usage:
    ./log_client.py [--port=port#]
            [--host=ahostname]
            [--log_msg=a_log_msg]
            [--sleep=0]
            [--count=number_msgs]

Where:
    --port=port#        - The port number for messaging.
                          Default: 5555
    --count=number_msgs - The # messages to send to log server.
                          Default: 10
    --host=ahostname    - The name of the host where server lives.
                          Default: localhost
    --sleep=sec_sleep   - Seconds to sleep between messages.
    --svr-exit=true     - true to send exit msg to server at end
                          Default: false
    --log_msg=a_log_msg - The message to send to log server.
                          Default: 'A log message'
                          --log_msg=@EXIT@   causes the server to exit.

–port: A Channel to Communicate

A port is an addressable network location implemented in the operating system that allow code to provide different services.

The server and client must agree upon this port. The client uses to port to send messages to the server. The server accepts all logs sent to this port.

An incorrect port may hang the log_client.py or it may interact with another program using this port in strange and interesting ways.

The port must be an positive integer less than 65,535. Ports 0-1023 are “well known ports” also known as system ports. Unless you know what you are doing, stay away from these ports.

ZeroMQ commonly uses port 5555 in their documentation, but you may use most any convenient port.

To assist in using a valid port for the log_client when the log_server is running, use the listening_port utility:

./listening_port.py 5555
Port 5555 : listening thru pid 5699 ./log_server.py

The above output shows the log_server will read on port 5555. The pid of log_server is 5699. This pid is almost certainly different on your system.

–host: The System of the Server

For a log_server on the local system this would be localhost or 127.0.0.1. For a remote system, this is either the IP address or the system name.

To verify the system may be seen through your network, run the “ping” utility:

ping localhost
PING localhost (127.0.0.1) 56(84) bytes of data.
64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.055 ms
64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.076 ms
^C
--- localhost ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 999ms
rtt min/avg/max/mdev = 0.055/0.065/0.076/0.013 ms

Similar results appears from ping 127.0.0.1 and ping 0.0.0.0.

A named website may also be used:

ping google.com
PING google.com (216.58.194.174) 56(84) bytes of data.
64 bytes from sfo07s13-in-f174.1e100.net (216.58.194.174): icmp_seq=1 ttl=53 time=30.3 ms
64 bytes from sfo07s13-in-f174.1e100.net (216.58.194.174): icmp_seq=2 ttl=53 time=29.7 ms
...

Ping provides a useful utility to test reach-ability through your network.

–count: How Many Messages to Send

Very straightforward. A positive integer that sends “count” messages to the server. The log_client utility includes an index number with each logs sent.

–sleep: Wait Between Messages

Sometimes, particularly in debugging, a slow, methodical stream of messages assists. The --sleep allows fine tuning of message throughput.

The default of --sleep=0 gets used to measure system throughput. Message get sent as fast as possible.

–log_msg: What Message to Send

This supplies a message to send to the server. If the message contain spaces or tabs, enclose the message in either double or single quotes.

The client logic adds a count to the end of the message. As a testing tool viewing the message count in the logs can highlight how and when a message was sent.

Additionally, send_msg() prepends the platform name to all messages. When working with multiple systems, the log messages clearly indicate the source of each message.

–svr_exit: Shut the Server Down

Using a message to shut the server down may appear to be a round-about way when Ctrl-C is so simple.

But this provides an alternate method for a remote system to shutdown a server. Also, this option provides a convenience when running tests. For example, a bash script that starts a server, sends messages and then shuts the server down enjoys this convenience.

Log Server Code Logic

The log_server codes the primary component for logging. This log service may have an arbitrary number of clients and the clients may reside on local or remote systems.

Unlike log_client, log_server code is meant to operate in a production environment. Adding startup options for various configurations enhances the worth of this code.

The log_server code previously just ran a simple receiver of logs that stored them into a text file. That text file grows and grows. For low volume work, this procedure work well: simple and straightforward.

The following start-up options have been added to configure the log_server:

./log_client.py --help

Testing utility to send log messages to the server.

This application simulates logs sent to
the logging server.

As a testing utility, this code has more
run-time options that might be expected.

The current hostname prefixes each message.

Usage:
    ./log_client.py [--port=port#]
            [--host=ahostname]
            [--log_msg=a_log_msg]
            [--sleep=0]
            [--count=number_msgs]

Where:
    --port=port#        - The port number for messaging.
                          Default: 5555
    --count=number_msgs - The # messages to send to log server.
                          Default: 10
    --host=ahostname    - The name of the host where server lives.
                          Default: localhost
    --sleep=sec_sleep   - Seconds to sleep between messages.
    --svr-exit=true     - true to send exit msg to server at end
                          Default: false
    --log_msg=a_log_msg - The message to send to log server.
                          Default: 'A log message'
                          --log_msg=@EXIT@   causes the server to exit.

The switches allow various configurations to the server. While basic, they have proved their worth in use.

The ECHO and EXIT Meta Messages

At certain times the convenience of printing logs to the console becomes necessary to debug or monitor certain situations. This not only includes debugging, but just watching events developing.

The --echo=true and --echo=false optional switch applies only to server startup. The clients may send meta messages to change this value.

A “meta message” allows control over processing within the server. Currently the EXIT and ECHO messages dynamically reconfigure the server.

EXIT Meta Message

Any client may send the exit message that causes log_server shutdown. After the log_server has started, send:

./log_client.py --log_msg=@EXIT@

The server should immediately exit.

ECHO Meta Messages

Start echoing logs to the console by the following meta message:

./log_client.py --log_msg=@ECHO=true@
... Continue working, sending logs, etc.
./log_client.py --log_msg=@ECHO=false@
... Stops logging to console. Normal logging to file.
... Continue working, logging, etc.
./log_client.py --log-msg=@EXIT@  # Server exits

The above examples uses log_client to first send a log with the message contents “@ECHO=true@” and then a log with message contents of “@ECHO=false@”. The the log_client shuts down the server with a log message of “@EXIT@”.

Server Logic

The enhanced logic extends the skeleton log-server from previous chapters.

The command line gets parsed in process_cmd_line using standard python routines, specifically getopt. While multiple parsers of the command line, exist, getopt remains rather standard and easy to use.

Opening the log file with open_log_file_for_writing() uses the --log_append setting to either truncate or concatenate the log file.

The ZeroMQ environment uses setup_zmq() as a create method and the mainline receives both the context and socket.

An “infinite” loop proceeds to wait for logs and adds a timestamp to that log.

If echoing was requested, that log gets printed. Any @ECHO=...@ meta messages get handled in the echo_message_detector() routine.

If the @EXIT@ meta message was received, the “infinite” loop exits and the log_server terminates.

WARNING: Any logs queued behind the @EXIT@ disappear upon exit!

Determining whether any logs remain in the queue or even the number of logs in the queue presents an impossible problem for the ZeroMQ libraries. While logs may live in the processing queue, they may also be “on the wire”, that is, in transmission. It’s not possible to detect this as these logs exist outside the local software.

A word about the flush(). This routine slows down the log_server because each log gets handled by the system logs and send the log to the log file, line by line. This is expensive. Use the flush() only in debug situation where the server may crash.

In production, logs get buffered and flushed only when the log buffers are full. This is much faster.

Running log_server and log_client

Just like the previous servers and clients, start the log_server in one terminal, and in one or more other terminals, start the client(s). Use whatever optional arguments you like.

./log_server.py      # Start in one terminal
...
./log_client.py --count=10 --log_msg=hello # in another terminal
... Repeat above log_client with different log_msg

Then terminate the log_server:

./log_client --log_msg=@EXIT@

Now look at log.log (unless you sent the logs to a different file).

Mix it up. Start a few clients first, then the server.

./log_client.py --count=10 --sleep=1 --log_msg=sleep-1

Notice log_client appears to do nothing. Actually log_client stills send messages to the ZeroMQ code. Since log_server has not been started, ZeroMQ waits until it can send these queued messages.

The output of log_client then reports “Client exiting” and it still appears to hang. Again, ZeroMQ awaits someone on port 5555 to accept the messages.

Start log_server and the list of messages seemingly appears instantly:

./log_server.py --echo=true
./log_server.py log_filename=./log.log echo=True port=5555 log_append=True 
2017-12-25 09:19:07.170965 metali2 0: sleep-1
2017-12-25 09:19:07.171122 metali2 1: sleep-1
...

When log_server accepts the messages, log_client finally exits.

Now kill log_server any way you wish; with a Ctrl-C or a message.

This time, start log_server with echo turned on:

./log_server.py --echo=true
./log_server.py log_filename=./log.log echo=True port=5555 log_append=True

Start log_client with a sleep=1 for a message per second:

./log_client.py --count=10 --sleep=1 --log_msg=again
./log_client.py count=10 log_msg=again svr_exit=False host=localhost sleep=1.0 port=5555 
Client exiting

log_client will run for 10 second and exit.

Notice the logs echoed from log_server at once per second.