Opened 2 months ago

Last modified 5 weeks ago

#30926 needs_information defect

OnionPerf requests to onion service fail close towards completion with TGEN/READ error

Reported by: karsten Owned by:
Priority: Medium Milestone: Tor: 0.4.2.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-hs, improve-performance, 041-deferred-20190719
Cc: asn Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

We're currently investigating an issue where OnionPerf requests to onion service fail close towards completion with TGEN/READ error. I'm opening this ticket to attach/link the relevant logs. More (useful) information to follow.

Child Tickets

Attachments (2)

logs.tar.xz (2.6 MB) - added by karsten 2 months ago.
op-ab-2019-06-07-logs.tar.xz (2.4 MB) - added by karsten 2 months ago.

Change History (10)

Changed 2 months ago by karsten

Attachment: logs.tar.xz added

comment:1 Changed 2 months ago by asn

Keywords: 041-should tor-hs added
Milestone: Tor: 0.4.1.x-final
Status: newneeds_information

comment:2 Changed 2 months ago by asn

Example of failure:

2018-01-02 20:17:02 1514924222.876832 [info] [shd-tgen-transfer.c:833] [_tgentransfer_log] [transfer-status] transport TCP,18,localhost:127.0.0.1:49912,localhost:127.0.0.1:21869,73ut3hckbwugbkgd.onion:0.0.0.0:80,state=SUCCESS,error=NONE transfer transfer5m,12431,op-nl,GET,5242880,op-nl,16189,state=PAYLOAD,error=NONE total-bytes-read=5211141 total-bytes-write=56 payload-bytes-read=5211108/5242880 (99.39%)
2018-01-02 20:17:03 1514924223.681162 [info] [shd-tgen-transfer.c:192] [_tgentransfer_changeState] transfer transfer5m,12431,op-nl,GET,5242880,op-nl,16189,state=PAYLOAD,error=NONE moving from state PAYLOAD to state ERROR
2018-01-02 20:17:03 1514924223.681245 [info] [shd-tgen-transfer.c:200] [_tgentransfer_changeError] transfer transfer5m,12431,op-nl,GET,5242880,op-nl,16189,state=ERROR,error=NONE moving from error NONE to error READ
2018-01-02 20:17:03 1514924223.681295 [critical] [shd-tgen-transfer.c:457] [_tgentransfer_readPayload] read(): transport TCP,18,localhost:127.0.0.1:49912,localhost:127.0.0.1:21869,73ut3hckbwugbkgd.onion:0.0.0.0:80,state=SUCCESS,error=NONE transfer transfer5m,12431,op-nl,GET,5242880,op-nl,16189,state=ERROR,error=READ closed unexpectedly

comment:3 Changed 2 months ago by asn

We get this in the service side 5 seconds before the client connection closes:

Jan 02 20:16:57.000 [info] connection_edge_process_relay_cell(): sendme cell dropped, unknown stream (streamid 64043).

This tor version seems to be quite old (maybe 029?).

comment:4 in reply to:  3 Changed 2 months ago by arma

Replying to asn:

We get this in the service side 5 seconds before the client connection closes:

Jan 02 20:16:57.000 [info] connection_edge_process_relay_cell(): sendme cell dropped, unknown stream (streamid 64043).

That's potentially normal -- this is a stream-level sendme from the client to the service. The service will expect to get one of these after sending 250KBytes. If the service finishes sending the file, it will send an end cell, thus closing the stream from its perspective. If the end cell is heading toward the client, while the sendme cell is heading toward the service, then when it arrives at the service, the service will no longer remember what stream 64043 was.

comment:5 Changed 2 months ago by gaba

Keywords: improve-performance added

Changed 2 months ago by karsten

comment:6 in reply to:  3 Changed 2 months ago by karsten

Replying to asn:

This tor version seems to be quite old (maybe 029?).

Maybe, yes. But I don't think that this matters here. I just attached logs from op-ab (running 0.3.5.7-dev) for another case, this time a 1 MiB download from earlier this month that stopped after receiving 91.24% of the response:

2019-06-07 22:39:55 1559943595.389059 [info] [shd-tgen-transfer.c:1534] [_tgentransfer_log] [transfer-status] transport TCP,16,localhost:127.0.0.1:37054,localhost:127.0.0.1:48240,5bbbmrgzxhiykhah.onion:0.0.0.0:443,state=SUCCESS,error=NONE transfer transfer1m,3056,op-ab,GET,1048576,op-ab,834,state=PAYLOAD,error=NONE total-bytes-read=956746 total-bytes-write=55 payload-bytes-read=956715/1048576 (91.24%)
2019-06-07 22:39:56 1559943596.317712 [info] [shd-tgen-transport.c:408] [tgentransport_read] read(): socket 16 closed unexpectedly
2019-06-07 22:39:56 1559943596.317761 [info] [shd-tgen-transport.c:203] [_tgentransport_changeState] transport TCP,16,localhost:127.0.0.1:37054,localhost:127.0.0.1:48240,5bbbmrgzxhiykhah.onion:0.0.0.0:443,state=SUCCESS,error=NONE moving from state SUCCESS to state ERROR
2019-06-07 22:39:56 1559943596.317787 [info] [shd-tgen-transport.c:211] [_tgentransport_changeError] transport TCP,16,localhost:127.0.0.1:37054,localhost:127.0.0.1:48240,5bbbmrgzxhiykhah.onion:0.0.0.0:443,state=ERROR,error=NONE moving from error NONE to error READ
2019-06-07 22:39:56 1559943596.317807 [info] [shd-tgen-transfer.c:363] [_tgentransfer_changeState] transfer transfer1m,3056,op-ab,GET,1048576,op-ab,834,state=PAYLOAD,error=NONE moving from state PAYLOAD to state ERROR
2019-06-07 22:39:56 1559943596.317829 [info] [shd-tgen-transfer.c:371] [_tgentransfer_changeError] transfer transfer1m,3056,op-ab,GET,1048576,op-ab,834,state=ERROR,error=NONE moving from error NONE to error READ
2019-06-07 22:39:56 1559943596.317850 [critical] [shd-tgen-transfer.c:684] [_tgentransfer_readPayload] read(): transport TCP,16,localhost:127.0.0.1:37054,localhost:127.0.0.1:48240,5bbbmrgzxhiykhah.onion:0.0.0.0:443,state=ERROR,error=READ transfer transfer1m,3056,op-ab,GET,1048576,op-ab,834,state=ERROR,error=READ closed unexpectedly
2019-06-07 22:39:56 1559943596.317899 [message] [shd-tgen-transfer.c:1504] [_tgentransfer_log] [transfer-error] transport TCP,16,localhost:127.0.0.1:37054,localhost:127.0.0.1:48240,5bbbmrgzxhiykhah.onion:0.0.0.0:443,state=ERROR,error=READ transfer transfer1m,3056,op-ab,GET,1048576,op-ab,834,state=ERROR,error=READ total-bytes-read=956746 total-bytes-write=55 payload-bytes-read=956715/1048576 (91.24%) usecs-to-socket-create=16 usecs-to-socket-connect=159 usecs-to-proxy-init=198 usecs-to-proxy-choice=899 usecs-to-proxy-request=976 usecs-to-proxy-response=-1 usecs-to-command=4685610 usecs-to-response=6607887 usecs-to-first-byte=6607924 usecs-to-last-byte=-1 usecs-to-checksum=-1
2019-06-07 22:39:56 1559943596.317932 [info] [shd-tgen-transport.c:321] [_tgentransport_free] closing transport socket for fd 16

comment:7 Changed 5 weeks ago by nickm

Keywords: 041-deferred-20190719 added; 041-should removed

Add 041-deferred-20190719 tag to 041-should tickets I am deferring today.

comment:8 Changed 5 weeks ago by nickm

Milestone: Tor: 0.4.1.x-finalTor: 0.4.2.x-final
Note: See TracTickets for help on using tickets.