Console and Syslog log formats are different

[IgorAga]

When logging to both Console and Syslog I'm getting completely different format of log entries:

Example:

Zigbee2MQTT:info 2021-11-28 15:29:56: Currently 8 devices are joined: in Console entry

2021-11-28T12:29:56.860+03:00 192.168.0.2 zigbee2mqtt - - - Currently 8 devices are joined:<134>1 without new line in Syslog entry for most of entries.

As a result Syslog becomes completely unreadable, while Console output is clear.

My logging settings are as following:

log_level: info
log_output: ['console', 'syslog']
log_syslog:
app_name: zigbee2mqtt
host: 192.168.0.6
localhost: 192.168.0.2
pid: process.pid
port: 514
protocol: tcp4
type: '5424'

Another point is that log_level: parameter works fine for Console output, however Syslog always logs in log_level: debug mode.

My rsyslog.service is running on 192.168.0.6 and is serving several other logs without any problem.

And yes, I am in timezone UTC+3... but don't see any need to remind me in every log entry about that.

Thanks in advance.

[amadeo-alex]

The messages being one big chunk of text might be a bug (please see PR referenced below).
Regarding the log format itself, dirty copying format parameter from file logger unfortunately ends up with this:

This is because zigbee2mqtt is not directly responsible for the syslog messages format. As far as I've been able to quickly check, the formatting is done by #glossy (used by #winston-syslog). z2m just passed message content.

This could be changed by providing customProducer to glossy.

[amadeo-alex]

Interesting, the PR solved the issue for me on Kiwi Syslog Server (windows syslog server), but when I pointed z2m to my rsyslog server it failed miserably with:

The first message starts with:

and ends with:

The same happens with "vanilla" z2m, something is not right here. Seems like z2m is not sending proper line endings?

[amadeo-alex]

"Interesting intensifies"
I've switched to UDP as a means of transport:

As you can see, this time there is no newline issue (afaik each UDP message is treated as a separate message, that would explain this). The interesting thing is the "\n" at the end of each message.

My EOL settings:

I've searched a bit after that and found this: winstonjs/winston-syslog#150
Seems like exactly the same issue. This person has "<13>" between the messages, if you look closely in my case, when TCP is selected as a means of transport, there are "<134>" between the messages (in addition to "\n" specified in the z2m config).

[IgorAga]

I tried to switch to UDP - and yes, it solves newline issue (I do not have eol: \n in my configuration).

Nov 29 06:19:27 192.168.0.2 zigbee2mqtt Logging to console only'
Nov 29 06:19:27 192.168.0.2 zigbee2mqtt Starting Zigbee2MQTT version 1.22.0 (commit #df0543d4)
Nov 29 06:19:27 192.168.0.2 zigbee2mqtt Starting zigbee-herdsman (0.13.164)

Funny thing, however, is that with UDP configured it shows timestamp in different format and UTC only (local time is 09:19:27 i this case).

That's definitely better, but raises another issue with the timestamp :)

[IgorAga]

Interesting point is that timestamp in Console output is in local timezone:

Zigbee2MQTT:info 2021-11-29 09:40:40: Logging to console only'
Zigbee2MQTT:info 2021-11-29 09:40:41: Starting Zigbee2MQTT version 1.22.0 (commit #df0543d4)
Zigbee2MQTT:info 2021-11-29 09:40:41: Starting zigbee-herdsman (0.13.164)

while the same entries in Syslog are in UTC:

Nov 29 06:40:40 192.168.0.2 zigbee2mqtt Logging to console only'
Nov 29 06:40:41 192.168.0.2 zigbee2mqtt Starting Zigbee2MQTT version 1.22.0 (commit #df0543d4)
Nov 29 06:40:41 192.168.0.2 zigbee2mqtt Starting zigbee-herdsman (0.13.164)

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days