sources: add selection log

Add an option to enable selection log, capturing some data from the
selectdata report.

conf.c

@@ -115,6 +115,7 @@ static int cmd_port = DEFAULT_CANDM_PORT;
 
 static int raw_measurements = 0;
 static int do_log_measurements = 0;
+static int do_log_selection = 0;
 static int do_log_statistics = 0;
 static int do_log_tracking = 0;
 static int do_log_rtc = 0;
@@ -1032,6 +1033,8 @@ parse_log(char *line)
         raw_measurements = 1;
       } else if (!strcmp(log_name, "measurements")) {
         do_log_measurements = 1;
+      } else if (!strcmp(log_name, "selection")) {
+        do_log_selection = 1;
       } else if (!strcmp(log_name, "statistics")) {
         do_log_statistics = 1;
       } else if (!strcmp(log_name, "tracking")) {
@@ -1929,6 +1932,14 @@ CNF_GetLogMeasurements(int *raw)
 
 /* ================================================== */
 
+int
+CNF_GetLogSelection(void)
+{
+  return do_log_selection;
+}
+
+/* ================================================== */
+
 int
 CNF_GetLogStatistics(void)
 {

conf.h

@@ -58,6 +58,7 @@ extern char *CNF_GetLogDir(void);
 extern char *CNF_GetDumpDir(void);
 extern int CNF_GetLogBanner(void);
 extern int CNF_GetLogMeasurements(int *raw);
+extern int CNF_GetLogSelection(void);
 extern int CNF_GetLogStatistics(void);
 extern int CNF_GetLogTracking(void);
 extern int CNF_GetLogRtc(void);

doc/chrony.conf.adoc

@@ -2144,6 +2144,71 @@ from the example line above):
   the source is more variable than the delay of packets sent from the source
   back. [0.00, i.e. no correction for asymmetry]
 +
+*selection*:::
+This option logs information about selection of sources for synchronisation to
+a file called _selection.log_. Note that the rate of entries written to this
+file grows quadratically with the number of specified sources (each measurement
+triggers the selection for all sources). An example line (which actually
+appears as a single line in the file) from the log file is shown below.
++
+----
+2022-05-01 02:01:20 203.0.113.15    * -----  377  1.00  \
+     4.228e+01 -1.575e-04  1.239e-04
+----
++
+The columns are as follows (the quantities in square brackets are the values
+from the example line above):
++
+. Date [2022-05-01]
+. Hour:Minute:Second. Note that the date-time pair is expressed in
+  UTC, not the local time zone. [02:01:20]
+. IP address or reference ID of the source. [203.0.113.15]
+. State of the source indicated with one of the following symbols. [*]
+{blank}::::
+Not considered selectable for synchronisation:
+* _N_ - has the *noselect* option.
+* _s_ - is not synchronised.
+* _M_ - does not have enough measurements.
+* _d_ - has a root distance larger than the maximum distance (configured by the
+        <<maxdistance,*maxdistance*>> directive).
+* _~_ - has a jitter larger than the maximum jitter (configured by the
+        <<maxjitter,*maxjitter*>> directive).
+* _w_ - waits for other sources to get out of the _M_ state.
+* _S_ - has older measurements than other sources.
+* _O_ - has a stratum equal or larger than the orphan stratum (configured by
+        the <<local,*local*>> directive).
+* _T_ - does not fully agree with sources that have the *trust* option.
+* _x_ - does not agree with other sources (falseticker).
+{blank}::::
+Considered selectable for synchronisation, but not currently used:
+* _W_ - waits for other sources to be selectable (required by the
+        <<minsources,*minsources*>> directive, or the *require* option of
+        another source).
+* _P_ - another selectable source is preferred due to the *prefer* option.
+* _U_ - waits for a new measurement (after selecting a different best source).
+* _D_ - has, or recently had, a root distance which is too large to be combined
+        with other sources (configured by the <<combinelimit,*combinelimit*>>
+        directive).
+{blank}::::
+Used for synchronisation of the local clock:
+* _+_ - combined with the best source.
+* _*_ - selected as the best source to update the reference data (e.g. root
+        delay, root dispersion).
+. Reachability register printed as an octal number. The register has 8 bits and
+  is updated on every received or missed packet from the source. A value of 377
+  indicates that a valid reply was received for all from the last eight
+  transmissions. [377]
+. Current score against the source in the _*_ state. The scoring system avoids
+  frequent reselection when multiple sources have a similar root distance. A
+  value larger than 1 indicates this source was better than the _*_ source in
+  recent selections. If the score reaches 10, the best source will be reselected
+  and the scores will be reset to 1. [1.00]
+. Interval since the last measurement of the source in seconds. [4.228e+01]
+. Lower endpoint of the interval which was expected to contain the true offset
+  of the local clock determined by the root distance of the source. [-1.575e-04]
+. Upper endpoint of the interval which was expected to contain the true offset
+  of the local clock determined by the root distance of the source. [1.239e-04]
++
 *tracking*:::
 This option logs changes to the estimate of the system's gain or loss rate, and
 any slews made, to a file called _tracking.log_. An example line (which

sources.c

@@ -178,6 +178,8 @@ static double reselect_distance;
 static double stratum_weight;
 static double combine_limit;
 
+static LOG_FileID logfileid;
+
 /* Identifier of the dump file */
 #define DUMP_IDENTIFIER "SRC0\n"
 
@@ -209,6 +211,10 @@ void SRC_Initialise(void) {
 
   LCL_AddParameterChangeHandler(slew_sources, NULL);
   LCL_AddDispersionNotifyHandler(add_dispersion, NULL);
+
+  logfileid = CNF_GetLogSelection() ? LOG_FileOpen("selection",
+              "   Date (UTC) Time     IP Address   S EOpts Reach Score Last sample  Low end   High end")
+              : -1;
 }
 
 /* ================================================== */
@@ -641,6 +647,8 @@ source_to_string(SRC_Instance inst)
 static void
 mark_source(SRC_Instance inst, SRC_Status status)
 {
+  struct timespec now;
+
   inst->status = status;
 
   DEBUG_LOG("%s status=%c options=%x reach=%o/%d updates=%d distant=%d leap=%d vote=%d lo=%f hi=%f",
@@ -649,6 +657,23 @@ mark_source(SRC_Instance inst, SRC_Status status)
             inst->reachability_size, inst->updates,
             inst->distant, (int)inst->leap, inst->leap_vote,
             inst->sel_info.lo_limit, inst->sel_info.hi_limit);
+
+  if (logfileid == -1)
+    return;
+
+  SCH_GetLastEventTime(&now, NULL, NULL);
+
+  LOG_FileWrite(logfileid,
+                "%s %-15s %c -%c%c%c%c %4o %5.2f %10.3e %10.3e %10.3e",
+                UTI_TimeToLogForm(now.tv_sec), source_to_string(inst),
+                get_status_char(inst->status),
+                inst->sel_options & SRC_SELECT_NOSELECT ? 'N' : '-',
+                inst->sel_options & SRC_SELECT_PREFER ? 'P' : '-',
+                inst->sel_options & SRC_SELECT_TRUST ? 'T' : '-',
+                inst->sel_options & SRC_SELECT_REQUIRE ? 'R' : '-',
+                (unsigned int)inst->reachability, inst->sel_score,
+                inst->sel_info.last_sample_ago,
+                inst->sel_info.lo_limit, inst->sel_info.hi_limit);
 }
 
 /* ================================================== */

test/simulation/134-log

@@ -11,7 +11,7 @@ client_server_options="maxpoll 6"
 client_conf="refclock PHC /dev/ptp0 dpoll 4 poll 6 noselect
 logbanner 10
 logdir tmp
-log tracking rawmeasurements measurements statistics rtc refclocks tempcomp
+log tracking rawmeasurements measurements selection statistics rtc refclocks tempcomp
 tempcomp tmp/tempcomp 64 0.0 0.0 0.0 0.0"
 
 echo 0.0 > tmp/tempcomp
@@ -26,6 +26,8 @@ check_file_messages "=============" 31 33 \
 	tracking.log measurements.log tempcomp.log || test_fail
 check_file_messages "20.*192\.168\.123\.1" 150 160 \
 	tracking.log measurements.log statistics.log || test_fail
+check_file_messages "20.*PHC0 * N " 300 320 selection.log || test_fail
+check_file_messages "20.*192\.168\.123\.1 *[M*]" 300 320 selection.log || test_fail
 check_file_messages "20.*PHC0" 150 160 statistics.log || test_fail
 check_file_messages "20.*PHC0" 750 800 refclocks.log || test_fail
 check_file_messages "20.* 0\.0000" 150 160 tempcomp.log || test_fail