Re: [tor-bugs] #22400 [Core Tor/Tor]: We bootstrap from different primary guards when we start with a non-live consensus and not enough guards in the state file

["Tor Bug Tracker & Wiki" <blackhole@xxxxxxxxxxxxxx>]

#22400: We bootstrap from different primary guards when we start with a non-live
consensus and not enough guards in the state file
--------------------------+------------------------------------
 Reporter:  arma          |          Owner:
     Type:  defect        |         Status:  new
 Priority:  Medium        |      Milestone:  Tor: 0.3.1.x-final
Component:  Core Tor/Tor  |        Version:  Tor: 0.3.0.7
 Severity:  Normal        |     Resolution:
 Keywords:                |  Actual Points:
Parent ID:                |         Points:
 Reviewer:                |        Sponsor:
--------------------------+------------------------------------
Description changed by arma:

Old description:

> I started my Tor client (0.3.1.1-alpha (git-ab9976b7245f05a9)) with these
> three guards (and only these three guards) in my state file:
> {{{
> Guard in=default rsa_id=BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910
> nickname=onslaught sampled_on=2017-04-29T09:28:05 sampled_by=0.3.1.0
> -alpha-dev listed=1 confirmed_on=2017-05-02T22:48:40 confirmed_idx=1
> Guard in=default rsa_id=7369A0E14C59B11D78357EC5AFE573A259264BBD
> nickname=yono1 sampled_on=2017-05-02T20:44:35 sampled_by=0.3.1.0-alpha-
> dev listed=1 confirmed_on=2017-04-25T13:14:11 confirmed_idx=0
> pb_use_attempts=3.000000 pb_use_successes=3.000000
> pb_circ_attempts=105.000000 pb_circ_successes=105.000000
> pb_successful_circuits_closed=95.000000 pb_collapsed_circuits=10.000000
> pb_timeouts=8.000000
> Guard in=default rsa_id=62DA0256BBC28992D41CBAFB549FFD7C9B846A99
> nickname=IRejectTorFoundatnN sampled_on=2017-05-21T02:25:50
> sampled_by=0.3.1.0-alpha-dev listed=1 confirmed_on=2017-05-23T22:28:05
> confirmed_idx=2
> }}}
>
> I figured that since there were three, and they were all confirmed, they
> would be my primary guards.
>
> Also, my cached-microdesc-consensus file was about a day old.
>
> When Tor starts, it says
> {{{
> May 25 20:58:06.155 [info] sampled_guards_update_from_consensus(): No
> live consensus; can't update sampled entry guards.
> }}}
> Ok, great, it's not going to go deleting or modifying any of my guards
> before it's even tried to load my consensus file from disk. Makes sense.
>
> Then it goes through to update my three guards to say that they're not
> working:
> {{{
> May 25 20:58:06.155 [debug] entry_guard_set_filtered_flags(): Updated
> sampled guard onslaught ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910):
> filtered=0; reachable_filtered=0.
> May 25 20:58:06.155 [debug] entry_guard_set_filtered_flags(): Updated
> sampled guard yono1 ($7369A0E14C59B11D78357EC5AFE573A259264BBD):
> filtered=0; reachable_filtered=0.
> May 25 20:58:06.156 [debug] entry_guard_set_filtered_flags(): Updated
> sampled guard IRejectTorFoundatnN
> ($62DA0256BBC28992D41CBAFB549FFD7C9B846A99): filtered=0;
> reachable_filtered=0.
> }}}
> I'm guessing that happened because of entry_guards_update_filtered_sets()
> which got called from entry_guards_update_all(), but there are several
> possible paths to that function so I'm not sure which one it was. Maybe
> it's decided they're all down, since it hasn't even loaded a consensus
> yet, so they're all missing from the nonexistent consensus?
>
> Then we get to:
> {{{
> May 25 20:58:06.156 [info] sample_reachable_filtered_entry_guards():
> Trying to sample a reachable guard: We know of 0 in the USABLE_FILTERED
> set.
> May 25 20:58:06.156 [info] sample_reachable_filtered_entry_guards():
> (That isn't enough. Trying to expand the sample.)
> May 25 20:58:06.156 [info] entry_guards_expand_sample(): Expanding the
> sample guard set. We have 3 guards in the sample, and 0 eligible guards
> to extend it with.
> May 25 20:58:06.156 [info] entry_guards_expand_sample(): Not expanding
> the guard sample any further; just ran out of eligible guards
> May 25 20:58:06.156 [info] sample_reachable_filtered_entry_guards():
> (After filters [b], we have 0 guards to consider.)
> }}}
> Ok, great, we refuse to expand the guard list now. That's good because we
> don't have any consensus loaded yet.
>
> Then I finish loading the state file, and load other stuff from my
> datadirectory, like the cached-microdesc-consensus file:
> {{{
> May 25 20:58:06.644 [info] A consensus needs 5 good signatures from
> recognized authorities for us to accept it. This one has 8 (dannenberg
> tor26 longclaw maatuska moria1 dizum gabelmoo Faravahar).
> May 25 20:58:06.797 [info] microdesc_cache_reload(): Reloaded
> microdescriptor cache. Found 7298 descriptors.
> May 25 20:58:06.812 [info]
> update_consensus_networkstatus_fetch_time_impl(): No live microdesc
> consensus; we should fetch one immediately.
> May 25 20:58:06.812 [info] cell_ewma_set_scale_factor(): Enabled
> cell_ewma algorithm because of value in CircuitPriorityHalflifeMsec in
> consensus; scale factor is 0.793701 per 10 seconds
> May 25 20:58:07.046 [info] networkstatus_set_current_consensus(): Loaded
> an expired consensus. Discarding.
> May 25 20:58:07.046 [info] router_reload_consensus_networkstatus():
> Couldn't load unverified consensus microdesc networkstatus from cache
> }}}
> Ok, fine, it's expired so we discarded it, no problem.
>
> {{{
> May 25 20:58:07.182 [info]
> update_consensus_bootstrap_attempt_downloads(): Launching microdesc
> bootstrap mirror networkstatus consensus download.
> May 25 20:58:07.182 [notice] Starting with guard context "default"
> May 25 20:58:07.182 [info] sample_reachable_filtered_entry_guards():
> Trying to sample a reachable guard: We know of 0 in the USABLE_FILTERED
> set.
> May 25 20:58:07.182 [info] sample_reachable_filtered_entry_guards():
> (That isn't enough. Trying to expand the sample.)
> }}}
> Sounds good, I agree it's time to go get a fresh consensus.
>
> {{{
> May 25 20:58:07.182 [info] entry_guards_expand_sample(): Expanding the
> sample guard set. We have 3 guards in the sample, and 2220 eligible
> guards to extend it with.
> }}}
>
> Wait, what? Where did these 2220 eligible guards come from?
>
> Did they get added to a list of potential eligible guards, when we were
> examining the old microdesc consensus -- the one that we then discarded
> because it was too old?
>
> That theory sounds plausible:
> {{{
> $ grep "^s " cached-microdesc-consensus |grep Guard|grep V2Dir|wc -l
> 2224
> }}}
>
> That's bug number one.
>
> So we proceed to add an eligible guard, since I have 0 eligible guards in
> my set:
> {{{
> May 25 20:58:07.182 [debug] compute_weighted_bandwidths(): Generated
> weighted bandwidths for rule weight as guard based on weights Wg=0.594700
> Wm=0.594700 We=0.000000 Wd=0.000000 with total bw 0
> May 25 20:58:07.182 [info] entry_guard_add_to_sample(): Adding
> $9285B22F7953D7874604EEE2B470609AD81C74E9~0x3d005 at 62.138.7.171 as to
> the entry guard sample set.
> May 25 20:58:07.182 [debug] entry_guard_set_filtered_flags(): Updated
> sampled guard 0x3d005 ($9285B22F7953D7874604EEE2B470609AD81C74E9):
> filtered=1; reachable_filtered=1.
> }}}
> In fact, we add 20 of them like this. And these ones are filtered=1,
> reachable_filtered=1, because we just picked them out of, I guess, a
> consensus that said they were Running.
>
> After we add the 20, we hit:
> {{{
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> Trying to sample a reachable guard: We know of 20 in the USABLE_FILTERED
> set.
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (After filters [b], we have 20 guards to consider.)
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (Selected 0x3d005 ($9285B22F7953D7874604EEE2B470609AD81C74E9).)
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> Trying to sample a reachable guard: We know of 20 in the USABLE_FILTERED
> set.
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (After filters [b], we have 19 guards to consider.)
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (Selected colosimo ($51939625169E2C7E0DC83D38BAE628BDE67E9A22).)
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> Trying to sample a reachable guard: We know of 20 in the USABLE_FILTERED
> set.
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (After filters [b], we have 18 guards to consider.)
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (Selected Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23).)
> }}}
> Ok, we've picked three. Then we see:
> {{{
> May 25 20:58:07.185 [info] entry_guards_update_primary(): Primary entry
> guards have changed. New primary guard list is:
> May 25 20:58:07.185 [info] entry_guards_update_primary():   1/3: 0x3d005
> ($9285B22F7953D7874604EEE2B470609AD81C74E9)
> May 25 20:58:07.185 [info] entry_guards_update_primary():   2/3: colosimo
> ($51939625169E2C7E0DC83D38BAE628BDE67E9A22)
> May 25 20:58:07.185 [info] entry_guards_update_primary():   3/3:
> Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23)
> }}}
> I had three perfectly fine primary guards earlier, but I had marked them
> down, so I guess we have three new ones.
>
> But then we proceed to ignore those three new ones too!
> {{{
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (After filters [7], we have 17 guards to consider.)
> May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
> (Selected Yuman ($3265FB6279E142BFBB8BE08AA0582011D23ED2EF).)
> May 25 20:58:07.185 [info] select_entry_guard_for_circuit(): No primary
> or confirmed guards available. Selected random guard Yuman
> ($3265FB6279E142BFBB8BE08AA0582011D23ED2EF) for circuit. Will try other
> guards before using this circuit.
> }}}
>
> That's bug number two.
>
> It looks like it launches a consensus download attempt to Yuman smoothly:
> {{{
> May 25 20:58:07.185 [info] directory_send_command(): Downloading
> consensus from 37.187.177.2:9001 using /tor/status-vote/current
> /consensus-
> microdesc/0232AF+14C131+23D15D+49015F+D586D1+E8A9C4+ED03BB+EFCBE7.z
> }}}
>
> And it launches a parallel fetch to an authority too, just like it's
> supposed to:
> {{{
> May 25 20:58:07.185 [info] directory_send_command(): Downloading
> consensus from 154.35.175.225:443 using /tor/status-vote/current
> /consensus-
> microdesc/0232AF+14C131+23D15D+49015F+D586D1+E8A9C4+ED03BB+EFCBE7.z
> }}}
>
> Faravahar is way more responsive than whoever Yuman is, so by the time I
> get my one-hop circuit open to Yuman, I'm already partway through
> fetching the consensus from Faravahar:
> {{{
> May 25 20:58:07.824 [info] internal circ (length 1, last hop Yuman):
> $3265FB6279E142BFBB8BE08AA0582011D23ED2EF(open)
> May 25 20:58:07.824 [debug] command_process_created_cell(): Moving to
> next skin.
> May 25 20:58:07.824 [debug] circuit_send_next_onion_skin(): starting to
> send subsequent skin.
> May 25 20:58:07.824 [info] circuit_send_next_onion_skin(): circuit built!
> May 25 20:58:07.824 [info] connection_ap_handshake_attach_circuit():
> Closing extra consensus fetch (to 37.187.177.2) since one is already
> downloading.
> }}}
>
> But then
> {{{
> May 25 20:58:07.825 [debug] conn_close_if_marked(): Cleaning up
> connection (fd -1).
> May 25 20:58:07.825 [info] entry_guards_note_guard_failure(): Recorded
> failure for guard Yuman ($3265FB6279E142BFBB8BE08AA0582011D23ED2EF)
> }}}
> That's not very nice of us, since the guard didn't actually fail, we just
> opted not to use that circuit because another circuit was faster.
>
> That's bug number three.
>
> Ok, after a bunch of lines, I get my microdesc consensus from Faravahar:
> {{{
> May 25 20:58:16.296 [debug] Received response from directory server
> '154.35.175.225:443': 200 "OK" (purpose: 14, response size: 629424,
> compression: 2)
> }}}
>
> And we start acting on it:
> {{{
> May 25 20:58:16.764 [info] launch_descriptor_downloads(): Launching 5
> requests for 2262 microdescs, 500 at a time
> May 25 20:58:16.766 [info] select_entry_guard_for_circuit(): Selected
> primary guard Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23) for
> circuit.
> }}}
> and we happily fetch the missing microdescriptors using our 3 (new)
> primary guards.
>
> There is this interesting tidbit:
> {{{
> May 25 20:58:18.032 [debug] fetch_from_buf_http(): headerlen 197, bodylen
> 127544.
> May 25 20:58:18.032 [debug] Received response from directory server
> '109.236.90.209:443': 200 "OK" (purpose: 19, response size: 127741,
> compression: 2)
> May 25 20:58:18.032 [info] make_guard_confirmed(): Marking colosimo
> ($51939625169E2C7E0DC83D38BAE628BDE67E9A22) as a confirmed guard (index
> 3)
> May 25 20:58:18.032 [info] entry_guards_update_primary(): Primary entry
> guards have changed. New primary guard list is:
> May 25 20:58:18.032 [info] entry_guards_update_primary():   1/3: colosimo
> ($51939625169E2C7E0DC83D38BAE628BDE67E9A22) (confirmed)
> May 25 20:58:18.032 [info] entry_guards_update_primary():   2/3: 0x3d005
> ($9285B22F7953D7874604EEE2B470609AD81C74E9)
> May 25 20:58:18.032 [info] entry_guards_update_primary():   3/3:
> Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23)
> May 25 20:58:18.032 [info] entry_guards_note_guard_success(): Recorded
> success for primary confirmed guard colosimo
> ($51939625169E2C7E0DC83D38BAE628BDE67E9A22)
> }}}
> We marked our guard confirmed because we used it to fetch directory info?
> I believe that's what we programmed it to do, but maybe our definition of
> confirmed should be that we attached a 'real' (non dir fetch) stream to a
> 'real' (3 hop or more) circuit.
>
> (We can call that bug number four if we like, but it's really more like
> feature request number one.)
>
> Eventually we get enough microdescs to convince us we should start making
> circuits:
> {{{
> May 25 20:58:18.453 [debug] compute_frac_paths_available(): f_guard:
> 0.86, f_mid: 0.86, f_exit: 0.88
> May 25 20:58:18.453 [notice] Bootstrapped 80%: Connecting to the Tor
> network
> May 25 20:58:18.454 [debug] update_guard_selection_choice(): Staying with
> guard context "default" (no change)
> May 25 20:58:18.454 [info] sampled_guards_update_from_consensus():
> Updating sampled guard status based on received consensus.
> May 25 20:58:18.454 [debug] sampled_guards_update_from_consensus():
> Sampled guard onslaught ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910) is
> still listed.
> May 25 20:58:18.454 [debug] sampled_guards_update_from_consensus():
> Sampled guard yono1 ($7369A0E14C59B11D78357EC5AFE573A259264BBD) is still
> listed.
> }}}
> and we see those sampled_guards_update_from_consensus() lines for each of
> our 23 of our guards, followed by 23 of these lines, one for each guard:
> {{{
> May 25 20:58:18.454 [debug] entry_guard_set_filtered_flags(): Updated
> sampled guard onslaught ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910):
> filtered=1; reachable_filtered=1.
> May 25 20:58:18.454 [debug] entry_guard_set_filtered_flags(): Updated
> sampled guard yono1 ($7369A0E14C59B11D78357EC5AFE573A259264BBD):
> filtered=1; reachable_filtered=1.
> }}}
>
> And then, oh hey, we get our original primary guards back!
> {{{
> May 25 20:58:18.455 [info] entry_guards_update_primary(): Primary entry
> guards have changed. New primary guard list is:
> May 25 20:58:18.455 [info] entry_guards_update_primary():   1/3: yono1
> ($7369A0E14C59B11D78357EC5AFE573A259264BBD) (confirmed)
> May 25 20:58:18.455 [info] entry_guards_update_primary():   2/3:
> onslaught ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910) (confirmed)
> May 25 20:58:18.455 [info] entry_guards_update_primary():   3/3:
> IRejectTorFoundatnN ($62DA0256BBC28992D41CBAFB549FFD7C9B846A99)
> (confirmed)
> }}}
>
> And then we build a 3-hop circuit with yono1:
> {{{
> May 25 20:58:19.738 [info] exit circ (length 3, last hop digineo3):
> $7369A0E14C59B11D78357EC5AFE573A259264BBD(open)
> $0269165034C5586D6551CCCFA8940D2305948754(
> open) $B21211A1A2C68F2D9E57E3C7AEAF4F04AFC10E7F(open)
> May 25 20:58:19.738 [info] entry_guards_note_guard_success(): Recorded
> success for primary confirmed guard yono1
> ($7369A0E14C59B11D78357EC5AFE573A259264BBD)
> May 25 20:58:19.738 [notice] Tor has successfully opened a circuit. Looks
> like client functionality is working.
> }}}

New description:

 I started my Tor client (0.3.1.1-alpha (git-ab9976b7245f05a9)) with these
 three guards (and only these three guards) in my state file:
 {{{
 Guard in=default rsa_id=BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910
 nickname=onslaught sampled_on=2017-04-29T09:28:05 sampled_by=0.3.1.0
 -alpha-dev listed=1 confirmed_on=2017-05-02T22:48:40 confirmed_idx=1
 Guard in=default rsa_id=7369A0E14C59B11D78357EC5AFE573A259264BBD
 nickname=yono1 sampled_on=2017-05-02T20:44:35 sampled_by=0.3.1.0-alpha-dev
 listed=1 confirmed_on=2017-04-25T13:14:11 confirmed_idx=0
 pb_use_attempts=3.000000 pb_use_successes=3.000000
 pb_circ_attempts=105.000000 pb_circ_successes=105.000000
 pb_successful_circuits_closed=95.000000 pb_collapsed_circuits=10.000000
 pb_timeouts=8.000000
 Guard in=default rsa_id=62DA0256BBC28992D41CBAFB549FFD7C9B846A99
 nickname=IRejectTorFoundatnN sampled_on=2017-05-21T02:25:50
 sampled_by=0.3.1.0-alpha-dev listed=1 confirmed_on=2017-05-23T22:28:05
 confirmed_idx=2
 }}}

 I figured that since there were three, and they were all confirmed, they
 would be my primary guards.

 Also, my cached-microdesc-consensus file was about a day old.

 When Tor starts, it says
 {{{
 May 25 20:58:06.155 [info] sampled_guards_update_from_consensus(): No live
 consensus; can't update sampled entry guards.
 }}}
 Ok, great, it's not going to go deleting or modifying any of my guards
 before it's even tried to load my consensus file from disk. Makes sense.

 Then it goes through to update my three guards to say that they're not
 working:
 {{{
 May 25 20:58:06.155 [debug] entry_guard_set_filtered_flags(): Updated
 sampled guard onslaught ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910):
 filtered=0; reachable_filtered=0.
 May 25 20:58:06.155 [debug] entry_guard_set_filtered_flags(): Updated
 sampled guard yono1 ($7369A0E14C59B11D78357EC5AFE573A259264BBD):
 filtered=0; reachable_filtered=0.
 May 25 20:58:06.156 [debug] entry_guard_set_filtered_flags(): Updated
 sampled guard IRejectTorFoundatnN
 ($62DA0256BBC28992D41CBAFB549FFD7C9B846A99): filtered=0;
 reachable_filtered=0.
 }}}
 I'm guessing that happened because of entry_guards_update_filtered_sets()
 which got called from entry_guards_update_all(), but there are several
 possible paths to that function so I'm not sure which one it was. Maybe
 it's decided they're all down, since it hasn't even loaded a consensus
 yet, so they're all missing from the nonexistent consensus?

 Then we get to:
 {{{
 May 25 20:58:06.156 [info] sample_reachable_filtered_entry_guards():
 Trying to sample a reachable guard: We know of 0 in the USABLE_FILTERED
 set.
 May 25 20:58:06.156 [info] sample_reachable_filtered_entry_guards():
 (That isn't enough. Trying to expand the sample.)
 May 25 20:58:06.156 [info] entry_guards_expand_sample(): Expanding the
 sample guard set. We have 3 guards in the sample, and 0 eligible guards to
 extend it with.
 May 25 20:58:06.156 [info] entry_guards_expand_sample(): Not expanding the
 guard sample any further; just ran out of eligible guards
 May 25 20:58:06.156 [info] sample_reachable_filtered_entry_guards():
 (After filters [b], we have 0 guards to consider.)
 }}}
 Ok, great, we refuse to expand the guard list now. That's good because we
 don't have any consensus loaded yet.

 Then I finish loading the state file, and load other stuff from my
 datadirectory, like the cached-microdesc-consensus file:
 {{{
 May 25 20:58:06.644 [info] A consensus needs 5 good signatures from
 recognized authorities for us to accept it. This one has 8 (dannenberg
 tor26 longclaw maatuska moria1 dizum gabelmoo Faravahar).
 May 25 20:58:06.797 [info] microdesc_cache_reload(): Reloaded
 microdescriptor cache. Found 7298 descriptors.
 May 25 20:58:06.812 [info]
 update_consensus_networkstatus_fetch_time_impl(): No live microdesc
 consensus; we should fetch one immediately.
 May 25 20:58:06.812 [info] cell_ewma_set_scale_factor(): Enabled cell_ewma
 algorithm because of value in CircuitPriorityHalflifeMsec in consensus;
 scale factor is 0.793701 per 10 seconds
 May 25 20:58:07.046 [info] networkstatus_set_current_consensus(): Loaded
 an expired consensus. Discarding.
 May 25 20:58:07.046 [info] router_reload_consensus_networkstatus():
 Couldn't load unverified consensus microdesc networkstatus from cache
 }}}
 Ok, fine, it's expired so we discarded it, no problem.

 {{{
 May 25 20:58:07.182 [info] update_consensus_bootstrap_attempt_downloads():
 Launching microdesc bootstrap mirror networkstatus consensus download.
 May 25 20:58:07.182 [notice] Starting with guard context "default"
 May 25 20:58:07.182 [info] sample_reachable_filtered_entry_guards():
 Trying to sample a reachable guard: We know of 0 in the USABLE_FILTERED
 set.
 May 25 20:58:07.182 [info] sample_reachable_filtered_entry_guards():
 (That isn't enough. Trying to expand the sample.)
 }}}
 Sounds good, I agree it's time to go get a fresh consensus.

 {{{
 May 25 20:58:07.182 [info] entry_guards_expand_sample(): Expanding the
 sample guard set. We have 3 guards in the sample, and 2220 eligible guards
 to extend it with.
 }}}

 Wait, what? Where did these 2220 eligible guards come from?

 Did they get added to a list of potential eligible guards, when we were
 examining the old microdesc consensus -- the one that we then discarded
 because it was too old?

 That theory sounds plausible:
 {{{
 $ grep "^s " cached-microdesc-consensus |grep Guard|grep V2Dir|wc -l
 2224
 }}}

 That's bug number one.

 So we proceed to add an eligible guard, since I have 0 eligible guards in
 my set:
 {{{
 May 25 20:58:07.182 [debug] compute_weighted_bandwidths(): Generated
 weighted bandwidths for rule weight as guard based on weights Wg=0.594700
 Wm=0.594700 We=0.000000 Wd=0.000000 with total bw 0
 May 25 20:58:07.182 [info] entry_guard_add_to_sample(): Adding
 $9285B22F7953D7874604EEE2B470609AD81C74E9~0x3d005 at 62.138.7.171 as to
 the entry guard sample set.
 May 25 20:58:07.182 [debug] entry_guard_set_filtered_flags(): Updated
 sampled guard 0x3d005 ($9285B22F7953D7874604EEE2B470609AD81C74E9):
 filtered=1; reachable_filtered=1.
 }}}
 In fact, we add 20 of them like this. And these ones are filtered=1,
 reachable_filtered=1, because we just picked them out of, I guess, a
 consensus that said they were Running.

 After we add the 20, we hit:
 {{{
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 Trying to sample a reachable guard: We know of 20 in the USABLE_FILTERED
 set.
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (After filters [b], we have 20 guards to consider.)
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (Selected 0x3d005 ($9285B22F7953D7874604EEE2B470609AD81C74E9).)
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 Trying to sample a reachable guard: We know of 20 in the USABLE_FILTERED
 set.
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (After filters [b], we have 19 guards to consider.)
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (Selected colosimo ($51939625169E2C7E0DC83D38BAE628BDE67E9A22).)
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 Trying to sample a reachable guard: We know of 20 in the USABLE_FILTERED
 set.
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (After filters [b], we have 18 guards to consider.)
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (Selected Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23).)
 }}}
 Ok, we've picked three. Then we see:
 {{{
 May 25 20:58:07.185 [info] entry_guards_update_primary(): Primary entry
 guards have changed. New primary guard list is:
 May 25 20:58:07.185 [info] entry_guards_update_primary():   1/3: 0x3d005
 ($9285B22F7953D7874604EEE2B470609AD81C74E9)
 May 25 20:58:07.185 [info] entry_guards_update_primary():   2/3: colosimo
 ($51939625169E2C7E0DC83D38BAE628BDE67E9A22)
 May 25 20:58:07.185 [info] entry_guards_update_primary():   3/3:
 Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23)
 }}}
 I had three perfectly fine primary guards earlier, but I had marked them
 down, so I guess we have three new ones.

 But then we proceed to ignore those three new ones too!
 {{{
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (After filters [7], we have 17 guards to consider.)
 May 25 20:58:07.185 [info] sample_reachable_filtered_entry_guards():
 (Selected Yuman ($3265FB6279E142BFBB8BE08AA0582011D23ED2EF).)
 May 25 20:58:07.185 [info] select_entry_guard_for_circuit(): No primary or
 confirmed guards available. Selected random guard Yuman
 ($3265FB6279E142BFBB8BE08AA0582011D23ED2EF) for circuit. Will try other
 guards before using this circuit.
 }}}

 That's bug number two.

 It looks like it launches a consensus download attempt to Yuman smoothly:
 {{{
 May 25 20:58:07.185 [info] directory_send_command(): Downloading consensus
 from 37.187.177.2:9001 using /tor/status-vote/current/consensus-
 microdesc/0232AF+14C131+23D15D+49015F+D586D1+E8A9C4+ED03BB+EFCBE7.z
 }}}

 And it launches a parallel fetch to an authority too, just like it's
 supposed to:
 {{{
 May 25 20:58:07.185 [info] directory_send_command(): Downloading consensus
 from 154.35.175.225:443 using /tor/status-vote/current/consensus-
 microdesc/0232AF+14C131+23D15D+49015F+D586D1+E8A9C4+ED03BB+EFCBE7.z
 }}}

 Faravahar is way more responsive than whoever Yuman is, so by the time I
 get my one-hop circuit open to Yuman, I'm already partway through fetching
 the consensus from Faravahar:
 {{{
 May 25 20:58:07.824 [info] internal circ (length 1, last hop Yuman):
 $3265FB6279E142BFBB8BE08AA0582011D23ED2EF(open)
 May 25 20:58:07.824 [debug] command_process_created_cell(): Moving to next
 skin.
 May 25 20:58:07.824 [debug] circuit_send_next_onion_skin(): starting to
 send subsequent skin.
 May 25 20:58:07.824 [info] circuit_send_next_onion_skin(): circuit built!
 May 25 20:58:07.824 [info] connection_ap_handshake_attach_circuit():
 Closing extra consensus fetch (to 37.187.177.2) since one is already
 downloading.
 }}}

 But then
 {{{
 May 25 20:58:07.825 [debug] conn_close_if_marked(): Cleaning up connection
 (fd -1).
 May 25 20:58:07.825 [info] entry_guards_note_guard_failure(): Recorded
 failure for guard Yuman ($3265FB6279E142BFBB8BE08AA0582011D23ED2EF)
 }}}
 That's not very nice of us, since the guard didn't actually fail, we just
 opted not to use that circuit because another circuit was faster.

 That's bug number three.

 Ok, after a bunch of lines, I get my microdesc consensus from Faravahar:
 {{{
 May 25 20:58:16.296 [debug] Received response from directory server
 '154.35.175.225:443': 200 "OK" (purpose: 14, response size: 629424,
 compression: 2)
 }}}

 And we start acting on it:
 {{{
 May 25 20:58:16.764 [info] launch_descriptor_downloads(): Launching 5
 requests for 2262 microdescs, 500 at a time
 May 25 20:58:16.766 [info] select_entry_guard_for_circuit(): Selected
 primary guard Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23) for
 circuit.
 }}}
 and we happily fetch the missing microdescriptors using our 3 (new)
 primary guards.

 There is this interesting tidbit:
 {{{
 May 25 20:58:18.032 [debug] fetch_from_buf_http(): headerlen 197, bodylen
 127544.
 May 25 20:58:18.032 [debug] Received response from directory server
 '109.236.90.209:443': 200 "OK" (purpose: 19, response size: 127741,
 compression: 2)
 May 25 20:58:18.032 [info] make_guard_confirmed(): Marking colosimo
 ($51939625169E2C7E0DC83D38BAE628BDE67E9A22) as a confirmed guard (index 3)
 May 25 20:58:18.032 [info] entry_guards_update_primary(): Primary entry
 guards have changed. New primary guard list is:
 May 25 20:58:18.032 [info] entry_guards_update_primary():   1/3: colosimo
 ($51939625169E2C7E0DC83D38BAE628BDE67E9A22) (confirmed)
 May 25 20:58:18.032 [info] entry_guards_update_primary():   2/3: 0x3d005
 ($9285B22F7953D7874604EEE2B470609AD81C74E9)
 May 25 20:58:18.032 [info] entry_guards_update_primary():   3/3:
 Tungurahua ($7CB15FA5CD985B9BBD6AC386C62C206A1F391C23)
 May 25 20:58:18.032 [info] entry_guards_note_guard_success(): Recorded
 success for primary confirmed guard colosimo
 ($51939625169E2C7E0DC83D38BAE628BDE67E9A22)
 }}}
 We marked our guard confirmed because we used it to fetch directory info?
 I believe that's what we programmed it to do, but maybe our definition of
 confirmed should be that we attached a 'real' (non dir fetch) stream to a
 'real' (3 hop or more) circuit.

 (We can call that bug number four if we like, but it's really more like
 feature request number one.)

 Eventually we get enough microdescs to convince us we should start making
 circuits:
 {{{
 May 25 20:58:18.453 [debug] compute_frac_paths_available(): f_guard: 0.86,
 f_mid: 0.86, f_exit: 0.88
 May 25 20:58:18.453 [notice] Bootstrapped 80%: Connecting to the Tor
 network
 May 25 20:58:18.454 [debug] update_guard_selection_choice(): Staying with
 guard context "default" (no change)
 May 25 20:58:18.454 [info] sampled_guards_update_from_consensus():
 Updating sampled guard status based on received consensus.
 May 25 20:58:18.454 [debug] sampled_guards_update_from_consensus():
 Sampled guard onslaught ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910) is
 still listed.
 May 25 20:58:18.454 [debug] sampled_guards_update_from_consensus():
 Sampled guard yono1 ($7369A0E14C59B11D78357EC5AFE573A259264BBD) is still
 listed.
 }}}
 and we see those sampled_guards_update_from_consensus() lines for each of
 our 23 of our guards, followed by 23 of these lines, one for each guard:
 {{{
 May 25 20:58:18.454 [debug] entry_guard_set_filtered_flags(): Updated
 sampled guard onslaught ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910):
 filtered=1; reachable_filtered=1.
 May 25 20:58:18.454 [debug] entry_guard_set_filtered_flags(): Updated
 sampled guard yono1 ($7369A0E14C59B11D78357EC5AFE573A259264BBD):
 filtered=1; reachable_filtered=1.
 }}}

 And then, oh hey, we get our original primary guards back!
 {{{
 May 25 20:58:18.455 [info] entry_guards_update_primary(): Primary entry
 guards have changed. New primary guard list is:
 May 25 20:58:18.455 [info] entry_guards_update_primary():   1/3: yono1
 ($7369A0E14C59B11D78357EC5AFE573A259264BBD) (confirmed)
 May 25 20:58:18.455 [info] entry_guards_update_primary():   2/3: onslaught
 ($BB119A5A4D5DA2BBB7B796ECC50E3C0F1D4FD910) (confirmed)
 May 25 20:58:18.455 [info] entry_guards_update_primary():   3/3:
 IRejectTorFoundatnN ($62DA0256BBC28992D41CBAFB549FFD7C9B846A99)
 (confirmed)
 }}}

 And then we build a 3-hop circuit with yono1, as expected:
 {{{
 May 25 20:58:19.738 [info] exit circ (length 3, last hop digineo3):
 $7369A0E14C59B11D78357EC5AFE573A259264BBD(open)
 $0269165034C5586D6551CCCFA8940D2305948754(
 open) $B21211A1A2C68F2D9E57E3C7AEAF4F04AFC10E7F(open)
 May 25 20:58:19.738 [info] entry_guards_note_guard_success(): Recorded
 success for primary confirmed guard yono1
 ($7369A0E14C59B11D78357EC5AFE573A259264BBD)
 May 25 20:58:19.738 [notice] Tor has successfully opened a circuit. Looks
 like client functionality is working.
 }}}

--

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/22400#comment:3>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs