diff --git a/include/if482.h b/include/if482.h index d31f5d59..a787030d 100644 --- a/include/if482.h +++ b/include/if482.h @@ -5,7 +5,6 @@ #include "timekeeper.h" #define IF482_FRAME_SIZE (17) -#define IF482_PULSE_LENGTH (1000) extern HardwareSerial IF482; diff --git a/include/timesync.h b/include/timesync.h index bbba4a7f..e91155cd 100644 --- a/include/timesync.h +++ b/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 \ No newline at end of file diff --git a/platformio.ini b/platformio.ini index 74f6787b..e0d424ed 100644 --- a/platformio.ini +++ b/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 diff --git a/src/dcf77.cpp b/src/dcf77.cpp index 7a1e5ab3..d240976d 100644 --- a/src/dcf77.cpp +++ b/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 *DCFpulse) { +uint8_t IRAM_ATTR dec2bcd(uint8_t const dec, uint8_t const startpos, + 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 \ No newline at end of file diff --git a/src/if482.cpp b/src/if482.cpp index fe645c18..92151b5d 100644 --- a/src/if482.cpp +++ b/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; } diff --git a/src/lorawan.cpp b/src/lorawan.cpp index 3d79cf3b..7b0f51ee 100644 --- a/src/lorawan.cpp +++ b/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; diff --git a/src/main.cpp b/src/main.cpp index 2a7dc259..8934bbb0 100644 --- a/src/main.cpp +++ b/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 0 temporary task for sending time sync requests +timesync_req 1 4 temporary task for processing 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 diff --git a/src/spislave.cpp b/src/spislave.cpp index cd6455a0..a288d4b0 100644 --- a/src/spislave.cpp +++ b/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; diff --git a/src/timekeeper.cpp b/src/timekeeper.cpp index f27d7343..65f4352f 100644 --- a/src/timekeeper.cpp +++ b/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); diff --git a/src/timesync.cpp b/src/timesync.cpp index e1c8e614..b5ae0725 100644 --- a/src/timesync.cpp +++ b/src/timesync.cpp @@ -27,6 +27,7 @@ typedef std::chrono::system_clock myClock; typedef myClock::time_point myClock_timepoint; typedef std::chrono::duration> myClock_msecTick; +typedef std::chrono::duration 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 - for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++) { - time_sync_tx[i] = time_sync_rx[i] = myClock_timepoint(); // set to epoch - } + // initialize timestamp array + for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++) + 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( + time_sync_tx[k]); // timepoint when node TX_completed + auto t_rx = time_point_cast( + 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, - 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 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( - time_sync_tx[k]); // timepoint when node TX_completed - auto t_rx = time_point_cast( - 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 \ No newline at end of file