[NIFI-8114] Timer-driven ListFile processor sometimes doesn't start

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.11.4
• Component/s: Extensions
• Labels: crondriven listfile processor
• Environment: Nifi on kunernates
• Assignee: Unassigned
• Reporter: Annalisa Asta
• Created: 05/Jan/21 16:26
• Updated: 17/Feb/23 16:17

Description

I have a nifi flow doing a list/fetch file. ListFile processor is scheduled using a CRON Driven strategy every day at 10:45 (0 45 10 * * ?). My problem is that sometimes this processor doesn't start even if the source directory contains file to list and files timestamp is greater than timestamp store in state (I use tracking timestamp strategy). If I stop the processor, change the scheduling time and start then it works.

• Today I set log level to DEBUG for listFile class in logback.xml and at 10:45 obtain these log lines:

2021-01-05 10:45:00,001 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Returning CLUSTER State: StandardStateMap[version=55, va
lues={id.0=/opt/datafiles/ERMES/2021/01/04/CM_OWNER_1.CMT_DOMANDE_ACC_20210104-07_16_18.csv, processed.timestamp=1609740980291, listing.timestamp=1609740980291}]
2021-01-05 10:45:00,001 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] has chosen to yield its resources; will not be scheduled
to run again for 1000 milliseconds

Files didn't listed.

• Then I stop the processor, modify the scheduling time to 10:50 and then start it:

2021-01-05 10:48:17,369 INFO [NiFi Web Server-1888443] o.a.n.c.s.StandardProcessScheduler Stopping ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf]
2021-01-05 10:48:17,369 INFO [NiFi Web Server-1888443] o.a.n.controller.StandardProcessorNode Stopping processor: ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf]
2021-01-05 10:48:17,369 INFO [Timer-Driven Process Thread-7] o.a.n.c.scheduling.QuartzSchedulingAgent Stopped scheduling ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] to run

2021-01-05 10:48:30,370 INFO [Flow Service Tasks Thread-2] o.a.nifi.controller.StandardFlowService Saved flow controller org.apache.nifi.controller.FlowController@2ab3a38b // Another save pending = false
2021-01-05 10:48:30,596 INFO [NiFi Web Server-1888901] o.a.n.c.s.StandardProcessScheduler Starting ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf]
2021-01-05 10:48:30,596 INFO [NiFi Web Server-1888901] o.a.n.controller.StandardProcessorNode Starting ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf]
2021-01-05 10:48:30,597 DEBUG [Timer-Driven Process Thread-5] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Returning CLUSTER State: StandardStateMap[version=55, va
lues={id.0=/opt/datafiles/ERMES/2021/01/04/CM_OWNER_1.CMT_DOMANDE_ACC_20210104-07_16_18.csv, processed.timestamp=1609740980291, listing.timestamp=1609740980291}]
2021-01-05 10:48:30,597 INFO [Timer-Driven Process Thread-5] o.a.n.c.scheduling.QuartzSchedulingAgent Scheduled ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] to run with 1 threads on schedule 0 50 10 *
* ?

• And at 10:50 it seems to work:

2021-01-05 10:50:00,003 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Over the past 0 seconds, for Operation 'RETRIEVE_BASIC_A
TTRIBUTES' there were no operations performed
2021-01-05 10:50:00,003 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Over the past 0 seconds, for Operation 'RETRIEVE_OWNER_A
TTRIBUTES' there were no operations performed
2021-01-05 10:50:00,003 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Over the past 0 seconds, for Operation 'RETRIEVE_POSIX_A
TTRIBUTES' there were no operations performed
2021-01-05 10:50:00,004 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Over the past 0 seconds, for Operation 'CHECK_HIDDEN' th
ere were no operations performed
2021-01-05 10:50:00,004 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Over the past 0 seconds, for Operation 'CHECK_READABLE'
there were no operations performed
2021-01-05 10:50:00,004 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Over the past 0 seconds, for Operation 'FILTER' there we
re no operations performed
2021-01-05 10:50:00,004 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Over the past 0 seconds, for Operation 'RETRIEVE_NEXT_FI
LE_FROM_OS' there were no operations performed
2021-01-05 10:50:00,167 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Took 166 milliseconds to perform listing and gather 27 e
ntries
2021-01-05 10:50:00,177 INFO [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Successfully created listing with 27 new objects
2021-01-05 10:50:00,180 DEBUG [Timer-Driven Process Thread-7] o.a.nifi.processors.standard.ListFile ListFile[id=5b8735a7-484a-19e7-957e-9a51673c4eaf] Setting CLUSTER State to

{id.0=/opt/datafiles/ERMES/2021 /01/05/CM_OWNER_1.CMT_DOMANDE_ACC_20210105-07_16_14.csv, processed.timestamp=1609827375913, listing.timestamp=1609827375913}

 

 

 

Issue Links

• is fixed by: NIFI-11196 Add missing primary node only restriction to ListFile processor