Page MenuHomePhabricator

Special:UploadStash thumbnails failing to generate with 500 & 503
Closed, ResolvedPublic

Description

It has been reported on Commons Village Pump that some uploads are failing.

@Josve05a did a quick test and got these errors in console, showing 500 and 503s:

Event Timeline

Restricted Application added a project: Multimedia. · View Herald TranscriptMar 17 2016, 1:00 PM
Restricted Application added subscribers: Steinsplitter, Aklapper. · View Herald Transcript
Restricted Application added a subscriber: Matanya. · View Herald TranscriptMar 17 2016, 1:17 PM
matmarex renamed this task from Uploading files (<100MB) with UploadWizard chunked uploads failing with 500 & 503 to Special:UploadStash thumbnails failing to generate with 500 & 503.Mar 17 2016, 6:01 PM
matmarex added a subscriber: matmarex.

These errors are just failures to generate the thumbnails and should not interfere with uploads, perhaps there's something else going on (I'll reply on Commons). I could reproduce these reliably with a big JPG file, and unreliably with some SVGs. (Small non-SVG files are thumbnailed client-side by UploadWizard.)

Dzahn added a subscriber: Dzahn.Mar 17 2016, 6:09 PM

i have been asked to check logs. this is from oxygen /srv/log/webrequests/5xx.json where that filename appears. all the same IP that should be matmarex.

{"hostname":"cp3009.esams.wmnet","sequence":3049221719,"dt":"2016-03-17T17:34:20","time_firstbyte":5.546011209,"ip":"91.218.200.230","cache_status":"miss","http_status":"500","response_size":286,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"https://commons.wikimedia.org/wiki/Special:UploadWizard?debug=1","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3049233242,"dt":"2016-03-17T17:34:27","time_firstbyte":6.065303087,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":871,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"https://commons.wikimedia.org/wiki/Special:UploadWizard?debug=1","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3049238144,"dt":"2016-03-17T17:34:29","time_firstbyte":2.473597288,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":871,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"-","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3049242981,"dt":"2016-03-17T17:34:32","time_firstbyte":4.801492214,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":872,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"https://commons.wikimedia.org/wiki/Special:UploadWizard?debug=1","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3049248942,"dt":"2016-03-17T17:34:35","time_firstbyte":2.482312202,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":872,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"https://commons.wikimedia.org/wiki/Special:UploadWizard?debug=1","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3049255230,"dt":"2016-03-17T17:34:38","time_firstbyte":2.475832701,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":872,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"https://commons.wikimedia.org/wiki/Special:UploadWizard?debug=1","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3049262761,"dt":"2016-03-17T17:34:42","time_firstbyte":2.376269341,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":871,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"https://commons.wikimedia.org/wiki/Special:UploadWizard?debug=1","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
..

{"hostname":"cp3009.esams.wmnet","sequence":3050266989,"dt":"2016-03-17T17:43:39","time_firstbyte":2.547093153,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":872,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"-","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3050290796,"dt":"2016-03-17T17:43:52","time_firstbyte":2.638962746,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":871,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"-","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3051249107,"dt":"2016-03-17T17:52:24","time_firstbyte":2.449830055,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":872,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"-","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
{"hostname":"cp3009.esams.wmnet","sequence":3052200290,"dt":"2016-03-17T18:00:45","time_firstbyte":2.939506531,"ip":"91.218.200.230","cache_status":"miss","http_status":"503","response_size":872,"http_method":"GET","uri_host":"commons.wikimedia.org","uri_path":"/wiki/Special:UploadStash/thumb/13vu5jeqv2as.6m2ump.239936.jpg/100px-13vu5jeqv2as.6m2ump.239936.jpg","uri_query":"","content_type":"text/html; charset=utf-8","referer":"-","x_forwarded_for":"91.218.200.230","user_agent":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 OPR/36.0.2130.29 (Edition beta)","accept_language":"en-US,en;q=0.8","x_analytics":"WMF-Last-Access=17-Mar-2016;https=1","range":"-","x_cache":"cp1065 miss+chfp(0), cp3003 miss(0), cp3009 frontend miss(0)"}
Dzahn added a comment.Mar 17 2016, 6:51 PM

also check backend logs on fluorine but can't find "UploadStash" related issues in exception.log or fatal.log, except this single one:

2016-03-17 11:39:20 mw1200 commonswiki 1.27.0-wmf.17 exception ERROR: [d1f325d3] /w/api.php?action=query&format=json&prop=stashimageinfo&siifilekey=13vted7b2nlk%2Exchznz%2E79828%2Ejpg&siiprop=url&siiurlwidth=100&siiurlheight=100   UploadStashNotLoggedInException from line 126 of /srv/mediawiki/php-1.27.0-wmf.17/includes/upload/UploadStash.php: UploadStash::getFile No user is logged in, files must belong to users {"exception_id":"d1f325d3"} 
[Exception UploadStashNotLoggedInException] (/srv/mediawiki/php-1.27.0-wmf.17/includes/upload/UploadStash.php:126) UploadStash::getFile No user is logged in, files must belong to users
  #0 /srv/mediawiki/php-1.27.0-wmf.17/includes/api/ApiQueryStashImageInfo.php(57): UploadStash->getFile(string)
ori added a subscriber: ori.Mar 17 2016, 7:15 PM
2016-03-17 11:39:20 mw1200 commonswiki 1.27.0-wmf.17 exception ERROR: [d1f325d3] /w/api.php?action=query&format=json&prop=stashimageinfo&siifilekey=13vted7b2nlk%2Exchznz%2E79828%2Ejpg&siiprop=url&siiurlwidth=100&siiurlheight=100   UploadStashNotLoggedInException from line 126 of /srv/mediawiki/php-1.27.0-wmf.17/includes/upload/UploadStash.php: UploadStash::getFile No user is logged in, files must belong to users {"exception_id":"d1f325d3"}
[Exception UploadStashNotLoggedInException] (/srv/mediawiki/php-1.27.0-wmf.17/includes/upload/UploadStash.php:126) UploadStash::getFile No user is logged in, files must belong to users
  #0 /srv/mediawiki/php-1.27.0-wmf.17/includes/api/ApiQueryStashImageInfo.php(57): UploadStash->getFile(string)
  #1 /srv/mediawiki/php-1.27.0-wmf.17/includes/api/ApiQuery.php(250): ApiQueryStashImageInfo->execute()
  #2 /srv/mediawiki/php-1.27.0-wmf.17/includes/api/ApiMain.php(1359): ApiQuery->execute()
  #3 /srv/mediawiki/php-1.27.0-wmf.17/includes/api/ApiMain.php(462): ApiMain->executeAction()
  #4 /srv/mediawiki/php-1.27.0-wmf.17/includes/api/ApiMain.php(433): ApiMain->executeActionWithErrorHandling()
  #5 /srv/mediawiki/php-1.27.0-wmf.17/api.php(83): ApiMain->execute()
  #6 /srv/mediawiki/w/api.php(3): include(string)
  #7 {main}
ori added a comment.Mar 17 2016, 7:54 PM

Managed to reproduce this and to capture the 503 response via varnishlog:

1 171 ReqStart c 10.192.48.27 52497 2662045707
2 171 RxRequest c GET
3 171 RxURL c /wiki/Special:UploadStash/thumb/13vufizik66c.ccuykd.46848.svg/100px-13vufizik66c.ccuykd.46848.svg.png
4 171 RxProtocol c HTTP/1.1
5 171 RxHeader c X-Client-IP: 198.73.209.4
6 171 RxHeader c X-Forwarded-Proto: https
7 171 RxHeader c X-Connection-Properties: SPDY=3.1; SSR=0; SSL=TLSv1.2; C=ECDHE-ECDSA-AES128-GCM-SHA256;
8 171 RxHeader c accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
9 171 RxHeader c upgrade-insecure-requests: 1
10 171 RxHeader c user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2676.0 Safari/537.36
11 171 RxHeader c accept-language: en-US,en;q=0.8,he;q=0.6
12 171 RxHeader c Host: commons.wikimedia.org
13 171 RxHeader c X-WMF-LastStamp: 17-Mar-2016
14 171 RxHeader c X-Varnish: 4257713313
15 171 RxHeader c X-Varnish: 427518770
16 171 RxHeader c X-Forwarded-For: 198.73.209.4, 10.128.0.118, 10.128.0.118, 10.128.0.117
17 171 RxHeader c X-Varnish: 3750445777
18 171 RxHeader c Accept-Encoding: gzip
19 171 RxHeader c Cookie: [REDACTED]
20 171 VCL_call c recv
21 171 VCL_acl c MATCH wikimedia_nets 10.0.0.0/8
22 171 VCL_return c lookup
23 171 VCL_call c hash
24 171 Hash c /wiki/Special:UploadStash/thumb/13vufizik66c.ccuykd.46848.svg/100px-13vufizik66c.ccuykd.46848.svg.png
25 171 Hash c commons.wikimedia.org
26 171 VCL_return c hash
27 171 VCL_call c miss fetch
28 171 Backend c 211 appservers be_appservers
29 171 TTL c 2662045707 RFC 2592000 -1 -1 1458244096 0 1458244095 0 0
30 171 VCL_call c fetch
31 171 TTL c 2662045707 VCL 1814400 -1 -1 1458244096 -0
32 171 TTL c 2662045707 VCL -1 -1 -1 1458244096 -0
33 171 TTL c 2662045707 VCL -1 3600 -1 1458244096 -0
34 171 TTL c 2662045707 VCL 601 3600 -1 1458244096 -0
35 171 VCL_return c hit_for_pass
36 171 ObjProtocol c HTTP/1.1
37 171 ObjResponse c OK
38 171 ObjHeader c Date: Thu, 17 Mar 2016 19:48:15 GMT
39 171 ObjHeader c Server: Apache
40 171 ObjHeader c X-Powered-By: HHVM/3.12.1
41 171 ObjHeader c X-Content-Type-Options: nosniff
42 171 ObjHeader c Cache-control: private
43 171 ObjHeader c Content-Transfer-Encoding: binary
44 171 ObjHeader c Expires: Sun, 17-Jan-2038 19:14:07 GMT
45 171 ObjHeader c Content-Encoding: gzip
46 171 ObjHeader c Vary: Accept-Encoding
47 171 ObjHeader c Content-Length: 10527
48 171 ObjHeader c Backend-Timing: D=116686 t=1458244095571536
49 171 ObjHeader c Content-Type: image/png
50 171 Gzip c u F - 10527 10527 80 80 84211
51 171 FetchError c TestGunzip error at the very end
52 171 VCL_call c error deliver
53 171 VCL_call c deliver deliver
54 171 TxProtocol c HTTP/1.1
55 171 TxStatus c 503
56 171 TxResponse c Service Unavailable
57 171 TxHeader c Server: Varnish
58 171 TxHeader c Content-Type: text/html; charset=utf-8
59 171 TxHeader c Content-Length: 1511
60 171 TxHeader c Accept-Ranges: bytes
61 171 TxHeader c Date: Thu, 17 Mar 2016 19:48:15 GMT
62 171 TxHeader c X-Varnish: 2662045707
63 171 TxHeader c Age: 0
64 171 TxHeader c Via: 1.1 varnish
65 171 TxHeader c Connection: close
66 171 TxHeader c X-Cache: cp1068 miss+chfp(0)
67 171 Length c 1511
68 171 ReqEnd c 2662045707 1458244095.571494818 1458244095.688978910 0.051499844 0.117449045 0.000035048

ori added a comment.Mar 17 2016, 8:17 PM

The content-type is image/png, so there is no point in gzipping, but the backend sends a gzipped-encoded response anyhow.

Mentioned in SAL [2016-03-17T22:14:27Z] <ori@tin> Synchronized php-1.27.0-wmf.17/includes/specials/SpecialUploadStash.php: Debug code for T130204 (duration: 00m 28s)

Mentioned in SAL [2016-03-17T22:17:39Z] <ori@tin> Synchronized php-1.27.0-wmf.17/includes/specials/SpecialUploadStash.php: Revert: Debug code for T130204 (it worked!) (duration: 00m 25s)

Change 278168 had a related patch set uploaded (by Bartosz Dziewoński):
SpecialUploadStash: Disable output gzipping when outputting remove scaled thumb

https://gerrit.wikimedia.org/r/278168

Change 278168 merged by jenkins-bot:
SpecialUploadStash: Disable output gzipping when outputting remove scaled thumb

https://gerrit.wikimedia.org/r/278168

Change 278190 had a related patch set uploaded (by Ori.livneh):
SpecialUploadStash: Disable output gzipping when outputting remove scaled thumb

https://gerrit.wikimedia.org/r/278190

Change 278190 merged by jenkins-bot:
SpecialUploadStash: Disable output gzipping when outputting remove scaled thumb

https://gerrit.wikimedia.org/r/278190

Tgr added a subscriber: Tgr.Mar 17 2016, 11:44 PM

Could be the same issue as T90599?

matmarex closed this task as Resolved.Mar 17 2016, 11:45 PM
matmarex claimed this task.
matmarex removed a project: Patch-For-Review.

Fixed and deployed.

Could be the same issue as T90599?

I don't think so. I'm pretty sure this was broken for just a few days at most, that bug is from last year.

There's actually an UploadWizard-specific bit here, see T130437. That only affects Internet Explorer, other browsers should not be running into this naymore.