wirtz
/
esp-link
mirror of https://github.com/jeelabs/esp-link.git
1
0
Fork 0
Code Issues Releases Wiki Activity

Merge pull request #80 from susisstrolch/TvEmaster

Browse Source 
syslog: fix UDP timing problems
pull/91/head
Thorsten von Eicken 9 years ago
parent 59d4bdf99e 077bcaf02d
commit 0c6b798f38
4 changed files with 451 additions and 159 deletions
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Show Stats Download Patch File Download Diff File
  1. 4
      include/user_config.h
  2. 445
      syslog/syslog.c
  3. 9
      syslog/syslog.h
  4. 146
      syslog/syslog.md

4
include/user_config.h
Unescape View File

@ -31,8 +31,8 @@
#define UART_DBG #define UART_DBG
#define MDNS_DBG #define MDNS_DBG
#define OPTIBOOT_DBG #define OPTIBOOT_DBG
#define SYSLOG_DBG #undef SYSLOG_DBG
#define CGISERVICES_DBG #undef CGISERVICES_DBG
// If defined, the default hostname for DHCP will include the chip ID to make it unique // If defined, the default hostname for DHCP will include the chip ID to make it unique
#undef CHIP_IN_HOSTNAME #undef CHIP_IN_HOSTNAME

445
syslog/syslog.c
Unescape View File

@ -23,9 +23,8 @@ extern void * mem_trim(void *m, size_t s); // not well documented...
#endif #endif
#define WIFI_CHK_INTERVAL 1000 // ms to check Wifi statis #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 uint32_t syslog_msgid = 1;
static uint8_t syslog_task = 0; static uint8_t syslog_task = 0;
@ -34,144 +33,136 @@ static syslog_entry_t *syslogQueue = NULL;
static enum syslog_state syslogState = SYSLOG_NONE; 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_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 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 #ifdef SYSLOG_UDP_RECV
static void ICACHE_FLASH_ATTR syslog_udp_recv_cb(void *arg, char *pusrdata, unsigned short length); static void ICACHE_FLASH_ATTR syslog_udp_recv_cb(void *arg, char *pusrdata, unsigned short length);
#endif #endif
#define syslog_send_udp() post_usr_task(syslog_task,0) #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_wifi_stat * FunctionName : syslog_chk_status
* Description : check whether get ip addr or not * Description : check whether get ip addr or not
* Parameters : none * Parameters : none
* Returns : 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; struct ip_info ipconfig;
DBG("syslog_chk_wifi_stat: state: %d ", syslogState);
DBG("[%uµs] %s: id=%lu ", WDEV_NOW(), __FUNCTION__, syslogQueue ? syslogQueue->msgid : 0);
//disarm timer first //disarm timer first
os_timer_disarm(&wifi_chk_timer); syslog_timer_armed = false;
//try to get ip info of ESP8266 station //try to get ip info of ESP8266 station
wifi_get_ip_info(STATION_IF, &ipconfig); wifi_get_ip_info(STATION_IF, &ipconfig);
int wifi_status = wifi_station_get_connect_status(); int wifi_status = wifi_station_get_connect_status();
if (wifi_status == STATION_GOT_IP && ipconfig.ip.addr != 0) if (wifi_status == STATION_GOT_IP && ipconfig.ip.addr != 0)
{ {
if (syslogState == SYSLOG_WAIT) { // waiting for initialization // it seems we have to add an additional delay after the Wifi is up and running.
DBG("connected, initializing UDP socket\n"); // so we simply add an intermediate state with 25ms delay
switch (syslogState)
{
case SYSLOG_WAIT:
DBG("%s: Wifi connected\n", syslog_get_status());
syslog_set_status(SYSLOG_INIT);
syslog_timer_arm(100);
break;
case SYSLOG_INIT:
DBG("%s: init syslog\n", syslog_get_status());
syslog_set_status(SYSLOG_INITDONE);
syslog_init(flashConfig.syslog_host); syslog_init(flashConfig.syslog_host);
syslog_timer_arm(10);
break;
case SYSLOG_DNSWAIT:
DBG("%s: wait for DNS resolver\n", syslog_get_status());
syslog_timer_arm(10);
break;
case SYSLOG_READY:
DBG("%s: enforce sending\n", syslog_get_status());
syslog_send_udp();
break;
case SYSLOG_SENDING:
DBG("%s: delay\n", syslog_get_status());
syslog_set_status(SYSLOG_SEND);
syslog_timer_arm(2);
break;
case SYSLOG_SEND:
DBG("%s: start sending\n", syslog_get_status());
syslog_send_udp();
break;
default:
DBG("%s: %d\n", syslog_get_status(), syslogState);
break;
} }
} else { } else {
if ((wifi_status == STATION_WRONG_PASSWORD || if ((wifi_status == STATION_WRONG_PASSWORD ||
wifi_status == STATION_NO_AP_FOUND || wifi_status == STATION_NO_AP_FOUND ||
wifi_status == STATION_CONNECT_FAIL)) { wifi_status == STATION_CONNECT_FAIL)) {
syslogState = SYSLOG_ERROR; syslog_set_status(SYSLOG_ERROR);
os_printf("*** connect failure!!!\n"); os_printf("*** connect failure!!!\n");
} else { } else {
DBG("re-arming timer...\n"); DBG("re-arming timer...\n");
os_timer_setfn(&wifi_chk_timer, (os_timer_func_t *)syslog_chk_wifi_stat, NULL); syslog_timer_arm(WIFI_CHK_INTERVAL);
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;
} }
} }
} }
@ -188,15 +179,39 @@ static void ICACHE_FLASH_ATTR syslog_udp_sent_cb(void *arg)
struct espconn *pespconn = arg; struct espconn *pespconn = arg;
(void) pespconn; (void) pespconn;
DBG("[%uµs] %s: id=%lu\n", WDEV_NOW(), __FUNCTION__, syslogQueue ? syslogQueue->msgid : 0);
// datagram is delivered - free and advance queue // datagram is delivered - free and advance queue
syslog_entry_t *pse = syslogQueue; syslog_entry_t *pse = syslogQueue;
syslogQueue = syslogQueue -> next; syslogQueue = syslogQueue -> next;
os_free(pse); os_free(pse);
if (syslogQueue != NULL) if (syslogQueue == NULL)
syslog_send_udp(); syslog_set_status(SYSLOG_READY);
else else {
syslogState = SYSLOG_READY; // UDP seems timecritical - we must ensure a minimum delay after each package...
syslog_set_status(SYSLOG_SENDING);
if (! syslog_timer_armed)
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);
DBG("[%uµs] %s: id=%lu\n", WDEV_NOW(), __FUNCTION__, syslogQueue ? syslogQueue->msgid : 0);
if (syslogQueue == NULL)
syslog_set_status(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);
}
}
} }
/***************************************************************************** /*****************************************************************************
@ -221,14 +236,18 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_
{ {
struct espconn *pespconn = (struct espconn *)arg; struct espconn *pespconn = (struct espconn *)arg;
(void) pespconn; (void) pespconn;
DBG("[%uµs] %s\n", WDEV_NOW(), __FUNCTION__);
if (ipaddr != NULL) { if (ipaddr != NULL) {
syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG",
"resolved hostname: %s: " IPSTR, name, IP2STR(ipaddr));
syslogHost.addr.addr = ipaddr->addr; syslogHost.addr.addr = ipaddr->addr;
syslogState = SYSLOG_SENDING; syslog_set_status(SYSLOG_READY);
syslog_send_udp();
} else { } else {
syslogState = SYSLOG_ERROR; syslog_set_status(SYSLOG_ERROR);
DBG("syslog_gethostbyname_cb: state=SYSLOG_ERROR\n"); DBG("syslog_gethostbyname_cb: status=%s\n", syslog_get_status());
} }
DBG("[%uµs] ex syslog_gethostbyname_cb()\n", WDEV_NOW());
} }
/****************************************************************************** /******************************************************************************
@ -240,55 +259,175 @@ static void ICACHE_FLASH_ATTR syslog_gethostbyname_cb(const char *name, ip_addr_
*******************************************************************************/ *******************************************************************************/
void ICACHE_FLASH_ATTR syslog_init(char *syslog_host) void ICACHE_FLASH_ATTR syslog_init(char *syslog_host)
{ {
DBG("[%uµs] %s\n", WDEV_NOW(), __FUNCTION__);
if (!*syslog_host) { if (!*syslog_host) {
syslogState = SYSLOG_HALTED; syslog_set_status(SYSLOG_HALTED);
return; return;
} }
char host[32], *port = &host[0];
syslog_task = register_usr_task(syslog_udp_send_event); if (syslog_host == NULL) {
syslogHost.min_heap_size = flashConfig.syslog_minheap; // disable and unregister syslog handler
syslogHost.port = 514; syslog_set_status(SYSLOG_HALTED);
syslogState = SYSLOG_WAIT; 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); os_strncpy(host, syslog_host, 32);
while (*port && *port != ':') // find port delimiter while (*port && *port != ':') // find port delimiter
port++; port++;
if (*port) { if (*port) {
*port++ = '\0'; *port++ = '\0';
syslogHost.port = atoi(port); syslogHost.port = atoi(port);
} }
wifi_set_broadcast_if(STATIONAP_MODE); // send UDP broadcast from both station and soft-AP interface if (syslogHost.port == 0)
syslog_espconn.type = ESPCONN_UDP; syslogHost.port = 514;
syslog_espconn.proto.udp = (esp_udp *)os_zalloc(sizeof(esp_udp));
syslog_espconn.proto.udp->local_port = espconn_port(); // set a available port // 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 #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 #endif
espconn_regist_sentcb(&syslog_espconn, syslog_udp_sent_cb); // register a udp packet sent callback espconn_regist_sentcb(syslog_espconn, syslog_udp_sent_cb); // register a udp packet sent callback
espconn_create(&syslog_espconn); // create udp 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
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)) { if (UTILS_StrToIP((const char *)host, (void*)&syslogHost.addr)) {
syslogState = SYSLOG_SENDING; syslog_set_status(SYSLOG_READY);
syslog_send_udp();
} else { } else {
static struct espconn espconn_ghbn; syslog_set_status(SYSLOG_DNSWAIT);
espconn_gethostbyname(&espconn_ghbn, host, &syslogHost.addr, syslog_gethostbyname_cb); syslog(SYSLOG_FAC_USER, SYSLOG_PRIO_NOTICE, "SYSLOG",
// syslog_send_udp is called by syslog_gethostbyname_cb() "must resolve hostname \"%s\"", host);
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,
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,
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("[%dµs] %s id=%lu\n", WDEV_NOW(), __FUNCTION__, entry->msgid);
// 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();
syslog_set_status(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, ...)
{
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;
// 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:%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);
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++);
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 * FunctionName : syslog
* Description : compose and queue a new syslog message * Description : compose and queue a new syslog message
* Parameters : facility * Parameters : facility
@ -361,11 +500,15 @@ void ICACHE_FLASH_ATTR syslog_init(char *syslog_host)
*******************************************************************************/ *******************************************************************************/
void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *tag, const char *fmt, ...) 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 || if (syslogState == SYSLOG_ERROR ||
syslogState == SYSLOG_HALTED) syslogState == SYSLOG_HALTED)
return; return;
if (severity > flashConfig.syslog_filter)
return;
// compose the syslog message // compose the syslog message
void *arg = __builtin_apply_args(); void *arg = __builtin_apply_args();
void *res = __builtin_apply((void*)syslog_compose, arg, 128); void *res = __builtin_apply((void*)syslog_compose, arg, 128);
@ -374,13 +517,9 @@ void ICACHE_FLASH_ATTR syslog(uint8_t facility, uint8_t severity, const char *ta
// and append it to the message queue // and append it to the message queue
syslog_add_entry(se); syslog_add_entry(se);
if (syslogState == SYSLOG_READY) { if (syslogState == SYSLOG_NONE)
syslogState = SYSLOG_SENDING; syslog_set_status(SYSLOG_WAIT);
syslog_send_udp();
}
if (syslogState == SYSLOG_NONE) { if (! syslog_timer_armed)
syslogState = SYSLOG_WAIT; syslog_chk_status();
syslog_chk_wifi_stat(); // fire the timer to check the Wifi connection status
}
} }

9
syslog/syslog.h
Unescape View File

@ -20,9 +20,14 @@ extern "C" {
enum syslog_state { enum syslog_state {
SYSLOG_NONE, // not initialized SYSLOG_NONE, // not initialized
SYSLOG_WAIT, // initialized, waiting for Wifi 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_READY, // Wifi established, ready to send
SYSLOG_SENDING, // UDP package on the air SYSLOG_SENDING, // UDP package on the air
SYSLOG_SEND,
SYSLOG_SENT,
SYSLOG_HALTED, // heap full, discard message SYSLOG_HALTED, // heap full, discard message
SYSLOG_ERROR, SYSLOG_ERROR,
}; };
@ -78,6 +83,8 @@ struct syslog_host_t {
typedef struct syslog_entry_t syslog_entry_t; typedef struct syslog_entry_t syslog_entry_t;
struct syslog_entry_t { struct syslog_entry_t {
syslog_entry_t *next; syslog_entry_t *next;
uint32_t msgid;
uint32_t tick;
uint16_t datagram_len; uint16_t datagram_len;
char datagram[]; char datagram[];
}; };

146
syslog/syslog.md
Unescape View File

@ -0,0 +1,146 @@
syslog
======
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:
```
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
```
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 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 "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**
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
========
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.
+ If **syslog_showdate** == 1, the syslog _server_ MAY replace it's own receive timestamp with the timestamp sent by the syslog client.
+ Some syslog servers don't show the fractional seconds of the syslog timestamp
+ 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.
+ Some servers (e.g. _Synology_) won't show the syslog message if you set **facility** to **SYSLOG_FAC_SYSLOG**.
Write Preview
Loading…
Cancel
Save