Opened 3 months ago

Last modified 2 months ago

#26434 new defect

Bug: Emptied a dirserv buffer, but it's still spooling!

Reported by: arma Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: 035-removed-20180711
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

On moria1, running valgrind so things are slower than usual, I got these two Bug: lines (client IP address replaced with "[ip]"):

Jun 20 18:11:24.982 [info] connection_handle_write_impl(): tls error ([ip]:65063). breaking.
Jun 20 18:11:24.982 [info] connection_or_notify_error(): called for [ip]:65063
Jun 20 18:11:24.982 [info] connection_close_immediate(): fd 571, type OR, state open, 1024 bytes on outbuf.
Jun 20 18:11:25.000 [warn] connection_dir_finished_flushing(): Bug: Emptied a dirserv buffer, but it's still spooling! (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 18:11:25.000 [warn] connection_mark_for_close_internal_(): Bug: Duplicate call to connection_mark_for_close at src/or/directory.c:5229 (first at src/or/main.c:1218) (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 18:11:25.000 [info] connection_edge_reached_eof(): conn (fd -1) reached eof. Closing.
Jun 20 18:11:25.001 [info] connection_free_minimal(): Freeing linked Exit connection [open] with 0 bytes on inbuf, 0 on outbuf.

I'm putting this in the 0.3.5 milestone since that's the version I was running, but I bet it's a bug in earlier releases too.

Child Tickets

TicketStatusOwnerSummaryComponent
#27759closed3 Bugs in Tor relay logsCore Tor/Tor

Change History (3)

comment:1 Changed 3 months ago by arma

Ah ha. This happens once an hour or so. Here is the first time, with more detail:

Jun 20 15:14:05.948 [warn] connection_mark_for_close_internal_(): Bug: Duplicate call to connection_mark_for_close at src/or/directory.c:5232 (first at src/or/main.c:1218) (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.948 [warn] tor_bug_occurred_(): Bug: src/or/connection.c:871: connection_mark_for_close_internal_: This line should not have been reached. (Future instances of this warning will be silenced.) (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.951 [warn] Bug: Line unexpectedly reached at connection_mark_for_close_internal_ at src/or/connection.c:871. Stack trace: (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.951 [warn] Bug:     ../git/src/or/tor(log_backtrace+0x42) [0x2907f2] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.951 [warn] Bug:     ../git/src/or/tor(tor_bug_occurred_+0xca) [0x2ab4ea] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.951 [warn] Bug:     ../git/src/or/tor(connection_dir_finished_flushing+0x164) [0x23f934] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     ../git/src/or/tor(connection_handle_read+0x8b1) [0x21a301] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     ../git/src/or/tor(+0x52631) [0x15a631] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     /usr/lib64/libevent-2.0.so.5(event_base_loop+0x53c) [0x50c6f8c] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     ../git/src/or/tor(do_main_loop+0x47c) [0x15b7ec] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     ../git/src/or/tor(tor_run_main+0x28c) [0x15bc1c] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     ../git/src/or/tor(tor_main+0x43) [0x1538d3] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     ../git/src/or/tor(main+0x19) [0x153769] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x5d78d1d] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 20 15:14:05.952 [warn] Bug:     ../git/src/or/tor(+0x4b679) [0x153679] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)

comment:2 Changed 3 months ago by toralf

Happened here at a stable hardened Gentoo Linux server too (for the first time):

Jun 29 08:02:13.000 [warn] connection_dir_finished_flushing(): Bug: Emptied a dirserv buffer, but it's still spooling! (on Tor 0.3.4.2-alpha bc951e83aac770d1)

And happened now again, and similar to the one above 2 minutes past a full hour:

Jul 01 19:02:49.000 [warn] connection_dir_finished_flushing(): Bug: Emptied a dirserv buffer, but it's still spooling! (on Tor 0.3.4.2-alpha bc951e83aac770d1)
Last edited 3 months ago by toralf (previous) (diff)

comment:3 Changed 2 months ago by nickm

Keywords: 035-removed-20180711 added
Milestone: Tor: 0.3.5.x-finalTor: unspecified

These tickets are being triaged out of 0.3.5. The ones marked "035-roadmap-proposed" may return.

Note: See TracTickets for help on using tickets.