syslog: fix UDP timing problems

- start README file describing the interface
- add 2ms delay before sending the next package
pull/80/head
susisstrolch 9 years ago
parent 59d4bdf99e
commit 8791bda62d
  1. 360
      syslog/syslog.c
  2. 8
      syslog/syslog.h
  3. 110
      syslog/syslog.md

@ -16,6 +16,7 @@
extern void * mem_trim(void *m, size_t s); // not well documented...
#undef SYSLOG_DBG
#ifdef SYSLOG_DBG
#define DBG(format, ...) do { os_printf(format, ## __VA_ARGS__); } while(0)
#else
@ -25,7 +26,7 @@ extern void * mem_trim(void *m, size_t s); // not well documented...
#define WIFI_CHK_INTERVAL 1000 // ms to check Wifi statis
static os_timer_t wifi_chk_timer;
static struct espconn syslog_espconn;
static struct espconn *syslog_espconn = NULL;
static uint32_t syslog_msgid = 1;
static uint8_t syslog_task = 0;
@ -35,8 +36,10 @@ static syslog_entry_t *syslogQueue = NULL;
static enum syslog_state syslogState = SYSLOG_NONE;
static void ICACHE_FLASH_ATTR syslog_add_entry(syslog_entry_t *entry);
static void ICACHE_FLASH_ATTR syslog_chk_wifi_stat(void);
static void ICACHE_FLASH_ATTR syslog_chk_status(void);
static void ICACHE_FLASH_ATTR syslog_udp_sent_cb(void *arg);
static syslog_entry_t ICACHE_FLASH_ATTR *syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...);
#ifdef SYSLOG_UDP_RECV
static void ICACHE_FLASH_ATTR syslog_udp_recv_cb(void *arg, char *pusrdata, unsigned short length);
#endif
@ -44,27 +47,70 @@ static void ICACHE_FLASH_ATTR syslog_udp_recv_cb(void *arg, char *pusrdata, unsi
#define syslog_send_udp() post_usr_task(syslog_task,0)
/******************************************************************************
* FunctionName : syslog_chk_wifi_stat
* FunctionName : syslog_chk_status
* Description : check whether get ip addr or not
* Parameters : none
* Returns : none
*******************************************************************************/
static void ICACHE_FLASH_ATTR syslog_chk_wifi_stat(void)
static void ICACHE_FLASH_ATTR syslog_chk_status(void)
{
struct ip_info ipconfig;
DBG("syslog_chk_wifi_stat: state: %d ", syslogState);
//disarm timer first
os_timer_disarm(&wifi_chk_timer);
DBG("syslog_chk_status: state: %d ", syslogState);
//try to get ip info of ESP8266 station
wifi_get_ip_info(STATION_IF, &ipconfig);
int wifi_status = wifi_station_get_connect_status();
if (wifi_status == STATION_GOT_IP && ipconfig.ip.addr != 0)
{
if (syslogState == SYSLOG_WAIT) { // waiting for initialization
DBG("connected, initializing UDP socket\n");
// it seems we have to add an additional delay after the Wifi is up and running.
// so we simply add an intermediate state with 25ms delay
switch (syslogState)
{
case SYSLOG_WAIT:
DBG("state SYSLOG_WAIT: Wifi connected\n");
syslogState = SYSLOG_INIT;
os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_status, NULL);
os_timer_arm(&wifi_chk_timer, 100, 0);
break;
case SYSLOG_INIT:
DBG("state SYSLOG_INIT: init syslog\n");
syslog_init(flashConfig.syslog_host);
os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_status, NULL);
os_timer_arm(&wifi_chk_timer, 100, 0);
break;
case SYSLOG_DNSWAIT:
DBG("state SYSLOG_DNSWAIT: wait for DNS resolver\n");
os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_status, NULL);
os_timer_arm(&wifi_chk_timer, 100, 0);
syslogState = SYSLOG_READY;
break;
case SYSLOG_READY:
DBG("state SYSLOG_READY: start sending\n");
syslog_send_udp();
break;
case SYSLOG_SENDING:
DBG("state SYSLOG_SENDING: delay\n");
os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_status, NULL);
os_timer_arm(&wifi_chk_timer, 2, 0);
syslogState = SYSLOG_SEND;
break;
case SYSLOG_SEND:
DBG("state SYSLOG_SEND: start sending\n");
syslog_send_udp();
break;
default:
DBG("state DEFAULT: %d\n", syslogState);
break;
}
} else {
if ((wifi_status == STATION_WRONG_PASSWORD ||
@ -74,108 +120,12 @@ static void ICACHE_FLASH_ATTR syslog_chk_wifi_stat(void)
os_printf("*** connect failure!!!\n");
} else {
DBG("re-arming timer...\n");
os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_wifi_stat, NULL);
os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_status, NULL);
os_timer_arm(&wifi_chk_timer, WIFI_CHK_INTERVAL, 0);
}
}
}
static void ICACHE_FLASH_ATTR syslog_udp_send_event(os_event_t *events) {
if (syslogQueue == NULL)
syslogState = SYSLOG_READY;
else {
int res = 0;
syslog_espconn.proto.udp->remote_port = syslogHost.port; // ESP8266 udp remote port
os_memcpy(&syslog_espconn.proto.udp->remote_ip, &syslogHost.addr.addr, 4); // ESP8266 udp remote IP
res = espconn_send(&syslog_espconn, (uint8_t *)syslogQueue->datagram, syslogQueue->datagram_len);
if (res != 0) {
os_printf("syslog_udp_send: error %d\n", res);
}
}
}
/******************************************************************************
* FunctionName : syslog_compose
* Description : compose a syslog_entry_t from va_args
* Parameters : va_args
* Returns : the malloced syslog_entry_t
******************************************************************************/
static syslog_entry_t* ICACHE_FLASH_ATTR syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...)
{
syslog_entry_t *se = os_zalloc(sizeof (syslog_entry_t) + 1024); // allow up to 1k datagram
char *p = se->datagram;
uint32_t tick = WDEV_NOW(); // 0 ... 4294.967295s
// The Priority value is calculated by first multiplying the Facility
// number by 8 and then adding the numerical value of the Severity.
p += os_sprintf(p, "<%d> ", facility * 8 + severity);
// strftime doesn't work as expected - or adds 8k overhead.
// so let's do poor man conversion - format is fixed anyway
if (flashConfig.syslog_showdate == 0)
p += os_sprintf(p, "- ");
else {
time_t now = NULL;
struct tm *tp = NULL;
// create timestamp: FULL-DATE "T" PARTIAL-TIME "Z": 'YYYY-mm-ddTHH:MM:SSZ '
// as long as realtime_stamp is 0 we use tick div 10⁶ as date
now = (realtime_stamp == 0) ? (tick / 1000000) : realtime_stamp;
tp = gmtime(&now);
p += os_sprintf(p, "%4d-%02d-%02dT%02d:%02d:%02dZ ",
tp->tm_year + 1900, tp->tm_mon + 1, tp->tm_mday,
tp->tm_hour, tp->tm_min, tp->tm_sec);
}
// add HOSTNAME APP-NAME PROCID MSGID
if (flashConfig.syslog_showtick)
p += os_sprintf(p, "%s %s %lu.%06lu %lu ", flashConfig.hostname, tag, tick / 1000000, tick % 1000000, syslog_msgid++);
else
p += os_sprintf(p, "%s %s - %lu ", flashConfig.hostname, tag, syslog_msgid++);
// append syslog message
va_list arglist;
va_start(arglist, fmt);
p += ets_vsprintf(p, fmt, arglist );
va_end(arglist);
se->datagram_len = p - se->datagram;
se = mem_trim(se, sizeof(syslog_entry_t) + se->datagram_len + 1);
return se;
}
/******************************************************************************
* FunctionName : syslog_add_entry
* Description : add a syslog_entry_t to the syslogQueue
* Parameters : entry: the syslog_entry_t
* Returns : none
******************************************************************************/
static void ICACHE_FLASH_ATTR syslog_add_entry(syslog_entry_t *entry)
{
syslog_entry_t *pse = syslogQueue;
// append msg to syslog_queue
if (pse == NULL)
syslogQueue = entry;
else {
while (pse->next != NULL)
pse = pse->next;
pse->next = entry; // append msg to syslog queue
}
// ensure we have sufficient heap for the rest of the system
if (system_get_free_heap_size() < syslogHost.min_heap_size) {
if (syslogState != SYSLOG_HALTED) {
os_printf("syslog_add_entry: Warning: queue filled up, halted\n");
entry->next = syslog_compose(SYSLOG_FAC_SYSLOG, SYSLOG_PRIO_CRIT, "-", "queue filled up, halted");
if (syslogState == SYSLOG_READY)
syslog_send_udp();
syslogState = SYSLOG_HALTED;
}
}
}
/******************************************************************************
* FunctionName : syslog_sent_cb
* Description : udp sent successfully
@ -193,10 +143,29 @@ static void ICACHE_FLASH_ATTR syslog_udp_sent_cb(void *arg)
syslogQueue = syslogQueue -> next;
os_free(pse);
if (syslogQueue != NULL)
syslog_send_udp();
else
if (syslogQueue == NULL)
syslogState = SYSLOG_READY;
else {
// UDP seems timecritical - we must ensure a minimum delay after each package...
syslogState = SYSLOG_SENDING;
syslog_chk_status();
}
}
static void ICACHE_FLASH_ATTR
syslog_udp_send_event(os_event_t *events) {
// os_printf("syslog_udp_send_event: %d %lu, %lu\n", syslogState, syslogQueue->msgid, syslogQueue->tick);
if (syslogQueue == NULL)
syslogState = SYSLOG_READY;
else {
int res = 0;
syslog_espconn->proto.udp->remote_port = syslogHost.port; // ESP8266 udp remote port
os_memcpy(syslog_espconn->proto.udp->remote_ip, &syslogHost.addr.addr, 4); // ESP8266 udp remote IP
res = espconn_send(syslog_espconn, (uint8_t *)syslogQueue->datagram, syslogQueue->datagram_len);
if (res != 0) {
os_printf("syslog_udp_send: error %d\n", res);
}
}
}
/*****************************************************************************
@ -222,9 +191,10 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_
struct espconn *pespconn = (struct espconn *)arg;
(void) pespconn;
if (ipaddr != NULL) {
syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG",
"resolved hostname: %s: " IPSTR, name, IP2STR(ipaddr));
syslogHost.addr.addr = ipaddr->addr;
syslogState = SYSLOG_SENDING;
syslog_send_udp();
syslogState = SYSLOG_DNSWAIT;
} else {
syslogState = SYSLOG_ERROR;
DBG("syslog_gethostbyname_cb: state=SYSLOG_ERROR\n");
@ -240,55 +210,176 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_
*******************************************************************************/
void ICACHE_FLASH_ATTR syslog_init(char *syslog_host)
{
if (!*syslog_host) {
syslogState = SYSLOG_HALTED;
if (!*syslog_host) {
return;
}
char host[32], *port = &host[0];
syslog_task = register_usr_task(syslog_udp_send_event);
syslogHost.min_heap_size = flashConfig.syslog_minheap;
syslogHost.port = 514;
syslogState = SYSLOG_WAIT;
if (syslog_host == NULL) {
// disable and unregister syslog handler
if (syslog_espconn != NULL) {
if (syslog_espconn->proto.udp) {
// there's no counterpart to espconn_create...
os_free(syslog_espconn->proto.udp);
}
os_free(syslog_espconn);
}
syslog_espconn = NULL;
// clean up syslog queue
syslog_entry_t *pse = syslogQueue;
while (pse != NULL) {
syslog_entry_t *next = pse->next;
os_free(pse);
pse = next;
}
syslogQueue = NULL;
return;
}
char host[32], *port = &host[0];
os_strncpy(host, syslog_host, 32);
while (*port && *port != ':') // find port delimiter
port++;
if (*port) {
*port++ = '\0';
syslogHost.port = atoi(port);
}
wifi_set_broadcast_if(STATIONAP_MODE); // send UDP broadcast from both station and soft-AP interface
syslog_espconn.type = ESPCONN_UDP;
syslog_espconn.proto.udp = (esp_udp *)os_zalloc(sizeof(esp_udp));
syslog_espconn.proto.udp->local_port = espconn_port(); // set a available port
if (syslogHost.port == 0)
syslogHost.port = 514;
// allocate structures, init syslog_handler
if (syslog_espconn == NULL)
syslog_espconn = (espconn *)os_zalloc(sizeof(espconn));
if (syslog_espconn->proto.udp == NULL)
syslog_espconn->proto.udp = (esp_udp *)os_zalloc(sizeof(esp_udp));
syslog_espconn->type = ESPCONN_UDP;
syslog_espconn->proto.udp->local_port = espconn_port(); // set a available port
#ifdef SYSLOG_UDP_RECV
espconn_regist_recvcb(&syslog_espconn, syslog_udp_recv_cb); // register a udp packet receiving callback
espconn_regist_recvcb(syslog_espconn, syslog_udp_recv_cb); // register a udp packet receiving callback
#endif
espconn_regist_sentcb(&syslog_espconn, syslog_udp_sent_cb); // register a udp packet sent callback
espconn_create(&syslog_espconn); // create udp
espconn_regist_sentcb(syslog_espconn, syslog_udp_sent_cb); // register a udp packet sent callback
syslog_task = register_usr_task(syslog_udp_send_event);
syslogHost.min_heap_size = flashConfig.syslog_minheap;
// the wifi_set_broadcast_if must be handled global in connection handler...
// wifi_set_broadcast_if(STATIONAP_MODE); // send UDP broadcast from both station and soft-AP interface
espconn_create(syslog_espconn); // create udp
if (UTILS_StrToIP((const char *)host, (void*)&syslogHost.addr)) {
syslogState = SYSLOG_SENDING;
syslog_send_udp();
syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG",
"syslogserver: %s:%d", host, syslogHost.port);
syslogState = SYSLOG_READY;
} else {
static struct espconn espconn_ghbn;
espconn_gethostbyname(&espconn_ghbn, host, &syslogHost.addr, syslog_gethostbyname_cb);
// syslog_send_udp is called by syslog_gethostbyname_cb()
syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG",
"resolving hostname: %s", host);
syslogState = SYSLOG_DNSWAIT;
espconn_gethostbyname(syslog_espconn, host, &syslogHost.addr, syslog_gethostbyname_cb);
}
#ifdef SYSLOG_UDP_RECV
DBG("syslog_init: host: %s, port: %d, lport: %d, recvcb: %p, sentcb: %p, state: %d\n",
host, syslogHost.port, syslog_espconn.proto.udp->local_port,
host, syslogHost.port, syslog_espconn->proto.udp->local_port,
syslog_udp_recv_cb, syslog_udp_sent_cb, syslogState );
#else
DBG("syslog_init: host: %s, port: %d, lport: %d, rsentcb: %p, state: %d\n",
host, syslogHost.port, syslog_espconn.proto.udp->local_port,
host, syslogHost.port, syslog_espconn->proto.udp->local_port,
syslog_udp_sent_cb, syslogState );
#endif
}
/******************************************************************************
* FunctionName : syslog_add_entry
* Description : add a syslog_entry_t to the syslogQueue
* Parameters : entry: the syslog_entry_t
* Returns : none
******************************************************************************/
static void ICACHE_FLASH_ATTR
syslog_add_entry(syslog_entry_t *entry)
{
syslog_entry_t *pse = syslogQueue;
DBG("syslog_add_entry: %p", syslogQueue);
// append msg to syslog_queue
if (pse == NULL)
syslogQueue = entry;
else {
while (pse->next != NULL)
pse = pse->next;
pse->next = entry; // append msg to syslog queue
}
DBG("%p %lu %d\n", entry, entry->msgid, system_get_free_heap_size());
// ensure we have sufficient heap for the rest of the system
if (system_get_free_heap_size() < syslogHost.min_heap_size) {
if (syslogState != SYSLOG_HALTED) {
os_printf("syslog_add_entry: Warning: queue filled up, halted\n");
entry->next = syslog_compose(SYSLOG_FAC_USER, SYSLOG_PRIO_CRIT, "SYSLOG", "queue filled up, halted");
if (syslogState == SYSLOG_READY)
syslog_send_udp();
syslogState = SYSLOG_HALTED;
}
}
}
/******************************************************************************
* FunctionName : syslog_compose
* Description : compose a syslog_entry_t from va_args
* Parameters : va_args
* Returns : the malloced syslog_entry_t
******************************************************************************/
LOCAL syslog_entry_t ICACHE_FLASH_ATTR *
syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...)
{
syslog_entry_t *se = os_zalloc(sizeof (syslog_entry_t) + 1024); // allow up to 1k datagram
char *p = se->datagram;
se->tick = WDEV_NOW(); // 0 ... 4294.967295s
se->msgid = syslog_msgid;
// The Priority value is calculated by first multiplying the Facility
// number by 8 and then adding the numerical value of the Severity.
p += os_sprintf(p, "<%d> ", facility * 8 + severity);
// strftime doesn't work as expected - or adds 8k overhead.
// so let's do poor man conversion - format is fixed anyway
if (flashConfig.syslog_showdate == 0)
p += os_sprintf(p, "- ");
else {
time_t now = NULL;
struct tm *tp = NULL;
// create timestamp: FULL-DATE "T" PARTIAL-TIME "Z": 'YYYY-mm-ddTHH:MM:SSZ '
// as long as realtime_stamp is 0 we use tick div 10⁶ as date
now = (realtime_stamp == 0) ? (se->tick / 1000000) : realtime_stamp;
tp = gmtime(&now);
p += os_sprintf(p, "%4d-%02d-%02dT%02d:%02d:%02dZ ",
tp->tm_year + 1900, tp->tm_mon + 1, tp->tm_mday,
tp->tm_hour, tp->tm_min, tp->tm_sec);
}
// add HOSTNAME APP-NAME PROCID MSGID
if (flashConfig.syslog_showtick)
p += os_sprintf(p, "%s %s %lu.%06lu %lu ", flashConfig.hostname, tag, se->tick / 1000000, se->tick % 1000000, syslog_msgid++);
else
p += os_sprintf(p, "%s %s - %lu ", flashConfig.hostname, tag, syslog_msgid++);
// append syslog message
va_list arglist;
va_start(arglist, fmt);
p += ets_vsprintf(p, fmt, arglist );
va_end(arglist);
se->datagram_len = p - se->datagram;
se = mem_trim(se, sizeof(syslog_entry_t) + se->datagram_len + 1);
return se;
}
/*****************************************************************************
* FunctionName : syslog
* Description : compose and queue a new syslog message
* Parameters : facility
@ -374,13 +465,8 @@ void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *ta
// and append it to the message queue
syslog_add_entry(se);
if (syslogState == SYSLOG_READY) {
syslogState = SYSLOG_SENDING;
syslog_send_udp();
}
if (syslogState == SYSLOG_NONE) {
if (syslogState == SYSLOG_NONE)
syslogState = SYSLOG_WAIT;
syslog_chk_wifi_stat(); // fire the timer to check the Wifi connection status
}
syslog_chk_status();
}

@ -20,9 +20,13 @@ extern "C" {
enum syslog_state {
SYSLOG_NONE, // not initialized
SYSLOG_WAIT, // initialized, waiting for Wifi
SYSLOG_WAIT, // waiting for Wifi
SYSLOG_INIT, // WIFI avail, must initialize
SYSLOG_DNSWAIT, // WIFI avail, init done, waiting for DNS resolve
SYSLOG_READY, // Wifi established, ready to send
SYSLOG_SENDING, // UDP package on the air
SYSLOG_SEND,
SYSLOG_SENT,
SYSLOG_HALTED, // heap full, discard message
SYSLOG_ERROR,
};
@ -78,6 +82,8 @@ struct syslog_host_t {
typedef struct syslog_entry_t syslog_entry_t;
struct syslog_entry_t {
syslog_entry_t *next;
uint32_t msgid;
uint32_t tick;
uint16_t datagram_len;
char datagram[];
};

@ -0,0 +1,110 @@
syslog
======
The lib implements a RFC5424 compliant syslog interface for ESP8266. The syslog
message is send via UDP.
syslog messages are queued on heap until the Wifi stack is fully initialized.
If the remaining heap size reaches a given limit, syslog will add a final obituary
and stop further logging until the queue is empty and sufficient heap space is
available again.
The module may be controlled by flashconfig variables:
* **syslog_host: host[:port]**
**host** is an IP-address or DNS-name. **port** is optional and defaults to 514.
DNS-Resolution is done as soon as the Wifi stack is up and running.
* **syslog_minheap: 8192**
**minheap** specifies the minimum amount of remaining free heap when queuing up
syslog messages. If the remaining heap size is below **minheap**, syslog will insert
an obituary message and stop queuing. After processing all queued messages, the
logging will be enabled again.
* **syslog_filter: 0..7**
**syslog_filter** is the minimum severity for sending a syslog message. The filter
is applied against the message queue, so any message with a severity numerical lower
than **syslog_filter** will be dropped instead of being send.
* **syslog_showtick: 0|1**
If **syslog_showtick** is set to **1**, syslog will insert an additional timestamp
(system tick) as "PROCESS" field (before the users syslog message).
The value shown is in ms, (1µs resolution) since (re)boot or timer overflow.
* **syslog_showdate: 0|1**
If **syslog_showdate** is set to **1**, syslog will insert the ESPs NTP time
into the syslog message. If "realtime_stamp" (NTP 1s ticker) is **NULL**, the
time is derived from a pseudo-time based on the absolute value of systemticks.
Some syslog servers (e.g. Synology) will do crazy things if you set **syslog_showdate** to **1**
The syslog module exports two functions:
```
syslog_init(char *server_name);
syslog(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...);
```
syslog_init
-----------
usage: `syslog_init(char *server_name);`
**syslog_init** expects a server name in format "host:port" (see **syslog_host** flashconfig).
If **server_name** is **NULL**, all dynamic allocated memory (buffers, queues, interfaces)
are released and the syslog state is set to "SYSLOG_HALTED".
If **server_name** is **""**, syslog state is set to "SYSLOG_HALTED", without clearing
the queue.
Otherwise, syslog_init will allocate all required structures (buffers, interfaces) and
send all collected syslog messages.
syslog is self-initializing, meaning the syslog_init(server_name) is called on first
invocation. The syslog_init function is only for convenience if you have to stop or disable syslog functions.
syslog
------
usage: `syslog(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...);`
* **facility**
the message facility (see syslog.h, **enum syslog_facility**).
* **severity**
the message severity (see syslog.h, **enum syslog_severity**)
* **tag**
user defined tag (e.g. "MQTT", "REST", "UART") to specify where the message belongs to
* ** const char *fmt, ...**
the desired message, in printf format.
Examples
========
showtick=0, showdate=0
Invocation: syslog()
output:
showtick=1, showdate=1
Invocation: syslog()
output:
showtick=1, showdate=1, NTP not available
Invocation: syslog()
output:
showtick=1, showdate=1, NTP available
Invocation: syslog()
output:
Loading…
Cancel
Save