Page MenuHomePhabricator

Uploading 1.2GB ogv results in 503
Open, MediumPublic

Description

With T76614: Raise max upload limit above 1GB resolved, uploads of large files should succeed, however, 503 keeps happening (likely due to server timeout handling large files) and the next request failing:

1[2016-02-28 10:48:30,040: WARNING/Worker-11] -1: Uploading...
2[2016-02-28 10:48:30,524: INFO/Worker-11] Sleeping for 9.1 seconds, 2016-02-28 10:48:30
3[2016-02-28 10:49:06,740: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
4[2016-02-28 10:49:29,870: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
5[2016-02-28 10:49:52,369: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
6[2016-02-28 10:50:17,824: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
7[2016-02-28 10:50:42,077: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
8[2016-02-28 10:51:04,521: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
9[2016-02-28 10:51:27,871: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
10[2016-02-28 10:51:48,629: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
11[2016-02-28 10:52:11,812: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
12[2016-02-28 10:52:37,152: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
13[2016-02-28 10:53:00,429: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
14[2016-02-28 10:53:21,620: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
15[2016-02-28 10:53:42,046: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
16[2016-02-28 10:54:02,630: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
17[2016-02-28 10:54:28,309: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
18[2016-02-28 10:54:51,963: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
19[2016-02-28 10:55:16,548: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
20[2016-02-28 10:55:38,725: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
21[2016-02-28 10:55:59,289: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
22[2016-02-28 10:58:15,136: WARNING/Worker-11] Http response status 503
23[2016-02-28 10:58:15,137: VERBOSE/Worker-11] Http response doesn't contain a charset.
24[2016-02-28 10:58:15,139: WARNING/Worker-11] Non-JSON response received from server commons:commons; the server may be down.
25[2016-02-28 10:58:15,139: WARNING/Worker-11] Waiting 5 seconds before retrying.
26[2016-02-28 10:58:20,146: VERBOSE/Worker-11] Submitting unthrottled action 'upload'.
27[2016-02-28 10:58:37,444: WARNING/Worker-11] API error stashfailed: No chunked upload session with this key
28[2016-02-28 10:58:37,445: VERBOSE/Worker-11] API Error: query=
29u"{u'ignorewarnings': [False], u'maxlag': ['5'], u'format': [u'json'], u'filekey': [u'13ua5xnevmjo.z9d9a.14108.ogx'], u'stash': [True], u'filename': [u'1924 \\u0421\\u0442\\u0430\\u0447\\u043a\\u0430.ogv'], u'assert': [u'user'], u'token': [u'5b5139<REDACTED>56d2d07e+\\\\'], u'filesize': [1337930716], u'offset': [1275068416], u'action': [u'upload']}"
30[2016-02-28 10:58:37,445: VERBOSE/Worker-11] response=
31{u'servedby': u'mw1126', u'error': {u'info': u'No chunked upload session with this key', u'code': u'stashfailed', u'help': u'See https://commons.wikimedia.org/w/api.php for API usage'}}
32[2016-02-28 10:58:37,449: WARNING/Worker-11] -1: Cleaning up...
33[2016-02-28 10:58:38,040: ERROR/MainProcess] Task worker.main[fac03c09-ead7-401d-8ac9-b3e442ace1cf] raised unexpected: TaskError('pywikibot.Error: APIError: stashfailed: No chunked upload session with this key [help:See https://commons.wikimedia.org/w/api.php for API usage]',)
34Traceback (most recent call last):
35 File "/usr/local/lib/python2.7/dist-packages/celery/app/trace.py", line 240, in trace_task
36 R = retval = fun(*args, **kwargs)
37 File "/usr/local/lib/python2.7/dist-packages/celery/app/trace.py", line 438, in __protected_call__
38 return self.run(*args, **kwargs)
39 File "/srv/v2c/backend/worker.py", line 77, in main
40 filename, wikifileurl = upload.upload(file, filename, url, http_host, filedesc, username, statuscallback, errorcallback)
41 File "/srv/v2c/backend/upload/__init__.py", line 49, in upload
42 if site.upload(page, source_filename=filename, comment=comment, text=filedesc, chunk_size=chunked, ignore_warnings=['exists-normalized']):
43 File "/usr/local/lib/python2.7/dist-packages/pywikibot-3.0.dev0-py2.7.egg/pywikibot/tools/__init__.py", line 1357, in wrapper
44 return obj(*__args, **__kw)
45 File "/usr/local/lib/python2.7/dist-packages/pywikibot-3.0.dev0-py2.7.egg/pywikibot/site.py", line 5799, in upload
46 raise error
47TaskError: pywikibot.Error: APIError: stashfailed: No chunked upload session with this key [help:See https://commons.wikimedia.org/w/api.php for API usage]

1[2016-02-29 07:53:56,957: WARNING/Worker-4] -1: Uploading...
2[2016-02-29 07:53:57,462: INFO/Worker-4] Sleeping for 9.1 seconds, 2016-02-29 07:53:57
3[2016-02-29 07:54:35,442: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
4[2016-02-29 07:54:58,630: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
5[2016-02-29 07:55:23,038: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
6[2016-02-29 07:55:46,353: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
7[2016-02-29 07:56:10,213: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
8[2016-02-29 07:56:34,484: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
9[2016-02-29 07:56:56,492: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
10[2016-02-29 07:57:20,793: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
11[2016-02-29 07:57:43,597: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
12[2016-02-29 07:58:07,834: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
13[2016-02-29 07:58:34,053: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
14[2016-02-29 07:58:59,173: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
15[2016-02-29 07:59:22,964: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
16[2016-02-29 07:59:48,386: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
17[2016-02-29 08:00:11,607: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
18[2016-02-29 08:00:43,108: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
19[2016-02-29 08:01:11,025: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
20[2016-02-29 08:01:37,672: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
21[2016-02-29 08:02:01,492: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
22[2016-02-29 08:04:18,741: WARNING/Worker-4] Http response status 503
23[2016-02-29 08:04:18,743: VERBOSE/Worker-4] Http response doesn't contain a charset.
24[2016-02-29 08:04:18,749: WARNING/Worker-4] Non-JSON response received from server commons:commons; the server may be down.
25[2016-02-29 08:04:18,749: WARNING/Worker-4] Waiting 5 seconds before retrying.
26[2016-02-29 08:04:23,756: VERBOSE/Worker-4] Submitting unthrottled action 'upload'.
27[2016-02-29 08:04:40,779: WARNING/Worker-4] API error stashedfilenotfound: Could not find the file in the stash: key '13ucutq7lvxw.tklt8l.14108.ogx' not found in stash
28[2016-02-29 08:04:40,781: VERBOSE/Worker-4] API Error: query=
29u"{u'ignorewarnings': [False], u'maxlag': ['5'], u'format': [u'json'], u'filekey': [u'13ucutq7lvxw.tklt8l.14108.ogx'], u'stash': [True], u'filename': [u'1924 \\u0421\\u0442\\u0430\\u0447\\u043a\\u0430.ogv'], u'assert': [u'user'], u'token': [u'ffd8c2<REDACTED>d3f915+\\\\'], u'filesize': [1337930716], u'offset': [1275068416], u'action': [u'upload']}"
30[2016-02-29 08:04:40,781: VERBOSE/Worker-4] response=
31{u'servedby': u'mw1137', u'error': {u'info': u"Could not find the file in the stash: key '13ucutq7lvxw.tklt8l.14108.ogx' not found in stash", u'code': u'stashedfilenotfound', u'help': u'See https://commons.wikimedia.org/w/api.php for API usage'}}
32[2016-02-29 08:04:40,793: WARNING/Worker-4] -1: Cleaning up...
33[2016-02-29 08:04:41,634: ERROR/MainProcess] Task worker.main[5b5de5fe-fc11-4ec0-8e8b-d17e11b2aac0] raised unexpected: TaskError("pywikibot.Error: APIError: stashedfilenotfound: Could not find the file in the stash: key '13ucutq7lvxw.tklt8l.14108.ogx' not found in stash [help:See https://commons.wikimedia.org/w/api.php for API usage]",)
34Traceback (most recent call last):
35 File "/usr/local/lib/python2.7/dist-packages/celery/app/trace.py", line 240, in trace_task
36 R = retval = fun(*args, **kwargs)
37 File "/usr/local/lib/python2.7/dist-packages/celery/app/trace.py", line 438, in __protected_call__
38 return self.run(*args, **kwargs)
39 File "/srv/v2c/backend/worker.py", line 77, in main
40 filename, wikifileurl = upload.upload(file, filename, url, http_host, filedesc, username, statuscallback, errorcallback)
41 File "/srv/v2c/backend/upload/__init__.py", line 49, in upload
42 if site.upload(page, source_filename=filename, comment=comment, text=filedesc, chunk_size=chunked, ignore_warnings=['exists-normalized']):
43 File "/usr/local/lib/python2.7/dist-packages/pywikibot-3.0.dev0-py2.7.egg/pywikibot/tools/__init__.py", line 1357, in wrapper
44 return obj(*__args, **__kw)
45 File "/usr/local/lib/python2.7/dist-packages/pywikibot-3.0.dev0-py2.7.egg/pywikibot/site.py", line 5799, in upload
46 raise error
47TaskError: pywikibot.Error: APIError: stashedfilenotfound: Could not find the file in the stash: key '13ucutq7lvxw.tklt8l.14108.ogx' not found in stash [help:See https://commons.wikimedia.org/w/api.php for API usage]

The framework is pywikibot and each chunk is 64MB.

Event Timeline

We should confirm whether this is purely timeout related (due to slow upload speeds), or something else, I guess by trying a large file from a known-fast source, or even from inside our networks somewhere?

We should confirm whether this is purely timeout related (due to slow upload speeds), or something else, I guess by trying a large file from a known-fast source, or even from inside our networks somewhere?

The uploading script is within WMFLabs video cluster, there should be no reason why the network is slow.

@Krenair What's the typical time needed to upload these kind of files from server side?

I'm not sure if it's related, but action=purge on 3GB+ videos results in 503 as well. (Will file a separate task)

I don't really watch the clock (I tend to read email while those scripts are running), and importImages doesn't give a time. I've never seen it timeout when uploading from terbium, but it doesn't take more than a few minutes there.

I don't really watch the clock (I tend to read email while those scripts are running), and importImages doesn't give a time. I've never seen it timeout when uploading from terbium, but it doesn't take more than a few minutes there.

Well, I don't think maintenance scripts times out at all. If it runs longer than 2 min, it might be a 503 if ran in a similar way as API upload.

The log above has most chunks uploading for 20-30 seconds, but the last chunk runs for 2:16 before receiving 503. I'm assuming there's some chunk-merging process happening.

A possible workaround is to use async chunked uploading, but pywikibot does not yet support so.

A possible workaround is to use async chunked uploading, but pywikibot does not yet support so.

Without async option, I would imagine the upload process should fail long before 1.2GB

akosiaris triaged this task as Medium priority.Apr 20 2016, 9:54 AM
MarkTraceur subscribed.

Multimedia team bowing out of working on this because it seems like it might be a pywikibot problem (namely not using async), not a problem with our software.

Hello. I seem to have run up against this problem. This seems like a serious barrier to contributing core content (media files into Commons). Can this receive higher priority, please?

If this really is a Pywikibot problem, it probably helps with prioritization if the relevant project is tagged.

At a glance though pywikibot does seem to support chunked uploads (upload.py at least has a -chunked option) so maybe try using that?

Pywikibot does support chunked uploading, this task is about why such chunked uploading must be using async mode, and if it must be done, how to fail gracefully with an error message.

The difference between sync and async chunked uploading is that the file recombining and publishing (some large swift operations) is done on the job queue in async mode, and the client just polls the status from the job queue; sync mode does the swift operation on-the-spot and the request does not return until the operation is done.

On a side note, there are few tools/scripts that support async chunked uploading (UW, Rillke's script, and v2c are the only ones I know of), and there are a few tools/scripts that support chunked uploading only in sync mode, such as videoconvert, VicuñaUploader, vanilla pywikibot, and even our own documentation.

(@Tgr - my concern is for end-users not using Pywikibot, but the videoconvert tool. Thanks to @zhuyifei1999 and @Harej I learned that video2commons supports uploads (perhaps it used to not support uploads?), so there is a workaround for end-users for the moment. This, then, becomes a videoconvert tool limitation, rather than a blocker for end-user video uploads for people not familiar with the command line (ffmpeg etc.).)

(unfortunately, videoconvert does not seem to be tracking issues here on Phabricator...)

I doubt much can be done about this on the MediaWiki side (other than a better error message) so probably those tools need to switch to async uploading. Vicuna's issue tracker is here, Pywikipedia already has a task (T129216: Pywikibot should support async chunked uploading), couldn't find the place for videoconvert.