Syslog format

[styygeli]

I was looking at starting to ingest events via syslog to my fluentd receiver, and after a little bit of back and forth, it initially looks to me that the Syslog messages that tasmota sends don't really conform with the message standard of either RFC3164 or 5424.

Outlet-Speakers1-3236 ESP-MQT: stat/Outlet-Speakers1/RESULT = {"TelePeriod":60}

as an example, it's missing timestamp, loglevel etc, and then has JSON in the payload.

Now to be brutally honest, I don't care too much doing a strict syslog, a pure json would also be very very good format and it's nice to ingest structured data.

So basically, what I would like to see is either

a) RFC5424 format with structured data https://datatracker.ietf.org/doc/html/rfc5424#section-6.3
This would make tasmota syslog output actually real syslog compatible

b) just pure json, include hostname and type whatever is not in the json now, in the json blob. Continue using syslog protocol to send the data

[davidelang]

don't use rfc5424 structured data, almost nobody actually does. It's far better to make the body of the message be JSON. (active contributer to the rsyslog project) adding the proper header to the message is a very good idea. Rsyslog has heuristics to guess that they are missing and generate replacements, but it's always better to have the right data there to start with. Although, is it possible that the hostname is outlet-speakers1-3236 in your example? David Lang

…

On Tue, 1 Feb 2022, Tommi Lätti wrote: Date: Tue, 01 Feb 2022 01:30:50 -0800 From: Tommi Lätti ***@***.***> Reply-To: arendst/Tasmota ***@***.***> To: arendst/Tasmota ***@***.***> Cc: Subscribed ***@***.***> Subject: [arendst/Tasmota] Syslog format (Discussion #14689) I was looking at starting to ingest events via syslog to my fluentd receiver, and after a little bit of back and forth, it initially looks to me that the Syslog messages that tasmota sends don't really conform with the message standard of either RFC3164 or 5424. `Outlet-Speakers1-3236 ESP-MQT: stat/Outlet-Speakers1/RESULT = {"TelePeriod":60}` as an example, it's missing timestamp, loglevel etc, and then has JSON in the payload. Now to be brutally honest, I don't care too much doing a strict syslog, a pure json would also be very very good format and it's nice to ingest structured data. So basically, what I would like to see is either a) RFC5424 format with structured data https://datatracker.ietf.org/doc/html/rfc5424#section-6.3 This would make tasmota syslog output actually real syslog compatible b) just pure json, include hostname and type whatever is not in the json now, in the json blob. Continue using syslog protocol to send the data

[sfromis]

As the syslog lines are just a straight replication of the format already used in the console (and other log locations), using much extra code to invent a different formatting specifically for syslog is not very likely. While many common payloads do include JSON, lots of log messages does not, thus the incidental JSON would then have to be escaped to fit into a uniform JSON syslog format for all types of messages. Not much benefit.

[styygeli]

Yeah if the header bit was unified at least, then the rest of the message bit could be ingested as is as a string and be done with it, and then any syslog consumer could just take it in without any custom regexp parsing.

outlet-speakers1-3236 is the hostname, so it's just missing the time and module in the right format from there I think?

My example line should probably be sent as

Feb 1 10:26:12 outlet-speakers1-3236 <modulename>: andthenwhateverhere

[arendst]

Agree with sfromis.

The way syslog works for years is as shown in the below syslog output:

Jan 31 00:00:38 wkaku5 ESP-MQT: tele/wkaku5/STATE = {"Time":"2022-01-31T00:00:37","Uptime":"185T07:52:58","UptimeSec":16012378,"Heap":25,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":15,"POWER":"ON","Wifi":{"AP":2,"SSId":"indebuurt_IoT","BSSId":"18:E8:29:CA:17:C1","Channel":11,"Mode":"11n","RSSI":100,"Signal":-44,"LinkCount":7,"Downtime":"0T00:03:16"}}
Jan 31 00:00:40 rf1 ESP-MQT: tele/rf1/STATE = {"Time":"2022-01-31T00:00:39","Uptime":"120T06:23:45","UptimeSec":10391025,"Heap":25,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":7,"POWER1":"OFF","Wifi":{"AP":2,"SSId":"indebuurt_IoT","BSSId":"18:E8:29:CA:17:C1","Channel":11,"Mode":"11n","RSSI":100,"Signal":-31,"LinkCount":5,"Downtime":"0T00:03:42"}}
Jan 31 00:00:40 rf1 ESP-MQT: tele/rf1/SENSOR = {"Time":"2022-01-31T00:00:39","ENERGY":{"TotalStartTime":"2020-05-22T00:00:00","Total":52.292,"TotalTariff":[0.000,52.292],"Yesterday":0.245,"Today":0.000,"ExportActive":0.000,"ExportTariff":[0.000,0.000],"Period":1.00,"Power":9.81,"ApparentPower":13.49,"ReactivePower":-9.15,"Factor":0.73,"Frequency":50.0,"Voltage":233.34,"Current":0.075,"ImportActive":71.830,"ImportReactive":0.046,"ExportReactive":140.701,"PhaseAngle":316.65}}
Jan 31 00:00:42 shp6 ESP-MQT: tele/shp6/STATE = {"Time":"2022-01-31T00:00:41","Uptime":"30T11:39:02","UptimeSec":2633942,"Heap":25,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":6,"POWER":"ON","Wifi":{"AP":2,"SSId":"indebuurt_IoT","BSSId":"74:83:C2:2A:F1:AC","Channel":1,"Mode":"11n","RSSI":26,"Signal":-87,"LinkCount":3,"Downtime":"0T00:00:33"}}
Jan 31 00:00:42 shp6 ESP-MQT: domoticz/in = {"idx":301,"nvalue":0,"svalue":"234.6","Battery":100,"RSSI":2}
Jan 31 00:00:42 shp6 ESP-MQT: domoticz/in = {"idx":302,"nvalue":0,"svalue":"0.213","Battery":100,"RSSI":2}
Jan 31 00:00:42 shp6 ESP-MQT: domoticz/in = {"idx":300,"nvalue":0,"svalue":"0;6907.6","Battery":100,"RSSI":2}
Jan 31 00:00:42 shp6 ESP-MQT: domoticz/in = {"idx":303,"nvalue":0,"svalue":"3975.6;2928.0;0.0;0.0;0;0","Battery":100,"RSSI":2}
Jan 31 00:00:42 shp6 ESP-MQT: tele/shp6/SENSOR = {"Time":"2022-01-31T00:00:41","ENERGY":{"TotalStartTime":"2020-02-17T00:00:00","Total":6.908,"TotalTariff":[3.976,2.928],"Yesterday":0.005,"Today":0.000,"Period":0.01,"Power":0.30,"ApparentPower":49.97,"ReactivePower":50.00,"Factor":0.01,"Voltage":234.6,"Current":0.213}}
Jan 31 00:00:43 sspm2 ESP-SPM: ESP AA5501000000000000000000000000001800106B7E3237393734134B3536370101003CDA9FD1
Jan 31 00:00:43 sspm2 ESP-SPM: ARM AA55010000000000000000000000008018000105DA35D1
Jan 31 00:00:43 sspm2 ESP-SPM: Command 24 result 5

Worked perfectly.

[styygeli]

Ah well, that's a shame, no uniform structure whatsoever and doesn't adhere to any standard. Should perhaps stop calling it 'Syslog' then.

[sfromis]

It would be illogical not to call it syslog when the data is sent to a syslog server. There also exists other software where raw format, with only message text, is logged.

[styygeli]

sure, I just personally wouldn't call something syslog when it doesn't conform to the full spec

[joba-1]

your choice, but you also call rfc3164 a standard, while the document itself says it is not?

Then the rfc says „It should be reiterated here that the payload of any IP packet destined to UDP port 514 MUST be considered to be a valid syslog message“

and goes on with just a recommendation „It is, however, RECOMMENDED that the syslog packet have all of the parts described in Section 4.1 - PRI, HEADER and MSG“

So it seems to me tasmota does conform to the rfc in this regard and this should be called doing syslog. No need for usercode breaking or code inflating changes.

[davidelang]

as far as things that violate the syslog spec, this is pretty trivial (the default output of syslog-ng is much messier to deal with for example, and that entire program bills itself as syslog)

[davidelang]

On Tue, 1 Feb 2022, sfromis wrote: It would be illogical not to call it syslog when the data is sent to a syslog server. There also exists other cases where raw format, with only message text, is logged.

The problem with sending raw data with no header is that the syslog server that's receiving it has to guess as to what the different parts are. Is the first string the hostname, the programname, or the beginning of the message text? I'm not worried about the body of the message, that is not standardized and so anyone dealing with syslog gets used to parsing it (and the mmnormalize module in rsyslog makes short work of it, other syslog servers have regex engines that can get the job done with a bit more cpu) But it would be good if we could be confident that we are always sending the hostname, a category name and then the message. it would be nice to also send the timestamp, but detecting that it's missing and replacing it with the local time on the server when it was processed is reliable enough that it's not a big problem. David Lang

[davidelang]

actually, it looks like we do always have the hostname and programname, so it should be pretty reliable. not having timestamp and facility/severity isn't nice, but it's far from the worst.

[styygeli]

indeed it would be nice if the header side would get normalised to conform the syslog format, then pretty much any implementation of syslog servers could slurp it in by default without having to write a regexp bit to accept the messages (like I would have to with fluentd, and I assume with many other ones too).

After it's in there, anybody can then write whatever transform filter they want and push It out to elastic etc

[stefanbode]

I use the syslog server from Synology and it worked for me either quite well. I have no problems with the timestamp nor with the device sending the information. Compared to your first complaint I do not see this problem.

[styygeli]

If somebody could point me to where the syslog sending bits in the code are, I can take a look. I only know python/ruby though but who knows, might be easy for me too to test out.

[sfromis]

Searching for "syslog" led to the function SyslogAsync:
https://github.com/arendst/Tasmota/blob/development/tasmota/support.ino#L2364-L2423

[arendst]

That's the correct function.

Remember though that Tasmota (debug) logging is all about as much information in as less code/RAM space representing asynchronously to fix interrupt issues. Current logging uses a rotating RAM buffer of max 4k on ESP8266 and 6k on ESP32. It does not store log levels and time simply because it takes too much logging space. In addition the following assumptions are made:

• Tasmota log messages need to be as small as possible for the above reason (JSON is overhead)
• syslog server can provide it's own timestamp
• log levels are of no use for debugging purposes

A user is supposed to use the provided MQTT JSON messages and NOT the hybrid syslog output. It's not meant for that.

[styygeli]

A user is supposed to use the provided MQTT JSON messages and NOT the hybrid syslog output. It's not meant for that.

You mean, I should just write a simple regexp filter on my syslog server that matches the 'syslog' lines that have JSON, and just ignore the rest? Because I can definitely do that too. It looks like the rest of the lines don't contain much useful information.

4k has plenty of space though, if a timestamp and fake loglevel/facility takes like, 40 bytes that's like 0.08% of 4k?

[sfromis]

No, the point is that users are supposed to use MQTT for a backend keeping track of Tasmota device activities, syslog is not meant for this, but is more of an extra feature for debugging purposes. The "M" in the Tasmota name is for MQTT.

4K is not "plenty of space" as it is not for a single message, but for a rotating RAM buffer with potentially many messages. Longer messages reduces buffer capacity, and increases risk of it running full.

[gweiss76]

Just as a reference here...(as i got hit by this). Setting hostnames in tasmota starting with "z" will trigger rsyslog/rsyslog#4598 in rsyslogd. Just to make you aware.

[arendst]

Fixed in dev branch v13.3.0.1