Opened 15 months ago

Last modified 11 months ago

#25976 new defect

connection_dir_finished_flushing(): Bug: called in unexpected state 3

Reported by: dgoulet Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: regression, 034-removed-must-2018-09-05
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

This from tor version git-302908657f492f06 on one of my test relay. It was immediately followed by another BUG() below. Note that relay is still running and seems well.

Torrc has nothing special except:

BandwidthRate 400 KBytes

Stacktrace:

Apr 29 13:30:59.691 [warn] connection_dir_finished_flushing(): Bug: called in unexpected state 3. (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.691 [warn] tor_bug_occurred_(): Bug: src/or/directory.c:5248: connection_dir_finished_flushing: This line should not have been reached. (Future instances of this warning will be silenced.) (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug: Line unexpectedly reached at connection_dir_finished_flushing at src/or/directory.c:5248. Stack trace: (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(log_backtrace+0x42) [0x55811a451722] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(tor_bug_occurred_+0xb9) [0x55811a46c559] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(connection_dir_finished_flushing+0x12e) [0x55811a3fc6ee] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(+0x108fcd) [0x55811a3d5fcd] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(connection_handle_write+0x2e) [0x55811a3d67ae] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(+0x534be) [0x55811a3204be] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5(event_base_loop+0x819) [0x7f0f91d364c9] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(do_main_loop+0x1a5) [0x55811a3217d5] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(tor_run_main+0x275) [0x55811a322ed5] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(tor_main+0x3a) [0x55811a31c40a] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(main+0x19) [0x55811a31c179] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0) [0x7f0f90a48830] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(_start+0x29) [0x55811a31c1c9] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] conn_write_callback(): Bug: unhandled error on write for Directory connection (fd 1588); removing (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] tor_bug_occurred_(): Bug: src/or/main.c:935: conn_write_callback: This line should not have been reached. (Future instances of this warning will be silenced.) (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug: Line unexpectedly reached at conn_write_callback at src/or/main.c:935. Stack trace: (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(log_backtrace+0x42) [0x55811a451722] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(tor_bug_occurred_+0xb9) [0x55811a46c559] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(+0x53692) [0x55811a320692] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5(event_base_loop+0x819) [0x7f0f91d364c9] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(do_main_loop+0x1a5) [0x55811a3217d5] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(tor_run_main+0x275) [0x55811a322ed5] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(tor_main+0x3a) [0x55811a31c40a] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(main+0x19) [0x55811a31c179] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0) [0x7f0f90a48830] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)
Apr 29 13:30:59.731 [warn] Bug:     /home/relay/tor/src/or/tor(_start+0x29) [0x55811a31c1c9] (on Tor 0.3.4.0-alpha-dev 302908657f492f06)

Child Tickets

Change History (5)

comment:1 Changed 15 months ago by nickm

Huh. So the complaint is:

Apr 29 13:30:59.691 [warn] connection_dir_finished_flushing(): Bug: called in unexpected state 3. (on Tor 0.3.4.0-alpha-dev 302908657f492f06)

And state 3 is:

/** State for connection to directory server: reading HTTP response. */
#define DIR_CONN_STATE_CLIENT_READING 3

comment:2 Changed 13 months ago by dgoulet

So when a client directory connection ends sending it goes back in DIR_CONN_STATE_CLIENT_READING. This is the only transition I could find.

Meaning, once we are done flushing data on the wire, we go back in READING mode. Thus, one theory is that something in tor wrote things on that connection outbuf after it was done sending whatever it had...?

comment:3 Changed 13 months ago by dgoulet

Milestone: Tor: 0.3.4.x-finalTor: unspecified

Without a way to reproduce, this is very difficult to track down in the code... Moving out of 034 for now and lets see if it comes back on more stable production relays.

comment:4 Changed 13 months ago by arma

Hit this on moria1 too.

Jun 22 11:00:10.976 [warn] connection_dir_finished_flushing(): Bug: called in unexpected state 3. (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:10.977 [warn] tor_bug_occurred_(): Bug: src/or/directory.c:5238: connection_dir_finished_flushing: 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 22 11:00:11.008 [warn] Bug: Line unexpectedly reached at connection_dir_finished_flushing at src/or/directory.c:5238. Stack trace: (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(log_backtrace+0x42) [0x560ad42dd842] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(tor_bug_occurred_+0xca) [0x560ad42f853a] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(connection_dir_finished_flushing+0x195) [0x560ad428c9b5] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(connection_handle_write+0x68e) [0x560ad4267cde] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(+0x5244e) [0x560ad41a744e] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     /usr/lib64/libevent-2.0.so.5(event_base_loop+0x53c) [0x7fd0165b5f8c] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(do_main_loop+0x47c) [0x560ad41a87ec] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(tor_run_main+0x28c) [0x560ad41a8c1c] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(tor_main+0x43) [0x560ad41a08d3] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(main+0x19) [0x560ad41a0769] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7fd0157d1d1d] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(+0x4b679) [0x560ad41a0679] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] conn_write_callback(): Bug: unhandled error on write for Directory connection (fd 1112); removing (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] tor_bug_occurred_(): Bug: src/or/main.c:943: conn_write_callback: 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 22 11:00:11.008 [warn] Bug: Line unexpectedly reached at conn_write_callback at src/or/main.c:943. Stack trace: (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(log_backtrace+0x42) [0x560ad42dd842] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(tor_bug_occurred_+0xca) [0x560ad42f853a] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(+0x525d2) [0x560ad41a75d2] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     /usr/lib64/libevent-2.0.so.5(event_base_loop+0x53c) [0x7fd0165b5f8c] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.008 [warn] Bug:     ../git/src/or/tor(do_main_loop+0x47c) [0x560ad41a87ec] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.009 [warn] Bug:     ../git/src/or/tor(tor_run_main+0x28c) [0x560ad41a8c1c] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.009 [warn] Bug:     ../git/src/or/tor(tor_main+0x43) [0x560ad41a08d3] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.009 [warn] Bug:     ../git/src/or/tor(main+0x19) [0x560ad41a0769] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.009 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7fd0157d1d1d] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.009 [warn] Bug:     ../git/src/or/tor(+0x4b679) [0x560ad41a0679] (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.079 [warn] connection_dir_finished_flushing(): Bug: called in unexpected state 3. (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 22 11:00:11.079 [warn] conn_write_callback(): Bug: unhandled error on write for Directory connection (fd 6260); removing (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 24 16:00:14.963 [warn] connection_dir_finished_flushing(): Bug: called in unexpected state 3. (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 24 16:00:14.963 [warn] conn_write_callback(): Bug: unhandled error on write for Directory connection (fd 2386); removing (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 24 16:00:14.963 [info] connection_dir_request_failed(): Giving up on downloading microdescriptors from directory server at '199.58.81.140'; will retry

Jun 24 16:00:15.267 [warn] connection_dir_finished_flushing(): Bug: called in unexpected state 3. (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 24 16:00:15.267 [warn] conn_write_callback(): Bug: unhandled error on write for Directory connection (fd 1999); removing (on Tor 0.3.5.0-alpha-dev e4e949e901400c85)
Jun 24 16:00:15.267 [info] connection_dir_request_failed(): Giving up on serverdesc/extrainfo fetch from directory server at '171.25.193.9'; retrying

comment:5 Changed 11 months ago by teor

Keywords: 034-removed-must-2018-09-05 added; 034-must removed

These tickets were removed from 0.3.4, so they can't be 034-must.

Note: See TracTickets for help on using tickets.