MonitorWare Knowledge Base

I have a problem with rsyslog 2.0.5 and 3.17.x on FreeBSD 7.0. I try to log events from a Cisco router via TCP syslog directly to MySQL. It works in general, but rsyslog collects several messages and writes them - as one message - after 2048 bytes into the database or in a file, which is useless.

If I switch to UDP it works!

Code: Select all

673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Message length: 2048, File descriptor: 8.
[color=#FF0000]673190144: logmsg: local7.notice<189>, flags 2, from 'fw', msg 681: Sep 22 2008 02:48:13.984 MET-DST: %SYS-5-CONFIG_I: Confjigured from console by svcaccount on vty0 (209.240.42.198)<190>682: Sep 22 2008 02:48:19.982 MET-DST: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 192.168.1.5 port 514 started - reconnection<189>683: Sep 22 2008 02:48:42.118 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>684: Sep 22 2008 02:48:43.874 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>685: Sep 22 2008 02:48:45.438 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>686: Sep 22 2008 02:48:47.150 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>687: Sep 22 2008 02:48:48.850 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>688: Sep 22 2008 02:48:50.809 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>689: Sep 22 2008 02:48:53.624 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>690: Sep 22 2008 02:48:56.478 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>691: Sep 22 2008 02:48:58.901 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>692: Sep 22 2008 02:49:00.344 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>693: Sep 22 2008 02:49:02.095 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>694: Sep 22 2008 02:49:03.743 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>695: Sep 22 2008 02:49:05.354 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>696: Sep 22 2008 02:49:06.965 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>697: Sep 22 2008 02:49:09.024 MET-DST: %SYS-5-CONFIG_I: Configure[/color]
673190144: Message has legacy syslog format.
673190144: HOSTNAME contains invalid characters, assuming it to be a TAG.
673190144: EnqueueMsg signaled condition (0)
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8

I noticed that after the PRI Cisco sends out an sequence number example: <189>685:. I can't disable this sequence number. You can enable on Cisco with service sequence number and additional sequence number, but than rsyslog receives two sequence numbers.

I hope somebody can help!

Regards
Thomas

Cisco Router config:
logging trap debugging
logging host 192.168.1.5 transport tcp port 514

rsyslog 2.x config:
$ModLoad MySQL
*.* >localhost,Syslog,sysloguser,password
*.* /var/log/tcp


example debug of rsyslog 2.0.5 (same problem with 3.17.x):

Code: Select all

svr1# /usr/local/sbin/rsyslogd -i /var/run/rsyslogd.pid -f /usr/local/etc/rsyslog.conf -t514,500 -d
Starting.
673190144: rsyslog 2.0.5.
673190144: Called init.
673190144: Unloading non-static modules.
673190144: Clearing templates.
673190144: cfline: '$ModLoad MySQL'
673190144: Requested to load module 'MySQL'
673190144: cfline: '*.* >localhost,Syslog,sysloguser,7yhnmju8&YHN'
673190144:  - traditional PRI filter
673190144: symbolic name: * ==> 255
673190144: tried selector action for builtin-file: -2001
673190144: tried selector action for builtin-fwd: -2001
673190144: tried selector action for builtin-shell: -2001
673190144: tried selector action for builtin-discard: -2001
673190144: tried selector action for builtin-usrmsg: -2001
673190144: tried selector action for ommysql.so: 0
673190144: Module ommysql.so processed this config line.
673190144: template: ' StdDBFmt' assigned
673190144: cfline: '*.* /var/log/tcp'
673190144: selector line successfully processed
673190144:  - traditional PRI filter
673190144: symbolic name: * ==> 255
673190144: tried selector action for builtin-file: 0
673190144: Module builtin-file processed this config line.
673190144: template: ' TradFmt' assigned
673190144: selector line successfully processed
673190144: Opened UNIX socket `/var/run/log' (fd 3).
673190144: Allocating buffer for 500 TCP sessions.
673190144: Opened 2 syslog TCP port(s).
673190144: Worker thread started with state 0.

Active selectors:
Selector 1:
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
Actions:
ommysql.so:
        Instance data: 0x28213400
        RepeatedMsgReduction: 1
        Resume Interval: 30
        Suspended: 0
        Disabled: 0
        Exec only when previous is suspended: 0



Selector 2:
FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
Actions:
builtin-file: /var/log/tcp
        Instance data: 0x28243140
        RepeatedMsgReduction: 1
        Resume Interval: 30
        Suspended: 0
673190400: singleWorker: queue EMPTY, waiting for next message.
        Disabled: 0
        Exec only when previous is suspended: 0




673190144: Template: Name=' TradFmt'
673190144:      Entry(2820b040): type 2, (FIELD), value: 'TIMESTAMP'
673190144:      Entry(2820b080): type 1, (CONSTANT), value: ' '
673190144:      Entry(2820b0c0): type 2, (FIELD), value: 'HOSTNAME'
673190144:      Entry(2820b100): type 1, (CONSTANT), value: ' '
673190144:      Entry(2820b140): type 2, (FIELD), value: 'syslogtag'
673190144:      Entry(2820b180): type 2, (FIELD), value: 'msg' [drop last LF in msg]
673190144:      Entry(2820b1c0): type 1, (CONSTANT), value: '
'
673190144: Template: Name=' WallFmt'
673190144:      Entry(2820b200): type 1, (CONSTANT), value: '
Message from syslogd@'
673190144:      Entry(2820b240): type 2, (FIELD), value: 'HOSTNAME'
673190144:      Entry(2820b280): type 1, (CONSTANT), value: ' at '
673190144:      Entry(2820b2c0): type 2, (FIELD), value: 'timegenerated'
673190144:      Entry(2820b300): type 1, (CONSTANT), value: ' ...
'
673190144:      Entry(2820b340): type 2, (FIELD), value: 'syslogtag'
673190144:      Entry(2820b380): type 2, (FIELD), value: 'msg'
673190144:      Entry(2820b3c0): type 1, (CONSTANT), value: '
'
673190144: Template: Name=' StdFwdFmt'
673190144:      Entry(2820b400): type 1, (CONSTANT), value: '<'
673190144:      Entry(2820b440): type 2, (FIELD), value: 'PRI'
673190144:      Entry(2820b480): type 1, (CONSTANT), value: '>'
673190144:      Entry(2820b4c0): type 2, (FIELD), value: 'TIMESTAMP'
673190144:      Entry(2820b500): type 1, (CONSTANT), value: ' '
673190144:      Entry(2820b540): type 2, (FIELD), value: 'HOSTNAME'
673190144:      Entry(2820b580): type 1, (CONSTANT), value: ' '
673190144:      Entry(2820b5c0): type 2, (FIELD), value: 'syslogtag'
673190144:      Entry(2820b600): type 2, (FIELD), value: 'msg'
673190144: Template: Name=' StdUsrMsgFmt'
673190144:      Entry(2820b640): type 1, (CONSTANT), value: ' '
673190144:      Entry(2820b680): type 2, (FIELD), value: 'syslogtag'
673190144:      Entry(2820b6c0): type 2, (FIELD), value: 'msg'
673190144:      Entry(2820b700): type 1, (CONSTANT), value: '
'
673190144: Template: Name=' StdDBFmt' [SQL-Format (MySQL)]
673190144:      Entry(2820b740): type 1, (CONSTANT), value: 'insert into SystemEvents (Message, Facility, FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values (''
673190144:      Entry(2820b780): type 2, (FIELD), value: 'msg'
673190144:      Entry(2820b7c0): type 1, (CONSTANT), value: '', '
673190144:      Entry(2820b800): type 2, (FIELD), value: 'syslogfacility'
673190144:      Entry(2820b840): type 1, (CONSTANT), value: ', ''
673190144:      Entry(2820b880): type 2, (FIELD), value: 'HOSTNAME'
673190144:      Entry(2820b8c0): type 1, (CONSTANT), value: '', '
673190144:      Entry(2820b900): type 2, (FIELD), value: 'syslogpriority'
673190144:      Entry(2820b940): type 1, (CONSTANT), value: ', ''
673190144:      Entry(2820b980): type 2, (FIELD), value: 'timereported' [Format as MySQL-Date]
673190144:      Entry(2820b9c0): type 1, (CONSTANT), value: '', ''
673190144:      Entry(2820ba00): type 2, (FIELD), value: 'timegenerated' [Format as MySQL-Date]
673190144:      Entry(2820ba40): type 1, (CONSTANT), value: '', '
673190144:      Entry(2820ba80): type 2, (FIELD), value: 'iut'
673190144:      Entry(2820bac0): type 1, (CONSTANT), value: ', ''
673190144:      Entry(2820bb00): type 2, (FIELD), value: 'syslogtag'
673190144:      Entry(2820bb40): type 1, (CONSTANT), value: '')'
673190144: Template: Name=' StdPgSQLFmt' [SQL-Format (standard SQL)]
673190144:      Entry(2820bb80): type 1, (CONSTANT), value: 'insert into SystemEvents (Message, Facility, FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values (''
673190144:      Entry(2820bbc0): type 2, (FIELD), value: 'msg'
673190144:      Entry(2820bc00): type 1, (CONSTANT), value: '', '
673190144:      Entry(2820bc40): type 2, (FIELD), value: 'syslogfacility'
673190144:      Entry(2820bc80): type 1, (CONSTANT), value: ', ''
673190144:      Entry(2820bcc0): type 2, (FIELD), value: 'HOSTNAME'
673190144:      Entry(2820bd00): type 1, (CONSTANT), value: '', '
673190144:      Entry(2820bd40): type 2, (FIELD), value: 'syslogpriority'
673190144:      Entry(2820bd80): type 1, (CONSTANT), value: ', ''
673190144:      Entry(2820bdc0): type 2, (FIELD), value: 'timereported' [Format as PgSQL-Date]
673190144:      Entry(2820be00): type 1, (CONSTANT), value: '', ''
673190144:      Entry(2820be40): type 2, (FIELD), value: 'timegenerated' [Format as PgSQL-Date]
673190144:      Entry(2820be80): type 1, (CONSTANT), value: '', '
673190144:      Entry(2820bec0): type 2, (FIELD), value: 'iut'
673190144:      Entry(2820bf00): type 1, (CONSTANT), value: ', ''
673190144:      Entry(2820bf40): type 2, (FIELD), value: 'syslogtag'
673190144:      Entry(2820bf80): type 1, (CONSTANT), value: '')'
673190144: Loaded Module: Name='builtin-file', IFVersion=1, type=output module.
673190144: Entry points:
673190144:      queryEtryPt:        0x805ca30
673190144:      doAction:           0x805d6b0
673190144:      parseSelectorAct:   0x805cfe0
673190144:      dbgPrintInstInfo:   0x805ccf0
673190144:      freeInstance:       0x805cc70
673190144:
673190144: Loaded Module: Name='builtin-fwd', IFVersion=1, type=output module.
673190144: Entry points:
673190144:      queryEtryPt:        0x805a9d0
673190144:      doAction:           0x805afa0
673190144:      parseSelectorAct:   0x805b340
673190144:      dbgPrintInstInfo:   0x805af80
673190144:      freeInstance:       0x805aef0
673190144:
673190144: Loaded Module: Name='builtin-shell', IFVersion=1, type=output module.
673190144: Entry points:
673190144:      queryEtryPt:        0x8059ce0
673190144:      doAction:           0x8059ff0
673190144:      parseSelectorAct:   0x8059ee0
673190144:      dbgPrintInstInfo:   0x8059ec0
673190144:      freeInstance:       0x8059ea0
673190144:
673190144: Loaded Module: Name='builtin-discard', IFVersion=1, type=output module.
673190144: Entry points:
673190144:      queryEtryPt:        0x805dcb0
673190144:      doAction:           0x805dc00
673190144:      parseSelectorAct:   0x805de90
673190144:      dbgPrintInstInfo:   0x805dbd0
673190144:      freeInstance:       0x805de70
673190144:
673190144: Loaded Module: Name='builtin-usrmsg', IFVersion=1, type=output module.
673190144: Entry points:
673190144:      queryEtryPt:        0x805a110
673190144:      doAction:           0x805a8e0
673190144:      parseSelectorAct:   0x805a340
673190144:      dbgPrintInstInfo:   0x805a2f0
673190144:      freeInstance:       0x805a2d0
673190144:
673190144: Loaded Module: Name='ommysql.so', IFVersion=1, type=output module.
673190144: Entry points:
673190144:      queryEtryPt:        0x281bbbe0
673190144:      doAction:           0x281bc310
673190144:      parseSelectorAct:   0x281bc010
673190144:      dbgPrintInstInfo:   0x281bbb10
673190144:      freeInstance:       0x281bbfd0
673190144:

Sytem Line Configuration Commands:
        Command 'dynafilecachesize':
                type : 6
                pData: 0x0
                Hdlr : 0x805cdd0
                Owner: 0x805c760

        Command 'dirowner':
                type : 2
                pData: 0x8067a4c
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'dirgroup':
                type : 3
                pData: 0x8067a50
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'fileowner':
                type : 2
                pData: 0x8067a44
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'filegroup':
                type : 3
                pData: 0x8067a48
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'dircreatemode':
                type : 5
                pData: 0x80668d0
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'filecreatemode':
                type : 5
                pData: 0x80668d4
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'createdirs':
                type : 4
                pData: 0x8067a54
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'failonchownfailure':
                type : 4
                pData: 0x8067a40
                Hdlr : 0x0
                Owner: 0x805c760

        Command 'resetconfigvariables':
                type : 1
                pData: 0x0
                Hdlr : 0x805c6f0
                Owner: 0x805c760

                type : 1
                pData: 0x0
                Hdlr : 0x804cca0
                Owner: 0x0

        Command 'mainmsgqueuesize':
                type : 6
                pData: 0x8067ba4
                Hdlr : 0x0
                Owner: 0x0

        Command 'repeatedmsgreduction':
                type : 4
                pData: 0x8067968
                Hdlr : 0x0
                Owner: 0x0

        Command 'actionexeconlywhenpreviousissuspended':
                type : 4
                pData: 0x806796c
                Hdlr : 0x0
                Owner: 0x0

        Command 'actionresumeinterval':
                type : 6
                pData: 0x0
                Hdlr : 0x804ce20
                Owner: 0x0

        Command 'controlcharacterescapeprefix':
                type : 7
                pData: 0x80664d9
                Hdlr : 0x0
                Owner: 0x0

        Command 'escapecontrolcharactersonreceive':
                type : 4
                pData: 0x80664dc
                Hdlr : 0x0
                Owner: 0x0

        Command 'dropmsgswithmaliciousdnsptrrecords':
                type : 4
                pData: 0x80678dc
                Hdlr : 0x0
                Owner: 0x0

        Command 'droptrailinglfonreception':
                type : 4
                pData: 0x80664e0
                Hdlr : 0x0
                Owner: 0x0

        Command 'template':
                type : 1
                pData: 0x0
                Hdlr : 0x8051720
                Owner: 0x0

        Command 'outchannel':
                type : 1
                pData: 0x1
                Hdlr : 0x8051720
                Owner: 0x0

        Command 'allowedsender':
                type : 1
                pData: 0x2
                Hdlr : 0x8051720
                Owner: 0x0

        Command 'modload':
                type : 1
                pData: 0x0
                Hdlr : 0x804f680
                Owner: 0x0

        Command 'includeconfig':
                type : 1
                pData: 0x0
                Hdlr : 0x8050830
                Owner: 0x0

        Command 'umask':
                type : 5
                pData: 0x0
                Hdlr : 0x804d360
                Owner: 0x0

        Command 'debugprinttemplatelist':
                type : 4
                pData: 0x80664e4
                Hdlr : 0x0
                Owner: 0x0

        Command 'debugprintmodulelist':
                type : 4
                pData: 0x80664e8
                Hdlr : 0x0
                Owner: 0x0

        Command 'debugprintcfsyslinehandlerlist':
                type : 4
                pData: 0x80664ec
                Hdlr : 0x0
                Owner: 0x0

        Command 'moddir':
                type : 8
                pData: 0x8067918
                Hdlr : 0x0
                Owner: 0x0



Allowed UDP Senders:
        No restrictions set.

Allowed TCP Senders:
        No restrictions set.

Messages with malicious PTR DNS Records are not dropped.
Control characters are replaced upon reception.
Control character escape sequence prefix is '#'.
Main queue size 10000 messages.
673190144: logmsg: syslog.info<46>, flags 5, from 'svr1', msg  [origin software="rsyslogd" swVersion="2.0.5" x-pid="26769" x-info="http://www.rsyslog.com"][x-configInfo udpReception="No" udpPort="514" tcpReception="Yes" tcpPort="514"] restart
673190144: Message has legacy syslog format.
673190144: EnqueueMsg signaled condition (0)
673190144:  restarted.
673190144: Debugging enabled, SIGUSR1 to turn off debugging.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 7): 3 6 7
673190400: Lone worker is running...
673190400: Called fprintlog, logging to ommysql.so
673190400: Called fprintlog, logging to builtin-file (/var/log/tcp)
673190400: singleWorker: queue EMPTY, waiting for next message.
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 7): 3 6 7
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 7): 3 6 7
673190144:
Successful select, descriptor count = 1, Activity on: 7
673190144: New connect on TCP inetd socket: #7
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: Select interrupted.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: Select interrupted.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 8
673190144: tcp session socket with new data: #8
673190144: Message length: 2048, File descriptor: 8.
673190144: logmsg: local7.notice<189>, flags 2, from 'fw', msg 681: Sep 22 2008 02:48:13.984 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<190>682: Sep 22 2008 02:48:19.982 MET-DST: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 192.168.1.5 port 514 started - reconnection<189>683: Sep 22 2008 02:48:42.118 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>684: Sep 22 2008 02:48:43.874 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>685: Sep 22 2008 02:48:45.438 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>686: Sep 22 2008 02:48:47.150 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>687: Sep 22 2008 02:48:48.850 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>688: Sep 22 2008 02:48:50.809 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>689: Sep 22 2008 02:48:53.624 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>690: Sep 22 2008 02:48:56.478 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>691: Sep 22 2008 02:48:58.901 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>692: Sep 22 2008 02:49:00.344 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>693: Sep 22 2008 02:49:02.095 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>694: Sep 22 2008 02:49:03.743 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>695: Sep 22 2008 02:49:05.354 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>696: Sep 22 2008 02:49:06.965 MET-DST: %SYS-5-CONFIG_I: Configured from console by svcaccount on vty0 (209.240.42.198)<189>697: Sep 22 2008 02:49:09.024 MET-DST: %SYS-5-CONFIG_I: Configure
673190144: Message has legacy syslog format.
673190144: HOSTNAME contains invalid characters, assuming it to be a TAG.
673190144: EnqueueMsg signaled condition (0)
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190400: Lone worker is running...
673190400: Called fprintlog, logging to ommysql.so
673190400: Called fprintlog, logging to builtin-file (/var/log/tcp)
673190400: singleWorker: queue EMPTY, waiting for next message.
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: Select interrupted.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: Select interrupted.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144:
Successful select, descriptor count = 1, Activity on: 3
673190144: Message from UNIX socket: #3
673190144: Message length: 74, File descriptor: 3.
673190144: logmsg: cron.info<78>, flags 2, from 'svr1', msg Sep 22 02:50:01 /usr/sbin/cron[26774]: (root) CMD (/usr/libexec/atrun)
673190144: Message has legacy syslog format.
673190144: EnqueueMsg signaled condition (0)
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190400: Lone worker is running...
673190400: Called fprintlog, logging to ommysql.so
673190400: Called fprintlog, logging to builtin-file (/var/log/tcp)
673190400: singleWorker: queue EMPTY, waiting for next message.
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: Select interrupted.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
673190144: No select activity.
673190144: Listening on TCP syslogd socket 6 (IPv6/port 514).
673190144: Listening on TCP syslogd socket 7 (IPv4/port 514).
673190144: Adding TCP Session 8
673190144: ----------------------------------------
673190144: Calling select, active file descriptors (max 8): 3 6 7 8
^C673190144: DoDie called.
673190144: Select interrupted.
673190144:  exiting on signal 2
673190144: logmsg: syslog.info<46>, flags 5, from 'svr1', msg  [origin software="rsyslogd" swVersion="2.0.5" x-pid="26769" x-info="http://www.rsyslog.com"] exiting on signal 2.
673190144: Message has legacy syslog format.
673190144: EnqueueMsg signaled condition (0)
673190144: Freeing log structures.
673190144: Initiating worker thread shutdown sequence...
673190400: Lone worker is running...
673190400: Called fprintlog, logging to ommysql.so
673190400: Called fprintlog, logging to builtin-file (/var/log/tcp)
673190400: Worker thread terminates
673190144: Worker thread terminated.
673190144: Closing TCP Session 8
673190144: Closing socket 7.
673190144: Closing socket 6.
673190144: Unloading module builtin-file
673190144: Unloading module builtin-fwd
673190144: Unloading module builtin-shell
673190144: Unloading module builtin-discard
673190144: Unloading module builtin-usrmsg
673190144: Unloading module ommysql.so
673190144: Clean shutdown completed, bye.


• Custom written rsyslog.conf?
• Maintenance Contract?
• Installation support?

OK, let's start with the glued-together messages. This looks a bit extreme. Unfortunately, there is no standard on how to transmit syslog messages over plain TCP. However, the industry standard, so far I thought implemented by all major players, is to terminate the message with a line feed. There is a better way of doing things (as described in syslog-tls draft), but let not yet look into it as it does not apply here.

From what I see, it looks like the Cisco device is sending messages without any termination sequence. This looks very (very!) strange. From personal experience with PIX, I know that Cisco at least sometimes does the proper termination. May this be something you can turn on or off in the device?

Please let me know.

Rainer

Hi,

I setup two other Cisco router to send tcp syslog and same problem: multiple messages get recorded/stored into the file/DB.

Do you have a working configuration for Cisco routers in combination with rsyslog TCP/MySQL?

Regards
Thomas

I continued with the troubleshooting and captured the following packets:

Code: Select all

svr1# tcpdump -n -vvv -X -s 1500 tcp port 514
tcpdump: listening on le0, link-type EN10MB (Ethernet), capture size 1500 bytes
20:35:31.210749 IP (tos 0x0, ttl 255, id 63429, offset 0, flags [none], proto TCP (6), length 162) 192.168.1.1.26583 > 192.168.1.5.514: ., cksum 0xaa39 (correct), 3993659652:3993659774(122) ack 1935482468 win 4128
        0x0000:  4500 00a2 f7c5 0000 ff06 4039 c0a8 0101  E.........@9....
        0x0010:  c0a8 0105 67d7 0202 ee0a 6904 735d 1e64  ....g.....i.s].d
        0x0020:  5010 1020 aa39 0000 3c31 3839 3e37 3135  P....9..<189>715
        0x0030:  3a20 5365 7020 3232 2032 3030 3820 3230  :.Sep.22.2008.20
        0x0040:  3a33 353a 3330 2e32 3132 204d 4554 2d44  :35:30.212.MET-D
        0x0050:  5354 3a20 2553 5953 2d35 2d43 4f4e 4649  ST:.%SYS-5-CONFI
        0x0060:  475f 493a 2043 6f6e 6669 6775 7265 6420  G_I:.Configured.
        0x0070:  6672 6f6d 2063 6f6e 736f 6c65 2062 7920  from.console.by.
        0x0080:  7376 6361 6363 6f75 6e74 206f 6e20 7674  svcaccount.on.vt
        0x0090:  7930 2028 xxxx xx2e xxxx xx2e xxxx 2exx  y0.(xxx.xxx.xx.x
        0x00a0:  xx29                                     x)
20:35:31.310654 IP (tos 0x0, ttl 64, id 16931, offset 0, flags [DF], proto TCP (6), length 40) 192.168.1.5.514 > 192.168.1.1.26583: ., cksum 0xd959 (correct), 1:1(0) ack 122 win 65535
        0x0000:  4500 0028 4223 4000 4006 7556 c0a8 0105  E..(B#@.@.uV....
        0x0010:  c0a8 0101 0202 67d7 735d 1e64 ee0a 697e  ......g.s].d..i~
        0x0020:  5010 ffff d959 0000                      P....Y..
20:35:48.475270 IP (tos 0x0, ttl 255, id 63430, offset 0, flags [none], proto TCP (6), length 162) 192.168.1.1.26583 > 192.168.1.5.514: ., cksum 0xa9ae (correct), 122:244(122) ack 1 win 4128
        0x0000:  4500 00a2 f7c6 0000 ff06 4038 c0a8 0101  E.........@8....
        0x0010:  c0a8 0105 67d7 0202 ee0a 697e 735d 1e64  ....g.....i~s].d
        0x0020:  5010 1020 a9ae 0000 3c31 3839 3e37 3136  P.......<189>716
        0x0030:  3a20 5365 7020 3232 2032 3030 3820 3230  :.Sep.22.2008.20
        0x0040:  3a33 353a 3437 2e35 3038 204d 4554 2d44  :35:47.508.MET-D
        0x0050:  5354 3a20 2553 5953 2d35 2d43 4f4e 4649  ST:.%SYS-5-CONFI
        0x0060:  475f 493a 2043 6f6e 6669 6775 7265 6420  G_I:.Configured.
        0x0070:  6672 6f6d 2063 6f6e 736f 6c65 2062 7920  from.console.by.
        0x0080:  7376 6361 6363 6f75 6e74 206f 6e20 7674  svcaccount.on.vt
        0x0090:  7930 2028 xxxx xx2e xxxx xx2e xxxx 2exx  y0.(xxx.xxx.xx.x
        0x00a0:  xx29                                     x)                                  5)
20:35:48.575206 IP (tos 0x0, ttl 64, id 16934, offset 0, flags [DF], proto TCP (6), length 40) 192.168.1.5.514 > 192.168.1.1.26583: ., cksum 0xd8df (correct), 1:1(0) ack 244 win 65535
        0x0000:  4500 0028 4226 4000 4006 7553 c0a8 0105  E..(B&@.@.uS....
        0x0010:  c0a8 0101 0202 67d7 735d 1e64 ee0a 69f8  ......g.s].d..i.
        0x0020:  5010 ffff d8df 0000                      P.......


You can see the router sends only one single syslog message and the syslog server ACK.

This points to a problem on the syslog server. Is there a option to write every syslog message immediately and don't play around with the buffers?

Regards
Thomas

t.reisinger wrote:This points to a problem on the syslog server.

No! TCP is a stream-oriented protocol and as such there, from a logical point of view, is no such thing as a record. Protocols needs to define framing. And the framing for plain tcp syslog is LF at the end of the message. From what I see, the router sends everything is a bunch of bytes, so there is no way to know when the record ends.

I think there must be a way to configure the router to send data with the proper framing.

Rainer

side-note: you may want to try the rsyslog mailing list to ask if folks over there experienced similar problems.

The UDP syslog message is also missing the LF at the end of the packet, but processed correct.

t.reisinger wrote:The UDP syslog message is also missing the LF at the end of the packet, but processed correct.

I am sorry, but you do not understand the difference between datagram services and network streams. Datagrams *are* packet oriented, streams are not. Thus different communication protocols are needed for both.

I suggest you check your router config on how to make the router send the message with correct framing. If you do not follow my advise, I can not help

I'll ask the mailing list if there is someone who know the correct router configuration.

Please have a look at this mailing list post:

http://lists.adiscon.net/pipermail/rsys ... 01203.html

Does that help? Also, please let me know which version of IOS you are using.

Rainer

Rainer,

First at all thank you very much for your prompt support and replies. I know about the two additional options in IOS:

BEEP (Cisco's reference to RFC3195)
and ESM filter

For my test I'm using 12.4T versions.

The problem is, I will use also older IOS versions, which doesn't support this features. With this limitation in mind I have to find the smallest common feature: TCP, which is implemented since 12.3

I understand also the difference between UDP/TCP block/stream. I'm just surprised that nobody else run into this problem before using a Cisco router? I'm sure other people are fine with using UDP inside there LAN. I want to monitor devices via the Internet and UDP is maybe not the best transport protocol for this purpose.

The next step is to create Cisco TAC case. I will do, but it will take some time.

I'm sure that it's not a big issue to implement a work around into rsyslog.

New feature:

Global option:

Code: Select all

Fix-Cisco-IOS-TCP Yes/No

After every received TCP message insert a LF inside the rsyslog buffer.


Sorry, if I'm to naive for this feature request, but what do you think about it?

Regards
Thomas

t.reisinger wrote:I'm just surprised that nobody else run into this problem before using a Cisco router?

That surprises me too. Really. Someone should have run into it...

t.reisinger wrote:I'm sure other people are fine with using UDP inside there LAN. I want to monitor devices via the Internet and UDP is maybe not the best transport protocol for this purpose.

You are phrasing it very polite...

t.reisinger wrote:The next step is to create Cisco TAC case. I will do, but it will take some time.

I have contacted someone at Cisco earlier today. I hope to get some results from that.

t.reisinger wrote:I'm sure that it's not a big issue to implement a work around into rsyslog.

New feature:

Global option:

Code: Select all

Fix-Cisco-IOS-TCP Yes/No

After every received TCP message insert a LF inside the rsyslog buffer.


Sorry, if I'm to naive for this feature request, but what do you think about it?

Well, honestly, you have not understood how a TCP stream works. When I initially learned about TCP streams I had the same problem. You think that a fragment received and acked is some higher-level entity. It is not. There is no one-to-one mapping between frames received and application records. So the problem with this feature request is that it doesn't tell us when one message ends and the next one starts. TCP low-level framing does not tell you that.

I suggest that you have a look at RFC 3117, which provides some very good information on the topic.

http://tools.ietf.org/html/rfc3117

It is best to read it completely, but a partial read should at least cover section 3.1, which talks about framing. Also, any other reasonable textbook about how TCP works should help. And, of course, you could have a look at the TCP RFC's themselfs, which clearly spell out why you can't rely on TCP acks for app-level framing. Finally, you might want to have a look at

http://blog.gerhards.net/2008/04/on-unr ... yslog.html

so that you can feel really bad if you have ever thought that pure TCP is a cure for reliability issues

Rainer

I have evaluted this problem a bit further. Unfortunately I am lacking the necessary hardware, so I can not do any testing myself. From what I have found on the Internet, though, it really looks like a bug in IOS. As I wrote, there is no good work-around available. One option may be to use beep (rsyslog supports it), but there are some differences in Cisco's BEEP interpretation and ours. I did some interop testing with them and with unpatched versions the router quickly aborted. I patched our beep stack, but unfortunately the patched version is not yet available as open source. I'll see if I can get a release for that, but I can not promise (as it looks Adiscon's Windows syslog servers are currently the only ones who can talk to Cisco's BEEP syslog implementation and I think I will be a bit hard to get a release for that code - especially as liblogging comes under a BSD license).

If you have anything new, please post. I'll do the same.

Rainer

Quick update: I got confirmation that the problem exists in IOS. I am in discussion with Cisco on how to proceed from here. It would probably helpful if you opened a Cisco TAC case. I am willing to develop a work-around. I may go for what you suggested, even though there will remain a Window of exposure where the solution does not work. But before I can make a decision I need to wait for additional feedback from Cisco development.

Rainer

Rainer,

Thank you for your effort so far. At the moment I continue with my project via UDP. The TAC case will take some time. I hope I have time at the end of next week to create it.

What's about RELP and vendor support? I didn't find a single word about RELP especially on the Cisco web site. If you need Cisco syslog messages,I can setup a router for you.

Cheers,
Thomas

Hi Thomas,

t.reisinger wrote:Thank you for your effort so far. At the moment I continue with my project via UDP. The TAC case will take some time. I hope I have time at the end of next week to create it.

As I said I am also in discussion with Cisco. I hope to get back from them some time this week. I'll then see which work-around to create. When I do this exactly depends on a number of factors and is mostly driven by some priorities (aka "paid work first" ).

t.reisinger wrote:What's about RELP and vendor support? I didn't find a single word about RELP especially on the Cisco web site. If you need Cisco syslog messages,I can setup a router for you.

I think there is no RELP vendor support somewhere at this stage. It's a protocol that I developed, but it has not yet reached enough momentum to draw in any vendors (except that Adiscon's Windows product support it now). So it is primarily for reliable rsyslog-to-rsyslog transport at this time.

Rainer