[wp-trac] [WordPress Trac] #57924: Cron fires twice (was: Cron Goes Missing. _set_cron_array called with incorrect number of crons)

[WordPress Trac]

#57924: Cron fires twice
--------------------------+------------------------------
 Reporter:  j3gaming      |       Owner:  j3gaming
     Type:  defect (bug)  |      Status:  assigned
 Priority:  normal        |   Milestone:  Awaiting Review
Component:  Cron API      |     Version:  6.1.1
 Severity:  normal        |  Resolution:
 Keywords:                |     Focuses:
--------------------------+------------------------------

Comment (by j3gaming):

 At this point I'm just using the ticket as a chronicle of my journey until
 I give up.
 Hope the spam is fine!

 I set some more logging. **wp-cron.php** this time:


 {{{
 /*
  * The cron lock (a unix timestamp set when the cron was spawned),
  * must match $doing_wp_cron (the "key").
  */
 if ( $doing_cron_transient !== $doing_wp_cron ) {
         return;
 }

 error_log(" START --- --- --- --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- ");
 error_log("[wp-cron.php] Jobs ready: " . count($crons) . ", with UNIX key:
 " . var_export($doing_cron_transient, true));

 foreach ( $crons as $timestamp => $cronhooks ) {

 ...
 // ... all the usual normal WP code ...
 ...

 if ( _get_cron_lock() === $doing_wp_cron ) {
         delete_transient( 'doing_cron' );
 }

 error_log(" --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- END");
 die();
 }}}

 You would expect to NEVER get 2 "starts" in a row right?
 It's possible. Notice the different $doing_cron_transient outputs? The
 microtime(true) is slightly different. At the end of the log, I do get
 double the outputs from my code inside the cron.


 {{{
 [16-Mar-2023 22:05:01 UTC]  START --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- ---
 [16-Mar-2023 22:05:01 UTC] [wp-cron.php] Jobs ready: 1, with UNIX key:
 '1679004301.2089200019836425781250'
 [16-Mar-2023 22:05:01 UTC] wp_schedule_event(1679004332, 'minutely',
 'crontrol_cron_job', array (
   'code' => 'require_once(\'wp-content/cron/email_send.php\');',
   'name' => 'Send Emails',
 ) , .... )
 [16-Mar-2023 22:05:01 UTC]  START --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- ---
 [16-Mar-2023 22:05:01 UTC] [wp-cron.php] Jobs ready: 1, with UNIX key:
 '1679004301.2094271183013916015625'
 [16-Mar-2023 22:05:01 UTC] wp_schedule_event(1679004332, 'minutely',
 'crontrol_cron_job', array (
   'code' => 'require_once(\'wp-content/cron/email_send.php\');',
   'name' => 'Send Emails',
 ) , .... )
 [16-Mar-2023 22:05:01 UTC] wp_unschedule_event(1679004272,
 'crontrol_cron_job', array (
   'code' => 'require_once(\'wp-content/cron/email_send.php\');',
   'name' => 'Send Emails',
 ) , .... )
 [16-Mar-2023 22:05:01 UTC] Cron reschedule event error for hook:
 crontrol_cron_job, Error code: could_not_set, Error message: The cron
 event list could not be saved. true false, Data:
 {"schedule":"minutely","args":{"code":"require_once('wp-
 content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
 [16-Mar-2023 22:05:01 UTC] wp_unschedule_event(1679004272,
 'crontrol_cron_job', array (
   'code' => 'require_once(\'wp-content/cron/email_send.php\');',
   'name' => 'Send Emails',
 ) , .... )
 [16-Mar-2023 22:05:01 UTC] Cron unschedule event error for hook:
 crontrol_cron_job, Error code: could_not_set, Error message: The cron
 event list could not be saved. true false, Data:
 {"schedule":"minutely","args":{"code":"require_once('wp-
 content\/cron\/email_send.php');","name":"Send Emails"},"interval":"60"}
 [16-Mar-2023 22:05:01 UTC] [1679004301] Started email_send
 [16-Mar-2023 22:05:01 UTC] [1679004301] Started email_send
 [16-Mar-2023 22:05:01 UTC] [1679004301] Ended email_send
 [16-Mar-2023 22:05:01 UTC] [1679004301] Ended email_send
 [16-Mar-2023 22:05:01 UTC]  --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- ---
 --- --- --- --- --- --- --- --- --- --- END

 }}}



 When The cron gets past the lock, firing twice I can trigger
 could_not_set.

 **Proposed fix: Better locking to ensure it only runs once.**
 Not sure if I can help further. I'm unsure how this would change to ensure
 the lock is properly coded & checked.

 Maybe something like a sleep for 1 second, and re-check the lock? Only the
 first or last to get there gets to execute the cron?

-- 
Ticket URL: <https://core.trac.wordpress.org/ticket/57924#comment:13>
WordPress Trac <https://core.trac.wordpress.org/>
WordPress publishing platform