diff --git a/chrony.texi b/chrony.texi index 90bb260..54a4176 100644 --- a/chrony.texi +++ b/chrony.texi @@ -1751,6 +1751,10 @@ rate, and any slews made, to a file called tracking.log. @item rtc This option logs information about the system's real-time clock. + +@item refclocks +This option logs the raw reference clock measurements to a file +called refclocks.log. @end table The files are written to the directory specified by the logdir @@ -1767,6 +1771,7 @@ log measurements statistics tracking * statistics log:: The format of the statistics log * tracking log:: The format of the tracking log * RTC log:: The format of the RTC log +* refclocks log:: The format of the refclocks log @end menu @c }}} @c {{{ measurements.log @@ -1980,6 +1985,47 @@ The measurement interval used prior to the measurement being made (in seconds). [120] @end enumerate +A banner is periodically written to the log file to indicate the +meanings of the columns. +@c }}} +@c {{{ refclocks.log +@node refclocks log +@subsubsection Refclocks log file format + +An example line (which actually appears as a single line in the file) +from the refclocks log file is shown below. + +@example +2009-11-30 14:33:27.000000 PPS2 7 N 1 4.900000e-07 -6.741777e-07 +@end example + +The columns are as follows (the quantities in square brackets are the +values from the example line above) : + +@enumerate 1 +@item +Date [2009-11-30] +@item +Hour:Minute:Second.Microsecond [14:33:27.000000]. Note that the +date/time pair is expressed in UTC, not the local time zone. +@item +Reference ID of refclock from which measurement comes. [PPS2] +@item +Sequence number of driver poll within one polling interval. [7] +@item +Leap status (@code{N} means normal, @code{+} means that the last minute +of today has 61 seconds, @code{-} means that the last minute of the day +has 59 seconds). [N] +@item +Flag indicating whether the sample comes from PPS source. (1 for yes, +0 for no). [1] +@item +Local clock error measured by refclock driver. [4.900000e-07] +@item +Local clock error with applied corrections. Positive indicates +that the local clock is slow. [-6.741777e-07] +@end enumerate + A banner is periodically written to the log file to indicate the meanings of the columns. @c }}} diff --git a/cmdmon.c b/cmdmon.c index c8d22d5..5cbc89f 100644 --- a/cmdmon.c +++ b/cmdmon.c @@ -1458,6 +1458,7 @@ handle_cyclelogs(CMD_Request *rx_message, CMD_Reply *tx_message) SST_CycleLogFile(); REF_CycleLogFile(); RTC_CycleLogFile(); + RCL_CycleLogFile(); tx_message->status = htons(STT_SUCCESS); return; diff --git a/conf.c b/conf.c index 2d8a2c9..1c1b4f0 100644 --- a/conf.c +++ b/conf.c @@ -118,6 +118,7 @@ static int do_log_measurements = 0; static int do_log_statistics = 0; static int do_log_tracking = 0; static int do_log_rtc = 0; +static int do_log_refclocks = 0; static int do_dump_on_exit = 0; static char *logdir = "."; static char *dumpdir = "."; @@ -648,6 +649,9 @@ parse_log(const char *line) } else if (!strncmp(line, "rtc", 3)) { do_log_rtc = 1; line += 3; + } else if (!strncmp(line, "refclocks", 9)) { + do_log_refclocks = 1; + line += 9; } else { break; } @@ -1218,6 +1222,13 @@ CNF_GetLogRtc(void) return do_log_rtc; } +/* ================================================== */ +int +CNF_GetLogRefclocks(void) +{ + return do_log_refclocks; +} + /* ================================================== */ char * diff --git a/conf.h b/conf.h index 845502f..004bfcf 100644 --- a/conf.h +++ b/conf.h @@ -52,6 +52,7 @@ extern int CNF_GetLogMeasurements(void); extern int CNF_GetLogStatistics(void); extern int CNF_GetLogTracking(void); extern int CNF_GetLogRtc(void); +extern int CNF_GetLogRefclocks(void); extern char *CNF_GetKeysFile(void); extern char *CNF_GetRtcFile(void); extern unsigned long CNF_GetCommandKey(void); diff --git a/refclock.c b/refclock.c index d110def..15ab658 100644 --- a/refclock.c +++ b/refclock.c @@ -34,6 +34,7 @@ #include "sources.h" #include "logging.h" #include "sched.h" +#include "mkdirpp.h" /* list of refclock drivers */ extern RefclockDriver RCL_SHM_driver; @@ -75,11 +76,17 @@ struct RCL_Instance_Record { static struct RCL_Instance_Record refclocks[MAX_RCL_SOURCES]; static int n_sources = 0; +#define REFCLOCKS_LOG "refclocks.log" +static FILE *logfile = NULL; +static char *logfilename = NULL; +static unsigned long logwrites = 0; + static int valid_sample_time(RCL_Instance instance, struct timeval *tv); static int pps_stratum(RCL_Instance instance, struct timeval *tv); static void poll_timeout(void *arg); static void slew_samples(struct timeval *raw, struct timeval *cooked, double dfreq, double afreq, double doffset, int is_step_change, void *anything); +static void log_sample(RCL_Instance instance, struct timeval *sample_time, int pulse, double raw_offset, double cooked_offset); static void filter_init(struct MedianFilter *filter, int length); static void filter_fini(struct MedianFilter *filter); @@ -92,6 +99,18 @@ void RCL_Initialise(void) { CNF_AddRefclocks(); + + if (CNF_GetLogRefclocks()) { + char *logdir = CNF_GetLogDir(); + if (!mkdir_and_parents(logdir)) { + LOG(LOGS_ERR, LOGF_Refclock, "Could not create directory %s", logdir); + } else { + logfilename = MallocArray(char, 2 + strlen(logdir) + strlen(REFCLOCKS_LOG)); + strcpy(logfilename, logdir); + strcat(logfilename, "/"); + strcat(logfilename, REFCLOCKS_LOG); + } + } } void @@ -111,6 +130,10 @@ RCL_Finalise(void) if (n_sources > 0) LCL_RemoveParameterChangeHandler(slew_samples, NULL); + + if (logfile) + fclose(logfile); + Free(logfilename); } int @@ -262,6 +285,8 @@ RCL_AddSample(RCL_Instance instance, struct timeval *sample_time, double offset, filter_add_sample(&instance->filter, &cooked_time, offset - correction + instance->offset); instance->leap_status = leap_status; + log_sample(instance, &cooked_time, 0, offset, offset - correction + instance->offset); + return 1; } @@ -318,9 +343,21 @@ RCL_AddPulse(RCL_Instance instance, struct timeval *pulse_time, double second) filter_add_sample(&instance->filter, &cooked_time, offset); instance->leap_status = LEAP_Normal; + log_sample(instance, &cooked_time, 1, second, offset); + return 1; } +void +RCL_CycleLogFile(void) +{ + if (logfile) { + fclose(logfile); + logfile = NULL; + logwrites = 0; + } +} + static int valid_sample_time(RCL_Instance instance, struct timeval *tv) { @@ -426,6 +463,42 @@ slew_samples(struct timeval *raw, struct timeval *cooked, double dfreq, double a filter_slew_samples(&refclocks[i].filter, cooked, dfreq, doffset); } +static void +log_sample(RCL_Instance instance, struct timeval *sample_time, int pulse, double raw_offset, double cooked_offset) +{ + char sync_stats[4] = {'N', '+', '-', '?'}; + + if (!logfilename) + return; + + if (!logfile) { + logfile = fopen(logfilename, "a"); + if (!logfile) { + LOG(LOGS_WARN, LOGF_Refclock, "Couldn't open logfile %s for update", logfilename); + Free(logfilename); + logfilename = NULL; + return; + } + } + + if (((logwrites++) % 32) == 0) { + fprintf(logfile, + "====================================================================\n" + " Date (UTC) Time Refid DP L P Raw offset Cooked offset\n" + "====================================================================\n"); + } + fprintf(logfile, "%s.%06d %-5s %3d %1c %1d %13.6e %13.6e\n", + UTI_TimeToLogForm(sample_time->tv_sec), + (int)sample_time->tv_usec, + UTI_RefidToString(instance->ref_id), + instance->driver_polled, + sync_stats[instance->leap_status], + pulse, + raw_offset, + cooked_offset); + fflush(logfile); +} + static void filter_init(struct MedianFilter *filter, int length) { diff --git a/refclock.h b/refclock.h index 76dbe37..459cb86 100644 --- a/refclock.h +++ b/refclock.h @@ -57,6 +57,7 @@ extern int RCL_AddRefclock(RefclockParameters *params); extern void RCL_StartRefclocks(void); extern void RCL_StartRefclocks(void); extern void RCL_ReportSource(RPT_SourceReport *report, struct timeval *now); +extern void RCL_CycleLogFile(void); /* functions used by drivers */ extern void RCL_SetDriverData(RCL_Instance instance, void *data);