Monitor your factory floor fleet of ESP nodes with rsyslog!

As we start deploying our esp32 based devices onto the factory floor, we often run into the need to track down a problem or examine what a device has done.

When the device is on your desktop, its as easy as connecting to the USB port and looking at all the “LOG_X” messages that you added to your code so that you could understand if the device was operating correctly.

So what do we do when we have dozens of devices deployed on the factory floor, and no way to plug into the device serial port?

It turns out that it is possible, with a little bit of code, to collect all the log messages from all of the nodes on the factory floor in a single place where we can use tools like logstash, elastic search and kibana to analyze device behaviours.

In order for this to happen, we need three building blocks. The first is a rsyslog server running on a monitoring device like a workstation on the factory floor network. The second is a rsyslog client installed on the esp32 node that can take log messages and post them to the rsyslog server as they are generated. The third is to patch the ESP32 logging system so that log messages go to the syslog client. We will look at each block and see how they are put together.

Configuring the rsyslog server

Most modern linux systems (eg Ubuntu) come with a pre-installed rsyslog server. If your monitoring server does not come with this installed, please follow your distribution instructions to install it. We assume here that you have already done so.

There are two things that we need to do in order to have the server accept messages from our nodes. The first is to enable acceptance of messages, and the second is to configure where and how our messages will be logged.

Edit /etc/rsyslog.conf and turn on UDP syslog reception.

# provides UDP syslog reception

module(load=”imudp”)

input(type=”imudp” port=”514″)

Create a configuration file in /etc/rsyslog.d to specify the handling of your messages. Here is what out file looks like:

local0.=info    /var/log/iotready.log

Rsyslog uses the concept of a “facility” and a “severity” to classify incoming messages and to direct them to a specified logfile. The configuration above says that we are capturing local0 facility messages and only those of severity info to the iotready.log file.

Facilities and severities have numeric values. The combination of the facility value and the severity value yields a priority value for a message. The priority value will be set in your rsyslog messages to direct messages correctly. In our case our chosen facility and severity result in a priority value of 134. Refer to the rsyslog documentation if you want the details.

Now that logs are being created, it is necessary to add the log file to logrotate so that they can’ grow indefinitely. To do this we edit /etc/logrotate.d/rsyslog and add a configuration for our log.

{

rotate 7

daily

missingok

notifempty

delaycompress

compress

postrotate

/usr/lib/rsyslog/rsyslog-rotate

endscript

}

Finally, in order to make the system self configuring we need one more capability, that is a way for esp32 nodes to find the rsyslog server. We do this using mDNS. The server advertises on the network to allow nodes to find it.

Advertising uses AVAHI, an mDNS implementation that is installed by default on most linux systems. We add our service description to the /etc/avahi/services directory. Here is our syslog.service description:

<?xml version=”1.0″ standalone=’no’?>

<!DOCTYPE service-group SYSTEM “avahi-service.dtd”>

<service-group>

<name>rsyslog service</name>

<service>

<type>_rsyslog._udp</type>

<port>514</port>

</service>

</service-group>

ESP32 rsyslog client

The simplest way to build this capability is to create two functions. One for initialization to setup and establish a connection from the esp32 device to the syslog server, the second to handle the log redirection. Initializing the connection is standard socket code. We need a port number and the syslog server IP address to do this.

We do this in two steps. First each node creates a unique hostname for itself by concatenating a prefix string with the last three octets of its mac address. Then each node carries out a mdns query, looking for the rsyslog service over udp (_rsyslog._udp). We look for the first instance of this service found on the network and use the corresponding IP address and port for initializing the socket client.

Diverting the ESP32 LOG_X messages.

ESP-IDF has a full fledged logging library. Included as a part of this library is the ability to add your own handler for outputting log entries. While the default log output is to UART0, ESP IDF provides an API that allows us to redirect the log output to some other handler. The only restriction is that the handler must have the same signature as the “vprintf” function ie handle a format string and a va_list of arguments to be logged. When called, it returns the original handler so that it is easy to switch logging back.

Putting it all together

The example here provides the mDNS handler, the syslog client and a main routine that ties all the pieces together into an implementation.

Here is a capture from a linux rsyslog server of an ESP32 logging a burst of 25 error messages and then an information message indicating that it is going back to logging on the UART.

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11153) SYSLOG: Message no. 0 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11153) SYSLOG: Message no. 1 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11153) SYSLOG: Message no. 2 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 5 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 6 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 7 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 8 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 9 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 10 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 11 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11163) SYSLOG: Message no. 12 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 13 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 14 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 15 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 16 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 17 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 18 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 19 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11173) SYSLOG: Message no. 20 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11183) SYSLOG: Message no. 21 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11183) SYSLOG: Message no. 22 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11183) SYSLOG: Message no. 23 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11183) SYSLOG: Message no. 24 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 E (11183) SYSLOG: Message no. 25 

Jan 24 20:22:02 10.0.0.10 IoTReady-34C098 I (11183) SYSLOG: Returning to UART logging

Each line from the LOG_X invocation in the ESP32 results in a timestamp, the IP address of the node sending the message, its hostname, the kind of log message (E = Log_E, I = LOG_I etc) the ESP time stamp and message.

I hope this information will help you monitor and debug your product on the factory floor !