syslogd implementation for OpenThread

README.md

RFC 5424 compatible syslog implementation for OpenThread.

This requires:

• a filesystem of some kind, with stubs for newlib's file I/O functions… we're using SPIFFS with a SPI EEPROM, but there are lots of options.
• a real-time clock with an implementation of gettimeofday… we use a NXP PCF8523 I²C RTC to synchronise a software counter

If sending of a message fails (because buffers are full) and the message severity is high enough, the message is buffered to a file in the EEPROM and will be sent later when comms recovers. Otherwise it tries to send the message straight away. iprintf-compatible formatting is possible on messages.

syslog.c

/* vim: set tw=78 ts=8 noet si: */
/*!
 * VRT WideSky Hub Demo Firmware System Logger
 * (C) 2017 VRT Systems
 */

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>

#include "hostname.h"
#include "syslog.h"
#include "fs.h"

#include <stdlib.h>
#include <sys/time.h>
#include <time.h>
#include <errno.h>
#include <stdarg.h>

#include <openthread/ip6.h>
#include <openthread/udp.h>
#include <openthread/thread.h>
#include <openthread/openthread.h>

#define SYSLOG_BUF_SZ	(512)

#define SYSLOG_CFG	"syslog.cfg"
#define LOGFILE_PRI	"logfile.1"
#define LOGFILE_SEC	"logfile.2"

#define SYSLOG_INIT_DELAY		(5)
#define SYSLOG_NETWORK_DELAY		(10)
#define SYSLOG_CHECK_DELAY		(60)
#define SYSLOG_MAX_BUFFER_USE_PERCENT	(10)

#define SYSLOG_PERSIST_SEVERITY		(4)

/*!
 * System logger re-sender file descriptor.
 */
static int syslog_resend_fd;

/*!
 * System logger timer.
 */
static uint8_t syslog_timer;

/*!
 * Configuration data
 */
struct syslog_config_t {
	/*! Destination IP and port */
	otSockAddr sockaddr;
	/*! TTL for outgoing messages */
	uint8_t ttl;
};

/*!
 * Configuration
 */
static struct syslog_config_t syslog_config;

/*!
 * Socket used for syslog traffic.
 */
static otUdpSocket syslog_socket;

/*!
 * Format a received message into a log buffer and return its size.
 */
static int16_t syslog_format(
		otInstance* instance,
		char* buffer, uint16_t buf_sz,
		time_t timestamp, uint8_t facility, uint8_t severity,
		const char* app, const char* fmt, va_list fmt_args) {
	/* Sum of bytes written */
	int16_t sum = 0;

	/* Converted timestamp */
	struct tm tm;
	if (!gmtime_r(&timestamp, &tm)) {
		/* Invalid timestamp arguments given */
		return -errno;
	}

#ifdef SYSLOG_TRACE
#ifdef SYSLOG_TRACE_FORMAT
	iprintf("%s:%d Format message %s\r\n",
		__FILE__, __LINE__, fmt);
#endif
#endif

	/* Format the message header first. */
	int fmt_sz = sniprintf(buffer, buf_sz,
			"<%d>1 %04d-%02d-%02dT%02d:%02d:%02dZ ",
			/* Priority value */
			(facility << 3) | (severity & 0x07),
			/* Timestamp */
			tm.tm_year + 1900,
			tm.tm_mon + 1,
			tm.tm_mday,
			tm.tm_hour,
			tm.tm_min,
			tm.tm_sec);

#ifdef SYSLOG_TRACE
#ifdef SYSLOG_TRACE_FORMAT
	iprintf("%s:%d Size: %d Buffer: %s\r\n",
		__FILE__, __LINE__, fmt_sz, buffer);
#endif
#endif

	buf_sz -= fmt_sz;
	buffer += fmt_sz;
	sum += fmt_sz;

	/* Append hostname */
	hostname(instance, buffer, buf_sz);
#ifdef SYSLOG_TRACE
#ifdef SYSLOG_TRACE_FORMAT
	iprintf("%s:%d Size: %d Buffer: %s\r\n",
		__FILE__, __LINE__, HOSTNAME_LEN, buffer);
#endif
#endif
	buffer += HOSTNAME_LEN;
	buf_sz -= HOSTNAME_LEN;
	sum += HOSTNAME_LEN;

	/* Append remainder of header */
	fmt_sz = sniprintf(buffer, buf_sz,
			" %s - - - ", app);
#ifdef SYSLOG_TRACE
#ifdef SYSLOG_TRACE_FORMAT
	iprintf("%s:%d Size: %d Buffer: %s\r\n",
		__FILE__, __LINE__, fmt_sz, buffer);
#endif
#endif

	buffer += fmt_sz;
	buf_sz -= fmt_sz;
	sum += fmt_sz;

	/* Append message */
	fmt_sz = vsniprintf(buffer, buf_sz, fmt, fmt_args);
#ifdef SYSLOG_TRACE
#ifdef SYSLOG_TRACE_FORMAT
	iprintf("%s:%d Size: %d Buffer: %s\r\n",
		__FILE__, __LINE__, fmt_sz, buffer);
#endif
#endif
	sum += fmt_sz;

	/* We're done */
#ifdef SYSLOG_TRACE
#ifdef SYSLOG_TRACE_FORMAT
	iprintf("%s:%d Total %u\r\n",
		__FILE__, __LINE__, sum);
#endif
#endif
	return sum;
}


/*!
 * Append a log message to a file for later transmission.
 */
static int16_t syslog_write(const char* log_msg, uint16_t msg_len) {
#ifdef SYSLOG_TRACE
	iprintf("%s:%d write %s\r\n", __FILE__, __LINE__, log_msg);
#endif

	int fd = open((syslog_resend_fd > 0) ? LOGFILE_SEC : LOGFILE_PRI,
			O_CREAT|O_APPEND|O_WRONLY);
	if (fd < 0) {
#ifdef SYSLOG_TRACE
		iprintf("%s:%d Open fails with %s\r\n",
				__FILE__, __LINE__, strerror(errno));
#endif
		return -errno;
	}

	int sz = write(fd, &msg_len, sizeof(msg_len));
	if (sz != sizeof(msg_len)) {
#ifdef SYSLOG_TRACE
		iprintf("%s:%d Write length fails with %s\r\n",
				__FILE__, __LINE__, strerror(errno));
#endif

		close(fd);
		return -errno;
	}

	sz = write(fd, log_msg, msg_len);
	close(fd);

	if (sz != (int)msg_len) {
#ifdef SYSLOG_TRACE
		iprintf("%s:%d Write message fails with %s\r\n",
				__FILE__, __LINE__, strerror(errno));
#endif

		return -errno;
	}

	return 0;
}


/*!
 * Submit a log message immediately.
 */
static otError syslog_tx(otInstance* instance,
		const char* log_msg, uint16_t msg_len) {
	otMessageInfo msg_info;
	if (!syslog_socket.mHandler) {
		return OT_ERROR_INVALID_STATE;
	}

	otError err = OT_ERROR_NONE;
	memset(&msg_info, 0, sizeof(msg_info));
	memcpy(&msg_info.mPeerAddr, &syslog_config.sockaddr.mAddress,
			sizeof(otIp6Address));
	msg_info.mPeerPort = syslog_config.sockaddr.mPort;
	msg_info.mHopLimit = syslog_config.ttl;
	msg_info.mInterfaceId = OT_NETIF_INTERFACE_ID_THREAD;

#ifdef SYSLOG_TRACE
	iprintf("%s:%d tx %s\r\n", __FILE__, __LINE__, log_msg);
#endif
	otMessage* msg = otUdpNewMessage(instance, true);
	if (msg) {
		err = otMessageAppend(msg, log_msg, msg_len);
	} else {
		err = OT_ERROR_NO_BUFS;
	}

	if (err == OT_ERROR_NONE) {
		err = otUdpSend(&syslog_socket, msg, &msg_info);
	}

	if (msg && (err != OT_ERROR_NONE)) {
		otMessageFree(msg);
	}

#ifdef SYSLOG_TRACE
	iprintf("%s:%d res %s\r\n", __FILE__, __LINE__, otThreadErrorToString(err));
#endif
	return err;
}

/*!
 * Read the system logger configuration.
 */
static int syslog_cfg_read() {
	/* Try to read the syslog configuration */
	int fd = open(SYSLOG_CFG, O_RDONLY);
	if (fd >= 0) {
		int res = read(fd, &syslog_config,
				sizeof(syslog_config));
		if (res < (int)sizeof(syslog_config)) {
			res = -errno;
		}
		close(fd);
		return res;
	} else {
		return -errno;
	}
}

/*!
 * Close any existing socket
 */
static void syslog_close() {
	if (syslog_socket.mHandler) {
		otUdpClose(&syslog_socket);
		memset(&syslog_socket, 0, sizeof(syslog_socket));
	}
}

/*!
 * What to do on receipt of a UDP frame?  Ignore it!
 */
static void syslog_recv(void *aContext, otMessage *aMessage,
		const otMessageInfo *aMessageInfo) {
	(void)aContext;
	(void)aMessage;
	(void)aMessageInfo;
}

/*!
 * Open a new socket
 */
static int syslog_open(otInstance* instance) {
	otError err = otUdpOpen(instance, &syslog_socket,
			&syslog_recv, NULL);
#ifdef SYSLOG_TRACE
	iprintf("%s:%d udpOpen = %d\r\n", __FILE__, __LINE__, err);
#endif
	switch (err) {
	case OT_ERROR_INVALID_ARGS:
		return -EINVAL;
	case OT_ERROR_NONE:
		break;
	default:
		return -EIO;
	}

	err = otUdpConnect(&syslog_socket, &syslog_config.sockaddr);
#ifdef SYSLOG_TRACE
	iprintf("%s:%d udpConnect = %d\r\n", __FILE__, __LINE__, err);
#endif
	switch (err) {
	case OT_ERROR_INVALID_ARGS:
		return -EINVAL;
	case OT_ERROR_NONE:
		break;
	default:
		return -EIO;
	}

	return 0;
}

/*!
 * Initialise the system logger interface.
 */
int syslog_init(otInstance* instance) {
	syslog_resend_fd = -1;
	syslog_timer = SYSLOG_INIT_DELAY;

	if (syslog_cfg_read() < 0) {
		return syslog_set_endpoint(instance, "ff02::1", 514, 1);
	} else {
		return syslog_open(instance);
	}
}

/*!
 * Set the endpoint for log messages.
 */
int syslog_set_endpoint(otInstance* instance, const char* target_ip,
		uint16_t target_port, uint8_t ttl) {
	syslog_close();

	otSockAddr sockaddr;
	memset(&sockaddr, 0, sizeof(sockaddr));

	/* Parse the IP address */
	otError err = otIp6AddressFromString(target_ip, &sockaddr.mAddress);
	if (err != OT_ERROR_NONE) {
		return -EINVAL;
	}

	/* Set the message target */
	sockaddr.mPort = target_port;
	memcpy(&syslog_config.sockaddr, &sockaddr, sizeof(sockaddr));
	syslog_config.ttl = ttl;

	int res = syslog_open(instance);
	if (!res) {
		int fd = open(SYSLOG_CFG, O_WRONLY);
		if (fd < 0) {
			return -errno;
		}
		res = write(fd, &syslog_config, sizeof(syslog_config));
		if (res < (int)sizeof(syslog_config)) {
			res = -errno;
		}
		close(fd);
	}
	return res;
}

/*!
 * Process the stored log messages in our EEPROM logs.
 */
void syslog_process(otInstance* instance) {
	if (syslog_timer) {
		syslog_timer--;
		return;
	}

	/* Check that we have a network */
	switch (otThreadGetDeviceRole(instance)) {
	case OT_DEVICE_ROLE_CHILD:
	case OT_DEVICE_ROLE_ROUTER:
	case OT_DEVICE_ROLE_LEADER:
		break;
	default:
		/* No network */
		syslog_timer = SYSLOG_NETWORK_DELAY;
		return;
	}

	if (syslog_resend_fd <= 0) {
		/* Check for written log messages to send */
		syslog_resend_fd = open(LOGFILE_PRI, O_RDONLY);
		if (syslog_resend_fd < 0) {
#ifdef SYSLOG_TRACE
			iprintf("%s:%d Unable to open log file: %s\r\n",
					__FILE__, __LINE__, strerror(errno));
#endif

			/*
			 * Rename the secondary to the
			 * primary, if it exists.  Ignore if it doesn't.
			 */
			fs_rename(LOGFILE_SEC, LOGFILE_PRI);

			/* Wait before retrying */
			syslog_timer = SYSLOG_CHECK_DELAY;
			return;
		}
#ifdef SYSLOG_TRACE
		iprintf("%s:%d Log file opened.\r\n",
				__FILE__, __LINE__);
#endif

	}

	if (syslog_resend_fd) {
		/* 
		 * We have a log file open.  Read the next message and
		 * send it if we can.  Is there buffer space?
		 */
		otBufferInfo buffer_info;
		otMessageGetBufferInfo(instance, &buffer_info);
		uint32_t buffer_usage = buffer_info.mTotalBuffers
			- buffer_info.mFreeBuffers;
		buffer_usage *= 100;
		buffer_usage /= buffer_info.mTotalBuffers;

		if (buffer_usage > SYSLOG_MAX_BUFFER_USE_PERCENT) {
			/* Do nothing for now */
			syslog_timer = SYSLOG_NETWORK_DELAY;
			return;
		}

		/* We have buffer space, and a network. */
		int16_t msg_len;
		int res = read(syslog_resend_fd, &msg_len, sizeof(msg_len));
		if ((res != sizeof(msg_len)) || (msg_len < 26) || (msg_len > 2048)) {
			/* Bad read… assume file is corrupt or end of file */
			close(syslog_resend_fd);
			syslog_resend_fd = -1;
			fs_remove(LOGFILE_PRI);
#ifdef SYSLOG_TRACE
			iprintf("%s:%d Log file closed.\r\n",
					__FILE__, __LINE__);
#endif
			return;
		}

		/* Read the message to be sent */
		char msg[msg_len+1];
		res = read(syslog_resend_fd, msg, msg_len);
		msg[msg_len] = 0;
		if (res != msg_len) {
			/* Bad read… assume file is corrupt or end of file */
			close(syslog_resend_fd);
			syslog_resend_fd = -1;
			fs_remove(LOGFILE_PRI);
#ifdef SYSLOG_TRACE
			iprintf("%s:%d Log file closed.\r\n",
					__FILE__, __LINE__);
#endif
			return;
		}

#ifdef SYSLOG_TRACE
		iprintf("%s:%d Read stored message: %s\r\n",
				__FILE__, __LINE__, msg);
#endif

		/* We have read the message in… send it */
		otError err = syslog_tx(instance, msg, msg_len);
		if (err != OT_ERROR_NONE) {
#ifdef SYSLOG_TRACE
			iprintf("%s:%d Send failed: %s\r\n",
					__FILE__, __LINE__, msg);
#endif

			/* Failed.  Re-wind to try again. */
			lseek(syslog_resend_fd,
					-msg_len - sizeof(msg_len), SEEK_CUR);
		}
	}
}

/*!
 * Send a syslog message.
 */
int syslog_send_va(otInstance* instance,
		uint8_t facility, uint8_t severity,
		const char* app, const char* fmt, va_list fmt_args) {

	/* Retrieve the current system time */
	struct timeval tv;
	int res = gettimeofday(&tv, NULL);
	if (res < 0) {
		return res;
	}

	char buffer[SYSLOG_BUF_SZ];
	int16_t sz = syslog_format(instance, buffer, sizeof(buffer),
			tv.tv_sec, facility, severity, app, fmt, fmt_args);
	if (sz < 0) {
		return sz;
	}

	/* Try to send the message */
#ifdef SYSLOG_TRACE
	iprintf("%s:%d msg %s\r\n", __FILE__, __LINE__, buffer);
#endif
	otError err = syslog_tx(instance, buffer, sz);
	if ((err != OT_ERROR_NONE) && (severity <= SYSLOG_PERSIST_SEVERITY)) {
		/* Try to persist it for later */
		res = syslog_write(buffer, sz);
	}

	return res;
}

syslog.h

/* vim: set tw=78 sw=8 ts=8 noet: */
/*!
 * VRT WideSky Hub System Log
 * (C) 2017 VRT Systems
 */

#ifndef SYSLOG_H_
#define SYSLOG_H_

#ifdef __cplusplus
extern "C" {
#endif

#include <string.h>
#include <stdbool.h>
#include <stdint.h>

#include <stdarg.h>

#include <openthread/types.h>
#include <openthread/ip6.h>
#include <openthread/udp.h>

/* Syslog message facilities */
#define SYSLOG_FAC_KERNEL	(0) /*!< kernel messages */
#define SYSLOG_FAC_USER		(1) /*!< user-level messages */
#define SYSLOG_FAC_MAIL		(2) /*!< mail system */
#define SYSLOG_FAC_SYSTEM	(3) /*!< system daemons */
#define SYSLOG_FAC_SECURITY	(4) /*!< security/authorization messages */
#define SYSLOG_FAC_SYSLOGD	(5) /*!< messages generated by syslogd */
#define SYSLOG_FAC_LP		(6) /*!< line printer subsystem */
#define SYSLOG_FAC_NETNEWS	(7) /*!< network news subsystem */
#define SYSLOG_FAC_UUCP		(8) /*!< UUCP subsystem */
#define SYSLOG_FAC_CLOCK	(9) /*!< clock daemon */
#define SYSLOG_FAC_SECURITY2	(10) /*!< security/authorization messages */
#define SYSLOG_FAC_FTP		(11) /*!< FTP daemon */
#define SYSLOG_FAC_NTP		(12) /*!< NTP subsystem */
#define SYSLOG_FAC_AUDIT	(13) /*!< log audit */
#define SYSLOG_FAC_ALERT	(14) /*!< log alert */
#define SYSLOG_FAC_CLOCKD	(15) /*!< clock daemon */
#define SYSLOG_FAC_LOCAL0	(16) /*!< local use 0  (local0) */
#define SYSLOG_FAC_LOCAL1	(17) /*!< local use 1  (local1) */
#define SYSLOG_FAC_LOCAL2	(18) /*!< local use 2  (local2) */
#define SYSLOG_FAC_LOCAL3	(19) /*!< local use 3  (local3) */
#define SYSLOG_FAC_LOCAL4	(20) /*!< local use 4  (local4) */
#define SYSLOG_FAC_LOCAL5	(21) /*!< local use 5  (local5) */
#define SYSLOG_FAC_LOCAL6	(22) /*!< local use 6  (local6) */
#define SYSLOG_FAC_LOCAL7	(23) /*!< local use 7  (local7) */

/* Syslog message severities */
#define SYSLOG_SEV_EMERGENCY	(0) /*!< Emergency: system is unusable */
#define SYSLOG_SEV_ALERT	(1) /*!< Alert: action must be taken immediately */
#define SYSLOG_SEV_CRITICAL	(2) /*!< Critical: critical conditions */
#define SYSLOG_SEV_ERROR	(3) /*!< Error: error conditions */
#define SYSLOG_SEV_WARNING	(4) /*!< Warning: warning conditions */
#define SYSLOG_SEV_NOTICE	(5) /*!< Notice: normal but significant condition */
#define SYSLOG_SEV_INFO		(6) /*!< Informational: informational messages */
#define SYSLOG_SEV_DEBUG	(7) /*!< Debug: debug-level messages */

/*!
 * Initialise the system logger interface.
 */
int syslog_init(otInstance* instance);

/*!
 * Set the endpoint for log messages.
 */
int syslog_set_endpoint(otInstance* instance, const char* target_ip,
		uint16_t target_port, uint8_t ttl);

/*!
 * Process the stored log messages in our EEPROM logs.
 */
void syslog_process(otInstance* instance);

/*!
 * Send a syslog message.
 */
int syslog_send_va(otInstance* instance,
		uint8_t facility, uint8_t severity,
		const char* app, const char* fmt, va_list fmt_args);

/*!
 * Send a syslog message (varadic version).
 */
static inline int syslog_send(otInstance* instance,
		uint8_t facility, uint8_t severity,
		const char* app, const char* fmt, ...) {
	int res;
	va_list fmt_args;
	va_start(fmt_args, fmt);
	res = syslog_send_va(instance, facility, severity, app, fmt, fmt_args);
	va_end(fmt_args);
	return res;
}

#ifdef __cplusplus
} // end extern "C"
#endif
#endif