While experimenting with Tor v0.2.3.4-alpha's "optimistic data" and thus keeping an eye on the logs, I noticed that I get a lot of the following messages (with and without "optimistic data"):
Sep 20 13:47:57.428 [debug] {APP} connection_edge_process_relay_cell(): Now seen 8236 relay cells here (command 2, stream 49411). Sep 20 13:47:57.428 [debug] {APP} connection_edge_process_relay_cell(): circ deliver_window now 911. Sep 20 13:47:57.428 [info] {APP} connection_edge_process_relay_cell(): data cell dropped, unknown stream (streamid 49411). Sep 20 13:47:57.431 [debug] {APP} connection_edge_process_relay_cell(): Now seen 8237 relay cells here (command 2, stream 49411). Sep 20 13:47:57.431 [debug] {APP} connection_edge_process_relay_cell(): circ deliver_window now 910. Sep 20 13:47:57.431 [info] {APP} connection_edge_process_relay_cell(): data cell dropped, unknown stream (streamid 49411). Sep 20 13:47:57.432 [debug] {APP} connection_edge_process_relay_cell(): Now seen 8238 relay cells here (command 2, stream 49411). Sep 20 13:47:57.432 [debug] {APP} connection_edge_process_relay_cell(): circ deliver_window now 909. Sep 20 13:47:57.432 [info] {APP} connection_edge_process_relay_cell(): data cell dropped, unknown stream (streamid 49411). Sep 20 13:47:57.432 [debug] {APP} connection_edge_process_relay_cell(): Now seen 8239 relay cells here (command 2, stream 49411). [...] Sep 20 13:48:01.479 [debug] {APP} connection_edge_process_relay_cell(): Now seen 8379 relay cells here (command 2, stream 49411). Sep 20 13:48:01.479 [debug] {APP} connection_edge_process_relay_cell(): circ deliver_window now 968. Sep 20 13:48:01.479 [info] {APP} connection_edge_process_relay_cell(): data cell dropped, unknown stream (streamid 49411). Sep 20 13:48:01.479 [debug] {APP} relay_lookup_conn(): found conn for stream 49410.
Sometimes up to 400-500 dropped cells per unknown stream id. The deliver window seems to go down to 900 and then starts at 999 again.
It's my impression that it always happens after the client connection is closed prematurely, something my feed reader unfortunately does frequently:
Sep 20 13:47:56.608 [debug] {APP} connection_edge_process_relay_cell(): Now seen 8235 relay cells here (command 2, stream 49411). Sep 20 13:47:56.608 [debug] {APP} connection_edge_process_relay_cell(): circ deliver_window now 912. Sep 20 13:47:56.792 [debug] {APP} circuit_consider_stop_edge_reading(): considering layer_hint->package_window 995 Sep 20 13:47:56.792 [info] {EDGE} connection_edge_reached_eof(): conn (fd 14) reached eof. Closing.
I assume it can take several seconds for the exit relay to stop sending data and the Tor client has to continue reading from the stream to keep the circuit usable. Is that correct?
Is it intended behaviour for the Tor client to forget a stream id before the stream is actually closed on the remote end?
Fabian
On Wed, Sep 21, 2011 at 10:20:22PM +0200, Fabian Keil wrote:
While experimenting with Tor v0.2.3.4-alpha's "optimistic data" and thus keeping an eye on the logs, I noticed that I get a lot of the following messages (with and without "optimistic data"):
Sep 20 13:47:57.428 [debug] {APP} connection_edge_process_relay_cell(): Now seen 8236 relay cells here (command 2, stream 49411). Sep 20 13:47:57.428 [debug] {APP} connection_edge_process_relay_cell(): circ deliver_window now 911. Sep 20 13:47:57.428 [info] {APP} connection_edge_process_relay_cell(): data cell dropped, unknown stream (streamid 49411).
Sometimes up to 400-500 dropped cells per unknown stream id. The deliver window seems to go down to 900 and then starts at 999 again.
It's my impression that it always happens after the client connection is closed prematurely, something my feed reader unfortunately does frequently:
Exactly so.
I assume it can take several seconds for the exit relay to stop sending data and the Tor client has to continue reading from the stream to keep the circuit usable. Is that correct?
Yes. The client closes the stream, and sends an end cell toward the exit. Meanwhile, the exit sends stuff toward the client. Because of that pesky "the intermediate hops can't look inside the circuit" feature, there's nothing that the relays can do to realize that these cells aren't wanted anymore.
This behavior is particularly unfortunate when the client is on a modem, asks for a page, gives up on the page, asks for another one, and then the first one fills his pipe for a little while, making the second one not work either.
I guess we could kill the whole circuit that the stream was on, which would propagate forward and meet up with the data cells propagating back. But that wouldn't work in situations where you wanted the circuit to stick around, e.g. for its other streams.
Is it intended behaviour for the Tor client to forget a stream id before the stream is actually closed on the remote end?
Yes. No good can come of remembering the streamid just so we can know that we meant to throw the cells away. Unless you have something in mind?
--Roger
Roger Dingledine arma@mit.edu wrote:
On Wed, Sep 21, 2011 at 10:20:22PM +0200, Fabian Keil wrote:
I assume it can take several seconds for the exit relay to stop sending data and the Tor client has to continue reading from the stream to keep the circuit usable. Is that correct?
Yes. The client closes the stream, and sends an end cell toward the exit. Meanwhile, the exit sends stuff toward the client. Because of that pesky "the intermediate hops can't look inside the circuit" feature, there's nothing that the relays can do to realize that these cells aren't wanted anymore.
This behavior is particularly unfortunate when the client is on a modem, asks for a page, gives up on the page, asks for another one, and then the first one fills his pipe for a little while, making the second one not work either.
In my case the feed reader seems to request most images twice, aborting the first request prematurely. I'm not sure how much this actually affects the performance.
I guess we could kill the whole circuit that the stream was on, which would propagate forward and meet up with the data cells propagating back. But that wouldn't work in situations where you wanted the circuit to stick around, e.g. for its other streams.
Maybe I should experiment with that.
Is it intended behaviour for the Tor client to forget a stream id before the stream is actually closed on the remote end?
Yes. No good can come of remembering the streamid just so we can know that we meant to throw the cells away. Unless you have something in mind?
Nope. I just wasn't sure if my interpretation of the logs was correct, and from the code it wasn't obvious to me in what kind of situation unknown cells are to be expected.
Thanks for the explanation, Roger.
Fabian
-
Fabian Keil -
Roger Dingledine