timesync errorhandling improved

src/TTN/Nodered-Timeserver.json

@@ -1,11 +1,4 @@
 [
-    {
-        "id": "449c1517.e25f4c",
-        "type": "tab",
-        "label": "Timeserver MQTT",
-        "disabled": false,
-        "info": ""
-    },
     {
         "id": "49e3c067.e782e",
         "type": "change",
@@ -219,7 +212,7 @@
         "type": "function",
         "z": "449c1517.e25f4c",
         "name": "Generate Time Answer",
-        "func": "/* LoRaWAN Timeserver\n\nconstruct 6 byte timesync_answer from gateway timestamp and node's time_sync_req\n\nbyte    meaning\n0       sequence number (taken from node's time_sync_req)\n1..4    current second (from epoch time 1970)\n5       1/250ths fractions of current second\n\n*/\n\nfunction timecompare(a, b) {\n  \n  const timeA = a.time;\n  const timeB = b.time;\n\n  let comparison = 0;\n  if (timeA > timeB) {\n    comparison = 1;\n  } else if (timeA < timeB) {\n    comparison = -1;\n  }\n  return comparison;\n}\n\nlet confidence = 2000; // max millisecond diff gateway time to server time\n\nvar device = msg.payload.dev_id;\nvar gateways = msg.payload.metadata.gateways;\nvar gateway_time = gateways.map(gw => {\n    return {\n      time: new Date(gw.time),\n      eui: gw.gtw_id,\n      }\n  });\nvar server_time = new Date(msg.payload.metadata.time);\n\n// validate all gateway timestamps against lorawan server_time (which is assumed to be recent)\nvar gw_timestamps = gateway_time.filter(function (element) {\n  return ((element.time > (server_time - confidence) && element.time <= server_time));\n});\n\n// if no timestamp left, we have no valid one and exit\nif (gw_timestamps.length === 0) return null;\n\n// sort time array in ascending order to find most recent timestamp for time answer\ngw_timestamps.sort(timecompare);\n\nvar timestamp = gw_timestamps[0].time;\nvar eui = gw_timestamps[0].eui;\nvar offset = server_time - timestamp;\n\nvar seconds = Math.floor(timestamp/1000);\nvar fractions = (timestamp % 1000) / 4;\nvar seqno = msg.payload.payload_raw[0];\n\nlet buf = new ArrayBuffer(6);\nnew DataView(buf).setUint8(0, seqno);\nnew DataView(buf).setUint32(1, seconds);\nnew DataView(buf).setUint8(5, fractions);\n\nmsg.payload = new Buffer(new Uint8Array(buf));\nvar infoMsg = { payload: eui };\nvar offsetMsg = { payload: offset };\nvar deviceMsg = { payload: device };\n\nreturn [infoMsg, offsetMsg, deviceMsg, msg];",
+        "func": "/* LoRaWAN Timeserver\n\nconstruct 6 byte timesync_answer from gateway timestamp and node's time_sync_req\n\nbyte    meaning\n0       sequence number (taken from node's time_sync_req)\n1..4    current second (from epoch time 1970)\n5       1/250ths fractions of current second\n\n*/\n\nfunction timecompare(a, b) {\n  \n  const timeA = a.time;\n  const timeB = b.time;\n\n  let comparison = 0;\n  if (timeA > timeB) {\n    comparison = 1;\n  } else if (timeA < timeB) {\n    comparison = -1;\n  }\n  return comparison;\n}\n\nlet confidence = 2000; // max millisecond diff gateway time to server time\n\nvar deviceMsg = { payload: msg.payload.dev_id };\nvar gateways = msg.payload.metadata.gateways;\nvar gateway_time = gateways.map(gw => {\n    return {\n      time: new Date(gw.time),\n      eui: gw.gtw_id,\n      }\n  });\nvar server_time = new Date(msg.payload.metadata.time);\n\n// validate all gateway timestamps against lorawan server_time (which is assumed to be recent)\nvar gw_timestamps = gateway_time.filter(function (element) {\n  return ((element.time > (server_time - confidence) && element.time <= server_time));\n});\n\n// if no timestamp left, we have no valid one and exit\nif (gw_timestamps.length === 0) return [\"n/a\", \"n/a\", deviceMsg, 0xff];\n\n// sort time array in ascending order to find most recent timestamp for time answer\ngw_timestamps.sort(timecompare);\n\nvar timestamp = gw_timestamps[0].time;\nvar eui = gw_timestamps[0].eui;\nvar offset = server_time - timestamp;\n\nvar seconds = Math.floor(timestamp/1000);\nvar fractions = (timestamp % 1000) / 4;\nvar seqno = msg.payload.payload_raw[0];\n\nlet buf = new ArrayBuffer(6);\nnew DataView(buf).setUint8(0, seqno);\nnew DataView(buf).setUint32(1, seconds);\nnew DataView(buf).setUint8(5, fractions);\n\nmsg.payload = new Buffer(new Uint8Array(buf));\nvar euiMsg = { payload: eui };\nvar offsetMsg = { payload: offset };\n\nreturn [euiMsg, offsetMsg, deviceMsg, msg];",
         "outputs": 4,
         "noerr": 0,
         "x": 360,

src/main.cpp

@@ -46,9 +46,9 @@ Tasks using i2c bus all must have same priority, because using mutex semaphore
 
 // ESP32 hardware timers
 -------------------------------------------------------------------------------
-0	displayIRQ -> display refresh -> 40ms (DISPLAYREFRESH_MS in paxcounter.conf)
+0	displayIRQ -> display refresh -> 40ms (DISPLAYREFRESH_MS)
-1 ppsIRQ -> pps clock irq -> 1sec 
+1 ppsIRQ -> pps clock irq -> 1sec
-2	unused 
+2	unused
 3	unused
 
 
@@ -156,7 +156,7 @@ void setup() {
            ESP.getFlashChipSpeed());
   ESP_LOGI(TAG, "Wifi/BT software coexist version %s", esp_coex_version_get());
 
-#if(HAS_LORA)
+#if (HAS_LORA)
   ESP_LOGI(TAG, "IBM LMIC version %d.%d.%d", LMIC_VERSION_MAJOR,
            LMIC_VERSION_MINOR, LMIC_VERSION_BUILD);
   ESP_LOGI(TAG, "Arduino LMIC version %d.%d.%d.%d",
@@ -167,7 +167,7 @@ void setup() {
   showLoraKeys();
 #endif // HAS_LORA
 
-#if(HAS_GPS)
+#if (HAS_GPS)
   ESP_LOGI(TAG, "TinyGPS+ version %s", TinyGPSPlus::libraryVersion());
 #endif
 
@@ -185,7 +185,12 @@ void setup() {
 // set low power mode to off
 #ifdef HAS_LOWPOWER_SWITCH
   pinMode(HAS_LOWPOWER_SWITCH, OUTPUT);
+#if (LOW_POWER_ACTIVE_LOW)
+  digitalWrite(HAS_LOWPOWER_SWITCH, HIGH);
+#else
   digitalWrite(HAS_LOWPOWER_SWITCH, LOW);
+#endif
+
   strcat_P(features, " LPWR");
 #endif
 
@@ -269,7 +274,7 @@ void setup() {
 #endif // HAS_BUTTON
 
 // initialize gps
-#if(HAS_GPS)
+#if (HAS_GPS)
   strcat_P(features, " GPS");
   if (gps_init()) {
     ESP_LOGI(TAG, "Starting GPS Feed...");
@@ -284,13 +289,13 @@ void setup() {
 #endif
 
 // initialize sensors
-#if(HAS_SENSORS)
+#if (HAS_SENSORS)
   strcat_P(features, " SENS");
   sensor_init();
 #endif
 
 // initialize LoRa
-#if(HAS_LORA)
+#if (HAS_LORA)
   strcat_P(features, " LORA");
   assert(lora_stack_init() == ESP_OK);
 #endif
@@ -425,7 +430,7 @@ void setup() {
 
 void loop() {
   while (1) {
-#if(HAS_LORA)
+#if (HAS_LORA)
     os_runloop_once(); // execute lmic scheduled jobs and events
 #endif
     delay(2); // yield to CPU

src/timesync.cpp

@@ -37,7 +37,7 @@ void send_timesync_req() {
 
   // if a timesync handshake is pending then exit
   if (lora_time_sync_pending) {
-    ESP_LOGI(TAG, "Timeserver sync request already pending");
+    // ESP_LOGI(TAG, "Timeserver sync request already pending");
     return;
   } else {
     ESP_LOGI(TAG, "[%0.3f] Timeserver sync request started", millis() / 1000.0);
@@ -90,7 +90,8 @@ void process_timesync_req(void *taskparameter) {
                          pdMS_TO_TICKS(TIME_SYNC_TIMEOUT * 1000)) == pdFALSE) ||
         (seq_no != time_sync_seqNo)) {
 
-      ESP_LOGW(TAG, "[%0.3f] Timeserver handshake failed", millis() / 1000.0);
+      ESP_LOGW(TAG, "[%0.3f] Timeserver error: handshake timed out",
+               millis() / 1000.0);
       goto finish;
     } // no valid sequence received before timeout
 
@@ -161,9 +162,12 @@ void process_timesync_req(void *taskparameter) {
       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");
+      ESP_LOGI(TAG,
+               "[%0.3f] Timesync finished, time is up to date",
+               millis() / 1000.0);
   } else
-    ESP_LOGW(TAG, "Invalid time received from timeserver");
+    ESP_LOGW(TAG, "[%0.3f] Timesync failed, outdated time calculated",
+             millis() / 1000.0);
 
 finish:
 
@@ -188,36 +192,54 @@ void store_time_sync_req(uint32_t t_txEnd_ms) {
 int recv_timesync_ans(uint8_t buf[], uint8_t buf_len) {
 
   // if no timesync handshake is pending or spurious buffer then exit
-  if ((!lora_time_sync_pending) || (buf_len != TIME_SYNC_FRAME_LENGTH))
+  if (!lora_time_sync_pending)
     return 0; // failure
 
-  uint8_t seq_no = buf[0], k = seq_no % TIME_SYNC_SAMPLES;
+  // if no time is available or spurious buffer then exit
-  uint16_t timestamp_msec; // convert 1/250th sec fractions to ms
+  if (buf_len != TIME_SYNC_FRAME_LENGTH) {
-  uint32_t timestamp_sec;
+    if (buf[0] == 0xff)
+      ESP_LOGI(TAG, "[%0.3f] Timeserver error: no confident time available",
+               millis() / 1000.0);
+    else
+      ESP_LOGW(TAG, "[%0.3f] Timeserver error: spurious data received",
+               millis() / 1000.0);
+    return 0; // failure
+  }
 
-  // get the timeserver time.
+  else { // we received a probably valid time frame
-  // The first 4 bytes contain the UTC seconds since unix epoch.
-  // Octet order is big endian. Casts are necessary, because buf is an array
-  // of single byte values, and they might overflow when shifted
-  timestamp_sec = ((uint32_t)buf[4]) | (((uint32_t)buf[3]) << 8) |
-                  (((uint32_t)buf[2]) << 16) | (((uint32_t)buf[1]) << 24);
 
-  // The 5th byte contains the fractional seconds in 2^-8 second steps
+    uint8_t seq_no = buf[0], k = seq_no % TIME_SYNC_SAMPLES;
-  timestamp_msec = 4 * buf[5];
+    uint16_t timestamp_msec; // convert 1/250th sec fractions to ms
+    uint32_t timestamp_sec;
 
-  if ((timestamp_sec) || (timestamp_msec)) // field validation: time not 0 ?
+    // fetch timeserver time from 4 bytes containing the UTC seconds since unix
+    // epoch. Octet order is big endian. Casts are necessary, because buf is an
+    // array of single byte values, and they might overflow when shifted
+    timestamp_sec = ((uint32_t)buf[4]) | (((uint32_t)buf[3]) << 8) |
+                    (((uint32_t)buf[2]) << 16) | (((uint32_t)buf[1]) << 24);
+
+    // the 5th byte contains the fractional seconds in 2^-8 second steps
+    timestamp_msec = 4 * buf[5];
+
+    // construct the timepoint when message was seen on gateway
     time_sync_rx[k] += seconds(timestamp_sec) + milliseconds(timestamp_msec);
-  else
-    return 0; // failure
 
-  ESP_LOGD(TAG, "[%0.3f] Timesync request #%d rcvd at %d.%03d",
+    // guess if the timepoint is recent by comparing with code compile date
-           millis() / 1000.0, seq_no, timestamp_sec, timestamp_msec);
+    if (timeIsValid(myClock::to_time_t(time_sync_rx[k]))) {
+      ESP_LOGD(TAG, "[%0.3f] Timesync request #%d rcvd at %d.%03d",
+               millis() / 1000.0, seq_no, timestamp_sec, timestamp_msec);
 
-  // inform processing task
+      // inform processing task
-  if (timeSyncReqTask)
+      if (timeSyncReqTask)
-    xTaskNotify(timeSyncReqTask, seq_no, eSetBits);
+        xTaskNotify(timeSyncReqTask, seq_no, eSetBits);
 
-  return 1; // success
+      return 1; // success
+    } else {
+      ESP_LOGW(TAG, "[%0.3f] Timeserver error: outdated time received",
+               millis() / 1000.0);
+      return 0; // failure
+    }
+  }
 }
 
 #endif