corrupted file displayed to user after failure to download followed by retry #698
Labels
No Label
0.2.0
0.3.0
0.4.0
0.5.0
0.5.1
0.6.0
0.6.1
0.7.0
0.8.0
0.9.0
1.0.0
1.1.0
1.10.0
1.10.1
1.10.2
1.10a2
1.11.0
1.12.0
1.12.1
1.13.0
1.14.0
1.15.0
1.15.1
1.2.0
1.3.0
1.4.1
1.5.0
1.6.0
1.6.1
1.7.0
1.7.1
1.7β
1.8.0
1.8.1
1.8.2
1.8.3
1.8β
1.9.0
1.9.0-s3branch
1.9.0a1
1.9.0a2
1.9.0b1
1.9.1
1.9.2
1.9.2a1
LeastAuthority.com automation
blocker
cannot reproduce
cloud-branch
code
code-dirnodes
code-encoding
code-frontend
code-frontend-cli
code-frontend-ftp-sftp
code-frontend-magic-folder
code-frontend-web
code-mutable
code-network
code-nodeadmin
code-peerselection
code-storage
contrib
critical
defect
dev-infrastructure
documentation
duplicate
enhancement
fixed
invalid
major
minor
n/a
normal
operational
packaging
somebody else's problem
supercritical
task
trivial
unknown
was already fixed
website
wontfix
worksforme
No Milestone
No Assignees
3 Participants
Notifications
Due Date
No due date set.
Reference: tahoe-lafs/trac-2024-07-25#698
Loading…
Reference in New Issue
No description provided.
Delete Branch "%!s(<nil>)"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
I clicked the bookmark to load my blog writably, and I got an HTML page saying:
I looked at the "Recent Uploads/Downloads" page and saw that my attempt to load it had failed:
The three details pages are attached:
mapupdate-35.html
,retrieve-35.html
, anddown-13.html
.I looked in the
logs
directory of my Tahoe node, and saw that thetwistd.log
had these same error messages aboutDeadReferenceError
.twistd.log
is attached (bzipped).I looked in the
logs/incidents
directory and saw that there was one incident that was recorded at the time of this attempt to load. It is attached asincident-2009-05-07-094319-jg54cni.flog.bz2
. The triggering incident line isSo far I think that this Tahoe demonstrating suboptimal handling of a network failure -- it should probably have returned an HTTP 503 "Service Unavailable" (or maybe 504 "Gateway Timeout" or just 500 "Internal Server Error"?) instead of an HTML page containing cryptic error messages. But it gets worse:
Then I hit the "Reload" button on my web browser, and I got the same two error message lines followed by a partial copy of the contents of my blog source code! This result is attached as
wiki.html
(bzipped). This is what I mean by a corrupted file being displayed to the user.The "Recent Uploads and Downloads" now says:
The fact that there is no download following the map-update is surprising to me.
The details from the new
mapupdate-36.html
andretrieve-36.html
are attached. There are no new problems reported in thetwistd.log
or thelogs/incidents/
.I'm going to go ahead and mark this with
Priority: critical
because I see a corrupted file and I don't understand why. Hopefully it will turn out to be a bug in the web browser, which is an unstable release: firefox-3.53.5~b4~hg20090330r24021+nobinonly-0ubuntu1
.Attachment mapupdate-35.html (1745 bytes) added
Attachment retrieve-35.html (1000 bytes) added
Attachment down-13.html (1817 bytes) added
Attachment twistd.log.bz2 (7368 bytes) added
Attachment incident-2009-05-07-094319-jg54cni.flog.bz2 (38154 bytes) added
Attachment wiki.html.bz2 (147850 bytes) added
Attachment mapupdate-36.html (1744 bytes) added
Attachment retrieve-36.html (1000 bytes) added
That's pretty weird. The first thing that comes to mind is that a server
connection could have been lost in the middle of the download (in this case,
after we've retrieved the UEB and some of the hashes, but before we've
retrieved the first data block). The web server has to commit to success
(200) or failure (404 or 500 or something) before it starts sending any of
the plaintext, but it doesn't want to store the entire file either. So it
bases the HTTP response code upon the initial availability of k servers, and
hopes they'll stick around for the whole download.
When we get a "late failure" (i.e. one of the servers disconnects in the
middle), the webapi doesn't have a lot of choices. At the moment, it emits a
brief error message (attached to whatever partial content has already been
written out), then drops the HTTP connection, and hopes that the client is
observant enough to notice that the number of received bytes does not match
the previously-sent Content-Length header, and then announce an error on the
client side.
If the application doing the fetch (perhaps the browser, perhaps tiddywiki
itself?) doesn't strictly check the Content-Length header, then it could get
partial content without an error message.
There are two directions to fix this:
segment at a time, possibly giving the server a chance to emit an error
header in between segments: this would let us respond better to these
errors
lost servers better, which might reduce the rate at which these errors
occur
I'm not sure what's up with the happens-again-after-retry part of this. For
the benefit of partial-range fetches, we sometimes cache the file's contents
locally, and I don't know how that would interact with lost-server errors.
It's at least conceivable that the caching mechanism doesn't realize that an
error occurred, and tries to pass partial data to the second download
attempt. But most browsers don't send a Range: header at all (it's mostly
streaming media players which do that), and I believe that the webapi will
skip this whole caching thing unless it sees a Range: header.
By the way, the client doing the fetch was Firefox 3.5 beta 4 -- more details in the original report. It's the package named "firefox-3.5" in Ubuntu Jaunty.
Also, Brian, what do you think about the fact that there was no download step after the
When I reloaded, but there was a download step after those two steps when I initially loaded? This means the client (Firefox-3.5b4 web browser) didn't actually fetch the contents of my blog when I hit "Reload" and instead just spewed that messed-up page (attached as "wiki.html.bz2"), right? In that case the "displaying corrupt page" is actually Firefox's problem (although as David-Sarah Hopwood pointed out on the mailing list, the way that Tahoe commits to a 200 success code before completely downloading the file means this can always happen by accident).
Certainly something that Tahoe did was unusual, see the attached file
incident-2009-05-07-094319-jg54cni.flog.bz2
, which, when viewed withflogtool web-viewer incident-2009-05-07-094319-jg54cni.flog.bz2
shows this among other things:I just got this failure again. The file in question (my blog) has been appended-to since the original report, so now its total size is different from last time. Here is the accompanying foolscap incident report. I did not hit re-load in this case, I just opened a new tab and clicked on the bookmark that opens up my blog in writeable mode.
Attachment incident-2009-05-14-142935-v7cl57a.flog.bz2 (14926 bytes) added
The triggering incident in that new incident log (as displayed by
flogtool web-viewer
is:So I think we need to split this ticket up into (at least):
A ticket to switch the wui/wapi to chunked encoding so that we can unambiguously signal late errors to the client.
This ticket, whose focus is probably going to turn to seeing if I can reproduce this problem with any other web browser than the Firefox-3.5b4 that I've seen it on.
A ticket to investigate the
WEIRD Tub.connectorFinished
mentioned in comment:70966. Is that right, Brian, that it deserves investigation?Okay, re topic 2 from comment:70967, I see that the corrupted page that I get is actually the complete contents of my wiki with the first 2302 or 2306 bytes of it overwritten by the Twisted error messages.
That is: my wiki begins with the following 4000 bytes:
When I encountered this failure the first time, the first 4000 bytes of the resulting page that I got looked like this:
See what I mean? It looks like Firefox 3.5b4 has overwritten the first 2302 or so bytes of the file with the twisted error message. Note that it doesn't exactly line up -- the twisted error message from
<html>
to</html>
inclusive is 2302 bytes, but the first bytes of the original file, 19 Feb 2009)
I would expect to begin on byte 2306 rather than byte 2302. Maybe there was a newline conversion or the header got subtly rewritten a little between the time I captured the above view of "my wiki" and the time the bad wiki was emitted.Anyway, this makes me pretty sure that Firefox-3.5b4 is doing something mighty funny here. Certainly I don't think Tahoe is sending those bytes down in an HTTP response. Indeed, from the "Current Uploads Downloads" log, we can see that Tahoe wasn't asked for the contents of the wiki at all (the "update in MODE_READ" and the "retrieve" operations are the get the directory, not to get the actual
wiki.html
file from the directory). Firefox-3.5b4 must have supplied the cached contents of the wiki itself, then overwritten the first few bytes of it with the twisted error message, then displayed it to the user. Ugh.I suppose we should report this on the firefox issue tracker...
Okay I reported this to the Ubuntu maintainers of firefox via launchpad:
https://bugs.launchpad.net/ubuntu/+source/firefox/+bug/382444 # short read from server results in cached page with the first few bytes overwritten by the short read result
Closing this ticket as 'invalid'.
I've opened a ticket for Firefox-3.5b4: https://bugzilla.mozilla.org/show_bug.cgi?id=496205
Replying to zooko:
This is now #822.
Does this still deserve its own ticket?
I believe Brian downgraded that event to no longer be considered "weird" so it would stop triggering incident reports.
WEIRD Tub.connectorFinished: WEIRD, <foolscap.negotiate.TubConnector object at 0x21ace10 from vraj3cgb5eqs5xrb44qgqvwo4obbdhfd to qvqv7jmm76yfhdjuuzeqyfuwlqinpofd> is not in [....]
This unexplained behavior may be related to #653, as described in /tahoe-lafs/trac-2024-07-25/issues/5715#comment:20. So, I guess it isn't clear to me whether we should ticket that issue or instead engage in some strategy which makes our use of foolscap immune to such issues. I suppose if we were going to do that then we should ticket that.