Opened 4 months ago

Closed 3 weeks ago

#26896 closed defect (fixed)

Duplicate call to connection_mark_for_close

Reported by: toralf Owned by: nickm
Priority: Medium Milestone: Tor: 0.3.4.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: regression 034-backport
Cc: Actual Points:
Parent ID: Points:
Reviewer: dgoulet Sponsor:

Description

catched that warning (for the 1st time IIRC) at a hardened stable Gentoo Linux exit relay with LibreSSL 2.6.5:

Jul 21 08:02:55.000 [warn] connection_mark_for_close_internal_(): Bug: Duplicate call to connection_mark_for_close at src/or/directory.c:5204 (first at src/or/main.c
:1210) (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] tor_bug_occurred_(): Bug: src/or/connection.c:841: connection_mark_for_close_internal_: This line should not have been reached. (Future in
stances of this warning will be silenced.) (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug: Line unexpectedly reached at connection_mark_for_close_internal_ at src/or/connection.c:841. Stack trace: (on Tor 0.3.4.5-rc 673f3d64
0ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(log_backtrace+0x43) [0x564c703385b3] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xb9) [0x564c70353419] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(connection_dir_finished_flushing+0x99) [0x564c702ee739] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(connection_handle_read+0xb06) [0x564c702c7df6] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(+0x5211e) [0x564c7021511e] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(+0x2259d) [0x7fd546aa759d] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(event_base_loop+0x4e7) [0x7fd546aa8367] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0x17a) [0x564c7021733a] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(tor_run_main+0x1015) [0x564c70219725] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(tor_main+0x3a) [0x564c70211bba] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(main+0x19) [0x564c70211949] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xea) [0x7fd545829eda] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)
Jul 21 08:02:55.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x564c7021199a] (on Tor 0.3.4.5-rc 673f3d640ef7fb05)

Child Tickets

Change History (9)

comment:1 Changed 4 months ago by nickm

Keywords: 034-must? regression? crash? added
Milestone: Tor: 0.3.4.x-final

comment:2 Changed 3 months ago by nickm

Owner: set to nickm
Status: newaccepted

Okay -- this looks like a directory connection that got closed in main.c because it was stalled for a while, and then soon after we call connection_finished_flushing() on it because its linked connection just pulled some data from it anyway.

The fact that this turned up in 0.3.4 is probably a side-effect of the mainloop refactoring.

comment:3 Changed 3 months ago by nickm

Keywords: regression added; 034-must? regression? crash? removed
Status: acceptedneeds_review

I have a simple fix in my branch bug26896_034, with PR at https://github.com/torproject/tor/pull/284

Since this isn't a crash bug, I recommend we merge it first in 0.3.5 and then consider a backport.

comment:4 Changed 3 months ago by nickm

Keywords: 034-backport added
Milestone: Tor: 0.3.4.x-finalTor: 0.3.5.x-final

comment:5 Changed 3 months ago by dgoulet

Reviewer: dgoulet

comment:6 Changed 3 months ago by dgoulet

Status: needs_reviewmerge_ready

ACK.

comment:7 Changed 3 months ago by nickm

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

merged to 0.3.5; marked for possible backport.

comment:8 in reply to:  3 Changed 8 weeks ago by Ralph

Replying to nickm:

Since this isn't a crash bug, I recommend we merge it first in 0.3.5 and then consider a backport.

I wonder about the "not a crash" part. I've seen this bug on my nodes, and typically Tor will die shortly after the incident, according to log files. Here's the latest example:

Sep 27 04:59:00 foo Tor[3049]: connection_dir_finished_flushing(): Bug: Emptied a dirserv buffer, but it's still spooling! (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: connection_mark_for_close_internal_(): Bug: Duplicate call to connection_mark_for_close at src/or/directory.c:5201 (first at src/or/main.c:1210) (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: tor_bug_occurred_(): Bug: src/or/connection.c:841: connection_mark_for_close_internal_: This line should not have been reached. (Future instances of this warning will be silenced.) (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug: Line unexpectedly reached at connection_mark_for_close_internal_ at src/or/connection.c:841. Stack trace: (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(log_backtrace+0x33) [0x559ba45aaa23] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(tor_bug_occurred_+0xb9) [0x559ba45c1069] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(connection_dir_finished_flushing+0x9a) [0x559ba45668ea] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(connection_handle_read+0xacb) [0x559ba453f99b] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(+0x4e5ae) [0x559ba449b5ae] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/lib64/libevent-2.1.so.6(+0x20a73) [0x7fae3c70fa73] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/lib64/libevent-2.1.so.6(event_base_loop+0x53f) [0x7fae3c71092f] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(do_main_loop+0x17a) [0x559ba449d1aa] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(tor_run_main+0x1005) [0x559ba449f4b5] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(tor_main+0x26) [0x559ba4498b46] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(main+0x9) [0x559ba44989a9] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /lib64/libc.so.6(__libc_start_main+0xea) [0x7fae3b840f0a] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 04:59:00 foo Tor[3049]: Bug:     /usr/bin/tor(_start+0x2a) [0x559ba44989ea] (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 05:04:12 foo Tor[3049]: connection_dir_finished_flushing(): Bug: Emptied a dirserv buffer, but it's still spooling! (on Tor 0.3.4.8 da95b91355248ad8)
Sep 27 05:04:12 foo Tor[3049]: connection_mark_for_close_internal_(): Bug: Duplicate call to connection_mark_for_close at src/or/directory.c:5201 (first at src/or/main.c:1210) (on Tor 0.3.4.8 da95b91355248ad8)

These are the last log entries, and my monitoring told me that the Tor ports went dead after that. Logging in on the machine showed that the Tor process had disappeared.

Edit: For reasons unknown to me, I cannot add myself to this ticket's "Cc" field (it is greyed out). Perhaps a friendly Tor developer could do that for me? Thank you.

Last edited 8 weeks ago by Ralph (previous) (diff)

comment:9 Changed 3 weeks ago by nickm

Resolution: fixed
Status: merge_readyclosed

Merged to 0.3.4 and forward!

Note: See TracTickets for help on using tickets.