#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 12 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 12 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 12 months ago by teor

Milestone: Tor: 0.3.5.x-finalTor: unspecified

comment:4 Changed 12 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 12 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 12 months ago by traumschule (previous) (diff)

comment:6 Changed 12 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 12 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 12 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 12 months ago by teor

No, but logrotate will HUP tor every day.

comment:10 in reply to:  7 Changed 11 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 11 months ago by traumschule

Keywords: pathbias added

Put open pathbias bugs on the radar of #27879.

comment:12 Changed 10 months ago by traumschule

Resolution: worksforme
Status: assignedclosed

Did not see this for some time.

Note: See TracTickets for help on using tickets.