search

emsesp / EMS-ESP

ESP8266 firmware to read and control EMS and Heatronic compatible equipment such as boilers, thermostats, solar modules, and heat pumps
https://emsesp.github.io/docs
GNU Lesser General Public License v3.0
305 stars 97 forks source link

Syslog syntax #758

Closed lmdecroos closed 3 years ago

lmdecroos commented 3 years ago

I'm wondering if syslog messages are fully compliant with the RFC 5424 specifications? As the ems-esp is using the uptime and not the actual date & time, the syslog messages doesn't have the expected timestamp format.

When I'm forwarding the syslog messages to my influxdb of my grafana monitor, none of the messages of the ems-esp are forwarded. They seems to rejected by the RSYSLOG_SyslogProtocol23Format parsing.

ems-esp syslog messages : Apr 14 20:10:17 ems-esp - 000+23:25:07.732 I 43: [telnet] Connection from [192.168.0.20]:46882 closed Apr 14 20:10:17 ems-esp - 000+23:25:07.732 I 44: [shell] Shutdown console pty0 for connection from [192.168.0.20]:46882 with tcpdump : 20:10:17.155222 IP (tos 0x0, ttl 255, id 15021, offset 0, flags [none], proto UDP (17), length 130) 192.168.0.121.61746 > mini.syslog: SYSLOG, length: 102 Facility daemon (3), Severity info (6) Msg: 1 - ems-esp - - - - \0xef\0xbb\0xbf000+23:25:07.732 I 43: [telnet] Connection from [192.168.0.20]:46882 closed 20:10:17.160100 IP (tos 0x0, ttl 255, id 15022, offset 0, flags [none], proto UDP (17), length 148) 192.168.0.121.61746 > mini.syslog: SYSLOG, length: 120 Facility lpr (6), Severity info (6) Msg: 1 - ems-esp - - - - \0xef\0xbb\0xbf000+23:25:07.732 I 44: [shell] Shutdown console pty0 for connection from [192.168.0.20]:46882

When comparing syslog messages from another server : Apr 14 20:11:20 nasplus System Test message from Synology Syslog Client from (0.0.0.0) with tcpdump : 20:11:47.486459 IP (tos 0x0, ttl 64, id 37434, offset 0, flags [DF], proto UDP (17), length 119) nasplus.local.50793 > mini.syslog: SYSLOG, length: 91 Facility user (1), Severity info (6) Msg: Apr 14 20:11:20 nasplus System Test message from Synology Syslog Client from (0.0.0.0)\0x0a

As the ems-esp has an NTP sync, why is the uptime used and not the actual time for the syslog messages?

proddy commented 3 years ago

I think the fomat is correct reading https://tools.ietf.org/html/rfc5424#section-6.2.3

Also there was a discussion a while ago in https://github.com/emsesp/EMS-ESP/issues/496#issuecomment-728812345 on the special characters \xEF\xBB\xBF which is explained here: https://tools.ietf.org/html/rfc5424#section-6.4

I agree if we have NTP then we should use the real time.

Are you on v2 or v3?

lmdecroos commented 3 years ago

Using the real time (NTP) clock for the date&time would be perfect.

Based on the RFC 3339 specifications it seems we are missing the full date : date-time = full-date "T" full-time

I’m on version 2.2.1 , as I have an ESP8266 I can’t upgrade to version 3

On 15 Apr 2021, at 01:04, Proddy @.***> wrote:

I think the fomat is correct reading https://tools.ietf.org/html/rfc5424#section-6.2.3 https://tools.ietf.org/html/rfc5424#section-6.2.3 I agree if we have NTP then we should use the real time.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/emsesp/EMS-ESP/issues/758#issuecomment-819904865, or unsubscribe https://github.com/notifications/unsubscribe-auth/ANDW44ZEQHW6LR3P2EOOVILTIYNP5ANCNFSM4257P6HA.

proddy commented 3 years ago

But still, the format today is valid so not sure why your 'RSYSLOG_SyslogProtocol23Format' is failing. I'll also try on my grafana setup.

I always wondered why the client is responsible for the timestamp and not the syslog server. maybe worth looking into that too

MichaelDvP commented 3 years ago

@lmdecroos the uptime is part of the message and not the timestamp. The timestamp is skipped in the actual version, but can be reactivated in syslog.cpp. With timestamp it's a bit nasty, because the log shows local time before NTP is connected and UTC after. With timestamp:

Apr 15 13:48:10 ems-esp2 - 000+00:00:00.000 I 0: [syslog] Log level set to INFO
Apr 15 13:48:10 ems-esp2 - 000+00:00:00.000 I 1: [emsesp] EMS Device library loaded with 78 records
Apr 15 11:48:11 ems-esp2 - 000+00:00:01.045 I 2: [emsesp] Starting NTP
       ^^

@proddy BTW: syslog in all v3 versions stick to log-all, independent of set level. Fix is in system.ccp->System::syslog_start() to set syslog_.log_level((uuid::log::Level)syslog_level_); after syslog_.start(); (in dev: line 145)

MichaelDvP commented 3 years ago

@lmdecroos I pushed a new v2-dev with reenabled timestamp. Please check.

lmdecroos commented 3 years ago

@MichelDvP Thanks for pushing a new version. Unfortunately I don’t see any change.

I have dumped the data from my influxdb and spotted that for the syslog messages from my ems-esp the “app” or “service” tag is empty

Syslog with version 2.2.2b0 Apr 15 20:22:10 ems-esp - 000+00:00:00.000 I 2: [system] External multi-functional button enabled Apr 15 20:22:10 ems-esp - 000+00:00:00.000 I 3: [emsesp] EMS Device library loaded with 78 records Apr 15 20:22:10 ems-esp - 000+00:00:04.672 I 4: [emsesp] WiFi Connected with IP=192.168.0.121, hostname=ems-esp Apr 15 18:22:09 ems-esp - 000+00:00:04.727 I 5: [mqtt] MQTT connected

Influxdb dump from my ems-esp syslog,1618510930386555649,,kern,0,mini,ems-esp,000+00:00:00.000 I 1: [emsesp] Syslog started,,info,6,1618510930385690000,1 syslog,1618510930395986737,,kern,0,mini,ems-esp,000+00:00:00.000 I 2: [system] External multi-functional button enabled,,info,6,1618510930395524000,1 syslog,1618510930408498175,,kern,0,mini,ems-esp,000+00:00:00.000 I 3: [emsesp] EMS Device library loaded with 78 records,,info,6,1618510930408057000,1 syslog,1618510930420627414,,kern,0,mini,ems-esp,"000+00:00:04.672 I 4: [emsesp] WiFi Connected with IP=192.168.0.121, hostname=ems-esp",,info,6,1618510930420186000,1 syslog,1618510930429702917,,daemon,3,mini,ems-esp,000+00:00:04.727 I 5: [mqtt] MQTT connected,,info,6,1618510929415938000,1

dump from my Synology nas syslog,1618338442057786018,System,user,1,mini,nasplus," Test message from Synology Syslog Client from (0.0.0.0)",,info,6,1618338415000000000,1 syslog,1618338948314914906,System,user,1,mini,nasplus," Test message from Synology Syslog Client from (0.0.0.0)",,info,6,1618338921000000000,1 syslog,1618423255905287269,System,user,1,mini,nasplus," Test message from Synology Syslog Client from (0.0.0.0)",,info,6,1618423228000000000,1 syslog,1618423907486914880,System,user,1,mini,nasplus," Test message from Synology Syslog Client from (0.0.0.0)",,info,6,1618423880000000000,1

After the first timestamp there is an empty paramater. For my other devices I have system, cron, sshd, sudo, kernel, rsyslogd …

I would assume that this field is not populated by the ems-esp and therefore parsed as an empty field. This is the field where I can select the app in my grafara dashboard

As you earlier mentioned It’s correct that the timestamp is part of the syslog message and therefore has no influence on further parsing.

On 15 Apr 2021, at 17:50, MichaelDvP @.***> wrote:

@lmdecroos https://github.com/lmdecroos I pushed a new v2-dev with reenabled timestamp. Please check.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/emsesp/EMS-ESP/issues/758#issuecomment-820537271, or unsubscribe https://github.com/notifications/unsubscribe-auth/ANDW447L3DJTTASQ2IQFL6LTI4DNTANCNFSM4257P6HA.

MichaelDvP commented 3 years ago

After the first timestamp there is an empty paramater.

No, there is the hostname, but after that there are 4 NILVALUE. Syslog is:

VERSION TIMESTAMP HOSTNAME APPNAME PROCID MSGID STRUCTUREDDATA BOMmessage and we have now VERSION TIMESTAMP HOSTNAME NIL NIL NIL NIL BOMmessage which is conform. We can set APPNAME to `emsesp` and put the IDmessageid to MSGID, but what field do you mean exactly?
lmdecroos commented 3 years ago

What’s missing from the parsing is the name you have in square brackets in the message I would assume this is the APPNAME ( shell, telnet, system, mqtt..)

Thanks in advance

On 16 Apr 2021, at 08:16, MichaelDvP @.***> wrote:

After the first timestamp there is an empty paramater.

No, there is the hostname, but after that there are 4 NILVALUE. Syslog is: VERSION TIMESTAMP HOSTNAME APPNAME PROCID MSGID STRUCTUREDDATA BOMmessage and we have now VERSION TIMESTAMP HOSTNAME NIL NIL NIL NIL BOMmessage which is conform. We can set APPNAME to emsesp and put the IDmessageid to MSGID, but what field do you mean exactly?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/emsesp/EMS-ESP/issues/758#issuecomment-820936934, or unsubscribe https://github.com/notifications/unsubscribe-auth/ANDW444HYV6AP5WKR2WSIZ3TI7I2PANCNFSM4257P6HA.

MichaelDvP commented 3 years ago

I've tested a bit and changed timestamp to local with timezone (only full hours). For the header it tried (output from raspian-syslogd): appname: emesp, procid: message_name: Apr 16 08:31:44 ems-esp2 emsesp[syslog] 000+00:00:00.000 I 0: [syslog] Log level set to INFO appname: message_name, procid: timestamp, ski message_name from message: Apr 17 07:10:21 ems-esp2 syslog[000+00:00:00.000] I 0: Log level set to INFO appname: message_name +:, procid, msgid, struct: nil, and skip message_name from message: Apr 17 08:10:48 ems-esp2 syslog: 000+00:00:00.000 I 0: Log level set to INFO This is now in the latest dev-version.

lmdecroos commented 3 years ago

@MichaelDvP : nice job, works now also with the parsing form syslog to my grafrana dashboard

Screenshot 2021-04-17 at 17 29 33

Many thanks for this enhancement

lmdecroos commented 3 years ago

a small additional request : can you remove the colon from the appname ?

MichaelDvP commented 3 years ago

Done.

lmdecroos commented 3 years ago

Perfect, many thanks

On 17 Apr 2021, at 18:05, MichaelDvP @.***> wrote:

Done.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/emsesp/EMS-ESP/issues/758#issuecomment-821846140, or unsubscribe https://github.com/notifications/unsubscribe-auth/ANDW444AWGSSKESCRXMWYU3TJGWWDANCNFSM4257P6HA.