[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]
Re: [tor-bugs] #28970 [Core Tor/Tor]: tor_bug_occurred_(): Bug: ../src/or/hs_client.c:624: setup_intro_circ_auth_key: Non-fatal assertion
#28970: tor_bug_occurred_(): Bug: ../src/or/hs_client.c:624:
setup_intro_circ_auth_key: Non-fatal assertion
-------------------------------------------------+-------------------------
Reporter: torcrash | Owner: dgoulet
Type: defect | Status:
| reopened
Priority: High | Milestone: Tor:
| 0.4.2.x-final
Component: Core Tor/Tor | Version: Tor:
| 0.3.4.9
Severity: Critical | Resolution:
Keywords: tor-client, tor-hs, postfreeze-ok, | Actual Points:
040-unreached-must, network-team-roadmap- |
august, regression?, 041-unreached-must |
Parent ID: #29995 | Points: 5
Reviewer: | Sponsor:
| Sponsor27-must
-------------------------------------------------+-------------------------
Changes (by asn):
* status: closed => reopened
* resolution: fixed =>
Comment:
Hmm, I got this on a recent 042 branch of mine
(https://github.com/asn-d6/tor/tree/padanalysis) which is based on
`e57209dc32`. That should include all the fixes from above as it is from
about a month ago.
Fortunately I have info logs which might be helpful. The fun thing is that
a NEWNYM occured between cannibalization and use of intro circ:
{{{
Sep 09 10:36:23.000 [info] circuit_launch_by_extend_info(): Cannibalizing
circ 2971206838 (id: 18) for purpose 6 (Hidden service client: Connecting
to intro point)
Sep 09 10:36:23.000 [info] circuit_send_intermediate_onion_skin(): Sending
extend relay cell.
Sep 09 10:36:23.000 [info] rep_hist_note_used_internal(): New port
prediction added. Will continue predictive circ building for 2484 more
seconds.
Sep 09 10:36:23.000 [info] connection_ap_handshake_attach_circuit(): Intro
2971206838 (id: 18) and rend circuit 2792227503 (id: 17) circuits are not
both ready. Stalling
conn. (0 sec old)
Sep 09 10:36:24.000 [info] hs_client_receive_rendezvous_acked(): Received
an RENDEZVOUS_ESTABLISHED. This circuit is now ready for rendezvous.
Sep 09 10:36:24.000 [info] circpad_setup_machine_on_circ(): Registering
machine client_rp_circ to origin circ 17 (10)
Sep 09 10:36:24.000 [info] circpad_node_supports_padding(): Checking
padding: supported
Sep 09 10:36:24.000 [info] circpad_negotiate_padding(): Negotiating
padding on circuit 17 (10)
Sep 09 10:36:24.000 [info] circpad_machine_spec_transition(): Circpad
machine 0 transitioning from 0 to 1
Sep 09 10:36:24.000 [info] circpad_choose_state_length(): State length
sampled to 1.
Sep 09 10:36:24.000 [info] circpad_machine_schedule_padding(): Padding in
751 usec
Sep 09 10:36:24.000 [info] circpad_machine_schedule_padding(): Padding in
0 sec, 751 usec
Sep 09 10:36:24.000 [info] connection_ap_handshake_attach_circuit(): ready
rend circ 2792227503 (id: 17) already here. Nointro-ack yet on intro
2971206838 (id: 18). (str
eam 1 sec old)
Sep 09 10:36:24.000 [info] connection_ap_handshake_attach_circuit(): Intro
2971206838 (id: 18) and rend circuit 2792227503 (id: 17) circuits are not
both ready. Stalling
conn. (1 sec old)
Sep 09 10:36:24.000 [info] circpad_send_padding_cell_for_callback():
Callback: Sending padding to origin circuit 17 (10) [length: 0]
Sep 09 10:36:24.000 [info] circpad_machine_spec_transition(): Circpad
machine 0 transitioning from 1 to 65535
Sep 09 10:36:24.000 [info] circpad_handle_padding_negotiated(): Middle
node did not accept our padding request.
Sep 09 10:36:24.000 [info] connection_ap_handshake_attach_circuit(): ready
rend circ 2792227503 (id: 17) already here. Nointro-ack yet on intro
2971206838 (id: 18). (str
eam 1 sec old)
Sep 09 10:36:24.000 [info] connection_ap_handshake_attach_circuit(): Intro
2971206838 (id: 18) and rend circuit 2792227503 (id: 17) circuits are not
both ready. Stalling
conn. (1 sec old)
Sep 09 10:36:24.000 [info] circuit_predict_and_launch_new(): Have 7 clean
circs (0 uptime-internal, 0 internal), need another hidden service circ.
Sep 09 10:36:24.000 [info] extend_info_from_node(): Including Ed25519 ID
for $0FEDEBE83C1F2DE3D6673876BBA1433CCF0ADE51~jannis at 31.31.74.47
Sep 09 10:36:24.000 [info] select_primary_guard_for_circuit(): Selected
primary guard Unnamed ($C07622052739697129BA49A5DF3C503CE1AAA100) for
circuit.
Sep 09 10:36:24.000 [info] extend_info_from_node(): Including Ed25519 ID
for $C07622052739697129BA49A5DF3C503CE1AAA100~Unnamed at 78.129.180.14
Sep 09 10:36:24.000 [info] extend_info_from_node(): Including Ed25519 ID
for $ACE29EC7700BD112DEB42B934E5E443476CD577C~StoneCat at 195.201.26.175
Sep 09 10:36:24.000 [info] circuit_send_first_onion_skin(): First hop:
finished sending CREATE cell to
'$C07622052739697129BA49A5DF3C503CE1AAA100~Unnamed at 78.129.180.1
4'
Sep 09 10:36:24.000 [info] circuit_finish_handshake(): Finished building
circuit hop:
Sep 09 10:36:24.000 [info] internal (high-uptime) circ (length 3, last hop
jannis): $C07622052739697129BA49A5DF3C503CE1AAA100(open)
$ACE29EC7700BD112DEB42B934E5E443476CD
577C(closed) $0FEDEBE83C1F2DE3D6673876BBA1433CCF0ADE51(closed)
Sep 09 10:36:24.000 [info] circuit_send_intermediate_onion_skin(): Sending
extend relay cell.
Sep 09 10:36:24.000 [info] handle_deferred_signewnym_cb(): Honoring
delayed NEWNYM request
Sep 09 10:36:24.000 [notice] Executing NEWNYM
Sep 09 10:36:24.000 [info] rend_cache_purge(): Purging HS v2 descriptor
cache
Sep 09 10:36:24.000 [info] rend_cache_failure_purge(): Purging HS v2
failure cache
Sep 09 10:36:24.000 [info] hs_purge_last_hid_serv_requests(): Purging
client last-HS-desc-request-time table
Sep 09 10:36:24.000 [info] cancel_descriptor_fetches(): Hidden service
client descriptor fetches cancelled.
Sep 09 10:36:24.000 [info] hs_cache_client_intro_state_purge(): Hidden
service client introduction point state cache purged.
Sep 09 10:36:24.000 [info] hs_cache_purge_as_client(): Hidden service
client descriptor cache purged.
Sep 09 10:36:24.000 [info] hs_client_purge_state(): Hidden service client
state has been purged.
Sep 09 10:36:24.000 [info] connection_edge_process_inbuf(): data from edge
while in 'waiting for circuit' state. Leaving it on buffer.
Sep 09 10:36:24.000 [info] connection_edge_reached_eof(): conn (fd 15)
reached eof. Closing.
Sep 09 10:36:24.000 [info] connection_handle_listener_read(): New SOCKS
connection opened from 127.0.0.1.
Sep 09 10:36:24.000 [info] connection_ap_handle_onion(): No descriptor
found in our cache for
ieed562tnprqmalo7geqcgxqcdixbg2czptgmqxlxx4v2kwrmb74ufad. Fetching.
Sep 09 10:36:24.000 [info] rep_hist_note_used_internal(): New port
prediction added. Will continue predictive circ building for 2484 more
seconds.
Sep 09 10:36:24.000 [info] rep_hist_note_used_internal(): New port
prediction added. Will continue predictive circ building for 2484 more
seconds.
Sep 09 10:36:24.000 [info] connection_ap_make_link(): Making internal
anonymized tunnel to 51.68.140.94:443 ...
Sep 09 10:36:24.000 [info] connection_ap_make_link(): ... application
connection created and linked.
Sep 09 10:36:24.000 [info] directory_launch_v3_desc_fetch(): Descriptor
fetch request for service QQg++1Nr4wYBbvmJARrwENFwm0LL5mZC6735XSrRYH8 with
blinded key ecp1LrfJD36sKrkzHCxuel+psRktL3Cg6fZcaGb85io to directory
$71EFE4314646C4613895509723BFD354D8EABCAF~Cosworth01 at 51.68.140.94
Sep 09 10:36:24.000 [info] connection_edge_process_inbuf(): data from edge
while in 'waiting for rendezvous desc' state. Leaving it on buffer.
Sep 09 10:36:24.000 [info] extend_info_from_node(): Including Ed25519 ID
for $71EFE4314646C4613895509723BFD354D8EABCAF~Cosworth01 at 51.68.140.94
Sep 09 10:36:24.000 [info] onion_pick_cpath_exit(): Using requested exit
node '$71EFE4314646C4613895509723BFD354D8EABCAF~Cosworth01 at
51.68.140.94'
Sep 09 10:36:24.000 [info] select_primary_guard_for_circuit(): Selected
primary guard Unnamed ($C07622052739697129BA49A5DF3C503CE1AAA100) for
circuit.
Sep 09 10:36:24.000 [info] extend_info_from_node(): Including Ed25519 ID
for $C07622052739697129BA49A5DF3C503CE1AAA100~Unnamed at 78.129.180.14
Sep 09 10:36:24.000 [info] extend_info_from_node(): Including Ed25519 ID
for $134DED8B9FC5EEFD61AEF65659CF4AF0AA7FBCB5~Unnamed at 213.239.204.62
Sep 09 10:36:24.000 [info] extend_info_from_node(): Including Ed25519 ID
for $3F05B8C1DF491BBF5E7DD199440911A84D9165D8~Unnamed at 91.211.247.246
Sep 09 10:36:24.000 [info] circuit_send_first_onion_skin(): First hop:
finished sending CREATE cell to
'$C07622052739697129BA49A5DF3C503CE1AAA100~Unnamed at 78.129.180.14'
Sep 09 10:36:24.000 [info] connection_edge_process_inbuf(): data from edge
while in 'waiting for circuit' state. Leaving it on buffer.
Sep 09 10:36:24.000 [info] connection_edge_process_inbuf(): data from edge
while in 'waiting for circuit' state. Leaving it on buffer.
Sep 09 10:36:24.000 [info] circuit_finish_handshake(): Finished building
circuit hop:
Sep 09 10:36:24.000 [info] internal (high-uptime) circ (length 4, last hop
): $C07622052739697129BA49A5DF3C503CE1AAA100(open)
$46644B13F6409018E14ECEE1E9594740064C9F24(open)
$DC79C9D75CFD7A91F9232922E05D225CBDCB7703(open)
$7C499ACD60FB651DD486B6D802290A3EBBECCD84(open)
Sep 09 10:36:24.000 [info] entry_guards_note_guard_success(): Recorded
success for primary confirmed guard Unnamed
($C07622052739697129BA49A5DF3C503CE1AAA100)
Sep 09 10:36:24.000 [info] circuit_build_no_more_hops(): circuit built!
Sep 09 10:36:24.000 [info] client_intro_circ_has_opened(): Introduction
circuit 2971206838 has opened. Attaching streams.
Sep 09 10:36:24.000 [warn] tor_bug_occurred_(): Bug:
src/feature/hs/hs_client.c:685: setup_intro_circ_auth_key: Non-fatal
assertion !(desc == NULL) failed. (Future instances of this warning will
be silenced.) (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: Non-fatal assertion !(desc == NULL) failed
in setup_intro_circ_auth_key at src/feature/hs/hs_client.c:685. Stack
trace: (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(log_backtrace_impl+0x46)
[0x560f75f444f6] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(tor_bug_occurred_+0x16b)
[0x560f75f3f8fb] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug:
./src/app/tor(hs_client_circuit_has_opened+0x3b0) [0x560f75e40ce0] (on Tor
0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug:
./src/app/tor(circuit_send_next_onion_skin+0x2b8) [0x560f75dbb588] (on Tor
0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(+0xb8eb3)
[0x560f75df1eb3] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug:
./src/app/tor(circuit_receive_relay_cell+0x2b5) [0x560f75df3ff5] (on Tor
0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug:
./src/app/tor(command_process_cell+0x2c0) [0x560f75dd5bb0] (on Tor 0.4.2.0
-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug:
./src/app/tor(channel_tls_handle_cell+0x253) [0x560f75db5433] (on Tor
0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(+0xa595c)
[0x560f75dde95c] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug:
./src/app/tor(connection_handle_read+0xaac) [0x560f75da2c4c] (on Tor
0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(+0x6eebe)
[0x560f75da7ebe] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: /usr/lib/x86_64-linux-
gnu/libevent-2.1.so.6(+0x229ba) [0x7fedcecba9ba] (on Tor 0.4.2.0-alpha-dev
eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: /usr/lib/x86_64-linux-
gnu/libevent-2.1.so.6(event_base_loop+0x5a7) [0x7fedcecbb537] (on Tor
0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(do_main_loop+0xdd)
[0x560f75da91dd] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(tor_run_main+0x1115)
[0x560f75d96af5] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(tor_main+0x3a)
[0x560f75d9418a] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(main+0x19)
[0x560f75d93d69] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: /lib/x86_64-linux-
gnu/libc.so.6(__libc_start_main+0xeb) [0x7fedce74009b] (on Tor 0.4.2.0
-alpha-dev eef7896e854c3d6d)
Sep 09 10:36:24.000 [warn] Bug: ./src/app/tor(_start+0x2a)
[0x560f75d93dba] (on Tor 0.4.2.0-alpha-dev eef7896e854c3d6d)
}}}
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/28970#comment:28>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs