Opened 3 months ago

Last modified 13 days ago

#27750 merge_ready defect

conn_close_if_marked: Non-fatal assertion !(connection_is_writing(conn))

Reported by: dgoulet Owned by: dgoulet
Priority: Very High Milestone: Tor: 0.3.4.x-final
Component: Core Tor/Tor Version: Tor: 0.3.4.8
Severity: Normal Keywords: regression, 034-backport, 035-must, 035-rc-blocker?
Cc: Actual Points:
Parent ID: Points:
Reviewer: nickm Sponsor:

Description

From tor-talk:

https://lists.torproject.org/pipermail/tor-talk/2018-September/044448.html

Sep 15 16:06:26.000 [warn] tor_bug_occurred_(): Bug: src/or/main.c:1044: conn_close_if_marked: Non-fatal assertion !(connection_is_writing(conn)) failed. (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug: Non-fatal assertion !(connection_is_writing(conn)) failed in conn_close_if_marked at src/or/main.c:1044. Stack trace: (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(log_backtrace+0x47) [0x55727ae152e7] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xbd) [0x55727ae307ad] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(+0x51b18) [0x55727acdbb18] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7fb01de555b1] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug: /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7fb01de55d47] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0x209) [0x55727acde149] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x1015) [0x55727ace0835] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3e) [0x55727acd868e] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(main+0x1d) [0x55727acd841d] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug: /lib64/libc.so.6(__libc_start_main+0xeb) [0x7fb01c3d611b] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 15 16:06:26.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x55727acd847a] (on Tor 0.3.4.8 da95b91355248ad8)

Child Tickets

Change History (43)

comment:1 Changed 3 months ago by udo

The same box experienced an out of memory (4GB!) event (or two) and tor got killed, and restarted.
Nothing much else is running there which is quiet stable.

comment:2 Changed 3 months ago by udo

MaxMemInQueues 1024 MB

So OoM is unexpected.

comment:3 Changed 3 months ago by udo

In fact OoM events happen multiple times per day.
They did not before this.
Is this due to some open ports?
Or solely because of this version?

comment:4 Changed 3 months ago by udo

I closed all open ports to see if that 'fixes' the issue (makes it not appear anymore).
I.e.: relay-only for now.

comment:5 Changed 3 months ago by udo

So far tor appears to be more stable. No OoM and no assertion events.

comment:6 Changed 3 months ago by udo

With just port 22 and 53 open the issue does not happen. (yet)

comment:7 Changed 2 months ago by udo

Even with just port 22 and 53 open I do get OoM events.
Please provide a fix soon!

comment:8 Changed 2 months ago by traumschule

If the reason is not found before, can you please try if this also happens with the 0.3.3.x series and 0.3.4.7. Is it reproducible with other ports?

comment:9 Changed 2 months ago by nickm

Keywords: 035-must added

Add the 035-must tag to some assertion failures, hangs, ci-blockers, etc.

comment:10 Changed 2 months ago by nickm

Priority: MediumVery High

Mark all 035-must tickets as "very high"

comment:11 Changed 2 months ago by nickm

It would be very very helpful to know what's the first version that shows this issue.

comment:12 Changed 2 months ago by dgoulet

Owner: set to dgoulet
Status: newaccepted

comment:13 Changed 2 months ago by nickm

note: dgoulet and I are going to try to have a look here.

comment:14 Changed 2 months ago by nickm

I think this could be related to the token bucket changes in #25373.

comment:15 Changed 8 weeks ago by nickm

Status: acceptedneeds_information

This may be fixed by the fix of #28089; let's see whether it recurs in 0.3.5.3-alpha or later. (Or in 0.3.4.9 or later.)

comment:16 Changed 8 weeks ago by udo

tor-0.3.3.9-0.fc28.x86_64 does NOT have this issue.

While trying to build an rpm for 0.3.5.3.-alpha I try:
Version: 0.3.5.3-%{alphatag}
but:
# rpmbuild -bb SPECS/tor.spec
error: line 23: Illegal char '-' (0x2d) in: Version: 0.3.5.3-alpha

I.e.: one cannot have a dash ('-') there when building rpm.
but I do need to tell rpm the exact version string as it also expects this version in the directory tree in the source tar file.

comment:17 Changed 8 weeks ago by udo

After 0.3.3.9 I went to 0.3.4.8 which has the issue.

comment:18 Changed 8 weeks ago by udo

Now running 0.3.5.3-alpha.
We will need a few days to be fairly sure.

comment:19 Changed 8 weeks ago by udo

We still see some bug:

Oct 20 04:05:03.000 [notice] New control connection opened from 127.0.0.1.
Oct 20 04:10:03.000 [notice] New control connection opened from 127.0.0.1.
Oct 20 04:12:32.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x561eb63d4636] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x561eb63cfd30] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x561eb624dd25] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7ff1c8dcf5b1] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff1c8dcfd47] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x561eb624f780] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x561eb623d56f] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x561eb623a7da] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x561eb623a399] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xeb) [0x7ff1c734d11b] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:32.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x561eb623a3ea] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x561eb63d4636] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x561eb63cfd30] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x561eb624dd25] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7ff1c8dcf5b1] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff1c8dcfd47] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x561eb624f780] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x561eb623d56f] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x561eb623a7da] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x561eb623a399] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xeb) [0x7ff1c734d11b] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:40.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x561eb623a3ea] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x561eb63d4636] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x561eb63cfd30] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x561eb624dd25] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7ff1c8dcf5b1] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff1c8dcfd47] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x561eb624f780] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x561eb623d56f] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x561eb623a7da] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x561eb623a399] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xeb) [0x7ff1c734d11b] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:47.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x561eb623a3ea] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x561eb63d4636] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x561eb63cfd30] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x561eb624dd25] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7ff1c8dcf5b1] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff1c8dcfd47] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x561eb624f780] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x561eb623d56f] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x561eb623a7da] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x561eb623a399] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xeb) [0x7ff1c734d11b] (on Tor 0.3.5.3-alpha )
Oct 20 04:12:55.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x561eb623a3ea] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x561eb63d4636] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x561eb63cfd30] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x561eb624dd25] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7ff1c8dcf5b1] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff1c8dcfd47] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x561eb624f780] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x561eb623d56f] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x561eb623a7da] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x561eb623a399] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xeb) [0x7ff1c734d11b] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:13.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x561eb623a3ea] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x561eb63d4636] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x561eb63cfd30] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x561eb624dd25] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7ff1c8dcf5b1] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff1c8dcfd47] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x561eb624f780] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x561eb623d56f] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x561eb623a7da] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x561eb623a399] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xeb) [0x7ff1c734d11b] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x561eb623a3ea] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x561eb63d4636] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x561eb63cfd30] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x561eb624dd25] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x235b1) [0x7ff1c8dcf5b1] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff1c8dcfd47] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x561eb624f780] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x561eb623d56f] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x561eb623a7da] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x561eb623a399] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xeb) [0x7ff1c734d11b] (on Tor 0.3.5.3-alpha )
Oct 20 04:13:14.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x561eb623a3ea] (on Tor 0.3.5.3-alpha )
Oct 20 04:15:03.000 [notice] New control connection opened from 127.0.0.1.
Oct 20 04:20:03.000 [notice] New control connection opened from 127.0.0.1.
Oct 20 04:25:03.000 [notice] New control connection opened from 127.0.0.1.

(...)

Oct 20 04:58:54.000 [notice] Heartbeat: Tor's uptime is 18:00 hours, with 595 circuits open. I've sent 16.60 GB and received 16.56 GB.
Oct 20 04:58:54.000 [notice] Heartbeat: Accounting enabled. Sent: 15.51 GB, Received: 15.47 GB, Used: 15.52 GB / 99.00 GB, Rule: max. The current accounting interval ends on 2018-10-20 12:21:00, in 7:22 hours.
Oct 20 04:58:54.000 [notice] Circuit handshake stats since last time: 1138/1138 TAP, 21372/21372 NTor.
Oct 20 04:58:54.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 0 v3 connections, and 4988 v4 connections; and received 0 v1 connections, 298 v2 connections, 560 v3 connections, and 6409 v4 connections.
Oct 20 04:58:54.000 [notice] DoS mitigation since startup: 0 circuits killed with too many cells. 0 circuits rejected, 0 marked addresses. 0 connections closed. 224 single hop clients refused.

So what does this tell us?
Were we dealing with two issues? With one fixed now?

comment:20 in reply to:  19 Changed 7 weeks ago by arma

Replying to udo:

So what does this tell us?
Were we dealing with two issues? With one fixed now?

That does sound like a plausible summary of where we are.

Udo: how quickly does your relay experience this bug, after startup?

And, do you have any weird torrc options set?

Can you remove as many torrc options as possible, while still experiencing the bug? If so, can you tell us what minimal set of torrc options still trigger it?

comment:21 Changed 7 weeks ago by udo

After ~18 hours per the logs I posted.
What are 'weird' torrc options?
It is a mostly non-exit node with obfs4 proxy.
Only two open ports.
List of ExitPolicy reject from tornull.org.
ExcludeNodes and ExcludeExitNodes from same source.
But are these efecting the issue we see here?

comment:22 Changed 7 weeks ago by udo

FWIW: I restarted tor with ExitPolicy reject removed from torrc.

comment:23 Changed 7 weeks ago by udo

What remains of the configuration torrc:

SocksPort 127.0.0.1:9050 # Default: Bind to localhost:9050 for local connections.

Log notice file /var/log/tor/notices.log
RunAsDaemon 1
DataDirectory /var/lib/tor
ControlPort 9051
HashedControlPassword zz:xxx

Address x
Nickname x
ContactInfo Random Person <jobseek2001@yahoo.com>

ORPort 9001
DirPort 9030 # what port to advertise for directory connections

GeoIPExcludeUnknown 1
ExcludeNodes default,Unnamed,{ae},{af},{ag},{ao},{az},{ba},{bb},{bd},{bh},{bi},{bn},{bt},{bw},{by},{cd},{cf},{cg},{ci},{ck},{cm},{cn},{cu},{cy},{dj},{dm},{dz},{eg},{er},{et},{fj},{ga},{gd},{gh},{gm},{gn},{gq},{gy},{hr},{ht},{id},{in},{iq},{ir},{jm},{jo},{ke},{kg},{kh},{ki},{km},{kn},{kp},{kw},{kz},{la},{lb},{lc},{lk},{lr},{ly},{ma},{me},{mk},{ml},{mm},{mr},{mu},{mv},{mw},{my},{na},{ng},{om},{pg},{ph},{pk},{ps},{qa},{rs},{ru},{rw},{sa},{sb},{sd},{sg},{si},{sl},{sn},{so},{st},{sy},{sz},{td},{tg},{th},{tj},{tm},{tn},{to},{tr},{tt},{tv},{tz},{ug},{uz},{vc},{ve},{vn},{ws},{ye},{zm},{zw},{??}
ExcludeExitNodes default,Unnamed,{ae},{af},{ag},{ao},{az},{ba},{bb},{bd},{bh},{bi},{bn},{bt},{bw},{by},{cd},{cf},{cg},{ci},{ck},{cm},{cn},{cu},{cy},{dj},{dm},{dz},{eg},{er},{et},{fj},{ga},{gd},{gh},{gm},{gn},{gq},{gy},{hr},{ht},{id},{in},{iq},{ir},{jm},{jo},{ke},{kg},{kh},{ki},{km},{kn},{kp},{kw},{kz},{la},{lb},{lc},{lk},{lr},{ly},{ma},{me},{mk},{ml},{mm},{mr},{mu},{mv},{mw},{my},{na},{ng},{om},{pg},{ph},{pk},{ps},{qa},{rs},{ru},{rw},{sa},{sb},{sd},{sg},{si},{sl},{sn},{so},{st},{sy},{sz},{td},{tg},{th},{tj},{tm},{tn},{to},{tr},{tt},{tv},{tz},{ug},{uz},{vc},{ve},{vn},{ws},{ye},{zm},{zw},{??}

LongLivedPorts 21,22,80,110,143,443,706,993,1863,5050,5190,5222,5223,6523,6667,6697,8080,8300,8443,9001,9030

ExitPolicy accept *:22     # SSH
ExitPolicy accept *:53        # DNS

ExitPolicy reject *:* # middleman only -- no exits allowed

ExitRelay 1
MaxMemInQueues 1024 MB

BandwidthRate 1024 KB
BandwidthBurst 1536 KB
MaxAdvertisedBandwidth 999 KB

AccountingStart day 12:21
AccountingMax 99 GB

DisableAllSwap 1

User _tor

ServerDNSResolvConfFile /etc/tor/resolv.conf

ServerTransportPlugin obfs4 exec /usr/local/bin/obfs4proxy managed
ServerTransportListenAddr obfs4 x:y
ExtORPort auto

Strictnodes 1

PidFile /run/tor/tor.pid

Any weird things remaining?

comment:24 Changed 7 weeks ago by udo

Oct 22 13:44:12.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 22 13:44:12.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )

So it happened again.

comment:25 Changed 7 weeks ago by arma

Status: needs_informationnew

A very similar line happened on moria1 as well (running recent master):

Oct 23 12:00:16.220 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(log_backtrace_impl+0x47) [0x55beac520f37] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(tor_bug_occurred_+0xd1) [0x55beac51c4c1] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(+0x6a645) [0x55beac392645] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(+0x6a72e) [0x55beac39272e] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(+0x216622) [0x55beac53e622] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(+0x216b25) [0x55beac53eb25] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(event_base_loop+0x2c8) [0x55beac53f289] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(do_main_loop+0x84) [0x55beac3909f4] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(tor_run_main+0x4d6) [0x55beac3816c6] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(tor_main+0x43) [0x55beac37e4c3] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(main+0x19) [0x55beac37e149] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f1712c16d1d] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:16.220 [warn] Bug:     ../git/src/app/tor(+0x56059) [0x55beac37e059] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.220 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(log_backtrace_impl+0x47) [0x55beac520f37] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(tor_bug_occurred_+0xd1) [0x55beac51c4c1] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(+0x6a645) [0x55beac392645] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(+0x6a72e) [0x55beac39272e] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(+0x216622) [0x55beac53e622] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(+0x216b25) [0x55beac53eb25] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(event_base_loop+0x2c8) [0x55beac53f289] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(do_main_loop+0x84) [0x55beac3909f4] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(tor_run_main+0x4d6) [0x55beac3816c6] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(tor_main+0x43) [0x55beac37e4c3] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(main+0x19) [0x55beac37e149] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f1712c16d1d] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:19.221 [warn] Bug:     ../git/src/app/tor(+0x56059) [0x55beac37e059] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.214 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.214 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.214 [warn] Bug:     ../git/src/app/tor(log_backtrace_impl+0x47) [0x55beac520f37] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.214 [warn] Bug:     ../git/src/app/tor(tor_bug_occurred_+0xd1) [0x55beac51c4c1] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.214 [warn] Bug:     ../git/src/app/tor(+0x6a645) [0x55beac392645] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.214 [warn] Bug:     ../git/src/app/tor(+0x6a72e) [0x55beac39272e] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.214 [warn] Bug:     ../git/src/app/tor(+0x216622) [0x55beac53e622] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(+0x216b25) [0x55beac53eb25] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(event_base_loop+0x2c8) [0x55beac53f289] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(do_main_loop+0x84) [0x55beac3909f4] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(tor_run_main+0x4d6) [0x55beac3816c6] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(tor_main+0x43) [0x55beac37e4c3] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(main+0x19) [0x55beac37e149] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f1712c16d1d] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(+0x56059) [0x55beac37e059] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(log_backtrace_impl+0x47) [0x55beac520f37] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(tor_bug_occurred_+0xd1) [0x55beac51c4c1] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(+0x6a645) [0x55beac392645] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(+0x6a72e) [0x55beac39272e] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(+0x216622) [0x55beac53e622] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(+0x216b25) [0x55beac53eb25] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(event_base_loop+0x2c8) [0x55beac53f289] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(do_main_loop+0x84) [0x55beac3909f4] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(tor_run_main+0x4d6) [0x55beac3816c6] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(tor_main+0x43) [0x55beac37e4c3] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(main+0x19) [0x55beac37e149] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f1712c16d1d] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:23.215 [warn] Bug:     ../git/src/app/tor(+0x56059) [0x55beac37e059] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(log_backtrace_impl+0x47) [0x55beac520f37] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(tor_bug_occurred_+0xd1) [0x55beac51c4c1] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(+0x6a645) [0x55beac392645] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(+0x6a72e) [0x55beac39272e] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(+0x216622) [0x55beac53e622] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(+0x216b25) [0x55beac53eb25] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(event_base_loop+0x2c8) [0x55beac53f289] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(do_main_loop+0x84) [0x55beac3909f4] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(tor_run_main+0x4d6) [0x55beac3816c6] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.221 [warn] Bug:     ../git/src/app/tor(tor_main+0x43) [0x55beac37e4c3] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(main+0x19) [0x55beac37e149] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f1712c16d1d] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(+0x56059) [0x55beac37e059] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(log_backtrace_impl+0x47) [0x55beac520f37] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(tor_bug_occurred_+0xd1) [0x55beac51c4c1] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(+0x6a645) [0x55beac392645] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(+0x6a72e) [0x55beac39272e] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(+0x216622) [0x55beac53e622] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(+0x216b25) [0x55beac53eb25] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(event_base_loop+0x2c8) [0x55beac53f289] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(do_main_loop+0x84) [0x55beac3909f4] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(tor_run_main+0x4d6) [0x55beac3816c6] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(tor_main+0x43) [0x55beac37e4c3] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(main+0x19) [0x55beac37e149] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f1712c16d1d] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)
Oct 23 12:00:27.222 [warn] Bug:     ../git/src/app/tor(+0x56059) [0x55beac37e059] (on Tor 0.3.6.0-alpha-dev 275e831ceac6382a)

(isn't it supposed to stop the detailed stack traces after the first one?)

In fact, I seem to be getting a flood of these stack traces at the top of each hour (right after I make available my new consensus).

comment:26 Changed 7 weeks ago by arma

My hint is that before each flood of backtraces, I have lines like

Oct 22 11:00:08.822 [info] run_connection_housekeeping(): Expiring non-used OR connection to fd 6685 (37.187.124.72:443) [Too old].
Oct 22 11:00:08.822 [info] run_connection_housekeeping(): Expiring non-used OR connection to fd 6508 (220.216.101.171:9001) [Too old].
Oct 22 11:00:08.823 [info] run_connection_housekeeping(): Expiring non-used OR connection to fd 6584 (51.254.84.5:9001) [Too old].

(not always relays, but these ones were relays so I figured I'd pick them for pasting)

comment:27 Changed 7 weeks ago by dgoulet

Fun ... this assert switched from connection_is_writing() to is_reading()....

comment:28 Changed 7 weeks ago by udo

I do not see the lines from comment 26.

comment:29 Changed 6 weeks ago by udo

There look only slightly different:

Oct 25 09:07:37.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:07:37.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:21.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:08:38.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:58.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:09:59.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:28.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:36.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:40.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:44.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:10:52.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:06.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] tor_bug_occurred_(): Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(log_backtrace_impl+0x46) [0x564696486636] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc0) [0x564696481d30] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(+0x68d25) [0x5646962ffd25] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /lib64/libevent-2.1.so.6(+0x24031) [0x7ff7cc050031] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /lib64/libevent-2.1.so.6(event_base_loop+0x537) [0x7ff7cc0507c7] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0xb0) [0x564696301780] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x147f) [0x5646962ef56f] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x5646962ec7da] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x5646962ec399] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xf3) [0x7ff7cb93e413] (on Tor 0.3.5.3-alpha )
Oct 25 09:11:11.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x5646962ec3ea] (on Tor 0.3.5.3-alpha )
Oct 25 09:55:04.000 [notice] Heartbeat: Tor's uptime is 4 days 0:00 hours, with 734 circuits open. I've sent 101.36 GB and received 101.15 GB.

comment:30 Changed 6 weeks ago by udo

Can I try a patch?

comment:31 Changed 5 weeks ago by Felixix

conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed.

As a singular event:

Nov 08 15:14:26.000 [warn] tor_bug_occurred_: Bug: src/core/mainloop/mainloop.c:1022: conn_close_if_marked: Non-fatal assertion !(connection_is_reading(conn)) failed. (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug: Non-fatal assertion !(connection_is_reading(conn)) failed in conn_close_if_marked at src/core/mainloop/mainloop.c:1022. Stack trace: (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x121aadc <log_backtrace_impl+0x4c> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x1216f01 <tor_bug_occurred_+0x111> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x1090840 <tor_mainloop_free_all+0x540> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x109000e <initialize_mainloop_events+0x3de> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x801b63d22 <event_base_assert_ok_nolock_+0xa92> at /usr/local/lib/libevent-2.1.so.6 (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x801b5fe6f <event_base_loop+0x51f> at /usr/local/lib/libevent-2.1.so.6 (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x1090171 <do_main_loop+0x141> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x107e6ef <tor_run_main+0x70f> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x107c906 <tor_main+0x66> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x107c5b9 <main+0x19> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )
Nov 08 15:14:26.000 [warn] Bug:     0x107c3c5 <_start+0xa5> at /usr/local/bin/tor (on Tor 0.3.5.3-alpha )

Started here:

Oct 28 02:11:06.109 [notice] Tor 0.3.5.3-alpha running on FreeBSD with Libevent 2.1.8-stable, OpenSSL LibreSSL 2.7.4, Zlib 1.2.11, Liblzma 5.2.3, and Libzstd 1.3.5.

comment:32 Changed 5 weeks ago by ln5

Here's my 2c. Exit relay on HardenedBSD 11.2-STABLE. First sighting was

Oct 15 07:00:08.000 [warn] Bug: Non-fatal assertion !(connection_is_writing(conn)) failed in conn_close_if_marked at src/or/main.c:1044. Stack trace: (on Tor 0.3.4.8 da95b91355248ad8)

(All times in CET/CEST.)

Here's the upgrade history for tor on that system:

Apr 21 14:32:45.128 [notice] Tor 0.3.2.10 (git-31cc63deb69db819) running on FreeBSD with Libevent 2.1.8-stable, OpenSSL LibreSSL 2.6.4, Zlib 1.2.11, Liblzma 5.2.3, and Libzstd 1.3.4.
Aug 29 13:26:16.059 [notice] Tor 0.3.3.9 (git-45028085ea188baf) running on FreeBSD with Libevent 2.1.8-stable, OpenSSL 1.0.2p-freebsd, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.5.
Oct 13 23:42:30.079 [notice] Tor 0.3.4.8 (git-da95b91355248ad8) running on FreeBSD with Libevent 2.1.8-stable, OpenSSL 1.0.2p-freebsd, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.5.
Nov 09 15:53:40.234 [notice] Tor 0.3.5.3-alpha running on FreeBSD with Libevent 2.1.8-stable, OpenSSL 1.0.2p-freebsd, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.7.

We'll see if it keeps appearing in 0.3.5.

comment:33 Changed 4 weeks ago by ln5

Still see it on 0.3.5.3-alpha.

comment:34 Changed 4 weeks ago by nickm

Keywords: 035-rc-blocker? added

comment:35 Changed 4 weeks ago by dgoulet

Ok, here is my analysis (we are in mainloop.c, function conn_close_if_marked():

The idea of the function is to do some actions for a connection that is marked "for close". Tor must flush everything on the wire for a connection that is about to get closed thus it looks at the *write* bucket and see if it can:

ssize_t sz = connection_bucket_write_limit(conn, now);

Then it tries to flush regardless of the value in sz which if sz = 0 then retval will be 0 as well. Which brings us to where the BUG() happens in the condition:

      } else if (sz == 0) {
        /* Also, retval==0.  If we get here, we didn't want to write anything
         * (because of rate-limiting) and we didn't. */

The whole point of this condition iiuc is to keep the connection "alive" because it is being rate limited but still has data to flush (we check connection_wants_to_flush()).

I believe #28089 fixed this for the is_writing() case and now we are only seeing the is_reading() case on tor >= 0.3.4.8.

connection_consider_empty_read_buckets(conn); can most of the time *not* stop the connection from reading because simply the bucket aren't empty for the read() part of the connection. Which means that we will hit the BUG() probably often when the connection can't write anymore. From the code:

        if (BUG(connection_is_reading(conn))) {
          /* XXXX+ We should make this code unreachable; if a connection is
           * marked for close and flushing, there is no point in reading to it
           * at all. Further, checking at this point is a bit of a hack: it
           * would make much more sense to react in
           * connection_handle_read_impl, or to just stop reading in
           * mark_and_flush */
          connection_read_bw_exhausted(conn, true/* kludge. */);
        }

I agree with the comment. We shouldn't even BUG() there in the first place, actually, it makes no sense to call the bw exhausted. We should simply stop reading() because the connection is marked for close and move on regardless of the read state.

Again, this condition is only relevant if we _need_ to flush data on the wire but we are prevented to do so because of rate limit.

comment:36 Changed 4 weeks ago by udo

FWIW:
Upgraded to 0.3.5.4-alpha recently but had to change the open ports after local ISP complained about ssh brute force.
With these changed ports after three full days no manifestation of tor_bug_occurred_() occurred yet.

comment:37 Changed 4 weeks ago by dgoulet

Keywords: 034-backport added; assert removed
Reviewer: nickm
Status: newneeds_review

Proposed fix on 034:

Branch: ticket27750_034_01
PR: https://github.com/torproject/tor/pull/500

comment:38 Changed 4 weeks ago by teor

We should test this in chutney, but chutney is unreliable on 0.3.4 and later due to #28192.

comment:39 Changed 4 weeks ago by nickm

Milestone: Tor: 0.3.5.x-finalTor: 0.3.4.x-final
Status: needs_reviewmerge_ready

Looks plausible to me. Squashed as https://github.com/torproject/tor/pull/507 ; merged to maint-0.3.5. Marking for 0.3.5 backport if nothing goes wrong.

comment:40 Changed 3 weeks ago by udo

FWIW: I upgraded to 0.3.5.5-alpha, so far no issues.
Will there be a 0.3.4.x release with this fix?

comment:41 Changed 3 weeks ago by nickm

Yes, assuming nothing in 035 breaks in a subtle way with this fix.

comment:42 Changed 3 weeks ago by udo

Well, this issue appears to be fixed.

comment:43 Changed 13 days ago by teor

Another user is reporting this bug in 0.3.4, we should backport:
https://lists.torproject.org/pipermail/tor-relays/2018-November/016676.html

Note: See TracTickets for help on using tickets.