MonitorWare Knowledge Base

Hello,

we are deploying rsyslog as part of ISO27000-certification of our IT infrastructure. The test environment (running rsyslog-3.21.4-1 on RHEL5.2 on 32-bit and 64-bit x86) works well and logs to both file and network under normal conditions. As part of acceptance testing, however, we must be able to survive dropping the network and still retain several hours worth of logs, resent when the network comes up. The ActionQueue looks like a good match for this, but practical testing shows that no spool file is created and local logging ceases when network logging fails. I would be very grateful for errors/misconfiguration in rsyslog.conf which follows:

$ModLoad immark # provides --MARK-- message capability
$ModLoad imuxsock # provides support for local system logging (e.g. via logger command)
$ModLoad imklog # kernel logging (formerly provided by rklogd)

$WorkDirectory /opt/rsyslog/spool # where to place spool files
$ActionQueueFileName rsyslogspool # unique name prefix for spool files
$ActionQueueMaxDiskSpace 1g # 1gb space limit (use as much as possible)
$ActionQueueSaveOnShutdown on # save messages to disk on shutdown
$ActionQueueType LinkedList # run asynchronously
$ActionResumeRetryCount -1 # infinite retries if host is down

*.* @@log.test.net:1514

*.info;mail.none;authpriv.none;cron.none -/var/log/messages
authpriv.* /var/log/secure
mail.* -/var/log/maillog
cron.* -/var/log/cron
*.emerg *
uucp,news.crit -/var/log/spooler
local7.* /var/log/boot.log

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

mhhh... I don't see any obviously wrong. Can you send me a debug log?

Rainer

follow-up question: you say multiple targets. The config file shows just one. Is this the full config?

Yes, multiple targets as in both network and local file - that is to say that each log message will both go to @@host:1514 and to some local file, e.g. /var/log/messages ...

debug log - I can absolutely get you one as soon as I figure out how. Thanks a lot for the help!

sorry, I thought of multiple receiving systems as multiple targets. My fault

And I also forgot the debug log link, which is:

http://www.rsyslog.com/doc-troubleshoot.html

Seems not to be my best day...

Rainer

Slightly reduced debug log follows, this is for normal operation with both log sources up:

4722.318647912:main thread: Writing pidfile /var/run/rsyslogd.pid.
4722.321172030:main thread: rsyslog 3.21.4 - called init()
4722.321180087:main thread: Unloading non-static modules.
4722.321185518:main thread: module lmnet NOT unloaded because it still has a refcount of 3
4722.321191620:main thread: Clearing templates.
4722.321235940:main thread: cfline: '$ModLoad immark # provides --MARK-- message capability'
4722.321252128:main thread: Requested to load module 'immark'
4722.321259304:main thread: loading module '/opt/rsyslog/usr/lib/rsyslog/immark.so'
4722.321325268:main thread: module of type 0 being loaded.
4722.321334142:main thread: cfline: '$ModLoad imuxsock # provides support for local system logging (e.g. via logger command)'ead: Requested to load module 'imuxsock'
4722.321346277:main thread: loading module '/opt/rsyslog/usr/lib/rsyslog/imuxsock.so'
4722.321395129:main thread: imuxsock version 3.21.4 initializing
4722.321418650:main thread: module of type 0 being loaded.
4722.321425915:main thread: cfline: '$ModLoad imklog # kernel logging (formerly provided by rklogd)'
4722.321432685:main thread: Requested to load module 'imklog'
4722.321437918:main thread: loading module '/opt/rsyslog/usr/lib/rsyslog/imklog.so'
4722.321564119:main thread: module of type 0 being loaded.
4722.321573520:main thread: cfline: '$WorkDirectory /opt/rsyslog/spool # where to place spool files'
4722.321581607:main thread: cfline: '$ActionQueueFileName rsyslogspool # unique name prefix for spool files'21590281:main thread: cfline: '$ActionQueueMaxDiskSpace 1g # 1gb space limit (use as much as possible)'98861:main thread: cfline: '$ActionQueueSaveOnShutdown on # save messages to disk on shutdown'722.321607564:main thread: cfline: '$ActionQueueType LinkedList # run asynchronously'
4722.321616956:main thread: action queue type set to LINKEDLIST
4722.321623205:main thread: cfline: '$ActionResumeRetryCount -1 # infinite retries if host is down'
4722.321630210:main thread: cfline: '*.* @@localhost:1514'
4722.321635803:main thread: - traditional PRI filter
4722.321640943:main thread: symbolic name: * ==> 255
4722.321652290:main thread: tried selector action for builtin-file: -2001
4722.321659498:main thread: caller requested object 'netstrms', not found (iRet -3003)
4722.321665104:main thread: Requested to load module 'lmnetstrms'
4722.321670638:main thread: loading module '/opt/rsyslog/usr/lib/rsyslog/lmnetstrms.so'
4722.321726313:main thread: module of type 2 being loaded.
4722.321733561:main thread: source file omfwd.c requested reference for module 'lmnetstrms', reference count now 1
4722.321744902:main thread: source file omfwd.c requested reference for module 'lmnetstrms', reference count now 2
4722.321755280:main thread: caller requested object 'tcpclt', not found (iRet -3003)
4722.321760630:main thread: Requested to load module 'lmtcpclt'
4722.321765779:main thread: loading module '/opt/rsyslog/usr/lib/rsyslog/lmtcpclt.so'
4722.321811521:main thread: module of type 2 being loaded.
4722.321818724:main thread: source file omfwd.c requested reference for module 'lmtcpclt', reference count now 1
4722.321825599:main thread: hostname 'localhost', port '1514'
4722.321831599:main thread: tried selector action for builtin-fwd: 0
4722.321836952:main thread: Module builtin-fwd processed this config line.
4722.321847243:main thread: template: 'RSYSLOG_TraditionalForwardFormat' assigned

4722.321858749:main thread: action 1 queue: save on shutdown 1, max disk space allowed 1073741824
4722.321869125:main thread: action 1 queue: is disk-assisted, disk will be used on demand
4722.321875013:main thread: action 1 queue: type 1, enq-only 0, disk assisted 1, maxFileSz 1048576, qsize 0, child 0 starting
4722.321883235:main thread: action 1 queue:Reg: finalizing construction of worker thread pool
4722.321890107:main thread: action 1 queue:Reg/w0: finalizing construction of worker instance data
4722.321899710:main thread: action 1 queue: no .qi file found
4722.321904798:main thread: action 1 queue: error -2040 trying to access on-disk queue files, starting without them. Some data may be lost
4722.321919513:main thread: action 1 queue: queue starts up without (loading) any DA disk state (this is normal for the DA queue itself!)
4722.321926472:main thread: action 1 queue:Reg: high activity - starting 1 additional worker thread(s).
4722.321932382:main thread: action 1 queue:Reg/w0: receiving command 2
4722.321976903:main thread: action 1 queue:Reg: started with state 0, num workers now 1
4722.321991886:main thread: Action 0x849b220: queue 0x849b2c8 created
4722.322000393:main thread: cfline: '*.info;mail.none;authpriv.none;cron.none -/var/log/messages'
4722.322005924:main thread: selector line successfully processed
4722.322011274:main thread: - traditional PRI filter
4722.322016414:main thread: symbolic name: info ==> 6
4722.322025673:main thread: symbolic name: none ==> 16
4722.322034374:main thread: symbolic name: mail ==> 16
4722.322043829:main thread: symbolic name: none ==> 16
4722.322052361:main thread: symbolic name: authpriv ==> 80
4722.322060911:main thread: symbolic name: none ==> 16
4722.322069305:main thread: symbolic name: cron ==> 72
4722.322087947:main thread: tried selector action for builtin-file: 0
4722.322094287:main thread: Module builtin-file processed this config line.
4722.322100662:main thread: template: 'RSYSLOG_FileFormat' assigned
4722.322107961:main thread: action 2 queue: save on shutdown 1, max disk space allowed 0
4722.322114587:main thread: action 2 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322120926:main thread: Action 0x849b8b8: queue 0x849b960 created
4722.322127681:main thread: cfline: 'authpriv.* /var/log/secure'
4722.322133046:main thread: selector line successfully processed
4722.322138567:main thread: - traditional PRI filter
4722.322143557:main thread: symbolic name: * ==> 255
4722.322152338:main thread: symbolic name: authpriv ==> 80
4722.322167225:main thread: tried selector action for builtin-file: 0
4722.322173209:main thread: Module builtin-file processed this config line.
4722.322179405:main thread: template: 'RSYSLOG_FileFormat' assigned
4722.322186081:main thread: action 3 queue: save on shutdown 1, max disk space allowed 0
4722.322201013:main thread: action 3 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322207833:main thread: Action 0x849bd08: queue 0x849bdb0 created
4722.322214389:main thread: cfline: 'mail.* -/var/log/maillog'
4722.322219761:main thread: selector line successfully processed
4722.322225213:main thread: - traditional PRI filter
4722.322232025:main thread: symbolic name: * ==> 255
4722.322240668:main thread: symbolic name: mail ==> 16
4722.322254799:main thread: tried selector action for builtin-file: 0
4722.322260838:main thread: Module builtin-file processed this config line.
4722.322267024:main thread: template: 'RSYSLOG_FileFormat' assigned
4722.322273722:main thread: action 4 queue: save on shutdown 1, max disk space allowed 0
4722.322279950:main thread: action 4 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322286202:main thread: Action 0x849c180: queue 0x849c228 created
4722.322292599:main thread: cfline: 'cron.* -/var/log/cron'
4722.322297880:main thread: selector line successfully processed
4722.322303200:main thread: - traditional PRI filter
4722.322308138:main thread: symbolic name: * ==> 255
4722.322316796:main thread: symbolic name: cron ==> 72
4722.322330823:main thread: tried selector action for builtin-file: 0
4722.322336811:main thread: Module builtin-file processed this config line.
4722.322342958:main thread: template: 'RSYSLOG_FileFormat' assigned
4722.322349553:main thread: action 5 queue: save on shutdown 1, max disk space allowed 0
4722.322355727:main thread: action 5 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322370051:main thread: Action 0x849c5f8: queue 0x849c6a0 created
4722.322377013:main thread: cfline: '*.emerg *'
4722.322382339:main thread: selector line successfully processed
4722.322387852:main thread: - traditional PRI filter
4722.322392748:main thread: symbolic name: emerg ==> 0
4722.322401884:main thread: tried selector action for builtin-file: -2001
4722.322408007:main thread: tried selector action for builtin-fwd: -2001
4722.322414290:main thread: tried selector action for builtin-shell: -2001
4722.322419853:main thread: tried selector action for builtin-discard: -2001
4722.322425844:main thread: write-alltried selector action for builtin-usrmsg: 0
4722.322434610:main thread: Module builtin-usrmsg processed this config line.
4722.322440854:main thread: template: ' WallFmt' assigned
4722.322447677:main thread: action 6 queue: save on shutdown 1, max disk space allowed 0
4722.322453924:main thread: action 6 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322460071:main thread: Action 0x849ca28: queue 0x849cad0 created
4722.322471550:main thread: cfline: 'uucp,news.crit -/var/log/spooler'
4722.322481026:main thread: selector line successfully processed
4722.322487390:main thread: - traditional PRI filter
4722.322492304:main thread: symbolic name: crit ==> 2
4722.322500911:main thread: symbolic name: uucp ==> 64
4722.322509581:main thread: symbolic name: news ==> 56
4722.322528838:main thread: tried selector action for builtin-file: 0
4722.322534879:main thread: Module builtin-file processed this config line.
4722.322540993:main thread: template: 'RSYSLOG_FileFormat' assigned
4722.322550849:main thread: action 7 queue: save on shutdown 1, max disk space allowed 0
4722.322557495:main thread: action 7 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322563681:main thread: Action 0x849ce90: queue 0x849cf38 created
4722.322570354:main thread: cfline: 'local7.* /var/log/boot.log'
4722.322575662:main thread: selector line successfully processed
4722.322581175:main thread: - traditional PRI filter
4722.322586071:main thread: symbolic name: * ==> 255
4722.322594723:main thread: symbolic name: local7 ==> 184
4722.322609219:main thread: tried selector action for builtin-file: 0
4722.322615143:main thread: Module builtin-file processed this config line.
4722.322621305:main thread: template: 'RSYSLOG_FileFormat' assigned
4722.322627786:main thread: action 8 queue: save on shutdown 1, max disk space allowed 0
4722.322633825:main thread: action 8 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322640002:main thread: Action 0x849d308: queue 0x849d3b0 created
4722.322647346:main thread: selector line successfully processed
4722.322669652:main thread: main queue: is NOT disk-assisted
4722.322676061:main thread: main queue: type 0, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
4722.322690725:main thread: main queue:Reg: finalizing construction of worker thread pool
4722.322697203:main thread: main queue:Reg/w0: finalizing construction of worker instance data
4722.322702568:main thread: main queue: queue starts up without (loading) any DA disk state (this is normal for the DA queue itself!)
4722.322708207:main thread: main queue:Reg: high activity - starting 1 additional worker thread(s).
4722.322713698:main thread: main queue:Reg/w0: receiving command 2
4722.322747381:main thread: main queue:Reg: started with state 0, num workers now 1
4722.322762427:b7f21b90: action 1 queue:Reg/w0: receiving command 4
4722.322779972:main thread: Main processing queue is initialized and running
4722.322826448:main thread: Opened UNIX socket '/dev/log' (fd 3).
4722.322909045:main thread: main queue: entry added, size now 1 entries
4722.322917078:main thread: main queue: EnqueueMsg signaled condition (0)
4722.322922961:main thread: wtpAdviseMaxWorkers signals busy
4722.322950442:main thread:
Active selectors:
4722.322956685:main thread: Selector 1:
4722.322961401:main thread: 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:
4722.323049066:main thread: builtin-fwd: localhost
Instance data: 0x849a8b8
4722.323059083:main thread: RepeatedMsgReduction: 0
4722.323063709:main thread: Resume Interval: 30
4722.323068292:main thread: Suspended: 0
4722.323076138:main thread: Disabled: 0
4722.323080637:main thread: Exec only when previous is suspended: 0
4722.323085627:main thread:
4722.323089987:main thread:
4722.323099015:main thread: Selector 2:
4722.323103560: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 7F
Actions:
4722.323189029:main thread: builtin-file: /var/log/messages
Instance data: 0x849b790
4722.323197645:main thread: RepeatedMsgReduction: 0
4722.323202171:main thread: Resume Interval: 30
4722.323206634:main thread: Suspended: 0
4722.323214246:main thread: Disabled: 0
4722.323218700:main thread: Exec only when previous is suspended: 0
4722.323223704:main thread:
4722.323230059:action 1 queue:Reg/w0: action 1 queue: entering rate limiter
4722.323272361:main thread:
4722.323277434:main thread:
4722.323281933:main thread: Selector 3:
4722.323286592:main thread: X X X X X X X X X X FF X X X X X X X X X X X X X X
Actions:
4722.323368579:main thread: builtin-file: /var/log/secure
Instance data: 0x849bbf0
4722.323376999:main thread: RepeatedMsgReduction: 0
4722.323381670:main thread: Resume Interval: 30
4722.323386241:main thread: Suspended: 0
4722.323393922:main thread: Disabled: 0
4722.323398424:main thread: Exec only when previous is suspended: 0
etc...
4722.324109894:main thread: Template: Name='RSYSLOG_DebugFormat'
4722.324118375:main thread: Entry(84957a0): type 1, (CONSTANT), value: 'Debug line with all properties:OST: ''
4722.324129677:main thread: Entry(8495738): type 2, (FIELD), value: 'fromhost'
4722.324141093:main thread: Entry(8495830): type 1, (CONSTANT), value: '', fromhost-ip: ''
4722.324152310:main thread: Entry(84958c8): type 2, (FIELD), value: 'fromhost-ip'
4722.324163495:main thread: Entry(8495928): type 1, (CONSTANT), value: '', HOSTNAME: ''
4722.324174598:main thread: Entry(84959a0): type 2, (FIELD), value: 'hostname'
4722.324185722:main thread: Entry(8495a00): type 1, (CONSTANT), value: '', PRI: '
4722.324196856:main thread: Entry(8495a98): type 2, (FIELD), value: 'pri'
4722.324207947:main thread: Entry(8495af8): type 1, (CONSTANT), value: ',
syslogtag ''
4722.324219065:main thread: Entry(8495b70): type 2, (FIELD), value: 'syslogtag'
4722.324232150:main thread: Entry(8495bd0): type 1, (CONSTANT), value: '', programname: ''
4722.324243410:main thread: Entry(8495c68): type 2, (FIELD), value: 'programname'
4722.324254552:main thread: Entry(8495cc8): type 1, (CONSTANT), value: '', APP-NAME: ''
4722.324265652:main thread: Entry(8495d40): type 2, (FIELD), value: 'app-name'
4722.324276756:main thread: Entry(8495da0): type 1, (CONSTANT), value: '', PROCID: ''
4722.324287841:main thread: Entry(8495e38): type 2, (FIELD), value: 'procid'
4722.324298911:main thread: Entry(8495e98): type 1, (CONSTANT), value: '', MSGID: ''
4722.324310005:main thread: Entry(8495f08): type 2, (FIELD), value: 'msgid'
4722.324321090:main thread: Entry(8495f68): type 1, (CONSTANT), value: '',
TIMESTAMP: ''
4722.324332166:main thread: Entry(8496000): type 2, (FIELD), value: 'timestamp'
4722.324343282:main thread: Entry(8496060): type 1, (CONSTANT), value: '', STRUCTURED-DATA: ''
4722.324354415:main thread: Entry(84960e0): type 2, (FIELD), value: 'structured-data'
4722.324365539:main thread: Entry(8496140): type 1, (CONSTANT), value: '',
msg: ''
4722.324376612:main thread: Entry(84961e0): type 2, (FIELD), value: 'msg'
4722.324387650:main thread: Entry(8496240): type 1, (CONSTANT), value: ''
escaped msg: ''
4722.324398714:main thread: Entry(84962b8): type 2, (FIELD), value: 'msg' [drop control-characters]
4722.324413056:main thread: Entry(8496318): type 1, (CONSTANT), value: ''
rawmsg: ''
4722.324424195:main thread: Entry(84963b0): type 2, (FIELD), value: 'rawmsg'
4722.324435340:main thread: Entry(8496410): type 1, (CONSTANT), value: ''

'
4722.324446450:main thread: Template: Name='RSYSLOG_SyslogProtocol23Format'
4722.324454555:main thread: Entry(84964c8): type 1, (CONSTANT), value: '<'
4722.324465673:main thread: Entry(8496538): type 2, (FIELD), value: 'pri'
4722.324476734:main thread: Entry(8496598): type 1, (CONSTANT), value: '>1 '
4722.324487726:main thread: Entry(8496630): type 2, (FIELD), value: 'timestamp' [Format as RFC3339-Date]
4722.324507268:main thread: Entry(8496690): type 1, (CONSTANT), value: ' '
4722.324518395:main thread: Entry(8496700): type 2, (FIELD), value: 'hostname'
4722.324529540:main thread: Entry(8496760): type 1, (CONSTANT), value: ' '
4722.324540617:main thread: Entry(84967f8): type 2, (FIELD), value: 'app-name'
4722.324551681:main thread: Entry(8496858): type 1, (CONSTANT), value: ' '
4722.324562745:main thread: Entry(84968c8): type 2, (FIELD), value: 'procid'
4722.324581391:main thread: Entry(8496928): type 1, (CONSTANT), value: ' '
4722.324592662:main thread: Entry(84969c0): type 2, (FIELD), value: 'msgid'
4722.324603723:main thread: Entry(8496a20): type 1, (CONSTANT), value: ' '
4722.324614754:main thread: Entry(8496a90): type 2, (FIELD), value: 'structured-data'
4722.324626279:main thread: Entry(8496af0): type 1, (CONSTANT), value: ' '
4722.324637337:main thread: Entry(8496b90): type 2, (FIELD), value: 'msg'
4722.324648350:main thread: Entry(8496bf0): type 1, (CONSTANT), value: '
'
4722.324659321:main thread: Template: Name='RSYSLOG_FileFormat'
4722.324666990:main thread: Entry(8496c98): type 2, (FIELD), value: 'timestamp' [Format as RFC3339-Date]
4722.324684657:main thread: Entry(8496cf8): type 1, (CONSTANT), value: ' '
4722.324695709:main thread: Entry(8496d90): type 2, (FIELD), value: 'hostname'
4722.324706788:main thread: Entry(8496df0): type 1, (CONSTANT), value: ' '
4722.324717819:main thread: Entry(8496e60): type 2, (FIELD), value: 'syslogtag'
4722.324728896:main thread: Entry(8496ec0): type 2, (FIELD), value: 'msg' [SP iff no first SP]
4722.324743150:main thread: Entry(8496f58): type 2, (FIELD), value: 'msg' [drop last LF in msg]
4722.324757454:main thread: Entry(8496fb8): type 1, (CONSTANT), value: '
'
4722.324768518:main thread: Template: Name='RSYSLOG_TraditionalFileFormat'
4722.324776586:main thread: Entry(8497048): type 2, (FIELD), value: 'timestamp'
4722.324787615:main thread: Entry(84970d0): type 1, (CONSTANT), value: ' '
4722.324798609:main thread: Entry(8497150): type 2, (FIELD), value: 'hostname'
4722.324809650:main thread: Entry(84971b0): type 1, (CONSTANT), value: ' '
4722.324820651:main thread: Entry(8497248): type 2, (FIELD), value: 'syslogtag'
4722.324831715:main thread: Entry(84972a8): type 2, (FIELD), value: 'msg' [SP iff no first SP]
...
4722.329205699:main thread:
4722.329227292:main thread: Main queue size 10000 messages.
4722.329232185:main thread: Main queue worker threads: 1, Perists every 0 updates.
4722.329237508:main thread: Main queue timeouts: shutdown: 0, action completion shutdown: 1000, enq: 2000
4722.329242576:main thread: Main queue watermarks: high: 8000, low: 2000, discard: 9800, discard-severity: 4
4722.329248115:main thread: Main queue save on shutdown 1, max disk space allowed 0
4722.329253508:main thread: Work Directory: '/opt/rsyslog/spool'.
4722.329295027:main thread: logmsg: flags 5, pri 46, from 'cadiz', msg [origin software="rsyslogd" swVersion="3.21.4" x-pid="27932" x-info="http://www.rsyslog.com"] restart
4722.329302519:main thread: Message has legacy syslog format.
4722.329311382:main thread: main queue: entry added, size now 2 entries
4722.329317899:main thread: main queue: EnqueueMsg signaled condition (0)
4722.329332502:b7520b90: main queue:Reg/w0: receiving command 4
4722.329345639:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3):
4722.329353873:action 1 queue:Reg/w0: action 1 queue:Reg/w0: worker IDLE, waiting for work.
4722.329365054:imuxsock.c: 3
4722.329369394:main queue:Reg/w0: 4722.329383898:main queue: entering rate limiter
main thread: wtpAdviseMaxWorkers signals busy
4722.329434756:main thread: (re)started.
4722.329438576:main queue:Reg/w0: main queue: entry deleted, state 0, size now 1 entries
4722.329445105:main thread: Debugging enabled, SIGUSR1 to turn off debugging.
4722.329498934:main thread: initialization completed, transitioning to regular run mode
4722.329510885:main queue:Reg/w0: Called action, logging to builtin-fwd
4722.329527510:main queue:Reg/w0: action 1 queue: entry added, size now 1 entries
4722.329538517:main queue:Reg/w0: action 1 queue: EnqueueMsg signaled condition (0)
4722.329550062:main queue:Reg/w0: 4722.329551954:action 1 queue:Reg/w0: action 1 queue: entering rate limiter
wtpAdviseMaxWorkers signals busy
4722.329585805:main queue:Reg/w0: Called action, logging to builtin-file
4722.329589146:action 1 queue:Reg/w0: action 1 queue: entry deleted, state 0, size now 0 entries
4722.329684348:action 1 queue:Reg/w0: localhost
4722.329697418:main queue:Reg/w0: (/var/log/messages)
4722.329715504:action 1 queue:Reg/w0: caller requested object 'nsd_ptcp', not found (iRet -3003)
4722.329746964:main queue:Reg/w0: main queue: entering rate limiter
4722.329763848:4722.329747539:action 1 queue:Reg/w0: Requested to load module 'lmnsd_ptcp'
main queue:Reg/w0: 4722.329788848:action 1 queue:Reg/w0: loading module '/opt/rsyslog/usr/lib/rsyslog/lmnsd_ptcp.so'
main queue: entry deleted, state 0, size now 0 entries
4722.329815406:main queue:Reg/w0: Called action, logging to builtin-fwd
4722.329824236:main queue:Reg/w0: action 1 queue: entry added, size now 1 entries
4722.329831983:main queue:Reg/w0: action 1 queue: EnqueueMsg signaled condition (0)
4722.329839549:main queue:Reg/w0: wtpAdviseMaxWorkers signals busy
4722.329847585:main queue:Reg/w0: Called action, logging to builtin-file
4722.329867076:main queue:Reg/w0: (/var/log/messages)
4722.329876594:action 1 queue:Reg/w0: source file nsd_ptcp.c requested reference for module 'lmnetstrms', reference count now 3
4722.329867076:main queue:Reg/w0: (/var/log/messages)
4722.329894503:action 1 queue:Reg/w0: module of type 2 being loaded.
4722.329906866:action 1 queue:Reg/w0: source file netstrms.c requested reference for module 'lmnsd_ptcp', reference count now 1
4722.329918340:main queue:Reg/w0: main queue:Reg/w0: worker IDLE, waiting for work.
4722.330273812:action 1 queue:Reg/w0: localhost:1514/tcp
4722.330299443:action 1 queue:Reg/w0: TCP sent 81 bytes, requested 81
4722.330312105:action 1 queue:Reg/w0: action 1 queue: entering rate limiter
4722.330329325:action 1 queue:Reg/w0: action 1 queue: entry deleted, state 0, size now 0 entries
4722.330342807:action 1 queue:Reg/w0: localhost
4722.330348226:action 1 queue:Reg/w0: localhost:1514/tcp
4722.330366691:action 1 queue:Reg/w0: TCP sent 138 bytes, requested 138
4722.330375638:action 1 queue:Reg/w0: action 1 queue: entering rate limiter
4722.330381870:action 1 queue:Reg/w0: action 1 queue:Reg/w0: worker IDLE, waiting for work.
4782.337511705:main queue:Reg/w0: main queue:Reg/w0: inactivity timeout, worker terminating...
4782.337533908:main queue:Reg/w0: main queue: entering rate limiter
4782.337542506:main queue:Reg/w0: main queue:Reg/w0: receiving command 1
4782.337549832:main queue:Reg/w0: main queue:Reg/w0: worker terminating
4782.337557116:main queue:Reg/w0: main queue:Reg: Worker thread 84a7458, terminated, num workers now 0
4782.337703783:main queue:Reg/w0: destructor for debug call stack 0x84abec8 called
4782.337795327:action 1 queue:Reg/w0: action 1 queue:Reg/w0: inactivity timeout, worker terminating...
4782.337819648:action 1 queue:Reg/w0: action 1 queue: entering rate limiter
4782.337830054:action 1 queue:Reg/w0: action 1 queue:Reg/w0: receiving command 1
4782.337837656:action 1 queue:Reg/w0: action 1 queue:Reg/w0: worker terminating
4782.337845087:action 1 queue:Reg/w0: action 1 queue:Reg: Worker thread 849b5f0, terminated, num workers now 0
4782.337703783:main queue:Reg/w0: destructor for debug call stack 0x84abec8 called
4782.337795327:action 1 queue:Reg/w0: action 1 queue:Reg/w0: inactivity timeout, worker terminating...
4782.337819648:action 1 queue:Reg/w0: action 1 queue: entering rate limiter
4782.337876418:action 1 queue:Reg/w0: destructor for debug call stack 0x84a7588 called
4956.853723366:imuxsock.c: Message from UNIX socket: #3
4956.853750559:imuxsock.c: logmsg: flags 4, pri 86, from 'cadiz', msg Nov 5 12:35:56 sshd[27948]: Accepted password for emilar from 192.168.231.9 port 56380 ssh2
4956.853758023:imuxsock.c: Message has legacy syslog format.
4956.853770735:imuxsock.c: main queue: entry added, size now 1 entries
4956.853777764:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
4956.853784013:imuxsock.c: main queue:Reg: high activity - starting 1 additional worker thread(s).
4956.853790635:imuxsock.c: waiting for worker main queue:Reg/w0 termination, current state 1
4956.853805973:imuxsock.c: main queue:Reg/w0: receiving command 0
4956.853812526:imuxsock.c: worker main queue:Reg/w0 has stopped
4956.853817617:imuxsock.c: main queue:Reg/w0: receiving command 2
4956.853833662:imuxsock.c: main queue:Reg: started with state 0, num workers now 1
4956.853853282:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
4956.853869892:b7520b90: main queue:Reg/w0: receiving command 4
4956.853880757:main queue:Reg/w0: main queue: entering rate limiter
4956.853888336:main queue:Reg/w0: main queue: entry deleted, state 0, size now 0 entries
4956.853899168:main queue:Reg/w0: Called action, logging to builtin-fwd
4956.853906133:main queue:Reg/w0: action 1 queue: entry added, size now 1 entries
4956.853911878:main queue:Reg/w0: action 1 queue: EnqueueMsg signaled condition (0)
4956.853917754:main queue:Reg/w0: action 1 queue:Reg: high activity - starting 1 additional worker thread(s).

mhhh... I don't see any failed remote end. Am I overlooking the obvious?

Rainer

No, nothing is visible to show that anything is wrong. Lemme try to explain it further:
After getting
2129.655475722:action 1 queue:Reg/w0: TCP sent 92 bytes, requested 92

rsyslog will discover that the sending didn't succeed over tcp:

2605.824959571:action 1 queue:Reg/w0: actionTryResume: iRet: -2007, next retry (if applicable): 122605
2605 [now 1226052605]
2635.822601228:action 1 queue:Reg/w0: localhost
2635.822620235:action 1 queue:Reg/w0: caller requested object 'nsd_ptcp', not found (iRet -3003)
2635.822629047:action 1 queue:Reg/w0: Requested to load module 'lmnsd_ptcp'
2635.822637528:action 1 queue:Reg/w0: loading module '/opt/rsyslog/usr/lib/rsyslog/lmnsd_ptcp.so'
2635.822723012:action 1 queue:Reg/w0: source file nsd_ptcp.c requested reference for module 'lmnetstrm
s', reference count now 3
2635.822734648:action 1 queue:Reg/w0: module of type 2 being loaded.
2635.822741499:action 1 queue:Reg/w0: source file netstrms.c requested reference for module 'lmnsd_ptc
p', reference count now 1
2635.822833999:action 1 queue:Reg/w0: file netstrms.c released module 'lmnsd_ptcp', reference count no
w 0
2635.822842180:action 1 queue:Reg/w0: module 'lmnsd_ptcp' has zero reference count, unloading...
2635.822847824:action 1 queue:Reg/w0: Unloading module lmnsd_ptcp
2635.822854486:action 1 queue:Reg/w0: file nsd_ptcp.c released module 'lmnetstrms', reference count no
w 2
2635.822875387:action 1 queue:Reg/w0: actionTryResume: iRet: -2007, next retry (if applicable): 122605
2665 [now 1226052635]
2661.584715636:main queue:Reg/w0: main queue:Reg/w0: inactivity timeout, worker terminating...

this builds up for a while

9865.411485097:action 1 queue:Reg/w0: actionTryResume: iRet: -2007, next retry (if applicable): 1226060015 [now 1226059865]
9895.409889514:action 1 queue:Reg/w0: actionTryResume: iRet: -2007, next retry (if applicable): 1226060015 [now 1226059895]
9925.408555077:action 1 queue:Reg/w0: actionTryResume: iRet: -2007, next retry (if applicable): 1226060015 [now 1226059925]

yet nothing is stored to disk:

$ ls -ltra /opt/rsyslog/spool/
totalt 8
drwxr-xr-x 6 root root 4096 18 sep 09.17 ..
drwxr-xr-x 2 root root 4096 18 sep 09.17 .

and upon restart with network up, the messages are not saved nor sent.

That nothing is saved on disk while it is running is a good sign - it should not, until the size of the main memory buffer is overrun. Things are kept in memory until it becomes necessary to write them out. A failure condition is not something that requires a write.

HOWEVER, the shutdown, with your parameters and a non-empty queue should require files to be written. So I would be interested in a debug log of the shutdown while the TCP target is in unavailable mode (and the queue holds data).

Rainer

I double-checked the other log you sent, and the queue params were correctly set:

Code: Select all

4722.321858749:main thread: action 1 queue: save on shutdown 1, max disk space allowed 1073741824
4722.321869125:main thread: action 1 queue: is disk-assisted, disk will be used on demand
4722.321875013:main thread: action 1 queue: type 1, enq-only 0, disk assisted 1, maxFileSz 1048576, qsize 0, child 0 starting

So, yes, It looks like I need the shutdown log.

Rainer