[tor-bugs] #23543 [Core Tor/Tor]: prop224: Disconnects on long-lasting HS connections (possibly because of mds)
Tor Bug Tracker & Wiki
blackhole at torproject.org
Sun Sep 17 11:44:08 UTC 2017
#23543: prop224: Disconnects on long-lasting HS connections (possibly because of
mds)
-----------------------------------------+---------------------------------
Reporter: asn | Owner: (none)
Type: defect | Status: new
Priority: Medium | Milestone: Tor:
| 0.3.2.x-final
Component: Core Tor/Tor | Version:
Severity: Normal | Resolution:
Keywords: tor-hs prop224 prop224-bugs | Actual Points:
Parent ID: | Points: 1
Reviewer: | Sponsor:
-----------------------------------------+---------------------------------
Comment (by asn):
Here is another such disconnect case from yesterday evening. It's a legacy
HS client running latest master connecting to a legacy HS:
{{{
Sep 16 17:29:31.000 [debug] connection_edge_process_relay_cell(): Now seen
55751 relay cells here (command 9, stream 0).
Sep 16 17:29:31.000 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() returning circuit 0x7f8c23b46820 for
circ_id 2915300815, channel ID 6 (0x7f8c240de460)
Sep 16 17:29:31.000 [debug] pathbias_count_use_success(): Marked circuit
151 (7.000000/8.000000) as used successfully for guard motmot
($E248C3A604E196137A3175D4B2E4328922178B47)
Sep 16 17:29:31.000 [info] circuit_mark_for_close_(): Circuit 2915300815
marked for close at src/or/circuitbuild.c:1543 (orig reason: 520, new
reason: 0)
Sep 16 17:29:31.000 [debug] connection_or_process_cells_from_inbuf(): 16:
starting, inbuf_datalen 0 (0 pending in tls object).
Sep 16 17:29:31.000 [debug] connection_bucket_refill_helper():
global_read_bucket now 1073741824.
Sep 16 17:29:31.000 [debug] connection_bucket_refill_helper():
or_conn->read_bucket now 1073741824.
Sep 16 17:29:31.000 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() returning circuit 0x7f8c23b46820 for
circ_id 2915300815, channel ID 6 (0x7f8c240de460)
Sep 16 17:29:31.000 [debug] circuitmux_append_destroy_cell(): Cmux at
0x7f8c23af4dc0 queued a destroy for circ 2915300815, cmux counter is now
1, global counter is now 1
Sep 16 17:29:31.000 [debug] circuitmux_append_destroy_cell(): Primed a
buffer.
Sep 16 17:29:31.000 [debug] channel_write_cell_generic_(): Writing p
0x7f8c2364cee0 to channel 0x7f8c240de460 with global ID 6
Sep 16 17:29:31.000 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() returning circuit 0x7f8c23b46820 for
circ_id 2915300815, channel ID 6 (0x7f8c240de460)
Sep 16 17:29:31.000 [debug] channel_tls_get_overhead_estimate_method():
Estimated overhead ratio for TLS chan 6 is 1.053891
Sep 16 17:29:31.000 [debug] channel_update_xmit_queue_size(): Increasing
queue size for channel 6 by 541 from 0 to 541
Sep 16 17:29:31.000 [debug] channel_update_xmit_queue_size(): Increasing
global queue size by 541 for channel 6, new size is 541
Sep 16 17:29:31.000 [debug] scheduler_adjust_queue_size(): Queue size
adjustment by +541 for channel 6
Sep 16 17:29:31.000 [debug] scheduler_update_queue_heuristic(): Queue
heuristic is now 0
Sep 16 17:29:31.000 [debug] scheduler_adjust_queue_size(): Queue heuristic
is now 541
Sep 16 17:29:31.000 [debug] circuitmux_notify_xmit_destroy(): Cmux at
0x7f8c23af4dc0 sent a destroy, cmux counter is now 0, global counter is
now 0
Sep 16 17:29:31.000 [debug] channel_send_destroy(): Sending destroy
(circID 2915300815) on channel 0x7f8c240de460 (global ID 6)
Sep 16 17:29:31.000 [info] connection_edge_destroy(): CircID 0: At an
edge. Marking connection for close.
Sep 16 17:29:31.000 [info] rend_client_note_connection_attempt_ended():
Connection attempt for d6sfftbz6pkwfwwl has ended; cleaning up temporary
state.
Sep 16 17:29:31.000 [debug] conn_close_if_marked(): Cleaning up connection
(fd 12).
Sep 16 17:29:31.000 [debug] connection_remove(): removing socket 12 (type
Socks), n_conns now 4
Sep 16 17:29:31.000 [debug] connection_free_(): closing fd 12.
Sep 16 17:29:31.000 [debug] conn_write_callback(): socket 16 wants to
write.
Sep 16 17:29:31.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 ready
to flush, 0 remain.
Sep 16 17:29:31.000 [debug] connection_handle_write_impl(): After TLS
write of 514: 0 read, 543 written
Sep 16 17:29:31.000 [debug] channel_tls_get_overhead_estimate_method():
Estimated overhead ratio for TLS chan 6 is 1.053891
Sep 16 17:29:31.000 [debug] channel_update_xmit_queue_size(): Decreasing
queue size for channel 6 by 541 from 541 to 0
Sep 16 17:29:31.000 [debug] channel_update_xmit_queue_size(): Decreasing
global queue size by 541 for channel 6, new size is 0
Sep 16 17:29:31.000 [debug] scheduler_adjust_queue_size(): Queue size
adjustment by -541 for channel 6
Sep 16 17:29:31.000 [debug] scheduler_adjust_queue_size(): Queue heuristic
is now 0
Sep 16 17:29:31.000 [debug] connection_bucket_refill_helper():
global_write_bucket now 1073741824.
Sep 16 17:29:31.000 [debug] connection_bucket_refill_helper():
or_conn->write_bucket now 1073741824.
Sep 16 17:29:32.000 [debug] conn_read_callback(): socket 7 wants to read.
Sep 16 17:29:32.000 [debug] connection_handle_listener_read(): Connection
accepted on socket 12 (child of fd 7).
Sep 16 17:29:32.000 [info] connection_handle_listener_read(): New SOCKS
connection opened from 127.0.0.1.
Sep 16 17:29:32.000 [debug] connection_add_impl(): new conn type Socks,
socket 12, address 127.0.0.1, n_conns 4.
Sep 16 17:29:32.000 [debug] conn_read_callback(): socket 12 wants to read.
Sep 16 17:29:32.000 [debug] read_to_chunk(): Read 33 bytes. 33 on inbuf.
Sep 16 17:29:32.000 [debug] connection_ap_handshake_process_socks():
entered.
Sep 16 17:29:32.000 [debug] parse_socks(): socks4: Everything is here.
Success.
Sep 16 17:29:32.000 [debug] connection_ap_handshake_rewrite(): Client
asked for d6sfftbz6pkwfwwl.onion:6697
Sep 16 17:29:32.000 [info] connection_ap_handle_onion(): Got a hidden
service request for ID 'd6sfftbz6pkwfwwl'
Sep 16 17:29:32.000 [info] rep_hist_note_used_internal(): New port
prediction added. Will continue predictive circ building for 2580 more
seconds.
Sep 16 17:29:32.000 [info] connection_ap_handle_onion(): Descriptor is
here. Great.
Sep 16 17:29:32.000 [info] connection_edge_process_inbuf(): data from edge
while in 'waiting for circuit' state. Leaving it on buffer.
Sep 16 17:29:32.000 [notice] Application request when we haven't used
client functionality lately. Optimistically trying directory fetches
again.
}}}
The incriminating mark for close at circuitbuild.c:1543 seems to be from
`circuit_truncated()`. Could this be from natural causes where one of the
rend circuit hops died and the circ had to be rebuilt? :/
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/23543#comment:5>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list