HOST macro problems when ending messages between syslog-ng instances via OTLP/gRPC

[czanik]

I wanted to learn about OpenTelemetry. Before looking at other log sources / destinations I wanted to get OTLP working between two syslog-ng instances.

The sender host is called fedora, and has the following config:

destination d_syslog_ng_otlp {
  syslog-ng-otlp(url("172.16.167.174:6514"));
};

log {source(s_sys); destination(d_syslog_ng_otlp);};

destination d_file {
  file("/var/log/otel.json" template("$(format-json --scope everything)\n\n"));
};

log {source(s_sys); destination(d_file); };

The receiving host is called tumbleweed, and has the following config:

source s_syslog_ng_otlp {
  syslog-ng-otlp(port(6514));
};

destination d_file {
  file("/var/log/otel");
  file("/var/log/otel.json" template("$(format-json --scope everything)\n\n"));
};

log {source(s_syslog_ng_otlp); destination(d_file); };

Expectation: I see the same log on both hosts:

Nov 27 13:35:42 fedora root[1545]: bla

Reality: on the receiving host the log created on fedora looks like:

Nov 27 13:35:42 tumbleweed root[1545]: bla

Next I created file destinations with JSON formatting and printed all name-value pairs on both hosts.

Output of logger bla on the source side:

{"_journald":{"_UID":"0","_TRANSPORT":"syslog","_SOURCE_REALTIME_TIMESTAMP":"1701088542218225","_SELINUX_CONTEXT":"unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023","_RUNTIME_SCOPE":"system","_PID":"1545","_MACHINE_ID":"be64aeb7a12a42f9b2b87aea8b6eaa65","_HOSTNAME":"fedora","_GID":"0","_COMM":"logger","_BOOT_ID":"fa2a6112342d4ad29e989efaa0f1ac50","SYSLOG_TIMESTAMP":"Nov 27 13:35:42 ","SYSLOG_IDENTIFIER":"root","SYSLOG_FACILITY":"1","PRIORITY":"5","MESSAGE":"bla"},"YEAR_DAY":"331","YEAR":"2023","WEEK_DAY_NAME":"Monday","WEEK_DAY_ABBREV":"Mon","WEEK_DAY":"2","WEEKDAY":"Mon","WEEK":"48","USEC":"218468","UNIXTIME":"1701088542","TZOFFSET":"+01:00","TZ":"+01:00","TAGS":[".source.s_sys"],"TAG":"0d","S_YEAR_DAY":"331","S_YEAR":"2023","S_WEEK_DAY_NAME":"Monday","S_WEEK_DAY_ABBREV":"Mon","S_WEEK_DAY":"2","S_WEEKDAY":"Mon","S_WEEK":"48","S_USEC":"218468","S_UNIXTIME":"1701088542","S_TZOFFSET":"+01:00","S_TZ":"+01:00","S_STAMP":"Nov 27 13:35:42","S_SEC":"42","S_MSEC":"218","S_MONTH_WEEK":"4","S_MONTH_NAME":"November","S_MONTH_ABBREV":"Nov","S_MONTH":"11","S_MIN":"35","S_ISOWEEK":"48","S_ISODATE":"2023-11-27T13:35:42+01:00","S_HOUR12":"01","S_HOUR":"13","S_FULLDATE":"2023 Nov 27 13:35:42","S_DAY":"27","S_DATE":"Nov 27 13:35:42","S_AMPM":"PM","SYSUPTIME":"584","STAMP":"Nov 27 13:35:42","SOURCEIP":"127.0.0.1","SOURCE":"s_sys","SEVERITY_NUM":5,"SEVERITY":"notice","SEC":"42","R_YEAR_DAY":"331","R_YEAR":"2023","R_WEEK_DAY_NAME":"Monday","R_WEEK_DAY_ABBREV":"Mon","R_WEEK_DAY":"2","R_WEEKDAY":"Mon","R_WEEK":"48","R_USEC":"478865","R_UNIXTIME":"1701088542","R_TZOFFSET":"+01:00","R_TZ":"+01:00","R_STAMP":"Nov 27 13:35:42","R_SEC":"42","R_MSEC":"478","R_MONTH_WEEK":"4","R_MONTH_NAME":"November","R_MONTH_ABBREV":"Nov","R_MONTH":"11","R_MIN":"35","R_ISOWEEK":"48","R_ISODATE":"2023-11-27T13:35:42+01:00","R_HOUR12":"01","R_HOUR":"13","R_FULLDATE":"2023 Nov 27 13:35:42","R_DAY":"27","R_DATE":"Nov 27 13:35:42","R_AMPM":"PM","RUNID":"7","RAWMSG_SIZE":0,"P_YEAR_DAY":"331","P_YEAR":"2023","P_WEEK_DAY_NAME":"Monday","P_WEEK_DAY_ABBREV":"Mon","P_WEEK_DAY":"2","P_WEEKDAY":"Mon","P_WEEK":"48","P_USEC":"479570","P_UNIXTIME":"1701088542","P_TZOFFSET":"+01:00","P_TZ":"+01:00","P_STAMP":"Nov 27 13:35:42","P_SEC":"42","P_MSEC":"479","P_MONTH_WEEK":"4","P_MONTH_NAME":"November","P_MONTH_ABBREV":"Nov","P_MONTH":"11","P_MIN":"35","P_ISOWEEK":"48","P_ISODATE":"2023-11-27T13:35:42+01:00","P_HOUR12":"01","P_HOUR":"13","P_FULLDATE":"2023 Nov 27 13:35:42","P_DAY":"27","P_DATE":"Nov 27 13:35:42","P_AMPM":"PM","PROTO":0,"PROGRAM":"root","PRIORITY":"notice","PRI":"13","PID":"1545","MSGHDR":"root[1545]: ","MSG":"bla","MSEC":"218","MONTH_WEEK":"4","MONTH_NAME":"November","MONTH_ABBREV":"Nov","MONTH":"11","MIN":"35","MESSAGE":"bla","LOGHOST":"fedora","LEVEL_NUM":5,"LEVEL":"notice","ISOWEEK":"48","ISODATE":"2023-11-27T13:35:42+01:00","IP_PROTO":0,"HOUR12":"01","HOUR":"13","HOST_FROM":"fedora","HOSTID":"85a98c33","HOST":"fedora","FULLDATE":"2023 Nov 27 13:35:42","FACILITY_NUM":1,"FACILITY":"user","DESTPORT":0,"DESTIP":"127.0.0.1","DAY":"27","DATE":"Nov 27 13:35:42","C_YEAR_DAY":"331","C_YEAR":"2023","C_WEEK_DAY_NAME":"Monday","C_WEEK_DAY_ABBREV":"Mon","C_WEEK_DAY":"2","C_WEEKDAY":"Mon","C_WEEK":"48","C_USEC":"479570","C_UNIXTIME":"1701088542","C_TZOFFSET":"+01:00","C_TZ":"+01:00","C_STAMP":"Nov 27 13:35:42","C_SEC":"42","C_MSEC":"479","C_MONTH_WEEK":"4","C_MONTH_NAME":"November","C_MONTH_ABBREV":"Nov","C_MONTH":"11","C_MIN":"35","C_ISOWEEK":"48","C_ISODATE":"2023-11-27T13:35:42+01:00","C_HOUR12":"01","C_HOUR":"13","C_FULLDATE":"2023 Nov 27 13:35:42","C_DAY":"27","C_DATE":"Nov 27 13:35:42","C_AMPM":"PM","BSDTAG":"5B","AMPM":"PM"}

The same log on the receiver side:

{"_journald":{"_UID":"0","_TRANSPORT":"syslog","_SOURCE_REALTIME_TIMESTAMP":"1701088542218225","_SELINUX_CONTEXT":"unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023","_RUNTIME_SCOPE":"system","_PID":"1545","_MACHINE_ID":"be64aeb7a12a42f9b2b87aea8b6eaa65","_HOSTNAME":"fedora","_GID":"0","_COMM":"logger","_BOOT_ID":"fa2a6112342d4ad29e989efaa0f1ac50","SYSLOG_TIMESTAMP":"Nov 27 13:35:42 ","SYSLOG_IDENTIFIER":"root","SYSLOG_FACILITY":"1","PRIORITY":"5","MESSAGE":"bla"},"YEAR_DAY":"331","YEAR":"2023","WEEK_DAY_NAME":"Monday","WEEK_DAY_ABBREV":"Mon","WEEK_DAY":"2","WEEKDAY":"Mon","WEEK":"48","USEC":"218468","UNIXTIME":"1701088542","TZOFFSET":"+01:00","TZ":"+01:00","TRANSPORT":"otlp","TAGS":[".source.s_syslog_ng_otlp",".source.s_sys"],"TAG":"0d","S_YEAR_DAY":"331","S_YEAR":"2023","S_WEEK_DAY_NAME":"Monday","S_WEEK_DAY_ABBREV":"Mon","S_WEEK_DAY":"2","S_WEEKDAY":"Mon","S_WEEK":"48","S_USEC":"218468","S_UNIXTIME":"1701088542","S_TZOFFSET":"+01:00","S_TZ":"+01:00","S_STAMP":"Nov 27 13:35:42","S_SEC":"42","S_MSEC":"218","S_MONTH_WEEK":"4","S_MONTH_NAME":"November","S_MONTH_ABBREV":"Nov","S_MONTH":"11","S_MIN":"35","S_ISOWEEK":"48","S_ISODATE":"2023-11-27T13:35:42+01:00","S_HOUR12":"01","S_HOUR":"13","S_FULLDATE":"2023 Nov 27 13:35:42","S_DAY":"27","S_DATE":"Nov 27 13:35:42","S_AMPM":"PM","SYSUPTIME":"169982","STAMP":"Nov 27 13:35:42","SOURCEIP":"127.0.0.1","SOURCE":"s_syslog_ng_otlp","SEVERITY_NUM":5,"SEVERITY":"notice","SEC":"42","R_YEAR_DAY":"331","R_YEAR":"2023","R_WEEK_DAY_NAME":"Monday","R_WEEK_DAY_ABBREV":"Mon","R_WEEK_DAY":"2","R_WEEKDAY":"Mon","R_WEEK":"48","R_USEC":"478865","R_UNIXTIME":"1701088542","R_TZOFFSET":"+01:00","R_TZ":"+01:00","R_STAMP":"Nov 27 13:35:42","R_SEC":"42","R_MSEC":"478","R_MONTH_WEEK":"4","R_MONTH_NAME":"November","R_MONTH_ABBREV":"Nov","R_MONTH":"11","R_MIN":"35","R_ISOWEEK":"48","R_ISODATE":"2023-11-27T13:35:42+01:00","R_HOUR12":"01","R_HOUR":"13","R_FULLDATE":"2023 Nov 27 13:35:42","R_DAY":"27","R_DATE":"Nov 27 13:35:42","R_AMPM":"PM","RUNID":"5","RAWMSG_SIZE":0,"P_YEAR_DAY":"331","P_YEAR":"2023","P_WEEK_DAY_NAME":"Monday","P_WEEK_DAY_ABBREV":"Mon","P_WEEK_DAY":"2","P_WEEKDAY":"Mon","P_WEEK":"48","P_USEC":"480660","P_UNIXTIME":"1701088542","P_TZOFFSET":"+01:00","P_TZ":"+01:00","P_STAMP":"Nov 27 13:35:42","P_SEC":"42","P_MSEC":"480","P_MONTH_WEEK":"4","P_MONTH_NAME":"November","P_MONTH_ABBREV":"Nov","P_MONTH":"11","P_MIN":"35","P_ISOWEEK":"48","P_ISODATE":"2023-11-27T13:35:42+01:00","P_HOUR12":"01","P_HOUR":"13","P_FULLDATE":"2023 Nov 27 13:35:42","P_DAY":"27","P_DATE":"Nov 27 13:35:42","P_AMPM":"PM","PROTO":0,"PROGRAM":"root","PRIORITY":"notice","PRI":"13","PID":"1545","MSGHDR":"root[1545]: ","MSG":"bla","MSEC":"218","MONTH_WEEK":"4","MONTH_NAME":"November","MONTH_ABBREV":"Nov","MONTH":"11","MIN":"35","MESSAGE":"bla","LOGHOST":"tumbleweed","LEVEL_NUM":5,"LEVEL":"notice","ISOWEEK":"48","ISODATE":"2023-11-27T13:35:42+01:00","IP_PROTO":0,"HOUR12":"01","HOUR":"13","HOST_FROM":"tumbleweed","HOSTID":"1141f424","HOST":"tumbleweed","FULLDATE":"2023 Nov 27 13:35:42","FACILITY_NUM":1,"FACILITY":"user","DESTPORT":0,"DESTIP":"127.0.0.1","DAY":"27","DATE":"Nov 27 13:35:42","C_YEAR_DAY":"331","C_YEAR":"2023","C_WEEK_DAY_NAME":"Monday","C_WEEK_DAY_ABBREV":"Mon","C_WEEK_DAY":"2","C_WEEKDAY":"Mon","C_WEEK":"48","C_USEC":"480660","C_UNIXTIME":"1701088542","C_TZOFFSET":"+01:00","C_TZ":"+01:00","C_STAMP":"Nov 27 13:35:42","C_SEC":"42","C_MSEC":"480","C_MONTH_WEEK":"4","C_MONTH_NAME":"November","C_MONTH_ABBREV":"Nov","C_MONTH":"11","C_MIN":"35","C_ISOWEEK":"48","C_ISODATE":"2023-11-27T13:35:42+01:00","C_HOUR12":"01","C_HOUR":"13","C_FULLDATE":"2023 Nov 27 13:35:42","C_DAY":"27","C_DATE":"Nov 27 13:35:42","C_AMPM":"PM","BSDTAG":"5B","AMPM":"PM"}

As you can see, on the receiving host all host related macros are set to tumbleweed instead of fedora, except for .journald.HOSTNAME.

[bazsi]

Is it perhaps keep-hostname(no) on the receiving end?

[czanik]

No. It's an almost default openSUSE syslog-ng.conf:

#
# Global options.
#
options { chain_hostnames(off); flush_lines(0); perm(0640); stats(freq(3600)); threaded(yes); };

And if you take a closer look at the macros on the receiving side, you will find an interesting one "SOURCEIP":"127.0.0.1" as if the log is originating from the localhost. Is this macro copied over from the source host? It is not really clear for me, which name-value pair is coming from the original message, and what is populated by the destination host.

[bazsi]

On Sat, Dec 2, 2023, 17:16 Peter Czanik ***@***.***> wrote: No. It's an almost default openSUSE syslog-ng.conf: # # Global options. # options { chain_hostnames(off); flush_lines(0); perm(0640); stats(freq(3600)); threaded(yes); }; Keep-hostname(no) is the default.

This may be surprising for not syslog traffic though. And if you take a closer look at the macros on the receiving side, you

will find an interesting one "SOURCEIP":"127.0.0.1" as if the log is originating from the localhost. Is this macro copied over from the source host? It is not really clear for me, which name-value pair is coming from the original message, and what is populated by the destination host.

I think that value is simply not populated. —

…

Reply to this email directly, view it on GitHub <#4729 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAFOK5QAC6ZMXAZCCWXS44LYHNH6FAVCNFSM6AAAAAA737XT32VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQMZXGE4TGNBYGM> . You are receiving this because you commented.Message ID: ***@***.***>

[czanik]

When using the following config with a syslog() source on the same host:

source net {
  syslog(transport(tcp) port(6666));
};
destination fromnet {
  file("/var/log/fromnet" template("$(format-json --scope everything)\n\n"));
  file("/var/log/fromnet.txt");
};
log {source(net); destination(fromnet);};

I get the following logs:

Dec  4 09:44:11 172.16.167.187 root: this is a test again

and the same as JSON:

{"YEAR_DAY":"338","YEAR":"2023","WEEK_DAY_NAME":"Monday","WEEK_DAY_ABBREV":"Mon","WEEK_DAY":"2","WEEKDAY":"Mon","WEEK":"49","USEC":"000000","UNIXTIME":"1701679451","TZOFFSET":"+01:00","TZ":"+01:00","TRANSPORT":"rfc6587","TAGS":[".source.net"],"TAG":"0d","S_YEAR_DAY":"338","S_YEAR":"2023","S_WEEK_DAY_NAME":"Monday","S_WEEK_DAY_ABBREV":"Mon","S_WEEK_DAY":"2","S_WEEKDAY":"Mon","S_WEEK":"49","S_USEC":"000000","S_UNIXTIME":"1701679451","S_TZOFFSET":"+01:00","S_TZ":"+01:00","S_STAMP":"Dec  4 09:44:11","S_SEC":"11","S_MSEC":"000","S_MONTH_WEEK":"1","S_MONTH_NAME":"December","S_MONTH_ABBREV":"Dec","S_MONTH":"12","S_MIN":"44","S_ISOWEEK":"49","S_ISODATE":"2023-12-04T09:44:11+01:00","S_HOUR12":"09","S_HOUR":"09","S_FULLDATE":"2023 Dec  4 09:44:11","S_DAY":"04","S_DATE":"Dec  4 09:44:11","S_AMPM":"AM","SYSUPTIME":"4634","STAMP":"Dec  4 09:44:11","SOURCEIP":"172.16.167.187","SOURCE":"net","SEVERITY_NUM":5,"SEVERITY":"notice","SEC":"11","R_YEAR_DAY":"338","R_YEAR":"2023","R_WEEK_DAY_NAME":"Monday","R_WEEK_DAY_ABBREV":"Mon","R_WEEK_DAY":"2","R_WEEKDAY":"Mon","R_WEEK":"49","R_USEC":"797868","R_UNIXTIME":"1701679451","R_TZOFFSET":"+01:00","R_TZ":"+01:00","R_STAMP":"Dec  4 09:44:11","R_SEC":"11","R_MSEC":"797","R_MONTH_WEEK":"1","R_MONTH_NAME":"December","R_MONTH_ABBREV":"Dec","R_MONTH":"12","R_MIN":"44","R_ISOWEEK":"49","R_ISODATE":"2023-12-04T09:44:11+01:00","R_HOUR12":"09","R_HOUR":"09","R_FULLDATE":"2023 Dec  4 09:44:11","R_DAY":"04","R_DATE":"Dec  4 09:44:11","R_AMPM":"AM","RUNID":"19","RAWMSG_SIZE":53,"P_YEAR_DAY":"338","P_YEAR":"2023","P_WEEK_DAY_NAME":"Monday","P_WEEK_DAY_ABBREV":"Mon","P_WEEK_DAY":"2","P_WEEKDAY":"Mon","P_WEEK":"49","P_USEC":"801409","P_UNIXTIME":"1701679451","P_TZOFFSET":"+01:00","P_TZ":"+01:00","P_STAMP":"Dec  4 09:44:11","P_SEC":"11","P_MSEC":"801","P_MONTH_WEEK":"1","P_MONTH_NAME":"December","P_MONTH_ABBREV":"Dec","P_MONTH":"12","P_MIN":"44","P_ISOWEEK":"49","P_ISODATE":"2023-12-04T09:44:11+01:00","P_HOUR12":"09","P_HOUR":"09","P_FULLDATE":"2023 Dec  4 09:44:11","P_DAY":"04","P_DATE":"Dec  4 09:44:11","P_AMPM":"AM","PROTO":6,"PROGRAM":"root","PRIORITY":"notice","PRI":"13","MSGHDR":"root: ","MSG":"this is a test again","MSEC":"000","MONTH_WEEK":"1","MONTH_NAME":"December","MONTH_ABBREV":"Dec","MONTH":"12","MIN":"44","MESSAGE":"this is a test again","LOGHOST":"tumbleweed","LEVEL_NUM":5,"LEVEL":"notice","LEGACY_MSGHDR":"root: ","ISOWEEK":"49","ISODATE":"2023-12-04T09:44:11+01:00","IP_PROTO":4,"HOUR12":"09","HOUR":"09","HOST_FROM":"172.16.167.187","HOSTID":"1141f424","HOST":"172.16.167.187","FULLDATE":"2023 Dec  4 09:44:11","FACILITY_NUM":1,"FACILITY":"user","DESTPORT":6666,"DESTIP":"172.16.167.174","DAY":"04","DATE":"Dec  4 09:44:11","C_YEAR_DAY":"338","C_YEAR":"2023","C_WEEK_DAY_NAME":"Monday","C_WEEK_DAY_ABBREV":"Mon","C_WEEK_DAY":"2","C_WEEKDAY":"Mon","C_WEEK":"49","C_USEC":"801409","C_UNIXTIME":"1701679451","C_TZOFFSET":"+01:00","C_TZ":"+01:00","C_STAMP":"Dec  4 09:44:11","C_SEC":"11","C_MSEC":"801","C_MONTH_WEEK":"1","C_MONTH_NAME":"December","C_MONTH_ABBREV":"Dec","C_MONTH":"12","C_MIN":"44","C_ISOWEEK":"49","C_ISODATE":"2023-12-04T09:44:11+01:00","C_HOUR12":"09","C_HOUR":"09","C_FULLDATE":"2023 Dec  4 09:44:11","C_DAY":"04","C_DATE":"Dec  4 09:44:11","C_AMPM":"AM","BSDTAG":"5B","AMPM":"AM"}

So, HOST, HOST_FROM, and SOURCEIP are all set to the IP address where the log is coming from, when using the syslog() source, but set to "127.0.0.1" and "tumbleweed" when using syslog-ng-otlp() source.

[czanik]

@bazsi I did a few more experiments while testing syslog-ng-otlp() on RHEL9 (to do fucntional testing of your RHEL9 patch). If I use keep-hostname(yes) then:

Dec  6 17:35:43 fedora root: this is a test

If keep-hostname(no) then:

Dec  6 17:37:20 localhost root: this is a test

Where localhost is the hostname of the RHEL 9 machine.

Name-value pairs are even more interesting. In the first case: "HOST":"fedora" but, "LOGHOST":"localhost" and "HOST_FROM":"localhost". For keep-hostname(no), all three name-value pairs are set to "localhost"

(on the positive side: OpenTelemetry support on RHEL 9 works with your patch, and with the same bug as on other platforms :-) )