hs-v3: Log reasons why service can't upload descriptor

When a service can not upload its descriptor(s), we have no logs on why. This
adds logging for each possible reason for each descriptors.

That logging is emitted every second so it is rate limited for each reason and
per descriptor.

Closes #33400

Signed-off-by: David Goulet <dgoulet@torproject.org>

1 files changed, 165 insertions, 0 deletions

diff --git a/src/test/test_hs_service.c b/src/test/test_hs_service.c
index 685f4c25a7..9966bd108d 100644
--- a/src/test/test_hs_service.c
+++ b/src/test/test_hs_service.c
@@ -89,6 +89,13 @@ mock_networkstatus_get_live_consensus(time_t now)
   return &mock_ns;
 }
 
+static networkstatus_t *
+mock_networkstatus_get_live_consensus_null(time_t now)
+{
+  (void) now;
+  return NULL;
+}
+
 static or_state_t *dummy_state = NULL;
 
 /* Mock function to get fake or state (used for rev counters) */
@@ -136,6 +143,20 @@ mock_relay_send_command_from_edge(streamid_t stream_id, circuit_t *circ,
   return 0;
 }
 
+static unsigned int num_intro_points = 0;
+static unsigned int
+mock_count_desc_circuit_established(const hs_service_descriptor_t *desc)
+{
+  (void) desc;
+  return num_intro_points;
+}
+
+static int
+mock_router_have_minimum_dir_info_false(void)
+{
+  return 0;
+}
+
 /* Helper: from a set of options in conf, configure a service which will add
  * it to the staging list of the HS subsytem. */
 static int
@@ -2520,6 +2541,148 @@ test_intro2_handling(void *arg)
   UNMOCK(launch_rendezvous_point_circuit);
 }
 
+static void
+test_cannot_upload_descriptors(void *arg)
+{
+  int ret;
+  time_t now;
+  hs_service_t *service;
+
+  (void) arg;
+
+  hs_init();
+  MOCK(get_or_state,
+       get_or_state_replacement);
+  MOCK(networkstatus_get_live_consensus,
+       mock_networkstatus_get_live_consensus);
+
+  dummy_state = or_state_new();
+
+  ret = parse_rfc1123_time("Sat, 26 Oct 1985 13:00:00 UTC",
+                           &mock_ns.valid_after);
+  tt_int_op(ret, OP_EQ, 0);
+  ret = parse_rfc1123_time("Sat, 26 Oct 1985 14:00:00 UTC",
+                           &mock_ns.fresh_until);
+  tt_int_op(ret, OP_EQ, 0);
+  dirauth_sched_recalculate_timing(get_options(), mock_ns.valid_after);
+
+  update_approx_time(mock_ns.valid_after + 1);
+  now = mock_ns.valid_after + 1;
+
+  /* Create a service with no descriptor. It's added to the global map. */
+  service = hs_service_new(get_options());
+  tt_assert(service);
+  service->config.version = HS_VERSION_THREE;
+  ed25519_secret_key_generate(&service->keys.identity_sk, 0);
+  ed25519_public_key_generate(&service->keys.identity_pk,
+                              &service->keys.identity_sk);
+  /* Register service to global map. */
+  ret = register_service(get_hs_service_map(), service);
+  tt_int_op(ret, OP_EQ, 0);
+  /* But first, build our descriptor. */
+  build_all_descriptors(now);
+
+  /* 1. Testing missing intro points reason. */
+  {
+    digest256map_t *cur = service->desc_current->intro_points.map;
+    digest256map_t *tmp = digest256map_new();
+    service->desc_current->intro_points.map = tmp;
+    service->desc_current->missing_intro_points = 1;
+    setup_full_capture_of_logs(LOG_INFO);
+    run_upload_descriptor_event(now);
+    digest256map_free(tmp, tor_free_);
+    service->desc_current->intro_points.map = cur;
+    expect_log_msg_containing(
+      "Service [scrubbed] can't upload its current descriptor: "
+      "Missing intro points");
+    teardown_capture_of_logs();
+    /* Reset. */
+    service->desc_current->missing_intro_points = 0;
+  }
+
+  /* 2. Testing non established intro points. */
+  {
+    setup_full_capture_of_logs(LOG_INFO);
+    run_upload_descriptor_event(now);
+    expect_log_msg_containing(
+      "Service [scrubbed] can't upload its current descriptor: "
+      "Intro circuits aren't yet all established (0/3).");
+    teardown_capture_of_logs();
+  }
+
+  /* We need to pass the established circuit tests and thus from now on, we
+   * MOCK this to return 3 intro points. */
+  MOCK(count_desc_circuit_established, mock_count_desc_circuit_established);
+  num_intro_points = 3;
+
+  /* 3. Testing non established intro points. */
+  {
+    service->desc_current->next_upload_time = now + 1000;
+    setup_full_capture_of_logs(LOG_INFO);
+    run_upload_descriptor_event(now);
+    expect_log_msg_containing(
+      "Service [scrubbed] can't upload its current descriptor: "
+      "Next upload time is");
+    teardown_capture_of_logs();
+    /* Reset. */
+    service->desc_current->next_upload_time = 0;
+  }
+
+  /* 4. Testing missing live consensus. */
+  {
+    MOCK(networkstatus_get_live_consensus,
+         mock_networkstatus_get_live_consensus_null);
+    setup_full_capture_of_logs(LOG_INFO);
+    run_upload_descriptor_event(now);
+    expect_log_msg_containing(
+      "Service [scrubbed] can't upload its current descriptor: "
+      "No live consensus");
+    teardown_capture_of_logs();
+    /* Reset. */
+    MOCK(networkstatus_get_live_consensus,
+         mock_networkstatus_get_live_consensus);
+  }
+
+  /* 5. Test missing minimum directory information. */
+  {
+    MOCK(router_have_minimum_dir_info,
+         mock_router_have_minimum_dir_info_false);
+    setup_full_capture_of_logs(LOG_INFO);
+    run_upload_descriptor_event(now);
+    expect_log_msg_containing(
+      "Service [scrubbed] can't upload its current descriptor: "
+      "Not enough directory information");
+    teardown_capture_of_logs();
+
+    /* Running it again shouldn't trigger anything due to rate limitation. */
+    setup_full_capture_of_logs(LOG_INFO);
+    run_upload_descriptor_event(now);
+    expect_no_log_entry();
+    teardown_capture_of_logs();
+    UNMOCK(router_have_minimum_dir_info);
+  }
+
+  /* Increase time and redo test (5) in order to test the rate limiting. */
+  update_approx_time(mock_ns.valid_after + 61);
+  {
+    MOCK(router_have_minimum_dir_info,
+         mock_router_have_minimum_dir_info_false);
+    setup_full_capture_of_logs(LOG_INFO);
+    run_upload_descriptor_event(now);
+    expect_log_msg_containing(
+      "Service [scrubbed] can't upload its current descriptor: "
+      "Not enough directory information");
+    teardown_capture_of_logs();
+    UNMOCK(router_have_minimum_dir_info);
+  }
+
+ done:
+  hs_free_all();
+  UNMOCK(count_desc_circuit_established);
+  UNMOCK(networkstatus_get_live_consensus);
+  UNMOCK(get_or_state);
+}
+
 struct testcase_t hs_service_tests[] = {
   { "e2e_rend_circuit_setup", test_e2e_rend_circuit_setup, TT_FORK,
     NULL, NULL },
@@ -2557,6 +2720,8 @@ struct testcase_t hs_service_tests[] = {
     NULL, NULL },
   { "upload_descriptors", test_upload_descriptors, TT_FORK,
     NULL, NULL },
+  { "cannot_upload_descriptors", test_cannot_upload_descriptors, TT_FORK,
+    NULL, NULL },
   { "rendezvous1_parsing", test_rendezvous1_parsing, TT_FORK,
     NULL, NULL },
   { "authorized_client_config_equal", test_authorized_client_config_equal,