[tor-bugs] #16013 [Tor]: Assertion ENTRY_TO_CONN(conn)->state == AP_CONN_STATE_CIRCUIT_WAIT failed in circuit_get_open_circ_or_launch at circuituse.c:1835
Tor Bug Tracker & Wiki
blackhole at torproject.org
Sun Jun 21 23:31:09 UTC 2015
#16013: Assertion ENTRY_TO_CONN(conn)->state == AP_CONN_STATE_CIRCUIT_WAIT failed
in circuit_get_open_circ_or_launch at circuituse.c:1835
-----------------------------+-------------------------------------
Reporter: cypherpunks | Owner:
Type: defect | Status: needs_information
Priority: normal | Milestone: Tor: 0.2.7.x-final
Component: Tor | Version: Tor: unspecified
Resolution: | Keywords: regression 026-backport
Actual Points: | Parent ID:
Points: |
-----------------------------+-------------------------------------
Comment (by starlight):
100% reproducible
{{{
[err] circuit_get_open_circ_or_launch(): Bug: Connection state mismatch:
wanted AP_CONN_STATE_CIRCUIT_WAIT, but got 6 (waiting for rendezvous desc)
}}}
{{{
Jun 21 19:22:52.000 [debug] conn_write_callback(): socket 12 wants to
write.
Jun 21 19:22:53.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:53.000 [info] connection_ap_handshake_attach_circuit(): Intro
circ 3044306830 present and awaiting ack (rend 3615842360). Stalling.
(stream 7 sec old)
Jun 21 19:22:53.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:53.000 [info] connection_ap_handshake_attach_circuit(): Intro
circ 3044306830 present and awaiting ack (rend 3615842360). Stalling.
(stream 7 sec old)
Jun 21 19:22:53.000 [debug] conn_write_callback(): socket 12 wants to
write.
Jun 21 19:22:54.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:54.000 [info] connection_ap_handshake_attach_circuit(): Intro
circ 3044306830 present and awaiting ack (rend 3615842360). Stalling.
(stream 8 sec old)
Jun 21 19:22:54.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:54.000 [info] connection_ap_handshake_attach_circuit(): Intro
circ 3044306830 present and awaiting ack (rend 3615842360). Stalling.
(stream 8 sec old)
Jun 21 19:22:54.000 [debug] conn_write_callback(): socket 12 wants to
write.
Jun 21 19:22:55.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:55.000 [info] connection_ap_handshake_attach_circuit(): Intro
circ 3044306830 present and awaiting ack (rend 3615842360). Stalling.
(stream 9 sec old)
Jun 21 19:22:55.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:55.000 [info] connection_ap_handshake_attach_circuit(): Intro
circ 3044306830 present and awaiting ack (rend 3615842360). Stalling.
(stream 9 sec old)
Jun 21 19:22:55.000 [debug] conn_write_callback(): socket 12 wants to
write.
Jun 21 19:22:56.000 [debug] conn_read_callback(): socket 12 wants to read.
Jun 21 19:22:56.000 [debug] read_to_chunk(): Read 15 bytes. 15 on inbuf.
Jun 21 19:22:56.000 [info] rend_cache_purge(): Purging HS descriptor cache
Jun 21 19:22:56.000 [info] rend_client_purge_last_hid_serv_requests():
Purging client last-HS-desc-request-time table
Jun 21 19:22:56.000 [debug] conn_write_callback(): socket 12 wants to
write.
Jun 21 19:22:56.000 [debug] circuit_find_to_cannibalize(): Hunting for a
circ to cannibalize: purpose 9, uptime 0, capacity 1, internal 1
Jun 21 19:22:56.000 [info] circuit_launch_by_extend_info(): Cannibalizing
circ 'AAAPolicy' for purpose 9 (Hidden service client: Establishing
rendezvous point)
Jun 21 19:22:56.000 [debug] circuit_change_purpose(): changing purpose of
origin circ 48 from "General-purpose client" (5) to "Hidden service
client: Establishing rendezvous point" (9)
Jun 21 19:22:56.000 [info] rend_client_rendcirc_has_opened(): rendcirc is
open
Jun 21 19:22:56.000 [info] rend_client_send_establish_rendezvous():
Sending an ESTABLISH_RENDEZVOUS cell
Jun 21 19:22:56.000 [debug] pathbias_count_use_attempt(): Marked circuit
48 (7.000000/15.000000) as used for guard Pascal8
($7B2553AEA4A3FC9E1B513D772ECA652C8CC15337).
Jun 21 19:22:56.000 [debug] relay_send_command_from_edge_(): delivering 33
cell forward.
Jun 21 19:22:56.000 [debug] relay_send_command_from_edge_(): Sending a
RELAY_EARLY cell; 4 remaining.
Jun 21 19:22:56.000 [debug] circuit_package_relay_cell(): crypting a layer
of the relay cell.
Jun 21 19:22:56.000 [debug] circuit_package_relay_cell(): crypting a layer
of the relay cell.
Jun 21 19:22:56.000 [debug] circuit_package_relay_cell(): crypting a layer
of the relay cell.
Jun 21 19:22:56.000 [debug] append_cell_to_circuit_queue(): Made a circuit
active.
Jun 21 19:22:56.000 [debug] scheduler_channel_has_waiting_cells(): Channel
0 at 0x614000087240 went from waiting_for_cells to pending
Jun 21 19:22:56.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:56.000 [warn] Query '[scrubbed]' didn't have valid rend desc
in cache. Failing.
Jun 21 19:22:56.000 [info] circuit_get_open_circ_or_launch(): No intro
points for '[scrubbed]': re-fetching service descriptor.
Jun 21 19:22:56.000 [debug] rend_client_refetch_v2_renddesc(): Fetching v2
rendezvous descriptor for service [scrubbed]
Jun 21 19:22:56.000 [debug] directory_initiate_command_rend(): anonymized
1, use_begindir 1.
Jun 21 19:22:56.000 [debug] directory_initiate_command_rend(): Initiating
hidden-service v2 descriptor fetch
Jun 21 19:22:56.000 [info] connection_ap_make_link(): Making internal
anonymized tunnel to [scrubbed]:9001 ...
Jun 21 19:22:56.000 [debug] connection_add_impl(): new conn type Socks,
socket -1, address (Tor_internal), n_conns 10.
Jun 21 19:22:56.000 [debug] extend_info_from_node(): using
141.255.189.161:9001 for OxylEpsilon
Jun 21 19:22:56.000 [debug] circuit_find_to_cannibalize(): Hunting for a
circ to cannibalize: purpose 5, uptime 0, capacity 1, internal 1
Jun 21 19:22:56.000 [info] circuit_launch_by_extend_info(): Cannibalizing
circ 'redjohn1' for purpose 5 (General-purpose client)
Jun 21 19:22:56.000 [debug] circuit_send_next_onion_skin(): starting to
send subsequent skin.
Jun 21 19:22:56.000 [info] circuit_send_next_onion_skin(): Sending extend
relay cell.
Jun 21 19:22:56.000 [debug] relay_send_command_from_edge_(): delivering 14
cell forward.
Jun 21 19:22:56.000 [debug] relay_send_command_from_edge_(): Sending a
RELAY_EARLY cell; 5 remaining.
Jun 21 19:22:56.000 [debug] circuit_package_relay_cell(): crypting a layer
of the relay cell.
Jun 21 19:22:56.000 [debug] circuit_package_relay_cell(): crypting a layer
of the relay cell.
Jun 21 19:22:56.000 [debug] circuit_package_relay_cell(): crypting a layer
of the relay cell.
Jun 21 19:22:56.000 [debug] append_cell_to_circuit_queue(): Made a circuit
active.
Jun 21 19:22:56.000 [debug] scheduler_channel_has_waiting_cells(): Channel
1 at 0x614000086440 went from waiting_for_cells to pending
Jun 21 19:22:56.000 [info] connection_ap_make_link(): ... application
connection created and linked.
Jun 21 19:22:56.000 [debug] connection_add_impl(): new conn type
Directory, socket -1, address 141.255.189.161, n_conns 11.
Jun 21 19:22:56.000 [info] directory_get_from_hs_dir(): Sending fetch
request for v2 descriptor for service 'v4sciq74tvcydqip' with descriptor
ID 'soxxwg56bxmusmbapm2uc2xay527nole', auth type 0, and descriptor cookie
'[none]' to hidden service directory
$93C3E9A094D9B3F01785DB7580101F93D8D19A89~OxylEpsilon at 141.255.189.161
Jun 21 19:22:56.000 [info] connection_ap_handshake_attach_circuit(): Intro
(0) and rend (3216239652) circs are not both ready. Stalling conn. (10 sec
old)
Jun 21 19:22:56.000 [debug] circuit_get_open_circ_or_launch(): one on the
way!
Jun 21 19:22:56.000 [warn] Query '[scrubbed]' didn't have valid rend desc
in cache. Failing.
Jun 21 19:22:56.000 [info] circuit_get_open_circ_or_launch(): No intro
points for '[scrubbed]': re-fetching service descriptor.
Jun 21 19:22:56.000 [debug] rend_client_refetch_v2_renddesc(): Fetching v2
rendezvous descriptor for service [scrubbed]
Jun 21 19:22:56.000 [debug] directory_initiate_command_rend(): anonymized
1, use_begindir 1.
Jun 21 19:22:56.000 [debug] directory_initiate_command_rend(): Initiating
hidden-service v2 descriptor fetch
Jun 21 19:22:56.000 [info] connection_ap_make_link(): Making internal
anonymized tunnel to [scrubbed]:9001 ...
Jun 21 19:22:56.000 [debug] connection_add_impl(): new conn type Socks,
socket -1, address (Tor_internal), n_conns 12.
Jun 21 19:22:56.000 [debug] extend_info_from_node(): using
85.228.195.5:9001 for hashmaps
Jun 21 19:22:56.000 [debug] circuit_find_to_cannibalize(): Hunting for a
circ to cannibalize: purpose 5, uptime 0, capacity 1, internal 1
Jun 21 19:22:56.000 [debug] new_route_len(): Chosen route length 4
(6629/6629 routers suitable).
Jun 21 19:22:56.000 [info] onion_pick_cpath_exit(): Using requested exit
node '$943CE107D30C653BC4CAF3840006DB8D1BCA6B29~hashmaps at 85.228.195.5'
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Path is 0 long; we want
4
Jun 21 19:22:56.000 [debug] extend_info_from_node(): using
23.254.166.222:80 for Pascal8
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Chose router
$7B2553AEA4A3FC9E1B513D772ECA652C8CC15337~Pascal8 at 23.254.166.222 for
hop 1 (exit is hashmaps)
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Path is 1 long; we want
4
Jun 21 19:22:56.000 [debug] choose_good_middle_server(): Contemplating
intermediate hop 1: random choice.
Jun 21 19:22:56.000 [debug] router_choose_random_node(): We found 5770
running nodes.
Jun 21 19:22:56.000 [debug] router_choose_random_node(): We removed 0
excludednodes, leaving 5770 nodes.
Jun 21 19:22:56.000 [debug] router_choose_random_node(): We removed 16
excludedsmartlist, leaving 5757 nodes.
Jun 21 19:22:56.000 [debug] compute_weighted_bandwidths(): Generated
weighted bandwidths for rule weight as middle node based on weights
Wg=0.408700 Wm=1.000000 We=0.000000 Wd=0.000000 with total bw 0
Jun 21 19:22:56.000 [debug] extend_info_from_node(): using 5.9.158.68:9001
for freespeech4thedumb1
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Chose router
$7E2F94EA9214EC6CD05A0FC1BA51A0FA30FC83C7~freespeech4thedumb1 at
5.9.158.68 for hop 2 (exit is hashmaps)
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Path is 2 long; we want
4
Jun 21 19:22:56.000 [debug] choose_good_middle_server(): Contemplating
intermediate hop 2: random choice.
Jun 21 19:22:56.000 [debug] router_choose_random_node(): We found 5770
running nodes.
Jun 21 19:22:56.000 [debug] router_choose_random_node(): We removed 0
excludednodes, leaving 5770 nodes.
Jun 21 19:22:56.000 [debug] router_choose_random_node(): We removed 62
excludedsmartlist, leaving 5714 nodes.
Jun 21 19:22:56.000 [debug] compute_weighted_bandwidths(): Generated
weighted bandwidths for rule weight as middle node based on weights
Wg=0.408700 Wm=1.000000 We=0.000000 Wd=0.000000 with total bw 0
Jun 21 19:22:56.000 [debug] extend_info_from_node(): using
213.136.71.21:9001 for maltimore
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Chose router
$78C4FCE0851C99A4E05563C6F520C68F28BD916E~maltimore at 213.136.71.21 for
hop 3 (exit is hashmaps)
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Path is 3 long; we want
4
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Chose router
$943CE107D30C653BC4CAF3840006DB8D1BCA6B29~hashmaps at 85.228.195.5 for hop
4 (exit is hashmaps)
Jun 21 19:22:56.000 [debug] onion_extend_cpath(): Path is complete: 4
steps long
Jun 21 19:22:56.000 [debug] circuit_handle_first_hop(): Looking for
firsthop '23.254.166.222:80'
Jun 21 19:22:56.000 [debug] circuit_handle_first_hop(): Conn open.
Delivering first onion skin.
Jun 21 19:22:56.000 [debug] circuit_send_next_onion_skin(): First skin;
sending create cell.
Jun 21 19:22:56.000 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 2423611392,
channel ID 0 (0x614000087240)
Jun 21 19:22:56.000 [debug] circuit_deliver_create_cell(): Chosen circID
2423611392.
Jun 21 19:22:56.000 [debug] circuitmux_attach_circuit(): Attaching circuit
2423611392 on channel 0 to cmux 0x6080000d7c20
Jun 21 19:22:56.000 [debug] append_cell_to_circuit_queue(): Made a circuit
active.
Jun 21 19:22:56.000 [info] circuit_send_next_onion_skin(): First hop:
finished sending CREATE cell to
'$7B2553AEA4A3FC9E1B513D772ECA652C8CC15337~Pascal8 at 23.254.166.222'
Jun 21 19:22:56.000 [info] connection_ap_make_link(): ... application
connection created and linked.
Jun 21 19:22:56.000 [debug] connection_add_impl(): new conn type
Directory, socket -1, address 85.228.195.5, n_conns 13.
Jun 21 19:22:56.000 [info] directory_get_from_hs_dir(): Sending fetch
request for v2 descriptor for service 'v4sciq74tvcydqip' with descriptor
ID 'soxxwg56bxmusmbapm2uc2xay527nole', auth type 0, and descriptor cookie
'[none]' to hidden service directory
$943CE107D30C653BC4CAF3840006DB8D1BCA6B29~hashmaps at 85.228.195.5
Jun 21 19:22:56.000 [info] connection_ap_handshake_attach_circuit(): Intro
(0) and rend (3216239652) circs are not both ready. Stalling conn. (10 sec
old)
Jun 21 19:22:56.000 [err] circuit_get_open_circ_or_launch(): Bug:
Connection state mismatch: wanted AP_CONN_STATE_CIRCUIT_WAIT, but got 6
(waiting for rendezvous desc)
Jun 21 19:22:56.000 [err] tor_assertion_failed_(): Bug:
src/or/circuituse.c:1841: circuit_get_open_circ_or_launch: Assertion
ENTRY_TO_CONN(conn)->state == AP_CONN_STATE_CIRCUIT_WAIT failed; aborting.
Jun 21 19:22:56.000 [err] Bug: Assertion ENTRY_TO_CONN(conn)->state ==
AP_CONN_STATE_CIRCUIT_WAIT failed in circuit_get_open_circ_or_launch at
src/or/circuituse.c:1841. Stack trace:
Jun 21 19:22:56.000 [err] Bug:
/usr/local/lib64/libasan.so.1(__interceptor_backtrace+0x3a)
[0x2b1b9500712a]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(log_backtrace+0x43) [0x2b1b945aac9d]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(tor_assertion_failed_+0xf6)
[0x2b1b945d15df]
Jun 21 19:22:56.000 [err] Bug: /w/gpl/tor-0.2.6.9-asus/src/or/tor
[0x2b1b944a488b]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(connection_ap_handshake_attach_circuit+0x9bf)
[0x2b1b944a6ac5]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(connection_ap_attach_pending+0x1d2)
[0x2b1b944f9680]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(circuit_build_needed_circs+0x30)
[0x2b1b944a450b]
Jun 21 19:22:56.000 [err] Bug: /w/gpl/tor-0.2.6.9-asus/src/or/tor
[0x2b1b94343218]
Jun 21 19:22:56.000 [err] Bug: /w/gpl/tor-0.2.6.9-asus/src/or/tor
[0x2b1b94343a52]
Jun 21 19:22:56.000 [err] Bug: /w/gpl/tor-0.2.6.9-asus/src/or/tor
[0x2b1b94615215]
Jun 21 19:22:56.000 [err] Bug:
/usr/local/lib64/libevent-2.0.so.5(event_base_loop+0x7e6) [0x2b1b96145066]
Jun 21 19:22:56.000 [err] Bug: /w/gpl/tor-0.2.6.9-asus/src/or/tor
[0x2b1b94339d24]
Jun 21 19:22:56.000 [err] Bug: /w/gpl/tor-0.2.6.9-asus/src/or/tor
[0x2b1b94339ec9]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(do_main_loop+0x356) [0x2b1b943445a8]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(tor_main+0x1aa) [0x2b1b94345c8e]
Jun 21 19:22:56.000 [err] Bug:
/w/gpl/tor-0.2.6.9-asus/src/or/tor(main+0x19) [0x2b1b94339289]
Jun 21 19:22:56.000 [err] Bug:
/lib64/libc.so.6(__libc_start_main+0xf4) [0x2b1b97f8d9f4]
Jun 21 19:22:56.000 [err] Bug: /w/gpl/tor-0.2.6.9-asus/src/or/tor
[0x2b1b94339149]
}}}
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/16013#comment:19>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list