From a77f032bb3023910c3500eda74fd15a2d75003d7 Mon Sep 17 00:00:00 2001 From: susisstrolch Date: Tue, 12 Jan 2016 02:09:17 +0100 Subject: [PATCH] syslog: various improvements - increase delay (100ms) after successfull syslog host lookup to avoid loss of UDP packages - use own espconn for syslog host lookup - fix horrible memory hole because of non-working mem_trim - reuse warning datagram in case of heap overflow - use own espconn for syslog-host lookup - remove some debug messages --- syslog/syslog.c | 64 +++++++++++++++++++++++++++++++------------------ 1 file changed, 41 insertions(+), 23 deletions(-) diff --git a/syslog/syslog.c b/syslog/syslog.c index 20a51cb..377b5b9 100644 --- a/syslog/syslog.c +++ b/syslog/syslog.c @@ -25,6 +25,8 @@ extern void * mem_trim(void *m, size_t s); // not well documented... #define WIFI_CHK_INTERVAL 1000 // ms to check Wifi statis static struct espconn *syslog_espconn = NULL; +static struct espconn *syslog_dnsconn = NULL; + static uint32_t syslog_msgid = 1; static uint8_t syslog_task = 0; @@ -131,7 +133,7 @@ static void ICACHE_FLASH_ATTR syslog_chk_status(void) case SYSLOG_DNSWAIT: DBG("%s: wait for DNS resolver\n", syslog_get_status()); - syslog_timer_arm(10); + syslog_timer_arm(100); break; case SYSLOG_READY: @@ -159,7 +161,7 @@ static void ICACHE_FLASH_ATTR syslog_chk_status(void) wifi_status == STATION_NO_AP_FOUND || wifi_status == STATION_CONNECT_FAIL)) { syslog_set_status(SYSLOG_ERROR); - os_printf("*** connect failure!!!\n"); + os_printf("*** connect failure %d!!!\n", wifi_status); } else { DBG("re-arming timer...\n"); syslog_timer_arm(WIFI_CHK_INTERVAL); @@ -234,11 +236,13 @@ static void ICACHE_FLASH_ATTR syslog_udp_recv_cb(void *arg, char *pusrdata, unsi ******************************************************************************/ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_t *ipaddr, void *arg) { - struct espconn *pespconn = (struct espconn *)arg; - (void) pespconn; - DBG("[%uµs] %s\n", WDEV_NOW(), __FUNCTION__); if (ipaddr != NULL) { + struct espconn *pespconn = (struct espconn *)arg; + // espconn not longer required + os_free(pespconn->proto.udp); + os_free(pespconn); + syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", "resolved hostname: %s: " IPSTR, name, IP2STR(ipaddr)); syslogHost.addr.addr = ipaddr->addr; @@ -322,16 +326,21 @@ 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); +// 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)) { syslog_set_status(SYSLOG_READY); } else { + // we use our own espconn structure to avoid side effects... + if (syslog_dnsconn == NULL) + syslog_dnsconn = (espconn *)os_zalloc(sizeof(espconn)); + + if (syslog_dnsconn->proto.udp == NULL) + syslog_dnsconn->proto.udp = (esp_udp *)os_zalloc(sizeof(esp_udp)); + syslog_set_status(SYSLOG_DNSWAIT); - syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", - "must resolve hostname \"%s\"", host); - espconn_gethostbyname(syslog_espconn, host, &syslogHost.addr, syslog_gethostbyname_cb); +// syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG", "must resolve hostname \"%s\"", host); + espconn_gethostbyname(syslog_dnsconn, host, &syslogHost.addr, syslog_gethostbyname_cb); } } @@ -355,13 +364,14 @@ 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 %s\n", entry, entry->msgid, system_get_free_heap_size(), entry->datagram); // 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"); + // os_printf("syslog_add_entry: Warning: queue filled up (%d), halted\n", system_get_free_heap_size()); + entry->next = syslog_compose(SYSLOG_FAC_USER, SYSLOG_PRIO_CRIT, "SYSLOG", "queue filled up (%d), halted", system_get_free_heap_size()); + os_printf("%s\n", entry->next->datagram); if (syslogState == SYSLOG_READY) syslog_send_udp(); syslog_set_status(SYSLOG_HALTED); @@ -378,11 +388,17 @@ 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, ...) { + union { + uint8_t buf[sizeof (syslog_entry_t) + 1024]; + syslog_entry_t se; + } sl; + 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 - se->msgid = syslog_msgid; + + sl.se.next = NULL; + sl.se.msgid = syslog_msgid; + sl.se.tick = WDEV_NOW(); // 0 ... 4294.967295s + char *p = sl.se.datagram; // The Priority value is calculated by first multiplying the Facility // number by 8 and then adding the numerical value of the Severity. @@ -398,21 +414,21 @@ syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char * // 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; + now = (realtime_stamp == 0) ? (sl.se.tick / 1000000) : realtime_stamp; tp = gmtime(&now); 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); if (realtime_stamp == 0) - p += os_sprintf(p, ".%06luZ ", se->tick % 1000000); + p += os_sprintf(p, ".%06luZ ", sl.se.tick % 1000000); else p += os_sprintf(p, "%+03d:00 ", flashConfig.timezone_offset); } // 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++); + p += os_sprintf(p, "%s %s %lu.%06lu %lu ", flashConfig.hostname, tag, sl.se.tick / 1000000, sl.se.tick % 1000000, syslog_msgid++); else p += os_sprintf(p, "%s %s - %lu ", flashConfig.hostname, tag, syslog_msgid++); @@ -422,8 +438,9 @@ syslog_compose(uint8_t facility, uint8_t severity, const char *tag, const char * 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); + sl.se.datagram_len = 1 + p - sl.se.datagram; + syslog_entry_t *se = os_zalloc(sizeof (syslog_entry_t) + sl.se.datagram_len); + os_memcpy(se, &sl.se, sizeof (syslog_entry_t) + sl.se.datagram_len); return se; } @@ -503,7 +520,8 @@ void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *ta DBG("[%dµs] %s status: %s\n", WDEV_NOW(), __FUNCTION__, syslog_get_status()); if (syslogState == SYSLOG_ERROR || - syslogState == SYSLOG_HALTED) + syslogState == SYSLOG_HALTED || + flashConfig.syslog_host[0] == '\0') return; if (severity > flashConfig.syslog_filter)