[tor-dev] connection_edge_process_relay_cell(): data cell dropped, unknown stream

[Fabian Keil]

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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 196 bytes
Desc: not available
URL: <http://lists.torproject.org/pipermail/tor-dev/attachments/20110921/fd07e228/attachment.pgp>