Convert TRACEON LOG messages to DEBUG_LOG

configure

@@ -114,7 +114,6 @@ For better control, use the options below.
   --disable-linuxcaps    Disable Linux capabilities support
   --disable-forcednsretry Don't retry on permanent DNS error
   --with-sendmail=PATH   Path to sendmail binary [/usr/lib/sendmail]
-  --enable-trace         Enable tracing
   --enable-debug         Enable debugging support
 
 Fine tuning of the installation directories:
@@ -197,9 +196,6 @@ mail_program="/usr/lib/sendmail"
 for option
 do
     case "$option" in
-    --enable-trace )
-      add_def TRACEON
-    ;;
     --enable-debug )
       debug=1
     ;;

local.c

@@ -510,10 +510,8 @@ LCL_AccumulateFrequencyAndOffset(double dfreq, double doffset, double corr_rate)
    terms of the gradient of the (offset) v (local time) function. */
   current_freq_ppm = (1.0 + dfreq) * old_freq_ppm + 1.0e6 * dfreq;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Local, "old_freq=%.3fppm new_freq=%.3fppm offset=%.6fsec",
-  LOG(LOGS_INFO, LOGF_Local, "old_freq=%.3fppm new_freq=%.3fppm offset=%.6fsec",
       old_freq_ppm, current_freq_ppm, doffset);
-#endif
 
   /* Call the system-specific driver for setting the frequency */
   current_freq_ppm = (*drv_set_freq)(current_freq_ppm);
@@ -561,9 +559,7 @@ lcl_RegisterSystemDrivers(lcl_ReadFrequencyDriver read_freq,
 
   current_freq_ppm = (*drv_read_freq)();
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Local, "Local freq=%.3fppm", current_freq_ppm);
-  LOG(LOGS_INFO, LOGF_Local, "Local freq=%.3fppm", current_freq_ppm);
-#endif
 }
 
 /* ================================================== */

ntp_core.c

@@ -686,10 +686,8 @@ transmit_timeout(void *arg)
     return;
   }
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_NtpCore, "Transmit timeout for [%s:%d]",
-  LOG(LOGS_INFO, LOGF_NtpCore, "Transmit timeout for [%s:%d]",
       UTI_IPToString(&inst->remote_addr.ip_addr), inst->remote_addr.port);
-#endif
 
   /* Check whether we need to 'warm up' the link to the other end by
      sending an echo exchange to ensure both ends' ARP caches are
@@ -1080,37 +1078,35 @@ receive_packet(NTP_Packet *message, struct timeval *now, double now_err, NCR_Ins
   root_delay = pkt_root_delay + fabs(delta);
   root_dispersion = pkt_root_dispersion + epsilon;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_NtpCore, "lvm=%o stratum=%d poll=%d prec=%d",
-  LOG(LOGS_INFO, LOGF_NtpCore, "lvm=%o stratum=%d poll=%d prec=%d",
       message->lvm, message->stratum, message->poll, message->precision);
-  LOG(LOGS_INFO, LOGF_NtpCore, "Root delay=%08x (%f), dispersion=%08x (%f)",
+  DEBUG_LOG(LOGF_NtpCore, "Root delay=%08x (%f), dispersion=%08x (%f)",
       message->root_delay, pkt_root_delay, message->root_dispersion, pkt_root_dispersion);
-  LOG(LOGS_INFO, LOGF_NtpCore, "Ref id=[%x], ref_time=%08x.%08x [%s]",
+  DEBUG_LOG(LOGF_NtpCore, "Ref id=[%x], ref_time=%08x.%08x [%s]",
       ntohl(message->reference_id),
       message->reference_ts.hi, message->reference_ts.lo,
       UTI_TimestampToString(&message->reference_ts));
-  LOG(LOGS_INFO, LOGF_NtpCore, "Originate=%08x.%08x [%s]",
+  DEBUG_LOG(LOGF_NtpCore, "Originate=%08x.%08x [%s]",
       message->originate_ts.hi, message->originate_ts.lo,
       UTI_TimestampToString(&message->originate_ts));
-  LOG(LOGS_INFO, LOGF_NtpCore, "Message receive=%08x.%08x [%s]",
+  DEBUG_LOG(LOGF_NtpCore, "Message receive=%08x.%08x [%s]",
       message->receive_ts.hi, message->receive_ts.lo,
       UTI_TimestampToString(&message->receive_ts));
 
-  LOG(LOGS_INFO, LOGF_NtpCore, "Transmit=%08x.%08x [%s]",
+  DEBUG_LOG(LOGF_NtpCore, "Transmit=%08x.%08x [%s]",
       message->transmit_ts.hi, message->transmit_ts.lo,
       UTI_TimestampToString(&message->transmit_ts));
 
-  LOG(LOGS_INFO, LOGF_NtpCore, "theta=%f delta=%f epsilon=%f root_delay=%f root_dispersion=%f",
+  DEBUG_LOG(LOGF_NtpCore, "theta=%f delta=%f epsilon=%f root_delay=%f root_dispersion=%f",
       theta, delta, epsilon, root_delay, root_dispersion);
 
-  LOG(LOGS_INFO, LOGF_NtpCore, "test1=%d test2=%d test3=%d test4=%d valid_data=%d good_data=%d",
+  DEBUG_LOG(LOGF_NtpCore, "test1=%d test2=%d test3=%d test4=%d valid_data=%d good_data=%d",
       test1, test2, test3, test4, valid_data, good_data);
 
-  LOG(LOGS_INFO, LOGF_NtpCore, "test5=%d test6=%d test7=%d test8=%d valid_header=%d good_header=%d",
+  DEBUG_LOG(LOGF_NtpCore, "test5=%d test6=%d test7=%d test8=%d valid_header=%d good_header=%d",
       test5, test6, test7, test8, valid_header, good_header);
 
-  LOG(LOGS_INFO, LOGF_NtpCore, "kod_rate=%d valid_kod=%d", kod_rate, valid_kod);
+  DEBUG_LOG(LOGF_NtpCore, "kod_rate=%d valid_kod=%d", kod_rate, valid_kod);
-#endif
 
   /* Reduce polling rate if KoD RATE was received */
   if (kod_rate && valid_kod) {
@@ -1545,21 +1541,13 @@ NCR_SlewTimes(NCR_Instance inst, struct timeval *when, double dfreq, double doff
   prev = inst->local_rx;
   if (inst->local_rx.tv_sec || inst->local_rx.tv_usec)
     UTI_AdjustTimeval(&inst->local_rx, when, &inst->local_rx, &delta, dfreq, doffset);
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_NtpCore, "rx prev=[%s] new=[%s]",
-  LOG(LOGS_INFO, LOGF_NtpCore, "rx prev=[%s] new=[%s]",
       UTI_TimevalToString(&prev), UTI_TimevalToString(&inst->local_rx));
-#else
-  (void)prev;
-#endif
   prev = inst->local_tx;
   if (inst->local_tx.tv_sec || inst->local_tx.tv_usec)
     UTI_AdjustTimeval(&inst->local_tx, when, &inst->local_tx, &delta, dfreq, doffset);
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_NtpCore, "tx prev=[%s] new=[%s]",
-  LOG(LOGS_INFO, LOGF_NtpCore, "tx prev=[%s] new=[%s]",
       UTI_TimevalToString(&prev), UTI_TimevalToString(&inst->local_tx));
-#else
-  (void)prev;
-#endif
 }
 
 /* ================================================== */

refclock.c

@@ -249,10 +249,8 @@ RCL_AddRefclock(RefclockParameters *params)
 
   inst->source = SRC_CreateNewInstance(inst->ref_id, SRC_REFCLOCK, params->sel_option, NULL);
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Refclock, "refclock %s added poll=%d dpoll=%d filter=%d",
-  LOG(LOGS_INFO, LOGF_Refclock, "refclock %s added poll=%d dpoll=%d filter=%d",
       params->driver_name, inst->poll, inst->driver_poll, params->filter_length);
-#endif
   n_sources++;
 
   Free(params->driver_name);
@@ -412,18 +410,14 @@ RCL_AddPulse(RCL_Instance instance, struct timeval *pulse_time, double second)
 
     if (!filter_get_last_sample(&refclocks[instance->lock_ref].filter,
           &ref_sample_time, &ref_offset, &ref_dispersion)) {
-#ifdef TRACEON
+      DEBUG_LOG(LOGF_Refclock, "refclock pulse ignored no ref sample");
-      LOG(LOGS_INFO, LOGF_Refclock, "refclock pulse ignored no ref sample");
-#endif
       return 0;
     }
 
     UTI_DiffTimevalsToDouble(&sample_diff, &cooked_time, &ref_sample_time);
     if (fabs(sample_diff) >= 2.0 / rate) {
-#ifdef TRACEON
+      DEBUG_LOG(LOGF_Refclock, "refclock pulse ignored samplediff=%.9f",
-      LOG(LOGS_INFO, LOGF_Refclock, "refclock pulse ignored samplediff=%.9f",
           sample_diff);
-#endif
       return 0;
     }
 
@@ -436,17 +430,13 @@ RCL_AddPulse(RCL_Instance instance, struct timeval *pulse_time, double second)
     offset += shift;
 
     if (fabs(ref_offset - offset) + ref_dispersion + dispersion >= 0.2 / rate) {
-#ifdef TRACEON
+      DEBUG_LOG(LOGF_Refclock, "refclock pulse ignored offdiff=%.9f refdisp=%.9f disp=%.9f",
-      LOG(LOGS_INFO, LOGF_Refclock, "refclock pulse ignored offdiff=%.9f refdisp=%.9f disp=%.9f",
           ref_offset - offset, ref_dispersion, dispersion);
-#endif
       return 0;
     }
 
-#ifdef TRACEON
+    DEBUG_LOG(LOGF_Refclock, "refclock pulse second=%.9f offset=%.9f offdiff=%.9f samplediff=%.9f",
-    LOG(LOGS_INFO, LOGF_Refclock, "refclock pulse second=%.9f offset=%.9f offdiff=%.9f samplediff=%.9f",
         second, offset, ref_offset - offset, sample_diff);
-#endif
   } else {
     struct timeval ref_time;
     int is_synchronised, stratum;
@@ -461,10 +451,8 @@ RCL_AddPulse(RCL_Instance instance, struct timeval *pulse_time, double second)
     distance = fabs(root_delay) / 2 + root_dispersion;
 
     if (!is_synchronised || distance >= 0.5 / rate) {
-#ifdef TRACEON
+      DEBUG_LOG(LOGF_Refclock, "refclock pulse ignored second=%.9f sync=%d dist=%.9f",
-      LOG(LOGS_INFO, LOGF_Refclock, "refclock pulse ignored second=%.9f sync=%d dist=%.9f",
           second, is_synchronised, distance);
-#endif
       /* Drop also all stored samples */
       filter_reset(&instance->filter);
       return 0;
@@ -493,10 +481,8 @@ valid_sample_time(RCL_Instance instance, struct timeval *tv)
   LCL_ReadRawTime(&raw_time);
   UTI_DiffTimevalsToDouble(&diff, &raw_time, tv);
   if (diff < 0.0 || diff > 1 << (instance->poll + 1)) {
-#ifdef TRACEON
+    DEBUG_LOG(LOGF_Refclock, "refclock sample not valid age=%.f tv=%s",
-    LOG(LOGS_INFO, LOGF_Refclock, "refclock sample not valid age=%.f tv=%s",
         diff, UTI_TimevalToString(tv));
-#endif
     return 0;
   }
   return 1;
@@ -683,10 +669,8 @@ filter_add_sample(struct MedianFilter *filter, struct timeval *sample_time, doub
   filter->samples[filter->index].offset = offset;
   filter->samples[filter->index].dispersion = dispersion;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Refclock, "filter sample %d t=%s offset=%.9f dispersion=%.9f",
-  LOG(LOGS_INFO, LOGF_Refclock, "filter sample %d t=%s offset=%.9f dispersion=%.9f",
       filter->index, UTI_TimevalToString(sample_time), offset, dispersion);
-#endif
 }
 
 static int

refclock_phc.c

@@ -175,9 +175,7 @@ static int phc_poll(RCL_Instance instance)
   tv.tv_sec = readings[best].sys_ts2.tv_sec;
   tv.tv_usec = readings[best].sys_ts2.tv_nsec / 1000;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Refclock, "PHC offset: %+.9f delay: %.9f", offset, best_delay);
-  LOG(LOGS_INFO, LOGF_Refclock, "PHC offset: %+.9f delay: %.9f", offset, best_delay);
-#endif
 
   return RCL_AddSample(instance, &tv, offset, LEAP_Normal);
 }

refclock_pps.c

@@ -147,10 +147,8 @@ static int pps_poll(RCL_Instance instance)
   }
 
   if (seq == pps->last_seq || (ts.tv_sec == 0 && ts.tv_nsec == 0)) { 
-#ifdef TRACEON
+    DEBUG_LOG(LOGF_Refclock, "PPS sample ignored seq=%lu ts=%lu.%09lu",
-    LOG(LOGS_INFO, LOGF_Refclock, "PPS sample ignored seq=%lu ts=%lu.%09lu",
         seq, ts.tv_sec, ts.tv_nsec);
-#endif
     return 0;
   }
 

refclock_shm.c

@@ -100,10 +100,8 @@ static int shm_poll(RCL_Instance instance)
   
   if ((t.mode == 1 && t.count != shm->count) ||
     !(t.mode == 0 || t.mode == 1) || !t.valid) {
-#ifdef TRACEON
+    DEBUG_LOG(LOGF_Refclock, "SHM sample ignored mode=%d count=%d valid=%d",
-    LOG(LOGS_INFO, LOGF_Refclock, "SHM sample ignored mode=%d count=%d valid=%d",
         t.mode, t.count, t.valid);
-#endif
     return 0;
   }
 

sources.c

@@ -307,10 +307,8 @@ void SRC_AccumulateSample
 
   inst->leap_status = leap_status;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Sources, "ip=[%s] t=%s ofs=%f del=%f disp=%f str=%d",
-  LOG(LOGS_INFO, LOGF_Sources, "ip=[%s] t=%s ofs=%f del=%f disp=%f str=%d",
       source_to_string(inst), UTI_TimevalToString(sample_time), -offset, root_delay, root_dispersion, stratum);
-#endif
 
   /* WE HAVE TO NEGATE OFFSET IN THIS CALL, IT IS HERE THAT THE SENSE OF OFFSET
      IS FLIPPED */
@@ -327,9 +325,7 @@ SRC_SetSelectable(SRC_Instance inst)
 {
   inst->selectable = 1;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Sources, "%s", source_to_string(inst));
-  LOG(LOGS_INFO, LOGF_Sources, "%s", source_to_string(inst));
-#endif
 
   /* Don't do selection at this point, though - that will come about
      in due course when we get some useful data from the source */
@@ -342,10 +338,8 @@ SRC_UnsetSelectable(SRC_Instance inst)
 {
   inst->selectable = 0;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Sources, "%s%s", source_to_string(inst),
-  LOG(LOGS_INFO, LOGF_Sources, "%s%s", source_to_string(inst),
       (inst->index == selected_source_index) ? "(REF)":"");
-#endif
 
   /* If this was the previous reference source, we have to reselect!  */
 
@@ -472,10 +466,8 @@ combine_sources(int n_sel_sources, struct timeval *ref_time, double *offset,
     offset_weight = 1.0 / sources[index]->sel_info.root_distance;
     frequency_weight = 1.0 / src_skew;
 
-#ifdef TRACEON
+    DEBUG_LOG(LOGF_Sources, "combining index=%d oweight=%e offset=%e sd=%e fweight=%e freq=%e skew=%e",
-    LOG(LOGS_INFO, LOGF_Sources, "combining index=%d oweight=%e offset=%e sd=%e fweight=%e freq=%e skew=%e",
         index, offset_weight, src_offset, src_offset_sd, frequency_weight, src_frequency, src_skew);
-#endif
 
     sum_offset_weight += offset_weight;
     sum_offset += offset_weight * src_offset;
@@ -495,10 +487,8 @@ combine_sources(int n_sel_sources, struct timeval *ref_time, double *offset,
   *frequency = sum_frequency / sum_frequency_weight;
   *skew = 1.0 / sqrt(inv_sum2_skew);
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_Sources, "combined result offset=%e sd=%e freq=%e skew=%e",
-  LOG(LOGS_INFO, LOGF_Sources, "combined result offset=%e sd=%e freq=%e skew=%e",
       *offset, *offset_sd, *frequency, *skew);
-#endif
 
   return combined;
 }

sourcestats.c

@@ -569,10 +569,8 @@ SST_GetSelectionData(SST_Stats inst, struct timeval *now,
 
   *select_ok = inst->regression_ok;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_SourceStats, "n=%d off=%f dist=%f var=%f selok=%d",
-  LOG(LOGS_INFO, LOGF_SourceStats, "n=%d off=%f dist=%f var=%f selok=%d",
       inst->n_samples, offset, *root_distance, *variance, *select_ok);
-#endif
 }
 
 /* ================================================== */
@@ -599,10 +597,8 @@ SST_GetTrackingData(SST_Stats inst, struct timeval *ref_time,
   UTI_DiffTimevalsToDouble(&elapsed_sample, &inst->offset_time, &inst->sample_times[i]);
   *root_dispersion = inst->root_dispersions[j] + inst->skew * elapsed_sample;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_SourceStats, "n=%d freq=%f (%.3fppm) skew=%f (%.3fppm) avoff=%f offsd=%f disp=%f",
-  LOG(LOGS_INFO, LOGF_SourceStats, "n=%d freq=%f (%.3fppm) skew=%f (%.3fppm) avoff=%f offsd=%f disp=%f",
       inst->n_samples, *frequency, 1.0e6* *frequency, *skew, 1.0e6* *skew, *average_offset, *offset_sd, *root_dispersion);
-#endif
 
 }
 
@@ -626,13 +622,10 @@ SST_SlewSamples(SST_Stats inst, struct timeval *when, double dfreq, double doffs
     UTI_AdjustTimeval(sample, when, sample, &delta_time, dfreq, doffset);
     prev_offset = inst->offsets[i];
     inst->offsets[i] += delta_time;
-#ifdef TRACEON
+
-    LOG(LOGS_INFO, LOGF_SourceStats, "i=%d old_st=[%s] new_st=[%s] old_off=%f new_off=%f",
+    DEBUG_LOG(LOGF_SourceStats, "i=%d old_st=[%s] new_st=[%s] old_off=%f new_off=%f",
         i, UTI_TimevalToString(&prev), UTI_TimevalToString(sample),
         prev_offset, inst->offsets[i]);
-#else
-    (void)prev; (void)prev_offset;
-#endif
   }
 
   /* Do a half-baked update to the regression estimates */
@@ -644,14 +637,10 @@ SST_SlewSamples(SST_Stats inst, struct timeval *when, double dfreq, double doffs
   inst->estimated_offset += delta_time;
   inst->estimated_frequency -= dfreq;
 
-#ifdef TRACEON
+  DEBUG_LOG(LOGF_SourceStats, "old_off_time=[%s] new=[%s] old_off=%f new_off=%f old_freq=%.3fppm new_freq=%.3fppm",
-  LOG(LOGS_INFO, LOGF_SourceStats, "old_off_time=[%s] new=[%s] old_off=%f new_off=%f old_freq=%.3fppm new_freq=%.3fppm",
       UTI_TimevalToString(&prev), UTI_TimevalToString(&(inst->offset_time)),
       prev_offset, inst->estimated_offset,
       1.0e6*prev_freq, 1.0e6*inst->estimated_frequency);
-#else
-  (void)prev; (void)prev_offset; (void)prev_freq;
-#endif
 }
 
 /* ================================================== */