[tor-bugs] #28970 [Core Tor/Tor]: tor_bug_occurred_(): Bug: ../src/or/hs_client.c:624: setup_intro_circ_auth_key: Non-fatal assertion

Tor Bug Tracker & Wiki blackhole at torproject.org
Mon Sep 9 07:45:06 UTC 2019


#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


More information about the tor-bugs mailing list