Problem/Motivation

Over in #3284704: Test that events are being properly triggered there is a proposed solution to properly calculate the first due time for a cron event that had never been executed ever before. In a code review comment we have this:

Choosing "yesterday" as a fallback seems a bit arbitrary. Why not using zero instead?

If the comment was about "weekly" or even "annually" instead of "daily", then the fallback timestamp should be at that time initially.

But the example case could also be "hourly", then the fallback needed to be current time - 3600.

None of those would ever match all possible use cases, therefore the fallback 0 indicates that this job had not triggered before. That way, the cronjob is always due if it wasn't executed ever before.

One could argue that this may execute an e.g. weekly task which should execute on Mondays but the job was created on a Tuesday. Then it should not execute before next Monday.

Proposed resolution

This could be mitigated by calculating the time between the next two execution timestamps and if that's larger than the difference between the next and the current time, then it wouldn't be due yet. Maybe something like this:

    if (!$lastRun) {
      $dtNext1 = new \DateTime();
      $dtNext1
        ->setTimezone(new \DateTimeZone('UTC'))
        ->setTimestamp($currentTime);
      $next1Time = $cron->getNextRunDate($dtNext1)->getTimestamp();
      $dtNext2 = new \DateTime();
      $dtNext2
        ->setTimezone(new \DateTimeZone('UTC'))
        ->setTimestamp($next1Time);
      $next2Time = $cron->getNextRunDate($dtNext2)->getTimestamp();
      if (($next2Time - $next1Time) > ($next1Time - $currentTime)) {
        $lastRun = $currentTime;
      }
    }

Issue fork eca-3291157

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

jurgenhaas created an issue. See original summary.

mxh’s picture

One approach to find the right fallback value (and maybe required behavior / calculation) could be to create a test up-front, describing possible input with according expected output. Example:

Input: Create new job that runs on every Monday, being created on a different day. Expected output: It must only start at the very next Monday.
Input: Create new job that runs on daily basis. Expected output: The job's first run would be on the same day it got created.
... and so on. Of course this test should then cover basically the most common cases, like hourly, daily, weekly etc.

Having such a black-box test should easily get us to the solution.

jurgenhaas’s picture

Assigned: Unassigned » jurgenhaas

  • jurgenhaas committed 8719bfc on 1.0.x
    Issue #3291157: Review due time calculation for new cron events
    

jurgenhaas’s picture

Assigned: jurgenhaas » Unassigned
Status: Active » Needs review

Please have a look into this MR, it provides the back-box and a data provider, where we can easily add all additional use cases to make sure that we're doing the right thing.

mxh’s picture

Something is wrong with that MR, there is a commit that includes the test, but in the MR it's not visible.

mxh’s picture

I've manually restored your commit in this branch, hope the copy-paste was right.

mxh’s picture

Status: Needs review » Needs work

I'd suggest that we test for the applies method of CronEvent. Have added the test data from the already existing Kernel test into that Unit test. There it can be seen that the current approach fails for "* * * * *", which should always run on first time.

jurgenhaas’s picture

Status: Needs work » Needs review

I've manually restored your commit in this branch, hope the copy-paste was right.

Thanks for fixing this, I guess this happened because I had accidentally committed to the dev branch instead of the MR and then reverted that commit after I had also committed to the MR. That must have screwed up things.

I'd suggest that we test for the applies method of CronEvent. Have added the test data from the already existing Kernel test into that Unit test.

This is good. I assume this is in addition to the unit test I had already prepared.

There it can be seen that the current approach fails for "* * * * *", which should always run on first time.

This is most likely because of return $currentTime > $this->getNextRunTimestamp($lastRun, $currentTime, $frequency); - the comparison there should be >=.

However, my proposal for handling initial due calculation has another weakness: it only works for regular schedules like every week, every day or every hour, etc. But for infrequent schedules it would work that well, e.g. if a schedule is defined for Monday, Tuesday and Friday. That may result in a wrong calculation for the initial execution of that event. Everything else would be just fine as it is.

Thinking about it again, the only reliable solution would be if we knew the date and time when the ECA config entity containing that event were created. We could use that timestamp as the lastRunTimestamp and the existing calculation would come back with the always correct timestamp for the next due time.

As config entities don't have create and update properties, we would have to store the timestamp to the ECA state when the ECA entity gets saved and if no such key exists yet in the state environment. To achieve that, eca_base may have to hook into the entity save event and do its magic. Thoughts?

jurgenhaas’s picture

This is most likely because of return $currentTime > $this->getNextRunTimestamp($lastRun, $currentTime, $frequency); - the comparison there should be >=.

This and 2 more adjustments were required to now have all tests passing:

  • When getting the current timestamp in isDue we need to cut off seconds so that we have a timestamp for a full minute. Otherwise the current time is something like 10:20:05 and then the next due timestamp would be 10:21:00
  • When falling back to current time on getNextRunTimestamp, we have to go back 1 second as well. That would give us a fallback timestamp of 10:19:59 which will then give us a due timestamp of 10:20:00
mxh’s picture

As config entities don't have create and update properties, we would have to store the timestamp to the ECA state when the ECA entity gets saved and if no such key exists yet in the state environment. To achieve that, eca_base may have to hook into the entity save event and do its magic. Thoughts?

Either a hook, or ECA gives plugin configurations a chance to do something on entity-level savings, defined by an interface.

jurgenhaas’s picture

Either a hook, or ECA gives plugin configurations a chance to do something on entity-level savings, defined by an interface.

Implemented an interface EcaAddPluginInterface which is called for all plugins when saving an ECA entity. This then also covers the scenario when importing a model or when enabling a module which comes with an ECA config entity.

All existing tests pass, so this looks solid now - at least I hope so.

mxh’s picture

I've noticed that my previous Kernel test was using a wrong configuration, I've adjusted that Kernel test accordingly and made the same adjustment in the Unit test.

I've added some further example frequency into the data provider. I'm not sure about the current expectation of the return value of the applies method, but I've added my subjective expectations there. Two of them currently fail - but my expectation could be wrong as it currently seems it's a subjective expectation. Maybe you could have a look at them and adjust the expected return values to your expectations - or the current implementation still has something missing. But at least I think once we have those examples correctly covered, this one should be good to go.

mxh’s picture

Status: Needs review » Needs work

Some minor nitpicks for the interface name and place of calling the interface method from the ECA entity. The added test assertions need a second look and possibly adjustment regarding expected return value. Of course if you find another reasonable use case to add to the data provider, feel free to add.

jurgenhaas’s picture

Status: Needs work » Needs review

Regarding the 2 failed tests, when debugging isDue, here is what we get:

$current = '2022-06-18 15:00';
$last = '2022-06-18 14:00';
$next = '2022-06-19 00:00';

So, the calculation of the next due time is exactly what we expect. What's not correct yet is the current time and that seems do be an issue with the mocked state service. I'll have a look.

jurgenhaas’s picture

Confirmed for the test "Every minute today.". When adding timezone to the mock like this

    $now = new \DateTime('now', new \DateTimeZone('UTC'));
    $today_0000am = new DateTime($now->format('Y-m-d 00:00:01'), new \DateTimeZone('UTC'));
    $today_0100am = new DateTime($now->format('Y-m-d 01:00:01'), new \DateTimeZone('UTC'));

then that test behaves as expected. But now 3 others are failing. Still looking.

jurgenhaas’s picture

['30 0 * * *', FALSE, 'Every day at 00:30 AM.'], needs to be ['30 0 * * *', TRUE, 'Every day at 00:30 AM.'], as last run was at 0:00 and this one should execute at 0:30.

['1 0 * * ' . $weekday_today, FALSE, 'Today at 00:01 AM.'], needs to be ['1 0 * * ' . $weekday_today, TRUE, 'Today at 00:01 AM.'], as last run was at 0:00 and this one should execute at 0:01.

And the same applies for "Today at 00:30 AM." and "Today at 01:00 AM."

I guess, what you wanted to test, requires a one hour shift in the mock for both timestamps. Then I only have to adjust the test "Today at 02:00 AM." to get everything passed.

mxh’s picture

My confusion level has reached over 9000. I checked out the branch and ran the Unit test where it passed completely. After checking out the branch again, 3 tests are now failing. Very confusing now, let's see what DrupalCI currently says (just requed the tests here).

I guess, what you wanted to test, requires a one hour shift in the mock for both timestamps. Then I only have to adjust the test "Today at 02:00 AM." to get everything passed.

The scenario I was going for was creation of ECA configuration at 00:00:01 AM while the cron execution was at 01:00:01 AM, therefore ::getTimestamp would have returned 00:00:01 and ::getCurrentTimestamp would have returned 01:00:01.

Will have a second look tomorrow.

jurgenhaas’s picture

Status: Needs review » Needs work

The scenario I was going for was creation of ECA configuration at 00:00:01 AM while the cron execution was at 01:00:01 AM, therefore ::getTimestamp would have returned 00:00:01 and ::getCurrentTimestamp would have returned 01:00:01.

Yes, that means that all schedules due between 00:00:01 and 01:00:01 would return TRUE, not FALSE as defined in the test data. That's why using 01:00:01 as creation time and 02:00:01 as current time allows to test that everything before creation time will return FALSE, everything between creation and current time will return TRUE and everything later than current time will return FALSE again.

I'll have a look into that one failing test right now.

jurgenhaas’s picture

Status: Needs work » Needs review

That was another timezone issue ;-)

In \Drupal\Tests\eca_base\Unit\CronEventTest::appliesData, the weekday timestamps got calculated and they were missing the timezone definition:

    $weekday_today = date('w', (new \DateTime('now', new \DateTimeZone('UTC')))->getTimestamp());
    $weekday_future = (date('w', (new \DateTime('now', new \DateTimeZone('UTC')))->getTimestamp()) + 2) % 7;

That explains why this fails sometimes: the test server of DrupalCI has a different default timezone and hence it comes back with different results.

Tests are passing on DrupalCI now as well.

mxh’s picture

Assigned: Unassigned » mxh

Uff, thanks for finding this, what a nut to crack 😄 will have a second look into it now.

mxh’s picture

Assigned: mxh » Unassigned

Have filled the Unit test with a bunch of more assertions, and added assertions that simulates a daily cron run (asserting for tomorrow and after tomorrow). In that regard I had to add an additional calculation within the isDue calculation. I put that into its own commit, just in case you'd like to revert this one by adding a different solution. I validated the test cases against my understandings and think they should be fine.

jurgenhaas’s picture

The additional test cases make sense and it's great to have more cases being tested.

However, the change in isDue doesn't feel right and digging deeper indicates, that this is most likely because of an unclear expectation. Example: "Tomorrow - Every minute today." - here are the values that we get from that test case:

  • Current: 21. June 2022 - 02:00:00
  • Last: 20. June 2022 - 02:00:00
  • Next: 20. June 2022 - 02:01:00

This will return TRUE because the next due timestamp is smaller than the current timestamp.

Now, your expectation in the test case is to not run the task, because at the current time it is a weekday which is excluded from the cron pattern.

However, there have been many missed executions for that cron pattern, i.e. every minute from 02:01 until 23:59 yesterday. This happens, if the cron scheduler didn't run. The current implementation therefore does execute missed cron runs. And therefore returning TRUE in this case is considered correct.

I can see, that one would want to change this. But doing so would open up all sort of additional issues that would have to be captured. Example: a cron pattern of * 1,7,15 * * * would execute every minute every day, but only between 1 and 2, 7 and 8 and 15 and 16. Our isDue would have to check that as well if it gets executed at 08:10 and gets a due time of 07:59. Should it then be executed or not? Well, following the weekday logic from above, it should not, but following the originally implemented algorithm, it should.

This second example is just made up. The two cases - weekday and a couple of hours - are just a fraction of possible cases where we would have to implement additional checks and adjustments, that we would almost have to implement a complete new cron pattern interpreter. If it's even possible.

All the above is complex and difficult to explain. The originally implemented paradigm can be simply explained as this:

The next due date is calculated based on the given cron pattern and the timestamp that cron was last executed. If that due timestamp is in the past, it is a task that should have been executed then and will therefore be executed now.

It then stores the current timestamp as the last execution timestamp so that it won't execute any arbitrary number of missed tasks, it'll only ever execute one missed task from the past.

This is important, because in Drupal the cron (or this cron event) won't be executed every minute the catch all due tasks. It may only be executed once an hour (or any other regular or unregular period) and therefore needs to pick up all missed tasks from the past just once.

mxh’s picture

It's probably unclear, or at least a subjective factor involved regards the expectation. My expectation is, that when I setup a cron job that is to be executed on every Monday, then I don't care about when on Monday it's being executed, but I only want to have it executed on Monday and not executed on Tuesday.

I think we both agree that we cannot bring up the perfect solution here that covers every possible aspect and expectation. I think the more likely case is that someone sets up a job to be run on a certain day only, but I may be wrong about this. For me the current implementation is not "wrong" but yes, it's not perfect and very likely missing some common cases, and even may be in conflict with the described expectation in #24.

Finally, I'm not forced to stick with the implementation I've brought up in the recent commits, it's just a suggestion. If you think that your expectation is more likely to be common, feel free to adjust the implementation and test data accordingly. Should probably be just to revert commit_id=cca20eac0bb40caf02224c6eac6b9a3f461ebb43 and set some different expected return values in the unit test that I've added in commit_id=e9735db618562bd511b74d6f5ffc9dbc2ccca3e6 and commit_id=89a408ad21f6185f70e2b73b8e9f923465cff278.

jurgenhaas’s picture

I think we both agree that we cannot bring up the perfect solution here that covers every possible aspect and expectation.

Agreed. The good news: the scenario in the test is pretty hypothetical and pretty unlikely in a production environment. I mean, if one defines cron tasks to run every minute, they also have to make sure that the cron scheduler gets executed every minute too. And then the issue would ever occur.

To mimic that scenario also in our test environment, I've changed the $lastRun values in testApplies so that it is set to 23:59 of the previous day of which will be tested in the next step. With the reverted commit for isDue all tests pass without any other changes required. In other words, even your expectation is being met by assuming that the last run was executed late the day before.

If you're ok with that, this one would be ready to go.

mxh’s picture

Status: Needs review » Reviewed & tested by the community

Think this one is good 👍

  • jurgenhaas committed daa9c58 on 1.0.x
    Issue #3291157 by jurgenhaas, mxh: Review due time calculation for new...
jurgenhaas’s picture

Status: Reviewed & tested by the community » Fixed

Amazing, this was a good round of improvements!!!

  • jurgenhaas committed 9a9f9e9 on 1.0.x
    Issue #3291157: Review due time calculation for new cron events
    

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.