MergeContent error on restart - not the most recent flow file in this session

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

MergeContent error on restart - not the most recent flow file in this session

bmichaud
This error occurred in NiFi 1.1.1 (single node) right after an upgrade from 1.1.0, so I thought it was due to the upgrade, but now I see that it happens if I restart as well and there is data in the flow.

This MergeContent processor is sorting incoming FlowFiles into bins based on a correlation attribute and dumping out the accumulated uber-FlowFile after one hour or 500K messages are accumulated.

Questions:
(1) Should I clear out all the flow files from the flow (terminate intake and let everything drain out)?
(2) Will data be lost when this error occurs?

Error:
-------
2017-01-11 10:53:39,561 WARN [Timer-Driven Process Thread-9] o.a.n.processors.standard.MergeContent MergeContent[id=b9898788-1c11-45d9-8646-44b1dceb92d5] Processor Administratively Yielded for 1 sec due to processing failure
2017-01-11 10:53:39,561 WARN [Timer-Driven Process Thread-9] o.a.n.c.t.ContinuallyRunProcessorTask Administratively Yielding MergeContent[id=b9898788-1c11-45d9-8646-44b1dceb92d5] due to uncaught Exception: org.apache.nifi.processor.exception.FlowFileHandlingException: StandardFlowFileRecord[uuid=07f3d75a-3347-45da-8dd4-fecf775d1dcf,claim=StandardContentClaim [resourceClaim=StandardResourceClaim[id=1484151577298-1971, container=default, section=947], offset=566526, length=64],offset=0,name=8551433629757608.tsv,size=64] is not the most recent version of this FlowFile within this session (StandardProcessSession[id=133767])
2017-01-11 10:53:39,563 WARN [Timer-Driven Process Thread-9] o.a.n.c.t.ContinuallyRunProcessorTask
org.apache.nifi.processor.exception.FlowFileHandlingException: StandardFlowFileRecord[uuid=07f3d75a-3347-45da-8dd4-fecf775d1dcf,claim=StandardContentClaim [resourceClaim=StandardResourceClaim[id=1484151577298-1971, container=default, section=947], offset=566526, length=64],offset=0,name=8551433629757608.tsv,size=64] is not the most recent version of this FlowFile within this session (StandardProcessSession[id=133767])
        at org.apache.nifi.controller.repository.StandardProcessSession.migrate(StandardProcessSession.java:1121) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.repository.StandardProcessSession.migrate(StandardProcessSession.java:1102) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.processor.util.bin.Bin.offer(Bin.java:142) ~[na:na]
        at org.apache.nifi.processor.util.bin.BinManager.offer(BinManager.java:194) ~[na:na]
        at org.apache.nifi.processor.util.bin.BinFiles.binFlowFiles(BinFiles.java:279) ~[na:na]
        at org.apache.nifi.processor.util.bin.BinFiles.onTrigger(BinFiles.java:178) ~[na:na]
        at org.apache.nifi.controller.StandardProcessorNode.onTrigger(StandardProcessorNode.java:1099) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.tasks.ContinuallyRunProcessorTask.call(ContinuallyRunProcessorTask.java:136) [nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.tasks.ContinuallyRunProcessorTask.call(ContinuallyRunProcessorTask.java:47) [nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.scheduling.TimerDrivenSchedulingAgent$1.run(TimerDrivenSchedulingAgent.java:132) [nifi-framework-core-1.1.0.jar:1.1.0]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_65]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [na:1.8.0_65]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_65]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_65]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
Reply | Threaded
Open this post in threaded view
|

Re: MergeContent error on restart - not the most recent flow file in this session

Mark Payne
Hi Ben,

I've not seen this issue, but I created a JIRA [1] to address it. Will try to replicate it locally and see
if I can understand what is happening. When this happens, do you see the processor continually
spewing this Exception, rolling back, and trying again?

This error itself would not result in data loss. However, clearing the queue certainly would.

Thanks
-Mark


[1] https://issues.apache.org/jira/browse/NIFI-3329




On Jan 11, 2017, at 1:21 PM, bmichaud <[hidden email]<mailto:[hidden email]>> wrote:

This error occurred in NiFi 1.1.1 (single node) right after an upgrade from
1.1.0, so I thought it was due to the upgrade, but now I see that it happens
if I restart as well and there is data in the flow.

This MergeContent processor is sorting incoming FlowFiles into bins based on
a correlation attribute and dumping out the accumulated uber-FlowFile after
one hour or 500K messages are accumulated.

Questions:
(1) Should I clear out all the flow files from the flow (terminate intake
and let everything drain out)?
(2) Will data be lost when this error occurs?

Error:
-------
2017-01-11 10:53:39,561 WARN [Timer-Driven Process Thread-9]
o.a.n.processors.standard.MergeContent
MergeContent[id=b9898788-1c11-45d9-8646-44b1dceb92d5] Processor
Administratively Yielded for 1 sec due to processing failure
2017-01-11 10:53:39,561 WARN [Timer-Driven Process Thread-9]
o.a.n.c.t.ContinuallyRunProcessorTask Administratively Yielding
MergeContent[id=b9898788-1c11-45d9-8646-44b1dceb92d5] due to uncaught
Exception: org.apache.nifi.processor.exception.FlowFileHandlingException:
StandardFlowFileRecord[uuid=07f3d75a-3347-45da-8dd4-fecf775d1dcf,claim=StandardContentClaim
[resourceClaim=StandardResourceClaim[id=1484151577298-1971,
container=default, section=947], offset=566526,
length=64],offset=0,name=8551433629757608.tsv,size=64] is not the most
recent version of this FlowFile within this session
(StandardProcessSession[id=133767])
2017-01-11 10:53:39,563 WARN [Timer-Driven Process Thread-9]
o.a.n.c.t.ContinuallyRunProcessorTask
org.apache.nifi.processor.exception.FlowFileHandlingException:
StandardFlowFileRecord[uuid=07f3d75a-3347-45da-8dd4-fecf775d1dcf,claim=StandardContentClaim
[resourceClaim=StandardResourceClaim[id=1484151577298-1971,
container=default, section=947], offset=566526,
length=64],offset=0,name=8551433629757608.tsv,size=64] is not the most
recent version of this FlowFile within this session
(StandardProcessSession[id=133767])
       at
org.apache.nifi.controller.repository.StandardProcessSession.migrate(StandardProcessSession.java:1121)
~[nifi-framework-core-1.1.0.jar:1.1.0]
       at
org.apache.nifi.controller.repository.StandardProcessSession.migrate(StandardProcessSession.java:1102)
~[nifi-framework-core-1.1.0.jar:1.1.0]
       at org.apache.nifi.processor.util.bin.Bin.offer(Bin.java:142)
~[na:na]
       at
org.apache.nifi.processor.util.bin.BinManager.offer(BinManager.java:194)
~[na:na]
       at
org.apache.nifi.processor.util.bin.BinFiles.binFlowFiles(BinFiles.java:279)
~[na:na]
       at
org.apache.nifi.processor.util.bin.BinFiles.onTrigger(BinFiles.java:178)
~[na:na]
       at
org.apache.nifi.controller.StandardProcessorNode.onTrigger(StandardProcessorNode.java:1099)
~[nifi-framework-core-1.1.0.jar:1.1.0]
       at
org.apache.nifi.controller.tasks.ContinuallyRunProcessorTask.call(ContinuallyRunProcessorTask.java:136)
[nifi-framework-core-1.1.0.jar:1.1.0]
       at
org.apache.nifi.controller.tasks.ContinuallyRunProcessorTask.call(ContinuallyRunProcessorTask.java:47)
[nifi-framework-core-1.1.0.jar:1.1.0]
       at
org.apache.nifi.controller.scheduling.TimerDrivenSchedulingAgent$1.run(TimerDrivenSchedulingAgent.java:132)
[nifi-framework-core-1.1.0.jar:1.1.0]
       at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[na:1.8.0_65]
       at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[na:1.8.0_65]
       at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
[na:1.8.0_65]
       at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
[na:1.8.0_65]
       at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[na:1.8.0_65]
       at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_65]
       at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]




--
View this message in context: http://apache-nifi-developer-list.39713.n7.nabble.com/MergeContent-error-on-restart-not-the-most-recent-flow-file-in-this-session-tp14436.html
Sent from the Apache NiFi Developer List mailing list archive at Nabble.com<http://Nabble.com>.

Reply | Threaded
Open this post in threaded view
|

Re: MergeContent error on restart - not the most recent flow file in this session

bmichaud
Mark Payne wrote
I've not seen this issue, but I created a JIRA [1] to address it. Will try to replicate it locally and see
if I can understand what is happening. When this happens, do you see the processor continually
spewing this Exception, rolling back, and trying again?
Thank you. I do see the same exception many times, repeatedly. And it finally failed like this:

2017-01-11 14:06:47,157 INFO [StandardProcessScheduler Thread-8] o.a.n.c.r.WriteAheadFlowFileRepository Successfully swapped out 10000 FlowFiles from
FlowFileQueue[id=536e3794-0157-1000-8f4b-303d154b73eb] to Swap File /app_2/runtime/nifi/./flowfile_repository/swap/1484165206865-536e3794-0157-1000-8f
4b-303d154b73eb-3b22b90e-a691-4e8b-9474-64159092d8a7.swap
2017-01-11 14:06:47,291 INFO [StandardProcessScheduler Thread-6] o.a.n.c.r.WriteAheadFlowFileRepository Successfully swapped out 10000 FlowFiles from
FlowFileQueue[id=e6af072c-fda8-4596-3baa-67a4f0dd0691] to Swap File /app_2/runtime/nifi/./flowfile_repository/swap/1484165207150-e6af072c-fda8-4596-3b
aa-67a4f0dd0691-e7e015d9-b13a-4542-acb9-c143dfafc1eb.swap
2017-01-11 14:06:47,334 INFO [StandardProcessScheduler Thread-8] o.a.n.c.r.WriteAheadFlowFileRepository Successfully swapped out 10000 FlowFiles from
FlowFileQueue[id=536e3794-0157-1000-8f4b-303d154b73eb] to Swap File /app_2/runtime/nifi/./flowfile_repository/swap/1484165207232-536e3794-0157-1000-8f4b-303d154b73eb-6fb35722-ef7f-44b6-b930-b875831b6407.swap
2017-01-11 14:06:47,449 INFO [pool-1-thread-1] o.apache.nifi.controller.FlowController Controller has been terminated successfully.
2017-01-11 14:06:47,456 INFO [pool-1-thread-1] o.a.n.w.c.ApplicationStartupContextListener Flow service termination completed.
2017-01-11 14:06:47,457 INFO [pool-1-thread-1] /nifi-api Closing Spring root WebApplicationContext
2017-01-11 14:06:47,465 ERROR [StandardProcessScheduler Thread-6] org.apache.nifi.util.ReflectionUtils Failed while invoking annotated method 'public final void org.apache.nifi.processor.util.bin.BinFiles.resetState()' with arguments '[]'.
java.lang.reflect.InvocationTargetException: null
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_65]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_65]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_65]
        at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_65]
        at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotations(ReflectionUtils.java:137) [nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotations(ReflectionUtils.java:125) [nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.util.ReflectionUtils.quietlyInvokeMethodsWithAnnotations(ReflectionUtils.java:233) [nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.util.ReflectionUtils.quietlyInvokeMethodsWithAnnotation(ReflectionUtils.java:85) [nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.StandardProcessorNode$2.run(StandardProcessorNode.java:1373) [nifi-framework-core-1.1.0.jar:1.1.0]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_65]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_65]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_65]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_65]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
Caused by: java.lang.IllegalStateException: Partition is closed
        at org.wali.MinimalLockingWriteAheadLog$Partition.update(MinimalLockingWriteAheadLog.java:945) ~[nifi-write-ahead-log-1.1.0.jar:1.1.0]
        at org.wali.MinimalLockingWriteAheadLog.update(MinimalLockingWriteAheadLog.java:238) ~[nifi-write-ahead-log-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.repository.WriteAheadFlowFileRepository.swapFlowFilesOut(WriteAheadFlowFileRepository.java:318) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.FileSystemSwapManager.swapOut(FileSystemSwapManager.java:135) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.StandardFlowFileQueue.writeSwapFilesIfNecessary(StandardFlowFileQueue.java:582) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.StandardFlowFileQueue.put(StandardFlowFileQueue.java:282) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.repository.StandardProcessSession.rollback(StandardProcessSession.java:959) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.repository.StandardProcessSession.rollback(StandardProcessSession.java:882) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.controller.repository.StandardProcessSession.rollback(StandardProcessSession.java:877) ~[nifi-framework-core-1.1.0.jar:1.1.0]
        at org.apache.nifi.processor.util.bin.BinManager.purge(BinManager.java:65) ~[nifi-processor-utils-1.1.0.jar:1.1.0]
        at org.apache.nifi.processor.util.bin.BinFiles.resetState(BinFiles.java:111) ~[nifi-processor-utils-1.1.0.jar:1.1.0]
        ... 16 common frames omitted
Reply | Threaded
Open this post in threaded view
|

Re: MergeContent error on restart - not the most recent flow file in this session

bmichaud
This post was updated on .
In reply to this post by Mark Payne
I just realized that I had to recopy the lib folder from the new version (1.1.1), as all the stack traces were referencing 1.1.0 code.

This change where I cannot link symbolically to the latest version of the software is already causing problems. I have to change my deployment and upgrade process because of it.

I am still getting the same errors with the 1.1.1 libraries, however.