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: