Opened 8 months ago

Closed 6 months ago

#27228 closed defect (worksforme)

pathbias_should_count(): Bug: Circuit X is now being counted

Reported by: traumschule Owned by: traumschule
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: unspecified
Severity: Normal Keywords: pathbias
Cc: mikeperry Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Looking through my tor.log I found 64 lines like this during the last day (out of 66 BUG lines):

Aug 20 03:09:58.000 [info] {BUG} pathbias_should_count(): Bug: Circuit 355 is now being counted despite being ignored in the past. Purpose is Measuring circuit timeout, path state is new (on Tor 0.3.5.0-alpha-dev )

The other BUGs were:

Aug 20 03:19:00.000 [info] {BUG} pathbias_count_build_success(): Bug: Succeeded circuit is in strange path state new. Circuit is a Measuring circuit timeout currently open. (on Tor 0.3.5.0-alpha-dev )
Aug 20 03:19:03.000 [info] {CIRC} extend_info_from_node(): Including Ed25519 ID for $name at $address

(Maybe relevant: #24966, #24903, #19535, #8196, #8081)

Child Tickets

Change History (12)

comment:1 Changed 8 months ago by traumschule

$ git log --pretty=oneline -S "is now being counted"
b4ebf8421ada3edf104ae5fc96d288f11271445b Move pathbias functions into a new file.
6828a19670080a3d19bdddf1e55d53928d81a410 Add a tristate to guard against unexpected circ purpose transitions
$ git checkout b4ebf8421ada3edf104ae5fc96d288f11271445b
$ rgrep "is now being counted despite being ignored" -n
src/or/circpathbias.c:335:              "Circuit %d is now being counted despite being ignored "
$ git checkout 6828a19670080a3d19bdddf1e55d53928d81a410
$ rgrep "is now being counted despite being ignored" -n
src/or/circuitbuild.c:1414:              "Circuit %d is now being counted despite being ignored "
$ gitk

Author: Mike Perry <mikeperry-git@…> 2013-01-30 22:46:25
Committer: Nick Mathewson <nickm@…> 2013-02-01 23:01:12
Parent: 173ed05d2f7233371dfcb1ef32a4d95f5096c435 (Clarify state transition and related pathbias comments)
Follows: tor-0.2.4.9-alpha
Precedes: tor-0.2.4.10-alpha

+    /* Check to see if the shouldcount result has changed due to a
+     * unexpected purpose change that would affect our results.
+     *
+     * The reason we check the path state too here is because for the
+     * cannibalized versions of these purposes, we count them as successful
+     * before their purpose change.
+     */
+    if (circ->pathbias_shouldcount == PATHBIAS_SHOULDCOUNT_COUNTED
+            && circ->path_state != PATH_STATE_ALREADY_COUNTED) {
+      log_info(LD_BUG,
+               "Circuit %d is now being ignored despite being counted "
+               "in the past. Purpose is %s, path state is %s",
+               circ->global_identifier,
+               circuit_purpose_to_string(circ->base_.purpose),
+               pathbias_state_to_string(circ->path_state));
+    }
+    circ->pathbias_shouldcount = PATHBIAS_SHOULDCOUNT_IGNORED;
     return 0;
   }

comment:2 Changed 8 months ago by teor

Cc: mikeperry added
Status: newneeds_information

Hi traumschule, please tell us what your tor is doing. Is it a relay, a bridge, a client, or an onion service? How are you launching it?

Hi mikeperry, can you triage this bug? How serious is it?

comment:3 Changed 8 months ago by teor

Milestone: Tor: 0.3.5.x-finalTor: unspecified

comment:4 Changed 8 months ago by teor

Hi traumschule, what version of Tor are you running?
Please put it in the "version" field, not the "milestone" field.

comment:5 Changed 8 months ago by traumschule

At the time these messages appeared first Tor was configured as a system daemon to serve onions services only. Some hours ago I enabled doc/PluggableTransports/obfs4proxy, but below occurrences should be unrelated to that because it happened before it being a bridge only used as client with onion services:

Aug 17 21:34:59.000 [info] {BUG} pathbias_should_count(): Bug: Circuit 23 is now being counted despite being ignored in the past. Purpose is Measuring circuit timeout, path state is new (on Tor 0.3.5.0-alpha-dev )
...
Aug 20 03:09:58.000 [info] {BUG} pathbias_should_count(): Bug: Circuit 355 is now being counted despite being ignored in the past. Purpose is Measuring circuit timeout, path state is new (on Tor 0.3.5.0-alpha-dev )
...
Aug 21 03:24:50.000 [info] {BUG} pathbias_should_count(): Bug: Circuit 867 is now being counted despite being ignored in the past. Purpose is Measuring circuit timeout, path state is new (on Tor 0.3.5.0-alpha-dev )

Note the version at the end of each line: 0.3.5.0-alpha-dev. Can't define it in trac though because this version is not available yet.

Update: I disabled the obfs4proxy by now to not mix up issues here and to confirm that the pathbias BUG is unrelated to the bridge.

Last edited 8 months ago by traumschule (previous) (diff)

comment:6 Changed 8 months ago by traumschule

The bug did not reappear since. Will observe it further, could it be related to the choosen guard?

comment:7 Changed 8 months ago by mikeperry

This is not serious. One of related bugs you linked can happen with a Tor controller is launching circuits. Were you using any Tor controller, out of curiosity?

Also, just as an FYI, I think it is fine to remove all of the pathbias code once we get a tagging resistant cipher in place, such as https://gitweb.torproject.org/torspec.git/tree/proposals/295-relay-crypto-with-atl.txt

It is primarily designed to catch large amounts of circuit failure due to many circuits failing when the tag doesn't match the exit.

comment:8 Changed 8 months ago by traumschule

One of related bugs you linked can happen with a Tor controller is launching circuits. Were you using any Tor controller

No, neither nyx, TorCtl nor Tor Launcher.

Going through todays log, the disappearance of above bug since 3:30 could be related to closing the OR port:

Aug 21 01:27:39.000 [notice] {NET} Opening OR listener on 127.0.0.1:9090
Aug 21 01:27:39.000 [notice] {NET} Closing no-longer-configured OR listener on 0.0.0.0:443
Aug 21 01:27:39.000 [notice] Tor 0.3.5.0-alpha-dev opening log file.
Aug 21 01:27:39.000 [notice] {NET} Closing old OR listener on 0.0.0.0:443
Aug 21 03:29:26.000 [notice] {NET} Opening Extended OR listener on 127.0.0.1:0
Aug 21 03:29:26.000 [notice] {NET} Extended OR listener listening on port 40481.
Aug 21 03:29:26.000 [notice] Tor 0.3.5.0-alpha-dev opening log file.
Aug 21 03:45:23.000 [notice] {NET} Closing no-longer-configured Extended OR listener on 127.0.0.1:40481
Aug 21 03:45:23.000 [notice] {NET} Closing no-longer-configured OR listener on 127.0.0.1:9090
Aug 21 03:45:23.000 [notice] Tor 0.3.5.0-alpha-dev opening log file.
Aug 21 03:45:23.000 [notice] {NET} Closing old Extended OR listener on 127.0.0.1:40481
Aug 21 03:45:23.000 [notice] {NET} Closing old OR listener on 127.0.0.1:9090

Aug 21 22:49:09.000 [notice] {HEARTBEAT} Heartbeat: Tor's uptime is 23:59 hours
Aug 21 23:07:39.000 [notice] {CIRC} Your network connection speed appears to have changed. Resetting timeout to 60s after 18 timeouts and 1000 buildtimes.
Aug 22 00:21:23.000 [notice] {GENERAL} Received reload signal (hup). Reloading config and resetting internal state.
Aug 22 00:21:24.000 [notice] {CONFIG} Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Aug 22 00:21:24.000 [notice] {CONFIG} Read configuration file "/etc/tor/torrc".

The last reload surprised me because I did not trigger it. Is there some kind of mechanism to automatically reload if torrc if it has changed?

comment:9 Changed 8 months ago by teor

No, but logrotate will HUP tor every day.

comment:10 in reply to:  7 Changed 7 months ago by traumschule

Owner: set to traumschule
Status: needs_informationassigned

Replying to mikeperry:

I think it is fine to remove all of the pathbias code once we get a tagging resistant cipher in place, such as https://gitweb.torproject.org/torspec.git/tree/proposals/295-relay-crypto-with-atl.txt

Hoping for further guidance in any case i will just try this. We'll see if i end up with a stable tor.

comment:11 Changed 7 months ago by traumschule

Keywords: pathbias added

Put open pathbias bugs on the radar of #27879.

comment:12 Changed 6 months ago by traumschule

Resolution: worksforme
Status: assignedclosed

Did not see this for some time.

Note: See TracTickets for help on using tickets.