From 7f90d255b23b7b320004b827cf8ed0d5ad394ba2 Mon Sep 17 00:00:00 2001 From: Verkehrsrot Date: Thu, 14 Mar 2019 19:52:10 +0100 Subject: [PATCH] timeserver fixes --- include/timesync.h | 6 +++--- src/lorawan.cpp | 14 +++++++++----- src/timesync.cpp | 41 +++++++++++++++++++++++++---------------- 3 files changed, 37 insertions(+), 24 deletions(-) diff --git a/include/timesync.h b/include/timesync.h index 7ce8205f..e854301e 100644 --- a/include/timesync.h +++ b/include/timesync.h @@ -9,12 +9,12 @@ #define TIME_SYNC_SAMPLES 5 // number of time requests for averaging #define TIME_SYNC_CYCLE 60 // 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 time sync +#define TIME_SYNC_TRIGGER 100 // time deviation in millisec triggering a sync #define TIME_SYNC_FRAME_LENGTH 0x06 // timeserver answer frame length void send_timesync_req(void); -void recv_timesync_ans(uint8_t buf[], uint8_t buf_len); +int recv_timesync_ans(uint8_t buf[], uint8_t buf_len); void process_timesync_req(void *taskparameter); -void store_time_sync_req(time_t secs, uint32_t micros); +void store_time_sync_req(time_t t_millisec); #endif \ No newline at end of file diff --git a/src/lorawan.cpp b/src/lorawan.cpp index 2301d4bf..3d79cf3b 100644 --- a/src/lorawan.cpp +++ b/src/lorawan.cpp @@ -1,12 +1,12 @@ // Basic Config -#if(HAS_LORA) +#if (HAS_LORA) #include "lorawan.h" #endif // Local logging Tag static const char TAG[] = "lora"; -#if(HAS_LORA) +#if (HAS_LORA) #if CLOCK_ERROR_PROCENTAGE > 7 #warning CLOCK_ERROR_PROCENTAGE value in lmic_config.h is too high; values > 7 will cause side effects @@ -231,9 +231,13 @@ 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); - // maybe use more precise osticks2ms(LMIC.txend) here? + 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 strcpy_P(buff, (LMIC.txrxFlags & TXRX_ACK) ? PSTR("RECEIVED_ACK") diff --git a/src/timesync.cpp b/src/timesync.cpp index 5f47b592..c2b44b4d 100644 --- a/src/timesync.cpp +++ b/src/timesync.cpp @@ -61,11 +61,11 @@ void send_timesync_req() { } // process timeserver timestamp answer, called from lorawan.cpp -void recv_timesync_ans(uint8_t buf[], uint8_t buf_len) { +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)) - return; + return 0; // failure uint8_t seq_no = buf[0], k = seq_no % TIME_SYNC_SAMPLES; uint16_t timestamp_msec = 4 * buf[5]; // convert 1/250th sec fractions to ms @@ -75,7 +75,10 @@ void recv_timesync_ans(uint8_t buf[], uint8_t buf_len) { timestamp_sec = (tmp_sec <<= 8) |= buf[i]; } - time_sync_rx[k] += seconds(timestamp_sec) + milliseconds(timestamp_msec); + if (timestamp_sec + timestamp_msec) // field validation: timestamp not 0 ? + time_sync_rx[k] += seconds(timestamp_sec) + milliseconds(timestamp_msec); + else + return 0; // failure ESP_LOGD(TAG, "Timesync request #%d rcvd at %d", seq_no, myClock::to_time_t(time_sync_rx[k])); @@ -83,6 +86,8 @@ void recv_timesync_ans(uint8_t buf[], uint8_t buf_len) { // inform processing task if (timeSyncReqTask) xTaskNotify(timeSyncReqTask, seq_no, eSetBits); + + return 1; // success } // task for sending time sync requests @@ -92,6 +97,8 @@ void process_timesync_req(void *taskparameter) { 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++) { @@ -123,26 +130,28 @@ void process_timesync_req(void *taskparameter) { 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 - time_offset /= TIME_SYNC_SAMPLES; - ESP_LOGD(TAG, "Avg time diff: %lldms", time_offset.count()); + time_offset /= TIME_SYNC_SAMPLES; + // 1 sec floor round + 1sec wait for top of second + time_to_set = now() + 2 + time_offset.count() / 1000; + ESP_LOGD(TAG, "Calculated UTC epoch time: %d", time_to_set); - if (abs(time_offset.count()) >= TIME_SYNC_TRIGGER) { // milliseconds threshold + // adjust system time + if (timeIsValid(time_to_set)) { - time_t const time_to_set = now() + 1 + time_offset.count() / 1000; - ESP_LOGD(TAG, "New 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 - uint16_t const time_offset_msec = time_offset.count() % 1000; + 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)); @@ -156,9 +165,9 @@ void process_timesync_req(void *taskparameter) { timeSync); // set to regular repeat ESP_LOGI(TAG, "Timesync finished, time was adjusted"); } else - ESP_LOGW(TAG, "Invalid time received from timeserver"); + ESP_LOGI(TAG, "Timesync finished, time is up to date"); } else - ESP_LOGI(TAG, "Timesync finished, time is up to date"); + ESP_LOGW(TAG, "Invalid time received from timeserver"); finish: @@ -168,10 +177,10 @@ finish: } // called from lorawan.cpp after time_sync_req was sent -void store_time_sync_req(time_t t_sec, uint32_t t_microsec) { +void store_time_sync_req(time_t t_millisec) { uint8_t k = time_sync_seqNo % TIME_SYNC_SAMPLES; - time_sync_tx[k] += seconds(t_sec) + microseconds(t_microsec); + 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]));