Just noticed, for the third time, some computers stop forwarding logs
(imfile>omfwd) to central rsyslog.
Restarting or stop/start the service doesn't fix the issue and messages
only resume after deleting state file
rm /var/spool/rsyslog/imfile-state:134766:1a75f838195c3b3c
As this seems to be an error-recurrent issue, could you provide some hints
on how to debug/diagnose what's going on?
service estatus warns: "Warning: journal has been rotated since unit was
started, output may be incomplete."
computer rsyslog config:
module(load="imfile")
template(name="json" type="list" option.json="on") {
constant(value="{")
constant(value="\"@source_timestamp\":\"")
property(name="timereported" dateFormat="rfc3339")
constant(value="\",\"source_message\":\"")
property(name="msg")
constant(value="\",\"source_hostname\":\"")
property(name="hostname")
constant(value="\",\"source_severity\":\"")
property(name="syslogseverity-text")
constant(value="\",\"source_facility\":\"")
property(name="syslogfacility-text")
constant(value="\",\"source_tag\":\"")
property(name="syslogtag")
constant(value="\",\"source_app\":\"")
property(name="programname")
constant(value="\",\"source_filename\":\"")
property(name="$.filename")
constant(value="\"}\n")
}
input(type="imfile" file="/var/log/mail.log" addMetadata="on" tag="mail"
ruleset="syslog")
ruleset(name="syslog") {
set $.filename = $!metadata!filename;
action(type="omfwd" target="central.rsyslog.com" port="514" protocol="udp"
template="json")
}
rsyslog -dn output:
1146.583477945:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 4,
state 1, nbr to commit 0 isTransactional 1
1146.583481992:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: enter, 1 msgs
1146.583485767:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: processing...
1146.583491327:main Q:Reg/w0 : ../action.c: actionTryCommit[action-4-builtin
:omfile] enter
1146.583494925:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.583498534:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81b10
1146.583502246:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-4-builtin:omfile], state: itx, nMsgs 1
1146.583506576:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c000d60, lenBuf 138, strt data Apr 5 12:39:06 frontal4 postfix/
smtpd[597292]: disconnect from unknown[192.168.2.1] ehlo=1 auth=1 mail=1
rcpt=1 data=1 quit=1 c
1146.583511704:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13
strmFlush
1146.583516433:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c:
strmFlushinternal: file 13(/var/log/syslog) flush, buflen 138
1146.583522733:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13(/var/
log/syslog) doWriteInternal: bFlush 1
1146.583527022:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c000d60, len 138
1146.583561884:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13 write
wrote 138 bytes
1146.583593743:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-4-builtin:omfile] state: itx mod commitTransaction returned 0
1146.583613104:main Q:Reg/w0 : ../action.c: action[action-4-builtin:omfile]
transitioned to state: rdy
1146.583630368:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: return actionTryCommit 0
1146.583645230:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: done, iRet 0
1146.583660120:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 6,
state 1, nbr to commit 0 isTransactional 1
1146.583675971:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: enter, 1 msgs
1146.583709223:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: processing...
1146.583741768:main Q:Reg/w0 : ../action.c: actionTryCommit[action-6-builtin
:omfile] enter
1146.583758473:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.583773833:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81bf0
1146.583782139:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-6-builtin:omfile], state: itx, nMsgs 1
1146.583790599:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c0033b0, lenBuf 138, strt data Apr 5 12:39:06 frontal4 postfix/
smtpd[597292]: disconnect from unknown[192.168.2.1] ehlo=1 auth=1 mail=1
rcpt=1 data=1 quit=1 c
1146.583797298:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15
strmFlush
1146.583814558:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c:
strmFlushinternal: file 15(/var/log/mail.log) flush, buflen 138
1146.583830900:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15(/var/
log/mail.log) doWriteInternal: bFlush 1
1146.583911036:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c0033b0, len 138
1146.584019167:imfile.c : imfile.c: INOTIFY event: watch was MODIFID
1146.584038126:imfile.c : imfile.c: in_processEvent process Event 2 for
1146.584048017:imfile.c : imfile.c: in_processEvent process Event 2 is_file
1, act->name '/var/log/mail.log'
1146.584057896:imfile.c : imfile.c: fs_node_notify_file_update: act->name
'/var/log/mail.log'
1146.584068826:imfile.c : imfile.c: pollFileReal enter, act 0x7fed68000f60,
pStrm 0x7fed680030c0, name '/var/log/mail.log'
1146.584078371:imfile.c : imfile.c: pollFileReal enter, edge 0x55e808f81370
1146.584105588:imfile.c : imfile.c: pollFileReal enter, edge->instarr
0x55e808f81420
1146.584130782:imfile.c : strm 0x7fed680030c0: stream.c: file 14 read 0
bytes
1146.584141659:imfile.c : strm 0x7fed680030c0: stream.c: file
'/var/log/mail.log' (14) EOF, rotationCheck 0
1146.584158260:imfile.c : stream.c: strmHandleEOFMonitor: stream checking
for file change on '/var/log/mail.log', inode 134056/134056 size 982128151/
104709737
1146.584174347:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15 write
wrote 138 bytes
1146.584185307:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-6-builtin:omfile] state: itx mod commitTransaction returned 0
1146.584195582:main Q:Reg/w0 : ../action.c: action[action-6-builtin:omfile]
transitioned to state: rdy
1146.584205529:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: return actionTryCommit 0
1146.584214797:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: done, iRet 0
1146.584224204:main Q:Reg/w0 : ruleset.c: processBATCH: batch of 1 elements
has been processed
1146.584270051:main Q:Reg/w0 : queue.c: regular consumer finished, iret=0,
szlog 0 sz phys 1
1146.584282434:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: etry 0 state 3
1146.584291941:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: we deleted 1
objects and enqueued 0 objects
1146.584301114:main Q:Reg/w0 : queue.c: rger: deleteBatchFromQStore, nElem 1
1146.584310484:main Q:Reg/w0 : queue.c: doDeleteBatch: delete batch from
store, new sizes: log 0, phys 0
1146.584319930:main Q:Reg/w0 : main Q: queue.c: dequeued 0 consumable
elements, szlog 0 sz phys 0
1146.584329766:main Q:Reg/w0 : queue.c: regular consumer finished, iret=4,
szlog 0 sz phys 0
1146.584339261:main Q:Reg/w0 : wti.c: main Q:Reg/w0: worker IDLE, waiting
for work.
1146.597009623:imuxsock.c : imuxsock.c: Message from UNIX socket: #4, size
229
1146.597038480:imuxsock.c : datetime.c: ParseTIMESTAMP3339: invalid year: 0,
pszTS: 'p'
1146.597057643:imuxsock.c : main Q: queue.c: EnqueueMsg advised worker start
1146.597069575:imuxsock.c : imuxsock.c: --------imuxsock calling poll() on 2
fds
1146.597084385:imuxsock.c : imuxsock.c: Message from UNIX socket: #4, size
58
1146.597096424:imuxsock.c : datetime.c: ParseTIMESTAMP3339: invalid year: 0,
pszTS: 'p'
1146.597107666:imuxsock.c : main Q: queue.c: EnqueueMsg advised worker start
1146.597117887:imuxsock.c : imuxsock.c: --------imuxsock calling poll() on 2
fds
1146.597131443:main Q:Reg/w0 : wti 0x55e808f77fb0: wti.c: worker awoke from
idle processing
1146.597141719:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: we deleted 0
objects and enqueued 0 objects
1146.597151265:main Q:Reg/w0 : queue.c: rger: deleteBatchFromQStore, nElem 0
1146.597160715:main Q:Reg/w0 : queue.c: doDeleteBatch: delete batch from
store, new sizes: log 2, phys 2
1146.597170233:main Q:Reg/w0 : main Q: queue.c: entry deleted, size now log
1, phys 2 entries
1146.597179436:main Q:Reg/w0 : main Q: queue.c: entry deleted, size now log
0, phys 2 entries
1146.597189637:main Q:Reg/w0 : main Q: queue.c: dequeued 2 consumable
elements, szlog 0 sz phys 2
1146.597208406:main Q:Reg/w0 : ruleset.c: processBATCH: batch of 2 elements
must be processed
1146.597225664:main Q:Reg/w0 : ruleset.c: processBATCH: next msg 0: <22>Apr
5 12:39:06 postfix/smtp[597424]: 79D688D: to=<foo@bar.com>, relay=192.168.
2.111[.192.168.2.111
1146.597240065:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.597271779:main Q:Reg/w0 : rainerscript.c: Property.: 'msg'
1146.597308063:main Q:Reg/w0 : rainerscript.c: Operation: 'contains'
1146.597341758:main Q:Reg/w0 : rainerscript.c: Value....: '[.UFW '
1146.597366324:main Q:Reg/w0 : ruleset.c: Filter: check for property 'msg' (
value ' 79D688D: to=<foo@bar.com>, relay=192.168.2.111[192.168.2.111]:2525,
delay=0.1, delays=0.07/0/0.01/0.03, dsn=2.0.0, status=sent (250 2.0.0 Ok:
queued as 8C0BA12C)') contains '[.UFW ': FALSE
1146.597384080:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.597390154:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.597407745:main Q:Reg/w0 : rainerscript.c: Property.: 'syslogtag'
1146.597429850:main Q:Reg/w0 : rainerscript.c: Operation: 'isequal'
1146.597474680:main Q:Reg/w0 : rainerscript.c: Value....: '[CLOUDINIT]'
1146.597500997:main Q:Reg/w0 : ruleset.c: Filter: check for property
'syslogtag' (value 'postfix/smtp[597424]:') isequal '[CLOUDINIT]': FALSE
1146.597516221:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.597525027:main Q:Reg/w0 : rainerscript.c: PRIFILT 'auth,authpriv.*'
1146.597544821:main Q:Reg/w0 : rainerscript.c: pmask: X X X X FF X X X X X
FF X X X X X X X X X X X X X X X
1146.597736950:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.597790950:main Q:Reg/w0 : rainerscript.c: PRIFILT
'*.*;auth,authpriv.none'
1146.597815721:main Q:Reg/w0 : rainerscript.c: pmask: FF FF FF FF X FF FF FF
FF FF X FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
1146.598016862:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.598026524:main Q:Reg/w0 : rainerscript.c: ACTION 4 [builtin:omfile:-/
var/log/syslog]
1146.598047254:main Q:Reg/w0 : ruleset.c: executing action 4
1146.598057146:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.598069429:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
is transactional - executing in commit phase
1146.598079378:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.598088598:main Q:Reg/w0 : ../action.c: checking external state file
1146.598097842:main Q:Reg/w0 : ../action.c: done checking external state
file, iRet=0
1146.598107297:main Q:Reg/w0 : ../action.c: action[action-4-builtin:omfile]
transitioned to state: itx
1146.598116773:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
set suspended state to 0
1146.598125759:main Q:Reg/w0 : rainerscript.c: PRIFILT 'kern.*'
1146.598145538:main Q:Reg/w0 : rainerscript.c: pmask: FF X X X X X X X X X X
X X X X X X X X X X X X X X X
1146.598324409:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.598333833:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.*'
1146.598353752:main Q:Reg/w0 : rainerscript.c: pmask: 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 X
1146.598557546:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.598566635:main Q:Reg/w0 : rainerscript.c: ACTION 6 [builtin:omfile:-/
var/log/mail.log]
1146.598587017:main Q:Reg/w0 : ruleset.c: executing action 6
1146.598596236:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.598606783:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
is transactional - executing in commit phase
1146.598616658:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.598641905:main Q:Reg/w0 : ../action.c: checking external state file
1146.598653456:main Q:Reg/w0 : ../action.c: done checking external state
file, iRet=0
1146.598662687:main Q:Reg/w0 : ../action.c: action[action-6-builtin:omfile]
transitioned to state: itx
1146.598672080:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
set suspended state to 0
1146.598681121:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.err'
1146.598700770:main Q:Reg/w0 : rainerscript.c: pmask: X X F X X X X X X X X
X X X X X X X X X X X X X X X
1146.598917334:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.598926706:main Q:Reg/w0 : rainerscript.c: PRIFILT '*.emerg'
1146.598946246:main Q:Reg/w0 : rainerscript.c: pmask: 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 1
1146.599141106:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.599153182:main Q:Reg/w0 : ruleset.c: processBATCH: next msg 1: <22>Apr
5 12:39:06 postfix/qmgr[225134]: 79D688D: removed
1146.599162605:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.599181901:main Q:Reg/w0 : rainerscript.c: Property.: 'msg'
1146.599203353:main Q:Reg/w0 : rainerscript.c: Operation: 'contains'
1146.599229891:main Q:Reg/w0 : rainerscript.c: Value....: '[.UFW '
1146.599267947:main Q:Reg/w0 : ruleset.c: Filter: check for property 'msg' (
value ' 79D688D: removed') contains '[.UFW ': FALSE
1146.599284362:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.599293052:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.599312080:main Q:Reg/w0 : rainerscript.c: Property.: 'syslogtag'
1146.599333490:main Q:Reg/w0 : rainerscript.c: Operation: 'isequal'
1146.599360476:main Q:Reg/w0 : rainerscript.c: Value....: '[CLOUDINIT]'
1146.599418045:main Q:Reg/w0 : ruleset.c: Filter: check for property
'syslogtag' (value 'postfix/qmgr[225134]:') isequal '[CLOUDINIT]': FALSE
1146.599436271:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.599445484:main Q:Reg/w0 : rainerscript.c: PRIFILT 'auth,authpriv.*'
1146.599465966:main Q:Reg/w0 : rainerscript.c: pmask: X X X X FF X X X X X
FF X X X X X X X X X X X X X X X
1146.599674782:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.599683838:main Q:Reg/w0 : rainerscript.c: PRIFILT
'*.*;auth,authpriv.none'
1146.599715604:main Q:Reg/w0 : rainerscript.c: pmask: FF FF FF FF X FF FF FF
FF FF X FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
1146.599909058:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.599918397:main Q:Reg/w0 : rainerscript.c: ACTION 4 [builtin:omfile:-/
var/log/syslog]
1146.599938442:main Q:Reg/w0 : ruleset.c: executing action 4
1146.599947953:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.599971278:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
is transactional - executing in commit phase
1146.599982125:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.599991747:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
set suspended state to 0
1146.600000803:main Q:Reg/w0 : rainerscript.c: PRIFILT 'kern.*'
1146.600020336:main Q:Reg/w0 : rainerscript.c: pmask: FF X X X X X X X X X X
X X X X X X X X X X X X X X X
1146.600230285:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.600239789:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.*'
1146.600258783:main Q:Reg/w0 : rainerscript.c: pmask: 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 X
1146.600434806:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.600444064:main Q:Reg/w0 : rainerscript.c: ACTION 6 [builtin:omfile:-/
var/log/mail.log]
1146.600481600:main Q:Reg/w0 : ruleset.c: executing action 6
1146.600491025:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.600501326:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
is transactional - executing in commit phase
1146.600511177:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.600520458:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
set suspended state to 0
1146.600529330:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.err'
1146.600548350:main Q:Reg/w0 : rainerscript.c: pmask: X X F X X X X X X X X
X X X X X X X X X X X X X X X
1146.600743680:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.600752863:main Q:Reg/w0 : rainerscript.c: PRIFILT '*.emerg'
1146.600772276:main Q:Reg/w0 : rainerscript.c: pmask: 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 1
1146.601042336:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.601056667:main Q:Reg/w0 : ruleset.c: END batch execution phase,
entering to commit phase [processed 2 of 2 messages]
1146.601070887:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 4,
state 1, nbr to commit 0 isTransactional 1
1146.601121917:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: enter, 2 msgs
1146.601139044:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: processing...
1146.601153863:main Q:Reg/w0 : ../action.c: actionTryCommit[action-4-builtin
:omfile] enter
1146.601166979:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.601180734:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81b10
1146.601195643:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-4-builtin:omfile], state: itx, nMsgs 2
1146.601285286:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c000d60, lenBuf 235, strt data Apr 5 12:39:06 frontal4 postfix/
smtp[597424]: 79D688D: to=<foo@bar.com>, relay=192.168.2.111[.192.168.
1146.601308314:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c000d60, lenBuf 64, strt data Apr 5 12:39:06 frontal4 postfix/
qmgr[225134]: 79D688D: removed
1146.601319204:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13
strmFlush
1146.601370533:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c:
strmFlushinternal: file 13(/var/log/syslog) flush, buflen 299
1146.601379024:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13(/var/
log/syslog) doWriteInternal: bFlush 1
1146.601388747:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c000d60, len 299
1146.601433938:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13 write
wrote 299 bytes
1146.601476850:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-4-builtin:omfile] state: itx mod commitTransaction returned 0
1146.601487869:main Q:Reg/w0 : ../action.c: action[action-4-builtin:omfile]
transitioned to state: rdy
1146.601494712:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: return actionTryCommit 0
1146.601501060:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: done, iRet 0
1146.601514999:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 6,
state 1, nbr to commit 0 isTransactional 1
1146.601519162:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: enter, 2 msgs
1146.601522602:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: processing...
1146.601526130:main Q:Reg/w0 : ../action.c: actionTryCommit[action-6-builtin
:omfile] enter
1146.601529537:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.601533101:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81bf0
1146.601536880:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-6-builtin:omfile], state: itx, nMsgs 2
1146.601545407:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c0033b0, lenBuf 235, strt data Apr 5 12:39:06 frontal4 postfix/
smtp[597424]: 79D688D: to=<foo@bar.com>, relay=192.168.2.111[.192.168.
1146.601552319:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c0033b0, lenBuf 64, strt data Apr 5 12:39:06 frontal4 postfix/
qmgr[225134]: 79D688D: removed
1146.601558907:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15
strmFlush
1146.601565618:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c:
strmFlushinternal: file 15(/var/log/mail.log) flush, buflen 299
1146.601587844:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15(/var/
log/mail.log) doWriteInternal: bFlush 1
1146.601594791:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c0033b0, len 299
1146.601630253:imfile.c : imfile.c: INOTIFY event: watch was MODIFID
1146.601639773:imfile.c : imfile.c: in_processEvent process Event 2 for
1146.601647061:imfile.c : imfile.c: in_processEvent process Event 2 is_file
1, act->name '/var/log/mail.log'
1146.601652785:imfile.c : imfile.c: fs_node_notify_file_update: act->name
'/var/log/mail.log'
1146.601660122:imfile.c : imfile.c: pollFileReal enter, act 0x7fed68000f60,
pStrm 0x7fed680030c0, name '/var/log/mail.log'
1146.601667104:imfile.c : imfile.c: pollFileReal enter, edge 0x55e808f81370
1146.601672203:imfile.c : imfile.c: pollFileReal enter, edge->instarr
0x55e808f81420
1146.601683743:imfile.c : strm 0x7fed680030c0: stream.c: file 14 read 0
bytes
1146.601691329:imfile.c : strm 0x7fed680030c0: stream.c: file
'/var/log/mail.log' (14) EOF, rotationCheck 0
1146.601723185:imfile.c : stream.c: strmHandleEOFMonitor: stream checking
for file change on '/var/log/mail.log', inode 134056/134056 size 982128151/
104710036
1146.601738111:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15 write
wrote 299 bytes
1146.601745391:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-6-builtin:omfile] state: itx mod commitTransaction returned 0
1146.601751543:main Q:Reg/w0 : ../action.c: action[action-6-builtin:omfile]
transitioned to state: rdy
1146.601757157:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: return actionTryCommit 0
1146.601763133:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: done, iRet 0
1146.601768736:main Q:Reg/w0 : ruleset.c: processBATCH: batch of 2 elements
has been processed
1146.601776308:main Q:Reg/w0 : queue.c: regular consumer finished, iret=0,
szlog 0 sz phys 2
1146.601780636:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: etry 0 state 3
1146.601785572:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: etry 1 state 3
1146.601789198:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: we deleted 2
objects and enqueued 0 objects
1146.601792545:main Q:Reg/w0 : queue.c: rger: deleteBatchFromQStore, nElem 2
1146.601796104:main Q:Reg/w0 : queue.c: doDeleteBatch: delete batch from
store, new sizes: log 0, phys 0
1146.601799845:main Q:Reg/w0 : main Q: queue.c: dequeued 0 consumable
elements, szlog 0 sz phys 0
1146.601806068:main Q:Reg/w0 : queue.c: regular consumer finished, iret=4,
szlog 0 sz phys 0
1146.601812046:main Q:Reg/w0 : wti.c: main Q:Reg/w0: worker IDLE, waiting
for work.
_______________________________________________
rsyslog mailing list
https://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.
(imfile>omfwd) to central rsyslog.
Restarting or stop/start the service doesn't fix the issue and messages
only resume after deleting state file
rm /var/spool/rsyslog/imfile-state:134766:1a75f838195c3b3c
As this seems to be an error-recurrent issue, could you provide some hints
on how to debug/diagnose what's going on?
service estatus warns: "Warning: journal has been rotated since unit was
started, output may be incomplete."
computer rsyslog config:
module(load="imfile")
template(name="json" type="list" option.json="on") {
constant(value="{")
constant(value="\"@source_timestamp\":\"")
property(name="timereported" dateFormat="rfc3339")
constant(value="\",\"source_message\":\"")
property(name="msg")
constant(value="\",\"source_hostname\":\"")
property(name="hostname")
constant(value="\",\"source_severity\":\"")
property(name="syslogseverity-text")
constant(value="\",\"source_facility\":\"")
property(name="syslogfacility-text")
constant(value="\",\"source_tag\":\"")
property(name="syslogtag")
constant(value="\",\"source_app\":\"")
property(name="programname")
constant(value="\",\"source_filename\":\"")
property(name="$.filename")
constant(value="\"}\n")
}
input(type="imfile" file="/var/log/mail.log" addMetadata="on" tag="mail"
ruleset="syslog")
ruleset(name="syslog") {
set $.filename = $!metadata!filename;
action(type="omfwd" target="central.rsyslog.com" port="514" protocol="udp"
template="json")
}
rsyslog -dn output:
1146.583477945:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 4,
state 1, nbr to commit 0 isTransactional 1
1146.583481992:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: enter, 1 msgs
1146.583485767:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: processing...
1146.583491327:main Q:Reg/w0 : ../action.c: actionTryCommit[action-4-builtin
:omfile] enter
1146.583494925:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.583498534:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81b10
1146.583502246:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-4-builtin:omfile], state: itx, nMsgs 1
1146.583506576:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c000d60, lenBuf 138, strt data Apr 5 12:39:06 frontal4 postfix/
smtpd[597292]: disconnect from unknown[192.168.2.1] ehlo=1 auth=1 mail=1
rcpt=1 data=1 quit=1 c
1146.583511704:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13
strmFlush
1146.583516433:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c:
strmFlushinternal: file 13(/var/log/syslog) flush, buflen 138
1146.583522733:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13(/var/
log/syslog) doWriteInternal: bFlush 1
1146.583527022:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c000d60, len 138
1146.583561884:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13 write
wrote 138 bytes
1146.583593743:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-4-builtin:omfile] state: itx mod commitTransaction returned 0
1146.583613104:main Q:Reg/w0 : ../action.c: action[action-4-builtin:omfile]
transitioned to state: rdy
1146.583630368:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: return actionTryCommit 0
1146.583645230:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: done, iRet 0
1146.583660120:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 6,
state 1, nbr to commit 0 isTransactional 1
1146.583675971:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: enter, 1 msgs
1146.583709223:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: processing...
1146.583741768:main Q:Reg/w0 : ../action.c: actionTryCommit[action-6-builtin
:omfile] enter
1146.583758473:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.583773833:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81bf0
1146.583782139:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-6-builtin:omfile], state: itx, nMsgs 1
1146.583790599:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c0033b0, lenBuf 138, strt data Apr 5 12:39:06 frontal4 postfix/
smtpd[597292]: disconnect from unknown[192.168.2.1] ehlo=1 auth=1 mail=1
rcpt=1 data=1 quit=1 c
1146.583797298:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15
strmFlush
1146.583814558:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c:
strmFlushinternal: file 15(/var/log/mail.log) flush, buflen 138
1146.583830900:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15(/var/
log/mail.log) doWriteInternal: bFlush 1
1146.583911036:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c0033b0, len 138
1146.584019167:imfile.c : imfile.c: INOTIFY event: watch was MODIFID
1146.584038126:imfile.c : imfile.c: in_processEvent process Event 2 for
1146.584048017:imfile.c : imfile.c: in_processEvent process Event 2 is_file
1, act->name '/var/log/mail.log'
1146.584057896:imfile.c : imfile.c: fs_node_notify_file_update: act->name
'/var/log/mail.log'
1146.584068826:imfile.c : imfile.c: pollFileReal enter, act 0x7fed68000f60,
pStrm 0x7fed680030c0, name '/var/log/mail.log'
1146.584078371:imfile.c : imfile.c: pollFileReal enter, edge 0x55e808f81370
1146.584105588:imfile.c : imfile.c: pollFileReal enter, edge->instarr
0x55e808f81420
1146.584130782:imfile.c : strm 0x7fed680030c0: stream.c: file 14 read 0
bytes
1146.584141659:imfile.c : strm 0x7fed680030c0: stream.c: file
'/var/log/mail.log' (14) EOF, rotationCheck 0
1146.584158260:imfile.c : stream.c: strmHandleEOFMonitor: stream checking
for file change on '/var/log/mail.log', inode 134056/134056 size 982128151/
104709737
1146.584174347:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15 write
wrote 138 bytes
1146.584185307:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-6-builtin:omfile] state: itx mod commitTransaction returned 0
1146.584195582:main Q:Reg/w0 : ../action.c: action[action-6-builtin:omfile]
transitioned to state: rdy
1146.584205529:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: return actionTryCommit 0
1146.584214797:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: done, iRet 0
1146.584224204:main Q:Reg/w0 : ruleset.c: processBATCH: batch of 1 elements
has been processed
1146.584270051:main Q:Reg/w0 : queue.c: regular consumer finished, iret=0,
szlog 0 sz phys 1
1146.584282434:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: etry 0 state 3
1146.584291941:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: we deleted 1
objects and enqueued 0 objects
1146.584301114:main Q:Reg/w0 : queue.c: rger: deleteBatchFromQStore, nElem 1
1146.584310484:main Q:Reg/w0 : queue.c: doDeleteBatch: delete batch from
store, new sizes: log 0, phys 0
1146.584319930:main Q:Reg/w0 : main Q: queue.c: dequeued 0 consumable
elements, szlog 0 sz phys 0
1146.584329766:main Q:Reg/w0 : queue.c: regular consumer finished, iret=4,
szlog 0 sz phys 0
1146.584339261:main Q:Reg/w0 : wti.c: main Q:Reg/w0: worker IDLE, waiting
for work.
1146.597009623:imuxsock.c : imuxsock.c: Message from UNIX socket: #4, size
229
1146.597038480:imuxsock.c : datetime.c: ParseTIMESTAMP3339: invalid year: 0,
pszTS: 'p'
1146.597057643:imuxsock.c : main Q: queue.c: EnqueueMsg advised worker start
1146.597069575:imuxsock.c : imuxsock.c: --------imuxsock calling poll() on 2
fds
1146.597084385:imuxsock.c : imuxsock.c: Message from UNIX socket: #4, size
58
1146.597096424:imuxsock.c : datetime.c: ParseTIMESTAMP3339: invalid year: 0,
pszTS: 'p'
1146.597107666:imuxsock.c : main Q: queue.c: EnqueueMsg advised worker start
1146.597117887:imuxsock.c : imuxsock.c: --------imuxsock calling poll() on 2
fds
1146.597131443:main Q:Reg/w0 : wti 0x55e808f77fb0: wti.c: worker awoke from
idle processing
1146.597141719:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: we deleted 0
objects and enqueued 0 objects
1146.597151265:main Q:Reg/w0 : queue.c: rger: deleteBatchFromQStore, nElem 0
1146.597160715:main Q:Reg/w0 : queue.c: doDeleteBatch: delete batch from
store, new sizes: log 2, phys 2
1146.597170233:main Q:Reg/w0 : main Q: queue.c: entry deleted, size now log
1, phys 2 entries
1146.597179436:main Q:Reg/w0 : main Q: queue.c: entry deleted, size now log
0, phys 2 entries
1146.597189637:main Q:Reg/w0 : main Q: queue.c: dequeued 2 consumable
elements, szlog 0 sz phys 2
1146.597208406:main Q:Reg/w0 : ruleset.c: processBATCH: batch of 2 elements
must be processed
1146.597225664:main Q:Reg/w0 : ruleset.c: processBATCH: next msg 0: <22>Apr
5 12:39:06 postfix/smtp[597424]: 79D688D: to=<foo@bar.com>, relay=192.168.
2.111[.192.168.2.111
1146.597240065:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.597271779:main Q:Reg/w0 : rainerscript.c: Property.: 'msg'
1146.597308063:main Q:Reg/w0 : rainerscript.c: Operation: 'contains'
1146.597341758:main Q:Reg/w0 : rainerscript.c: Value....: '[.UFW '
1146.597366324:main Q:Reg/w0 : ruleset.c: Filter: check for property 'msg' (
value ' 79D688D: to=<foo@bar.com>, relay=192.168.2.111[192.168.2.111]:2525,
delay=0.1, delays=0.07/0/0.01/0.03, dsn=2.0.0, status=sent (250 2.0.0 Ok:
queued as 8C0BA12C)') contains '[.UFW ': FALSE
1146.597384080:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.597390154:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.597407745:main Q:Reg/w0 : rainerscript.c: Property.: 'syslogtag'
1146.597429850:main Q:Reg/w0 : rainerscript.c: Operation: 'isequal'
1146.597474680:main Q:Reg/w0 : rainerscript.c: Value....: '[CLOUDINIT]'
1146.597500997:main Q:Reg/w0 : ruleset.c: Filter: check for property
'syslogtag' (value 'postfix/smtp[597424]:') isequal '[CLOUDINIT]': FALSE
1146.597516221:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.597525027:main Q:Reg/w0 : rainerscript.c: PRIFILT 'auth,authpriv.*'
1146.597544821:main Q:Reg/w0 : rainerscript.c: pmask: X X X X FF X X X X X
FF X X X X X X X X X X X X X X X
1146.597736950:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.597790950:main Q:Reg/w0 : rainerscript.c: PRIFILT
'*.*;auth,authpriv.none'
1146.597815721:main Q:Reg/w0 : rainerscript.c: pmask: FF FF FF FF X FF FF FF
FF FF X FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
1146.598016862:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.598026524:main Q:Reg/w0 : rainerscript.c: ACTION 4 [builtin:omfile:-/
var/log/syslog]
1146.598047254:main Q:Reg/w0 : ruleset.c: executing action 4
1146.598057146:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.598069429:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
is transactional - executing in commit phase
1146.598079378:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.598088598:main Q:Reg/w0 : ../action.c: checking external state file
1146.598097842:main Q:Reg/w0 : ../action.c: done checking external state
file, iRet=0
1146.598107297:main Q:Reg/w0 : ../action.c: action[action-4-builtin:omfile]
transitioned to state: itx
1146.598116773:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
set suspended state to 0
1146.598125759:main Q:Reg/w0 : rainerscript.c: PRIFILT 'kern.*'
1146.598145538:main Q:Reg/w0 : rainerscript.c: pmask: FF X X X X X X X X X X
X X X X X X X X X X X X X X X
1146.598324409:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.598333833:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.*'
1146.598353752:main Q:Reg/w0 : rainerscript.c: pmask: 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 X
1146.598557546:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.598566635:main Q:Reg/w0 : rainerscript.c: ACTION 6 [builtin:omfile:-/
var/log/mail.log]
1146.598587017:main Q:Reg/w0 : ruleset.c: executing action 6
1146.598596236:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.598606783:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
is transactional - executing in commit phase
1146.598616658:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.598641905:main Q:Reg/w0 : ../action.c: checking external state file
1146.598653456:main Q:Reg/w0 : ../action.c: done checking external state
file, iRet=0
1146.598662687:main Q:Reg/w0 : ../action.c: action[action-6-builtin:omfile]
transitioned to state: itx
1146.598672080:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
set suspended state to 0
1146.598681121:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.err'
1146.598700770:main Q:Reg/w0 : rainerscript.c: pmask: X X F X X X X X X X X
X X X X X X X X X X X X X X X
1146.598917334:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.598926706:main Q:Reg/w0 : rainerscript.c: PRIFILT '*.emerg'
1146.598946246:main Q:Reg/w0 : rainerscript.c: pmask: 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 1
1146.599141106:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.599153182:main Q:Reg/w0 : ruleset.c: processBATCH: next msg 1: <22>Apr
5 12:39:06 postfix/qmgr[225134]: 79D688D: removed
1146.599162605:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.599181901:main Q:Reg/w0 : rainerscript.c: Property.: 'msg'
1146.599203353:main Q:Reg/w0 : rainerscript.c: Operation: 'contains'
1146.599229891:main Q:Reg/w0 : rainerscript.c: Value....: '[.UFW '
1146.599267947:main Q:Reg/w0 : ruleset.c: Filter: check for property 'msg' (
value ' 79D688D: removed') contains '[.UFW ': FALSE
1146.599284362:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.599293052:main Q:Reg/w0 : rainerscript.c: PROPFILT
1146.599312080:main Q:Reg/w0 : rainerscript.c: Property.: 'syslogtag'
1146.599333490:main Q:Reg/w0 : rainerscript.c: Operation: 'isequal'
1146.599360476:main Q:Reg/w0 : rainerscript.c: Value....: '[CLOUDINIT]'
1146.599418045:main Q:Reg/w0 : ruleset.c: Filter: check for property
'syslogtag' (value 'postfix/qmgr[225134]:') isequal '[CLOUDINIT]': FALSE
1146.599436271:main Q:Reg/w0 : ruleset.c: PROPFILT condition result is 0
1146.599445484:main Q:Reg/w0 : rainerscript.c: PRIFILT 'auth,authpriv.*'
1146.599465966:main Q:Reg/w0 : rainerscript.c: pmask: X X X X FF X X X X X
FF X X X X X X X X X X X X X X X
1146.599674782:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.599683838:main Q:Reg/w0 : rainerscript.c: PRIFILT
'*.*;auth,authpriv.none'
1146.599715604:main Q:Reg/w0 : rainerscript.c: pmask: FF FF FF FF X FF FF FF
FF FF X FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
1146.599909058:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.599918397:main Q:Reg/w0 : rainerscript.c: ACTION 4 [builtin:omfile:-/
var/log/syslog]
1146.599938442:main Q:Reg/w0 : ruleset.c: executing action 4
1146.599947953:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.599971278:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
is transactional - executing in commit phase
1146.599982125:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.599991747:main Q:Reg/w0 : ../action.c: action 'action-4-builtin:omfile':
set suspended state to 0
1146.600000803:main Q:Reg/w0 : rainerscript.c: PRIFILT 'kern.*'
1146.600020336:main Q:Reg/w0 : rainerscript.c: pmask: FF X X X X X X X X X X
X X X X X X X X X X X X X X X
1146.600230285:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.600239789:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.*'
1146.600258783:main Q:Reg/w0 : rainerscript.c: pmask: 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 X
1146.600434806:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 1
1146.600444064:main Q:Reg/w0 : rainerscript.c: ACTION 6 [builtin:omfile:-/
var/log/mail.log]
1146.600481600:main Q:Reg/w0 : ruleset.c: executing action 6
1146.600491025:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
called, logging to builtin:omfile (susp 0/0, direct q 1)
1146.600501326:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
is transactional - executing in commit phase
1146.600511177:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.600520458:main Q:Reg/w0 : ../action.c: action 'action-6-builtin:omfile':
set suspended state to 0
1146.600529330:main Q:Reg/w0 : rainerscript.c: PRIFILT 'mail.err'
1146.600548350:main Q:Reg/w0 : rainerscript.c: pmask: X X F X X X X X X X X
X X X X X X X X X X X X X X X
1146.600743680:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.600752863:main Q:Reg/w0 : rainerscript.c: PRIFILT '*.emerg'
1146.600772276:main Q:Reg/w0 : rainerscript.c: pmask: 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 1
1146.601042336:main Q:Reg/w0 : ruleset.c: PRIFILT condition result is 0
1146.601056667:main Q:Reg/w0 : ruleset.c: END batch execution phase,
entering to commit phase [processed 2 of 2 messages]
1146.601070887:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 4,
state 1, nbr to commit 0 isTransactional 1
1146.601121917:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: enter, 2 msgs
1146.601139044:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: processing...
1146.601153863:main Q:Reg/w0 : ../action.c: actionTryCommit[action-4-builtin
:omfile] enter
1146.601166979:main Q:Reg/w0 : ../action.c: actionPrepare[action-4-builtin:
omfile]: enter
1146.601180734:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81b10
1146.601195643:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-4-builtin:omfile], state: itx, nMsgs 2
1146.601285286:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c000d60, lenBuf 235, strt data Apr 5 12:39:06 frontal4 postfix/
smtp[597424]: 79D688D: to=<foo@bar.com>, relay=192.168.2.111[.192.168.
1146.601308314:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c000d60, lenBuf 64, strt data Apr 5 12:39:06 frontal4 postfix/
qmgr[225134]: 79D688D: removed
1146.601319204:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13
strmFlush
1146.601370533:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c:
strmFlushinternal: file 13(/var/log/syslog) flush, buflen 299
1146.601379024:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13(/var/
log/syslog) doWriteInternal: bFlush 1
1146.601388747:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c000d60, len 299
1146.601433938:main Q:Reg/w0 : strm 0x7fed6c000d60: stream.c: file 13 write
wrote 299 bytes
1146.601476850:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-4-builtin:omfile] state: itx mod commitTransaction returned 0
1146.601487869:main Q:Reg/w0 : ../action.c: action[action-4-builtin:omfile]
transitioned to state: rdy
1146.601494712:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: return actionTryCommit 0
1146.601501060:main Q:Reg/w0 : ../action.c: actionCommit[action-4-builtin:
omfile]: done, iRet 0
1146.601514999:main Q:Reg/w0 : ../action.c: actionCommitAllDirect: action 6,
state 1, nbr to commit 0 isTransactional 1
1146.601519162:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: enter, 2 msgs
1146.601522602:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: processing...
1146.601526130:main Q:Reg/w0 : ../action.c: actionTryCommit[action-6-builtin
:omfile] enter
1146.601529537:main Q:Reg/w0 : ../action.c: actionPrepare[action-6-builtin:
omfile]: enter
1146.601533101:main Q:Reg/w0 : ../action.c: doTransaction: have
commitTransaction IF, using that, pWrkrInfo 0x55e808f81bf0
1146.601536880:main Q:Reg/w0 : ../action.c: entering
actionCallCommitTransaction[action-6-builtin:omfile], state: itx, nMsgs 2
1146.601545407:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c0033b0, lenBuf 235, strt data Apr 5 12:39:06 frontal4 postfix/
smtp[597424]: 79D688D: to=<foo@bar.com>, relay=192.168.2.111[.192.168.
1146.601552319:main Q:Reg/w0 : omfile.c: omfile: write to stream, pData->
pStrm 0x7fed6c0033b0, lenBuf 64, strt data Apr 5 12:39:06 frontal4 postfix/
qmgr[225134]: 79D688D: removed
1146.601558907:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15
strmFlush
1146.601565618:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c:
strmFlushinternal: file 15(/var/log/mail.log) flush, buflen 299
1146.601587844:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15(/var/
log/mail.log) doWriteInternal: bFlush 1
1146.601594791:main Q:Reg/w0 : stream.c: strmPhysWrite, stream
0x7fed6c0033b0, len 299
1146.601630253:imfile.c : imfile.c: INOTIFY event: watch was MODIFID
1146.601639773:imfile.c : imfile.c: in_processEvent process Event 2 for
1146.601647061:imfile.c : imfile.c: in_processEvent process Event 2 is_file
1, act->name '/var/log/mail.log'
1146.601652785:imfile.c : imfile.c: fs_node_notify_file_update: act->name
'/var/log/mail.log'
1146.601660122:imfile.c : imfile.c: pollFileReal enter, act 0x7fed68000f60,
pStrm 0x7fed680030c0, name '/var/log/mail.log'
1146.601667104:imfile.c : imfile.c: pollFileReal enter, edge 0x55e808f81370
1146.601672203:imfile.c : imfile.c: pollFileReal enter, edge->instarr
0x55e808f81420
1146.601683743:imfile.c : strm 0x7fed680030c0: stream.c: file 14 read 0
bytes
1146.601691329:imfile.c : strm 0x7fed680030c0: stream.c: file
'/var/log/mail.log' (14) EOF, rotationCheck 0
1146.601723185:imfile.c : stream.c: strmHandleEOFMonitor: stream checking
for file change on '/var/log/mail.log', inode 134056/134056 size 982128151/
104710036
1146.601738111:main Q:Reg/w0 : strm 0x7fed6c0033b0: stream.c: file 15 write
wrote 299 bytes
1146.601745391:main Q:Reg/w0 : ../action.c: actionCallCommitTransaction[
action-6-builtin:omfile] state: itx mod commitTransaction returned 0
1146.601751543:main Q:Reg/w0 : ../action.c: action[action-6-builtin:omfile]
transitioned to state: rdy
1146.601757157:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: return actionTryCommit 0
1146.601763133:main Q:Reg/w0 : ../action.c: actionCommit[action-6-builtin:
omfile]: done, iRet 0
1146.601768736:main Q:Reg/w0 : ruleset.c: processBATCH: batch of 2 elements
has been processed
1146.601776308:main Q:Reg/w0 : queue.c: regular consumer finished, iret=0,
szlog 0 sz phys 2
1146.601780636:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: etry 0 state 3
1146.601785572:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: etry 1 state 3
1146.601789198:main Q:Reg/w0 : queue.c: DeleteProcessedBatch: we deleted 2
objects and enqueued 0 objects
1146.601792545:main Q:Reg/w0 : queue.c: rger: deleteBatchFromQStore, nElem 2
1146.601796104:main Q:Reg/w0 : queue.c: doDeleteBatch: delete batch from
store, new sizes: log 0, phys 0
1146.601799845:main Q:Reg/w0 : main Q: queue.c: dequeued 0 consumable
elements, szlog 0 sz phys 0
1146.601806068:main Q:Reg/w0 : queue.c: regular consumer finished, iret=4,
szlog 0 sz phys 0
1146.601812046:main Q:Reg/w0 : wti.c: main Q:Reg/w0: worker IDLE, waiting
for work.
_______________________________________________
rsyslog mailing list
https://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.