Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

imfile: truncated file won't be read until size growed to the previous length #511

Closed
ymattw opened this issue Sep 6, 2015 · 2 comments · Fixed by #662
Closed

imfile: truncated file won't be read until size growed to the previous length #511

ymattw opened this issue Sep 6, 2015 · 2 comments · Fixed by #662

Comments

@ymattw
Copy link
Contributor

ymattw commented Sep 6, 2015

When input file in truncated, log appended to the file won't be read until its size reached the previous length. This can be easily reproduced with following sample config:

module(load="imfile" mode="inotify")
input(type="imfile" file="/tmp/input.log" tag="myapp")

module(load="builtin:omfile")
*.* action(type="omfile"
           file="/tmp/output.log"
           action.resumeRetryCount="-1"
           queue.filename="queue"
           queue.size="100000"
           queue.saveonshutdown="on"
           queue.discardseverity="0"
          )

Desired behavior is to reset the recorded offset when input file is truncated.

I am attaching the full debug log below, broken into sections with some comments, hope this helps.

Startup

1989.179784440:imfile.c       : DDDDD: readLine returns[-2026]: '(null)' [*ppCStr 0x7fcb98004640]
1989.179797185:imfile.c       : DDDD: imfile event notification: rd 32[0], wd (1, mask 00000100, cookie 0000, len 16)
1989.179803351:imfile.c       : file was CREATED: output.log
1989.179809606:imfile.c       : DDDD: imfile: in_processEvent (wd=1) event Mask='0x00000100'
1989.179816504:imfile.c       : DDDD: imfile: wd 1 got file (nil), dir 0
1989.179822576:imfile.c       : DDDD: imfile: handle dir event for /tmp
1989.179829517:imfile.c       : DDDD: imfile: fileTableSearch file 'output.log' - 'input.log', found:-1
1989.179835792:imfile.c       : imfile: file 'output.log' not active in dir '/tmp'
1989.179842153:imfile.c       : DDDD: imfile: fileTableSearch file 'output.log' - 'input.log', found:-1
1989.179848426:imfile.c       : imfile: file 'output.log' not associated with dir '/tmp'

Write 10 lines with head /etc/services >> /tmp/input.log

2027.608540122:imfile.c       : DDDD: imfile event notification: rd 16[0], wd (2, mask 00000002, cookie 0000, len 0)
2027.608608521:imfile.c       : watch was MODIFID
2027.608618904:imfile.c       : DDDD: imfile: in_processEvent (wd=2) event Mask='0x00000002'
2027.608628299:imfile.c       : DDDD: imfile: wd 2 got file 0x7fcb98002190, dir -1
2027.608646167:imfile.c       : strm 0x7fcb98005770: file 6 read 439 bytes
2027.608657138:imfile.c       : DDDDD: readLine returns[0]: '# /etc/services:' [*ppCStr 0x7fcb98004640]
2027.608687765:imfile.c       : DDDDD: readLine returns[0]: '# $Id: services,v 1.55 2013/04/14 ovasik Exp $' [*ppCStr 0x7fcb98004640]
2027.608701590:imfile.c       : DDDDD: readLine returns[0]: '#' [*ppCStr 0x7fcb98004640]
2027.608745529:imfile.c       : DDDDD: readLine returns[0]: '# Network services, Internet style' [*ppCStr 0x7fcb98004640]
2027.608769890:imfile.c       : DDDDD: readLine returns[0]: '# IANA services version: last updated 2013-04-10' [*ppCStr 0x7fcb98004640]
2027.608784138:imfile.c       : DDDDD: readLine returns[0]: '#' [*ppCStr 0x7fcb98004640]
2027.608809741:imfile.c       : DDDDD: readLine returns[0]: '# Note that it is presently the policy of IANA to assign a single well-known' [*ppCStr 0x7fcb98004640]
2027.608825845:imfile.c       : DDDDD: readLine returns[0]: '# port number for both TCP and UDP; hence, most entries here have two entries' [*ppCStr 0x7fcb98004640]
2027.608846489:imfile.c       : DDDDD: readLine returns[0]: '# even if the protocol doesn't support UDP operations.' [*ppCStr 0x7fcb98004640]
2027.608869044:imfile.c       : DDDDD: readLine returns[0]: '# Updated from RFC 1700, ``Assigned Numbers'' (October 1994).  Not all ports' [*ppCStr 0x7fcb98004640]
2027.608899742:imfile.c       : strm 0x7fcb98005770: file 6 read 0 bytes
2027.608914558:imfile.c       : stream checking for file change on '/tmp/input.log', inode 33730184/33730184
2027.608950678:imfile.c       : DDDDD: readLine returns[-2026]: '(null)' [*ppCStr 0x7fcb98004640]
2027.608963847:imfile.c       : main Q: qqueueAdd: entry added, size now log 1, phys 1 entries
2027.608971456:imfile.c       : main Q: qqueueAdd: entry added, size now log 2, phys 2 entries
2027.608978252:imfile.c       : main Q: qqueueAdd: entry added, size now log 3, phys 3 entries
2027.608985118:imfile.c       : main Q: qqueueAdd: entry added, size now log 4, phys 4 entries
2027.608991867:imfile.c       : main Q: qqueueAdd: entry added, size now log 5, phys 5 entries
2027.608998819:imfile.c       : main Q: qqueueAdd: entry added, size now log 6, phys 6 entries
2027.609005610:imfile.c       : main Q: qqueueAdd: entry added, size now log 7, phys 7 entries
2027.609012657:imfile.c       : main Q: qqueueAdd: entry added, size now log 8, phys 8 entries
2027.609019386:imfile.c       : main Q: qqueueAdd: entry added, size now log 9, phys 9 entries
2027.609067314:imfile.c       : main Q: qqueueAdd: entry added, size now log 10, phys 10 entries
2027.609243441:imfile.c       : main Q: MultiEnqObj advised worker start
2027.609337245:main Q:Reg/w0  : wti 0xae53e0: worker awoke from idle processing
2027.609364349:main Q:Reg/w0  : DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
2027.609385055:main Q:Reg/w0  : doDeleteBatch: delete batch from store, new sizes: log 10, phys 10
2027.609398147:main Q:Reg/w0  : processBATCH: batch of 10 elements must be processed
2027.609406612:main Q:Reg/w0  : processBATCH: next msg 0: # /etc/services:
2027.609422314:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.609437088:main Q:Reg/w0  : executing action 0
2027.609452256:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.609464795:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.609480346:main Q:Reg/w0  : Action 0 transitioned to state: itx
2027.609487977:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.609495177:main Q:Reg/w0  : processBATCH: next msg 1: # $Id: services,v 1.55 2013/04/14 ovasik Exp $
2027.609508399:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.609520845:main Q:Reg/w0  : executing action 0
2027.609528214:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.609543082:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.609550510:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.609557627:main Q:Reg/w0  : processBATCH: next msg 2: #
2027.609572397:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.609584639:main Q:Reg/w0  : executing action 0
2027.609591765:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.609605798:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.609613434:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.609620739:main Q:Reg/w0  : processBATCH: next msg 3: # Network services, Internet style
2027.609635270:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.609647276:main Q:Reg/w0  : executing action 0
2027.609654332:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.609668579:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.609710306:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.609761451:main Q:Reg/w0  : processBATCH: next msg 4: # IANA services version: last updated 2013-04-10
2027.609768545:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.609896206:main Q:Reg/w0  : executing action 0
2027.610364627:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.610606494:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.610827958:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.611066105:main Q:Reg/w0  : processBATCH: next msg 5: #
2027.611339974:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.612018712:main Q:Reg/w0  : executing action 0
2027.612377818:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.612618710:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.612866126:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.613209335:main Q:Reg/w0  : processBATCH: next msg 6: # Note that it is presently the policy of IANA to assign a single well-known
2027.613442590:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.614189016:main Q:Reg/w0  : executing action 0
2027.614415604:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.614646169:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.615032404:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.615334575:main Q:Reg/w0  : processBATCH: next msg 7: # port number for both TCP and UDP; hence, most entries here have two entries
2027.615346130:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.615369539:main Q:Reg/w0  : executing action 0
2027.615378061:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.615395975:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.615404193:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.615419844:main Q:Reg/w0  : processBATCH: next msg 8: # even if the protocol doesn't support UDP operations.
2027.615456211:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.616075285:main Q:Reg/w0  : executing action 0
2027.616377957:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.616786278:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.617066979:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.617432491:main Q:Reg/w0  : processBATCH: next msg 9: # Updated from RFC 1700, ``Assigned Numbers'' (October 1994).  Not all ports
2027.617628579:main Q:Reg/w0  :     ACTION 0 [builtin:omfile:action(type="builtin:omfile" ...)]
2027.617977663:main Q:Reg/w0  : executing action 0
2027.618223341:main Q:Reg/w0  : action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
2027.618244284:main Q:Reg/w0  : action 'action 0': is transactional - executing in commit phase
2027.618249956:main Q:Reg/w0  : action 'action 0': set suspended state to 0
2027.618254897:main Q:Reg/w0  : END batch execution phase, entering to commit phase
2027.618260318:main Q:Reg/w0  : actionCommitAll: action 0, state 1, nbr to commit 10 isTransactional 1
2027.618265706:main Q:Reg/w0  : doTransaction: have commitTransaction IF, using that, pWrkrInfo 0xaea5c0
2027.618271140:main Q:Reg/w0  : entering actionCallCommitTransaction(), state: itx, actionNbr 0, nMsgs 10
2027.618277560:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 62, strt data 2015-09-06T23:07:07.608665+08:00 cent7 myapp # /etc/services:

2027.618283760:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 92, strt data 2015-09-06T23:07:07.608694+08:00 cent7 myapp # $Id: services,v 1.55 201
3/04/14 ovasik Exp $

2027.618288966:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 47, strt data 2015-09-06T23:07:07.608736+08:00 cent7 myapp #

2027.618294010:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 80, strt data 2015-09-06T23:07:07.608761+08:00 cent7 myapp # Network services, Intern
et style

2027.618306957:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 94, strt data 2015-09-06T23:07:07.608777+08:00 cent7 myapp # IANA services version: l
ast updated 2013-04-10

2027.618383901:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 47, strt data 2015-09-06T23:07:07.608800+08:00 cent7 myapp #

2027.618444012:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 122, strt data 2015-09-06T23:07:07.608816+08:00 cent7 myapp # Note that it is present
ly the policy of IANA to assign a single well-known

2027.618634843:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 123, strt data 2015-09-06T23:07:07.608837+08:00 cent7 myapp # port number for both TC
P and UDP; hence, most entries here have two entries

2027.618891790:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 100, strt data 2015-09-06T23:07:07.608859+08:00 cent7 myapp # even if the protocol do
esn't support UDP operations.

2027.619250130:main Q:Reg/w0  : omfile: write to stream, pData->pStrm 0x7fcb90002300, lenBuf 122, strt data 2015-09-06T23:07:07.608891+08:00 cent7 myapp # Updated from RFC 1700,
``Assigned Numbers'' (October 1994).  Not all ports

2027.619395746:main Q:Reg/w0  : strm 0x7fcb90002300: file 5(output.log) flush, buflen 889
2027.619406978:main Q:Reg/w0  : strmPhysWrite, stream 0x7fcb90002300, len 889
2027.619456277:main Q:Reg/w0  : strm 0x7fcb90002300: file 5 write wrote 889 bytes
2027.619466002:main Q:Reg/w0  : Action 0 transitioned to state: rdy
2027.619473842:main Q:Reg/w0  : Action 0 transitioned to state: itx
2027.619480765:main Q:Reg/w0  : Action 0 transitioned to state: rdy
2027.619487593:main Q:Reg/w0  : actionCommit, in retry loop, iRet 0
2027.619494670:main Q:Reg/w0  : processBATCH: batch of 10 elements has been processed
2027.619504180:main Q:Reg/w0  : regular consumer finished, iret=0, szlog 0 sz phys 10
2027.619521847:main Q:Reg/w0  : DeleteProcessedBatch: we deleted 10 objects and enqueued 0 objects
2027.619531013:main Q:Reg/w0  : doDeleteBatch: delete batch from store, new sizes: log 0, phys 0
2027.619539229:main Q:Reg/w0  : regular consumer finished, iret=4, szlog 0 sz phys 0
2027.619574863:main Q:Reg/w0  : main Q:Reg/w0: worker IDLE, waiting for work.

Truncate file with > /tmp/input.log

2037.902186763:imfile.c       : DDDD: imfile event notification: rd 16[0], wd (2, mask 00000002, cookie 0000, len 0)
2037.902250609:imfile.c       : watch was MODIFID
2037.902261407:imfile.c       : DDDD: imfile: in_processEvent (wd=2) event Mask='0x00000002'
2037.902269956:imfile.c       : DDDD: imfile: wd 2 got file 0x7fcb98002190, dir -1
2037.902294088:imfile.c       : strm 0x7fcb98005770: file 6 read 0 bytes
2037.902308881:imfile.c       : stream checking for file change on '/tmp/input.log', inode 33730184/33730184
2037.902316653:imfile.c       : DDDDD: readLine returns[-2026]: '(null)' [*ppCStr 0x7fcb98005740]

Write one line with echo HELLO >> /tmp/input.log, rsyslog does not read the line, neither writes output.log

2046.285996572:imfile.c       : DDDD: imfile event notification: rd 16[0], wd (2, mask 00000002, cookie 0000, len 0)
2046.286191021:imfile.c       : watch was MODIFID
2046.286204597:imfile.c       : DDDD: imfile: in_processEvent (wd=2) event Mask='0x00000002'
2046.286213722:imfile.c       : DDDD: imfile: wd 2 got file 0x7fcb98002190, dir -1
2046.286229835:imfile.c       : strm 0x7fcb98005770: file 6 read 0 bytes
2046.286283726:imfile.c       : stream checking for file change on '/tmp/input.log', inode 33730184/33730184
2046.286299483:imfile.c       : DDDDD: readLine returns[-2026]: '(null)' [*ppCStr 0x7fcb98005740]
@ymattw
Copy link
Contributor Author

ymattw commented Sep 7, 2015

Found the related changes that discarded truncation detection in commit cdc27ae, possible to add it back with a flag to enable this feature? For example in my case duplicate content is fine but message loss is unacceptable.

ymattw added a commit to ymattw/rsyslog that referenced this issue Sep 7, 2015
@ymattw
(imfile) Fix rsyslog#511 with better truncation detection
66f4ca5
@ymattw ymattw mentioned this issue Sep 7, 2015
Closed
ymattw added a commit to ymattw/rsyslog that referenced this issue Sep 7, 2015
@ymattw
(imfile) Fix rsyslog#511 with better truncation detection
375c79c
@ymattw ymattw mentioned this issue Sep 7, 2015
Closed
ymattw added a commit to ymattw/rsyslog that referenced this issue Nov 24, 2015
@ymattw
Our own attempt to fix rsyslog#511
4a58773 
Works for us but upstream wants an opt-in flag
ymattw added a commit to ymattw/rsyslog that referenced this issue Dec 3, 2015
@ymattw
Reopen truncated file with opt-in flag 'reopenOnTruncate'
5040b3e 
Attempt to fix rsyslog#511.  This is an enhanced version based on
rsyslog#514, works fine for us so far.
As discussed before, I added an opt-in flag 'reopenOnTruncate' and
default is "off".
@ymattw ymattw mentioned this issue Dec 3, 2015
Merged
ymattw added a commit to ymattw/rsyslog that referenced this issue Dec 3, 2015
@ymattw
Reopen truncated file with opt-in flag 'reopenOnTruncate'
ca79a68 
Attempt to fix rsyslog#511.  This is an enhanced version based on
rsyslog#514, works fine for us so far.
As discussed before, I added an opt-in flag 'reopenOnTruncate' and
default is "off".
@ymattw ymattw mentioned this issue Jan 6, 2016
Closed
@orls orls mentioned this issue Jul 13, 2016
Closed
@lock
Copy link

lock bot commented Dec 27, 2019

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@lock lock bot locked as resolved and limited conversation to collaborators Dec 27, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
1 participant
@ymattw