MonitorWare Knowledge Base

[radas]

Hello,

i have problem with logs over tcp connect, when is server for remote logs down.
How to say. For example: I send 20 messages from SERVER1 to SERVER2.
In SERVER1 is everything ok, but in SERVER2 is something bad, because SERVER2 had only 19 messages. One message missed.
It's this ok? I hope that no . Debug mode said:

Code: Select all

5123.249949705:main queue:Reg/w0: Called action, logging to builtin-fwd5123.249977335:main queue:Reg/w0: action 2 queue: entry added, size now 1 entries
5123.250001665:main queue:Reg/w0: action 2 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
5123.250031210:main queue:Reg/w0: Called action, logging to builtin-file (/var/log/messages)
5123.250168858:action 2 queue:Reg/w0: action 2 queue: entry deleted, state 0, size now 0 entries
5123.250199695:action 2 queue:Reg/w0:  192.168.0.30:514/tcp
5123.250246624:action 2 queue:Reg/w0: TCP sent 155 bytes, requested 155
5123.250263140:action 2 queue:Reg/w0: action 2 queue:Reg/w0: worker IDLE, waiting for work.
5123.250889209:main queue:Reg/w0: main queue: entry deleted, state 0, size now 0 entries

why was first entry deleted?

[rgerhards]

The message was deleted *from the queue*, which is good to happen (else we would have a really big memory leak ). Debug output is probably a bit verbose at this point in time. But to really track it down, it would be useful to get the full debug log of all 20 messages - or is always a specific one missing (e.g. first, last)?

Rainer

[radas]

Only first message missing.

[rgerhards]

Aha, that's interesting. Can you please let me know the version of rsyslog that you run on both the client (sender) and server. Also, the debug log up until the second message would be useful.

[radas]

We have 3.12.1 version on both machine. Ok, i will send this debug message tomorrow.

[rgerhards]

Thanks for the bug report, I will look into that when I am done with what I am currently implementing (hopefully later today or early tomorrow). In the mean time, debug logs would be appreciated.

Rainber

[radas]

Ok, i simulated my problem with up/down rsyslog on server.
My steps were:

Start rsyslog with debug mode.
Stop rsyslog on server.
Send 4 messages from client to server.
Start rsyslog on server.
On server is everything ok now.He has every message.
Now, I stopped rsyslog on server again.
Send 4 messages.
But i have only 7 messages on server now. One message missing

My debug file:

[code]
Starting system logger (rsyslog):
9060.803710283:main thread: Compatibility Mode: 0
9060.803746489:main thread: Writing pidfile /var/run/rsyslogd.pid.
9060.804482111:main thread: caller requested object 'errmsg', found at index 0
9060.804525964:main thread: module of type 1 being loaded.
9060.804543387:main thread: caller requested object 'errmsg', found at index 0
9060.804551969:main thread: module of type 1 being loaded.
9060.804580173:main thread: caller requested object 'errmsg', found at index 0
9060.804588228:main thread: module of type 1 being loaded.
9060.804602125:main thread: module of type 1 being loaded.
9060.804614138:main thread: caller requested object 'errmsg', found at index 0
9060.804621611:main thread: module of type 1 being loaded.
9060.804849553:main thread: Starting.
9060.804864318:main thread: rsyslog 3.12.1.
9060.804870662:main thread: Called init.
9060.804875557:main thread: Unloading non-static modules.
9060.804881920:main thread: Clearing templates.
9060.804952528:main thread: cfline: '$ModLoad imudp.so # provides UDP syslog reception'
9060.804969722:main thread: Requested to load module 'imudp.so'
9060.804989105:main thread: loading module '/usr/local/lib/rsyslog/imudp.so'
9060.805133609:main thread: caller requested object 'errmsg', found at index 0
9060.805151601:main thread: module of type 0 being loaded.
9060.805162810:main thread: cfline: '$ModLoad imtcp.so # provides TCP syslog reception and GSS-API (if compiled to support it)'
9060.805172403:main thread: Requested to load module 'imtcp.so'
9060.805180567:main thread: loading module '/usr/local/lib/rsyslog/imtcp.so'
9060.805258803:main thread: caller requested object 'tcps_sess', not found (iRet -3003)
9060.805268345:main thread: Requested to load module 'tcpsrv'
9060.805276343:main thread: loading module '/usr/local/lib/rsyslog/tcpsrv.so'
9060.805386416:main thread: caller requested object 'errmsg', found at index 0
9060.805397078:main thread: object 'tcps_sess' successfully registered with index 18, qIF 0x121d00
9060.805412160:main thread: caller requested object 'tcps_sess', found at index 18
9060.805420986:main thread: caller requested object 'conf', found at index 17
9060.805427840:main thread: object 'tcpsrv' successfully registered with index 19, qIF 0x122530
9060.805434442:main thread: caller requested object 'errmsg', found at index 0
9060.805441332:main thread: module of type 2 being loaded.
9060.805450038:main thread: caller requested object 'tcps_sess', found at index 18
9060.805458238:main thread: caller requested object 'tcpsrv', found at index 19
9060.805472262:main thread: module of type 0 being loaded.
9060.805483402:main thread: cfline: '$ModLoad imuxsock.so # provides support for local system logging (e.g. via logger command)'
9060.805492717:main thread: Requested to load module 'imuxsock.so'
9060.805501240:main thread: loading module '/usr/local/lib/rsyslog/imuxsock.so'
9060.805606690:main thread: caller requested object 'errmsg', found at index 0
9060.805630496:main thread: module of type 0 being loaded.
9060.805641550:main thread: cfline: '$ModLoad imklog.so # provides kernel logging support (previously done by rklogd)'
9060.805650538:main thread: Requested to load module 'imklog.so'
9060.805658888:main thread: loading module '/usr/local/lib/rsyslog/imklog.so'
9060.805799192:main thread: module of type 0 being loaded.
9060.805817983:main thread: cfline: '$EscapeControlCharactersOnReceive off'
9060.805830127:main thread: cfline: '$template DStatsFmt,"%msg%\n"'
9060.805844689:main thread: cfline: '$template DStatsFile,"/pub/StatisticalModule/dstats/pending/%$YEAR%-%$MONTH%-%$DAY%_%$HOUR%:%$MINUTE%.dstats"'
9060.805865209:main thread: cfline: '$umask 0000'
9060.805877669:main thread: umask set to 0000.
9060.805890712:main thread: cfline: '$DirCreateMode 0755'
9060.805898751:main thread: cfline: '$FileCreateMode 0664'
9060.805906769:main thread: cfline: '$FileGroup users'
9060.806064781:main thread: gid 100 obtained for group 'users'
9060.806079497:main thread: cfline: '$FileOwner bill'
9060.806207629:main thread: uid 500 obtained for user 'bill'
9060.806221233:main thread: cfline: ':programname,isequal,"showit" ?DStatsFile;DStatsFmt'
9060.806229793:main thread: - property-based filter
9060.806254208:main thread: tried selector action for builtin-file: 0
9060.806262691:main thread: Module builtin-file processed this config line.
9060.806272345:main thread: template: 'DStatsFmt' assigned
9060.806278665:main thread: template: 'DStatsFile' assigned

9060.806291964:main thread: action 1 queue: save on shutdown 1, max disk space allowed 0
9060.806307983:main thread: action 1 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.806317085:main thread: Action 0x8e94208: queue 0x8e94268 created
9060.806326563:main thread: cfline: '$WorkDirectory /pub/StatisticalModule/dstats/rsyslog-queue # default location for work (spool) files'
9060.806338715:main thread: cfline: '$ActionQueueType LinkedList # use asynchronous processing'
9060.806350302:main thread: action queue type set to LINKEDLIST
9060.806358840:main thread: cfline: '$ActionQueueFileName dstats # set file name, also enables disk mode'
9060.806370227:main thread: cfline: '$ActionQueueMaxFileSize 100m'
9060.806381620:main thread: cfline: '$ActionQueueSaveOnShutdown on'
9060.806396849:main thread: cfline: '$ActionQueueDiscardSeverity 6 # do not discard NOTICE messages!'
9060.806407590:main thread: cfline: '$ActionResumeInterval 1'
9060.806416628:main thread: cfline: '$ActionResumeRetryCount -1 # infinite retries on insert failure'
9060.806445294:main thread: cfline: '& @@192.168.0.30'
9060.806451924:main thread: tried selector action for builtin-file: -2001
9060.806537443:main thread: tried selector action for builtin-fwd: 0
9060.806545393:main thread: Module builtin-fwd processed this config line.
9060.806553045:main thread: template: ' StdFwdFmt' assigned
9060.806584463:main thread: action 2 queue: save on shutdown 1, max disk space allowed 0
9060.806593453:main thread: action 2 queue: is disk-assisted, disk will be used on demand
9060.806600262:main thread: action 2 queue: type 1, enq-only 0, disk assisted 1, maxFileSz 104857600, qsize 0, child 0 starting
9060.806610754:main thread: action 2 queue:Reg: finalizing construction of worker thread pool
9060.806618965:main thread: action 2 queue:Reg/w0: finalizing construction of worker instance data
9060.806655580:main thread: action 2 queue: no .qi file found
9060.806662480:main thread: action 2 queue: error -2040 trying to access on-disk queue files, starting without them. Some data may be lost
9060.806668865:main thread: action 2 queue: queue starts up without (loading) any DA disk state (this is normal for the DA queue itself!)
9060.806677844:main thread: action 2 queue:Reg: high activity - starting 1 additional worker thread(s).
9060.806684719:main thread: action 2 queue:Reg/w0: receiving command 2
9060.806757187:main thread: action 2 queue:Reg: started with state 0, num workers now 1
9060.806783457:b7febb90: action 2 queue:Reg/w0: receiving command 4
9060.806815072:action 2 queue:Reg/w0: action 2 queue:Reg/w0: worker IDLE, waiting for work.
9060.806835969:main thread: Action 0x8e94558: queue 0x8e945c8 created
9060.806849030:main thread: cfline: '& ~'
9060.806856868:main thread: tried selector action for builtin-file: -2001
9060.806865438:main thread: tried selector action for builtin-fwd: -2001
9060.806873868:main thread: tried selector action for builtin-shell: -2001
9060.806880848:main thread: discard
9060.806886375:main thread: tried selector action for builtin-discard: 0
9060.806893117:main thread: Module builtin-discard processed this config line.
9060.806900773:main thread: module is incompatible with RepeatedMsgReduction - turned off
9060.806909674:main thread: action 3 queue: save on shutdown 1, max disk space allowed 0
9060.806918450:main thread: action 3 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.806927368:main thread: Action 0x8e959d8: queue 0x8e95a58 created
9060.806935303:main thread: module is incompatible with RepeatedMsgReduction - turned off
9060.806944470:main thread: cfline: '$DirCreateMode 0700'
9060.806961273:main thread: cfline: '$FileCreateMode 0600'
9060.806970798:main thread: cfline: '$FileGroup root'
9060.807026660:main thread: gid 0 obtained for group 'root'
9060.807036439:main thread: cfline: '$FileOwner root'
9060.807073880:main thread: uid 0 obtained for user 'root'
9060.807086523:main thread: cfline: '*.info;mail.none;authpriv.none;cron.none /var/log/messages'
9060.807095399:main thread: selector line successfully processed
9060.807102516:main thread: - traditional PRI filter
9060.807110081:main thread: symbolic name: info ==> 6
9060.807135703:main thread: symbolic name: none ==> 16
9060.807145743:main thread: symbolic name: mail ==> 16
9060.807155222:main thread: symbolic name: none ==> 16
9060.807164519:main thread: symbolic name: authpriv ==> 80
9060.807175565:main thread: symbolic name: none ==> 16
9060.807184687:main thread: symbolic name: cron ==> 72
9060.807324357:main thread: tried selector action for builtin-file: 0
9060.807383012:main thread: Module builtin-file processed this config line.
9060.807419698:main thread: template: ' TradFmt' assigned
9060.807463310:main thread: action 4 queue: save on shutdown 1, max disk space allowed 0
9060.807513153:main thread: action 4 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.807552828:main thread: Action 0x8e95dd0: queue 0x8e95e60 created
9060.807620909:main thread: cfline: 'authpriv.* /var/log/secure'
9060.807656121:main thread: selector line successfully processed
9060.807686540:main thread: - traditional PRI filter
9060.807716367:main thread: symbolic name: * ==> 255
9060.807772070:main thread: symbolic name: authpriv ==> 80
9060.807866655:main thread: tried selector action for builtin-file: 0
9060.807878838:main thread: Module builtin-file processed this config line.
9060.807888425:main thread: template: ' TradFmt' assigned
9060.807898493:main thread: action 5 queue: save on shutdown 1, max disk space allowed 0
9060.807907567:main thread: action 5 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.807916783:main thread: Action 0x8e961e0: queue 0x8e96270 created
9060.807928262:main thread: cfline: 'mail.* -/var/log/maillog'
9060.807935686:main thread: selector line successfully processed
9060.807942861:main thread: - traditional PRI filter
9060.807949640:main thread: symbolic name: * ==> 255
9060.807959741:main thread: symbolic name: mail ==> 16
9060.808085408:main thread: tried selector action for builtin-file: 0
9060.808118081:main thread: Module builtin-file processed this config line.
9060.808152216:main thread: template: ' TradFmt' assigned
9060.808185776:main thread: action 6 queue: save on shutdown 1, max disk space allowed 0
9060.808218475:main thread: action 6 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.808250974:main thread: Action 0x8e965f0: queue 0x8e96680 created
9060.808302019:main thread: cfline: 'cron.* /var/log/cron'
9060.808347350:main thread: selector line successfully processed
9060.808377330:main thread: - traditional PRI filter
9060.808406491:main thread: symbolic name: * ==> 255
9060.808461228:main thread: symbolic name: cron ==> 72
9060.808535285:main thread: tried selector action for builtin-file: 0
9060.808582896:main thread: Module builtin-file processed this config line.
9060.808626590:main thread: template: ' TradFmt' assigned
9060.808658057:main thread: action 7 queue: save on shutdown 1, max disk space allowed 0
9060.808688623:main thread: action 7 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.808720323:main thread: Action 0x8e96a00: queue 0x8e96a90 created
9060.808752861:main thread: cfline: '*.emerg *'
9060.808784960:main thread: selector line successfully processed
9060.808814624:main thread: - traditional PRI filter
9060.808843545:main thread: symbolic name: emerg ==> 0
9060.808898721:main thread: tried selector action for builtin-file: -2001
9060.808960397:main thread: tried selector action for builtin-fwd: -2001
9060.808972955:main thread: tried selector action for builtin-shell: -2001
9060.808982403:main thread: tried selector action for builtin-discard: -2001
9060.808989813:main thread: write-alltried selector action for builtin-usrmsg: 0
9060.809002079:main thread: Module builtin-usrmsg processed this config line.
9060.809010318:main thread: template: ' WallFmt' assigned
9060.809025559:main thread: action 8 queue: save on shutdown 1, max disk space allowed 0
9060.809034586:main thread: action 8 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.809043674:main thread: Action 0x8e96db0: queue 0x8e96e40 created
9060.809054616:main thread: cfline: 'uucp,news.crit /var/log/spooler'
9060.809062293:main thread: selector line successfully processed
9060.809069850:main thread: - traditional PRI filter
9060.809076842:main thread: symbolic name: crit ==> 2
9060.809100309:main thread: symbolic name: uucp ==> 64
9060.809111319:main thread: symbolic name: news ==> 56
9060.809196896:main thread: tried selector action for builtin-file: 0
9060.809227050:main thread: Module builtin-file processed this config line.
9060.809257719:main thread: template: ' TradFmt' assigned
9060.809288604:main thread: action 9 queue: save on shutdown 1, max disk space allowed 0
9060.809319218:main thread: action 9 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.809350679:main thread: Action 0x8e971c0: queue 0x8e97250 created
9060.809383054:main thread: cfline: 'local7.* /var/log/boot.log'
9060.809415306:main thread: selector line successfully processed
9060.809444592:main thread: - traditional PRI filter
9060.809472822:main thread: symbolic name: * ==> 255
9060.809526026:main thread: symbolic name: local7 ==> 184
9060.809600134:main thread: tried selector action for builtin-file: 0
9060.809638215:main thread: Module builtin-file processed this config line.
9060.809682416:main thread: template: ' TradFmt' assigned
9060.809724740:main thread: action 10 queue: save on shutdown 1, max disk space allowed 0
9060.809769914:main thread: action 10 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.809802337:main thread: Action 0x8e975d0: queue 0x8e97660 created
9060.809841155:main thread: cfline: 'local4.debug /var/log/slapd.log'
9060.809893102:main thread: selector line successfully processed
9060.809925505:main thread: - traditional PRI filter
9060.809954386:main thread: symbolic name: debug ==> 7
9060.810008945:main thread: symbolic name: local4 ==> 160
9060.810076577:main thread: tried selector action for builtin-file: 0
9060.810090157:main thread: Module builtin-file processed this config line.
9060.810099132:main thread: template: ' TradFmt' assigned
9060.810108952:main thread: action 11 queue: save on shutdown 1, max disk space allowed 0
9060.810117697:main thread: action 11 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.810126542:main thread: Action 0x8e979e0: queue 0x8e97a70 created
9060.810137060:main thread: cfline: 'local6.* /var/log/smart'
9060.810144957:main thread: selector line successfully processed
9060.810152545:main thread: - traditional PRI filter
9060.810159886:main thread: symbolic name: * ==> 255
9060.810169555:main thread: symbolic name: local6 ==> 176
9060.810193059:main thread: tried selector action for builtin-file: 0
9060.810200478:main thread: Module builtin-file processed this config line.
9060.810208040:main thread: template: ' TradFmt' assigned
9060.810224121:main thread: action 12 queue: save on shutdown 1, max disk space allowed 0
9060.810233296:main thread: action 12 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.810243022:main thread: Action 0x8e97df0: queue 0x8e97e80 created
9060.810254856:main thread: selector line successfully processed
9060.810296449:main thread: main queue: is NOT disk-assisted
9060.810304669:main thread: main queue: type 0, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
9060.810316042:main thread: main queue:Reg: finalizing construction of worker thread pool
9060.810325437:main thread: main queue:Reg/w0: finalizing construction of worker instance data
9060.810332716:main thread: main queue: queue starts up without (loading) any DA disk state (this is normal for the DA queue itself!)
9060.810340479:main thread: main queue:Reg: high activity - starting 1 additional worker thread(s).
9060.810347805:main thread: main queue:Reg/w0: receiving command 2
9060.810406437:main thread: main queue:Reg: started with state 0, num workers now 1
9060.810428078:b75eab90: main queue:Reg/w0: receiving command 4
9060.810451616:main queue:Reg/w0: main queue:Reg/w0: worker IDLE, waiting for work.
9060.810469073:main thread: Main processing queue is initialized and running
9060.810478002:main thread: Allowed UDP Senders:
9060.810484449:main thread: No restrictions set.
9060.810490270:main thread: module 8e922a0 will not run, iRet 3
9060.810497718:main thread: Allowed TCP Senders:
9060.810503262:main thread: No restrictions set.
9060.810508772:main thread: module 8e92740 will not run, iRet 3
9060.810579529:main thread: Opened UNIX socket '/dev/log' (fd 3).
9060.810641628:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
9060.810801267:main thread: logmsg: flags 2, from 'dev', msg Mar 11 13:37:40 kernel: imklog 3.12.1, log source = /proc/kmsg started.
9060.810816754:main thread: Message has legacy syslog format.
9060.810837463:main thread: main queue: entry added, size now 1 entries
9060.810862742:main queue:Reg/w0: main queue: entry deleted, state 0, size now 0 entries
9060.810884030:main queue:Reg/w0: Filter: check for property 'programname' (value 'kernel') isequal 'showit': FALSE
9060.810899961:main queue:Reg/w0: Called action, logging to builtin-file (/var/log/messages)
9060.810999677:main thread: main queue: EnqueueMsg signaled condition (0)
9060.811009487:main thread: wtpAdviseMaxWorkers signals busy
9060.811037870:main thread: Searching for symbol map.
9060.811046030:main thread: Trying /boot/System.map-2.6.22.14-72.fc6.
9060.811083596:main thread: logmsg: flags 2, from 'dev', msg Mar 11 13:37:40 kernel: Inspecting /boot/System.map-2.6.22.14-72.fc6
9060.811092116:main thread: Message has legacy syslog format.
9060.811104853:main thread: main queue: entry added, size now 1 entries
9060.811113226:main thread: main queue: EnqueueMsg signaled condition (0)
9060.811120428:main thread: wtpAdviseMaxWorkers signals busy
9060.812656433:main queue:Reg/w0: main queue: entry deleted, state 0, size now 0 entries
9060.812782542:main queue:Reg/w0: Filter: check for property 'programname' (value 'kernel') isequal 'showit': FALSE
9060.812939064:main queue:Reg/w0: Called action, logging to builtin-file (/var/log/messages)
9060.813722552:main queue:Reg/w0: main queue:Reg/w0: worker IDLE, waiting for work.
9060.849490618:main thread: Version string = 132630, Major = 2, Minor = 6, Patch = 22.
9060.849519912:main thread: Comparing kernel 2.6.22.14-72.fc6 with symbol table 2.6.22.
9060.849568282:main thread: Found table with matching version number.
9060.849581036:main thread: End of search list encountered.
9060.908937714:main thread: Version string = 132630, Major = 2, Minor = 6, Patch = 22.
9060.908971514:main thread: Comparing kernel 2.6.22.14-72.fc6 with symbol table 2.6.22.
9060.912161682:main thread: logmsg: flags 2, from 'dev', msg Mar 11 13:37:40 kernel: Loaded 30533 symbols from /boot/System.map-2.6.22.14-72.fc6.
9060.912176164:main thread: Message has legacy syslog format.
9060.912196045:main thread: main queue: entry added, size now 1 entries
9060.912215018:main thread: main queue: EnqueueMsg signaled condition (0)
9060.912223958:main thread: wtpAdviseMaxWorkers signals busy
9060.912241555:main thread: logmsg: flags 2, from 'dev', msg Mar 11 13:37:40 kernel: Symbols match kernel version 2.6.22.
9060.912249336:main thread: Message has legacy syslog format.
9060.912260239:main thread: main queue: entry added, size now 2 entries
9060.912268955:main thread: main queue: EnqueueMsg signaled condition (0)
9060.912276175:main thread: wtpAdviseMaxWorkers signals busy
9060.912317764:main thread: dropped LF at very end of message (DropTrailingLF is set)
9060.912339221:main thread: logmsg: flags 2, from 'dev', msg Mar 11 13:37:40 kernel: No module symbols loaded - kernel modules not enabled.
9060.912347654:main thread: Message has legacy syslog format.
9060.912358838:main thread: main queue: entry added, size now 3 entries
9060.912376039:main thread: main queue: EnqueueMsg signaled condition (0)
9060.912384358:main thread: wtpAdviseMaxWorkers signals busy
9060.912483960:main thread:
Active selectors:
9060.912491813:main thread: Selector 1:
9060.912497696:main thread: PROPERTY-BASED Filter:
9060.912503422:main thread: Property.: 'programname'
9060.912508900:main thread: Operation: 'isequal'
9060.912517551:main thread: Value....: 'showit'
9060.912523138:main thread: Action...:
Actions:
9060.912532663:main thread: builtin-file: [dynamic]
template='DStatsFile' file cache size=10
create directories: yes
file owner 500, group 100
directory owner -1, group -1
fail if owner/group can not be set: yes

Instance data: 0x8e940b8
9060.912566258:main thread: RepeatedMsgReduction: 1
9060.912572699:main thread: Resume Interval: 30
9060.912578465:main thread: Suspended: 0
9060.912586927:main thread: Disabled: 0
9060.912592494:main thread: Exec only when previous is suspended: 0
9060.912598328:main thread:
9060.912603372:main thread:
9060.912608778:main thread: builtin-fwd: 192.168.0.30
Instance data: 0x8e94468
9060.912618827:main thread: RepeatedMsgReduction: 1
9060.912624442:main thread: Resume Interval: 1
9060.912629894:main thread: Suspended: 0
9060.912638216:main thread: Disabled: 0
9060.912643658:main thread: Exec only when previous is suspended: 0
9060.912649852:main thread:
9060.912654763:main thread:
9060.912660096:main thread: builtin-discard:
Instance data: 0x0
9060.912669422:main thread: RepeatedMsgReduction: 0
9060.912675108:main thread: Resume Interval: 1
9060.912680639:main thread: Suspended: 0
9060.912688994:main thread: Disabled: 0
9060.912694461:main thread: Exec only when previous is suspended: 0
9060.912700111:main thread:
9060.912705141:main thread:
9060.912710344:main thread:
9060.912715464:main thread: Selector 2:
9060.912721031:main thread: 7F 7F X 7F 7F 7F 7F 7F 7F X X 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 9060.912819815:main queue:Reg/w0: main queue: entry deleted, state 0, size now 2 entries

9060.912861148:main queue:Reg/w0: Filter: check for property 'programname' (value 'kernel') isequal 'showit': FALSE
9060.912882506:main queue:Reg/w0: Called action, logging to builtin-file (/var/log/messages)
9060.913048707:main thread: 7F
Actions:
9060.913230978:main thread: builtin-file: /var/log/messages
Instance data: 0x8e95c90
9060.913357992:main thread: RepeatedMsgReduction: 1
9060.913365582:main thread: Resume Interval: 1
9060.913371477:main thread: Suspended: 0
9060.913380169:main thread: Disabled: 0
9060.913385808:main thread: Exec only when previous is suspended: 0
9060.913391900:main thread:
9060.913397459:main thread:
9060.913403671:main thread:
9060.913409367:main thread: Selector 3:
9060.913415330:main thread: X X X X X X X X X X FF X X X X X X X 9060.913736198:main queue:Reg/w0: main queue: entry deleted, state 0, size now 1 entries

9060.913772790:main queue:Reg/w0: Filter: check for property 'programname' (value 'kernel') isequal 'showit': FALSE
9060.913803847:main queue:Reg/w0: Called action, logging to builtin-file (/var/log/messages)
9060.913932953:main thread: X X X X X X X
Actions:
9060.914206845:main thread: builtin-file: /var/log/secure
Instance data: 0x8e960b0
9060.914264577:main thread: RepeatedMsgReduction: 1
9060.914293171:main thread: Resume Interval: 1
9060.914322501:main thread: Suspended: 0
9060.914375121:main thread: Disabled: 0
9060.914428512:main thread: Exec only when previous is suspended: 0
9060.914472984:main thread:
9060.914501603:main thread:
9060.914529198:main thread:
9060.914565150:main thread: Selector 4:
9060.914592946:main thread: X X FF X X X X X X X X X X X X X X X X X X X X X X
Actions:
9060.915188009:main thread: builtin-file: /var/log/maillog
Instance data: 0x8e964c0
9060.915243384:main thread: RepeatedMsgReduction: 1
9060.915272258:main thread: Resume Interval: 1
9060.915300718:main thread: Suspended: 0
9060.915352392:main thread: Disabled: 0
9060.915380466:main thread: Exec only when previous is suspended: 0
9060.915409339:main thread:
9060.915436752:main thread:
9060.915464357:main thread:
9060.915491403:main thread: Selector 5:
9060.915519051:main thread: X X X X X X X X X FF X X X X X X X X X X X X X X X
Actions:
9060.916169198:main thread: builtin-file: /var/log/cron
Instance data: 0x8e968d0
9060.916224347:main thread: RepeatedMsgReduction: 1
9060.916264851:main thread: Resume Interval: 1
9060.916294055:main thread: Suspended: 0
9060.916347075:main thread: Disabled: 0
9060.916375342:main thread: Exec only when previous is suspended: 0
9060.916404486:main thread:
9060.916431873:main thread:
9060.916459264:main thread:
9060.916486470:main thread: Selector 6:
9060.916514383:main thread: 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1
Actions:
9060.917215861:main thread: builtin-usrmsg:
Instance data: 0x8e96ce0
9060.917271006:main thread: RepeatedMsgReduction: 1
9060.917299746:main thread: Resume Interval: 1
9060.917328789:main thread: Suspended: 0
9060.917381211:main thread: Disabled: 0
9060.917409492:main thread: Exec only when previous is suspended: 0
9060.917438860:main thread:
9060.917466077:main thread:
9060.917494149:main thread:
9060.917520381:main thread: Selector 7:
9060.917551805:main thread: X X X X X X X 7 7 X X X X X X X X X X X X X X X X
Actions:
9060.918192261:main thread: builtin-file: /var/log/spooler
Instance data: 0x8e97090
9060.918257853:main thread: RepeatedMsgReduction: 1
9060.918285584:main thread: Resume Interval: 1
9060.918314127:main thread: Suspended: 0
9060.918366605:main thread: Disabled: 0
9060.918394998:main thread: Exec only when previous is suspended: 0
9060.918423871:main thread:
9060.918451141:main thread:
9060.918478895:main thread:
9060.918515204:main thread: Selector 8:
9060.918546920:main thread: X X X X X X X X X X X X X X X X X X X X X X X FF X
Actions:
9060.918892321:main thread: builtin-file: /var/log/boot.log
Instance data: 0x8e974a0
9060.918904732:main thread: RepeatedMsgReduction: 1
9060.918910550:main thread: Resume Interval: 1
9060.918916000:main thread: Suspended: 0
9060.919082369:main thread: Disabled: 0
9060.919095839:main thread: Exec only when previous is suspended: 0
9060.919102488:main thread:
9060.919107833:main thread:
9060.919113105:main thread:
9060.919118134:main thread: Selector 9:
9060.919123639:main thread: X X X X X X X X X 9060.919283833:main queue:Reg/w0: main queue: entry deleted, state 0, size now 0 entries
X
9060.919396169:main queue:Reg/w0: Filter: check for property 'programname' (value 'kernel') isequal 'showit': FALSE
9060.919458328:main queue:Reg/w0: Called action, logging to builtin-file (/var/log/messages)
9060.919565305:main thread: X X X X X X X X X X FF X X X X
Actions:
9060.919716125:main thread: builtin-file: /var/log/slapd.log
Instance data: 0x8e978b0
9060.919790491:main thread: RepeatedMsgReduction: 1
9060.919796481:main thread: Resume Interval: 1
9060.919802105:main thread: Suspended: 0
9060.919810847:main thread: Disabled: 0
9060.919816289:main thread: Exec only when previous is suspended: 0
9060.919822082:main thread:
9060.919827167:main thread:
9060.919832463:main thread:
9060.919837553:main thread: Selector 10:
9060.919843317:main thread: X X X X X X X X X X X X X X X X X X X X X X FF X X
Actions:
9060.919939786:main thread: builtin-file: /var/log/smart
Instance data: 0x8e97cc0
9060.919950384:main thread: RepeatedMsgReduction: 1
9060.919956191:main thread: Resume Interval: 1
9060.919961674:main thread: Suspended: 0
9060.919980988:main thread: Disabled: 0
9060.919987493:main thread: Exec only when previous is suspended: 0
9060.919993490:main thread:
9060.919998756:main thread:
9060.920003888:main thread:
9060.920009395:main thread:
9060.920015070:main thread: Template: Name=' TradFmt'
9060.920023911:main thread: Entry(8e90428): type 2, (FIELD), value: 'TIMESTAMP'
9060.920036308:main thread: Entry(8e904a0): type 1, (CONSTANT), value: ' '
9060.920048410:main thread: Entry(8e90510): type 2, (FIELD), value: 'HOSTNAME'
9060.920060450:main thread: Entry(8e90560): type 1, (CONSTANT), value: ' '
9060.920072428:main thread: Entry(8e905f8): type 2, (FIELD), value: 'syslogtag'
9060.920084234:main thread: Entry(8e90648): type 2, (FIELD), value: 'msg' [drop last LF in msg]
9060.920099498:main thread: Entry(8e90698): type 1, (CONSTANT), value: '
'
9060.920111463:main thread: Template: Name=' WallFmt'
9060.920120284:main thread: Entry(8e90728): type 1, (CONSTANT), value: '
Message from syslogd@'
9060.920132504:main thread: Entry(8e90798): type 2, (FIELD), value: 'HOSTNAME'
9060.920144356:main thread: Entry(8e907e8): type 1, (CONSTANT), value: ' at '
9060.920156239:main thread: Entry(8e90880): type 2, (FIELD), value: 'timegenerated'
9060.920167942:main thread: Entry(8e908d0): type 1, (CONSTANT), value: ' ...
'
9060.920179728:main thread: Entry(8e90920): type 2, (FIELD), value: 'syslogtag'
9060.920191517:main thread: Entry(8e90970): type 2, (FIELD), value: 'msg'
9060.920203377:main thread: Entry(8e90a08): type 1, (CONSTANT), value: '

'
9060.920215238:main thread: Template: Name=' StdFwdFmt'
9060.920276253:main thread: Entry(8e90a78): type 1, (CONSTANT), value: '<'
9060.920288897:main thread: Entry(8e90ad8): type 2, (FIELD), value: 'PRI'
9060.920301397:main thread: Entry(8e90b28): type 1, (CONSTANT), value: '>'
9060.920313420:main thread: Entry(8e90bc0): type 2, (FIELD), value: 'TIMESTAMP'
9060.920325417:main thread: Entry(8e90c10): type 1, (CONSTANT), value: ' '
9060.920337374:main thread: Entry(8e90c60): type 2, (FIELD), value: 'HOSTNAME'
9060.920367993:main thread: Entry(8e90cb0): type 1, (CONSTANT), value: ' '
9060.920381697:main thread: Entry(8e90d48): type 2, (FIELD), value: 'syslogtag'
9060.920394090:main thread: Entry(8e90d98): type 2, (FIELD), value: 'msg'
9060.920405761:main thread: Template: Name=' StdUsrMsgFmt'
9060.920414269:main thread: Entry(8e90e30): type 1, (CONSTANT), value: ' '
9060.920426005:main thread: Entry(8e90e80): type 2, (FIELD), value: 'syslogtag'
9060.920438057:main thread: Entry(8e90ed0): type 2, (FIELD), value: 'msg'
9060.920449783:main thread: Entry(8e90f68): type 1, (CONSTANT), value: '

'
9060.920461555:main thread: Template: Name=' StdDBFmt' [SQL-Format (MySQL)]
9060.920486559:main thread: Entry(8e90fd8): type 1, (CONSTANT), value: 'insert into SystemEvents (Message, Facility, FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values (''
9060.920500187:main thread: Entry(8e91028): type 2, (FIELD), value: 'msg'
9060.920512030:main thread: Entry(8e91078): type 1, (CONSTANT), value: '', '
9060.920524039:main thread: Entry(8e911b0): type 2, (FIELD), value: 'syslogfacility'
9060.920535902:main thread: Entry(8e91200): type 1, (CONSTANT), value: ', ''
9060.920547579:main thread: Entry(8e91250): type 2, (FIELD), value: 'HOSTNAME'
9060.920559490:main thread: Entry(8e912a0): type 1, (CONSTANT), value: '', '
9060.920581218:main thread: Entry(8e91300): type 2, (FIELD), value: 'syslogpriority'
9060.920595003:main thread: Entry(8e91350): type 1, (CONSTANT), value: ', ''
9060.920607530:main thread: Entry(8e913f0): type 2, (FIELD), value: 'timereported' [Format as MySQL-Date]
9060.920622787:main thread: Entry(8e91440): type 1, (CONSTANT), value: '', ''
9060.920634832:main thread: Entry(8e91490): type 2, (FIELD), value: 'timegenerated' [Format as MySQL-Date]
9060.920649978:main thread: Entry(8e914e0): type 1, (CONSTANT), value: '', '
9060.920662001:main thread: Entry(8e91580): type 2, (FIELD), value: 'iut'
9060.920673968:main thread: Entry(8e915d0): type 1, (CONSTANT), value: ', ''
9060.920692990:main thread: Entry(8e91620): type 2, (FIELD), value: 'syslogtag'
9060.920707120:main thread: Entry(8e91670): type 1, (CONSTANT), value: '')'
9060.920730699:main thread: Template: Name=' StdPgSQLFmt' [SQL-Format (standard SQL)]
9060.920743520:main thread: Entry(8e91728): type 1, (CONSTANT), value: 'insert into SystemEvents (Message, Facility, FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values (''
9060.920756180:main thread: Entry(8e91778): type 2, (FIELD), value: 'msg'
9060.920769100:main thread: Entry(8e917c8): type 1, (CONSTANT), value: '', '
9060.920781588:main thread: Entry(8e91828): type 2, (FIELD), value: 'syslogfacility'
9060.920794622:main thread: Entry(8e91900): type 1, (CONSTANT), value: ', ''
9060.920807438:main thread: Entry(8e919a0): type 2, (FIELD), value: 'HOSTNAME'
9060.920820981:main thread: Entry(8e919f0): type 1, (CONSTANT), value: '', '
9060.920833507:main thread: Entry(8e91a40): type 2, (FIELD), value: 'syslogpriority'
9060.920846179:main thread: Entry(8e91a90): type 1, (CONSTANT), value: ', ''
9060.920858681:main thread: Entry(8e91b30): type 2, (FIELD), value: 'timereported' [Format as PgSQL-Date]
9060.920874888:main thread: Entry(8e91b80): type 1, (CONSTANT), value: '', ''
9060.920887273:main thread: Entry(8e91bd0): type 2, (FIELD), value: 'timegenerated' [Format as PgSQL-Date]
9060.920903360:main thread: Entry(8e91c20): type 1, (CONSTANT), value: '', '
9060.920915791:main thread: Entry(8e91cc0): type 2, (FIELD), value: 'iut'
9060.920938028:main thread: Entry(8e91d10): type 1, (CONSTANT), value: ', ''
9060.920950769:main thread: Entry(8e91d60): type 2, (FIELD), value: 'syslogtag'
9060.920963717:main thread: Entry(8e91db0): type 1, (CONSTANT), value: '')'
9060.921008750:main thread: Template: Name='DStatsFmt'
9060.921018484:main thread: Entry(8e93910): type 2, (FIELD), value: 'msg'
9060.921031525:main thread: Entry(8e93988): type 1, (CONSTANT), value: '
'
9060.921043897:main thread: Template: Name='DStatsFile'
9060.921052347:main thread: Entry(8e93a90): type 1, (CONSTANT), value: '/pub/StatisticalModule/dstats/pending/'
9060.921064663:main thread: Entry(8e93a28): type 2, (FIELD), value: '$YEAR'
9060.921077344:main thread: Entry(8e93b10): type 1, (CONSTANT), value: '-'
9060.921089953:main thread: Entry(8e93b70): type 2, (FIELD), value: '$MONTH'
9060.921102771:main thread: Entry(8e93bc0): type 1, (CONSTANT), value: '-'
9060.921115324:main thread: Entry(8e93c58): type 2, (FIELD), value: '$DAY'
9060.921128155:main thread: Entry(8e93ca8): type 1, (CONSTANT), value: '_'
9060.921140627:main thread: Entry(8e93cf8): type 2, (FIELD), value: '$HOUR'
9060.921153600:main thread: Entry(8e93d48): type 1, (CONSTANT), value: ':'
9060.921176553:main thread: Entry(8e93de0): type 2, (FIELD), value: '$MINUTE'
9060.921189833:main thread: Entry(8e93e30): type 1, (CONSTANT), value: '.dstats'
9060.921203159:main thread: Loaded Module: Name='builtin-file', IFVersion=2, type=output module.
9060.921234664:main thread: Entry points:
9060.921240997:main thread: queryEtryPt: 0x806f860
9060.921246861:main thread: doAction: 0x80705c0
9060.921252433:main thread: parseSelectorAct: 0x806fd30
9060.921258165:main thread: dbgPrintInstInfo: 0x80703d0
9060.921273622:main thread: freeInstance: 0x806fcc0
9060.921280047:main thread:
9060.921285856:main thread: Loaded Module: Name='builtin-fwd', IFVersion=2, type=output module.
9060.921301532:main thread: Entry points:
9060.921307000:main thread: queryEtryPt: 0x806e350
9060.921312656:main thread: doAction: 0x806ec20
9060.921318440:main thread: parseSelectorAct: 0x806e6f0
9060.921324037:main thread: dbgPrintInstInfo: 0x806ec00
9060.921329637:main thread: freeInstance: 0x806e680
9060.921335151:main thread:
9060.921340358:main thread: Loaded Module: Name='builtin-shell', IFVersion=2, type=output module.
9060.921355341:main thread: Entry points:
9060.921360597:main thread: queryEtryPt: 0x806d4b0
9060.921366226:main thread: doAction: 0x806d830
9060.921372493:main thread: parseSelectorAct: 0x806d670
9060.921378074:main thread: dbgPrintInstInfo: 0x806d810
9060.921383652:main thread: freeInstance: 0x806d650
9060.921389241:main thread:
9060.921394452:main thread: Loaded Module: Name='builtin-discard', IFVersion=2, type=output module.
9060.921409388:main thread: Entry points:
9060.921414514:main thread: queryEtryPt: 0x8070ce0
9060.921420070:main thread: doAction: 0x8070e80
9060.921425753:main thread: parseSelectorAct: 0x8070ec0
9060.921431293:main thread: dbgPrintInstInfo: 0x8070ba0
9060.921436968:main thread: freeInstance: 0x8070ea0
9060.921442564:main thread:
9060.921447766:main thread: Loaded Module: Name='builtin-usrmsg', IFVersion=2, type=output module.
9060.921462601:main thread: Entry points:
9060.921479437:main thread: queryEtryPt: 0x806da00
9060.921486905:main thread: doAction: 0x806e180
9060.921493271:main thread: parseSelectorAct: 0x806dc00
9060.921509770:main thread: dbgPrintInstInfo: 0x806dba0
9060.921516063:main thread: freeInstance: 0x806dbe0
9060.921521702:main thread:
9060.921527443:main thread: Loaded Module: Name='imudp.so', IFVersion=2, type=input module.
9060.921543117:main thread: Entry points:
9060.921548456:main thread: queryEtryPt: 0x11ca30
9060.921554212:main thread: doAction: 0x11cc90
9060.921559914:main thread: parseSelectorAct: 0x11cc40
9060.921565677:main thread: dbgPrintInstInfo: 0x0
9060.921571446:main thread: freeInstance: 0x0
9060.921577042:main thread:
9060.921582433:main thread: Loaded Module: Name='tcpsrv', IFVersion=2, type=library module.
9060.921597227:main thread: Entry points:
9060.921602468:main thread: queryEtryPt: 0x122840
9060.921608073:main thread: doAction: 0x0
9060.921613757:main thread: parseSelectorAct: 0x0
9060.921619307:main thread: dbgPrintInstInfo: 0x0
9060.921624911:main thread: freeInstance: 0x0
9060.921630475:main thread:
9060.921635629:main thread: Loaded Module: Name='imtcp.so', IFVersion=2, type=input module.
9060.921661431:main thread: Entry points:
9060.921667095:main thread: queryEtryPt: 0x11fa60
9060.921673794:main thread: doAction: 0x11fc10
9060.921679831:main thread: parseSelectorAct: 0x11fbe0
9060.921685390:main thread: dbgPrintInstInfo: 0x0
9060.921690848:main thread: freeInstance: 0x0
9060.921696353:main thread:
9060.921701520:main thread: Loaded Module: Name='imuxsock.so', IFVersion=2, type=input module.
9060.921716249:main thread: Entry points:
9060.921732264:main thread: queryEtryPt: 0x126b00
9060.921738640:main thread: doAction: 0x126fe0
9060.921744271:main thread: parseSelectorAct: 0x126dc0
9060.921749823:main thread: dbgPrintInstInfo: 0x0
9060.921755365:main thread: freeInstance: 0x0
9060.921761107:main thread:
9060.921766254:main thread: Loaded Module: Name='imklog.so', IFVersion=2, type=input module.
9060.921780965:main thread: Entry points:
9060.921786085:main thread: queryEtryPt: 0x12a100
9060.921791823:main thread: doAction: 0x12a940
9060.921807259:main thread: parseSelectorAct: 0x12aaf0
9060.921813564:main thread: dbgPrintInstInfo: 0x0
9060.921819360:main thread: freeInstance: 0x0
9060.921824865:main thread:
9060.921830893:main thread: Sytem Line Configuration Commands:
9060.921837609:main thread: Command 'dynafilecachesize':
9060.921843602:main thread: type : 6
9060.921849014:main thread: pData: 0x0
9060.921854512:main thread: Hdlr : 0x806fa00
9060.921860156:main thread: Owner: 0x806f4d0
9060.921865577:main thread:
9060.921870900:main thread: Command 'dirowner':
9060.921876388:main thread: type : 2
9060.921881867:main thread: pData: 0x8083c70
9060.921887428:main thread: Hdlr : 0x0
9060.921892872:main thread: Owner: 0x806f4d0
9060.921898378:main thread:
9060.921903490:main thread: Command 'dirgroup':
9060.921909042:main thread: type : 3
9060.921914530:main thread: pData: 0x8083c74
9060.921919979:main thread: Hdlr : 0x0
9060.921925455:main thread: Owner: 0x806f4d0
9060.921931039:main thread:
9060.921936301:main thread: Command 'fileowner':
9060.921942452:main thread: type : 2
9060.921947892:main thread: pData: 0x8083c68
9060.921953457:main thread: Hdlr : 0x0
9060.921958813:main thread: Owner: 0x806f4d0
9060.921964318:main thread:
9060.921992276:main thread: Command 'filegroup':
9060.921998529:main thread: type : 3
9060.922004004:main thread: pData: 0x8083c6c
9060.922009596:main thread: Hdlr : 0x0
9060.922015218:main thread: Owner: 0x806f4d0
9060.922020825:main thread:
9060.922025962:main thread: Command 'dircreatemode':
9060.922031671:main thread: type : 5
9060.922037154:main thread: pData: 0x8082888
9060.922042706:main thread: Hdlr : 0x0
9060.922048200:main thread: Owner: 0x806f4d0
9060.922053748:main thread:
9060.922058882:main thread: Command 'filecreatemode':
9060.922064541:main thread: type : 5
9060.922070006:main thread: pData: 0x808288c
9060.922075633:main thread: Hdlr : 0x0
9060.922081113:main thread: Owner: 0x806f4d0
9060.922086752:main thread:
9060.922092071:main thread: Command 'createdirs':
9060.922097624:main thread: type : 4
9060.922103024:main thread: pData: 0x8083c78
9060.922108613:main thread: Hdlr : 0x0
9060.922114180:main thread: Owner: 0x806f4d0
9060.922120176:main thread:
9060.922125303:main thread: Command 'failonchownfailure':
9060.922131053:main thread: type : 4
9060.922136379:main thread: pData: 0x8083c64
9060.922141805:main thread: Hdlr : 0x0
9060.922147367:main thread: Owner: 0x806f4d0
9060.922152840:main thread:
9060.922158041:main thread: Command 'resetconfigvariables':
9060.922163663:main thread: type : 1
9060.922169121:main thread: pData: 0x0
9060.922174548:main thread: Hdlr : 0x806f460
9060.922180054:main thread: Owner: 0x806f4d0
9060.922185588:main thread:
9060.922190797:main thread: type : 1
9060.922196327:main thread: pData: 0x0
9060.922201770:main thread: Hdlr : 0x804ff60
9060.922207287:main thread: Owner: 0x0
9060.922212844:main thread:
9060.922240707:main thread: type : 1
9060.922247953:main thread: pData: 0x0
9060.922253566:main thread: Hdlr : 0x11cb70
9060.922259173:main thread: Owner: 0x11c840
9060.922264611:main thread:
9060.922269727:main thread: type : 1
9060.922275379:main thread: pData: 0x0
9060.922280734:main thread: Hdlr : 0x11f760
9060.922286277:main thread: Owner: 0x11f720
9060.922291794:main thread:
9060.922297071:main thread: type : 1
9060.922302484:main thread: pData: 0x0
9060.922314468:main thread: Hdlr : 0x126ca0
9060.922321180:main thread: Owner: 0x126830
9060.922326725:main thread:
9060.922331792:main thread: type : 1
9060.922337295:main thread: pData: 0x0
9060.922342518:main thread: Hdlr : 0x129ea0
9060.922347849:main thread: Owner: 0x129e70
9060.922353227:main thread:
9060.922358324:main thread: Command 'workdirectory':
9060.922363861:main thread: type : 11
9060.922369302:main thread: pData: 0x8082ad4
9060.922374689:main thread: Hdlr : 0x0
9060.922379889:main thread: Owner: 0x0
9060.922385163:main thread:
9060.922390080:main thread: Command 'actionresumeretrycount':
9060.922395454:main thread: type : 6
9060.922400762:main thread: pData: 0x8083cb0
9060.922406152:main thread: Hdlr : 0x0
9060.922411520:main thread: Owner: 0x0
9060.922416908:main thread:
9060.922421908:main thread: Command 'mainmsgqueuefilename':
9060.922427473:main thread: type : 11
9060.922432814:main thread: pData: 0x8082af8
9060.922438199:main thread: Hdlr : 0x0
9060.922443516:main thread: Owner: 0x0
9060.922448931:main thread:
9060.922454073:main thread: Command 'mainmsgqueuesize':
9060.922459520:main thread: type : 6
9060.922464812:main thread: pData: 0x80818fc
9060.922480935:main thread: Hdlr : 0x0
9060.922487155:main thread: Owner: 0x0
9060.922492635:main thread:
9060.922497851:main thread: Command 'mainmsgqueuehighwatermark':
9060.922503669:main thread: type : 6
9060.922508913:main thread: pData: 0x8081900
9060.922514349:main thread: Hdlr : 0x0
9060.922529695:main thread: Owner: 0x0
9060.922535854:main thread:
9060.922541765:main thread: Command 'mainmsgqueuelowwatermark':
9060.922548171:main thread: type : 6
9060.922553650:main thread: pData: 0x8081904
9060.922559166:main thread: Hdlr : 0x0
9060.922564651:main thread: Owner: 0x0
9060.922570048:main thread:
9060.922575389:main thread: Command 'mainmsgqueuediscardmark':
9060.922581220:main thread: type : 6
9060.922586661:main thread: pData: 0x8081908
9060.922592210:main thread: Hdlr : 0x0
9060.922597772:main thread: Owner: 0x0
9060.922603324:main thread:
9060.922608503:main thread: Command 'mainmsgqueuediscardseverity':
9060.922614302:main thread: type : 10
9060.922619807:main thread: pData: 0x808190c
9060.922625426:main thread: Hdlr : 0x0
9060.922630825:main thread: Owner: 0x0
9060.922636265:main thread:
9060.922641411:main thread: Command 'mainmsgqueuecheckpointinterval':
9060.922647078:main thread: type : 6
9060.922652523:main thread: pData: 0x8082afc
9060.922658141:main thread: Hdlr : 0x0
9060.922663618:main thread: Owner: 0x0
9060.922668986:main thread:
9060.922674218:main thread: Command 'mainmsgqueuetype':
9060.922679703:main thread: type : 11
9060.922685314:main thread: pData: 0x0
9060.922690867:main thread: Hdlr : 0x8050120
9060.922696397:main thread: Owner: 0x0
9060.922701847:main thread:
9060.922706949:main thread: Command 'mainmsgqueueworkerthreads':
9060.922712550:main thread: type : 6
9060.922730050:main thread: pData: 0x8081910
9060.922736958:main thread: Hdlr : 0x0
9060.922742515:main thread: Owner: 0x0
9060.922747862:main thread:
9060.922752954:main thread: Command 'mainmsgqueuetimeoutshutdown':
9060.922758591:main thread: type : 6
9060.922764008:main thread: pData: 0x8082b00
9060.922769458:main thread: Hdlr : 0x0
9060.922775607:main thread: Owner: 0x0
9060.922781023:main thread:
9060.922786148:main thread: Command 'mainmsgqueuetimeoutactioncompletion':
9060.922791857:main thread: type : 6
9060.922797200:main thread: pData: 0x8081914
9060.922802806:main thread: Hdlr : 0x0
9060.922808352:main thread: Owner: 0x0
9060.922813652:main thread:
9060.922818735:main thread: Command 'mainmsgqueuetimeoutenqueue':
9060.922824351:main thread: type : 6
9060.922829742:main thread: pData: 0x8081918
9060.922835244:main thread: Hdlr : 0x0
9060.922840679:main thread: Owner: 0x0
9060.922846078:main thread:
9060.922851341:main thread: Command 'mainmsgqueueworketimeoutrthreadshutdown':
9060.922856879:main thread: type : 6
9060.922862175:main thread: pData: 0x808191c
9060.922867717:main thread: Hdlr : 0x0
9060.922873134:main thread: Owner: 0x0
9060.922878496:main thread:
9060.922883558:main thread: Command 'mainmsgqueuedequeueslowdown':
9060.922889040:main thread: type : 6
9060.922894511:main thread: pData: 0x8082b04
9060.922899878:main thread: Hdlr : 0x0
9060.922905227:main thread: Owner: 0x0
9060.922910685:main thread:
9060.922915767:main thread: Command 'mainmsgqueueworkerthreadminimummessages':
9060.922921363:main thread: type : 6
9060.922926777:main thread: pData: 0x8081920
9060.922932239:main thread: Hdlr : 0x0
9060.922937630:main thread: Owner: 0x0
9060.922942975:main thread:
9060.922947948:main thread: Command 'mainmsgqueuemaxfilesize':
9060.922953515:main thread: type : 7
9060.922958876:main thread: pData: 0x8081928
9060.922964361:main thread: Hdlr : 0x0
9060.922994941:main thread: Owner: 0x0
9060.923001490:main thread:
9060.923006833:main thread: Command 'mainmsgqueuemaxdiskspace':
9060.923012538:main thread: type : 7
9060.923017923:main thread: pData: 0x8082b08
9060.923023485:main thread: Hdlr : 0x0
9060.923028910:main thread: Owner: 0x0
9060.923034231:main thread:
9060.923039370:main thread: Command 'mainmsgqueuesaveonshutdown':
9060.923045179:main thread: type : 4
9060.923050592:main thread: pData: 0x8081930
9060.923056488:main thread: Hdlr : 0x0
9060.923061821:main thread: Owner: 0x0
9060.923067244:main thread:
9060.923072393:main thread: Command 'repeatedmsgreduction':
9060.923077895:main thread: type : 4
9060.923083325:main thread: pData: 0x8083ce4
9060.923088789:main thread: Hdlr : 0x0
9060.923094221:main thread: Owner: 0x0
9060.923099639:main thread:
9060.923104820:main thread: Command 'actionexeconlywhenpreviousissuspended':
9060.923110462:main thread: type : 4
9060.923115798:main thread: pData: 0x8083ce0
9060.923122214:main thread: Hdlr : 0x0
9060.923127835:main thread: Owner: 0x0
9060.923133164:main thread:
9060.923138009:main thread: Command 'actionresumeinterval':
9060.923143519:main thread: type : 6
9060.923148855:main thread: pData: 0x0
9060.923154136:main thread: Hdlr : 0x8050110
9060.923159499:main thread: Owner: 0x0
9060.923164768:main thread:
9060.923169646:main thread: Command 'controlcharacterescapeprefix':
9060.923175270:main thread: type : 8
9060.923181679:main thread: pData: 0x8081934
9060.923187422:main thread: Hdlr : 0x0
9060.923192857:main thread: Owner: 0x0
9060.923198321:main thread:
9060.923203462:main thread: Command 'escapecontrolcharactersonreceive':
9060.923209194:main thread: type : 4
9060.923214554:main thread: pData: 0x8081938
9060.923235174:main thread: Hdlr : 0x0
9060.923241265:main thread: Owner: 0x0
9060.923246730:main thread:
9060.923251848:main thread: Command 'dropmsgswithmaliciousdnsptrrecords':
9060.923257770:main thread: type : 4
9060.923263114:main thread: pData: 0x8082ad0
9060.923268609:main thread: Hdlr : 0x0
9060.923274032:main thread: Owner: 0x0
9060.923279414:main thread:
9060.923284529:main thread: Command 'droptrailinglfonreception':
9060.923290263:main thread: type : 4
9060.923295541:main thread: pData: 0x808193c
9060.923301057:main thread: Hdlr : 0x0
9060.923306531:main thread: Owner: 0x0
9060.923311934:main thread:
9060.923317039:main thread: Command 'template':
9060.923322556:main thread: type : 1
9060.923327817:main thread: pData: 0x0
9060.923333317:main thread: Hdlr : 0x806cf40
9060.923338807:main thread: Owner: 0x0
9060.923344231:main thread:
9060.923349379:main thread: Command 'outchannel':
9060.923354982:main thread: type : 1
9060.923360337:main thread: pData: 0x1
9060.923365857:main thread: Hdlr : 0x806cf40
9060.923371355:main thread: Owner: 0x0
9060.923376837:main thread:
9060.923381833:main thread: Command 'allowedsender':
9060.923387549:main thread: type : 1
9060.923404119:main thread: pData: 0x2
9060.923410197:main thread: Hdlr : 0x806cf40
9060.923415737:main thread: Owner: 0x0
9060.923421283:main thread:
9060.923426849:main thread: Command 'modload':
9060.923433022:main thread: type : 1
9060.923438617:main thread: pData: 0x0
9060.923444097:main thread: Hdlr : 0x806d020
9060.923449632:main thread: Own

[rgerhards]

I have just finished the unload process and will look soon into your bug report. Very useful, thanks. I already got an idea and it may be related to the TCP window. Does it only happen when the server is restarted? Will post more as soon as I know.

Rainer

[rgerhards]

damn, I know what's wrong... it's not actually rsyslog but the underlying protocol. I already doubted that. The problem is that plain TCP syslog is just relying on the TCP ack. However, the tcp stack acks a send operation even before it is ultimately completed. After restart of the server, rsyslog emits the message and gets an ack for that message from the stack. HOWEVER, shortly thereafter the IP stack notices that the connection is broken. But it can not tell rsyslog, because the API already completed. So the message is discarded by the stack. For the next message, the socket layer knows that the connection is broken and returns a proper error state to rsyslog, so it can act on it and re-establish the connection. I've written about this quite a while ago in my SELP spec, see section 2.4:

http://adiscon.org/specs/selp.txt

The ultimate solution to this is an application layer acknowledgement, which unfortunately is not supported by plain TCP syslog. I'll see if I can fiddle with the socket options, but that would come at a big performance hit. So the real solution is to use a reliable protocol. Rsyslog somewhat supports RFC 3195 - due to limited demand this is no longer properly maintained, but thankfully we started to clean up things just a week ago. I think I'll give this a priority, because it is the right solution to these kinds of problems.

Sorry I dont't have a better solution right now...

Rainer

[radas]

Thanks for all.

Radek

[rgerhards]

I have thought a bit more about this issue. I think I have at least a partial solution. It probably won't fix 100% of all cases, but it will, I think, cure the most probable ones. I think I can use a successful transmit as an indication that the *previous* message was transmitted correctly (in high traffic scenarios this will probably fail). So when I have a successful transmit, this is a proxy of an ACK for the previous message. More importantly, I can guess that when a send fails due to broken conection, not only the current message did not make it to the server but the previous one, too, was lost. So I can retransmit both messages in this case. In the worst case, this leads to duplication of messages, but that's quite unlikely.

I'll see if I can implement at least a rough fix tomorrow. In the mean time, feedback would much be appreciated.

Rainer

[rgerhards]

The fix I mentioned is now in 3.12.2, which has just been released. It worked in my lab. I'd appreciate if you could have a look at that version and tell us if it works for you, too.

Rainer

[vmix]

I'm seeing a very similar behavior. The sender is running 3.16.1 and the reciever is running 2.0.0.4. I have the sender send a message once a second, and then I stop the receiever's service for roughly 10 seconds and start it back up. The result is that I get all but one of the messages.

Receiver's log:

Code: Select all

May  7 13:45:33 sdltapi01 dflores: 2008.05.07.13.45.33.131665000
May  7 13:45:34 sdltapi01 dflores: 2008.05.07.13.45.34.137572000
May  7 13:45:35 sdltapi01 dflores: 2008.05.07.13.45.35.159391000
May  7 13:45:37 sdltapi01 dflores: 2008.05.07.13.45.37.191775000
May  7 13:45:38 sdltapi01 dflores: 2008.05.07.13.45.38.198475000
May  7 13:45:39 sdltapi01 dflores: 2008.05.07.13.45.39.219315000
May  7 13:45:40 sdltapi01 dflores: 2008.05.07.13.45.40.227605000


Sender's debug output:

Code: Select all

3136.181432000:imuxsock.c: Message from UNIX socket: #3
3136.181536000:imuxsock.c: logmsg: flags 6, from 'sdltapi01', msg May  7 13:45:36 dflores: 2008.05.07.13.45.36.177471000
3136.181545000:imuxsock.c: Message has legacy syslog format.
3136.181557000:imuxsock.c: main queue: entry added, size now 1 entries
3136.181567000:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
3136.181573000:imuxsock.c: wtpAdviseMaxWorkers signals busy
3136.181579000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
3136.183606000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 0 entries
3136.183620000:main queue:Reg/w0: main queue: queue size 0 below FullDlyMrk 100
3136.183625000:main queue:Reg/w0: main queue: queue size 0 below LightDlyMrk 3000
3136.183637000:main queue:Reg/w0: Called action, logging to builtin-fwd3136.183643000:main queue:Reg/w0: action 1 queue: entry added, size now 1 entries
3136.183651000:main queue:Reg/w0: action 1 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
3136.183714000:main queue:Reg/w0: main queue:Reg/w0: worker IDLE, waiting for work.
3136.183726000:action 1 queue:Reg/w0: action 1 queue: entry deleted, state 0, size now 0 entries
3136.183732000:action 1 queue:Reg/w0: action 1 queue: queue size 0 below FullDlyMrk 100
3136.183738000:action 1 queue:Reg/w0: action 1 queue: queue size 0 below LightDlyMrk 300
3136.183755000:action 1 queue:Reg/w0:  sdlogs01.vmix.com:514/tcp
3136.183769000:action 1 queue:Reg/w0: TCP sent 69 bytes, requested 69
3136.183810000:action 1 queue:Reg/w0: action 1 queue:Reg/w0: worker IDLE, waiting for work.
3137.192732000:imuxsock.c: Message from UNIX socket: #3
3137.192757000:imuxsock.c: logmsg: flags 6, from 'sdltapi01', msg May  7 13:45:37 dflores: 2008.05.07.13.45.37.191775000
3137.192764000:imuxsock.c: Message has legacy syslog format.
3137.192777000:imuxsock.c: main queue: entry added, size now 1 entries
3137.192786000:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
3137.192792000:imuxsock.c: wtpAdviseMaxWorkers signals busy
3137.192797000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
3137.193785000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 0 entries
3137.193797000:main queue:Reg/w0: main queue: queue size 0 below FullDlyMrk 100
3137.193803000:main queue:Reg/w0: main queue: queue size 0 below LightDlyMrk 3000
3137.193813000:main queue:Reg/w0: Called action, logging to builtin-fwd3137.193819000:main queue:Reg/w0: action 1 queue: entry added, size now 1 entries
3137.193826000:main queue:Reg/w0: action 1 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
3137.193885000:main queue:Reg/w0: main queue:Reg/w0: worker IDLE, waiting for work.
3137.193897000:action 1 queue:Reg/w0: action 1 queue: entry deleted, state 0, size now 0 entries
3137.193903000:action 1 queue:Reg/w0: action 1 queue: queue size 0 below FullDlyMrk 100
3137.193909000:action 1 queue:Reg/w0: action 1 queue: queue size 0 below LightDlyMrk 300
3137.193929000:action 1 queue:Reg/w0:  sdlogs01.vmix.com:514/tcp
3137.193941000:action 1 queue:Reg/w0: TCP sent -1 bytes, requested 69
3137.193946000:action 1 queue:Reg/w0: message not (tcp)sendcreate tcp connection failed, reason Connection refusedno working socket could be obtainederror forwarding via tcp, suspending
3137.199367000:action 1 queue:Reg/w0: Action requested to be suspended, done that.
3138.199516000:action 1 queue:Reg/w0: actionTryResume: iRet: -2007, next retry (if applicable): 1210193138 [now 1210193138]


The message lost, "May 7 13:45:36 dflores: 2008.05.07.13.45.36.177471000", doesn't appears to have erred, which may be why it is skipped. Please let me know if this is to be expected, and if you would like any more information. Thanks.

Dan.

[rgerhards]

Hi Dan,

that's expected behavior when the sender is v2. With v2, we could no queue on a per-action basis. So if the send fails, the message is intensionally discarded (we can't hold the syslogd to wait for the server come back on online, whenever this may be).

With v3. you put a queue in front of the send action. That will mostly solve the issue. However, due to protocol issues, plain tcp syslog is not really reliable. Read this to learn why:

http://rgerhards.blogspot.com/2008/04/o ... yslog.html

The ultimate cure is the RELP protocol. RELP was specifically designed to solve the reliability issues of tcp syslog.

Rainer

[rgerhards]

args, I've just noticed that the receiver is v3. Sorry. Please post your config. I guess you do not have a queue in front of the sed action. The sample configuration file contains the code necessary to do that:

http://git.adiscon.com/?p=rsyslog.git;a ... 7d;hb=HEAD

See lines 36 and below. An description on how this works (explained on a database use case) can be found here:

http://www.rsyslog.com/doc-rsyslog_high ... _rate.html

Rainer