Hi,
We are using rsyslog 5.8.10 on a system with 14 hosts to perform centralized
logging. The host running rsyslog receives RFC 5424 messages from all of the
other hosts via TCP and then:
1) Sends each message to a local Postgres database
2) Writes each message to either 1 or 2 local log files depending on the
message severity (all msgs to one file, notice and above to the other)
Three of the nodes have a bug that causes them to include 12 0xFF bytes in a
log message when the node is rebooted. The 0xFF bytes can be seen when viewing
the raw message in Wireshark. These messages are rejected by Postgres, which is
looking for valid UTF-8 encoding.
Running rsyslog with debug enabled produces the following when the message is
first processed:
4323.406081509:7f50575fe700: main Q: entry added, size now log 1, phys 1 entries
4323.406146203:7f50575fe700: main Q: MultiEnqObj advised worker start
4323.406212007:7f505d6d6700: wti 0x7f5064fa4510: worker awoke from idle
processing
4323.406266498:7f505d6d6700: we deleted 0 objects and enqueued 0 objects
4323.406289804:7f505d6d6700: delete batch from store, new sizes: log 1, phys 1
4323.406315147:7f505d6d6700: msg parser: flags 30, from 'GS05', msg '<134>1
2015-02-24T16:11:52.113Z 10.32.13.69 RU6 CpEEPROM.c:1'
4323.406337735:7f505d6d6700: parse using parser list 0x7f5064f9b2e0 (the
default list).
4323.406359986:7f505d6d6700: Message has RFC5424/syslog-protocol format.
4323.406386196:7f505d6d6700: Parser 'rsyslog.rfc5424' returned 0
4323.406408334:7f505d6d6700: processBatch: batch of 1 elements must be processed
4323.406437792:7f505d6d6700: Processing next rule
4323.406459326:7f505d6d6700: testing filter, f_pmask 255
4323.406479985:7f505d6d6700: Processing next action
4323.406501879:7f505d6d6700: Called action(NotAllMark), processing batch[0] via
'ompgsql.so'
4323.406522721:7f505d6d6700: Called action(Batch), logging to ompgsql.so
4323.406546523:7f505d6d6700: prop repl 4, pRes='local0.info<134>', len -1
4323.406567924:7f505d6d6700: end prop repl, pRes='local0.info<134>', len 16
4323.406589533:7f505d6d6700: prop repl 4, pRes='10.32.13.69', len 11
4323.406610432:7f505d6d6700: end prop repl, pRes='10.32.13.69', len 11
4323.406632442:7f505d6d6700: prop repl 4, pRes='2015-02-24T16:11:52.113Z', len
-1
4323.406653397:7f505d6d6700: end prop repl, pRes='2015-02-24T16:11:52.113Z',
len 24
4323.406674652:7f505d6d6700: prop repl 4, pRes='STA:014F PASSED: Comm Node
serial number is: <FF><FF><FF><FF><FF><FF><FF><FF><FF><FF><FF><FF>', len 57
4323.406695574:7f505d6d6700: end prop repl, pRes='STA:014F PASSED: Comm Node
serial number is: <FF><FF><FF><FF><FF><FF><FF><FF><FF><FF><FF><FF>', len 57
4323.406716807:7f505d6d6700: prop repl 4, pRes='6', len -1
4323.406737649:7f505d6d6700: end prop repl, pRes='6', len 1
4323.406759341:7f505d6d6700: XXXXX: tryDoAction 0x7f5064fbd6f0, pnElem 1,
nElem 1
4323.406781924:7f505d6d6700: ompgsql: beginTransaction
4323.406802804:7f505d6d6700: writePgSQL: begin
4323.406996817:7f505d6d6700: Action 0x7f5064fbd6f0 transitioned to state: itx
4323.407036589:7f505d6d6700: entering actionCalldoAction(), state: itx
4323.407058960:7f505d6d6700:
4323.407080255:7f505d6d6700: writePgSQL: INSERT INTO data_log ( id, category,
component, timestamp, description, severity, repeated ) VALUES (
nextval('data_log_entry_seq'::regclass), 'local0.info<134>', '10.32.13.69',
'2015-02-24T16:11:52.113Z', 'STA:014F PASSED: Comm Node serial number is:
<FF><FF><FF><FF><FF><FF>
<FF><FF><FF><FF><FF><FF>'::varchar(2000), '6', 0 );
4323.407374531:7f505d6d6700: postgres query execution failed: PGRES_FATAL_ERROR
4323.407440360:7f505d6d6700: host=localhost dbname=postgres uid=postgres
4323.410870363:7f505d6d6700: postgres query execution failed: PGRES_FATAL_ERROR
4323.410904378:7f505d6d6700: pgsql, DBError(silent): db error (0): ERROR:
invalid byte sequence for encoding "UTF8": 0xff
The configuration includes the "$Escape8BitCharactersOnReceive on" directive
and running rsyslog interactively with -c 5 -N 1 does not indicate any config
errors. The debug output includes the line:
3945.537959731:7f5062e36700: cfline: '$Escape8BitCharactersOnReceive on'
The startup command for rsyslog includes -c 5 as the first option:
root 8747 0.0 0.0 469496 3764 ? Sl Feb24 0:00 /sbin/rsyslogd
-c 5 -i /var/run/syslogd.pid
Disabling the connection to Postgres allows the message to be written to the
appropriate local logfile, but 0xFF characters have not been replaced with
escape sequences:
2015-02-24T18:55:10.905Z 10.32.13.69 RU6[CpEEPROM.c:1413] info STA:014F PASSED:
Comm Node serial number is: <FF><FF><FF><FF><FF><FF><FF><FF><FF><FF><FF><FF>
I thought that $Escape8BitCharactersOnReceive would replace any msg bytes
received with the 8th bit set with a sequence of valid ASCII, and therefore
UTF-8 characters. Since the 8 bit characters are replaced at the input to
rsyslog, shouldn't the outputs have the appropriate escape sequences? Why is
0xFF still being passed to Postgres?
Thanks,
Al
This message is intended only for the addressee and may contain information
that is company confidential or privileged. Any technical data in this message
may be exported only in accordance with the U.S. International Traffic in Arms
Regulations (22 CFR Parts 120-130) or the Export Administration Regulations (15
CFR Parts 730-774). Unauthorized use is strictly prohibited and may be
unlawful. If you are not the intended recipient, or the person responsible for
delivering to the intended recipient, you should not read, copy, disclose or
otherwise use this message. If you have received this email in error, please
delete it, and advise the sender immediately.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE
THAT.
