syslog: fixup

- implement syslog filter - honour timezone setting - rework syslog format - finish (really?) syslog documentation
9 years ago · 0248d1f698
parent 8791bda62d
commit 0248d1f698
2 changed files with 58 additions and 29 deletions
--- 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);
+    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);
--- 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**.