Closed Phrozyn closed 3 years ago
This is indeed very strange. How do you submit the message to syslog-ng? Can you pls show a syslog-ng debug output as the input is received?
Thanks
On Oct 18, 2017 23:08, "A Smith" notifications@github.com wrote:
syslog-ng
Getting inconsistent formatting using various versions of syslog-ng with format-json Version of syslog-ng
syslog-ng 3 (3.12.1) Installer-Version: 3.12.1 Revision: Compile-Date: Sep 22 2017 07:08:43 Module-Directory: //usr/lib64/syslog-ng Module-Path: //usr/lib64/syslog-ng Available-Modules: add-contextual-data,afamqp,affile,afprog,afsocket,afstomp,afuser,basicfuncs,cef,confgen,cryptofuncs,csvparser,date,dbparser,disk-buffer,graphite,json-plugin,kvformat,linux-kmsg-format,pseudofile,sdjournal,syslogformat,system-source,map-value-pairs,snmptrapd-parser,stardate,tags-parser,tfgetent,xml Enable-Debug: off Enable-GProf: off Enable-Memtrace: off Enable-IPv6: on Enable-Spoof-Source: on Enable-TCP-Wrapper: on Enable-Linux-Caps: on Enable-Systemd: on```
Platform
CentOS 7.4
Debug bundle
Create a debug bundle on your system with the syslog-ng-debun script which is included in the syslog-ng package.
Overwiew of the CLI options of syslog-ng-debun: -r: run actual information gathering -d: run syslog-ng in debug mode -p: perform packet capture -s: do strace -t: timeout period for running debug/pcap/strace -w: wait period before starting debug mode -l: light information gathering (respects privacy) -R: alternate installation directory for syslog-ng
$ syslog-ng-debun -r
Syslog-NG DEBUg buNdle generator Start environment detection Linux-type FHS detected
Operating System Name: Linux
Redhat specific checks Check package files integrity package syslog-ng-premium-edition is not installed package syslog-ng-premium-edition-client is not installed package syslog-ng-premium-edition-compact is not installed No syslog-ng RPM packages have been found! list syslog-related packages
Start general info collection System's full uname: Linux syslog2json.security.allizom.org 3.10.0-514.10.2.el7.x86_64 #1 SMP Fri Mar 3 00:04:05 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux Getting network-interface information: Success Getting network routes: Success Getting DNS resolution-related information: Done List all processes Mount and disk free info collection
Start Syslog-specific info collection Copy configs from /etc/syslog-ng 18 blocks Gathering PKI information... done. cat: /var/lib/syslog-ng/syslog-ng.pid: No such file or directory SVpid: SNGpid: Chpids: Syslog-ng's exact version: syslog-ng 3 (3.12.1) /usr/sbin/syslog-ng-ctl stats /usr/sbin/syslog-ng-ctl query get * /usr/sbin/syslog-ng-ctl show-license-info 32 blocks Detecting init system: systemd detected...
Generating hashes... done. Debug Bundle generation: Done. tar: ./var/syslog-ng.ctl: socket ignored Terminating live message watcher: /sbin/syslog-ng-debun: line 266: 21268 Terminated tail -f ${tmpdir}/syslog-ng.debun.txt 1>&3 (wd: ~)
root@syslog2json:~# rpm -qa | grep syslog-ng syslog-ng-3.12.1-2.el7.centos.x86_64 ( installed from https://copr.fedorainfracloud.org/coprs/czanik/syslog-ng312/)
Issue
Getting inconsistent formatting using various versions of syslog-ng with format-json I have tried syslog-ng 3.8 and 3.12 Using 3.8 the first 11 characters of the original timestamp was cut off in the message section. Using 3.12 bits of the timestamp and the string "intion" are scattered about the message as well as the IP address being malformed and scattered through it too.
Steps to reproduce
start syslog-ng
I've tried with two different configurations @version:3.12 @include "scl.conf"
syslog-ng configuration file.
#
This should behave pretty much like the original syslog on RedHat. But
it could be configured a lot smarter.
#
See syslog-ng(8) and syslog-ng.conf(5) for more information.
#
Note: it also sources additional configuration files (*.conf)
located in /etc/syslog-ng/conf.d/
options { flush_lines (0); time_reopen (10); log_fifo_size (1000); chain_hostnames (off); use_dns (no); use_fqdn (no); create_dirs (no); keep_hostname (yes); keep_timestamp(yes); };
source s_sys { system(); internal();
udp(ip(0.0.0.0) port(514));
};
source syslog { tcp(ip(127.0.0.1) port(514)); };
destination d_cons { file("/dev/console"); }; destination d_mesg { file("/var/log/messages"); }; destination d_auth { file("/var/log/secure"); }; destination d_mail { file("/var/log/maillog" flush_lines(10)); }; destination d_spol { file("/var/log/spooler"); }; destination d_boot { file("/var/log/boot.log"); }; destination d_cron { file("/var/log/cron"); }; destination d_kern { file("/var/log/kern"); }; destination d_mlal { usertty("*"); };
filter f_kernel { facility(kern); }; filter f_default { level(info..emerg) and not (facility(mail) or facility(authpriv) or facility(cron)); }; filter f_auth { facility(authpriv); }; filter f_mail { facility(mail); }; filter f_emergency { level(emerg); }; filter f_news { facility(uucp) or (facility(news) and level(crit..emerg)); }; filter f_boot { facility(local7); }; filter f_cron { facility(cron); };
log { source(s_sys); filter(f_kernel); destination(d_cons); };
log { source(s_sys); filter(f_kernel); destination(d_kern); }; log { source(s_sys); filter(f_default); destination(d_mesg); }; log { source(s_sys); filter(f_auth); destination(d_auth); }; log { source(s_sys); filter(f_mail); destination(d_mail); }; log { source(s_sys); filter(f_emergency); destination(d_mlal); }; log { source(s_sys); filter(f_news); destination(d_spol); }; log { source(s_sys); filter(f_boot); destination(d_boot); }; log { source(s_sys); filter(f_cron); destination(d_cron); };
log { source(syslog);
destination(d_amqp);
};
log { source(syslog); destination(d_json); };
destination d_json { file("/var/log/messages.json" template("$(format-json --scope selected_macros --scope nv_pairs)")); };
Tried with amqp driver using the first "body" line and then second "body" config line (after commenting out the first one)
destination d_amqp {
amqp(
vhost("/")
host("mozdefdemo.security.allizom.org")
port(5672)
exchange("eventtask")
exchange-type("direct")
routing-key("eventtask")
body("$(format-json date=datetime($ISODATE) pid=int64($PID) program=$PROGRAM message=$MESSAGE facility=$FACILITY host=$FULLHOST priorityNum=int64($LEVEL_NUM) priority=$LEVEL)")
body("$(format-json --scope selected_macros --scope nv_pairs)")
persistent(no)
username("guest")
password("guest")
);
};
Source additional configuration files (.conf extension only)
@include "/etc/syslog-ng/conf.d/*.conf" N/A (nothing in additional config files)
vim:ft=syslog-ng:ai:si:ts=4:sw=4:et:
Input and output logs (if possible)
original event: Oct 6 22:13:37 policy2.testorama.example.com info sshd 2664 Connection from 192.25.10.54 port 41343
output after json transformed: {"TAGS":".source.syslog","SOURCEIP":"127.0.0.1","SOURCE":"syslog","PROGRAM":"22","PRIORITY":"info","MESSAGE":"-18T20:45:21 6 22: -18T2xample.com in -18T2xample.com intion from 192com intion from 192co","LEGACY_MSGHDR":"22: ","HOST_FROM":"127.0.0.1","HOST":"6","FACILITY":"auth","DATE":"Oct 18 20:45:21"}
— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/balabit/syslog-ng/issues/1719, or mute the thread https://github.com/notifications/unsubscribe-auth/AArldodznJEUbfzzzybg7_r1JpZGo8GFks5stmjogaJpZM4P-XEg .
I am using loggen to read a log file to test this functionality. loggen -R test.log 127.0.0.1 514 --stream --quiet
Oh this is weird, so it's seeing the incoming log event in that format, so maybe my issue is actually loggen?
[2017-10-18T22:39:15.138392] Incoming log entry; line='<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com intion from 192com intion from 192co<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inVER from 20.acom inVER from 20.acom inVER f<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com in on 192.16.58com in on 192.16.585:fe via 192..16.585:<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inVER from 20.acom inVER from 20.acom inVER f<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com in on 192.16.58com in on 192.16.585:fe via 192..16.585:<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com er -18T2xample.com eretDomainJoinIcom eretDomainJoinImation(): ERRnJoinImation(): ERRnJoinI<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inproc/self/oomcom inproc<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inroc/self/oom_com'
Here's the output when I echo the data into a log file and change my config source to read from that file: [2017-10-18T22:44:48.214916] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1","SOURCE":"syslog","SEQNUM":"2","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPDISCOVER from 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":"alibaba.majordomo.example.com","FILE_NAME":"/var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}' [2017-10-18T22:44:48.214943] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1","SOURCE":"syslog","SEQNUM":"3","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPOFFER on 192.16.58.4 to 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":"alibaba.majordomo.example.com","FILE_NAME":"/var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}' [2017-10-18T22:44:48.214963] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1","SOURCE":"syslog","SEQNUM":"4","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPDISCOVER from 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":"alibaba.majordomo.example.com","FILE_NAME":"/var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}' [2017-10-18T22:44:48.214983] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1","SOURCE":"syslog","SEQNUM":"5","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPOFFER on 192.16.58.4 to 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":"alibaba.majordomo.example.com","FILE_NAME":"/var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}'
The log file is probably in rfc5424 format, but with that command line loggen assumes it is rfc3164 and tries to patch timestamps etc at specific offsets. loggen is not necessarily the most user friendly tool out there :)
Try adding --syslog-proto to your command line.
-- Bazsi
On Thu, Oct 19, 2017 at 12:46 AM, A Smith notifications@github.com wrote:
I am using loggen to read a log file to test this functionality. loggen -R test.log 127.0.0.1 514 --stream --quiet
Oh this is weird, so it's seeing the incoming log event in that format, so maybe my issue is actually loggen?
[2017-10-18T22:39:15.138392] Incoming log entry; line='<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com intion from 192com intion from 192co<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inVER from 20.acom inVER from 20.acom inVER f<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com in on 192.16.58com in on 192.16.585:fe via 192..16.585:<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inVER from 20.acom inVER from 20.acom inVER f<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com in on 192.16.58com in on 192.16.585:fe via 192..16.585:<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com er -18T2xample.com eretDomainJoinIcom eretDomainJoinImation(): ERRnJoinImation(): ERRnJoinI<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inproc/self/oomcom inproc<38>2017-10-18T22:39:15 6 22: -18T22:39:15 6 22: -18T2xample.com in -18T2xample.com inroc/self/oom_com'
Here's the output when I echo the data into a log file and change my config source to read from that file: [2017-10-18T22:44:48.214916 <(48)%20214%20916>] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1" ,"SOURCE":"syslog","SEQNUM":"2","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPDISCOVER from 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":"alibaba.majordomo.example.com ","FILE_NAME":"/var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}' [2017-10-18T22:44:48.214943 <(48)%20214%20943>] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1" ,"SOURCE":"syslog","SEQNUM":"3","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPOFFER on 192.16.58.4 to 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":" alibaba.majordomo.example.com","FILE_NAME":"/ var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}' [2017-10-18T22:44:48.214963 <(48)%20214%20963>] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1" ,"SOURCE":"syslog","SEQNUM":"4","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPDISCOVER from 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":"alibaba.majordomo.example.com ","FILE_NAME":"/var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}' [2017-10-18T22:44:48.214983 <(48)%20214%20983>] Outgoing message; message='{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1" ,"SOURCE":"syslog","SEQNUM":"5","PROGRAM":"info","PRIORITY":"notice","MESSAGE":"dhcpd DHCPOFFER on 192.16.58.4 to 20.a1:54:21:25:fe via 192.16.60.6","LEGACY_MSGHDR":"info ","HOST_FROM":"syslog2json","HOST":" alibaba.majordomo.example.com","FILE_NAME":"/ var/log/test.log","FACILITY":"user","DATE":"Oct 6 22:13:37"}'
— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/balabit/syslog-ng/issues/1719#issuecomment-337749573, or mute the thread https://github.com/notifications/unsubscribe-auth/AArldtPpOCvco2YhM2BHmURFBlB9gOr-ks5stn-9gaJpZM4P-XEg .
I tried with that switch and got the following that ended up being over 1570 bytes...
{"TAGS":".source.syslog","SOURCEIP":"127.0.0.1","SOURCE":"syslog","SEQNUM":"1","PROGRAM":"000000130","PRIORITY":"notice","MESSAGE":"<38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10000000139 <38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59000000149 <38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 -000000139 <38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59000000149 <38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 -000000166 <38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017000000119 <38>1 2017-10-19T14:59:22 6 22 - - - 38>1 2017-10- truncated
Loggen works fine when I don't specify a log file to read, so not sure if this is expected behavior. I'll move to testing with the log file generation I did to get the successful output.
This is an old question, I'm closing it as we could not reproduce this formatting problem (loggen v3.12.1).
Looking back, this seems to be an issue with line feed handling (probably <CR>
was used), and a parsing issue on top of it.
Please reopen if you still experience such a behavior with the current version of loggen's file reader.
syslog-ng
Getting inconsistent formatting using various versions of syslog-ng with format-json
Version of syslog-ng
$ syslog-ng-debun -r