Skip to content
Snippets Groups Projects
New look: Off

We bootstrap from different primary guards when we start with a non-live consensus and not enough guards in the state file

    • Closed (moved) Issue created by Roger Dingledine @arma

    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.
    To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information

    Child items ...

    • Activity

    • Roger Dingledine changed milestone to %Tor: 0.3.3.x-final

      changed milestone to %Tor: 0.3.3.x-final

    • Roger Dingledine added bootstrap component::core tor/tor milestone::Tor: 0.3.3.x-final owner::nickm points::3 priority::medium resolution::fixed reviewer::asn s8-errors severity::normal sponsor::8-can status::closed tor-client tor-guard type::defect version::tor 0.3.0.7 labels

      added bootstrap component::core tor/tor milestone::Tor: 0.3.3.x-final owner::nickm points::3 priority::medium resolution::fixed reviewer::asn s8-errors severity::normal sponsor::8-can status::closed tor-client tor-guard type::defect version::tor 0.3.0.7 labels

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      Trac:
      tord-log.gz

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      the debug level log

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      Trac:
      cached-microdesc-consensus.gz

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      the cached-microdesc-consensus I started it with

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      Trac:
      state

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      the state file I started it with

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      Trac:
      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.

      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 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.

      to

      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 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.
    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      Trac:
      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 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.

      to

      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.
    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      Trac:
      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.

      to

      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.
    • T
      teor @teor ·

      Replying to arma:

      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 }}}

      No, that's a bug: #20604 (moved).

      There's no need for every client to contact an authority: they didn't in 0.2.8, and they all worked fine. But when the exponential backoff code was merged, there was no provision for a set initial delay, and we couldn't define the schedules so that we'd get a short delay without blowing out the remaining attempts. So we got this compromise.

      Trac:
      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.

      to

      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.
    • T
      teor @teor ·

      (It could be argued, though, that it's better to have more load on the directory authorities rather than clients waiting for 10 seconds when the 3 fallbacks they choose are down. Someone else can work that one out!)

    • T
      teor @teor ·

      Replying to teor:

      Replying to arma:

      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 }}}

      No, that's a bug: #20604 (moved).

      There's no need for every client to contact an authority: they didn't in 0.2.8, and they all worked fine. But when the exponential backoff code was merged, there was no provision for a set initial delay, and we couldn't define the schedules so that we'd get a short delay without blowing out the remaining attempts. So we got this compromise.

      Sorry, I was wrong.

      This happened because we never reset download statuses before we use them. See #17750 (moved).

    • Roger Dingledine
      Roger Dingledine @arma ·
      Author

      (adding back the change to the ticket body that teor accidentally reverted above)

      Trac:
      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.

      to

      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.
    • George Kadianakis
      George Kadianakis @asn ·

      Trac:
      Cc: N/A to asn

    • S
      s7r @s7r ·

      Trac:
      Cc: asn to asn, s7r

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Diagnosis: The "Loaded an expired consensus. Discarding" message is a red herring; that is talking about a cached unverified consensus, as evidenced by the next line, "Couldn't load unverified consensus microdesc networkstatus from cache."

      What's actually going on here is that we are accepting a slightly old consensus. The expiration check is:

        if (from_cache && !accept_obsolete &&
      c->valid_until < now-OLD_ROUTER_DESC_MAX_AGE) {
    log_info(LD_DIR, "Loaded an expired consensus. Discarding.");
    goto done;
  }

      with the relevant constant defined as

      #define OLD_ROUTER_DESC_MAX_AGE (60*60*24*5)

      So, one bug here is that a really old unverified consensus got left around. We have a ticket for that from 2011 (#4187 (moved))!

      One other bug is that we're expanding our guard sample even though the consensus is a few days out of date.

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Trac:
      Owner: N/A to nickm
      Status: new to accepted

    • Nick Mathewson
      Nick Mathewson @nickm ·

      So, the main root bug here is fixed in my branch bug22400_030_01. (I'll let #4187 (moved) speak for itself.)

      I have a corresponding spec change in branch bug22400_01 in torspec.

      Trac:
      Points: N/A to 3
      Keywords: N/A deleted, tor-client gor-guard 030-backport added
      Status: accepted to needs_review

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Trac:
      Keywords: tor-client gor-guard 030-backport deleted, tor-client tor-guard 030-backport added

    • George Kadianakis
      George Kadianakis @asn ·

      Trac:
      Reviewer: N/A to asn

    • George Kadianakis
      George Kadianakis @asn ·

      Patch looks reasonable for what it's trying to do, but I think we now have two very similar logics: the one we just added, and the one that already exists in sampled_guards_update_from_consensus():

        // It's important to use only a live consensus here; we don't want to
  // make changes based on anything expired or old.
  if (gs->type != GS_TYPE_BRIDGE) {
    networkstatus_t *ns = networkstatus_get_live_consensus(approx_time());

    if (! ns) {
      log_info(LD_GUARD, "No live consensus; can't update "
               "sampled entry guards.");
      return;
    } else {
      log_info(LD_GUARD, "Updating sampled guard status based on received "
               "consensus.");
    }
  }

      Do we need both checks? If yes, can we functionify them?

    • Nick Mathewson
      Nick Mathewson @nickm ·

      I think we do need both checks; without a live consensus, we don't want to expand the list or change its members' status.

      The checks are slightly different; for expand it was "reasonably live" and for change status it's "live". I think that maybe they should both become "live"; let's try that.

      What do you think of the commit I just added to the branch?

    • George Kadianakis
      George Kadianakis @asn ·

      Replying to nickm:

      I think we do need both checks; without a live consensus, we don't want to expand the list or change its members' status.

      The checks are slightly different; for expand it was "reasonably live" and for change status it's "live". I think that maybe they should both become "live"; let's try that.

      What do you think of the commit I just added to the branch?

      Makes sense. I like it more this way and less code dup.

      I tested it with an old consensus from collector, and tor correctly declined to add any guards to the sampled set before fetching a new consensus.

      Marking this branch as merge_ready.

      Trac:
      Status: needs_review to merge_ready

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Thank you, asn! Merging to 0.3.0 and forward.

      I'm putting this back in "accept" since I believe Roger has more to add.

      Trac:
      Status: merge_ready to accepted

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Replying to cypherpunks:

      "reasonably live" (under 1 day old)

      No. "Reasonably live" is about valid_after <= now <= valid_until. 3 hours range by default.

      Are you quite sure? See networkstatus_valid_until_is_reasonably_live in networkstatus.c

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Roger, did you want to say more here? If not we should just close this.

      Trac:
      Cc: asn, s7r to asn, s7r, arma
      Milestone: Tor: 0.3.1.x-final to Tor: 0.3.3.x-final
      Status: accepted to needs_information

    • C
      Taylor Yu @catalyst ·

      Trac:
      Cc: asn, s7r, arma to asn, s7r, arma, catalyst
      Keywords: tor-client tor-guard 030-backport deleted, tor-client tor-guard 030-backport bootstrap added

    • C
      Taylor Yu @catalyst ·

      Trac:
      Sponsor: N/A to Sponsor8-can
      Keywords: tor-client tor-guard 030-backport bootstrap deleted, tor-client tor-guard 030-backport bootstrap s8-errors added

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Remove 030-backport from all open tickets that have it: 0.3.0 is now deprecated.

      Trac:
      Keywords: tor-client tor-guard 030-backport bootstrap s8-errors deleted, tor-client, s8-errors, bootstrap, tor-guard added

    • George Kadianakis
      George Kadianakis @asn ·

      Seems like this is done now. Closing.

      Trac:
      Resolution: N/A to fixed
      Status: needs_information to closed

    • Trac closed

      closed

    • Trac changed time estimate to 24h

      changed time estimate to 24h

    • George Kadianakis mentioned in issue #24300 (moved)

      mentioned in issue #24300 (moved)

    • Trac moved to tpo/core/tor#22400 (closed)

      moved to tpo/core/tor#22400 (closed)

    Please register or sign in to reply