Opened 4 years ago

Last modified 15 months ago

#17064 new defect

scanner.9 in torflow/bwauth failing

Reported by: tom Owned by:
Priority: Medium Milestone:
Component: Core Tor/Torflow Version:
Severity: Normal Keywords:
Cc: starlight@… Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

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

Child Tickets

TicketStatusOwnerSummaryComponent
#4272closedmikeperrychoose_url throws confusing exception in bw authCore Tor/Torflow
#20619needs_reviewtombwauths don't handle NEWCONSENSUS event correctlyCore Tor/pytorctl
#24094newtommeasured bw percentage is always 100Core Tor/Torflow
#24210needs_reviewAvoid division by zero and excessive ranks in pytorctl's ScanHandler.rank_to_percentCore Tor/pytorctl

Change History (9)

comment:1 Changed 18 months ago by tom

Severity: Blocker

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

comment:2 Changed 18 months ago by 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

comment:3 Changed 18 months ago by starlight

Cc: starlight@… added

comment:4 Changed 17 months ago by tom

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']

comment:5 Changed 17 months ago by 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.

comment:6 Changed 16 months ago by teor

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

comment:7 Changed 16 months ago by teor

Severity: BlockerNormal

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

comment:8 Changed 16 months ago by teor

Owner: aagbsn deleted
Status: newassigned

aagbsn was the default owner, unassigning

comment:9 Changed 15 months ago by teor

Status: assignednew

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

Note: See TracTickets for help on using tickets.