Trying to upload T200223: Server side upload for -revi, I miserably failed (at least twice IIRC) with the warning:
FAILED: stashfailed: Could not read file "mwstore://local-swift-eqiad/local-temp/a/ac/15xi9btm14os.u9p1dr.1208681.webm.0".
I have no idea what's wrong with my file here <,< And I think this is partially reason that I can't see UploadStash page? (It 503s)
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | revi | T200223 Server side upload for -revi | |||
| Open | None | T200820 FAILED: stashfailed: Could not read file "mwstore://local-swift-eqiad/local-temp/a/ac/15xi9btm14os.u9p1dr.1208681.webm.0". | |||
| Resolved | Clement_Goubert | T358308 AssembleUploadChunksJob & PublishStashedFile jobs seem to be timing out at about 3 minutes, but should be ~20 minutes |
Odd UploadStash would fail, can you try again? Does the 503 report any further error?
I tried once again, actually stash was empty at the moment (meh) so I re-tried the upload with the expectation that the upload will fail (and UploadStash will fail again), but it managed to upload it successfully this time (meh).
Ack, thanks for the report @revi ! I'll defer to some people more intimate with uploadstash
I got the same error while trying to upload a file with Rillke's Chunked Upload script on https://commons.wikimedia.org/wiki/File:L%27Illustration,_mars-ao%C3%BBt_1849.pdf
( https://commons.wikimedia.org/wiki/User:Rillke/bigChunkedUpload.js )
03592: FAILED: stashfailed: Could not read file "mwstore://local-swift-eqiad/local-temp/2/2a/16981zp2ivt0.wq8wbr.1.pdf.0".
I think the file is in Upload stash: 16986mjwpyvc.x9ltso.1.pdf
And it is the second time, it happened today. There is another file stucked in Upload stash: 1697wll1czuk.rcpwyj.1.pdf
That error message is backend-fail-read in FileBackendStore::doConcatenate() I believe. The earliest error in the request is Memcached error for key "/*/mw-wan/WANCache:v:filebackend:local-swift-eqiad:wikipedia-commons:file:<hash>" on server "127.0.0.1:11213": A TIMEOUT OCCURRED; that key seems to come from FileBackendStore::fileCacheKey(). Tracing back code paths in FileBackend is not really feasible (we should probably add a backtrace to the memcached error) but I'm guessig something in FileBackendStore or SwiftFileBackend messes up cache error handling and interprets "file stat not in cache" as "file does not exist".
For the record, a 472 MB file got through: https://commons.wikimedia.org/wiki/File:M%C3%A9tin_-_L%E2%80%99Inde_d%E2%80%99aujourd%E2%80%99hui%2C_%C3%A9tude_sociale%2C_1918.pdf
while a 903 MB file failed: https://commons.wikimedia.org/wiki/File:L%27Illustration,_Sep-Dec_1849.pdf
Just received the same error on Commons for File:116th United States Congress House Floor - 2019-01-10.webm. Trying again.
It failed twice. :/ I guess I am going to use video2commons and then make a Phabricator tag if (when) it fails again. </3
FWIW, i've been investigating this. It does seem to be happening at commons with some regularity for larger uploads. However in the modern case it is backend-fail-notexists not the read error tgr mentions above.
What i have observed so far
So it seems like either Swift is randomly losing the files, or something is deleting them. (unfortunately, there is no logging in logstash of DELETE operations, so I don't know directly. Of course that is probably for good reason as the log would be huge)
These are the theories I have thought of so far. Not a lot of evidence to back up any of them.
I'd be surprised (and unhappy!) were swift randomly losing objects. If you have object names (ideally plus timestamps) from a recent example I could go grobbling in the logs to check.
[When I looked into a similar complaint recently (T355610) it looked like concatenation/assembly/what-have-you failed and DELETEd the fragments which then resulted in an object not found being returned to the user]
Apropos theory 3, we do run the swift object expirer, but the relevant headers are not set (except for some specific use cases e.g. phonos). So I don't think it can be that.
maybe what is happening is that two assemble jobs are running at the same time and the first one is successful. Previously i was investigating the possibility of two jobs where both fail and wondering why no errors happened. However if the first one succeeds there would be no error, source file would be deleted. The second would then fail due to missing files. The second one overwrites the status in db, thus the user only sees the failure. The only thing is that then the first job should make a new stash file, which while never published should still be visible in user's uploadstash.
Maybe I should add more logging to MW around this part. Although i have no idea how two jobs would happen. A log entry is generated when a job is inserted and there was only one. The Assemble job has retrying disabled.
Evidence for this theory:
T355610 Looks like the same issue, so that is helpful. thanks :)
I'd be surprised (and unhappy!) were swift randomly losing objects. If you have object names (ideally plus timestamps) from a recent example I could go grobbling in the logs to check.
Thanks. A recent example from commons: mwstore://local-swift-codfw/local-temp/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 . It should have been first uploaded at about Wed, 21 Feb 2024 20:19:09 and reported missing at Feb 21, 2024 @ 21:03:12.363
Change 1005632 had a related patch set uploaded (by Brian Wolff; author: Brian Wolff):
[mediawiki/core@master] Improve chunked upload jobs and abort assemble job if already in progress
Gerrit patch to detect the situation where jobs are racing each other. It will also abort the job if a race is detected, but if this race is actually happening with any frequency (which hopefully the logging code would detect) we would probably want to use a real lock for robustness. In principle there should never be more than one assemble job for a specific file, not just at a time, but ever, so races should not be happening 🤷
Here's the relevant logs, sorted by time:
moss-fe2001.codfw.wmnet: Feb 21 20:19:14 moss-fe2001 proxy-server: 10.192.48.105 10.192.32.51 21/Feb/2024/20/19/14 PUT /v1/AUTH_mw/wikipedia-commons-local-temp.b8/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 HTTP/1.0 201 - wikimedia/multi-http-client%20v1.1 AUTH_tk7b6ed208d... - - - tx948576b6a72e4600a62d1-0065d65ac1 - 0.9693 - - 1708546753.577275038 1708546754.546539783 - ms-fe1009.eqiad.wmnet: Feb 21 20:19:16 ms-fe1009 proxy-server: 10.192.48.105 10.64.0.166 21/Feb/2024/20/19/16 PUT /v1/AUTH_mw/wikipedia-commons-local-temp.b8/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 HTTP/1.0 201 - wikimedia/multi-http-client%20v1.1 AUTH_tke5beae87e... - - - tx4683f2a851d249ea89bf1-0065d65ac2 - 1.5437 - - 1708546754.563668013 1708546756.107330084 - ms-fe2013.codfw.wmnet: Feb 21 20:59:24 ms-fe2013 proxy-server: 10.194.152.76 10.192.0.87 21/Feb/2024/20/59/24 GET /v1/AUTH_mw/wikipedia-commons-local-temp.b8/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 HTTP/1.0 200 - wikimedia/multi-http-client%20v1.1 AUTH_tk7b6ed208d... - 97498542 - tx8b68cb8506d34d1a9bb03-0065d66420 - 12.5442 - - 1708549152.229032040 1708549164.773195744 0 ms-fe2013.codfw.wmnet: Feb 21 21:00:02 ms-fe2013 proxy-server: 10.194.152.76 10.192.0.87 21/Feb/2024/21/00/02 DELETE /v1/AUTH_mw/wikipedia-commons-local-temp.b8/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 HTTP/1.0 204 - wikimedia/multi-http-client%20v1.1 AUTH_tk7b6ed208d... - - - txfabad3d0f009413ea82dd-0065d66452 - 0.0458 - - 1708549202.850069761 1708549202.895848513 0 ms-fe1009.eqiad.wmnet: Feb 21 21:00:03 ms-fe1009 proxy-server: 10.194.152.76 10.64.0.166 21/Feb/2024/21/00/03 DELETE /v1/AUTH_mw/wikipedia-commons-local-temp.b8/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 HTTP/1.0 204 - wikimedia/multi-http-client%20v1.1 AUTH_tke5beae87e... - - - tx26b0b6c03f1b4577a65b7-0065d66453 - 0.0454 - - 1708549203.070249796 1708549203.115652323 0 ms-fe2013.codfw.wmnet: Feb 21 21:03:12 ms-fe2013 proxy-server: 10.194.155.232 10.192.0.87 21/Feb/2024/21/03/12 GET /v1/AUTH_mw/wikipedia-commons-local-temp.b8/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 HTTP/1.0 404 - wikimedia/multi-http-client%20v1.1 AUTH_tk7b6ed208d... - 70 - tx36a819fdb39c4d61bb4ee-0065d66510 - 0.0335 - - 1708549392.151752949 1708549392.185259581 0 ms-fe2013.codfw.wmnet: Feb 21 21:03:12 ms-fe2013 proxy-server: 10.194.155.232 10.192.0.87 21/Feb/2024/21/03/12 GET /v1/AUTH_mw/wikipedia-commons-local-temp.b8/b/b8/1aqaxe3dattw.u1suhi.6080484.webm.0 HTTP/1.0 404 - wikimedia/multi-http-client%20v1.1 AUTH_tk7b6ed208d... - 70 - txfffc016f7af4438eac05b-0065d66510 - 0.0284 - - 1708549392.332885504 1708549392.361268997 0
From which, I see:
Change 1005632 merged by jenkins-bot:
[mediawiki/core@master] Improve chunked upload jobs and abort assemble job if already in progress
Correlating with other logs, I think the first GET/DELETE is coming from mw-jobrunner.codfw.main-6c569f5b7d-jt5sx, and the second one from mw-jobrunner.codfw.main-6c569f5b7d-pckkc (both with reqid cce2ebe2-cc67-40e3-a4e4-e09308a9d640) [Commons does not generally seem to be on k8s nodes, but i think the job queue is]. This is consistent with the theory that there are two jobs running that are stepping on each other. My MW change should go live soon, and then we'd know more (I guess we could correlate also with which jobs are running with that reqid, but i don't have access to mw-log anymore to check that particular log, but in any case its probably not necessary as I'm now feeling pretty confident in this theory).
Change 1005698 had a related patch set uploaded (by Brian Wolff; author: Brian Wolff):
[mediawiki/core@wmf/1.42.0-wmf.19] Improve chunked upload jobs and abort assemble job if already in progress
Change 1005698 merged by jenkins-bot:
[mediawiki/core@wmf/1.42.0-wmf.19] Improve chunked upload jobs and abort assemble job if already in progress
Mentioned in SAL (#wikimedia-operations) [2024-02-22T22:30:38Z] <cjming@deploy2002> Started scap: Backport for [[gerrit:1005698|Improve chunked upload jobs and abort assemble job if already in progress (T200820)]]
Mentioned in SAL (#wikimedia-operations) [2024-02-22T22:32:02Z] <cjming@deploy2002> bawolff and cjming: Backport for [[gerrit:1005698|Improve chunked upload jobs and abort assemble job if already in progress (T200820)]] synced to the testservers (https://wikitech.wikimedia.org/wiki/Mwdebug)
Mentioned in SAL (#wikimedia-operations) [2024-02-22T22:40:24Z] <cjming@deploy2002> Finished scap: Backport for [[gerrit:1005698|Improve chunked upload jobs and abort assemble job if already in progress (T200820)]] (duration: 09m 46s)
Ok, so new logs do show a bunch of:
Tried to assemble upload that is in stage assembling/Poll
They show up exactly 4 minutes later then the initial start. The initial start never seems to complete either.
I'm now thinking what is happening: is that there is some sort of timeout on jobs of 4 minutes, and the job is automatically retried if it times-out, despite being a no retry job, and timeouts aren't logged anywhere.
The upload status is in MainObjectStash, which is presumably why a rollback is not touching it (Not that it should be touched, we want it not to be, but i was initially confused how that worked).
So things we could do here - First we should figure out how to make the AssembleUploadChunksJob have a longer timeout.
I guess it would also be nice to actually make the job retryable... but that seems more complicated.
Longer term, using swift large object support might be a better way to handle these files, since they are already chunked.
I wonder if the slow part of the process is deleting all the chunks. Im not 100% sure, but as far as i can tell that is not paralelized. It would also help explain the errors being file missing, instead of running out of time in middle of concatenate. Its also not super important since they will eventually get deleted anyways, maybe we should rearrange things so code reports success before doing delete step.
Presumably that would make the job retryable on failure as well.
Edit: we dont see the Stashed combined ({chunks} chunks) of {oldkey} under new name {filekey} log entry, so that suggests the job has to be failing either during chunk delete, during file verification, or during stashing of combined file. It looks like stashing a file calls $fileProps = $mwProps->getPropsFromPath( $path, true ); which i imagine will calculate an sha1, which is probably quite slow on a large file
As an aside here, we don't currently support swift large objects on the servers (and some of our infrastructure assumes that we will continue not to do so).
Change 1005965 had a related patch set uploaded (by Brian Wolff; author: Brian Wolff):
[mediawiki/core@master] Make chunked upload delete chunks in deferred job
Change 1006083 had a related patch set uploaded (by Brian Wolff; author: Brian Wolff):
[mediawiki/core@master] Optimize AssembleUploadChunks to reuse SHA1 hash instead of recalc
Change 1006083 merged by jenkins-bot:
[mediawiki/core@master] Optimize AssembleUploadChunks to reuse SHA1 hash instead of recalc
Change 1005965 merged by jenkins-bot:
[mediawiki/core@master] Make chunked upload delete chunks in deferred update
Change 1007998 had a related patch set uploaded (by Brian Wolff; author: Brian Wolff):
[mediawiki/core@master] Make verifyPartialFile reuse SHA1 hash if we already know
On discord, Sazpaimon suggested having chunked upload keep a running total of the SHA1 hash so far (e.g. using https://www.php.net/manual/en/function.hash-update.php ). That way MW never has to calculate the entire hash at one time, but instead the work is split over all the uploaded chunks.
I'm not sure if this is worth the complexity right now, seems like its easier to just increase the timeout on AssembleUploadChunks jobs.
I guess PublishStashedFile could be further optimized if we didn't verify the file. In theory, the file should already have been verified when uploaded to stash. If we don't need to verify the file, then there is no need to download the file locally, and all operations can take place directly on swift. However maybe that's not worth it, and its better just to be paranoid and re-verify the file at all stages.
Change 1007998 merged by jenkins-bot:
[mediawiki/core@master] Make verifyPartialFile reuse SHA1 hash if we already know