Merge branch 'from_setconf_removal_squashed'

changes/ticket31999

@@ -0,0 +1,6 @@
+  o Code simplification and refactoring:
+    - Our default log (which ordinarily sends NOTICE-level message to
+      standard output) is now handled in a more logical manner. Previously,
+      we replaced the configured log options if they were empty.
+      Now, we interpret an empty set of log options as meaning "use the
+      default log". Closes ticket 31999.

src/app/config/config.c

@@ -836,8 +836,6 @@ static int check_server_ports(const smartlist_t *ports,
 static int validate_data_directories(or_options_t *options);
 static int write_configuration_file(const char *fname,
                                     const or_options_t *options);
-static int options_init_logs(const or_options_t *old_options,
-                             or_options_t *options, int validate_only);
 
 static void init_libevent(const or_options_t *options);
 static int opt_streq(const char *s1, const char *s2);
@@ -3429,20 +3427,17 @@ options_validate_single_onion(or_options_t *options, char **msg)
  * normalizing the contents of <b>options</b>.
  *
  * On error, tor_strdup an error explanation into *<b>msg</b>.
- *
- * XXX
- * If <b>from_setconf</b>, we were called by the controller, and our
- * Log line should stay empty. If it's 0, then give us a default log
- * if there are no logs defined.
  */
 STATIC int
 options_validate(or_options_t *old_options, or_options_t *options,
-                 or_options_t *default_options, int from_setconf, char **msg)
+                 or_options_t *default_options, int from_setconf_unused,
+                 char **msg)
 {
   config_line_t *cl;
   const char *uname = get_uname();
   int n_ports=0;
   int world_writable_control_socket=0;
+  (void)from_setconf_unused; /* 29211 TODO: Remove this from the API. */
 
   tor_assert(msg);
   *msg = NULL;
@@ -3505,14 +3500,6 @@ options_validate(or_options_t *old_options, or_options_t *options,
 
   check_network_configuration(server_mode(options));
 
-  /* Special case on first boot if no Log options are given. */
-  if (!options->Logs && !options->RunAsDaemon && !from_setconf) {
-    if (quiet_level == 0)
-      config_line_append(&options->Logs, "Log", "notice stdout");
-    else if (quiet_level == 1)
-      config_line_append(&options->Logs, "Log", "warn stdout");
-  }
-
   /* Validate the tor_log(s) */
   if (options_init_logs(old_options, options, 1)<0)
     REJECT("Failed to validate Log options. See logs for details.");
@@ -5686,22 +5673,14 @@ open_and_add_file_log(const log_severity_list_t *severity,
 }
 
 /**
- * Initialize the logs based on the configuration file.
+ * Try to set our global log granularity from `options->LogGranularity`,
- */
+ * adjusting it as needed so that we are an even divisor of a second, or an
+ * even multiple of seconds. Return 0 on success, -1 on failure.
+ **/
 static int
-options_init_logs(const or_options_t *old_options, or_options_t *options,
+options_init_log_granularity(const or_options_t *options,
-                  int validate_only)
+                             int validate_only)
 {
-  config_line_t *opt;
-  int ok;
-  smartlist_t *elts;
-  int run_as_daemon =
-#ifdef _WIN32
-               0;
-#else
-               options->RunAsDaemon;
-#endif
-
   if (options->LogTimeGranularity <= 0) {
     log_warn(LD_CONFIG, "Log time granularity '%d' has to be positive.",
              options->LogTimeGranularity);
@@ -5731,9 +5710,38 @@ options_init_logs(const or_options_t *old_options, or_options_t *options,
       set_log_time_granularity(options->LogTimeGranularity);
   }
 
+  return 0;
+}
+
+/**
+ * Initialize the logs based on the configuration file.
+ */
+STATIC int
+options_init_logs(const or_options_t *old_options, or_options_t *options,
+                  int validate_only)
+{
+  config_line_t *opt;
+  int ok;
+  smartlist_t *elts;
+  int run_as_daemon =
+#ifdef _WIN32
+               0;
+#else
+               options->RunAsDaemon;
+#endif
+
+  if (options_init_log_granularity(options, validate_only) < 0)
+    return -1;
+
   ok = 1;
   elts = smartlist_new();
 
+  if (options->Logs == NULL && !run_as_daemon && !validate_only) {
+    /* When no logs are given, the default behavior is to log nothing (if
+       RunAsDaemon is set) or to log based on the quiet level otherwise. */
+    add_default_log_for_quiet_level(quiet_level);
+  }
+
   for (opt = options->Logs; opt; opt = opt->next) {
     log_severity_list_t *severity;
     const char *cfg = opt->value;

src/app/config/config.h

@@ -309,6 +309,8 @@ STATIC uint64_t compute_real_max_mem_in_queues(const uint64_t val,
 STATIC int open_and_add_file_log(const log_severity_list_t *severity,
                                  const char *fname,
                                  int truncate_log);
+STATIC int options_init_logs(const or_options_t *old_options,
+                             or_options_t *options, int validate_only);
 
 #endif /* defined(CONFIG_PRIVATE) */
 

src/app/config/quiet_level.c

@@ -0,0 +1,33 @@
+/* Copyright (c) 2001 Matej Pfajfar.
+ * Copyright (c) 2001-2004, Roger Dingledine.
+ * Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson.
+ * Copyright (c) 2007-2019, The Tor Project, Inc. */
+/* See LICENSE for licensing information */
+
+#include "orconfig.h"
+#include "lib/log/log.h"
+#include "app/config/quiet_level.h"
+
+/** Decides our behavior when no logs are configured/before any logs have been
+ * configured.  For QUIET_NONE, we log notice to stdout as normal.  For
+ * QUIET_HUSH, we log warnings only.  For QUIET_SILENT, we log nothing.
+ */
+quiet_level_t quiet_level = 0;
+
+/** Add a default log (or not), depending on the value of <b>quiet</b>. */
+void
+add_default_log_for_quiet_level(quiet_level_t quiet)
+{
+  switch (quiet) {
+    case QUIET_SILENT:
+      /* --quiet: no initial logging */
+      return;
+    case QUIET_HUSH:
+    /* --hush: log at warning or higher. */
+      add_default_log(LOG_WARN);
+      break;
+    case QUIET_NONE: /* fall through */
+    default:
+      add_default_log(LOG_NOTICE);
+  }
+}

src/app/config/quiet_level.h

@@ -25,4 +25,6 @@ typedef enum {
 /** How quietly should Tor log at startup? */
 extern quiet_level_t quiet_level;
 
+void add_default_log_for_quiet_level(quiet_level_t quiet);
+
 #endif /* !defined(QUIET_LEVEL_H) */

src/app/main/main.c

@@ -109,16 +109,6 @@ static void dumpmemusage(int severity);
 static void dumpstats(int severity); /* log stats */
 static void process_signal(int sig);
 
-/********* START VARIABLES **********/
-
-/** Decides our behavior when no logs are configured/before any logs have been
- * configured.  For QUIET_NONE, we log notice to stdout as normal.  For
- * QUIET_HUSH, we log warnings only.  For QUIET_SILENT, we log nothing.
- */
-quiet_level_t quiet_level = 0;
-
-/********* END VARIABLES ************/
-
 /** Called when we get a SIGHUP: reload configuration files and keys,
  * retry all connections, and so on. */
 static int
@@ -558,18 +548,7 @@ tor_init(int argc, char *argv[])
   }
 
  /* give it somewhere to log to initially */
-  switch (quiet) {
+  add_default_log_for_quiet_level(quiet);
-    case QUIET_SILENT:
-      /* --quiet: no initial logging */
-      break;
-    case QUIET_HUSH:
-      /* --hush: log at warning or higher. */
-      add_temp_log(LOG_WARN);
-      break;
-    case QUIET_NONE: /* fall through */
-    default:
-      add_temp_log(LOG_NOTICE);
-  }
   quiet_level = quiet;
 
   {

src/core/include.am

@@ -9,6 +9,7 @@ endif
 # ADD_C_FILE: INSERT SOURCES HERE.
 LIBTOR_APP_A_SOURCES = 				\
 	src/app/config/config.c			\
+	src/app/config/quiet_level.c		\
 	src/app/config/statefile.c		\
 	src/app/main/main.c			\
 	src/app/main/shutdown.c			\

src/lib/log/log.c

@@ -276,8 +276,8 @@ static int log_time_granularity = 1;
 
 /** Define log time granularity for all logs to be <b>granularity_msec</b>
  * milliseconds. */
-void
+MOCK_IMPL(void,
-set_log_time_granularity(int granularity_msec)
+set_log_time_granularity,(int granularity_msec))
 {
   log_time_granularity = granularity_msec;
   tor_log_sigsafe_err_set_granularity(granularity_msec);
@@ -937,9 +937,9 @@ set_log_severity_config(int loglevelMin, int loglevelMax,
 
 /** Add a log handler named <b>name</b> to send all messages in <b>severity</b>
  * to <b>fd</b>. Copies <b>severity</b>. Helper: does no locking. */
-static void
+MOCK_IMPL(STATIC void,
-add_stream_log_impl(const log_severity_list_t *severity,
+add_stream_log_impl,(const log_severity_list_t *severity,
-                    const char *name, int fd)
+                     const char *name, int fd))
 {
   logfile_t *lf;
   lf = tor_malloc_zero(sizeof(logfile_t));
@@ -995,18 +995,16 @@ logs_set_domain_logging(int enabled)
   UNLOCK_LOGS();
 }
 
-/** Add a log handler to receive messages during startup (before the real
+/** Add a log handler to accept messages when no other log is configured.
- * logs are initialized).
  */
 void
-add_temp_log(int min_severity)
+add_default_log(int min_severity)
 {
   log_severity_list_t *s = tor_malloc_zero(sizeof(log_severity_list_t));
   set_log_severity_config(min_severity, LOG_ERR, s);
   LOCK_LOGS();
-  add_stream_log_impl(s, "<temp>", fileno(stdout));
+  add_stream_log_impl(s, "<default>", fileno(stdout));
   tor_free(s);
-  logfiles->is_temporary = 1;
   UNLOCK_LOGS();
 }
 
@@ -1149,8 +1147,7 @@ flush_log_messages_from_startup(void)
   UNLOCK_LOGS();
 }
 
-/** Close any log handlers added by add_temp_log() or marked by
+/** Close any log handlers marked by mark_logs_temp(). */
- * mark_logs_temp(). */
 void
 close_temp_logs(void)
 {
@@ -1202,10 +1199,10 @@ mark_logs_temp(void)
  * opening the logfile failed, -1 is returned and errno is set appropriately
  * (by open(2)).  Takes ownership of fd.
  */
-int
+MOCK_IMPL(int,
-add_file_log(const log_severity_list_t *severity,
+add_file_log,(const log_severity_list_t *severity,
-             const char *filename,
+              const char *filename,
-             int fd)
+              int fd))
 {
   logfile_t *lf;
 

src/lib/log/log.h

@@ -163,11 +163,11 @@ int parse_log_severity_config(const char **cfg,
                               log_severity_list_t *severity_out);
 void set_log_severity_config(int minSeverity, int maxSeverity,
                              log_severity_list_t *severity_out);
-void add_stream_log(const log_severity_list_t *severity, const char *name,
+void add_stream_log(const log_severity_list_t *severity,
-                    int fd);
+                    const char *name, int fd);
-int add_file_log(const log_severity_list_t *severity,
+MOCK_DECL(int, add_file_log,(const log_severity_list_t *severity,
-                 const char *filename,
+                             const char *filename,
-                 int fd);
+                             int fd));
 
 #ifdef HAVE_SYSLOG_H
 int add_syslog_log(const log_severity_list_t *severity,
@@ -185,7 +185,7 @@ int get_min_log_level(void);
 void switch_logs_debug(void);
 void logs_free_all(void);
 void logs_close_sigsafe(void);
-void add_temp_log(int min_severity);
+void add_default_log(int min_severity);
 void close_temp_logs(void);
 void rollback_log_changes(void);
 void mark_logs_temp(void);
@@ -194,7 +194,7 @@ void change_callback_log_severity(int loglevelMin, int loglevelMax,
 void flush_pending_log_callbacks(void);
 void flush_log_messages_from_startup(void);
 void log_set_application_name(const char *name);
-void set_log_time_granularity(int granularity_msec);
+MOCK_DECL(void, set_log_time_granularity,(int granularity_msec));
 void truncate_logs(void);
 
 void tor_log(int severity, log_domain_mask_t domain, const char *format, ...)
@@ -306,6 +306,8 @@ extern const log_domain_mask_t LD_GENERAL_;
 MOCK_DECL(STATIC void, logv, (int severity, log_domain_mask_t domain,
     const char *funcname, const char *suffix, const char *format,
     va_list ap) CHECK_PRINTF(5,0));
+MOCK_DECL(STATIC void, add_stream_log_impl,(
+         const log_severity_list_t *severity, const char *name, int fd));
 #endif
 
 #if defined(LOG_PRIVATE) || defined(TOR_UNIT_TESTS)

src/test/test_options.c

@@ -4,6 +4,7 @@
 /* See LICENSE for licensing information */
 
 #define CONFIG_PRIVATE
+#define LOG_PRIVATE
 #include "core/or/or.h"
 #include "lib/confmgt/confparse.h"
 #include "app/config/config.h"
@@ -678,8 +679,7 @@ test_options_validate__logs(void *ignored)
   tdata->opt->RunAsDaemon = 0;
 
   ret = options_validate(tdata->old_opt, tdata->opt, tdata->def_opt, 0, &msg);
-  tt_str_op(tdata->opt->Logs->key, OP_EQ, "Log");
+  tt_assert(!tdata->opt->Logs);
-  tt_str_op(tdata->opt->Logs->value, OP_EQ, "notice stdout");
   tor_free(msg);
   tt_int_op(ret, OP_EQ, -1);
 
@@ -689,8 +689,7 @@ test_options_validate__logs(void *ignored)
   tdata->opt->RunAsDaemon = 0;
   quiet_level = 1;
   ret = options_validate(tdata->old_opt, tdata->opt, tdata->def_opt, 0, &msg);
-  tt_str_op(tdata->opt->Logs->key, OP_EQ, "Log");
+  tt_assert(!tdata->opt->Logs);
-  tt_str_op(tdata->opt->Logs->value, OP_EQ, "warn stdout");
   tor_free(msg);
   tt_int_op(ret, OP_EQ, -1);
 
@@ -4166,6 +4165,191 @@ test_options_validate__accel(void *ignored)
   tor_free(msg);
 }
 
+static int mocked_granularity;
+
+static void
+mock_set_log_time_granularity(int g)
+{
+  mocked_granularity = g;
+}
+
+static void
+test_options_init_logs_granularity(void *arg)
+{
+  options_test_data_t *tdata = get_options_test_data("");
+  int rv;
+  (void) arg;
+
+  MOCK(set_log_time_granularity, mock_set_log_time_granularity);
+
+  /* Reasonable value. */
+  tdata->opt->LogTimeGranularity = 100;
+  mocked_granularity = -1;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(mocked_granularity, OP_EQ, 100);
+
+  /* Doesn't divide 1000. */
+  tdata->opt->LogTimeGranularity = 249;
+  mocked_granularity = -1;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(mocked_granularity, OP_EQ, 250);
+
+  /* Doesn't divide 1000. */
+  tdata->opt->LogTimeGranularity = 3;
+  mocked_granularity = -1;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(mocked_granularity, OP_EQ, 4);
+
+  /* Not a multiple of 1000. */
+  tdata->opt->LogTimeGranularity = 1500;
+  mocked_granularity = -1;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(mocked_granularity, OP_EQ, 2000);
+
+  /* Reasonable value. */
+  tdata->opt->LogTimeGranularity = 3000;
+  mocked_granularity = -1;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(mocked_granularity, OP_EQ, 3000);
+
+  /* Negative. (Shouldn't be allowed by rest of config parsing.) */
+  tdata->opt->LogTimeGranularity = -1;
+  mocked_granularity = -1;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, -1);
+
+  /* Very big */
+  tdata->opt->LogTimeGranularity = 3600 * 1000;
+  mocked_granularity = -1;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(mocked_granularity, OP_EQ, 3600 * 1000);
+
+ done:
+  free_options_test_data(tdata);
+  UNMOCK(set_log_time_granularity);
+}
+
+typedef struct {
+  char *name;
+  log_severity_list_t sev;
+  int fd;
+  bool stream;
+} added_log_t;
+
+static smartlist_t *added_logs = NULL;
+
+static void
+mock_add_stream_log_impl(const log_severity_list_t *sev, const char *name,
+                         int fd)
+{
+  added_log_t *a = tor_malloc_zero(sizeof(added_log_t));
+  a->name = tor_strdup(name);
+  memcpy(&a->sev, sev, sizeof(log_severity_list_t));
+  a->fd = fd;
+  a->stream = true;
+  smartlist_add(added_logs, a);
+}
+
+static int
+mock_add_file_log(const log_severity_list_t *sev, const char *name, int fd)
+{
+  added_log_t *a = tor_malloc_zero(sizeof(added_log_t));
+  a->name = tor_strdup(name);
+  memcpy(&a->sev, sev, sizeof(log_severity_list_t));
+  a->fd = fd;
+  smartlist_add(added_logs, a);
+  return 0;
+}
+
+static void
+clear_added_logs(void)
+{
+  SMARTLIST_FOREACH(added_logs, added_log_t *, a,
+                    { tor_free(a->name); tor_free(a); });
+  smartlist_clear(added_logs);
+}
+
+static void
+test_options_init_logs_quiet(void *arg)
+{
+  (void)arg;
+  char *cfg = NULL;
+  options_test_data_t *tdata = get_options_test_data("");
+  char *fn1 = tor_strdup(get_fname_rnd("log"));
+  const added_log_t *a;
+  int rv;
+  tdata->opt->RunAsDaemon = 0;
+
+  added_logs = smartlist_new();
+  MOCK(add_stream_log_impl, mock_add_stream_log_impl);
+  MOCK(add_file_log, mock_add_file_log);
+
+  tt_ptr_op(tdata->opt->Logs, OP_EQ, NULL);
+
+  /* First, try with no configured logs, and make sure that our configured
+     logs match the quiet level. */
+  quiet_level = QUIET_SILENT;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(smartlist_len(added_logs), OP_EQ, 0);
+
+  quiet_level = QUIET_HUSH;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(smartlist_len(added_logs), OP_EQ, 1);
+  a = smartlist_get(added_logs, 0);
+  tt_assert(a);
+  tt_assert(a->stream);
+  tt_int_op(a->fd, OP_EQ, fileno(stdout));
+  tt_int_op(a->sev.masks[LOG_INFO-LOG_ERR], OP_EQ, 0);
+  tt_int_op(a->sev.masks[LOG_NOTICE-LOG_ERR], OP_EQ, 0);
+  tt_int_op(a->sev.masks[LOG_WARN-LOG_ERR], OP_EQ, LD_ALL_DOMAINS);
+  clear_added_logs();
+
+  quiet_level = QUIET_NONE;
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(smartlist_len(added_logs), OP_EQ, 1);
+  a = smartlist_get(added_logs, 0);
+  tt_assert(a);
+  tt_assert(a->stream);
+  tt_int_op(a->fd, OP_EQ, fileno(stdout));
+  tt_int_op(a->sev.masks[LOG_INFO-LOG_ERR], OP_EQ, 0);
+  tt_int_op(a->sev.masks[LOG_NOTICE-LOG_ERR], OP_EQ, LD_ALL_DOMAINS);
+  tt_int_op(a->sev.masks[LOG_WARN-LOG_ERR], OP_EQ, LD_ALL_DOMAINS);
+  clear_added_logs();
+
+  /* Make sure that adding a configured log makes the default logs go away. */
+  tor_asprintf(&cfg, "Log info file %s\n", fn1);
+  free_options_test_data(tdata);
+  tdata = get_options_test_data(cfg);
+  rv = options_init_logs(NULL, tdata->opt, 0);
+  tt_int_op(rv, OP_EQ, 0);
+  tt_int_op(smartlist_len(added_logs), OP_EQ, 1);
+  a = smartlist_get(added_logs, 0);
+  tt_assert(a);
+  tt_assert(! a->stream);
+  tt_int_op(a->fd, OP_NE, fileno(stdout));
+  tt_int_op(a->sev.masks[LOG_INFO-LOG_ERR], OP_EQ, LD_ALL_DOMAINS);
+  tt_int_op(a->sev.masks[LOG_NOTICE-LOG_ERR], OP_EQ, LD_ALL_DOMAINS);
+  tt_int_op(a->sev.masks[LOG_WARN-LOG_ERR], OP_EQ, LD_ALL_DOMAINS);
+
+ done:
+  free_options_test_data(tdata);
+  tor_free(fn1);
+  tor_free(cfg);
+  clear_added_logs();
+  smartlist_free(added_logs);
+  UNMOCK(add_stream_log_impl);
+  UNMOCK(add_file_log);
+}
+
 #define LOCAL_VALIDATE_TEST(name) \
   { "validate__" #name, test_options_validate__ ## name, TT_FORK, NULL, NULL }
 
@@ -4213,5 +4397,9 @@ struct testcase_t options_tests[] = {
   LOCAL_VALIDATE_TEST(virtual_addr),
   LOCAL_VALIDATE_TEST(testing_options),
   LOCAL_VALIDATE_TEST(accel),
+  { "init_logs/granularity", test_options_init_logs_granularity, TT_FORK,
+    NULL, NULL },
+  { "init_logs/quiet", test_options_init_logs_quiet, TT_FORK,
+    NULL, NULL },
   END_OF_TESTCASES              /*  */
 };

src/test/testing_common.c

@@ -272,6 +272,9 @@ main(int c, const char **v)
 
   control_initialize_event_queue();
 
+  /* Don't add default logs; the tests manage their own. */
+  quiet_level = QUIET_SILENT;
+
   for (i_out = i = 1; i < c; ++i) {
     if (!strcmp(v[i], "--warn")) {
       loglevel = LOG_WARN;