[
https://issues.apache.org/jira/browse/NIFI-1171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15011494#comment-15011494
]
Bryan Bende commented on NIFI-1171:
-----------------------------------
So I applied the TailFile portion of NIFI-1165 and this patch, and have been
testing... Using the same test scenario from before, but this time TailFile
scheduled to run every 60 seconds, and the Solr log rolling more frequently.
Here are the TailFile related logs for one test...
{code}
2015-11-18 11:57:22,492 INFO [pool-25-thread-5]
o.a.n.c.s.TimerDrivenSchedulingAgent Scheduled
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] to run with 1 threads
2015-11-18 11:57:22,512 DEBUG [Timer-Driven Process Thread-5]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Created RandomAccessFile
sun.nio.ch.FileChannelImpl@4b6a7528 for
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log
2015-11-18 11:57:22,530 DEBUG [Timer-Driven Process Thread-5]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Read 244 lines; repositioning
reader from 48291 to 48291
2015-11-18 11:57:22,537 DEBUG [Timer-Driven Process Thread-5]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Created
StandardFlowFileRecord[uuid=be8fec41-0dde-481a-9ea5-fae651fd94e2,claim=StandardContentClaim
[resourceClaim=StandardResourceClaim[id=1447865842522-2, container=default,
section=2], offset=0, length=48291],offset=0,name=solr.0-48291.log,size=48291]
and routed to success
2015-11-18 11:57:22,553 DEBUG [Timer-Driven Process Thread-5]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Persisting state
TailFileState[filename=/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log,
position=48291, timestamp=1447865835000, checksum=3153858218] to
./conf/state/7b1f86e1-8eec-4179-ad1c-a52dd16d1cee
2015-11-18 11:58:22,555 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Found rolled off file
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.3 but its last modified
timestamp is before the cutoff (Last Mod = 1447865834000, Cutoff =
1447865835000) so will not consume it
2015-11-18 11:58:22,555 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Tailed file has rotated.
Rolled off files to check for un-consumed modifications:
[/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.2,
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.1]
2015-11-18 11:58:22,556 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Checksum for
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.2 matched expected
checksum. Will skip first 48291 bytes
2015-11-18 11:58:22,556 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Consuming more data from
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.2
2015-11-18 11:58:22,556 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Closed FileChannel
sun.nio.ch.FileChannelImpl@4b6a7528
2015-11-18 11:58:22,556 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Persisting state
TailFileState[filename=/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log,
position=0, timestamp=1447865845001, checksum=null] to
./conf/state/7b1f86e1-8eec-4179-ad1c-a52dd16d1cee
2015-11-18 11:58:22,558 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Persisting state
TailFileState[filename=/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log,
position=0, timestamp=1447865879001, checksum=null] to
./conf/state/7b1f86e1-8eec-4179-ad1c-a52dd16d1cee
2015-11-18 11:58:22,560 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Fully consumed
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.1
2015-11-18 11:58:22,560 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Closed RandomAccessFile
sun.nio.ch.FileChannelImpl@4b6a7528
2015-11-18 11:58:22,560 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Created RandomAccessFile
sun.nio.ch.FileChannelImpl@7b6ad8e2 for
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log
2015-11-18 11:58:22,562 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Read 107 lines; repositioning
reader from 34317 to 34317
2015-11-18 11:58:22,562 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Created
StandardFlowFileRecord[uuid=b7611f86-11be-4319-90b5-eb9a4266c51a,claim=StandardContentClaim
[resourceClaim=StandardResourceClaim[id=1447865842522-2, container=default,
section=2], offset=51325,
length=34317],offset=0,name=solr.0-34317.log,size=34317] and routed to success
2015-11-18 11:58:22,563 DEBUG [Timer-Driven Process Thread-4]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Persisting state
TailFileState[filename=/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log,
position=34317, timestamp=1447865902000, checksum=3130106624] to
./conf/state/7b1f86e1-8eec-4179-ad1c-a52dd16d1cee
2015-11-18 11:59:22,563 DEBUG [Timer-Driven Process Thread-2]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Read 49 lines; repositioning
reader from 51274 to 51274
2015-11-18 11:59:22,563 DEBUG [Timer-Driven Process Thread-2]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Created
StandardFlowFileRecord[uuid=dbaa65cc-0adf-4e79-abd0-5b3f36a54ba8,claim=StandardContentClaim
[resourceClaim=StandardResourceClaim[id=1447865842521-1, container=default,
section=1], offset=67267,
length=16957],offset=0,name=solr.34317-51274.log,size=16957] and routed to
success
2015-11-18 11:59:22,564 DEBUG [Timer-Driven Process Thread-2]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Persisting state
TailFileState[filename=/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log,
position=51274, timestamp=1447865962000, checksum=727567662] to
./conf/state/7b1f86e1-8eec-4179-ad1c-a52dd16d1cee
2015-11-18 12:00:22,563 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Found rolled off file
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.2 but its last modified
timestamp is before the cutoff (Last Mod = 1447865930000, Cutoff =
1447865962000) so will not consume it
2015-11-18 12:00:22,596 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Found rolled off file
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.3 but its last modified
timestamp is before the cutoff (Last Mod = 1447865902000, Cutoff =
1447865962000) so will not consume it
2015-11-18 12:00:22,596 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Found rolled off file
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.4 but its last modified
timestamp is before the cutoff (Last Mod = 1447865879000, Cutoff =
1447865962000) so will not consume it
2015-11-18 12:00:22,596 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Found rolled off file
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.5 but its last modified
timestamp is before the cutoff (Last Mod = 1447865845000, Cutoff =
1447865962000) so will not consume it
2015-11-18 12:00:22,596 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Found rolled off file
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.6 but its last modified
timestamp is before the cutoff (Last Mod = 1447865834000, Cutoff =
1447865962000) so will not consume it
2015-11-18 12:00:22,596 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Tailed file has rotated.
Rolled off files to check for un-consumed modifications:
[/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.1]
2015-11-18 12:00:22,596 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Last rolled over file
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log.1 is larger than our
last position; will consume data from it after offset 51274
2015-11-18 12:00:22,596 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Persisting state
TailFileState[filename=/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log,
position=51274, timestamp=1447865962000, checksum=727567662] to
./conf/state/7b1f86e1-8eec-4179-ad1c-a52dd16d1cee
2015-11-18 12:00:22,597 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Closed RandomAccessFile
sun.nio.ch.FileChannelImpl@7b6ad8e2
2015-11-18 12:00:22,598 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Created RandomAccessFile
sun.nio.ch.FileChannelImpl@4cdb7c2f for
/Users/bbende/Dev/solr/solr-5.3.1/server/logs/solr.log
2015-11-18 12:00:22,598 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Read 87 lines; repositioning
reader from 25694 to 25694
2015-11-18 12:00:22,599 DEBUG [Timer-Driven Process Thread-6]
o.a.nifi.processors.standard.TailFile
TailFile[id=dbd6a37b-df7a-49e2-9870-b5ecebf0c421] Created
StandardFlowFileRecord[uuid=756ef843-cd75-4278-b31e-c6c11f6eb4af,claim=StandardContentClaim
[resourceClaim=StandardResourceClaim[id=1447865842522-2, container=default,
section=2], offset=102693,
length=25694],offset=0,name=solr.0-25694.log,size=25694] and routed to success
{code}
* At 11:57 it is the initial execution when I started the whole flow, so it
sees the initial solr logs, but there haven't been any inserts to find yet so
nothing to do.
* At 11:58 it found the 60 updates from the last minute and all was good.
* At 11:59 it should have found another 60 updates for a total of 120, but
looks like it might not have found any here
* I then stopped the part of the flow that generates updates and let the
processor execute one more time which was the execution at 12:00
* At the end there were 137 updates produced, but only 73 found from tailing
the log, with the gap appearing to come from the execution at 11:58.
I will keep investigating to see if there is a more defined pattern.
> If a file rolls over multiple times between invocations of TailFile,
> Processor doesn't pick up all changes
> ----------------------------------------------------------------------------------------------------------
>
> Key: NIFI-1171
> URL: https://issues.apache.org/jira/browse/NIFI-1171
> Project: Apache NiFi
> Issue Type: Bug
> Components: Extensions
> Affects Versions: 0.4.0
> Reporter: Mark Payne
> Assignee: Mark Payne
> Fix For: 0.4.0
>
> Attachments:
> 0001-NIFI-1171-If-multiple-rollovers-occur-while-the-Proc.patch
>
>
> If TailFile is scheduled to run less often, say once per minute, and the file
> that it is tailing rolls over multiple times, it does not pick up all of the
> changes. We need to ensure that it picks up all of the changes to the log
> file in this case.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
