Maniphest T203929

cpjobqueue should log a warning when there is an HTTP error
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	tstarling
	Sep 10 2018, 2:57 AM

Project Tags

Referenced Files

None

Subscribers

Description

I briefly broke some video scaling jobs by setting the time limit to 200 seconds instead of 86400 seconds. To fix it I had to figure out the affected titles and click "reset transcode" on the file description pages. cpjobqueue provided no help with this, there was no information about the affected jobs in its logs. Luckily I was able to correlate the request ID in fatal.log with the job start message in the JobExecutor log, but for some failure modes, neither of these would exist.

I'm not sure if retries are possible for these jobs. No retry was attempted and no "retry exceeded" message was logged. Looking at the cpjobqueue log stream, it would seem that HTTP errors are sometimes logged as "retry exceeded".

It would have been helpful if more logs were available in flat files on scb1002. I see that it is currently writing only 6MB per day of warning-level logs.

Here are some log message details, in case you don't believe me that these messages are unlogged. The error occurred at 2018-09-10T00:35:41 , and the Apache access log confirms the request came from scb1002.

fatal.log:
2018-09-10 00:35:41 [W5W7jQpAMDgAADVDLpIAAAAQ] mw1302 commonswiki 1.32.0-wmf.20 fatal ERROR: [W5W7jQpAMDgAADVDLpIAAAAQ] /rpc/RunSingleJob.php   PHP Fatal Error from line 450 of /srv/mediawiki/php-1.32.0-wmf.20/includes/shell/Command.php: entire web request took longer than 200 seconds and timed out {"fatal_exception":{"class":"ErrorException","message":"PHP Fatal Error: entire web request took longer than 200 seconds and timed out","code":16777217,"file":"/srv/mediawiki/php-1.32.0-wmf.20/includes/shell/Command.php","line":450,"trace":"#0 /srv/mediawiki/php-1.32.0-wmf.20/includes/shell/Command.php(450): stream_select()


videoscaler-access.log:
2018-09-10T00:32:21	200079873	10.64.32.36	proxy-server/500	1505	POST	http://videoscaler.discovery.wmnet/rpc/RunSingleJob.php	-	text/html	-	10.64.16.21	ChangePropagation-JobQueue/WMF	-	-	-	10.64.32.36

Related Objects

Mentioned In: rMSCP533ab2ef5bde: Log the failed event execution with warn level.

Event Timeline

tstarling created this task.Sep 10 2018, 2:57 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 10 2018, 2:57 AM

tstarling added projects: Core-Platform-Team-Old, Services.Sep 10 2018, 2:58 AM

tstarling added subscribers: • mobrovac, • Pchelolo.

• Pchelolo moved this task from Backlog to doing on the Services board.Sep 10 2018, 8:56 PM

• Pchelolo edited projects, added: Services (doing); removed: Services.

PR here to add more logging: https://github.com/wikimedia/change-propagation/pull/291

No retry was attempted.

Are you talking about webVideoTranscode job? I can see some retry events in retry topics:

kafkacat -b localhost:9092 -p 0 -t "eqiad.cpjobqueue.retry.mediawiki.job.webVideoTranscode" -c 1 -o -1

{"meta":{"topic":"cpjobqueue.retry.mediawiki.job.webVideoTranscode","schema_uri":"retry/1","uri":"https://commons.wikimedia.org/wiki/File:Porch_Pirates.ogv","domain":"commons.wikimedia.org","id":"7243529b-b491-11e8-9868-4c0c1b34bb80","dt":"2018-09-10T00:35:41.507Z","request_id":"7243529c-b491-11e8-a965-685c713df305"},"triggered_by":"req:W5W7jQpAMDgAADVDLpIAAAAQ,mediawiki.job.webVideoTranscode:https://commons.wikimedia.org/wiki/File:Porch_Pirates.ogv","emitter_id":"cpjobqueue#webVideoTranscode","retries_left":2,"original_event":{"database":"commonswiki","mediawiki_signature":"23094a1ebb9de961e5720fac2856955c45f2a80dec141d72b5492f1fbc96ce80","meta":{"domain":"commons.wikimedia.org","dt":"2018-09-10T00:32:20+00:00","id":"fa6598b4-b490-11e8-9889-b083fecf12f3","request_id":"W5W7jQpAMDgAADVDLpIAAAAQ","schema_uri":"mediawiki/job/2","topic":"mediawiki.job.webVideoTranscode","uri":"https://commons.wikimedia.org/wiki/File:Porch_Pirates.ogv"},"page_namespace":6,"page_title":"File:Porch_Pirates.ogv","params":{"prioritized":false,"requestId":"W5W7jQpAMDgAADVDLpIAAAAQ","transcodeKey":"1080p.vp9.webm","transcodeMode":"derivative"},"sha1":"dbc198ca83e9b96b7098e7b452479f9443a3ede3","type":"webVideoTranscode"},"error_status":500,"reason":"<!DOCTYPE html>\n<html lang=\"en\" dir=\"ltr\">\n<meta charset=\"utf-8\">\n<title>Wikimedia Error</title>\n<style>\n* { margin: 0; padding: 0; }\nbody { background: #fff; font: 15px/1.6 sans-serif; color: #333; }\n.content { margin: 7% auto 0; padding: 2em 1em 1em; max-width: 640px; }\n.footer { clear: both; margin-top: 14%; border-top: 1px solid #e5e5e5; background: #f9f9f9; padding: 2em 0; font-size: 0.8em; text-align: center; }\nimg { float: left; margin: 0 2em 2em 0; }\na img { border: 0; }\nh1 { margin-top: 1em; font-size: 1.2em; }\np { margin: 0.7em 0 1em 0; }\na { color: #0645AD; text-decoration: none; }\na:hover { text-decoration: underline; }\ncode { font-family: inherit; }\n.text-muted { color: #777; }\n</style>\n<div class=\"content\" role=\"main\">\n<a href=\"https://www.wikimedia.org\"><img src=\"https://www.wikimedia.org/static/images/wmf.png\" srcset=\"https://www.wikimedia.org/static/images/wmf-2x.png 2x\" alt=Wikimedia width=135 height=135></a>\n<h1>Error</h1>\n<p>Our servers are currently under maintenance or experiencing a technical problem. Please <a href=\"\" title=\"Reload this page\" onclick=\"location.reload(false); return false\">try again</a> in a few&nbsp;minutes.</p><p>See the error message at the bottom of this page for more&nbsp;information.</p>\n</div>\n<div class=\"footer\">\n<p>If you report this error to the Wikimedia System Administrators, please include the details below.</p>\n<p class=\"text-muted\"><code>\n  PHP fatal error: <br/>\n  unlink(1): No such file or directory</code></p></div>\n</html>\n"}

Although I couldn't find reference to this job, that seems to be because the logs on mwlog have already rotated.

Since no retry count exceeded was logged, that means a subsequent attempt must have succeeded. Looking at the page which this retry event corresponds to https://commons.wikimedia.org/wiki/File:Porch_Pirates.ogv I see all the transcodes succeeded. Did you manually reset it?

It was webVideoTranscodePrioritized. This is the JobExecutor log line for one of the affected jobs:

2018-09-10 00:32:21 [4d7b56991ac53bb62b59f2a6] mw1334 commonswiki 1.32.0-wmf.20 JobExecutor DEBUG: Beginning job execution {"job":"webVideoTranscode File:Porch_Pirates.ogv prioritized= requestId=W5W7jQpAMDgAADVDLpIAAAAQ transcodeKey=1080p.webm transcodeMode=derivative","job_type":"webVideoTranscode"}

I manually reset the affected transcodes on https://commons.wikimedia.org/wiki/File:Porch_Pirates.ogv , and later, https://commons.wikimedia.org/wiki/File:Pine_River_Man_Arrested_For_Stealing_Packages_And_Mail.ogv . You can see from the completion times that I reset the Pine River transcodes more than two hours after the upload. I gather the retry schedule is supposed to be 1 minute, then 6 minutes? If that's the case then the retries would have finished before I rolled out the fix at 00:46.

The exact contents of your retry log entry is interesting/scary: "PHP fatal error: unlink(1): No such file or directory". This is presumably a TimedMediaHandler bug. I would have missed these log entries when I searched fatal.log for retries since I was only looking for timeouts.

It's very mysterious. My best guess is that "PHP fatal error: unlink(1): No such file or directory" was actually a suppressed warning, and was later misinterpreted as a fatal. There's definitely no entries in fatal.log with "unlink" in the message.

I gather the retry schedule is supposed to be 1 minute, then 6 minutes? If that's the case then the retries would have finished before I rolled out the fix at 00:46.

Ye, looked into kafka topics and retries indeed were attempted before you rolled out the fix.

The exact contents of your retry log entry is interesting/scary: "PHP fatal error: unlink(1): No such file or directory".

This didn't happen after the incident in question anymore, could've it been caused by broken scalers? Should we follow investigating this any more?

tstarling removed a project: Core-Platform-Team-Old.Sep 12 2018, 1:16 AM

Mentioned in SAL (#wikimedia-operations) [2018-09-18T19:55:23Z] <ppchelko@deploy1001> Started deploy [cpjobqueue/deploy@58f9ed3]: Log errors for HTTP error T203929

Mentioned in SAL (#wikimedia-operations) [2018-09-18T19:56:13Z] <ppchelko@deploy1001> Finished deploy [cpjobqueue/deploy@58f9ed3]: Log errors for HTTP error T203929 (duration: 00m 49s)

It now locally logs something similar to:

[2018-09-18T19:57:30.139Z]  INFO: cpjobqueue/2879 on scb2003: Exec error in cpjobqueue (message="Exec error in cpjobqueue", status=500, topic=mediawiki.job.categoryMembershipChange, error_body="", rule_name=categoryMembershipChange, executor=RuleExecutor, levelPath=info/exec_error)
    event_str: {"database":"enwiki","mediawiki_signature":"7b11306658e9a73d3e60e2102bba7be5a6359ef57585637d352fd57e28b676a5","meta":{"domain":"en.wikipedia.org","dt":"2018-09-18T19:51:17+00:00","id":"3542fb2e-bb7c-11e8-bb25-b083fee7ec2f","request_id":"W6FXKQrAIFcAAIKooggAAABK","schema_uri":"mediawiki/job/2","topic":"mediawiki.job.categoryMembershipChange","uri":"https://en.wikipedia.org/wiki/Talk:NASA_World_Wind"},"page_namespace":1,"page_title":"Talk:NASA_World_Wind","params":{"pageId":58519875,"requestId":"W6FXKQrAIFcAAIKooggAAABK","revTimestamp":"20180918195110"},"sha1":"5aa914f261205b20fa43739f7331d1f77f2bbbbb","type":"categoryMembershipChange"}

What other info do you think it worths adding in there? I believe some body would be nice to have with a more detailed explanation what happened

• mobrovac mentioned this in rMSCP533ab2ef5bde: Log the failed event execution with warn level..Sep 18 2018, 10:27 PM

• Pchelolo closed this task as Resolved.Oct 2 2018, 4:36 PM

• Pchelolo claimed this task.

cpjobqueue should log a warning when there is an HTTP errorClosed, ResolvedPublicActions

Description

Related Objects

Event Timeline

cpjobqueue should log a warning when there is an HTTP error
Closed, ResolvedPublic
Actions