[needs test] Capability of interrupted downloads is logged in twistd.log

[zooko]

I happened to see this in the twisted.log of a Tahoe-1.3.0 node (the testgrid web gateway):

2009-04-22 17:05:34.866Z [-] Unhandled Error
        Traceback (most recent call last):
        Failure: exceptions.RuntimeError: Producer was not unregistered for /uri/URI%3ADIR2%3Adjrdkfawoqihigoett4g6auz6a%3Ajx5mplfpwexnoqff7y5e4zjus4lidm76dcuarpct7cckorh2dpgq/Axe_Versus_Laptop-theora-videoquality5-audioquality3.ogv

As far as I can tell, the register/unregister producer code in src/allmydata/immutable/download.py hasn't changed since before the v1.3.0 release, so I suspect this bug is still here in trunk. I assume that it doesn't cause any actual trouble beyond noise in the twistd.log... Or does it? Maybe it wastes some memory? I guess the next step is to find this error message in the Twisted code base (Twisted v2.5.0 was used here).

This is part of a cluster of tickets including: #562, #563, #685, #887, #1008, and #1904.

[warner]

is this happening when somebody is downloading the file and stops their browser before the download has completed?

I suspect that I added that exception, since I used to be in the habit of raising RuntimeError as a sort of assertion. I suspect that the only consequences of this problem would be that we'd keep the tahoe-side download going even though nobody's left on the HTTP side to receive the data. But it might also mean that I don't understand producers and consumers (and twisted.web) as well as I thought I did.

(similar code is used in the FTP and SFTP servers, so we should make sure we know what sort of access was being used for that particular operation)

[zooko]

The fact that this leads to caps and filenames being written into twistd.log is a privacy and confidentiality issue: #887 (twisted.web logs the uri on some exceptional conditions, leading to a privacy leak in logfiles)

[warner]

This looks like it's coming from Twisted directly, rather than from something which I wrote: twisted/web/http.py Request._cleanup (about line 591).

[davidsarah]

Not sure why this was priority 'minor'.

[davidsarah]

#1155 was a duplicate.

​Here's the Request._cleanup method in Twisted 10.1.0. I can't immediately see how to fix this, short of replacing the logging sink and filtering strings containing "URI:" in all log messages.

[warner]

This should be fixed in 4b7c94ece074ede2, pushed a few hours after the release of 1.8.0b2 . The fix is to make sure we call unregisterProducer in all cases, even when the connection is dropped (which calls our stopProducing method). At least, this stops the log message in my experiments.

[davidsarah]

We need a test for this, that would have failed before 4b7c94ece074ede2.

[warner]

not making it into 1.9

[zooko]

#887 was a duplicate of this.