diff --git a/conf.c b/conf.c index 199b63c..8dd2743 100644 --- a/conf.c +++ b/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) { diff --git a/conf.h b/conf.h index f81f9aa..11fd11d 100644 --- a/conf.h +++ b/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); diff --git a/doc/chrony.conf.adoc b/doc/chrony.conf.adoc index fdd8499..70e27d4 100644 --- a/doc/chrony.conf.adoc +++ b/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 + <> directive). +* _~_ - has a jitter larger than the maximum jitter (configured by the + <> 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 <> 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 + <> 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 <> + 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 diff --git a/sources.c b/sources.c index d7fc0a6..2aee6f2 100644 --- a/sources.c +++ b/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); } /* ================================================== */ diff --git a/test/simulation/134-log b/test/simulation/134-log index c7a3433..ab1ced2 100755 --- a/test/simulation/134-log +++ b/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