Skip to content
Snippets Groups Projects

scheduler_release_channel: Non-fatal assertion

    • Closed (moved) Issue created by toralf @toralf

    Got this at a stable hardened Gentoo Linux exit :

    Dec 02 18:20:17.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)

... <repeating>

Dec 03 01:03:59.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
Dec 03 01:04:10.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
Dec 03 01:07:47.000 [warn] tor_bug_occurred_(): Bug: src/or/scheduler.c:631: scheduler_release_channel: Non-fatal assertion !(smartlist_pos(channels_pending, chan) == -1) failed. (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
    To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information

    Child items 0

    • No child items are currently assigned. Use child items to break down this issue into smaller parts.

    Activity

    • toralf changed milestone to %Tor: 0.3.2.x-final

      changed milestone to %Tor: 0.3.2.x-final

    • toralf added component::core tor/tor milestone::Tor: 0.3.2.x-final owner::dgoulet priority::low regression resolution::fixed reviewer::pastly severity::normal status::closed tor-sched type::defect version::tor 0.3.2.6-alpha labels

      added component::core tor/tor milestone::Tor: 0.3.2.x-final owner::dgoulet priority::low regression resolution::fixed reviewer::pastly severity::normal status::closed tor-sched type::defect version::tor 0.3.2.6-alpha labels

    • David Goulet
      David Goulet @dgoulet ·

      Oh, you should have much more log information after that warning. tor_bug_occurred_() prints much more usually of the current scheduler context?

      Trac:
      Status: new to needs_information

    • David Goulet
      David Goulet @dgoulet ·

      Oh also, you think you can find in your notice logs the Scheduler type. You are looking for something like (could be something else than "KIST"):

      [notice] Scheduler type KIST has been enabled.

      Trac:
      Milestone: N/A to Tor: 0.3.2.x-final
      Keywords: N/A deleted, tor-sched added

    • David Goulet
      David Goulet @dgoulet ·

      Bumping to High because this could mean we have a channel in a wrong scheduler state and thus might have been handled improperly through out its lifetime.

      However, the scheduler will recover here, this is just a sanity checks during a free channel.

      Trac:
      Priority: Medium to High

    • toralf
      toralf @toralf ·
      Author

      Indeed, here's the missing info :

      /tmp/warn.log-Dec 03 01:19:02.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:20:50.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:21:51.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
mr-fox ~ # grep -A 100 sched /tmp/warn*
/tmp/warn.log:Dec 03 01:07:47.000 [warn] tor_bug_occurred_(): Bug: src/or/scheduler.c:631: scheduler_release_channel: Non-fatal assertion !(smartlist_pos(channels_pending, chan) == -1) failed. (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log:Dec 03 01:07:47.000 [warn] Bug: Non-fatal assertion !(smartlist_pos(channels_pending, chan) == -1) failed in scheduler_release_channel at src/or/scheduler.c:631. Stack trace: (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(log_backtrace+0x53) [0x55ad3ea64e73] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc5) [0x55ad3ea81b75] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log:Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(scheduler_release_channel+0x19a) [0x55ad3e99312a] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(+0xc7408) [0x55ad3e99f408] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(connection_or_about_to_close+0x4d) [0x55ad3e9f43dd] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(+0x4ff8c) [0x55ad3e927f8c] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(+0x50788) [0x55ad3e928788] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(+0x2373a) [0x7ff15d09073a] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(event_base_loop+0x57f) [0x7ff15d09168f] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0x24d) [0x55ad3e929f3d] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(tor_main+0x1c2d) [0x55ad3e92d9bd] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(main+0x28) [0x55ad3e9252b8] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7ff15bc055ad] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x55ad3e92530a] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log:Dec 03 01:07:47.000 [warn] scheduler_bug_occurred(): Bug: Channel 431733 in state channel error and scheduler state 3. Num cells on cmux: 0. Connection outbuf len: 0. Num pending channels: 127. Channel in pending list: no. (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
/tmp/warn.log-Dec 03 01:07:47.000 [warn] Scheduler asked to release channel 431733 but it wasn't in channels_pending
/tmp/warn.log-Dec 03 01:10:05.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:11:45.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:11:47.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:13:36.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:16:41.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:18:19.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)
/tmp/warn.log-Dec 03 01:19:02.000 [warn] Tried to establish rendezvous on non-OR circuit with purpose Acting as rendevous (pending)

      and FWIW I set the loglevel from warn to notice.

    • David Goulet
      David Goulet @dgoulet ·

      Thanks toralf!

      Bottom line here is that a release on a channel has been done by connection_or_about_to_close() meaning the channel's connection was closed in error state. This seems to be coming from the libevent main loop, most likely the write_event of the connection.

      I think what happened is that the channel was in pending state in the scheduler, it got into the first condition if (socket_can_write(&socket_table, chan)) { but then because the channel wasn't opened, we moved to the next channel.

      This had two consequences. First, the channel scheduler state is kept at PENDING but it is not put back in the channel pending list. Second, because it is still in that state, scheduler_release_channel() triggered that bug but at least clean it up properly. A PENDING state for a channel implies that it has to be in the pending list.

      The KIST scheduler has 4 conditions and each of them should end with setting the channel scheduler state to reflect what has been done with it.

      The condition I outlined above is really the only place I can find where we fail to update the state properly. It has been introduced with dcabf801e52 (0.3.2.4-alpha). Fortunately, this is harmless but annoying.

      Branch: bug24502_032_01

      Trac:
      Status: needs_information to needs_review
      Priority: High to Low
      Keywords: N/A deleted, regression added

    • David Goulet
      David Goulet @dgoulet ·

      Trac:
      Status: needs_review to accepted
      Owner: N/A to dgoulet

    • David Goulet
      David Goulet @dgoulet ·

      Trac:
      Reviewer: N/A to pastly
      Status: accepted to needs_review

    • toralf
      toralf @toralf ·
      Author

      Another example from today:

      Dec 04 21:03:05.000 [warn] tor_bug_occurred_(): Bug: src/or/scheduler.c:631: scheduler_release_channel: Non-fatal assertion !(smartlist_pos(channels_pending, chan) =
= -1) failed. (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug: Non-fatal assertion !(smartlist_pos(channels_pending, chan) == -1) failed in scheduler_release_channel at src/or/scheduler.c:631. Sta
ck trace: (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(log_backtrace+0x53) [0x55ad3ea64e73] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc5) [0x55ad3ea81b75] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(scheduler_release_channel+0x19a) [0x55ad3e99312a] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(+0xc7408) [0x55ad3e99f408] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(connection_or_about_to_close+0x4d) [0x55ad3e9f43dd] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(+0x4ff8c) [0x55ad3e927f8c] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(+0x50788) [0x55ad3e928788] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(+0x2373a) [0x7ff15d09073a] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(event_base_loop+0x57f) [0x7ff15d09168f] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0x24d) [0x55ad3e929f3d] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(tor_main+0x1c2d) [0x55ad3e92d9bd] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(main+0x28) [0x55ad3e9252b8] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfd) [0x7ff15bc055ad] (on Tor 0.3.2.6-al
pha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Bug:     /usr/bin/tor(_start+0x2a) [0x55ad3e92530a] (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] scheduler_bug_occurred(): Bug: Channel 1204645 in state channel error and scheduler state 3. Num cells on cmux: 3. Connection outbuf len: 0. Num pending channels: 98. Channel in pending list: no. (on Tor 0.3.2.6-alpha 87012d076ef58bb9)
Dec 04 21:03:05.000 [warn] Scheduler asked to release channel 1204645 but it wasn't in channels_pending
    • pastly
      pastly @pastly ·

      dgoulet's bug24502_032_01 LGTM

      Trac:
      Status: needs_review to merge_ready

    • Nick Mathewson
      Nick Mathewson @nickm ·

      LGTM too but maybe we should have a test here?

      Trac:
      Status: merge_ready to needs_revision

    • David Goulet
      David Goulet @dgoulet ·

      Replying to nickm:

      LGTM too but maybe we should have a test here?

      Test added in 1a55a5ff06f9022a

    • David Goulet
      David Goulet @dgoulet ·

      Trac:
      Status: needs_revision to merge_ready

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Thank you!

      Merged to master.

      Trac:
      Resolution: N/A to fixed
      Status: merge_ready to closed

    • Nick Mathewson
      Nick Mathewson @nickm ·

      whoops -- also merged to 0.3.2

    • Trac closed

      closed

    • Trac moved to tpo/core/tor#24502 (closed)

      moved to tpo/core/tor#24502 (closed)

    Please register or sign in to reply