10 x time limit in failure log entries

[galbaras]

After setting the queue runner time limit to 600, failed actions show the message "action marked as failed after 6000 seconds. Unknown error occurred. Check server, PHP and database error logs to diagnose cause."

This is caused by Line 229 in ActionScheduler_Abstract_QueueRunner.php, which says

$this->cleaner->clean( 10 * $this->get_time_limit() );

This gives the impression that the action timed out after a much longer time than it likely did and should probably be adjusted to reflect the actual time limit used.

[barryhughes]

Hi @galbaras,

It doesn't feel inaccurate to me (in these cases, the action has indeed been marked as failed after 6,000 seconds have elapsed) but perhaps we could tweak the language to make it less ambiguous. For example:

This action was set to a status of in-progress at least 6000 seconds ago. There has been no further change and this suggests it has stopped running, therefore the status will now be updated to failed.

Alternatively, we could attempt to time the actual action duration and use PHP shutdown functions to handle this in situations where execution times out ... but, that is a larger effort and I'm a little unsure how valuable it would be to most users.

What do you think—and are there scenarios you can share where more accurate figures would be useful?

[galbaras]

The cleaner doesn't seem to run after 10x the time. This figure is just hardcoded with no other reference I could find that would explain why. Since I sent the time limit to 600, wouldn't the task have died after 600 seconds already?

Basically, the log should help with troubleshooting as much as possible, and I'm seeing nothing relevant in my error logs, which is totally weird. Increasing the time limit seemed to help, although the log previous quoted "300", so I doubled it, but really multiplied by 20, because of this 10x factor in the code.

[barryhughes]

The cleaner doesn't seem to run after 10x the time.

Right, but it doesn't reflect when the cleaner itself runs: instead it is used to form the cutoff time when the cleaner queries for stalled actions.

Put another way: all we are really trying to communicate is that we've come across an action that was set to in-progress, but then hasn't seen any further updates in the last cutoff seconds. The value of the cutoff being configurable (6,000 seconds as in your initial posts).

[barryhughes]

Since I sent the time limit to 600, wouldn't the task have died after 600 seconds already?

No ... if we're talking about the same time limit, this is the number of seconds in which we can continue to process batches of actions. However:

A) Many actions may be processed in a single batch.
B) The time limit is assessed after each batch.

So, conceivably (and depending on your server config), a single action could run for a much longer time than specified for the batch time out.

[galbaras]

Got it. Thank you.

[barryhughes]

@galbaras—though you closed this, I think you may be right that the message is not as clear as it could be (if you found it confusing, probably others will).

Would the alternative text I posted in my initial reply be clearer? Or, any other wording—perhaps if we just drop the reference to the number of seconds?

Action marked as failed: an unknown error occurred, or the action may have timed out. Check server, PHP and database error logs to diagnose the cause.

[galbaras]

Mentioning the check interval is actually helpful, as it was in my case. How about this:

action checked after 6000 seconds and was no longer running. Check server, PHP and database error logs for possible causes

The "failed" status already indicates that it's failed, so that bit is redundant, and if the error is unknown, why say it? It provides no additional information.

While we're on this, I've found nothing in the PHP logs, I'm on a shared server, so no access to database logs or server logs (unless you mean the access log). PHP normally catches issues, including timeouts, memory exceptions, query errors and database connection issues, but the actions I've been looking at (Rank Math data fetches from Google) seem to leave no trace. Can this be related to how they are triggered?

[barryhughes]

Thanks!

While we're on this, I've found nothing in the PHP logs

Yep, there's no guarantee that the logs will contain useful information—they may contain nothing of interest at all (but, there may be cases where they do).

[barryhughes]

Rank Math data fetches from Google

Could be worth flagging with the Rank Math team? They can probably provide guidance on further debugging in relation to the actual action code they added.

[galbaras]

They just suggested using the Action Scheduler debug addon, which kills performance 😞