timesync improvements

include/if482.h

@@ -5,7 +5,6 @@
 #include "timekeeper.h"
 
 #define IF482_FRAME_SIZE (17)
-#define IF482_PULSE_LENGTH (1000)
 
 extern HardwareSerial IF482;
 

include/timesync.h

@@ -7,7 +7,7 @@
 #include "timekeeper.h"
 
 #define TIME_SYNC_SAMPLES 3   // number of time requests for averaging
-#define TIME_SYNC_CYCLE 20    // seconds between two time requests
+#define TIME_SYNC_CYCLE 2     // seconds between two time requests
 #define TIME_SYNC_TIMEOUT 120 // timeout seconds waiting for timeserver answer
 #define TIME_SYNC_TRIGGER 100 // time deviation in millisec triggering a sync
 #define TIME_SYNC_FRAME_LENGTH 0x06 // timeserver answer frame length
@@ -15,6 +15,6 @@
 void send_timesync_req(void);
 int recv_timesync_ans(uint8_t buf[], uint8_t buf_len);
 void process_timesync_req(void *taskparameter);
-void store_time_sync_req(time_t t_millisec);
+void store_time_sync_req(uint32_t t_millisec);
 
 #endif

platformio.ini

@@ -30,10 +30,10 @@ description = Paxcounter is a proof-of-concept ESP32 device for metering passeng
 
 [common]
 ; for release_version use max. 10 chars total, use any decimal format like "a.b.c"
-release_version = 1.7.38
+release_version = 1.7.39
 ; DEBUG LEVEL: For production run set to 0, otherwise device will leak RAM while running!
 ; 0=None, 1=Error, 2=Warn, 3=Info, 4=Debug, 5=Verbose
-debug_level = 4
+debug_level = 3
 ; UPLOAD MODE: select esptool to flash via USB/UART, select custom to upload to cloud for OTA
 upload_protocol = esptool
 ;upload_protocol = custom

src/dcf77.cpp

@@ -22,7 +22,9 @@ void DCF77_Pulse(time_t t, uint8_t const *DCFpulse) {
   TickType_t startTime = xTaskGetTickCount();
   uint8_t sec = second(t);
 
-  ESP_LOGD (TAG, "DCF second %d", sec);
+  t = myTZ.toLocal(now());
+  ESP_LOGD(TAG, "[%02d:%02d:%02d.%03d] DCF second %d", hour(t), minute(t),
+           second(t), millisecond(), sec);
 
   // induce 10 pulses
   for (uint8_t pulse = 0; pulse <= 9; pulse++) {
@@ -100,8 +102,8 @@ uint8_t *IRAM_ATTR DCF77_Frame(time_t const tt) {
 } // DCF77_Frame()
 
 // helper function to convert decimal to bcd digit
-uint8_t IRAM_ATTR dec2bcd(uint8_t const dec, uint8_t const startpos, uint8_t const endpos,
+uint8_t IRAM_ATTR dec2bcd(uint8_t const dec, uint8_t const startpos,
-                          uint8_t *DCFpulse) {
+                          uint8_t const endpos, uint8_t *DCFpulse) {
 
   uint8_t data = (dec < 10) ? dec : ((dec / 10) << 4) + (dec % 10);
   uint8_t parity = 0;
@@ -116,6 +118,8 @@ uint8_t IRAM_ATTR dec2bcd(uint8_t const dec, uint8_t const startpos, uint8_t con
 }
 
 // helper function to encode parity
-uint8_t IRAM_ATTR setParityBit(uint8_t const p) { return ((p & 1) ? dcf_1 : dcf_0); }
+uint8_t IRAM_ATTR setParityBit(uint8_t const p) {
+  return ((p & 1) ? dcf_1 : dcf_0);
+}
 
 #endif // HAS_DCF77

src/if482.cpp

@@ -90,15 +90,15 @@ HardwareSerial IF482(2); // use UART #2 (note: #1 may be in use for serial GPS)
 void IF482_Pulse(time_t t) {
 
   static const TickType_t txDelay =
-      pdMS_TO_TICKS(IF482_PULSE_LENGTH - tx_Ticks(IF482_FRAME_SIZE, HAS_IF482));
+      pdMS_TO_TICKS(1000) - tx_Ticks(IF482_FRAME_SIZE, HAS_IF482);
 
   vTaskDelay(txDelay);             // wait until moment to fire
   IF482.print(IF482_Frame(t + 1)); // note: if482 telegram for *next* second
 }
 
-String IRAM_ATTR IF482_Frame(time_t startTime) {
+String IRAM_ATTR IF482_Frame(time_t printTime) {
 
-  time_t t = myTZ.toLocal(startTime);
+  time_t t = myTZ.toLocal(printTime);
   char mon, out[IF482_FRAME_SIZE + 1];
 
   switch (timeStatus()) { // indicates if time has been set and recently synced
@@ -118,7 +118,9 @@ String IRAM_ATTR IF482_Frame(time_t startTime) {
            year(t) - 2000, month(t), day(t), weekday(t), hour(t), minute(t),
            second(t));
 
-  ESP_LOGD(TAG, "IF482 = %s", out);
+  t = myTZ.toLocal(now());
+  ESP_LOGD(TAG, "[%02d:%02d:%02d.%03d] IF482 = %s", hour(t), minute(t),
+           second(t), millisecond(), out);
   return out;
 }
 

src/lorawan.cpp

@@ -232,10 +232,6 @@ void onEvent(ev_t ev) {
 #if (TIME_SYNC_TIMESERVER)
     // if last packet sent was a timesync request, store TX timestamp
     if (LMIC.pendTxPort == TIMEPORT) {
-      // store_time_sync_req(now(now_micros), now_micros);
-      // adjust sampled OS time back in time to the nearest second boundary
-      //const ostime_t tAdjust = LMIC.netDeviceTimeFrac * ms2osticks(1000) / 256;
-      //store_time_sync_req(osticks2ms(LMIC.txend - tAdjust)); // milliseconds
       store_time_sync_req(osticks2ms(LMIC.txend)); // milliseconds
     }
 #endif
@@ -244,7 +240,7 @@ void onEvent(ev_t ev) {
                                                : PSTR("TX_COMPLETE"));
     sprintf(display_line6, " "); // clear previous lmic status
 
-    if (LMIC.dataLen) { // did we receive data -> display info
+    if (LMIC.dataLen) { // did we receive payload data -> display info
       ESP_LOGI(TAG, "Received %d bytes of payload, RSSI %d SNR %d",
                LMIC.dataLen, LMIC.rssi, LMIC.snr / 4);
       sprintf(display_line6, "RSSI %d SNR %d", LMIC.rssi, LMIC.snr / 4);
@@ -429,12 +425,16 @@ esp_err_t lora_stack_init() {
 void lora_enqueuedata(MessageBuffer_t *message, sendprio_t prio) {
   // enqueue message in LORA send queue
   BaseType_t ret;
+  MessageBuffer_t DummyBuffer;
   switch (prio) {
   case prio_high:
+    // clear space in queue if full, then fallthrough to normal
+    if (uxQueueSpacesAvailable == 0)
+      xQueueReceive(LoraSendQueue, &DummyBuffer, (TickType_t)0);
+  case prio_normal:
     ret = xQueueSendToFront(LoraSendQueue, (void *)message, (TickType_t)0);
     break;
   case prio_low:
-  case prio_normal:
   default:
     ret = xQueueSendToBack(LoraSendQueue, (void *)message, (TickType_t)0);
     break;

src/main.cpp

@@ -36,8 +36,7 @@ looptask      1     1     arduino core -> runs the LMIC LoRa stack
 irqhandler    1     1     executes tasks triggered by timer irq
 gpsloop       1     2     reads data from GPS via serial or i2c
 bmeloop       1     1     reads data from BME sensor via i2c
-timesync_ans  1     0     temporary task for receiving time sync requests
+timesync_req  1     4     temporary task for processing time sync requests
-timesync_req  1     0     temporary task for sending time sync requests
 IDLE          1     0     ESP32 arduino scheduler -> runs wifi channel rotator
 
 Low priority numbers denote low priority tasks.
@@ -165,7 +164,6 @@ void setup() {
            ARDUINO_LMIC_VERSION_GET_MINOR(ARDUINO_LMIC_VERSION),
            ARDUINO_LMIC_VERSION_GET_PATCH(ARDUINO_LMIC_VERSION),
            ARDUINO_LMIC_VERSION_GET_LOCAL(ARDUINO_LMIC_VERSION));
-  ESP_LOGI(TAG, "DEVEUI: ");
   showLoraKeys();
 #endif // HAS_LORA
 

src/spislave.cpp

@@ -150,12 +150,16 @@ esp_err_t spi_init() {
 void spi_enqueuedata(MessageBuffer_t *message, sendprio_t prio) {
   // enqueue message in SPI send queue
   BaseType_t ret;
+  MessageBuffer_t DummyBuffer;
   switch (prio) {
   case prio_high:
+    // clear space in queue if full, then fallthrough to normal
+    if (!uxQueueSpacesAvailable(SPISendQueue))
+      xQueueReceive(SPISendQueue, &DummyBuffer, (TickType_t)0);
+  case prio_normal:
     ret = xQueueSendToFront(SPISendQueue, (void *)message, (TickType_t)0);
     break;
   case prio_low:
-  case prio_normal:
   default:
     ret = xQueueSendToBack(SPISendQueue, (void *)message, (TickType_t)0);
     break;

src/timekeeper.cpp

@@ -22,7 +22,7 @@ time_t timeProvider(void) {
 
   time_t t = 0;
 
-#if(HAS_GPS)
+#if (HAS_GPS)
   t = get_gpstime(); // fetch recent time from last NEMA record
   if (t) {
 #ifdef HAS_RTC
@@ -219,12 +219,12 @@ void clock_loop(void *taskparameter) { // ClockTask
     xTaskNotifyWait(0x00, ULONG_MAX, &printtime,
                     portMAX_DELAY); // wait for timepulse
 
-    // no confident time -> we suppress clock output
-    if (timeStatus() == timeNotSet)
-      continue;
-
     t = time_t(printtime); // UTC time seconds
 
+    // no confident time -> suppress clock output
+    if ((timeStatus() == timeNotSet) || !(timeIsValid(t)))
+      continue;
+
 #if defined HAS_IF482
 
     IF482_Pulse(t);

src/timesync.cpp

@@ -27,6 +27,7 @@ typedef std::chrono::system_clock myClock;
 typedef myClock::time_point myClock_timepoint;
 typedef std::chrono::duration<long long int, std::ratio<1, 1000>>
     myClock_msecTick;
+typedef std::chrono::duration<double> myClock_secTick;
 
 myClock_timepoint time_sync_tx[TIME_SYNC_SAMPLES];
 myClock_timepoint time_sync_rx[TIME_SYNC_SAMPLES];
@@ -39,14 +40,13 @@ void send_timesync_req() {
     ESP_LOGI(TAG, "Timeserver sync request already pending");
     return;
   } else {
-    ESP_LOGI(TAG, "Timeserver sync request started");
+    ESP_LOGI(TAG, "[%0.3f] Timeserver sync request started", millis() / 1000.0);
 
     lora_time_sync_pending = true;
 
-    // clear timestamp array
+    // initialize timestamp array
-    for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++) {
+    for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++)
-      time_sync_tx[i] = time_sync_rx[i] = myClock_timepoint(); // set to epoch
+      time_sync_tx[i] = time_sync_rx[i] = myClock_timepoint();
-    }
 
     // kick off temporary task for timeserver handshake processing
     if (!timeSyncReqTask)
@@ -54,12 +54,132 @@ void send_timesync_req() {
                               "timesync_req",       // name of task
                               2048,                 // stack size of task
                               (void *)1,            // task parameter
-                              0,                    // priority of the task
+                              4,                    // priority of the task
                               &timeSyncReqTask,     // task handle
                               1);                   // CPU core
   }
 }
 
+// task for sending time sync requests
+void process_timesync_req(void *taskparameter) {
+
+  uint32_t seq_no = 0, time_to_set_us;
+  long long int time_to_set_ms;
+  uint16_t time_to_set_fraction_msec;
+  uint8_t k = 0, i = 0;
+  time_t time_to_set;
+  auto time_offset = myClock_msecTick::zero();
+
+  // wait until we are joined
+  while (!LMIC.devaddr) {
+    vTaskDelay(pdMS_TO_TICKS(2000));
+  }
+
+  // enqueue timestamp samples in lora sendqueue
+  for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++) {
+
+    // wrap around seqNo 0 .. 254
+    time_sync_seqNo = (time_sync_seqNo >= 255) ? 0 : time_sync_seqNo + 1;
+
+    // send sync request to server
+    payload.reset();
+    payload.addByte(time_sync_seqNo);
+    SendPayload(TIMEPORT, prio_high);
+
+    // process answer, wait for notification from recv_timesync_ans()
+    if ((xTaskNotifyWait(0x00, ULONG_MAX, &seq_no,
+                         pdMS_TO_TICKS(TIME_SYNC_TIMEOUT * 1000)) == pdFALSE) ||
+        (seq_no != time_sync_seqNo)) {
+
+      ESP_LOGW(TAG, "[%0.3f] Timeserver handshake failed", millis() / 1000.0);
+      goto finish;
+    } // no valid sequence received before timeout
+
+    else { // calculate time diff from collected timestamps
+      k = seq_no % TIME_SYNC_SAMPLES;
+
+      auto t_tx = time_point_cast<milliseconds>(
+          time_sync_tx[k]); // timepoint when node TX_completed
+      auto t_rx = time_point_cast<milliseconds>(
+          time_sync_rx[k]); // timepoint when message was seen on gateway
+
+      time_offset += t_rx - t_tx; // cumulate timepoint diffs
+
+      if (i < TIME_SYNC_SAMPLES - 1) {
+        // wait until next cycle
+        vTaskDelay(pdMS_TO_TICKS(TIME_SYNC_CYCLE * 1000));
+      } else {
+        // send flush to open a receive window for last time_sync_ans
+        payload.reset();
+        payload.addByte(0x99);
+        SendPayload(RCMDPORT, prio_high);
+      }
+    }
+  } // for
+
+  // calculate time offset from collected diffs
+  time_offset /= TIME_SYNC_SAMPLES;
+  ESP_LOGD(TAG, "[%0.3f] avg time diff: %0.3f sec", millis() / 1000.0,
+           myClock_secTick(time_offset).count());
+
+  // calculate absolute time with millisecond precision
+  time_to_set_ms = (long long)now(time_to_set_us) * 1000LL +
+                   time_to_set_us / 1000LL + time_offset.count();
+  // convert to seconds
+  time_to_set = (time_t)(time_to_set_ms / 1000LL);
+  // calculate fraction milliseconds
+  time_to_set_fraction_msec = (uint16_t)(time_to_set_ms % 1000LL);
+
+  ESP_LOGD(TAG, "[%0.3f] Calculated UTC epoch time: %d.%03d sec",
+           millis() / 1000.0, time_to_set, time_to_set_fraction_msec);
+
+  // adjust system time
+  if (timeIsValid(time_to_set)) {
+
+    if (abs(time_offset.count()) >=
+        TIME_SYNC_TRIGGER) { // milliseconds threshold
+
+      // wait until top of second
+      ESP_LOGD(TAG, "[%0.3f] waiting %d ms", millis() / 1000.0,
+               1000 - time_to_set_fraction_msec);
+      vTaskDelay(pdMS_TO_TICKS(1000 - time_to_set_fraction_msec));
+
+      // sync timer pps to top of second
+      if (ppsIRQ) {
+        timerRestart(ppsIRQ); // reset pps timer
+        CLOCKIRQ();           // fire clock pps interrupt
+      }
+
+      setTime(time_to_set + 1);
+      timeSource = _lora;
+
+      timesyncer.attach(TIME_SYNC_INTERVAL * 60,
+                        timeSync); // set to regular repeat
+      ESP_LOGI(TAG, "[%0.3f] Timesync finished, time adjusted by %.3f sec",
+               millis() / 1000.0, myClock_secTick(time_offset).count());
+    } else
+      ESP_LOGI(TAG, "Timesync finished, time not adjusted, is up to date");
+  } else
+    ESP_LOGW(TAG, "Invalid time received from timeserver");
+
+finish:
+
+  lora_time_sync_pending = false;
+  timeSyncReqTask = NULL;
+  vTaskDelete(NULL); // end task
+}
+
+// called from lorawan.cpp after time_sync_req was sent
+void store_time_sync_req(uint32_t t_millisec) {
+
+  uint8_t k = time_sync_seqNo % TIME_SYNC_SAMPLES;
+  time_sync_tx[k] += milliseconds(t_millisec);
+
+  ESP_LOGD(TAG, "[%0.3f] Timesync request #%d sent at %d.%03d",
+           millis() / 1000.0, time_sync_seqNo, t_millisec / 1000,
+           t_millisec % 1000);
+}
+
 // process timeserver timestamp answer, called from lorawan.cpp
 int recv_timesync_ans(uint8_t buf[], uint8_t buf_len) {
 
@@ -80,8 +200,8 @@ int recv_timesync_ans(uint8_t buf[], uint8_t buf_len) {
   else
     return 0; // failure
 
-  ESP_LOGD(TAG, "Timesync request #%d rcvd at %d", seq_no,
+  ESP_LOGD(TAG, "[%0.3f] Timesync request #%d rcvd at %d.%03d",
-           myClock::to_time_t(time_sync_rx[k]));
+           millis() / 1000.0, seq_no, timestamp_sec, timestamp_msec);
 
   // inform processing task
   if (timeSyncReqTask)
@@ -90,103 +210,4 @@ int recv_timesync_ans(uint8_t buf[], uint8_t buf_len) {
   return 1; // success
 }
 
-// task for sending time sync requests
-void process_timesync_req(void *taskparameter) {
-
-  uint8_t k = 0, i = 0;
-  uint32_t seq_no = 0;
-  // milliseconds time_offset(0);
-  auto time_offset = myClock_msecTick::zero();
-  int time_offset_msec;
-  time_t time_to_set;
-
-  // enqueue timestamp samples in lora sendqueue
-  for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++) {
-
-    // wrap around seqNo 0 .. 254
-    time_sync_seqNo = (time_sync_seqNo >= 255) ? 0 : time_sync_seqNo + 1;
-
-    // send sync request to server
-    payload.reset();
-    payload.addByte(time_sync_seqNo);
-    SendPayload(TIMEPORT, prio_high);
-
-    // process answer
-    if ((xTaskNotifyWait(0x00, ULONG_MAX, &seq_no,
-                         pdMS_TO_TICKS(TIME_SYNC_TIMEOUT * 1000)) == pdFALSE) ||
-        (seq_no != time_sync_seqNo)) {
-
-      ESP_LOGW(TAG, "Timeserver handshake failed");
-      goto finish;
-    } // no valid sequence received before timeout
-
-    else { // calculate time diff from collected timestamps
-      k = seq_no % TIME_SYNC_SAMPLES;
-
-      auto t_tx = time_point_cast<milliseconds>(
-          time_sync_tx[k]); // timepoint when node TX_completed
-      auto t_rx = time_point_cast<milliseconds>(
-          time_sync_rx[k]); // timepoint when message was seen on gateway
-
-      time_offset += t_rx - t_tx; // cumulate timepoint diffs
-
-      ESP_LOGD(TAG, "time_offset: %lldms", time_offset.count());
-
-      if (i < TIME_SYNC_SAMPLES - 1) // wait until next cycle
-        vTaskDelay(pdMS_TO_TICKS(TIME_SYNC_CYCLE * 1000));
-    }
-  } // for
-
-  // calculate time offset from collected diffs and set time if necessary
-  ESP_LOGD(TAG, "Avg time diff: %lldms", time_offset.count());
-  time_offset /= TIME_SYNC_SAMPLES;
-  // 1sec wait for top of second
-  time_to_set = now() + time_offset.count() / 1000 + 1;
-  ESP_LOGD(TAG, "Calculated UTC epoch time: %d", time_to_set);
-
-  // adjust system time
-  if (timeIsValid(time_to_set)) {
-
-    if (abs(time_offset.count()) >=
-        TIME_SYNC_TRIGGER) { // milliseconds threshold
-
-      // wait until top of second
-      time_offset_msec = abs(time_offset.count()) % 1000;
-      ESP_LOGD(TAG, "waiting %dms", 1000 - time_offset_msec);
-      vTaskDelay(pdMS_TO_TICKS(1000 - time_offset_msec));
-
-      // sync timer pps to top of second
-      if (ppsIRQ) {
-        timerRestart(ppsIRQ); // reset pps timer
-        CLOCKIRQ(); // fire clock pps interrupt
-      }
-
-      setTime(time_to_set);
-      timeSource = _lora;
-      timesyncer.attach(TIME_SYNC_INTERVAL * 60,
-                        timeSync); // set to regular repeat
-      ESP_LOGI(TAG, "Timesync finished, time adjusted by %lld ms",
-               time_offset.count());
-    } else
-      ESP_LOGI(TAG, "Timesync finished, time not adjusted, is up to date");
-  } else
-    ESP_LOGW(TAG, "Invalid time received from timeserver");
-
-finish:
-
-  lora_time_sync_pending = false;
-  timeSyncReqTask = NULL;
-  vTaskDelete(NULL); // end task
-}
-
-// called from lorawan.cpp after time_sync_req was sent
-void store_time_sync_req(time_t t_millisec) {
-
-  uint8_t k = time_sync_seqNo % TIME_SYNC_SAMPLES;
-  time_sync_tx[k] += milliseconds(t_millisec);
-
-  ESP_LOGD(TAG, "Timesync request #%d sent at %d", time_sync_seqNo,
-           myClock::to_time_t(time_sync_tx[k]));
-}
-
 #endif