Totally didn't realized I accidentally moved this off of the mailing list. Brining it back.
---------- I just realized as well that NiFi is only using Quartz for the CronExpression. I think this bug is due to the logic going on in this block[1]. One thing specifically that worries me is in the CronExpression code here[2]. It sets the milliseconds to 0 when doing the computation and then in NiFi's next line it finds the delay using milliseconds. That said, this code is part of the initial contribution and has been running for many years. I'm surprised this has never come up before. I can write up a Jira ticket for this later today. [1] https://github.com/apache/nifi/blob/c10d11d378ffd7c3044446830e24d50c5befc98a/nifi-nar-bundles/nifi-framework-bundle/nifi-framework/nifi-framework-core/src/main/java/org/apache/nifi/controller/scheduling/QuartzSchedulingAgent.java#L177-L177 [2] https://github.com/quartz-scheduler/quartz/blob/quartz-2.2.1/quartz-core/src/main/java/org/quartz/CronExpression.java#L1170 - - - - - - Joseph Percivall linkedin.com/in/Percivall e: [email protected] On Wednesday, December 21, 2016, 5:33:32 AM EST, Davy De Waele <[email protected]> wrote: Hi, Also on 10.10.5. A colleague of mine has the same issue on his mac. Here is his output 2016-12-21 08:32:00,046 DEBUG [Timer-Driven Process Thread-2] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:34:00 CET 2016 after a delay of 119954 milliseconds 2016-12-21 08:34:00,001 DEBUG [Timer-Driven Process Thread-9] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:36:00 CET 2016 after a delay of 119999 milliseconds 2016-12-21 08:36:00,002 DEBUG [Timer-Driven Process Thread-7] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:38:00 CET 2016 after a delay of 119998 milliseconds 2016-12-21 08:37:59,999 DEBUG [Timer-Driven Process Thread-6] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:38:00 CET 2016 after a delay of 1 milliseconds 2016-12-21 08:38:00,003 DEBUG [Timer-Driven Process Thread-6] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:40:00 CET 2016 after a delay of 119997 milliseconds 2016-12-21 08:40:00,002 DEBUG [Timer-Driven Process Thread-6] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:42:00 CET 2016 after a delay of 119998 milliseconds 2016-12-21 08:42:00,004 DEBUG [Timer-Driven Process Thread-8] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:44:00 CET 2016 after a delay of 119996 milliseconds 2016-12-21 08:44:00,002 DEBUG [Timer-Driven Process Thread-6] o.a.n.c.scheduling.QuartzSchedulingAgent Finished task for GenerateFlowFile[id=20476217-0159-1000-63f4-7a3821b0f21a]; next scheduled time is at Wed Dec 21 08:46:00 CET 2016 after a delay of 119998 milliseconds So it seems that sometimes the schedule is fired too soon. In this case : * processor task fiinished at 08:37:59,999, a result of the job that was scheduled at 08:36:00,002 ( I assume that for some reason this job was scheduled x ms too soon, causing the GenerateFlowFileProcessor to finish the job early) * processor task fiinished at 08:38:00,003, a result of the job that was scheduled at 08:37:59,999 ( this gave the scheduler a window to schedule an additional job that could be completed). I'm running it in a docker container now and don't have any issues. As soon as I run the distribution directly on my mac I can reproduce it. I also just realised that NiFi isn't using Quartz at all for its scheduling.(besides the CronExpression parser class). QuartzSchedulingAgent would make one to believe that scheduling is handled by a Quartz engine. My mac is a pretty std dev laptop. Lots of stuff installed, but nothing that could explain this behavior Should I log a ticket for this, or post this on the mailinglist ? On Tue, Dec 20, 2016 at 5:03 PM, Joe Percivall <[email protected]> wrote: > I am running on a Mac version 10.10.5. I pulled down the 1.1.0 zip, created a > flow with a GenerateFF -> ReplaceText -> LogAttribute (one for success and > one for failure). I configured GenerateFF with a Run Schedule of "0 0/2 * * * > ?" and didn't change anything else. I let it run for over an hour and haven't > seen any errors. > > What version of OSX are your running? Is there anything unusual about your > Mac (other programs running)? Could you post your flow.xml.gz somewhere > (gist.github)? > > As for "cleaning out" a deployment of NiFi, there's a couple other > directories that get created: > run > state > work > > Also to have a truly clean deployment you also have to delete: > flow.xml.gz > the log directory > conf/archive > > Joe > - - - - - - > Joseph Percivall > linkedin.com/in/Percivall > e: [email protected] > > > > On Tuesday, December 20, 2016, 2:27:54 AM EST, Davy De Waele > <[email protected]> wrote: > Hi, > > On what OS did you try reproducing it ? I can now reproduce it very easily on > my mac by doing the following : > * On a clean nifi , place a GenerateFlowFile with cron "0 0/2 * * * ?" > and hook it up a replaceText processor > * Let it run for a while. First couple of runs are usually ok. After a > while it starts messing up. > Doing the same thing on my server (CentOS) never introduces an error. > > With "clean nifi" I'm referring to > * A clean rollout of nifi (untarring the 1.1.0 release, working with the > original config) > * Every restart doing this : > * ${NIFI_HOME}/bin/nifi.sh stop > * rm -rf ${NIFI_HOME}/content_ repository > * rm -rf ${NIFI_HOME}/database_ repository > * rm -rf ${NIFI_HOME}/provenance_ repository > * rm -rf ${NIFI_HOME}/flowfile_ repository > * ${NIFI_HOME}/bin/nifi.sh start > Is there any other state that I'm missing ? > > > > > On Tue, Dec 20, 2016 at 5:54 AM, Davy De Waele <[email protected]> wrote: >> I was meaning to say "I only see other "QuartzSchedulingAgent Scheduled" log >> entries for other componentIds". For this particular componentId >> (192bff4f-0159-1000-fa14- 1e6b66096465) there's just one "Scheduled" entry. >> >> On Tue, Dec 20, 2016 at 5:53 AM, Davy De Waele <[email protected]> wrote: >>> For for that particular componentId. NiFi was also restarted at 22:13. I >>> don't know if any quartz state is being maintained ? Are these quartz jobs >>> persisted somewhere on disk ? >>> I have it both on 1.0.0 and on 1.1.0, albeit only with my flow. >>> I'm trying to find the culprit and will keep you posted. >>> >>> On Tue, Dec 20, 2016 at 1:33 AM, Joe Percivall <[email protected]> >>> wrote: >>>> Well that's odd and nothing jumps out at me in your attached images. In >>>> your logs, do you see any other "QuartzSchedulingAgent Scheduled" log >>>> entries? In theory the other processors shouldn't affect it at all but if >>>> it does that would be an odd/unfortunate bug. >>>> >>>> Are you able to reproduce consistently? I tried to with both 1.1.0 and >>>> 1.0.0 and both worked properly. >>>> >>>> >>>> >>>> Joe >>>> - - - - - - >>>> Joseph Percivall >>>> linkedin.com/in/Percivall >>>> e: [email protected] >>>> >>>> >>>> >>>> On Monday, December 19, 2016, 6:44:40 PM EST, Davy De Waele >>>> <[email protected]> wrote: >>>> >>>> Hi, >>>> I added some debug logging before adding a new GenerateFlowFile processor >>>> with a schedule, starting it, and waiting for it to run for the first time. >>>> Here's what I saw. Notice how the Quartz task was finished twice at the >>>> 22:30 mark. (22:29:59,976 and 22:30:00,006) >>>> >>>> 2016-12-19 22:21:00,840 INFO [StandardProcessScheduler Thread-3] >>>> o.a.n.c.scheduling.QuartzSched ulingAgent Scheduled >>>> GenerateFlowFile[id=192bff4f-0 159-1000-fa14-1e6b66096465] to run with 1 >>>> threads on schedule 0 0/10 * * * ? >>>> >>>> 2016-12-19 22:29:59,976 DEBUG [Timer-Driven Process Thread-10] >>>> o.a.n.c.scheduling.QuartzSched ulingAgent Finished task for >>>> GenerateFlowFile[id=192bff4f-0 159-1000-fa14-1e6b66096465]; next scheduled >>>> time is at Mon Dec 19 22:30:00 UTC 2016 after a delay of 24 milliseconds >>>> >>>> 2016-12-19 22:30:00,006 DEBUG [Timer-Driven Process Thread-3] >>>> o.a.n.c.scheduling.QuartzSched ulingAgent Finished task for >>>> GenerateFlowFile[id=192bff4f-0 159-1000-fa14-1e6b66096465]; next scheduled >>>> time is at Mon Dec 19 22:40:00 UTC 2016 after a delay of 599994 >>>> milliseconds >>>> Any idea if other processors could influence the quartz scheduling of this >>>> particular processor ? I'll try to debug if further >>>> >>>> >>>> >>>> On Mon, Dec 19, 2016 at 5:47 PM, Davy De Waele <[email protected]> wrote: >>>>> Hi, >>>>> >>>>> I'm using nifi 1.0.0 (I'll try it with nifi 1.1.0 this evening). Didn't >>>>> do any special nifi config .... I do have 20+ processors on my >>>>> dashboard, but I've set aside 1 GenerateFlowFile processor + ReplaceText >>>>> processor to simulate it. >>>>> >>>>> For the six fields I read it in the docs : >>>>> >>>>> CRON driven: When using the CRON driven scheduling mode, the Processor is >>>>> scheduled to run periodically, similar to the Timer driven scheduling >>>>> mode. However, the CRON driven mode provides significantly more >>>>> flexibility at the expense of increasing the complexity of the >>>>> configuration. This value is made up of six fields, each separated by a >>>>> space. These fields include:.... >>>>> >>>>> Here are some screenshots >>>>> >>>>> Sorry to bother you with all of this .... I'll update the mailinglist as >>>>> soon as I have found something..... >>>>> >>>>> >>>>> >>>>> On Mon, Dec 19, 2016 at 4:50 PM, Joe Percivall <[email protected]> >>>>> wrote: >>>>>> Hello, >>>>>> >>>>>> Where do you see that you need a minimum of 6 fields? >>>>>> >>>>>> You're right about my initial CRON job running every second when the >>>>>> minute is divisible by 10. I switched it to "0 */10 * * * ?" and it >>>>>> works exactly as expected (runs once every ten minutes: 0, 10, 20, 30, >>>>>> 40, 50). >>>>>> >>>>>> >>>>>> I ran it for an hour+ and didn't see any of the double execution you >>>>>> mention. Is there anything special about your deployment, what version >>>>>> are you using, and where did you get those times? >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> Joe >>>>>> >>>>>> - - - - - - >>>>>> Joseph Percivall >>>>>> linkedin.com/in/Percivall >>>>>> e: [email protected] >>>>>> >>>>>> >>>>>> >>>>>> On Monday, December 19, 2016, 2:47:11 AM EST, ddewaele >>>>>> <[email protected]> wrote: >>>>>> Hi, >>>>>> >>>>>> I think you need to have a minimum of 6 fields (and optionally 7). I also >>>>>> think the cron definition below would be executed 60 times (every second >>>>>> due >>>>>> to the "*") every 10 minutes (due to the "0/10"). >>>>>> >>>>>> 60 times from xx:10:00 to xx:10:59 >>>>>> 60 times from xx:20:00 to xx:20:59 >>>>>> ... >>>>>> >>>>>> But even with this cron I'm seeing a duplicate when the schedule kicks in >>>>>> >>>>>> 12/19/2016 07:40:00.000 UTC >>>>>> 12/19/2016 07:39:59.972 UTC >>>>>> >>>>>> >>>>>> Joe Percivall wrote >>>>>> >>>>>>> Hello, >>>>>>> >>>>>>> Based on this[1] SO question, I believe you need to change your CRON >>>>>>> schedule to be "* */10 * * *". >>>>>>> >>>>>>> [1] >>>>>>> http://stackoverflow.com/quest ions/10401344/quartz-cron- >>>>>>> trigger-runs-twice >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> -- >>>>>> View this message in context: http://apache-nifi-users-list. >>>>>> 2361937.n4.nabble.com/NiFi-Cro n-scheduling-tp481p486. htmlSent from the >>>>>> Apache NiFi Users List mailing list archive at Nabble.com. >>>>> >>>>> >>>> >>> >>> >> >>
