Skip to content
Snippets Groups Projects
New look: Off

scanner.9 in torflow/bwauth failing

    • Closed (moved) Issue created by Tom Ritter @tjr

    I don't really have an idea of a cause here, but I noticed scanner.9 was failing. I have a 7.7GB log with debug messages, but here's the top and bottom 4000 lines:

    top: http://pastebin.com/3fuEjkJ0 bottom: http://pastebin.com/7kF75asb

    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

    • Tom Ritter added component::core tor/torflow priority::medium severity::normal status::new type::defect labels

      added component::core tor/torflow priority::medium severity::normal status::new type::defect labels

    • Tom Ritter
      Tom Ritter @tjr ·
      Author

      Still a problem. Here's some less verbose logs showing how it looks at the end:

      WARN[Wed Oct 04 11:56:14 2017]:Not enough streams yet. 0 < 17.875
NOTICE[Wed Oct 04 11:56:14 2017]:Stream 1452310 FAILED with TIMEOUT
NOTICE[Wed Oct 04 11:56:14 2017]:Stream 1452310 CLOSED with TIMEOUT
NOTICE[Wed Oct 04 11:58:14 2017]:Tor timed out our SOCKS stream request.
WARN[Wed Oct 04 11:58:14 2017]:Not enough streams yet. 0 < 17.875
NOTICE[Wed Oct 04 11:58:14 2017]:Stream 1452349 FAILED with TIMEOUT
NOTICE[Wed Oct 04 11:58:14 2017]:Stream 1452349 CLOSED with TIMEOUT
NOTICE[Wed Oct 04 12:00:14 2017]:Tor timed out our SOCKS stream request.
WARN[Wed Oct 04 12:00:14 2017]:Not enough streams yet. 0 < 17.875
NOTICE[Wed Oct 04 12:00:14 2017]:Stream 1452388 FAILED with TIMEOUT
NOTICE[Wed Oct 04 12:00:14 2017]:Stream 1452388 CLOSED with TIMEOUT

      Trac:
      Severity: N/A to Blocker
      Sponsor: N/A to N/A
      Reviewer: N/A to N/A

    • T
      teor @teor ·

      scanner9 is the unmeasured ondes scanner.

      The last 4000 lines are an infinite loop of:

      WARN[Mon Sep 14 07:31:41 2015]:Error building circ: ('552 No such router "D542940134156DCA0B872A9AFA43EECDF8E64A50"',)

      It looks like it got stuck on measuring this one node, but the node was down (or its descriptor was unavailable, or something).

      It would help to see:

      • any scanner logs from the NEWCONSENSUS event
      • the tor logs from the tor instance assigned to scanner 9
      • whether D542940134156DCA0B872A9AFA43EECDF8E64A50 was in the consensus at the time of the log
    • S
      starlight @starlight ·

      Trac:
      Cc: N/A to starlight@binnacle.cx

    • Tom Ritter
      Tom Ritter @tjr ·
      Author

      Okay, I have this error currently:

      WARN[Wed Oct 11 02:35:14 2017]:Error building circ: ('552 No such router "0456CEE48AF23B95610645D037D385F35679A1E2"',)

      The first occurrence is

      WARN[Wed Oct 04 23:23:09 2017]:Error building circ: ('552 No such router "0456CEE48AF23B95610645D037D385F35679A1E2"',)

      I can't find this relay in the consensus at https://consensus-health.torproject.org/consensus-health-2017-10-04-23-00.html#0456CEE48AF23B95610645D037D385F35679A1E2 or for the next 7 hours.

      The tor log has:

      • 33911 instances of the following line between Aug 8th and current
      • [notice] Tried for 120 seconds to get a connection to 130.242.60.21:443. Giving up. (waiting for controller)
      • Nothing unusual (at the notice level) except the connection give up around that time. A few control connections, a heartbeat, and the above notice.

      There is nothing about NEWCONSENSUS in scanner.9/bw.log prior to the first mention of 0456CEE48AF23B95610645D037D385F35679A1E2 (which is the no such router error).

      Before that error it's ~ 2 days of

      WARN[Wed Oct 04 23:16:24 2017]:No circuit for 2157208 circ: 0
NOTICE[Wed Oct 04 23:16:24 2017]:Stream 2157208 CLOSED with TIMEOUT
NOTICE[Wed Oct 04 23:18:24 2017]:Tor timed out our SOCKS stream request.
WARN[Wed Oct 04 23:18:26 2017]:Not enough streams yet. 0 < 17.875
WARN[Wed Oct 04 23:18:26 2017]:No circuit for 2157272 circ: 0
NOTICE[Wed Oct 04 23:18:26 2017]:Stream 2157272 FAILED with TIMEOUT
WARN[Wed Oct 04 23:18:26 2017]:No circuit for 2157272 circ: 0
NOTICE[Wed Oct 04 23:18:26 2017]:Stream 2157272 CLOSED with TIMEOUT
NOTICE[Wed Oct 04 23:20:26 2017]:Tor timed out our SOCKS stream request.
WARN[Wed Oct 04 23:20:28 2017]:Not enough streams yet. 0 < 17.875
NOTICE[Wed Oct 04 23:20:28 2017]:Stream 2157339 FAILED with TIMEOUT

      Then right before that it's

      WARN[Mon Oct 02 23:15:23 2017]:Not enough streams yet. 62 < 79.625
WARN[Mon Oct 02 23:15:35 2017]:Not enough streams yet. 63 < 79.625
WARN[Mon Oct 02 23:15:42 2017]:Not enough streams yet. 64 < 79.625
NOTICE[Mon Oct 02 23:17:42 2017]:Tor timed out our SOCKS stream request.
WARN[Mon Oct 02 23:17:42 2017]:Not enough streams yet. 64 < 79.625
NOTICE[Mon Oct 02 23:17:42 2017]:Stream 2054350 FAILED with TIMEOUT
NOTICE[Mon Oct 02 23:17:42 2017]:Stream 2054350 CLOSED with TIMEOUT
WARN[Mon Oct 02 23:17:50 2017]:Not enough streams yet. 65 < 79.625
NOTICE[Mon Oct 02 23:19:50 2017]:Tor timed out our SOCKS stream request.
WARN[Mon Oct 02 23:19:50 2017]:Not enough streams yet. 65 < 79.625
NOTICE[Mon Oct 02 23:19:50 2017]:Stream 2054397 FAILED with TIMEOUT
NOTICE[Mon Oct 02 23:19:50 2017]:Stream 2054397 CLOSED with TIMEOUT
NOTICE[Mon Oct 02 23:21:50 2017]:Tor timed out our SOCKS stream request.
WARN[Mon Oct 02 23:21:50 2017]:Not enough streams yet. 65 < 79.625
NOTICE[Mon Oct 02 23:21:50 2017]:Stream 2054447 FAILED with TIMEOUT
NOTICE[Mon Oct 02 23:21:50 2017]:Stream 2054447 CLOSED with TIMEOUT
WARN[Mon Oct 02 23:23:16 2017]:Not enough streams yet. 66 < 79.625
WARN[Mon Oct 02 23:23:23 2017]:Not enough streams yet. 67 < 79.625
NOTICE[Mon Oct 02 23:29:23 2017]:Wedged Tor stream. Closing all streams
WARN[Mon Oct 02 23:29:24 2017]:Timer exceeded limit: 360.298864841

WARN[Mon Oct 02 23:29:24 2017]:Not enough streams yet. 68 < 79.625
WARN[Mon Oct 02 23:29:27 2017]:Not enough streams yet. 69 < 79.625
WARN[Mon Oct 02 23:29:45 2017]:Not enough streams yet. 70 < 79.625
WARN[Mon Oct 02 23:30:26 2017]:Not enough streams yet. 71 < 79.625
WARN[Mon Oct 02 23:31:21 2017]:Not enough streams yet. 72 < 79.625
NOTICE[Mon Oct 02 23:33:22 2017]:Tor timed out our SOCKS stream request.
WARN[Mon Oct 02 23:33:22 2017]:Not enough streams yet. 72 < 79.625
NOTICE[Mon Oct 02 23:33:22 2017]:Stream 2054746 FAILED with TIMEOUT
NOTICE[Mon Oct 02 23:33:22 2017]:Stream 2054746 CLOSED with TIMEOUT
WARN[Mon Oct 02 23:33:29 2017]:Not enough streams yet. 73 < 79.625
WARN[Mon Oct 02 23:34:22 2017]:Not enough streams yet. 74 < 79.625
NOTICE[Mon Oct 02 23:36:23 2017]:Tor timed out our SOCKS stream request.
WARN[Mon Oct 02 23:36:23 2017]:Not enough streams yet. 74 < 79.625
NOTICE[Mon Oct 02 23:36:23 2017]:Stream 2054817 FAILED with TIMEOUT
NOTICE[Mon Oct 02 23:36:23 2017]:Stream 2054817 CLOSED with TIMEOUT
WARN[Mon Oct 02 23:36:46 2017]:Not enough streams yet. 75 < 79.625
NOTICE[Mon Oct 02 23:38:46 2017]:Tor timed out our SOCKS stream request.
WARN[Mon Oct 02 23:38:46 2017]:Not enough streams yet. 75 < 79.625
NOTICE[Mon Oct 02 23:38:46 2017]:Stream 2054854 FAILED with TIMEOUT
NOTICE[Mon Oct 02 23:38:46 2017]:Stream 2054854 CLOSED with TIMEOUT
WARN[Mon Oct 02 23:40:20 2017]:Not enough streams yet. 76 < 79.625
WARN[Mon Oct 02 23:41:02 2017]:Not enough streams yet. 77 < 79.625
WARN[Mon Oct 02 23:42:50 2017]:Not enough streams yet. 78 < 79.625
NOTICE[Mon Oct 02 23:44:50 2017]:Tor timed out our SOCKS stream request.
WARN[Mon Oct 02 23:44:50 2017]:Not enough streams yet. 78 < 79.625
NOTICE[Mon Oct 02 23:44:50 2017]:Stream 2054980 FAILED with TIMEOUT
NOTICE[Mon Oct 02 23:44:50 2017]:Stream 2054980 CLOSED with TIMEOUT
WARN[Mon Oct 02 23:45:54 2017]:Not enough streams yet. 79 < 79.625
NOTICE[Mon Oct 02 23:46:28 2017]:Child Process Spawned...
NOTICE[Mon Oct 02 23:49:03 2017]:Starting slice for percentiles 87.7192982456-175.438596491
NOTICE[Mon Oct 02 23:49:03 2017]:Only 6 exits remain in slice 87.7192982456-175.438596491 after restrictions. Adding in ['24E91955D969AEA1D80413C64FE106FAE7FD2EA9', 'A041B285B228241
C3185483EEF42F0BC96D40BFB', '6E64DC7207A92D38E552B73F891A53043562BF66', '38A42B8D7C0E6346F4A4821617740AEE86EA885B']
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit 6E64DC7207A92D38E552B73F891A53043562BF66 in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/sql-87.7:175.4-done-2017-10-02-23:56:16
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit 24E91955D969AEA1D80413C64FE106FAE7FD2EA9 in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/sql-87.7:175.4-done-2017-10-02-23:56:16
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit 38A42B8D7C0E6346F4A4821617740AEE86EA885B in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/sql-87.7:175.4-done-2017-10-02-23:56:16
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit A041B285B228241C3185483EEF42F0BC96D40BFB in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/sql-87.7:175.4-done-2017-10-02-23:56:16
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit 6E64DC7207A92D38E552B73F891A53043562BF66 in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/bws-87.7:175.4-done-2017-10-02-23:56:35
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit 24E91955D969AEA1D80413C64FE106FAE7FD2EA9 in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/bws-87.7:175.4-done-2017-10-02-23:56:35
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit 38A42B8D7C0E6346F4A4821617740AEE86EA885B in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/bws-87.7:175.4-done-2017-10-02-23:56:35
NOTICE[Mon Oct 02 23:56:35 2017]:Skipping stats on added exit A041B285B228241C3185483EEF42F0BC96D40BFB in /home/tom/bwauth/torflow/NetworkScanners/BwAuthority/./data/scanner.9/scan-
data/bws-87.7:175.4-done-2017-10-02-23:56:35
NOTICE[Mon Oct 02 23:56:35 2017]:Child Process Spawned...
NOTICE[Mon Oct 02 23:59:26 2017]:Child stop point 100 reached. Exiting with 9
NOTICE[Mon Oct 02 23:59:26 2017]:restarting from slice 0
NOTICE[Mon Oct 02 23:59:27 2017]:Child Process Spawned...
NOTICE[Tue Oct 03 00:02:01 2017]:Starting slice for percentiles 0.0-87.7192982456
NOTICE[Tue Oct 03 00:13:36 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:13:36 2017]:Stream 2055653 FAILED with TIMEOUT
NOTICE[Tue Oct 03 00:13:36 2017]:Stream 2055653 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 00:19:10 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:19:10 2017]:Stream 2055753 FAILED with TIMEOUT
NOTICE[Tue Oct 03 00:19:10 2017]:Stream 2055753 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 00:21:37 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:21:37 2017]:Stream 2055836 FAILED with TIMEOUT
NOTICE[Tue Oct 03 00:21:37 2017]:Stream 2055836 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 00:25:07 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:25:07 2017]:Stream 2055931 FAILED with TIMEOUT
NOTICE[Tue Oct 03 00:25:07 2017]:Stream 2055931 CLOSED with TIMEOUT
WARN[Tue Oct 03 00:26:00 2017]:BW event for unknown stream id: 2055978
NOTICE[Tue Oct 03 00:28:04 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:35:15 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:35:15 2017]:Stream 2056135 FAILED with TIMEOUT
NOTICE[Tue Oct 03 00:35:15 2017]:Stream 2056135 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 00:38:02 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:38:02 2017]:Stream 2056197 FAILED with TIMEOUT
NOTICE[Tue Oct 03 00:38:02 2017]:Stream 2056197 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 00:54:13 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:56:30 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 00:56:30 2017]:Stream 2056583 FAILED with TIMEOUT
NOTICE[Tue Oct 03 00:56:30 2017]:Stream 2056583 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:01:11 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:01:11 2017]:Stream 2056694 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:01:11 2017]:Stream 2056694 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:04:23 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:04:23 2017]:Stream 2056789 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:04:23 2017]:Stream 2056789 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:07:06 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:07:06 2017]:Stream 2056836 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:07:06 2017]:Stream 2056836 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:11:21 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:11:21 2017]:Stream 2056964 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:11:21 2017]:Stream 2056964 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:14:37 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:14:37 2017]:Stream 2057055 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:14:37 2017]:Stream 2057055 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:23:09 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:23:09 2017]:Stream 2057267 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:23:09 2017]:Stream 2057267 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:30:01 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:30:01 2017]:Stream 2057505 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:30:01 2017]:Stream 2057505 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:35:57 2017]:Tor timed out our SOCKS stream request.
NOTICE[Tue Oct 03 01:35:57 2017]:Stream 2057672 FAILED with TIMEOUT
NOTICE[Tue Oct 03 01:35:57 2017]:Stream 2057672 CLOSED with TIMEOUT
NOTICE[Tue Oct 03 01:38:24 2017]:Child Process Spawned...
NOTICE[Tue Oct 03 01:41:00 2017]:Starting slice for percentiles 94.3396226415-188.679245283
NOTICE[Tue Oct 03 01:41:00 2017]:Only 2 exits remain in slice 94.3396226415-188.679245283 after restrictions. Adding in ['998BF3ED7F70E33D1C307247B9626D9E7573C438', 'A478E421F83194C
114F41E94F95999672AED51FE', '38A42B8D7C0E6346F4A4821617740AEE86EA885B', 'B0279A521375F3CB2AE210BDBFC645FDD2E1973A', '5989521A85C94EE101E88B8DB2E68321673F9405', '3BADB3EFFB87534736BF
AC9A2024AB78401BDBC3', '557ACEC850F54EEE65839F83CACE2B0825BE811E', '7C0AA4E3B73E407E9F5FEB1912F8BE26D8AA124D']
    • T
      teor @teor ·

      Seems like the NEWCONSENSUS event is broken somehow.

      What's meant to happen is that the NEWCONSENSUS event arrives, and then the list of relays is updated.

    • T
      teor @teor ·

      Please test the patch in #20619 (moved) to see if it resolves this issue. I suspect that either #20619 (moved) or the workaround in #24094 (moved) will fix this.

    • T
      teor @teor ·

      Priorities and Severities in torflow are meaningless, setting them all to Medium/Normal.

      Trac:
      Severity: Blocker to Normal

    • T
      teor @teor ·

      aagbsn was the default owner, unassigning

      Trac:
      Status: new to assigned
      Owner: aagbsn to N/A

    • T
      teor @teor ·

      Mark all tickets that are assigned to nobody as "new".

      Trac:
      Status: assigned to new

    • teor mentioned in issue #20619 (moved)

      mentioned in issue #20619 (moved)

    • teor mentioned in issue #24094 (moved)

      mentioned in issue #24094 (moved)

    • Trac moved to tpo/network-health/torflow#17064 (closed)

      moved to tpo/network-health/torflow#17064 (closed)

    Please register or sign in to reply