Opened 2 months ago

Closed 7 weeks ago

#31958 closed defect (fixed)

connection_dir_is_anonymous: Non-fatal assertion !(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL) failed

Reported by: dgoulet Owned by: dgoulet
Priority: Medium Milestone: Tor: 0.4.2.x-final
Component: Core Tor/Tor Version: Tor: 0.4.2.1-alpha
Severity: Normal Keywords: regression, 042-must, 042-backport
Cc: teor, asn Actual Points: 0.1
Parent ID: #30344 Points: 0.1
Reviewer: teor Sponsor: Sponsor27-must

Description

Hmm, I just noticed this on one of my test relay:

Sep 14 17:35:18.196 [warn] tor_bug_occurred_(): Bug: src/feature/dircommon/directory.c:229: connection_dir_is_anonymous: Non-fatal assertion !(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL) failed. (Future instances of this warning will be silenced.) (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug: Tor 0.4.2.0-alpha-dev (git-796a9b37ea346f41): Non-fatal assertion !(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL) failed in connection_dir_is_anonymous at src/feature/dircommon/directory.c:229. Stack trace: (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(log_backtrace_impl+0x46) [0x56174b20aae6] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(tor_bug_occurred_+0x16c) [0x56174b205d9c] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(connection_dir_is_anonymous+0x131) [0x56174b0ef421] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(directory_handle_command+0x1ef) [0x56174b19755f] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(connection_dir_process_inbuf+0x95) [0x56174b0efb85] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(connection_handle_read+0xa0d) [0x56174b064bfd] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(+0x6fe0e) [0x56174b069e0e] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(+0x1e8f8) [0x7f65e17278f8] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(event_base_loop+0x53f) [0x7f65e172833f] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(do_main_loop+0xd9) [0x56174b06b0f9] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(tor_run_main+0x128d) [0x56174b058c8d] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(tor_main+0x3a) [0x56174b0560ca] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(main+0x19) [0x56174b055c59] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7f65e09c2b97] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)
Sep 14 17:35:18.257 [warn] Bug:     /root/git/tor/src/app/tor(_start+0x2a) [0x56174b055caa] (on Tor 0.4.2.0-alpha-dev 796a9b37ea346f41)

This is recent code that reject HSDir single hop connections (#24964). Offending piece of code is:

  /* Get the previous channel to learn if it is a client or relay link. */
  if (BUG(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL)) {
    log_info(LD_DIR, "Rejected HSDir request: no p_chan");
    return false;
  }

Not sure why this can BUG()...

Child Tickets

Change History (10)

comment:1 Changed 2 months ago by teor

Parent ID: #30344

It could be #30344?
The channel is closed, but the command is still being processed?

Otherwise we might have sent an origin circuit to this function, which seems unlikely.

comment:2 in reply to:  1 Changed 2 months ago by dgoulet

Owner: set to dgoulet
Status: newaccepted

Replying to teor:

It could be #30344?

Could be!

The channel is closed, but the command is still being processed?

Actually, yes that is possible that the channel was closed and thus leading to the p_chan to be NULL.

And if we can start reading on a closed connection, we might end up in that code path.

An approach here could be to test #30344 once merged and see if this happens again. On two relays I operate, I saw this assert() in few hours so over couple days of running the patch, I think we'll be sure that we fixed it.

Not sure we can easily unit test this with the whole connection "start reading" code complexity :S.

I'll take ownership of this and test #30344 fix in production.

comment:3 Changed 2 months ago by dgoulet

Status: acceptedneeds_information

comment:4 Changed 2 months ago by Felixix

Sep 28 10:05:31.873 [notice] Tor 0.4.2.1-alpha running on FreeBSD with Libevent 2.1.11-stable, OpenSSL LibreSSL 3.0.0, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.4.3. 
Sep 28 10:04:55.000 [notice] Your Tor server's identity key fingerprint is 'BeastieJoy63 52BFADA8BEAA01BA46C8F767F83C18E2FE50C1B9' 
...
Oct 10 10:41:17.000 [warn] tor_bug_occurred_: Bug: src/feature/dircommon/directory.c:229: connection_dir_is_anonymous: Non-fatal assertion !(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL) failed. (Future instances of this warning will be silenced.) (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug: Tor 0.4.2.1-alpha: Non-fatal assertion !(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL) failed in connection_dir_is_anonymous at src/feature/dircommon/directory.c:229. Stack trace: (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x12f484c <log_backtrace_impl+0x4c> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x12f0976 <tor_bug_occurred_+0x1d6> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x11ec178 <connection_dir_is_anonymous+0x118> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x11ed8b0 <directory_handle_command+0x500> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x11ec83d <connection_dir_process_inbuf+0x4d> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x114dcfd <connection_handle_read+0x8fd> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x119e323 <connection_add_impl+0x203> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x8013d52b3 <event_base_assert_ok_nolock_+0xc23> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x8013d118f <event_base_loop+0x53f> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x11a0801 <do_main_loop+0xf1> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x113dd7b <tor_run_main+0x14b> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x113c656 <tor_main+0x66> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 10 10:41:17.000 [warn] Bug:     0x113c309 <main+0x19> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha ) 
...
Oct 11 03:17:18.000 [warn] tor_bug_occurred_: Bug: src/feature/dircommon/directory.c:229: connection_dir_is_anonymous: Non-fatal assertion !(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL) failed. (Future instances of this warning will be silenced.) (on Tor 0.4.2.1-alpha ) 
Oct 11 03:17:18.000 [warn] Bug: Tor 0.4.2.1-alpha: Non-fatal assertion !(CONST_TO_OR_CIRCUIT(circ)->p_chan == NULL) failed in connection_dir_is_anonymous at src/feature/dircommon/directory.c:229. Stack trace: (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x12f484c <log_backtrace_impl+0x4c> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x12f0976 <tor_bug_occurred_+0x1d6> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x11ec178 <connection_dir_is_anonymous+0x118> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x11ed8b0 <directory_handle_command+0x500> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x11ec83d <connection_dir_process_inbuf+0x4d> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x114dcfd <connection_handle_read+0x8fd> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x119e323 <connection_add_impl+0x203> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x8013d52b3 <event_base_assert_ok_nolock_+0xc23> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x8013d118f <event_base_loop+0x53f> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x11a0801 <do_main_loop+0xf1> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x113dd7b <tor_run_main+0x14b> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x113c656 <tor_main+0x66> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha )
Oct 11 03:17:18.000 [warn] Bug:     0x113c309 <main+0x19> at /usr/local/bin/tor (on Tor 0.4.2.1-alpha ) 

Cheers, Felix

-format corrected-

Last edited 2 months ago by Felixix (previous) (diff)

comment:5 Changed 2 months ago by dgoulet

So far so good on my relay, #30344 seems to have fixed this issue.

comment:6 Changed 2 months ago by dgoulet

Resolution: fixed
Status: needs_informationclosed

I'm quite confident that this was fixed with #30344. I can't hit that on 2 of my testing relays which used to see it at least once a day.

Closing for now. Lets reopen if it appears in >= 0.4.2.2-alpha.

comment:7 Changed 7 weeks ago by dgoulet

Resolution: fixed
Status: closedreopened

Nope... still there in 042! :(

comment:8 Changed 7 weeks ago by dgoulet

Status: reopenedassigned

comment:9 Changed 7 weeks ago by dgoulet

Actual Points: 0.1y
Points: 0.1
Reviewer: teor
Status: assignedneeds_review

So turns out that the circuit can be marked for close at this stage so the fix is to check for that before inspecting the p_chan on the circuit. If the circuit is _not_ marked for close and the p_chan is NULL, then we have a problem thus I left the BUG() there.

While having help from Nick, he spotted that the log() are specific to HSDir and that is no good. Thus, this branch also changes that.

Finally, there is a commit to send back a 503 code in case of a single hop rejection which I believe is what should be done based on dir-spec.txt and other similar case in the code.

PR: https://github.com/torproject/tor/pull/1466
Branch: ticket31958_042_01

comment:10 Changed 7 weeks ago by teor

Actual Points: 0.1y0.1
Keywords: 042-backport added
Resolution: fixed
Status: needs_reviewclosed
Version: Tor: 0.4.2.1-alpha

Looks fine, merged to 0.4.2 and later.

Note: See TracTickets for help on using tickets.