Opened 5 weeks ago

Closed 43 hours ago

#24167 closed defect (fixed)

connection_check_event: Bug: Event missing on connection

Reported by: Felixix Owned by: nickm
Priority: Medium Milestone: Tor: 0.2.5.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-relay mem-limit 031-backport 030-backport 029-backport 028-backport 025-backport
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Hi everybody

The following bug appeared:
connection_check_event: Bug: Event missing on connection

It's before hand a #23751 bug which is re-opened for it.

Tor 0.3.2.3-alpha (git-023d756bfc04c244) running on FreeBSD with Libevent 2.1.8-stable, OpenSSL LibreSSL 2.5.4, Zlib 1.2.8, Liblzma 5.2.2, and Libzstd 1.3.2.

Tor memory is about 5 GB according to:

MaxMemInQueues 5 GB
Nov 06 20:45:27.000 [notice] Heartbeat: Tor's uptime is 9 days 2:59 hours, with 89916 circuits open. I've sent 6246.15 GB and received 6171.99 GB.
Nov 06 20:45:27.000 [notice] Circuit handshake stats since last time: 31997/31997 TAP, 402465/402465 NTor.
Nov 06 20:45:27.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 3 v3 connections, and 297718 v4 connections; and received 2284 v1 connections, 47407 v2 connections, 113778 v3 connections, and 907883 v4 connections.
Nov 06 21:45:27.000 [notice] Heartbeat: Tor's uptime is 9 days 3:59 hours, with 156766 circuits open. I've sent 6284.75 GB and received 6211.71 GB.
Nov 06 21:45:27.000 [notice] Circuit handshake stats since last time: 34286/34286 TAP, 399076/399076 NTor.
Nov 06 21:45:27.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 3 v3 connections, and 298544 v4 connections; and received 2290 v1 connections, 47654 v2 connections, 114327 v3 connections, and 911591 v4 connections.
Nov 06 22:32:42.000 [warn] connection_check_event: Bug: Event missing on connection 0x80f227b00 [OR;open]. socket=-1. linked=0. is_dns_request=0. Marked_for_close=src/or/connection.c:3894 (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug: Backtrace attached.. Stack trace: (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x11a2cd8 <log_backtrace+0x48> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x1071f21 <connection_is_reading+0x1c1> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x1071870 <connection_start_reading+0x30> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x1127408 <connection_bucket_refill+0x9a8> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x1073c8d <handle_signals+0xc2d> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x801b38d3e <event_base_assert_ok_nolock_+0xbce> at /usr/local/lib/libevent-2.1.so.6 (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x801b34cfe <event_base_loop+0x50e> at /usr/local/lib/libevent-2.1.so.6 (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x1072eb5 <do_main_loop+0x575> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x10752a9 <tor_main+0xe9> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x1070d09 <main+0x19> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:32:42.000 [warn] Bug:     0x1070c01 <_start+0x1a1> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 06 22:45:27.000 [notice] Heartbeat: Tor's uptime is 9 days 4:59 hours, with 221777 circuits open. I've sent 6323.37 GB and received 6252.10 GB.
Nov 06 22:45:27.000 [notice] Circuit handshake stats since last time: 97470/97470 TAP, 379601/379601 NTor.
Nov 06 22:45:27.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 3 v3 connections, and 299180 v4 connections; and received 2303 v1 connections, 47866 v2 connections, 114911 v3 connections, and 915142 v4 connections.
Nov 06 23:45:27.000 [notice] Heartbeat: Tor's uptime is 9 days 6:00 hours, with 87446 circuits open. I've sent 6350.85 GB and received 6278.68 GB.
Nov 06 23:45:27.000 [notice] Circuit handshake stats since last time: 21046/21046 TAP, 409042/409042 NTor.
Nov 06 23:45:27.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 3 v3 connections, and 300082 v4 connections; and received 2314 v1 connections, 48042 v2 connections, 115432 v3 connections, and 918682 v4 connections.
Nov 07 00:45:27.000 [notice] Heartbeat: Tor's uptime is 9 days 6:59 hours, with 298896 circuits open. I've sent 6373.37 GB and received 6302.57 GB.
Nov 07 00:45:27.000 [notice] Circuit handshake stats since last time: 206885/206885 TAP, 394540/394540 NTor.
Nov 07 00:45:27.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 3 v3 connections, and 300924 v4 connections; and received 2326 v1 connections, 48242 v2 connections, 115999 v3 connections, and 922124 v4 connections.
Nov 07 01:25:47.000 [warn] connection_check_event: Bug: Event missing on connection 0x80fac4980 [OR;open]. socket=-1. linked=0. is_dns_request=0. Marked_for_close=src/or/connection.c:3894 (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug: Backtrace attached.. Stack trace: (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x11a2cd8 <log_backtrace+0x48> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x1071f21 <connection_is_reading+0x1c1> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x1071870 <connection_start_reading+0x30> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x1127408 <connection_bucket_refill+0x9a8> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x1073c8d <handle_signals+0xc2d> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x801b38d3e <event_base_assert_ok_nolock_+0xbce> at /usr/local/lib/libevent-2.1.so.6 (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x801b34cfe <event_base_loop+0x50e> at /usr/local/lib/libevent-2.1.so.6 (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x1072eb5 <do_main_loop+0x575> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x10752a9 <tor_main+0xe9> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x1070d09 <main+0x19> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:25:47.000 [warn] Bug:     0x1070c01 <_start+0x1a1> at /usr/local/bin/tor (on Tor 0.3.2.3-alpha 023d756bfc04c244)
Nov 07 01:27:51.000 [notice] We're low on memory.  Killing circuits with over-long queues. (This behavior is controlled by MaxMemInQueues.)
Nov 07 01:27:52.000 [notice] Removed 824368 bytes by killing 519528 circuits; 0 circuits remain alive. Also killed 0 non-linked directory connections.
Nov 07 01:27:55.000 [notice] We're low on memory.  Killing circuits with over-long queues. (This behavior is controlled by MaxMemInQueues.)
Nov 07 01:27:55.000 [notice] Removed 528 bytes by killing 163 circuits; 0 circuits remain alive. Also killed 0 non-linked directory connections.
Nov 07 01:27:55.000 [notice] We're low on memory.  Killing circuits with over-long queues. (This behavior is controlled by MaxMemInQueues.)
Nov 07 01:27:55.000 [notice] Removed 528 bytes by killing 170 circuits; 0 circuits remain alive. Also killed 0 non-linked directory connections.
Nov 07 01:27:55.000 [notice] We're low on memory.  Killing circuits with over-long queues. (This behavior is controlled by MaxMemInQueues.)
Nov 07 01:27:55.000 [notice] Removed 528 bytes by killing 455 circuits; 0 circuits remain alive. Also killed 0 non-linked directory connections. 

Cheers !

Child Tickets

Change History (7)

comment:1 Changed 5 weeks ago by dgoulet

Component: - Select a componentCore Tor/Tor
Keywords: tor-relay mem-limit added
Milestone: Tor: 0.3.2.x-final

comment:2 Changed 4 weeks ago by nickm

Owner: set to nickm
Status: newaccepted

comment:3 Changed 4 weeks ago by nickm

Okay. So the fact that the connection was marked for close at src/or/connection.c:3894 means that it was closed via connection_close_immediate, because a buf_flush_to_tls() operation gave us a TLS error.

Then, later, we call connection_start_reading on the connection -- from connection_bucket_refill if the logs can be believed.

I don't think the memlimit issue is actually related.

comment:4 Changed 4 weeks ago by nickm

Keywords: 031-backport 030-backport 029-backport 028-backport 025-backport added
Status: acceptedneeds_review

Fix in branch bug24167_025. This is a bug on every supported Tor version -- fortunately, it's not a crash bug on any of them.

comment:5 Changed 4 weeks ago by ahf

Status: needs_reviewmerge_ready

LGTM.

comment:6 Changed 4 weeks ago by nickm

Milestone: Tor: 0.3.2.x-finalTor: 0.3.1.x-final

Okay. Going to try it out in 0.3.2, and mark for possible backport. Thanks!

comment:7 Changed 43 hours ago by nickm

Milestone: Tor: 0.3.1.x-finalTor: 0.2.5.x-final
Resolution: fixed
Status: merge_readyclosed

Packported to 0.2.5 and forward.

Note: See TracTickets for help on using tickets.