Opened 3 months ago

Closed 7 weeks ago

#33491 closed defect (fixed)

tor_bug_occurred_: Bug: src/core/or/dos.c:697: dos_new_client_conn: Non-fatal assertion !(entry == NULL) failed. (Future instances of this warning will be silenced.) (on Tor 0.4.2.6 )

Reported by: sjcjonker Owned by: dgoulet
Priority: Medium Milestone: Tor: 0.3.5.x-final
Component: Core Tor/Tor Version: Tor: 0.3.3.2-alpha
Severity: Normal Keywords: consider-backport-after-0434, tor-dos FreeBSD 043-backport 042-backport, 041-backport, 035-backport
Cc: Actual Points:
Parent ID: Points:
Reviewer: teor Sponsor:

Description

Hi there,

Receiving the below report, searched for 'src/core/or/dos.c:697' no hits, so opening ticket, please let me know if further info is needed to troubleshoot.

FreeBSD <<hostname>> 12.1-RELEASE-p2 FreeBSD 12.1-RELEASE-p2 GENERIC amd64

Mar  1 13:53:33 <<hostname>> Tor[86742]: tor_bug_occurred_: Bug: src/core/or/dos.c:697: dos_new_client_conn: Non-fatal assertion !(entry == NULL) failed. (Future instances of this warning will be silenced.) (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug: Tor 0.4.2.6: Non-fatal assertion !(entry == NULL) failed in dos_new_client_conn at src/core/or/dos.c:697. Stack trace: (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x12f4acc <log_backtrace_impl+0x5c> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x12f0b76 <tor_bug_occurred_+0x1d6> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x118d9a5 <channel_do_open_actions+0xf5> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x118d88e <channel_change_state_open+0x2e> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x1191a57 <channel_tls_handle_state_change_on_orconn+0x67> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x1144946 <connection_or_set_state_open+0x26> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x11923ee <channel_tls_handle_cell+0x88e> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x1140d52 <connection_or_process_inbuf+0x152> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x114ddad <connection_handle_read+0x8fd> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x119e3ee <connection_add_impl+0x23e> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x8013d72b3 <event_base_assert_ok_nolock_+0xc23> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x8013d318f <event_base_loop+0x53f> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x11a0881 <do_main_loop+0xf1> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x113de68 <tor_run_main+0x128> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x113c656 <tor_main+0x66> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:53:33 <<hostname>> Tor[86742]: Bug:     0x113c309 <main+0x19> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: tor_bug_occurred_: Bug: src/core/or/dos.c:697: dos_new_client_conn: Non-fatal assertion !(entry == NULL) failed. (Future instances of this warning will be silenced.) (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug: Tor 0.4.2.6: Non-fatal assertion !(entry == NULL) failed in dos_new_client_conn at src/core/or/dos.c:697. Stack trace: (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x12f4acc <log_backtrace_impl+0x5c> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x12f0b76 <tor_bug_occurred_+0x1d6> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x118d9a5 <channel_do_open_actions+0xf5> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x118d88e <channel_change_state_open+0x2e> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x1191a57 <channel_tls_handle_state_change_on_orconn+0x67> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x1144946 <connection_or_set_state_open+0x26> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x11923ee <channel_tls_handle_cell+0x88e> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x1140d52 <connection_or_process_inbuf+0x152> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x114ddad <connection_handle_read+0x8fd> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x119e3ee <connection_add_impl+0x23e> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x8013d72b3 <event_base_assert_ok_nolock_+0xc23> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x8013d318f <event_base_loop+0x53f> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x11a0881 <do_main_loop+0xf1> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x113de68 <tor_run_main+0x128> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x113c656 <tor_main+0x66> at /usr/local/bin/tor (on Tor 0.4.2.6 )
Mar  1 13:54:37 <<hostname>> Tor[86742]: Bug:     0x113c309 <main+0x19> at /usr/local/bin/tor (on Tor 0.4.2.6 )

Child Tickets

Change History (16)

comment:1 Changed 3 months ago by arma

See #25223 for a previous backtrace that looks awfully similar (but was supposedly fixed in 0.3.3.3-alpha).

comment:2 Changed 3 months ago by arma

Cc: dgoulet added

cc'ing dgoulet as the fixer of the previous bug

comment:3 Changed 3 months ago by sjcjonker

Checking matters further it seems the trigger happens when the connection comes from / via obfs4proxy.

comment:4 Changed 3 months ago by nickm

Keywords: 043-backport 042-backport added
Milestone: Tor: 0.4.4.x-final

comment:5 Changed 3 months ago by dgoulet

Cc: dgoulet removed
Owner: set to dgoulet
Status: newaccepted

comment:6 in reply to:  3 Changed 3 months ago by dgoulet

Status: acceptedneeds_information

Replying to sjcjonker:

Checking matters further it seems the trigger happens when the connection comes from / via obfs4proxy.

So hmmm... I think it has to do that your relay is a bridge and the code records the client with a transport_name but the DoS subsystem doesn't do that, it uses NULL every time and so it doesn't find the entry.

What I wonder here is why all the sudden we are seeing this obvious bug... I run an obs4 bridge and I just check, never seen that BUG() :S ...

What is the obs4 version you are using?

comment:7 Changed 3 months ago by dgoulet

I've confirmed that obfs4 is sending the obfs4 transport name... so I really wonder why that BUG() wasn't hit on all PTs out there.

comment:8 Changed 3 months ago by sjcjonker

Here are the versions:

[root@torrie ~]# uname -a
FreeBSD torrie.dev.sjc.nl 12.1-RELEASE-p2 FreeBSD 12.1-RELEASE-p2 GENERIC  amd64
[root@torrie ~]# tor --version
Tor version 0.4.2.6.
[root@torrie ~]# obfs4proxy --version
obfs4proxy-0.0.11

tor and obfs4proxy are from the packages, as indicated here:
https://community.torproject.org/relay/setup/guard/freebsd/
https://community.torproject.org/relay/setup/bridge/freebsd/

Could it be because the obfs4 is listening on IPv6, besides my normal bridge which has both IPv4 and IPv6 connectivity as per here:
https://metrics.torproject.org/rs.html#search/C51818DB4F3C03EFCA00C127EAA2780DFAFC8862

I have an complete other IPv6 prefix at my disposal so I added a IPv6 obfsproxy the whole config is:

SOCKSPort 127.0.0.1:9050
SOCKSPolicy accept 127.0.0.1/32
SOCKSPolicy reject *
Log notice syslog
RunAsDaemon 1
DataDirectory /var/db/tor
ControlPort 9051
CookieAuthentication 1
CookieAuthFileGroupReadable 0
DataDirectoryGroupReadable 0
DisableDebuggerAttachment 0
BandwidthRate 50 MBits
BandwidthBurst 60 MBits
ORPort 80.127.139.6:443 NoListen
ORPort 192.168.<<xxx.yyy>>:443 NoAdvertise
ORPort [2001:985:e77:5::9]:443
Nickname SJC01
RelayBandwidthRate 50 MBits
RelayBandwidthBurst 60 MBits
ContactInfo SJC Tor Admin <tor AT sjc dot nl>
DirPort 80
DirPortFrontPage /usr/local/etc/tor/tor-info-notice.html
ExitRelay 0
ClientUseIPv6 1
ClientPreferIPv6ORPort 1
IPv6Exit 1
ExitPolicy reject6 *:*
ExitPolicy reject *:*
ServerTransportPlugin obfs4 exec /usr/local/bin/obfs4proxy --enableLogging --logLevel=INFO
ServerTransportListenAddr obfs4 [2001<<REMOVED>>]:<<REMOVED>>
ExtORPort auto

When I manually set this obfs4proxy as my only proxy in torbrowser it works despite the error.

Please let me know if more info is required.

comment:9 Changed 3 months ago by dgoulet

Status: needs_informationaccepted

comment:10 Changed 3 months ago by dgoulet

Keywords: tor-dos 041-backport 035-backport added
Status: acceptedneeds_review

The obvious issue here is that we need to pass the transport_name to the DoS subsystem because it is needed to query the geoIP cache and needed if we want bridges to be able to use the DoS defenses at the connection level.

We should backport this down to 035 (all our stable) because this bug means bridges are not applying DoS defenses...

Branch: ticket33491_035_01
PR: https://github.com/torproject/tor/pull/1784

comment:11 Changed 2 months ago by asn

Reviewer: teor

comment:12 Changed 2 months ago by teor

Keywords: consider-backport-after-0434 added
Status: needs_reviewmerge_ready
Version: 0.4.2.6Tor: 0.3.3.2-alpha

Merge forward is clean, but I can't see any CI for master, so here it is:

Marking for backport after 0.4.3.4, seems pretty low-risk, and pretty important (but only for bridges with PTs).

If the test master CI passes, let's merge to master.

comment:13 Changed 2 months ago by teor

Milestone: Tor: 0.4.4.x-finalTor: 0.4.3.x-final

CI passed, merged to master, leaving open for backport to 0.3.5 and later.

comment:14 Changed 7 weeks ago by nickm

Dgoulet would like to know if we can take this in 0.4.3.4-rc. I think it would be okay, given the relative simplicity of the issue. Any objection?

comment:15 Changed 7 weeks ago by teor

Yes, that seems fine. The backport tags are only a guideline.

comment:16 Changed 7 weeks ago by teor

Milestone: Tor: 0.4.3.x-finalTor: 0.3.5.x-final
Resolution: fixed
Status: merge_readyclosed

Merged to 0.3.5 and later.

Note: See TracTickets for help on using tickets.