Annalisa Asta created NIFI-8114:
-----------------------------------
Summary: Timer-driven ListFile processor sometimes doesn't start
Key: NIFI-8114
URL: https://issues.apache.org/jira/browse/NIFI-8114
Project: Apache NiFi
Issue Type: Bug
Components: Extensions
Affects Versions: 1.11.4
Environment: Nifi on kunernates
Reporter: Annalisa Asta
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:
{color:#FF0000}2021-01-05 10:45:00,001{color} 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] {color:#FF0000}has chosen to
yield its resources; will not be scheduled
to run again for 1000 milliseconds{color}
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}]
{color:#FF0000}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 *
* ?{color}
* 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
{color:#FF0000}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{color}
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}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
