Add refclocks log

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 }}}

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;

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 *

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);

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)
 {

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);