From 8791bda62d2de688e158c6131057ffcb890ea0c0 Mon Sep 17 00:00:00 2001 From: susisstrolch Date: Mon, 14 Dec 2015 09:42:51 +0100 Subject: [PATCH 1/5] syslog: fix UDP timing problems - start README file describing the interface - add 2ms delay before sending the next package --- syslog/syslog.c | 366 +++++++++++++++++++++++++++++------------------ syslog/syslog.h | 8 +- syslog/syslog.md | 110 ++++++++++++++ 3 files changed, 343 insertions(+), 141 deletions(-) create mode 100644 syslog/syslog.md diff --git a/syslog/syslog.c b/syslog/syslog.c index 1b9df85..9cdc6d9 100644 --- a/syslog/syslog.c +++ b/syslog/syslog.c @@ -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,28 +47,71 @@ 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"); - syslog_init(flashConfig.syslog_host); - } + // 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 || wifi_status == STATION_NO_AP_FOUND || @@ -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) { + syslogState = SYSLOG_HALTED; + if (!*syslog_host) { - syslogState = SYSLOG_HALTED; 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(); } diff --git a/syslog/syslog.h b/syslog/syslog.h index faf0eec..3c9c73d 100644 --- a/syslog/syslog.h +++ b/syslog/syslog.h @@ -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[]; }; diff --git a/syslog/syslog.md b/syslog/syslog.md new file mode 100644 index 0000000..d7e08ac --- /dev/null +++ b/syslog/syslog.md @@ -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: From 0248d1f6985ed69c617a967c4df22dfb8b7ff59f Mon Sep 17 00:00:00 2001 From: susisstrolch Date: Tue, 15 Dec 2015 12:53:40 +0100 Subject: [PATCH 2/5] syslog: fixup - implement syslog filter - honour timezone setting - rework syslog format - finish (really?) syslog documentation --- syslog/syslog.c | 29 +++++++++++++++--------- syslog/syslog.md | 58 +++++++++++++++++++++++++++++++++--------------- 2 files changed, 58 insertions(+), 29 deletions(-) diff --git a/syslog/syslog.c b/syslog/syslog.c index 9cdc6d9..a9fbb2a 100644 --- a/syslog/syslog.c +++ b/syslog/syslog.c @@ -16,7 +16,6 @@ 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 @@ -210,14 +209,15 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_ *******************************************************************************/ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) { - syslogState = SYSLOG_HALTED; if (!*syslog_host) { + syslogState = SYSLOG_HALTED; return; } if (syslog_host == NULL) { // disable and unregister syslog handler + syslogState = SYSLOG_HALTED; if (syslog_espconn != NULL) { if (syslog_espconn->proto.udp) { // there's no counterpart to espconn_create... @@ -235,6 +235,7 @@ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) pse = next; } syslogQueue = NULL; + syslogState = SYSLOG_HALTED; return; } @@ -272,23 +273,22 @@ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) espconn_create(syslog_espconn); // create udp if (UTILS_StrToIP((const char *)host, (void*)&syslogHost.addr)) { + syslogState = SYSLOG_READY; syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", "syslogserver: %s:%d", host, syslogHost.port); - syslogState = SYSLOG_READY; } else { + syslogState = SYSLOG_DNSWAIT; 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", + LOG_NOTICE("syslog_init: host: %s, port: %d, lport: %d, recvcb: %p, sstate: %d", host, syslogHost.port, syslog_espconn->proto.udp->local_port, - syslog_udp_recv_cb, syslog_udp_sent_cb, syslogState ); + syslog_udp_recv_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, - syslog_udp_sent_cb, syslogState ); + LOG_NOTICE("syslog_init: host: %s, port: %d, lport: %d, state: %d", + host, syslogHost.port, syslog_espconn->proto.udp->local_port, syslogState ); #endif } @@ -357,9 +357,13 @@ syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char * now = (realtime_stamp == 0) ? (se->tick / 1000000) : realtime_stamp; tp = gmtime(&now); - p += os_sprintf(p, "%4d-%02d-%02dT%02d:%02d:%02dZ ", + p += os_sprintf(p, "%4d-%02d-%02dT%02d:%02d:%02d", tp->tm_year + 1900, tp->tm_mon + 1, tp->tm_mday, - tp->tm_hour, tp->tm_min, tp->tm_sec); + tp->tm_hour, tp->tm_min, tp->tm_sec); + if (realtime_stamp == 0) + p += os_sprintf(p, ".%06luZ ", se->tick % 1000000); + else + p += os_sprintf(p, "%+03d:00 ", flashConfig.timezone_offset); } // add HOSTNAME APP-NAME PROCID MSGID @@ -457,6 +461,9 @@ void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *ta syslogState == SYSLOG_HALTED) return; + if (severity > flashConfig.syslog_filter) + return; + // compose the syslog message void *arg = __builtin_apply_args(); void *res = __builtin_apply((void*)syslog_compose, arg, 128); diff --git a/syslog/syslog.md b/syslog/syslog.md index d7e08ac..dd71e70 100644 --- a/syslog/syslog.md +++ b/syslog/syslog.md @@ -1,8 +1,21 @@ syslog ====== -The lib implements a RFC5424 compliant syslog interface for ESP8266. The syslog -message is send via UDP. +The lib (tries to )implement a RFC5424 compliant syslog interface for ESP8266. syslog +messages are send via UDP. Messages are send in the following format: + +``` +PRI VERSION SP TIMESTAMP SP HOSTNAME SP APP-NAME SP PROCID SP MSGID SP MSG + PRI: msg priority: facility * 8 + severity + TIMESTAMP: dash (no timestamp) or ISO8601 (2015-12-14T17:26:32Z) + HOSTNAME: flashConfig.hostname + APP-NAME: tag - (e.g. MQTT, mySQL, REST, ...) + PROCID: dash or ESP system tick (µseconds since reboot) + MSGID: counter - # syslog messages since reboot + MSG: the syslog message +``` + +The meaning of TIMESTAMP, HOSTNAME, PROCID and MSGID is hardcoded, all others are parameters for the syslog function. 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 @@ -26,14 +39,14 @@ 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. +is applied against the message queue, so any message with a severity numerical higher +than **syslog_filter** will be dropped instead of being queued/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. +(system tick) as "PROCID" field (before the users real syslog message). +The value shown is in seconds, with 1µs resolution since (re)boot or timer overflow. * **syslog_showdate: 0|1** @@ -92,19 +105,28 @@ usage: `syslog(uint8_t facility, uint8_t severity, const char *tag, const char * Examples ======== + hostname="ems-link02", showtick=0, showdate=0 + Syslog message: USER.NOTICE: - ems-link02 esp_link - 20 syslog_init: host: 192.168.254.216, port: 514, lport: 28271, rsentcb: 40211e08, state: 4\n + + hostname="ems-link02", showtick=1, showdate=0 + Syslog message: USER.NOTICE: - ems-link02 esp_link 3.325677 8 syslog_init: host: 192.168.254.216, port: 514, lport: 19368, rsentcb: 40211e08, state: 4\n + + hostname="ems-link02", showtick=1, showdate=1, NTP not available + Syslog message: USER.NOTICE: 1970-01-01T00:00:03.325668Z ems-link02 esp_link 3.325668 8 syslog_init: host: 192.168.254.216, port: 514, lport: 36802, rsentcb: 40211e08, state: 4\n + + hostname="ems-link02", showtick=1, showdate=1, NTP available + Syslog message: USER.NOTICE: 2015-12-15T11:15:29+00:00 ems-link02 esp_link 182.036860 13 syslog_init: host: 192.168.254.216, port: 514, lport: 43626, rsentcb: 40291db8, state: 4\n + +Notes +===== ++ The ESP8266 (NON-OS) needs a delay of **at least 2ms** between consecutive UDP packages. So the syslog throughput is restricted to approx. 500EPS. + ++ If a syslog message doesn't have the timestamp set ( **syslog_showdate** == 0), the syslog _server_ will insert _it's own receive timestamp_ into the log message. - showtick=0, showdate=0 - Invocation: syslog() -output: ++ If **syslog_showdate** == 1, the syslog _server_ MAY replace it's own receive timestamp with the timestamp sent by the syslog client. - showtick=1, showdate=1 - Invocation: syslog() -output: ++ Some syslog servers don't show the fractional seconds of the syslog timestamp - showtick=1, showdate=1, NTP not available - Invocation: syslog() -output: ++ Setting **syslog_showdate** will send timestamps from 1970 (because of using the internal ticker) until the **SNTP-client** got a valid NTP datagram. Some syslog servers (for example _Synology_) will roll over their database if they get such "old" syslog messages. In fact, you won't see those messages in your current syslog. - showtick=1, showdate=1, NTP available - Invocation: syslog() -output: ++ Some servers (e.g. _Synology_) won't show the syslog message if you set **facility** to **SYSLOG_FAC_SYSLOG**. From 94d54c140c36c6beb41a3678d76d21b2330beeaf Mon Sep 17 00:00:00 2001 From: susisstrolch Date: Tue, 15 Dec 2015 12:53:40 +0100 Subject: [PATCH 3/5] syslog: fixup - implement syslog filter - honour timezone setting - rework syslog format - finish (really?) syslog documentation --- syslog/syslog.c | 29 +++++++++++-------- syslog/syslog.md | 72 ++++++++++++++++++++++++++++++++++++------------ 2 files changed, 72 insertions(+), 29 deletions(-) diff --git a/syslog/syslog.c b/syslog/syslog.c index 9cdc6d9..a9fbb2a 100644 --- a/syslog/syslog.c +++ b/syslog/syslog.c @@ -16,7 +16,6 @@ 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 @@ -210,14 +209,15 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_ *******************************************************************************/ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) { - syslogState = SYSLOG_HALTED; if (!*syslog_host) { + syslogState = SYSLOG_HALTED; return; } if (syslog_host == NULL) { // disable and unregister syslog handler + syslogState = SYSLOG_HALTED; if (syslog_espconn != NULL) { if (syslog_espconn->proto.udp) { // there's no counterpart to espconn_create... @@ -235,6 +235,7 @@ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) pse = next; } syslogQueue = NULL; + syslogState = SYSLOG_HALTED; return; } @@ -272,23 +273,22 @@ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) espconn_create(syslog_espconn); // create udp if (UTILS_StrToIP((const char *)host, (void*)&syslogHost.addr)) { + syslogState = SYSLOG_READY; syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", "syslogserver: %s:%d", host, syslogHost.port); - syslogState = SYSLOG_READY; } else { + syslogState = SYSLOG_DNSWAIT; 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", + LOG_NOTICE("syslog_init: host: %s, port: %d, lport: %d, recvcb: %p, sstate: %d", host, syslogHost.port, syslog_espconn->proto.udp->local_port, - syslog_udp_recv_cb, syslog_udp_sent_cb, syslogState ); + syslog_udp_recv_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, - syslog_udp_sent_cb, syslogState ); + LOG_NOTICE("syslog_init: host: %s, port: %d, lport: %d, state: %d", + host, syslogHost.port, syslog_espconn->proto.udp->local_port, syslogState ); #endif } @@ -357,9 +357,13 @@ syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char * now = (realtime_stamp == 0) ? (se->tick / 1000000) : realtime_stamp; tp = gmtime(&now); - p += os_sprintf(p, "%4d-%02d-%02dT%02d:%02d:%02dZ ", + p += os_sprintf(p, "%4d-%02d-%02dT%02d:%02d:%02d", tp->tm_year + 1900, tp->tm_mon + 1, tp->tm_mday, - tp->tm_hour, tp->tm_min, tp->tm_sec); + tp->tm_hour, tp->tm_min, tp->tm_sec); + if (realtime_stamp == 0) + p += os_sprintf(p, ".%06luZ ", se->tick % 1000000); + else + p += os_sprintf(p, "%+03d:00 ", flashConfig.timezone_offset); } // add HOSTNAME APP-NAME PROCID MSGID @@ -457,6 +461,9 @@ void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *ta syslogState == SYSLOG_HALTED) return; + if (severity > flashConfig.syslog_filter) + return; + // compose the syslog message void *arg = __builtin_apply_args(); void *res = __builtin_apply((void*)syslog_compose, arg, 128); diff --git a/syslog/syslog.md b/syslog/syslog.md index d7e08ac..d60cbf5 100644 --- a/syslog/syslog.md +++ b/syslog/syslog.md @@ -1,13 +1,40 @@ syslog ====== -The lib implements a RFC5424 compliant syslog interface for ESP8266. The syslog -message is send via UDP. +The lib (tries to )implement a RFC5424 compliant syslog interface for ESP8266. syslog +messages are send via UDP. Messages are send in the following format: + +``` +PRI VERSION SP TIMESTAMP SP HOSTNAME SP APP-NAME SP PROCID SP MSGID SP MSG + PRI: msg priority: facility * 8 + severity + TIMESTAMP: dash (no timestamp) or ISO8601 (2015-12-14T17:26:32Z) + HOSTNAME: flashConfig.hostname + APP-NAME: tag - (e.g. MQTT, mySQL, REST, ...) + PROCID: dash or ESP system tick (µseconds since reboot) + MSGID: counter - # syslog messages since reboot + MSG: the syslog message +``` + +The meaning of TIMESTAMP, HOSTNAME, PROCID and MSGID is hardcoded, all others are parameters for the syslog function. 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. +Example: + +``` +Jan 1 00:00:00 192.168.254.82 esp_link 0.126850 1 Reset cause: 4=restart +Jan 1 00:00:00 192.168.254.82 esp_link 0.133970 2 exccause=0 epc1=0x0 epc2=0x0 epc3=0x0 excvaddr=0x0 depc=0x0 +Jan 1 00:00:00 192.168.254.82 esp_link 0.151069 3 Flash map 4MB:512/512, manuf 0xC8 chip 0x4016 +Jan 1 00:00:00 192.168.254.82 esp_link 0.166935 4 ** esp-link ready +Jan 1 00:00:00 192.168.254.82 esp_link 0.185586 5 initializing MQTT +Jan 1 00:00:00 192.168.254.82 esp_link 0.200681 6 initializing user application +Jan 1 00:00:00 192.168.254.82 esp_link 0.215169 7 waiting for work to do... +Jan 1 00:00:03 192.168.254.82 SYSLOG 3.325626 8 syslogserver: 192.168.254.216:514 +Jan 1 00:00:03 192.168.254.82 esp_link 3.336756 9 syslog_init: host: 192.168.254.216, port: 514, lport: 24377, state: 4 +Dec 15 11:49:14 192.168.254.82 esp-link 18.037949 10 Accept port 23, conn=3fff5f68, pool slot 0 +``` The module may be controlled by flashconfig variables: @@ -26,14 +53,14 @@ 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. +is applied against the message queue, so any message with a severity numerical higher +than **syslog_filter** will be dropped instead of being queued/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. +(system tick) as "PROCID" field (before the users real syslog message). +The value shown is in seconds, with 1µs resolution since (re)boot or timer overflow. * **syslog_showdate: 0|1** @@ -92,19 +119,28 @@ usage: `syslog(uint8_t facility, uint8_t severity, const char *tag, const char * Examples ======== + hostname="ems-link02", showtick=0, showdate=0 + Syslog message: USER.NOTICE: - ems-link02 esp_link - 20 syslog_init: host: 192.168.254.216, port: 514, lport: 28271, rsentcb: 40211e08, state: 4\n + + hostname="ems-link02", showtick=1, showdate=0 + Syslog message: USER.NOTICE: - ems-link02 esp_link 3.325677 8 syslog_init: host: 192.168.254.216, port: 514, lport: 19368, rsentcb: 40211e08, state: 4\n + + hostname="ems-link02", showtick=1, showdate=1, NTP not available + Syslog message: USER.NOTICE: 1970-01-01T00:00:03.325668Z ems-link02 esp_link 3.325668 8 syslog_init: host: 192.168.254.216, port: 514, lport: 36802, rsentcb: 40211e08, state: 4\n + + hostname="ems-link02", showtick=1, showdate=1, NTP available + Syslog message: USER.NOTICE: 2015-12-15T11:15:29+00:00 ems-link02 esp_link 182.036860 13 syslog_init: host: 192.168.254.216, port: 514, lport: 43626, rsentcb: 40291db8, state: 4\n + +Notes +===== ++ The ESP8266 (NON-OS) needs a delay of **at least 2ms** between consecutive UDP packages. So the syslog throughput is restricted to approx. 500EPS. + ++ If a syslog message doesn't have the timestamp set ( **syslog_showdate** == 0), the syslog _server_ will insert _it's own receive timestamp_ into the log message. - showtick=0, showdate=0 - Invocation: syslog() -output: ++ If **syslog_showdate** == 1, the syslog _server_ MAY replace it's own receive timestamp with the timestamp sent by the syslog client. - showtick=1, showdate=1 - Invocation: syslog() -output: ++ Some syslog servers don't show the fractional seconds of the syslog timestamp - showtick=1, showdate=1, NTP not available - Invocation: syslog() -output: ++ Setting **syslog_showdate** will send timestamps from 1970 (because of using the internal ticker) until the **SNTP-client** got a valid NTP datagram. Some syslog servers (for example _Synology_) will roll over their database if they get such "old" syslog messages. In fact, you won't see those messages in your current syslog. - showtick=1, showdate=1, NTP available - Invocation: syslog() -output: ++ Some servers (e.g. _Synology_) won't show the syslog message if you set **facility** to **SYSLOG_FAC_SYSLOG**. From 66258fd48df3aa7469d8783c351d1451b3dfb20f Mon Sep 17 00:00:00 2001 From: susisstrolch Date: Tue, 15 Dec 2015 13:04:14 +0100 Subject: [PATCH 4/5] syslog.md: add example for queuing after reboot --- syslog/syslog.md | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/syslog/syslog.md b/syslog/syslog.md index d60cbf5..9841f91 100644 --- a/syslog/syslog.md +++ b/syslog/syslog.md @@ -17,11 +17,7 @@ PRI VERSION SP TIMESTAMP SP HOSTNAME SP APP-NAME SP PROCID SP MSGID SP MSG The meaning of TIMESTAMP, HOSTNAME, PROCID and MSGID is hardcoded, all others are parameters for the syslog function. -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. -Example: +syslog messages are queued on heap until the Wifi stack is fully initialized: ``` Jan 1 00:00:00 192.168.254.82 esp_link 0.126850 1 Reset cause: 4=restart @@ -36,6 +32,10 @@ Jan 1 00:00:03 192.168.254.82 esp_link 3.336756 9 syslog_init: host: 192.168.25 Dec 15 11:49:14 192.168.254.82 esp-link 18.037949 10 Accept port 23, conn=3fff5f68, pool slot 0 ``` +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]** From 077bcaf02ded218bd835989eee59095a8391a146 Mon Sep 17 00:00:00 2001 From: susisstrolch Date: Wed, 16 Dec 2015 19:21:54 +0100 Subject: [PATCH 5/5] syslog: fixed regression - #undef SYSLOG_DBG will discard first four syslog messages - race condition in os_timer_setfn/os_timer_arm lead to 1226> Fatal exception 9(LoadStoreAlignmentCause): 1227> epc1=0x4010076e, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000003, depc=0x00000000 - potential loop in syslog_init - fixed by additional state SYSLOG_INITDONE --- include/user_config.h | 4 +- syslog/syslog.c | 156 +++++++++++++++++++++++++++--------------- syslog/syslog.h | 1 + 3 files changed, 104 insertions(+), 57 deletions(-) diff --git a/include/user_config.h b/include/user_config.h index 4b9eeb0..72fe1ac 100644 --- a/include/user_config.h +++ b/include/user_config.h @@ -31,8 +31,8 @@ #define UART_DBG #define MDNS_DBG #define OPTIBOOT_DBG -#define SYSLOG_DBG -#define CGISERVICES_DBG +#undef SYSLOG_DBG +#undef CGISERVICES_DBG // If defined, the default hostname for DHCP will include the chip ID to make it unique #undef CHIP_IN_HOSTNAME diff --git a/syslog/syslog.c b/syslog/syslog.c index a9fbb2a..20a51cb 100644 --- a/syslog/syslog.c +++ b/syslog/syslog.c @@ -23,7 +23,6 @@ extern void * mem_trim(void *m, size_t s); // not well documented... #endif #define WIFI_CHK_INTERVAL 1000 // ms to check Wifi statis -static os_timer_t wifi_chk_timer; static struct espconn *syslog_espconn = NULL; static uint32_t syslog_msgid = 1; @@ -34,6 +33,8 @@ static syslog_entry_t *syslogQueue = NULL; static enum syslog_state syslogState = SYSLOG_NONE; +static bool syslog_timer_armed = false; + static void ICACHE_FLASH_ATTR syslog_add_entry(syslog_entry_t *entry); static void ICACHE_FLASH_ATTR syslog_chk_status(void); static void ICACHE_FLASH_ATTR syslog_udp_sent_cb(void *arg); @@ -45,6 +46,52 @@ static void ICACHE_FLASH_ATTR syslog_udp_recv_cb(void *arg, char *pusrdata, unsi #define syslog_send_udp() post_usr_task(syslog_task,0) +#ifdef SYSLOG_DBG +static char ICACHE_FLASH_ATTR *syslog_get_status(void) { + switch (syslogState) + { + case SYSLOG_NONE: + return "SYSLOG_NONE"; + case SYSLOG_WAIT: + return "SYSLOG_WAIT"; + case SYSLOG_INIT: + return "SYSLOG_INIT"; + case SYSLOG_INITDONE: + return "SYSLOG_INITDONE"; + case SYSLOG_DNSWAIT: + return "SYSLOG_DNSWAIT"; + case SYSLOG_READY: + return "SYSLOG_READY"; + case SYSLOG_SENDING: + return "SYSLOG_SENDING"; + case SYSLOG_SEND: + return "SYSLOG_SEND"; + case SYSLOG_SENT: + return "SYSLOG_SENT"; + case SYSLOG_HALTED: + return "SYSLOG_HALTED"; + case SYSLOG_ERROR: + return "SYSLOG_ERROR"; + default: + break; + } + return "UNKNOWN "; +} +#endif + +static void ICACHE_FLASH_ATTR syslog_set_status(enum syslog_state state) { + syslogState = state; + DBG("[%dµs] %s: %s (%d)\n", WDEV_NOW(), __FUNCTION__, syslog_get_status(), state); +} + +static void ICACHE_FLASH_ATTR syslog_timer_arm(int delay) { + static os_timer_t wifi_chk_timer = {}; + syslog_timer_armed = true; + os_timer_disarm(&wifi_chk_timer); + os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_status, NULL); + os_timer_arm(&wifi_chk_timer, delay, 0); +} + /****************************************************************************** * FunctionName : syslog_chk_status * Description : check whether get ip addr or not @@ -55,10 +102,10 @@ static void ICACHE_FLASH_ATTR syslog_chk_status(void) { struct ip_info ipconfig; - //disarm timer first - os_timer_disarm(&wifi_chk_timer); + DBG("[%uµs] %s: id=%lu ", WDEV_NOW(), __FUNCTION__, syslogQueue ? syslogQueue->msgid : 0); - DBG("syslog_chk_status: state: %d ", syslogState); + //disarm timer first + syslog_timer_armed = false; //try to get ip info of ESP8266 station wifi_get_ip_info(STATION_IF, &ipconfig); @@ -70,57 +117,52 @@ static void ICACHE_FLASH_ATTR syslog_chk_status(void) 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); + DBG("%s: Wifi connected\n", syslog_get_status()); + syslog_set_status(SYSLOG_INIT); + syslog_timer_arm(100); break; case SYSLOG_INIT: - DBG("state SYSLOG_INIT: init syslog\n"); + DBG("%s: init syslog\n", syslog_get_status()); + syslog_set_status(SYSLOG_INITDONE); 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); + syslog_timer_arm(10); 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; + DBG("%s: wait for DNS resolver\n", syslog_get_status()); + syslog_timer_arm(10); break; case SYSLOG_READY: - DBG("state SYSLOG_READY: start sending\n"); + DBG("%s: enforce sending\n", syslog_get_status()); syslog_send_udp(); - break; + 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; + DBG("%s: delay\n", syslog_get_status()); + syslog_set_status(SYSLOG_SEND); + syslog_timer_arm(2); break; case SYSLOG_SEND: - DBG("state SYSLOG_SEND: start sending\n"); + DBG("%s: start sending\n", syslog_get_status()); syslog_send_udp(); break; default: - DBG("state DEFAULT: %d\n", syslogState); + DBG("%s: %d\n", syslog_get_status(), syslogState); break; } } else { if ((wifi_status == STATION_WRONG_PASSWORD || wifi_status == STATION_NO_AP_FOUND || wifi_status == STATION_CONNECT_FAIL)) { - syslogState = SYSLOG_ERROR; + syslog_set_status(SYSLOG_ERROR); os_printf("*** connect failure!!!\n"); } else { DBG("re-arming timer...\n"); - os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_status, NULL); - os_timer_arm(&wifi_chk_timer, WIFI_CHK_INTERVAL, 0); + syslog_timer_arm(WIFI_CHK_INTERVAL); } } } @@ -137,16 +179,19 @@ static void ICACHE_FLASH_ATTR syslog_udp_sent_cb(void *arg) struct espconn *pespconn = arg; (void) pespconn; + DBG("[%uµs] %s: id=%lu\n", WDEV_NOW(), __FUNCTION__, syslogQueue ? syslogQueue->msgid : 0); + // datagram is delivered - free and advance queue syslog_entry_t *pse = syslogQueue; syslogQueue = syslogQueue -> next; os_free(pse); if (syslogQueue == NULL) - syslogState = SYSLOG_READY; + syslog_set_status(SYSLOG_READY); else { // UDP seems timecritical - we must ensure a minimum delay after each package... - syslogState = SYSLOG_SENDING; + syslog_set_status(SYSLOG_SENDING); + if (! syslog_timer_armed) syslog_chk_status(); } } @@ -154,8 +199,10 @@ static void ICACHE_FLASH_ATTR syslog_udp_sent_cb(void *arg) 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); + DBG("[%uµs] %s: id=%lu\n", WDEV_NOW(), __FUNCTION__, syslogQueue ? syslogQueue->msgid : 0); + if (syslogQueue == NULL) - syslogState = SYSLOG_READY; + syslog_set_status(SYSLOG_READY); else { int res = 0; syslog_espconn->proto.udp->remote_port = syslogHost.port; // ESP8266 udp remote port @@ -189,15 +236,18 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_ { struct espconn *pespconn = (struct espconn *)arg; (void) pespconn; + + DBG("[%uµs] %s\n", WDEV_NOW(), __FUNCTION__); 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_DNSWAIT; + syslog_set_status(SYSLOG_READY); } else { - syslogState = SYSLOG_ERROR; - DBG("syslog_gethostbyname_cb: state=SYSLOG_ERROR\n"); + syslog_set_status(SYSLOG_ERROR); + DBG("syslog_gethostbyname_cb: status=%s\n", syslog_get_status()); } + DBG("[%uµs] ex syslog_gethostbyname_cb()\n", WDEV_NOW()); } /****************************************************************************** @@ -210,14 +260,15 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) { + DBG("[%uµs] %s\n", WDEV_NOW(), __FUNCTION__); if (!*syslog_host) { - syslogState = SYSLOG_HALTED; + syslog_set_status(SYSLOG_HALTED); return; - } + } if (syslog_host == NULL) { // disable and unregister syslog handler - syslogState = SYSLOG_HALTED; + syslog_set_status(SYSLOG_HALTED); if (syslog_espconn != NULL) { if (syslog_espconn->proto.udp) { // there's no counterpart to espconn_create... @@ -235,7 +286,6 @@ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) pse = next; } syslogQueue = NULL; - syslogState = SYSLOG_HALTED; return; } @@ -272,24 +322,17 @@ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) // wifi_set_broadcast_if(STATIONAP_MODE); // send UDP broadcast from both station and soft-AP interface espconn_create(syslog_espconn); // create udp + syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", + "syslogserver: %s:%d %d", host, syslogHost.port, syslog_espconn->proto.udp->local_port); + if (UTILS_StrToIP((const char *)host, (void*)&syslogHost.addr)) { - syslogState = SYSLOG_READY; - syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", - "syslogserver: %s:%d", host, syslogHost.port); + syslog_set_status(SYSLOG_READY); } else { - syslogState = SYSLOG_DNSWAIT; + syslog_set_status(SYSLOG_DNSWAIT); syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", - "resolving hostname: %s", host); + "must resolve hostname \"%s\"", host); espconn_gethostbyname(syslog_espconn, host, &syslogHost.addr, syslog_gethostbyname_cb); } -#ifdef SYSLOG_UDP_RECV - LOG_NOTICE("syslog_init: host: %s, port: %d, lport: %d, recvcb: %p, sstate: %d", - host, syslogHost.port, syslog_espconn->proto.udp->local_port, - syslog_udp_recv_cb, syslogState ); -#else - LOG_NOTICE("syslog_init: host: %s, port: %d, lport: %d, state: %d", - host, syslogHost.port, syslog_espconn->proto.udp->local_port, syslogState ); -#endif } /****************************************************************************** @@ -303,7 +346,7 @@ syslog_add_entry(syslog_entry_t *entry) { syslog_entry_t *pse = syslogQueue; - DBG("syslog_add_entry: %p", syslogQueue); + DBG("[%dµs] %s id=%lu\n", WDEV_NOW(), __FUNCTION__, entry->msgid); // append msg to syslog_queue if (pse == NULL) syslogQueue = entry; @@ -312,7 +355,7 @@ syslog_add_entry(syslog_entry_t *entry) pse = pse->next; pse->next = entry; // append msg to syslog queue } - DBG("%p %lu %d\n", entry, entry->msgid, system_get_free_heap_size()); +// 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) { @@ -321,7 +364,7 @@ syslog_add_entry(syslog_entry_t *entry) 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; + syslog_set_status(SYSLOG_HALTED); } } } @@ -335,6 +378,7 @@ syslog_add_entry(syslog_entry_t *entry) LOCAL syslog_entry_t ICACHE_FLASH_ATTR * syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...) { + DBG("[%dµs] %s id=%lu\n", WDEV_NOW(), __FUNCTION__, syslog_msgid); 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 @@ -456,7 +500,8 @@ syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char * *******************************************************************************/ void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...) { - DBG("syslog: state=%d ", syslogState); + DBG("[%dµs] %s status: %s\n", WDEV_NOW(), __FUNCTION__, syslog_get_status()); + if (syslogState == SYSLOG_ERROR || syslogState == SYSLOG_HALTED) return; @@ -473,7 +518,8 @@ void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *ta syslog_add_entry(se); if (syslogState == SYSLOG_NONE) - syslogState = SYSLOG_WAIT; + syslog_set_status(SYSLOG_WAIT); - syslog_chk_status(); + if (! syslog_timer_armed) + syslog_chk_status(); } diff --git a/syslog/syslog.h b/syslog/syslog.h index 3c9c73d..ed453ab 100644 --- a/syslog/syslog.h +++ b/syslog/syslog.h @@ -22,6 +22,7 @@ enum syslog_state { SYSLOG_NONE, // not initialized SYSLOG_WAIT, // waiting for Wifi SYSLOG_INIT, // WIFI avail, must initialize + SYSLOG_INITDONE, SYSLOG_DNSWAIT, // WIFI avail, init done, waiting for DNS resolve SYSLOG_READY, // Wifi established, ready to send SYSLOG_SENDING, // UDP package on the air