src/feature/control/control_bootstrap.c

   1 /* Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson.
   2  * Copyright (c) 2007-2021, The Tor Project, Inc. */
   3 /* See LICENSE for licensing information */
   4
   5 /**
   6  * \file control_bootstrap.c
   7  * \brief Provide bootstrap progress events for the control port.
   8  */
   9 #include "core/or/or.h"
  10
  11 #include "app/config/config.h"
  12 #include "core/mainloop/connection.h"
  13 #include "core/or/connection_or.h"
  14 #include "core/or/connection_st.h"
  15 #include "core/or/or_connection_st.h"
  16 #include "core/or/reasons.h"
  17 #include "feature/control/control_events.h"
  18 #include "feature/hibernate/hibernate.h"
  19 #include "lib/malloc/malloc.h"
  20
  21 /** A sufficiently large size to record the last bootstrap phase string. */
  22 #define BOOTSTRAP_MSG_LEN 1024
  23
  24 /** What was the last bootstrap phase message we sent? We keep track
  25  * of this so we can respond to getinfo status/bootstrap-phase queries. */
  26 static char last_sent_bootstrap_message[BOOTSTRAP_MSG_LEN];
  27
  28 /** Table to convert bootstrap statuses to strings.  */
  29 static const struct {
  30   bootstrap_status_t status;
  31   const char *tag;
  32   const char *summary;
  33 } boot_to_str_tab[] = {
  34   { BOOTSTRAP_STATUS_UNDEF, "undef", "Undefined" },
  35   { BOOTSTRAP_STATUS_STARTING, "starting", "Starting" },
  36
  37   /* Initial connection to any relay */
  38
  39   { BOOTSTRAP_STATUS_CONN_PT, "conn_pt", "Connecting to pluggable transport" },
  40   { BOOTSTRAP_STATUS_CONN_DONE_PT, "conn_done_pt",
  41     "Connected to pluggable transport" },
  42   { BOOTSTRAP_STATUS_CONN_PROXY, "conn_proxy", "Connecting to proxy" },
  43   { BOOTSTRAP_STATUS_CONN_DONE_PROXY, "conn_done_proxy",
  44     "Connected to proxy" },
  45   { BOOTSTRAP_STATUS_CONN, "conn", "Connecting to a relay" },
  46   { BOOTSTRAP_STATUS_CONN_DONE, "conn_done", "Connected to a relay" },
  47   { BOOTSTRAP_STATUS_HANDSHAKE, "handshake",
  48     "Handshaking with a relay" },
  49   { BOOTSTRAP_STATUS_HANDSHAKE_DONE, "handshake_done",
  50     "Handshake with a relay done" },
  51
  52   /* Loading directory info */
  53
  54   { BOOTSTRAP_STATUS_ONEHOP_CREATE, "onehop_create",
  55     "Establishing an encrypted directory connection" },
  56   { BOOTSTRAP_STATUS_REQUESTING_STATUS, "requesting_status",
  57     "Asking for networkstatus consensus" },
  58   { BOOTSTRAP_STATUS_LOADING_STATUS, "loading_status",
  59     "Loading networkstatus consensus" },
  60   { BOOTSTRAP_STATUS_LOADING_KEYS, "loading_keys",
  61     "Loading authority key certs" },
  62   { BOOTSTRAP_STATUS_REQUESTING_DESCRIPTORS, "requesting_descriptors",
  63     "Asking for relay descriptors" },
  64   { BOOTSTRAP_STATUS_LOADING_DESCRIPTORS, "loading_descriptors",
  65     "Loading relay descriptors" },
  66   { BOOTSTRAP_STATUS_ENOUGH_DIRINFO, "enough_dirinfo",
  67     "Loaded enough directory info to build circuits" },
  68
  69   /* Connecting to a relay for AP circuits */
  70
  71   { BOOTSTRAP_STATUS_AP_CONN_PT, "ap_conn_pt",
  72     "Connecting to pluggable transport to build circuits" },
  73   { BOOTSTRAP_STATUS_AP_CONN_DONE_PT, "ap_conn_done_pt",
  74     "Connected to pluggable transport to build circuits" },
  75   { BOOTSTRAP_STATUS_AP_CONN_PROXY, "ap_conn_proxy",
  76     "Connecting to proxy to build circuits" },
  77   { BOOTSTRAP_STATUS_AP_CONN_DONE_PROXY, "ap_conn_done_proxy",
  78     "Connected to proxy to build circuits" },
  79   { BOOTSTRAP_STATUS_AP_CONN, "ap_conn",
  80     "Connecting to a relay to build circuits" },
  81   { BOOTSTRAP_STATUS_AP_CONN_DONE, "ap_conn_done",
  82     "Connected to a relay to build circuits" },
  83   { BOOTSTRAP_STATUS_AP_HANDSHAKE, "ap_handshake",
  84     "Finishing handshake with a relay to build circuits" },
  85   { BOOTSTRAP_STATUS_AP_HANDSHAKE_DONE, "ap_handshake_done",
  86     "Handshake finished with a relay to build circuits" },
  87
  88   /* Creating AP circuits */
  89
  90   { BOOTSTRAP_STATUS_CIRCUIT_CREATE, "circuit_create",
  91     "Establishing a Tor circuit" },
  92   { BOOTSTRAP_STATUS_DONE, "done", "Done" },
  93 };
  94 #define N_BOOT_TO_STR (sizeof(boot_to_str_tab)/sizeof(boot_to_str_tab[0]))
  95
  96 /** Convert the name of a bootstrapping phase <b>s</b> into strings
  97  * <b>tag</b> and <b>summary</b> suitable for display by the controller. */
  98 static int
  99 bootstrap_status_to_string(bootstrap_status_t s, const char **tag,
 100                            const char **summary)
 101 {
 102   for (size_t i = 0; i < N_BOOT_TO_STR; i++) {
 103     if (s == boot_to_str_tab[i].status) {
 104       *tag = boot_to_str_tab[i].tag;
 105       *summary = boot_to_str_tab[i].summary;
 106       return 0;
 107     }
 108   }
 109
 110   *tag = *summary = "unknown";
 111   return -1;
 112 }
 113
 114 /** What percentage through the bootstrap process are we? We remember
 115  * this so we can avoid sending redundant bootstrap status events, and
 116  * so we can guess context for the bootstrap messages which are
 117  * ambiguous. It starts at 'undef', but gets set to 'starting' while
 118  * Tor initializes. */
 119 static int bootstrap_percent = BOOTSTRAP_STATUS_UNDEF;
 120
 121 /** Like bootstrap_percent, but only takes on the enumerated values in
 122  * bootstrap_status_t.
 123  */
 124 static int bootstrap_phase = BOOTSTRAP_STATUS_UNDEF;
 125
 126 /** As bootstrap_percent, but holds the bootstrapping level at which we last
 127  * logged a NOTICE-level message. We use this, plus BOOTSTRAP_PCT_INCREMENT,
 128  * to avoid flooding the log with a new message every time we get a few more
 129  * microdescriptors */
 130 static int notice_bootstrap_percent = 0;
 131
 132 /** How many problems have we had getting to the next bootstrapping phase?
 133  * These include failure to establish a connection to a Tor relay,
 134  * failures to finish the TLS handshake, failures to validate the
 135  * consensus document, etc. */
 136 static int bootstrap_problems = 0;
 137
 138 /** We only tell the controller once we've hit a threshold of problems
 139  * for the current phase. */
 140 #define BOOTSTRAP_PROBLEM_THRESHOLD 10
 141
 142 /** When our bootstrapping progress level changes, but our bootstrapping
 143  * status has not advanced, we only log at NOTICE when we have made at least
 144  * this much progress.
 145  */
 146 #define BOOTSTRAP_PCT_INCREMENT 5
 147
 148 /** Do the actual logging and notifications for
 149  * control_event_bootstrap().  Doesn't change any state beyond that.
 150  */
 151 static void
 152 control_event_bootstrap_core(int loglevel, bootstrap_status_t status,
 153                              int progress)
 154 {
 155   char buf[BOOTSTRAP_MSG_LEN];
 156   const char *tag, *summary;
 157
 158   bootstrap_status_to_string(status, &tag, &summary);
 159   /* Locally reset status if there's incremental progress */
 160   if (progress)
 161     status = progress;
 162
 163   tor_log(loglevel, LD_CONTROL,
 164           "Bootstrapped %d%% (%s): %s", status, tag, summary);
 165   tor_snprintf(buf, sizeof(buf),
 166                "BOOTSTRAP PROGRESS=%d TAG=%s SUMMARY=\"%s\"",
 167                status, tag, summary);
 168   tor_snprintf(last_sent_bootstrap_message,
 169                sizeof(last_sent_bootstrap_message),
 170                "NOTICE %s", buf);
 171   control_event_client_status(LOG_NOTICE, "%s", buf);
 172 }
 173
 174 int
 175 control_get_bootstrap_percent(void)
 176 {
 177   return bootstrap_percent;
 178 }
 179
 180 /** Called when Tor has made progress at bootstrapping its directory
 181  * information and initial circuits.
 182  *
 183  * <b>status</b> is the new status, that is, what task we will be doing
 184  * next. <b>progress</b> is zero if we just started this task, else it
 185  * represents progress on the task.
 186  */
 187 void
 188 control_event_bootstrap(bootstrap_status_t status, int progress)
 189 {
 190   int loglevel = LOG_NOTICE;
 191
 192   if (bootstrap_percent == BOOTSTRAP_STATUS_DONE)
 193     return; /* already bootstrapped; nothing to be done here. */
 194
 195   if (status <= bootstrap_percent) {
 196     /* If there's no new progress, return early. */
 197     if (!progress || progress <= bootstrap_percent)
 198       return;
 199     /* Log at INFO if not enough progress happened. */
 200     if (progress < notice_bootstrap_percent + BOOTSTRAP_PCT_INCREMENT)
 201       loglevel = LOG_INFO;
 202   }
 203
 204   control_event_bootstrap_core(loglevel, status, progress);
 205
 206   if (status > bootstrap_percent) {
 207     bootstrap_phase = status; /* new milestone reached */
 208     bootstrap_percent = status;
 209   }
 210   if (progress > bootstrap_percent) {
 211     /* incremental progress within a milestone */
 212     bootstrap_percent = progress;
 213     bootstrap_problems = 0; /* Progress! Reset our problem counter. */
 214   }
 215   if (loglevel == LOG_NOTICE &&
 216       bootstrap_percent > notice_bootstrap_percent) {
 217     /* Remember that we gave a notice at this level. */
 218     notice_bootstrap_percent = bootstrap_percent;
 219   }
 220 }
 221
 222 /** Flag whether we've opened an OR_CONN yet  */
 223 static int bootstrap_first_orconn = 0;
 224
 225 /** Like bootstrap_phase, but for (possibly deferred) directory progress */
 226 static int bootstrap_dir_phase = BOOTSTRAP_STATUS_UNDEF;
 227
 228 /** Like bootstrap_problems, but for (possibly deferred) directory progress  */
 229 static int bootstrap_dir_progress = BOOTSTRAP_STATUS_UNDEF;
 230
 231 /** Defer directory info bootstrap events until we have successfully
 232  * completed our first connection to a router.  */
 233 void
 234 control_event_boot_dir(bootstrap_status_t status, int progress)
 235 {
 236   if (status > bootstrap_dir_progress) {
 237     bootstrap_dir_progress = status;
 238     bootstrap_dir_phase = status;
 239   }
 240   if (progress && progress >= bootstrap_dir_progress) {
 241     bootstrap_dir_progress = progress;
 242   }
 243
 244   /* Don't report unless we have successfully opened at least one OR_CONN */
 245   if (!bootstrap_first_orconn)
 246     return;
 247
 248   control_event_bootstrap(status, progress);
 249 }
 250
 251 /** Set a flag to allow reporting of directory bootstrap progress.
 252  * (Code that reports completion of an OR_CONN calls this.)  Also,
 253  * report directory progress so far. */
 254 void
 255 control_event_boot_first_orconn(void)
 256 {
 257   bootstrap_first_orconn = 1;
 258   control_event_bootstrap(bootstrap_dir_phase, bootstrap_dir_progress);
 259 }
 260
 261 /** Called when Tor has failed to make bootstrapping progress in a way
 262  * that indicates a problem. <b>warn</b> gives a human-readable hint
 263  * as to why, and <b>reason</b> provides a controller-facing short
 264  * tag.  <b>conn</b> is the connection that caused this problem and
 265  * can be NULL if a connection cannot be easily identified.
 266  */
 267 void
 268 control_event_bootstrap_problem(const char *warn, const char *reason,
 269                                 const connection_t *conn, int dowarn)
 270 {
 271   int status = bootstrap_percent;
 272   const char *tag = "", *summary = "";
 273   char buf[BOOTSTRAP_MSG_LEN];
 274   const char *recommendation = "ignore";
 275   int severity;
 276   char *or_id = NULL, *hostaddr = NULL;
 277   const or_connection_t *or_conn = NULL;
 278
 279   /* bootstrap_percent must not be in "undefined" state here. */
 280   tor_assert(status >= 0);
 281
 282   if (bootstrap_percent == 100)
 283     return; /* already bootstrapped; nothing to be done here. */
 284
 285   bootstrap_problems++;
 286
 287   if (bootstrap_problems >= BOOTSTRAP_PROBLEM_THRESHOLD)
 288     dowarn = 1;
 289
 290   /* Don't warn about our bootstrapping status if we are hibernating or
 291    * shutting down. */
 292   if (we_are_hibernating())
 293     dowarn = 0;
 294
 295   tor_assert(bootstrap_status_to_string(bootstrap_phase, &tag, &summary) == 0);
 296
 297   severity = dowarn ? LOG_WARN : LOG_INFO;
 298
 299   if (dowarn)
 300     recommendation = "warn";
 301
 302   if (conn && conn->type == CONN_TYPE_OR) {
 303     /* XXX TO_OR_CONN can't deal with const */
 304     or_conn = CONST_TO_OR_CONN(conn);
 305     or_id = tor_strdup(hex_str(or_conn->identity_digest, DIGEST_LEN));
 306   } else {
 307     or_id = tor_strdup("?");
 308   }
 309
 310   if (conn)
 311     tor_asprintf(&hostaddr, "%s:%d", conn->address, (int)conn->port);
 312   else
 313     hostaddr = tor_strdup("?");
 314
 315   log_fn(severity,
 316          LD_CONTROL, "Problem bootstrapping. Stuck at %d%% (%s): %s. (%s; %s; "
 317          "count %d; recommendation %s; host %s at %s)",
 318          status, tag, summary, warn, reason,
 319          bootstrap_problems, recommendation,
 320          or_id, hostaddr);
 321
 322   connection_or_report_broken_states(severity, LD_HANDSHAKE);
 323
 324   tor_snprintf(buf, sizeof(buf),
 325       "BOOTSTRAP PROGRESS=%d TAG=%s SUMMARY=\"%s\" WARNING=\"%s\" REASON=%s "
 326       "COUNT=%d RECOMMENDATION=%s HOSTID=\"%s\" HOSTADDR=\"%s\"",
 327       bootstrap_percent, tag, summary, warn, reason, bootstrap_problems,
 328       recommendation,
 329       or_id, hostaddr);
 330
 331   tor_snprintf(last_sent_bootstrap_message,
 332                sizeof(last_sent_bootstrap_message),
 333                "WARN %s", buf);
 334   control_event_client_status(LOG_WARN, "%s", buf);
 335
 336   tor_free(hostaddr);
 337   tor_free(or_id);
 338 }
 339
 340 /** Called when Tor has failed to make bootstrapping progress in a way
 341  * that indicates a problem. <b>warn</b> gives a hint as to why, and
 342  * <b>reason</b> provides an "or_conn_end_reason" tag.  <b>or_conn</b>
 343  * is the connection that caused this problem.
 344  */
 345 MOCK_IMPL(void,
 346 control_event_bootstrap_prob_or, (const char *warn, int reason,
 347                                   or_connection_t *or_conn))
 348 {
 349   int dowarn = 0;
 350
 351   if (! or_conn->potentially_used_for_bootstrapping) {
 352     /* We never decided that this channel was a good match for one of our
 353      * origin_circuit_t objects.  That means that we probably launched it
 354      * for somebody else, most likely in response to an EXTEND cell.
 355      *
 356      * Since EXTEND cells can contain arbitrarily broken descriptions of
 357      * relays, a failure on this connection here won't necessarily indicate a
 358      * bootstrapping problem.
 359      */
 360     return;
 361   }
 362
 363   if (or_conn->have_noted_bootstrap_problem)
 364     return;
 365
 366   or_conn->have_noted_bootstrap_problem = 1;
 367
 368   if (reason == END_OR_CONN_REASON_NO_ROUTE)
 369     dowarn = 1;
 370
 371   /* If we are using bridges and all our OR connections are now
 372      closed, it means that we totally failed to connect to our
 373      bridges. Throw a warning. */
 374   if (get_options()->UseBridges && !any_other_active_or_conns(or_conn))
 375     dowarn = 1;
 376
 377   control_event_bootstrap_problem(warn,
 378                                   orconn_end_reason_to_control_string(reason),
 379                                   TO_CONN(or_conn), dowarn);
 380 }
 381
 382 /** Return a copy of the last sent bootstrap message. */
 383 char *
 384 control_event_boot_last_msg(void)
 385 {
 386   return tor_strdup(last_sent_bootstrap_message);
 387 }
 388
 389 /** Reset bootstrap tracking state. */
 390 void
 391 control_event_bootstrap_reset(void)
 392 {
 393   bootstrap_percent = BOOTSTRAP_STATUS_UNDEF;
 394   bootstrap_phase = BOOTSTRAP_STATUS_UNDEF;
 395   notice_bootstrap_percent = 0;
 396   bootstrap_problems = 0;
 397   bootstrap_first_orconn = 0;
 398   bootstrap_dir_progress = BOOTSTRAP_STATUS_UNDEF;
 399   bootstrap_dir_phase = BOOTSTRAP_STATUS_UNDEF;
 400   memset(last_sent_bootstrap_message, 0, sizeof(last_sent_bootstrap_message));
 401 }