add logging for upload queue processing (WP-1014) - #629
add logging for upload queue processing (WP-1014)#629vsolovei-smartling wants to merge 7 commits into
Conversation
Queue rows were deleted the moment they were handed to the upload job, before the upload itself was attempted. Any fatal error, timeout or out of memory during the upload that followed destroyed the queued work with no trace: the submission stayed New, with no queue row, no last_error and no log line. Rows are now claimed instead of deleted, and removed only once the upload has been accounted for. A run that dies mid-upload leaves the claim behind, and the row becomes eligible again after a staleness timeout. Claims are counted, and once they are exhausted the submissions are failed with a visible error rather than retried forever. The two paths that dropped a whole queue item when a submission or its target locale could not be resolved did so silently; they now log which submission was responsible. Throttled cron runs logged nothing at all and now log a reason. Separately, shutdownHandler treated any error type outside a blacklist as a fatal, and the blacklist covered E_DEPRECATED but not E_USER_DEPRECATED. Since error_get_last() returns the last error of any severity, a single Guzzle deprecation was reported as "Wordpress is down" on nearly every request: one customer log held 2509 such false emergencies hiding one real E_PARSE. The check is now a whitelist of request-terminating types, and the error type is named instead of a decimal printed behind an "0x" prefix. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…ently (WP-1014) Code review on PR #629 found that the "cleanup" commit had silently reverted DebugTrait::shutdownHandler back to its original buggy blacklist implementation and deleted its test file, undoing the false-fatal-report fix described in the PR itself. Restored both from the original fix commit. Also fixes upload queue review finding: when a queue row groups submissions for the same content across multiple target locales and one submission's locale can no longer be resolved, the whole row was deleted but only logged - resolved sibling submissions were left in New status with no queue row and no error. dequeue() now keeps checking every submission in the group instead of stopping at the first failure, and sets a visible error message on every submission that still exists once the group is discarded.
- UploadJob: catch \Throwable (not just \Exception) around the upload dispatch, matching processCloning() and actually delivering the crash-resilience this queue rework is meant to provide. - UploadJob: complete() the claimed queue item when no active profile is found, instead of leaving it claimed until it's retried into a misleading "terminated unexpectedly" failure. - UploadJob: processCloning() now dispatches through WordpressFunctionProxyHelper::do_action(), matching processUploadQueue() and making it mockable in tests. - UploadQueueManager: build the stale-claim WHERE fragment via ConditionBlock/Condition instead of raw sprintf ordinals, and extract the duplicated fail-and-delete logic into discardQueueItem(). - SubmissionUploadTest: complete() dequeued items in the drain loop, since dequeue() now claims rows instead of deleting them and count() no longer drops on its own. - Add UploadJobTest coverage for the \Throwable catch, the no-active-profile completion, and the proxied cloning dispatch. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
… (WP-1014) - UploadJob::processUploadQueue() now catches failures from getOrCreateJobInfoForDailyBucketJob(), matching the crash-safety pattern already used for the settings profile lookup: log, record the error on the submission, complete the queue item, and continue instead of leaving the claimed row stuck and aborting the cron run. - DebugTrait declared FATAL_ERROR_TYPES/ERROR_TYPE_NAMES as trait constants, which PHP only allows from 8.2 onward, causing "Traits cannot have constants" fatal errors on this project's target PHP 8.0. Converted both to private static methods.
…lure (WP-1014) processUploadQueue() only logged/errored the first submission in a queue item when the profile lookup or daily bucket job creation failed, then deleted the whole row. Any sibling submission grouped in the same item (same content, other target locale) vanished silently: no error, no log line, stuck in New forever. Both catch blocks now loop over every submission in the item. Migration260825's ADD COLUMN also failed for any site still on a schema version below 240315: Migration240315 recreates the table with CREATE TABLE IF NOT EXISTS from the live, current UploadQueueEntity::getFieldDefinitions(), which already includes the new claimed/attempts columns, so the later unconditional ALTER TABLE hit a duplicate-column error and never recorded itself as applied. The migration now checks SHOW COLUMNS first and only adds what's actually missing. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
PavelLoparev
left a comment
PavelLoparev
left a comment
There was a problem hiding this comment.
Automated review for WP-1014. Despite the PR title ("add logging"), this is a genuine root-cause fix: claiming queue rows via claimed/attempts (Migration260825) instead of deleting them up front, and catching \Throwable (not just \Exception) around the upload dispatch, directly addresses the reported symptom (assets failing to upload most of the time due to a crash/timeout silently destroying the queue row with no retry). Well covered by new tests overall.
Two cross-cutting points not tied to a single line:
- No DB index covers the
claimedcolumn (UploadQueueEntity::getIndexes()only has the primary key).dequeue()'s stale-claim filter (q.claimed IS NULL OR q.claimed < threshold) will full-scan as the queue grows, which matters given the reported symptom is a backed-up queue. Migration260825.phphas real conditional logic (only adds columns that don't already exist) but no unit test, unlike most other recently-touched files in this PR.
Ready to merge? With fixes — see inline comments below. The unchecked claim()/delete() results create a duplicate-processing/infinite-loop risk in exactly the failure paths this PR is meant to harden.
|
|
||
| private function claim(int $id, int $attempts): void | ||
| { | ||
| $this->db->query(QueryBuilder::buildUpdateQuery( |
There was a problem hiding this comment.
🟡 warning — claim()'s $this->db->query() result is never checked. If this UPDATE silently fails (lock timeout, connection blip), the row is never actually marked claimed, so a concurrent dequeue() call can pick up the same row again while it's already being processed → duplicate upload to Smartling, which is the exact bug class this PR is trying to fix.
Suggested fix: return whether the update affected a row, and have dequeue() continue (skip/retry) instead of returning the item when the claim fails:
private function claim(int $id, int $attempts): bool
{
return (bool)$this->db->query(QueryBuilder::buildUpdateQuery(
$this->tableName,
[...],
$this->idCondition($id),
));
}This also doubles as a fix for the non-atomic claim (SELECT then separate UPDATE with no row locking) — checking affected-row count on a conditional WHERE id=? AND (claimed IS NULL OR claimed < ?) update would catch a lost race.
|
|
||
| private function delete(int $id): void | ||
| { | ||
| $this->db->query(QueryBuilder::buildDeleteQuery($this->tableName, $this->idCondition($id))); |
There was a problem hiding this comment.
🟡 warning — Same unchecked-query() issue as claim(). This delete() is called from discardQueueItem() (line 142), which is invoked inside dequeue()'s while loop for unprocessable rows. If the delete silently fails, the loop's continue re-runs the same SELECT and gets back the same row forever — an infinite loop inside a single dequeue() call. Worth checking the affected-row count and breaking/logging if the delete didn't remove the row.
| $this->getLogger()->notice("Skipping upload of submissionId={$itemSubmission->getId()}: $message"); | ||
| $this->submissionManager->setErrorMessage($itemSubmission, $message); | ||
| } | ||
| $this->uploadQueueManager->complete($item); |
There was a problem hiding this comment.
🟡 warning / 🟣 question — This branch calls complete($item) and permanently discards the item on the very first "no active profile" failure, bypassing the new claim/attempts/stale-retry mechanism entirely. Is this intentional (treating a missing profile as a permanent configuration error rather than transient)? If getSingleSettingsProfile can ever fail transiently (e.g. DB blip), this item is lost with no retry, unlike a hard crash further down which now gets up to MAX_ATTEMPTS retries.
| $this->getLogger()->notice("Skipping upload of submissionId={$itemSubmission->getId()}: failed to get or create daily bucket job: {$e->getMessage()}"); | ||
| $this->submissionManager->setErrorMessage($itemSubmission, $e->getMessage()); | ||
| } | ||
| $this->uploadQueueManager->complete($item); |
There was a problem hiding this comment.
🟡 warning / 🟣 question — Same pattern: a failure from getOrCreateJobInfoForDailyBucketJob (an API/network call — exactly the kind of intermittent failure that could explain "unable to upload most of the time") immediately calls complete($item) and permanently drops the submission, instead of leaving it claimed so it flows through the same stale-claim retry path as a crash in the do_action call below. Please confirm this is meant to be non-retryable, or consider not calling complete() here so it gets retried.
| return DateTimeHelper::dateTimeToString( | ||
| (new \DateTime('now', new \DateTimeZone(DateTimeHelper::TIMEZONE_UTC))) | ||
| ->modify('-' . self::STALE_CLAIM_SECONDS . ' seconds') | ||
| ); |
There was a problem hiding this comment.
🔵 suggestion — getStaleClaimThreshold() builds its own new \DateTimeZone(DateTimeHelper::TIMEZONE_UTC) explicitly, while claim() (below) stores the claim time via DateTimeHelper::nowAsString(), which uses DateTimeHelper::getDefaultTimezone() — UTC only because nothing currently overrides it. These two time sources aren't structurally guaranteed to agree. Consider computing both via the same helper so a future change to the default timezone can't silently desync staleness detection from claim timestamps.
2 participants
No description provided.