Some logs written, some are not
I’m hoping someone can help here, because I’m at my wits end. System info: syslog-ng OSE 3.27 OS: CentOS 7.8 (though, I get similar results on Ubuntu 18.04) I have some kubernetes pods sending logs to a remote syslog-ng server. I have an issue where some logs are not being created. These are specifically received via TCP. I can see the message inbound by doing a packet capture, but nothing is written. One of the messages that stands out is: "Error processing message <-1>" Here is my scenario: Start a deployment with 3 pods: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: nothing Pod3: nothing Delete and deploy again: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: log created on syslog-ng server: /data/2020/06/09/pod2/logs/app.log Pod3: nothing Delete and deploy again: Pod1: nothing Pod2: nothing Pod3: nothing There seems to be no pattern. The pods that log, do so successfully. All pods should be logging the same exact date except for timestamps and the pod name. A packet capture shows healthy traffic inbound, with no errors, even from the pods that are not logging. The only indication of an issue is the trace log. Here’s an example from one of the non-writing pods, with a message id “0x7f2af8003800” : Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='testlogger', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='LEGACY_MSGHDR', value='testlogger: ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='testlogger-service-54956569bb-kqsjs', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.143.181', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: severity() evaluation started; pri='6', valid_pri='000000ff', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> rewrite rule evaluation begin; rule='r_newlines', location='/etc/syslog-ng/syslog-ng.conf:186:5', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Message was cloned; original_msg='0x7f2af8003800', new_msg='0x7f2af8004830' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Performing subst() rewrite failed, pattern did not match; rule='r_newlines', value='MESSAGE', input='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', type='(null)', pattern='u2028', replacement='\x0a', location='/etc/syslog-ng/syslog-ng.conf:186:5’ Further down in the log, I see: Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Any help would be greatly appreciated. Thank you, Jason
Hi, A similar problem was just posted on Reddit (https://www.reddit.com/r/sysadmin/comments/gzl1f4/syslogng_dropping_some_tcp...). So I did a quick test. I sent the log with <-1> and it was dropped with an error message by syslog-ng. Then I simply removed the minus sign: <1>..., and it worked perfectly. Make sure that the sending site does not try to use a negative number as priority (the number between <>). Bye, Peter Czanik (CzP) <peter.czanik@oneidentity.com> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/ https://twitter.com/PCzanik ________________________________ From: syslog-ng <syslog-ng-bounces@lists.balabit.hu> on behalf of Jason Brown <jbrown@boxconsulting.net> Sent: Tuesday, June 9, 2020 15:40 To: syslog-ng@lists.balabit.hu <syslog-ng@lists.balabit.hu> Subject: [syslog-ng] Some logs written, some are not CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe. I’m hoping someone can help here, because I’m at my wits end. System info: syslog-ng OSE 3.27 OS: CentOS 7.8 (though, I get similar results on Ubuntu 18.04) I have some kubernetes pods sending logs to a remote syslog-ng server. I have an issue where some logs are not being created. These are specifically received via TCP. I can see the message inbound by doing a packet capture, but nothing is written. One of the messages that stands out is: "Error processing message <-1>" Here is my scenario: Start a deployment with 3 pods: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: nothing Pod3: nothing Delete and deploy again: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: log created on syslog-ng server: /data/2020/06/09/pod2/logs/app.log Pod3: nothing Delete and deploy again: Pod1: nothing Pod2: nothing Pod3: nothing There seems to be no pattern. The pods that log, do so successfully. All pods should be logging the same exact date except for timestamps and the pod name. A packet capture shows healthy traffic inbound, with no errors, even from the pods that are not logging. The only indication of an issue is the trace log. Here’s an example from one of the non-writing pods, with a message id “0x7f2af8003800” : Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='testlogger', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='LEGACY_MSGHDR', value='testlogger: ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='testlogger-service-54956569bb-kqsjs', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.143.181', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: severity() evaluation started; pri='6', valid_pri='000000ff', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> rewrite rule evaluation begin; rule='r_newlines', location='/etc/syslog-ng/syslog-ng.conf:186:5', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Message was cloned; original_msg='0x7f2af8003800', new_msg='0x7f2af8004830' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Performing subst() rewrite failed, pattern did not match; rule='r_newlines', value='MESSAGE', input='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', type='(null)', pattern='u2028', replacement='\x0a', location='/etc/syslog-ng/syslog-ng.conf:186:5’ Further down in the log, I see: Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Any help would be greatly appreciated. Thank you, Jason ______________________________________________________________________________ Member info: https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=7yJs4GRtKjFR0SNFxhXEa6jlCF8zEqUj8%2B6IU2U5uJE%3D&reserved=0 Documentation: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=fusHd74hogFKcYraC2j1sx90mmj7UAD%2FAy3y6cZ%2BR%2Fs%3D&reserved=0 FAQ: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=9HT%2BQYiSTckuBAU2Q%2F6whDB%2BwYNnfq3xtCG0gSMVU%2B0%3D&reserved=0
Thanks for the response, Peter. That reddit post was me :) I should have specified that the logger is a Java application using logback. Not sure how relevant this is. We are not sending a “-1’. Logback has the priority field set to “info”. This is the first line sent: 2020-06-09 12:09:36,134 (main) INFO [c.b.s.r.sTestLoggerServer] [trkId=] Server starting in Staging environment If priority is the issue, why would some pods create logs, while others do not? Thanks, Jason
On 9. Jun 2020, at 15:47, Peter Czanik (pczanik) <Peter.Czanik@oneidentity.com> wrote:
Hi,
A similar problem was just posted on Reddit (https://www.reddit.com/r/sysadmin/comments/gzl1f4/syslogng_dropping_some_tcp... <https://www.reddit.com/r/sysadmin/comments/gzl1f4/syslogng_dropping_some_tcpsourced_logs/>). So I did a quick test. I sent the log with <-1> and it was dropped with an error message by syslog-ng. Then I simply removed the minus sign: <1>..., and it worked perfectly. Make sure that the sending site does not try to use a negative number as priority (the number between <>).
Bye,
Peter Czanik (CzP) <peter.czanik@oneidentity.com <mailto:peter.czanik@oneidentity.com>> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/ <https://syslog-ng.com/community/> https://twitter.com/PCzanik <https://twitter.com/PCzanik> From: syslog-ng <syslog-ng-bounces@lists.balabit.hu <mailto:syslog-ng-bounces@lists.balabit.hu>> on behalf of Jason Brown <jbrown@boxconsulting.net <mailto:jbrown@boxconsulting.net>> Sent: Tuesday, June 9, 2020 15:40 To: syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu>> Subject: [syslog-ng] Some logs written, some are not
CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe.
I’m hoping someone can help here, because I’m at my wits end.
System info: syslog-ng OSE 3.27 OS: CentOS 7.8 (though, I get similar results on Ubuntu 18.04)
I have some kubernetes pods sending logs to a remote syslog-ng server. I have an issue where some logs are not being created. These are specifically received via TCP. I can see the message inbound by doing a packet capture, but nothing is written. One of the messages that stands out is: "Error processing message <-1>"
Here is my scenario:
Start a deployment with 3 pods: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: nothing Pod3: nothing
Delete and deploy again: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: log created on syslog-ng server: /data/2020/06/09/pod2/logs/app.log Pod3: nothing
Delete and deploy again: Pod1: nothing Pod2: nothing Pod3: nothing
There seems to be no pattern. The pods that log, do so successfully. All pods should be logging the same exact date except for timestamps and the pod name. A packet capture shows healthy traffic inbound, with no errors, even from the pods that are not logging. The only indication of an issue is the trace log. Here’s an example from one of the non-writing pods, with a message id “0x7f2af8003800” :
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='testlogger', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='LEGACY_MSGHDR', value='testlogger: ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='testlogger-service-54956569bb-kqsjs', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.143.181', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: severity() evaluation started; pri='6', valid_pri='000000ff', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> rewrite rule evaluation begin; rule='r_newlines', location='/etc/syslog-ng/syslog-ng.conf:186:5', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Message was cloned; original_msg='0x7f2af8003800', new_msg='0x7f2af8004830' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Performing subst() rewrite failed, pattern did not match; rule='r_newlines', value='MESSAGE', input='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', type='(null)', pattern='u2028', replacement='\x0a', location='/etc/syslog-ng/syslog-ng.conf:186:5’
Further down in the log, I see: Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800'
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800'
Any help would be greatly appreciated.
Thank you, Jason
______________________________________________________________________________ Member info: https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=7yJs4GRtKjFR0SNFxhXEa6jlCF8zEqUj8%2B6IU2U5uJE%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=7yJs4GRtKjFR0SNFxhXEa6jlCF8zEqUj8%2B6IU2U5uJE%3D&reserved=0> Documentation: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=fusHd74hogFKcYraC2j1sx90mmj7UAD%2FAy3y6cZ%2BR%2Fs%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=fusHd74hogFKcYraC2j1sx90mmj7UAD%2FAy3y6cZ%2BR%2Fs%3D&reserved=0> FAQ: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=9HT%2BQYiSTckuBAU2Q%2F6whDB%2BwYNnfq3xtCG0gSMVU%2B0%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=9HT%2BQYiSTckuBAU2Q%2F6whDB%2BwYNnfq3xtCG0gSMVU%2B0%3D&reserved=0>
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng <https://lists.balabit.hu/mailman/listinfo/syslog-ng> Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng <http://www.balabit.com/support/documentation/?product=syslog-ng> FAQ: http://www.balabit.com/wiki/syslog-ng-faq <http://www.balabit.com/wiki/syslog-ng-faq>
Hi, I have never used Kubernetes yet, so I don't know that part of the answer. Just that the error message included: Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800' is resolved if you use a positive number of priority. Just another suspicion, as I don't code in Java or use logback: priority is composed from two different numbers, facility (like "mail") and level (like "info"). <-1> might be sent as an error value because you specify only one of those. Bye, Peter Czanik (CzP) <peter.czanik@oneidentity.com> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/ https://twitter.com/PCzanik ________________________________ From: syslog-ng <syslog-ng-bounces@lists.balabit.hu> on behalf of Jason Brown <jbrown@boxconsulting.net> Sent: Tuesday, June 9, 2020 16:00 To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] Some logs written, some are not CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe. Thanks for the response, Peter. That reddit post was me :) I should have specified that the logger is a Java application using logback. Not sure how relevant this is. We are not sending a “-1’. Logback has the priority field set to “info”. This is the first line sent: 2020-06-09 12:09:36,134 (main) INFO [c.b.s.r.sTestLoggerServer] [trkId=] Server starting in Staging environment If priority is the issue, why would some pods create logs, while others do not? Thanks, Jason On 9. Jun 2020, at 15:47, Peter Czanik (pczanik) <Peter.Czanik@oneidentity.com<mailto:Peter.Czanik@oneidentity.com>> wrote: Hi, A similar problem was just posted on Reddit (https://www.reddit.com/r/sysadmin/comments/gzl1f4/syslogng_dropping_some_tcpsourced_logs/<https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.reddit.com%2Fr%2Fsysadmin%2Fcomments%2Fgzl1f4%2Fsyslogng_dropping_some_tcpsourced_logs%2F&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556671615&sdata=CcFkzQnHBFUg5MF44RVd%2BNsWEdmZyABQOl%2BmL3DB81s%3D&reserved=0>). So I did a quick test. I sent the log with <-1> and it was dropped with an error message by syslog-ng. Then I simply removed the minus sign: <1>..., and it worked perfectly. Make sure that the sending site does not try to use a negative number as priority (the number between <>). Bye, Peter Czanik (CzP) <peter.czanik@oneidentity.com<mailto:peter.czanik@oneidentity.com>> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/<https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Fsyslog-ng.com%2Fcommunity%2F&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556671615&sdata=m9RRlT%2FqHnyFjgdMLYvfvR7z%2By2kgPsV5Ahs%2FN1YhIM%3D&reserved=0> https://twitter.com/PCzanik<https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Ftwitter.com%2FPCzanik&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556681572&sdata=8rqnRnxIyu%2Be7TYnwIrZtDBOryT7PNK5egMXsv%2Bii6M%3D&reserved=0> ________________________________ From: syslog-ng <syslog-ng-bounces@lists.balabit.hu<mailto:syslog-ng-bounces@lists.balabit.hu>> on behalf of Jason Brown <jbrown@boxconsulting.net<mailto:jbrown@boxconsulting.net>> Sent: Tuesday, June 9, 2020 15:40 To: syslog-ng@lists.balabit.hu<mailto:syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu<mailto:syslog-ng@lists.balabit.hu>> Subject: [syslog-ng] Some logs written, some are not CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe. I’m hoping someone can help here, because I’m at my wits end. System info: syslog-ng OSE 3.27 OS: CentOS 7.8 (though, I get similar results on Ubuntu 18.04) I have some kubernetes pods sending logs to a remote syslog-ng server. I have an issue where some logs are not being created. These are specifically received via TCP. I can see the message inbound by doing a packet capture, but nothing is written. One of the messages that stands out is: "Error processing message <-1>" Here is my scenario: Start a deployment with 3 pods: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: nothing Pod3: nothing Delete and deploy again: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: log created on syslog-ng server: /data/2020/06/09/pod2/logs/app.log Pod3: nothing Delete and deploy again: Pod1: nothing Pod2: nothing Pod3: nothing There seems to be no pattern. The pods that log, do so successfully. All pods should be logging the same exact date except for timestamps and the pod name. A packet capture shows healthy traffic inbound, with no errors, even from the pods that are not logging. The only indication of an issue is the trace log. Here’s an example from one of the non-writing pods, with a message id “0x7f2af8003800” : Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='testlogger', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='LEGACY_MSGHDR', value='testlogger: ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='testlogger-service-54956569bb-kqsjs', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.143.181', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: severity() evaluation started; pri='6', valid_pri='000000ff', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> rewrite rule evaluation begin; rule='r_newlines', location='/etc/syslog-ng/syslog-ng.conf:186:5', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Message was cloned; original_msg='0x7f2af8003800', new_msg='0x7f2af8004830' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Performing subst() rewrite failed, pattern did not match; rule='r_newlines', value='MESSAGE', input='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', type='(null)', pattern='u2028', replacement='\x0a', location='/etc/syslog-ng/syslog-ng.conf:186:5’ Further down in the log, I see: Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Any help would be greatly appreciated. Thank you, Jason ______________________________________________________________________________ Member info: https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=7yJs4GRtKjFR0SNFxhXEa6jlCF8zEqUj8%2B6IU2U5uJE%3D&reserved=0<https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556681572&sdata=2j6perQkx4E3lPEk6kqrrStrbukd2NHGbtT2k%2B%2FKuM4%3D&reserved=0> Documentation: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=fusHd74hogFKcYraC2j1sx90mmj7UAD%2FAy3y6cZ%2BR%2Fs%3D&reserved=0<https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556691527&sdata=vqJXbY04zvy%2BLY4fg9neALm68HgY1YfRq8xkvLm8Rok%3D&reserved=0> FAQ: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=9HT%2BQYiSTckuBAU2Q%2F6whDB%2BwYNnfq3xtCG0gSMVU%2B0%3D&reserved=0<https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556691527&sdata=%2BTy4a6pl5jEKRQY5PXz%2BFTKQX3Hv8uJgA%2F0Eh4ZrFVs%3D&reserved=0> ______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng<https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556701484&sdata=Tl68X3wApyRZGPfnxgARSulj6x6j0QACN%2Fzvt8rEgic%3D&reserved=0> Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng<https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556701484&sdata=kdsCQ0%2F0R4F4k%2B32bJghFzAyJm8B1VUeP8sFBD4KKQI%3D&reserved=0> FAQ: http://www.balabit.com/wiki/syslog-ng-faq<https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556711442&sdata=EsRLqlrq1bHDYnmgoQTgPX4XLf8WCxQc9wkHpjwdPkY%3D&reserved=0>
Hi, The fact that it’s kubernetes is neither here nor there (I -think-). It’s effectively the same as n applications starting on n servers. What’s really weird is that logs are created some of the time. I’ll go dig through the logback config to see if I can find something. I’ll report any findings. Thanks again for the help, Jason
On 9. Jun 2020, at 16:14, Peter Czanik (pczanik) <Peter.Czanik@oneidentity.com> wrote:
Hi,
I have never used Kubernetes yet, so I don't know that part of the answer. Just that the error message included:
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800'
is resolved if you use a positive number of priority.
Just another suspicion, as I don't code in Java or use logback: priority is composed from two different numbers, facility (like "mail") and level (like "info"). <-1> might be sent as an error value because you specify only one of those.
Bye,
Peter Czanik (CzP) <peter.czanik@oneidentity.com <mailto:peter.czanik@oneidentity.com>> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/ <https://syslog-ng.com/community/> https://twitter.com/PCzanik <https://twitter.com/PCzanik> From: syslog-ng <syslog-ng-bounces@lists.balabit.hu <mailto:syslog-ng-bounces@lists.balabit.hu>> on behalf of Jason Brown <jbrown@boxconsulting.net <mailto:jbrown@boxconsulting.net>> Sent: Tuesday, June 9, 2020 16:00 To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu>> Subject: Re: [syslog-ng] Some logs written, some are not
CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe.
Thanks for the response, Peter. That reddit post was me :)
I should have specified that the logger is a Java application using logback. Not sure how relevant this is. We are not sending a “-1’. Logback has the priority field set to “info”. This is the first line sent:
2020-06-09 12:09:36,134 (main) INFO [c.b.s.r.sTestLoggerServer] [trkId=] Server starting in Staging environment
If priority is the issue, why would some pods create logs, while others do not?
Thanks, Jason
On 9. Jun 2020, at 15:47, Peter Czanik (pczanik) <Peter.Czanik@oneidentity.com <mailto:Peter.Czanik@oneidentity.com>> wrote:
Hi,
A similar problem was just posted on Reddit (https://www.reddit.com/r/sysadmin/comments/gzl1f4/syslogng_dropping_some_tcp... <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.reddit.com%2Fr%2Fsysadmin%2Fcomments%2Fgzl1f4%2Fsyslogng_dropping_some_tcpsourced_logs%2F&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556671615&sdata=CcFkzQnHBFUg5MF44RVd%2BNsWEdmZyABQOl%2BmL3DB81s%3D&reserved=0>). So I did a quick test. I sent the log with <-1> and it was dropped with an error message by syslog-ng. Then I simply removed the minus sign: <1>..., and it worked perfectly. Make sure that the sending site does not try to use a negative number as priority (the number between <>).
Bye,
Peter Czanik (CzP) <peter.czanik@oneidentity.com <mailto:peter.czanik@oneidentity.com>> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/ <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Fsyslog-ng.com%2Fcommunity%2F&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556671615&sdata=m9RRlT%2FqHnyFjgdMLYvfvR7z%2By2kgPsV5Ahs%2FN1YhIM%3D&reserved=0> https://twitter.com/PCzanik <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Ftwitter.com%2FPCzanik&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556681572&sdata=8rqnRnxIyu%2Be7TYnwIrZtDBOryT7PNK5egMXsv%2Bii6M%3D&reserved=0> From: syslog-ng <syslog-ng-bounces@lists.balabit.hu <mailto:syslog-ng-bounces@lists.balabit.hu>> on behalf of Jason Brown <jbrown@boxconsulting.net <mailto:jbrown@boxconsulting.net>> Sent: Tuesday, June 9, 2020 15:40 To: syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu>> Subject: [syslog-ng] Some logs written, some are not
CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe.
I’m hoping someone can help here, because I’m at my wits end.
System info: syslog-ng OSE 3.27 OS: CentOS 7.8 (though, I get similar results on Ubuntu 18.04)
I have some kubernetes pods sending logs to a remote syslog-ng server. I have an issue where some logs are not being created. These are specifically received via TCP. I can see the message inbound by doing a packet capture, but nothing is written. One of the messages that stands out is: "Error processing message <-1>"
Here is my scenario:
Start a deployment with 3 pods: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: nothing Pod3: nothing
Delete and deploy again: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: log created on syslog-ng server: /data/2020/06/09/pod2/logs/app.log Pod3: nothing
Delete and deploy again: Pod1: nothing Pod2: nothing Pod3: nothing
There seems to be no pattern. The pods that log, do so successfully. All pods should be logging the same exact date except for timestamps and the pod name. A packet capture shows healthy traffic inbound, with no errors, even from the pods that are not logging. The only indication of an issue is the trace log. Here’s an example from one of the non-writing pods, with a message id “0x7f2af8003800” :
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='testlogger', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='LEGACY_MSGHDR', value='testlogger: ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='testlogger-service-54956569bb-kqsjs', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.143.181', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: severity() evaluation started; pri='6', valid_pri='000000ff', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> rewrite rule evaluation begin; rule='r_newlines', location='/etc/syslog-ng/syslog-ng.conf:186:5', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Message was cloned; original_msg='0x7f2af8003800', new_msg='0x7f2af8004830' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Performing subst() rewrite failed, pattern did not match; rule='r_newlines', value='MESSAGE', input='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', type='(null)', pattern='u2028', replacement='\x0a', location='/etc/syslog-ng/syslog-ng.conf:186:5’
Further down in the log, I see: Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800'
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800'
Any help would be greatly appreciated.
Thank you, Jason
______________________________________________________________________________ Member info: https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=7yJs4GRtKjFR0SNFxhXEa6jlCF8zEqUj8%2B6IU2U5uJE%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556681572&sdata=2j6perQkx4E3lPEk6kqrrStrbukd2NHGbtT2k%2B%2FKuM4%3D&reserved=0> Documentation: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=fusHd74hogFKcYraC2j1sx90mmj7UAD%2FAy3y6cZ%2BR%2Fs%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556691527&sdata=vqJXbY04zvy%2BLY4fg9neALm68HgY1YfRq8xkvLm8Rok%3D&reserved=0> FAQ: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=9HT%2BQYiSTckuBAU2Q%2F6whDB%2BwYNnfq3xtCG0gSMVU%2B0%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556691527&sdata=%2BTy4a6pl5jEKRQY5PXz%2BFTKQX3Hv8uJgA%2F0Eh4ZrFVs%3D&reserved=0>
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556701484&sdata=Tl68X3wApyRZGPfnxgARSulj6x6j0QACN%2Fzvt8rEgic%3D&reserved=0> Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556701484&sdata=kdsCQ0%2F0R4F4k%2B32bJghFzAyJm8B1VUeP8sFBD4KKQI%3D&reserved=0> FAQ: http://www.balabit.com/wiki/syslog-ng-faq <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556711442&sdata=EsRLqlrq1bHDYnmgoQTgPX4XLf8WCxQc9wkHpjwdPkY%3D&reserved=0>
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng <https://lists.balabit.hu/mailman/listinfo/syslog-ng> Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng <http://www.balabit.com/support/documentation/?product=syslog-ng> FAQ: http://www.balabit.com/wiki/syslog-ng-faq <http://www.balabit.com/wiki/syslog-ng-faq>
It looks like the cause of the “Error processing log message: <-1>” was indeed the logback configuration. Changing the priority to something valid cleans up that error. Unfortunately, it looks like that wasn’t the source of the problem. Digging in a little deeper, I’m seeing this message: Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: Syslog connection accepted; fd='19', client='AF_INET(10.13.97.36:49346)', local='AF_INET(0.0.0.0:514)' Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: internal() messages are looping back, preventing loop by suppressing all internal messages until the current message is processed; trigger-msg='Syslog connection accepted; fd=\'19\', client=\'AF_INET(10.13.97.36:49346)\', local=\'AF_INET(0.0.0.0:514)\'', first-suppressed-msg='>>>>>> filter rule evaluation begin; rule=\'f_auth\', location=\'/etc/syslog-ng/syslog-ng.conf:136:32\', msg=\'0x11c1bc0\’’ So I’m assuming it’s likely a flow control issue. Jason
On 9. Jun 2020, at 16:20, Jason Brown <jbrown@boxconsulting.net> wrote:
Hi, The fact that it’s kubernetes is neither here nor there (I -think-). It’s effectively the same as n applications starting on n servers. What’s really weird is that logs are created some of the time.
I’ll go dig through the logback config to see if I can find something. I’ll report any findings.
Thanks again for the help,
Jason
On 9. Jun 2020, at 16:14, Peter Czanik (pczanik) <Peter.Czanik@oneidentity.com <mailto:Peter.Czanik@oneidentity.com>> wrote:
Hi,
I have never used Kubernetes yet, so I don't know that part of the answer. Just that the error message included:
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800'
is resolved if you use a positive number of priority.
Just another suspicion, as I don't code in Java or use logback: priority is composed from two different numbers, facility (like "mail") and level (like "info"). <-1> might be sent as an error value because you specify only one of those.
Bye,
Peter Czanik (CzP) <peter.czanik@oneidentity.com <mailto:peter.czanik@oneidentity.com>> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/ <https://syslog-ng.com/community/> https://twitter.com/PCzanik <https://twitter.com/PCzanik> From: syslog-ng <syslog-ng-bounces@lists.balabit.hu <mailto:syslog-ng-bounces@lists.balabit.hu>> on behalf of Jason Brown <jbrown@boxconsulting.net <mailto:jbrown@boxconsulting.net>> Sent: Tuesday, June 9, 2020 16:00 To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu>> Subject: Re: [syslog-ng] Some logs written, some are not
CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe.
Thanks for the response, Peter. That reddit post was me :)
I should have specified that the logger is a Java application using logback. Not sure how relevant this is. We are not sending a “-1’. Logback has the priority field set to “info”. This is the first line sent:
2020-06-09 12:09:36,134 (main) INFO [c.b.s.r.sTestLoggerServer] [trkId=] Server starting in Staging environment
If priority is the issue, why would some pods create logs, while others do not?
Thanks, Jason
On 9. Jun 2020, at 15:47, Peter Czanik (pczanik) <Peter.Czanik@oneidentity.com <mailto:Peter.Czanik@oneidentity.com>> wrote:
Hi,
A similar problem was just posted on Reddit (https://www.reddit.com/r/sysadmin/comments/gzl1f4/syslogng_dropping_some_tcp... <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwww.reddit.com%2Fr%2Fsysadmin%2Fcomments%2Fgzl1f4%2Fsyslogng_dropping_some_tcpsourced_logs%2F&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556671615&sdata=CcFkzQnHBFUg5MF44RVd%2BNsWEdmZyABQOl%2BmL3DB81s%3D&reserved=0>). So I did a quick test. I sent the log with <-1> and it was dropped with an error message by syslog-ng. Then I simply removed the minus sign: <1>..., and it worked perfectly. Make sure that the sending site does not try to use a negative number as priority (the number between <>).
Bye,
Peter Czanik (CzP) <peter.czanik@oneidentity.com <mailto:peter.czanik@oneidentity.com>> Balabit (a OneIdentity company) / syslog-ng upstream https://syslog-ng.com/community/ <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Fsyslog-ng.com%2Fcommunity%2F&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556671615&sdata=m9RRlT%2FqHnyFjgdMLYvfvR7z%2By2kgPsV5Ahs%2FN1YhIM%3D&reserved=0> https://twitter.com/PCzanik <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Ftwitter.com%2FPCzanik&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556681572&sdata=8rqnRnxIyu%2Be7TYnwIrZtDBOryT7PNK5egMXsv%2Bii6M%3D&reserved=0> From: syslog-ng <syslog-ng-bounces@lists.balabit.hu <mailto:syslog-ng-bounces@lists.balabit.hu>> on behalf of Jason Brown <jbrown@boxconsulting.net <mailto:jbrown@boxconsulting.net>> Sent: Tuesday, June 9, 2020 15:40 To: syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu> <syslog-ng@lists.balabit.hu <mailto:syslog-ng@lists.balabit.hu>> Subject: [syslog-ng] Some logs written, some are not
CAUTION: This email originated from outside of the organization. Do not follow guidance, click links, or open attachments unless you recognize the sender and know the content is safe.
I’m hoping someone can help here, because I’m at my wits end.
System info: syslog-ng OSE 3.27 OS: CentOS 7.8 (though, I get similar results on Ubuntu 18.04)
I have some kubernetes pods sending logs to a remote syslog-ng server. I have an issue where some logs are not being created. These are specifically received via TCP. I can see the message inbound by doing a packet capture, but nothing is written. One of the messages that stands out is: "Error processing message <-1>"
Here is my scenario:
Start a deployment with 3 pods: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: nothing Pod3: nothing
Delete and deploy again: Pod1: log created on syslog-ng server: /data/2020/06/09/pod1/logs/app.log Pod2: log created on syslog-ng server: /data/2020/06/09/pod2/logs/app.log Pod3: nothing
Delete and deploy again: Pod1: nothing Pod2: nothing Pod3: nothing
There seems to be no pattern. The pods that log, do so successfully. All pods should be logging the same exact date except for timestamps and the pod name. A packet capture shows healthy traffic inbound, with no errors, even from the pods that are not logging. The only indication of an issue is the trace log. Here’s an example from one of the non-writing pods, with a message id “0x7f2af8003800” :
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='testlogger', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='LEGACY_MSGHDR', value='testlogger: ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='testlogger-service-54956569bb-kqsjs', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.143.181', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='20', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: severity() evaluation started; pri='6', valid_pri='000000ff', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> rewrite rule evaluation begin; rule='r_newlines', location='/etc/syslog-ng/syslog-ng.conf:186:5', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Message was cloned; original_msg='0x7f2af8003800', new_msg='0x7f2af8004830' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Performing subst() rewrite failed, pattern did not match; rule='r_newlines', value='MESSAGE', input='2020-06-09 11:23:47,295 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment ', type='(null)', pattern='u2028', replacement='\x0a', location='/etc/syslog-ng/syslog-ng.conf:186:5’
Further down in the log, I see: Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,341 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Server starting in Staging environment \x0a\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800'
Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Initial message parsing follows; Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='MESSAGE', value='Error processing log message: <-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message \x0a\x0a>@<\x0a<-1>Jun 9 11:23:47 testlogger-service-54956569bb-2c5wl testlogger: 2020-06-09 11:23:47,346 (main) INFO [c.b.s.r.s.TestLoggerServer] [trkId=] Test log message ', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PROGRAM', value='syslog-ng', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='PID', value='28873', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST_FROM', value='10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='HOST', value='10.13.98.167/10.13.98.167', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Setting value; name='SOURCE', value='s_tcp_net_514', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:147:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00800000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local7', location='/etc/syslog-ng/syslog-ng.conf:147:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:146:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00400000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local6', location='/etc/syslog-ng/syslog-ng.conf:146:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:145:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00200000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local5', location='/etc/syslog-ng/syslog-ng.conf:145:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:142:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00040000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local2', location='/etc/syslog-ng/syslog-ng.conf:142:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:141:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00020000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local1', location='/etc/syslog-ng/syslog-ng.conf:141:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:144:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00100000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local4', location='/etc/syslog-ng/syslog-ng.conf:144:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: Requesting flow control; location='/etc/syslog-ng/syslog-ng.conf:143:32' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: facility() evaluation started; fac='5', valid_fac='00080000', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_local3', location='/etc/syslog-ng/syslog-ng.conf:143:32', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: >>>>>> filter rule evaluation begin; rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: match() evaluation started; input='syslog-ng', pattern='.*[.]000', value='PROGRAM', msg='0x7f2af8003800' Jun 9 11:23:47 s_local@syslog syslog-ng[28873]: <<<<<< filter rule evaluation result; result='UNMATCHED - Dropping message from LogPipe', rule='f_loggen', location='/etc/syslog-ng/syslog-ng.conf:97:22', msg='0x7f2af8003800'
Any help would be greatly appreciated.
Thank you, Jason
______________________________________________________________________________ Member info: https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=7yJs4GRtKjFR0SNFxhXEa6jlCF8zEqUj8%2B6IU2U5uJE%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556681572&sdata=2j6perQkx4E3lPEk6kqrrStrbukd2NHGbtT2k%2B%2FKuM4%3D&reserved=0> Documentation: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=fusHd74hogFKcYraC2j1sx90mmj7UAD%2FAy3y6cZ%2BR%2Fs%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556691527&sdata=vqJXbY04zvy%2BLY4fg9neALm68HgY1YfRq8xkvLm8Rok%3D&reserved=0> FAQ: https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7Cb44aaefd475f46061ff208d80c7abb2f%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273068575163388&sdata=9HT%2BQYiSTckuBAU2Q%2F6whDB%2BwYNnfq3xtCG0gSMVU%2B0%3D&reserved=0 <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556691527&sdata=%2BTy4a6pl5jEKRQY5PXz%2BFTKQX3Hv8uJgA%2F0Eh4ZrFVs%3D&reserved=0>
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng <https://nam05.safelinks.protection.outlook.com/?url=https%3A%2F%2Flists.balabit.hu%2Fmailman%2Flistinfo%2Fsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556701484&sdata=Tl68X3wApyRZGPfnxgARSulj6x6j0QACN%2Fzvt8rEgic%3D&reserved=0> Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fsupport%2Fdocumentation%2F%3Fproduct%3Dsyslog-ng&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556701484&sdata=kdsCQ0%2F0R4F4k%2B32bJghFzAyJm8B1VUeP8sFBD4KKQI%3D&reserved=0> FAQ: http://www.balabit.com/wiki/syslog-ng-faq <https://nam05.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.balabit.com%2Fwiki%2Fsyslog-ng-faq&data=02%7C01%7CPeter.Czanik%40oneidentity.com%7C589282067259439325f708d80c7d86c3%7C91c369b51c9e439c989c1867ec606603%7C0%7C1%7C637273080556711442&sdata=EsRLqlrq1bHDYnmgoQTgPX4XLf8WCxQc9wkHpjwdPkY%3D&reserved=0>
Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng <https://lists.balabit.hu/mailman/listinfo/syslog-ng> Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng <http://www.balabit.com/support/documentation/?product=syslog-ng> FAQ: http://www.balabit.com/wiki/syslog-ng-faq <http://www.balabit.com/wiki/syslog-ng-faq>
Hi Jason, On Fri, Jun 12, 2020 at 09:58:40AM +0200, Jason Brown wrote:
It looks like the cause of the “Error processing log message: <-1>” was indeed the logback configuration. Changing the priority to something valid cleans up that error. Unfortunately, it looks like that wasn’t the source of the problem. Digging in a little deeper, I’m seeing this message:
Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: Syslog connection accepted; fd='19', client='AF_INET(10.13.97.36:49346)', local='AF_INET(0.0.0.0:514)' Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: internal() messages are looping back, preventing loop by suppressing all internal messages until the current message is processed; trigger-msg='Syslog connection accepted; fd=\'19\', client=\'AF_INET(10.13.97.36:49346)\', local=\'AF_INET(0.0.0.0:514)\'', first-suppressed-msg='>>>>>> filter rule evaluation begin; rule=\'f_auth\', location=\'/etc/syslog-ng/syslog-ng.conf:136:32\', msg=\'0x11c1bc0\’’
So I’m assuming it’s likely a flow control issue.
I've already seen this message. It's probably unrelated to your issue which I forgot what it was about. This message means that the internal() source, which is referenced somewhere in your configuration (explicitly or implicitly through an scl) which contains messages from syslog-ng itself produces a feedback loop in a log path. This snowball effect is detected by syslog-ng and action is taken to keep syslog-ng from exploding catastrophically ;-) You could disable the internal() source, but usually isolating it in its separate log path is the way to go. Now back to your initial issue, what's happening exactly ?
Thanks. I’ll try disabling the internal() source. What’s happening is this: I have 3 kubernetes pods starting up (I don’t think the issue is related to kubernetes at all. I think we can treat these pods as 3 distinct servers and applications starting up). Each pod sends logs to the remote syslog-ng server. There are some logs sent via UDP, and others via TCP. The UDP logs always get created. The TCP logs only get created sometimes. Sometimes they’ll get created for all 3 pods. Sometimes for just 1. Rarely, none get created. Once a log does get created, the log continues to be written with no problems. Viewing a packet capture, I see TCP syslog traffic from the pods to the syslog server, even if no file is created. I’m not seeing any TCP issues overall. Thanks, Jason
On 12. Jun 2020, at 10:11, Fabien Wernli <wernli@in2p3.fr> wrote:
Hi Jason,
On Fri, Jun 12, 2020 at 09:58:40AM +0200, Jason Brown wrote:
It looks like the cause of the “Error processing log message: <-1>” was indeed the logback configuration. Changing the priority to something valid cleans up that error. Unfortunately, it looks like that wasn’t the source of the problem. Digging in a little deeper, I’m seeing this message:
Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: Syslog connection accepted; fd='19', client='AF_INET(10.13.97.36:49346)', local='AF_INET(0.0.0.0:514)' Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: internal() messages are looping back, preventing loop by suppressing all internal messages until the current message is processed; trigger-msg='Syslog connection accepted; fd=\'19\', client=\'AF_INET(10.13.97.36:49346)\', local=\'AF_INET(0.0.0.0:514)\'', first-suppressed-msg='>>>>>> filter rule evaluation begin; rule=\'f_auth\', location=\'/etc/syslog-ng/syslog-ng.conf:136:32\', msg=\'0x11c1bc0\’’
So I’m assuming it’s likely a flow control issue.
I've already seen this message. It's probably unrelated to your issue which I forgot what it was about. This message means that the internal() source, which is referenced somewhere in your configuration (explicitly or implicitly through an scl) which contains messages from syslog-ng itself produces a feedback loop in a log path. This snowball effect is detected by syslog-ng and action is taken to keep syslog-ng from exploding catastrophically ;-)
You could disable the internal() source, but usually isolating it in its separate log path is the way to go.
Now back to your initial issue, what's happening exactly ?
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.balabit.com/wiki/syslog-ng-faq
Just to update: I’m getting the same exact behaviour using rsyslog as well as syslog-ng. So I’m going to attribute it to an issue with logback. Thanks, Jason
On 12. Jun 2020, at 10:18, Jason Brown <jbrown@boxconsulting.net> wrote:
Thanks. I’ll try disabling the internal() source.
What’s happening is this: I have 3 kubernetes pods starting up (I don’t think the issue is related to kubernetes at all. I think we can treat these pods as 3 distinct servers and applications starting up). Each pod sends logs to the remote syslog-ng server. There are some logs sent via UDP, and others via TCP. The UDP logs always get created. The TCP logs only get created sometimes. Sometimes they’ll get created for all 3 pods. Sometimes for just 1. Rarely, none get created. Once a log does get created, the log continues to be written with no problems.
Viewing a packet capture, I see TCP syslog traffic from the pods to the syslog server, even if no file is created. I’m not seeing any TCP issues overall.
Thanks, Jason
On 12. Jun 2020, at 10:11, Fabien Wernli <wernli@in2p3.fr> wrote:
Hi Jason,
On Fri, Jun 12, 2020 at 09:58:40AM +0200, Jason Brown wrote:
It looks like the cause of the “Error processing log message: <-1>” was indeed the logback configuration. Changing the priority to something valid cleans up that error. Unfortunately, it looks like that wasn’t the source of the problem. Digging in a little deeper, I’m seeing this message:
Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: Syslog connection accepted; fd='19', client='AF_INET(10.13.97.36:49346)', local='AF_INET(0.0.0.0:514)' Jun 12 07:37:03 s_local@syslog syslog-ng[28873]: internal() messages are looping back, preventing loop by suppressing all internal messages until the current message is processed; trigger-msg='Syslog connection accepted; fd=\'19\', client=\'AF_INET(10.13.97.36:49346)\', local=\'AF_INET(0.0.0.0:514)\'', first-suppressed-msg='>>>>>> filter rule evaluation begin; rule=\'f_auth\', location=\'/etc/syslog-ng/syslog-ng.conf:136:32\', msg=\'0x11c1bc0\’’
So I’m assuming it’s likely a flow control issue.
I've already seen this message. It's probably unrelated to your issue which I forgot what it was about. This message means that the internal() source, which is referenced somewhere in your configuration (explicitly or implicitly through an scl) which contains messages from syslog-ng itself produces a feedback loop in a log path. This snowball effect is detected by syslog-ng and action is taken to keep syslog-ng from exploding catastrophically ;-)
You could disable the internal() source, but usually isolating it in its separate log path is the way to go.
Now back to your initial issue, what's happening exactly ?
______________________________________________________________________________ Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng Documentation: http://www.balabit.com/support/documentation/?product=syslog-ng FAQ: http://www.balabit.com/wiki/syslog-ng-faq
On Tue, Jun 16, 2020 at 02:21:19PM +0200, Jason Brown wrote:
I’m getting the same exact behaviour using rsyslog as well as syslog-ng. So I’m going to attribute it to an issue with logback.
Good to know there's at least one case where rsyslog is on par with syslog-ng
participants (3)
-
Fabien Wernli
-
Jason Brown
-
Peter Czanik (pczanik)