Merge pull request #562 from cyberman54/development

Reworked LoRaWAN timesync code
This commit is contained in:
Verkehrsrot 2020-03-03 16:54:24 +01:00 committed by GitHub
commit 253b17bd91
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 109 additions and 97 deletions

View File

@ -46,7 +46,7 @@ void lora_queuereset(void);
void IRAM_ATTR myEventCallback(void *pUserData, ev_t ev); void IRAM_ATTR myEventCallback(void *pUserData, ev_t ev);
void IRAM_ATTR myRxCallback(void *pUserData, uint8_t port, void IRAM_ATTR myRxCallback(void *pUserData, uint8_t port,
const uint8_t *pMsg, size_t nMsg); const uint8_t *pMsg, size_t nMsg);
void IRAM_ATTR myTxCallback(void *pUserData, int fSuccess); //void IRAM_ATTR myTxCallback(void *pUserData, int fSuccess);
void mac_decode(const uint8_t cmd[], const uint8_t cmdlen, const mac_t table[], void mac_decode(const uint8_t cmd[], const uint8_t cmdlen, const mac_t table[],
const uint8_t tablesize); const uint8_t tablesize);
//u1_t os_getBattLevel(void); //u1_t os_getBattLevel(void);

View File

@ -8,15 +8,23 @@
//#define TIME_SYNC_TRIGGER 100 // threshold for time sync [milliseconds] //#define TIME_SYNC_TRIGGER 100 // threshold for time sync [milliseconds]
#define TIME_SYNC_FRAME_LENGTH 0x07 // timeserver answer frame length [bytes] #define TIME_SYNC_FRAME_LENGTH 0x07 // timeserver answer frame length [bytes]
#define TIME_SYNC_FIXUP 4 // calibration to fixup processing time [milliseconds] #define TIME_SYNC_FIXUP 16 // empirical calibration to fixup processing time [milliseconds]
#define TIMEREQUEST_MAX_SEQNO 0xf0 // threshold for wrap around seqno #define TIMEREQUEST_MAX_SEQNO 0xfe // threshold for wrap around seqno
#define TIMEREQUEST_FINISH \
(TIMEREQUEST_MAX_SEQNO + 1) // marker for end of timesync handshake
enum timesync_t {
timesync_tx,
timesync_rx,
gwtime_sec,
gwtime_msec,
no_of_timestamps
};
void timesync_init(void); void timesync_init(void);
void send_timesync_req(void); void send_timesync_req(void);
int recv_timesync_ans(const uint8_t buf[], uint8_t buf_len); int recv_timesync_ans(const uint8_t buf[], uint8_t buf_len);
void process_timesync_req(void *taskparameter); void process_timesync_req(void *taskparameter);
void store_time_sync_req(uint32_t t_millisec); void store_timestamp(uint32_t timestamp, timesync_t timestamp_type);
#endif #endif

View File

@ -261,12 +261,24 @@ void lora_send(void *pvParameters) {
// attempt to transmit payload // attempt to transmit payload
else { else {
// switch (LMIC_sendWithCallback_strict( switch (LMIC_setTxData2_strict(SendBuffer.MessagePort, SendBuffer.Message,
switch (LMIC_sendWithCallback( SendBuffer.MessageSize,
SendBuffer.MessagePort, SendBuffer.Message, SendBuffer.MessageSize, (cfg.countermode & 0x02))) {
(cfg.countermode & 0x02), myTxCallback, NULL)) {
// switch (LMIC_sendWithCallback_strict(
// SendBuffer.MessagePort, SendBuffer.Message,
// SendBuffer.MessageSize, (cfg.countermode & 0x02), myTxCallback,
// &SendBuffer.MessagePort)) {
case LMIC_ERROR_SUCCESS: case LMIC_ERROR_SUCCESS:
#if (TIME_SYNC_LORASERVER)
// if last packet sent was a timesync request, store TX timestamp
if (SendBuffer.MessagePort == TIMEPORT)
// store LMIC time when we started transmit of timesync request
store_timestamp(osticks2ms(os_getTime()), timesync_tx);
#endif
ESP_LOGI(TAG, "%d byte(s) sent to LORA", SendBuffer.MessageSize); ESP_LOGI(TAG, "%d byte(s) sent to LORA", SendBuffer.MessageSize);
break; break;
case LMIC_ERROR_TX_BUSY: // LMIC already has a tx message pending case LMIC_ERROR_TX_BUSY: // LMIC already has a tx message pending
@ -544,6 +556,9 @@ void myRxCallback(void *pUserData, uint8_t port, const uint8_t *pMsg,
#if (TIME_SYNC_LORASERVER) #if (TIME_SYNC_LORASERVER)
// valid timesync answer -> call timesync processor // valid timesync answer -> call timesync processor
if (port == TIMEPORT) { if (port == TIMEPORT) {
// store LMIC time when we received the timesync answer
store_timestamp(osticks2ms(os_getTime()), timesync_rx);
// get and store gwtime from payload
recv_timesync_ans(pMsg, nMsg); recv_timesync_ans(pMsg, nMsg);
break; break;
} }
@ -555,15 +570,19 @@ void myRxCallback(void *pUserData, uint8_t port, const uint8_t *pMsg,
} // switch } // switch
} }
// transmit complete message handler /*
// event TRANSMIT COMPLETE message handler
void myTxCallback(void *pUserData, int fSuccess) { void myTxCallback(void *pUserData, int fSuccess) {
#if (TIME_SYNC_LORASERVER) uint8_t *const sendport = (uint8_t *)pUserData;
// if last packet sent was a timesync request, store TX timestamp
if (LMIC.pendTxPort == TIMEPORT) if (fSuccess) {
store_time_sync_req(osticks2ms(LMIC.txend)); // milliseconds // LMIC did tx on *sendport -> nothing yet to do here
#endif } else {
// LMIC could not tx on *sendport -> error handling yet to come
}
} }
*/
// decode LORAWAN MAC message // decode LORAWAN MAC message
void mac_decode(const uint8_t cmd[], const uint8_t cmdlen, const mac_t table[], void mac_decode(const uint8_t cmd[], const uint8_t cmdlen, const mac_t table[],

View File

@ -104,11 +104,11 @@ void IRAM_ATTR setMyTime(uint32_t t_sec, uint16_t t_msec,
timeSource = mytimesource; // set global variable timeSource = mytimesource; // set global variable
timesyncer.attach(TIME_SYNC_INTERVAL * 60, timeSync); timesyncer.attach(TIME_SYNC_INTERVAL * 60, timeSync);
ESP_LOGI(TAG, "[%0.3f] Timesync finished, time was set | source: %c", ESP_LOGI(TAG, "[%0.3f] Timesync finished, time was set | source: %c",
millis() / 1000.0, timeSetSymbols[timeSource]); millis() / 1000.0, timeSetSymbols[mytimesource]);
} else { } else {
timesyncer.attach(TIME_SYNC_INTERVAL_RETRY * 60, timeSync); timesyncer.attach(TIME_SYNC_INTERVAL_RETRY * 60, timeSync);
ESP_LOGI(TAG, "[%0.3f] Timesync failed, invalid time fetched | source: %c", ESP_LOGI(TAG, "[%0.3f] Timesync failed, invalid time fetched | source: %c",
millis() / 1000.0, timeSetSymbols[timeSource]); millis() / 1000.0, timeSetSymbols[mytimesource]);
} }
} }

View File

@ -16,19 +16,12 @@ algorithm in applications without granted license by the patent holder.
// Local logging tag // Local logging tag
static const char TAG[] = __FILE__; static const char TAG[] = __FILE__;
using namespace std::chrono;
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;
TaskHandle_t timeSyncReqTask = NULL; TaskHandle_t timeSyncReqTask = NULL;
static uint8_t time_sync_seqNo = (uint8_t)random(TIMEREQUEST_MAX_SEQNO); static uint8_t time_sync_seqNo = (uint8_t)random(TIMEREQUEST_MAX_SEQNO);
static uint8_t sample_idx = 0;
static bool timeSyncPending = false; static bool timeSyncPending = false;
static myClock_timepoint time_sync_tx[TIME_SYNC_SAMPLES]; static uint32_t timesync_timestamp[TIME_SYNC_SAMPLES][no_of_timestamps] = {0};
static myClock_timepoint time_sync_rx[TIME_SYNC_SAMPLES];
// send time request message // send time request message
void send_timesync_req() { void send_timesync_req() {
@ -46,37 +39,37 @@ void send_timesync_req() {
// task for sending time sync requests // task for sending time sync requests
void process_timesync_req(void *taskparameter) { void process_timesync_req(void *taskparameter) {
uint8_t k; uint32_t rcv_seq_no = TIMEREQUEST_FINISH, time_offset_ms;
uint16_t time_to_set_fraction_msec;
uint32_t seq_no = 0, time_to_set; // this task is an endless loop, waiting in blocked mode, until it is
auto time_offset_ms = myClock_msecTick::zero(); // unblocked by send_timesync_req(). It then waits to be notified from
// recv_timesync_ans(), which is called from RX callback in lorawan.cpp, each
// time a timestamp from timeserver arrived.
// --- asnychronous part: generate and collect timestamps from gateway ---
while (1) { while (1) {
// reset all timestamps before next sync run
time_offset_ms = myClock_msecTick::zero();
for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++)
time_sync_tx[i] = time_sync_rx[i] = myClock_timepoint();
// wait for kickoff // wait for kickoff
ulTaskNotifyTake(pdFALSE, portMAX_DELAY); ulTaskNotifyTake(pdFALSE, portMAX_DELAY);
timeSyncPending = true; timeSyncPending = true;
time_offset_ms = 0;
// wait until we are joined if we are not // wait until we are joined if we are not
while (!LMIC.devaddr) { while (!LMIC.devaddr) {
vTaskDelay(pdMS_TO_TICKS(3000)); vTaskDelay(pdMS_TO_TICKS(5000));
} }
// collect timestamp samples // trigger and collect timestamp samples
for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++) { for (uint8_t i = 0; i < TIME_SYNC_SAMPLES; i++) {
// send sync request to server // send timesync request to timeserver
payload.reset(); payload.reset();
payload.addByte(time_sync_seqNo); payload.addByte(time_sync_seqNo);
SendPayload(TIMEPORT, prio_high); SendPayload(TIMEPORT, prio_high);
// wait for a valid timestamp from recv_timesync_ans() // wait until recv_timesync_ans() signals a timestamp was received
while (seq_no != time_sync_seqNo) { while (rcv_seq_no != time_sync_seqNo) {
if (xTaskNotifyWait(0x00, ULONG_MAX, &seq_no, if (xTaskNotifyWait(0x00, ULONG_MAX, &rcv_seq_no,
pdMS_TO_TICKS(TIME_SYNC_TIMEOUT * 1000)) == pdMS_TO_TICKS(TIME_SYNC_TIMEOUT * 1000)) ==
pdFALSE) { pdFALSE) {
ESP_LOGW(TAG, "[%0.3f] Timesync handshake error: timeout", ESP_LOGW(TAG, "[%0.3f] Timesync handshake error: timeout",
@ -85,78 +78,70 @@ void process_timesync_req(void *taskparameter) {
} }
} }
// process answer ESP_LOGD(TAG, "sample_idx = %d", sample_idx);
k = seq_no % TIME_SYNC_SAMPLES;
// calculate time diff from collected timestamps // calculate time diff from collected timestamps
time_offset_ms += time_point_cast<milliseconds>(time_sync_rx[k]) - time_offset_ms += timesync_timestamp[sample_idx][timesync_rx] -
time_point_cast<milliseconds>(time_sync_tx[k]); timesync_timestamp[sample_idx][timesync_tx];
// wrap around seqNo, keeping it in time port range // increment and maybe wrap around seqNo, keeping it in time port range
time_sync_seqNo++; time_sync_seqNo++;
if (time_sync_seqNo > TIMEREQUEST_MAX_SEQNO) { if (time_sync_seqNo > TIMEREQUEST_MAX_SEQNO) {
time_sync_seqNo = 0; time_sync_seqNo = 0;
} }
if (i < TIME_SYNC_SAMPLES - 1) { // increment index for timestamp array
// wait until next cycle sample_idx++;
// if last cycle, send finish char for closing timesync handshake,
// else wait until time has come for next cycle
if (i < TIME_SYNC_SAMPLES - 1) { // wait for next cycle
vTaskDelay(pdMS_TO_TICKS(TIME_SYNC_CYCLE * 1000)); vTaskDelay(pdMS_TO_TICKS(TIME_SYNC_CYCLE * 1000));
} else { // before sending last time sample... } else { // finish timesync handshake
// ...send flush to open a receive window for last time_sync_answer
payload.reset(); payload.reset();
payload.addByte(0x99); payload.addByte(TIMEREQUEST_FINISH);
SendPayload(RCMDPORT, prio_high); SendPayload(RCMDPORT, prio_high);
// ...send a alive open a receive window for last time_sync_answer // open a receive window to get last time_sync_answer instantly
LMIC_sendAlive(); LMIC_sendAlive();
} }
} // end of for loop to collect timestamp samples } // end of for loop to collect timestamp samples
// --- time critial part: evaluate timestamps and calculate time ---
// mask application irq to ensure accurate timing // mask application irq to ensure accurate timing
mask_user_IRQ(); mask_user_IRQ();
// average time offset over all collected diffs // average time offset over the summed up difference
// + add msec from recent gateway time, found with last sample_idx
// + apply a compensation constant TIME_SYNC_FIXUP for processing time
time_offset_ms /= TIME_SYNC_SAMPLES; time_offset_ms /= TIME_SYNC_SAMPLES;
time_offset_ms +=
timesync_timestamp[sample_idx - 1][gwtime_msec] + TIME_SYNC_FIXUP;
// --------- do we need this? --------- // calculate absolute time in UTC epoch: take latest time received from
// calculate time offset with millisecond precision using LMIC's time base, // gateway, convert to whole seconds, round to ceil, add fraction seconds
// since we use LMIC's ostime_t txEnd as tx timestamp. setMyTime(timesync_timestamp[sample_idx - 1][gwtime_sec] +
// time_offset_ms / 1000,
// time_offset_ms += milliseconds(osticks2ms(os_getTime())) - time_offset_ms % 1000, _lora);
// milliseconds(millis());
// --------- not sure -----------------
// Apply calibration const to compensate processing time. // end of time critical section: release app irq lock
time_offset_ms += milliseconds(TIME_SYNC_FIXUP); unmask_user_IRQ();
// calculate absolute time in UTC epoch: convert to whole seconds, round
// to ceil, and calculate fraction milliseconds
time_to_set = (uint32_t)(time_offset_ms.count() / 1000) + 1;
// calculate fraction milliseconds
time_to_set_fraction_msec = (uint16_t)(time_offset_ms.count() % 1000);
setMyTime(time_to_set, time_to_set_fraction_msec, _lora);
finish: finish:
// end of time critical section: release app irq lock
timeSyncPending = false; timeSyncPending = false;
unmask_user_IRQ();
} // infinite while(1) } // infinite while(1)
} }
// called from lorawan.cpp after time_sync_req was sent // called from lorawan.cpp
void store_time_sync_req(uint32_t timestamp) { void store_timestamp(uint32_t timestamp, timesync_t timestamp_type) {
// if no timesync handshake is pending then exit ESP_LOGD(TAG, "[%0.3f] seq#%d[%d]: timestamp(t%d)=%d",
if (!timeSyncPending) millis() / 1000.0, time_sync_seqNo, sample_idx, timestamp_type,
return; timestamp);
uint8_t k = time_sync_seqNo % TIME_SYNC_SAMPLES; timesync_timestamp[sample_idx][timestamp_type] = timestamp;
time_sync_tx[k] += milliseconds(timestamp);
ESP_LOGD(TAG, "[%0.3f] Timesync request #%d of %d sent at %d.%03d",
millis() / 1000.0, k + 1, TIME_SYNC_SAMPLES, timestamp / 1000,
timestamp % 1000);
} }
// process timeserver timestamp answer, called by myRxCallback() in lorawan.cpp // process timeserver timestamp answer, called by myRxCallback() in lorawan.cpp
@ -176,7 +161,7 @@ int recv_timesync_ans(const uint8_t buf[], const uint8_t buf_len) {
if (!timeSyncPending) if (!timeSyncPending)
return 0; // failure return 0; // failure
// extract 1 byte timerequest sequence number from buffer // extract 1 byte timerequest sequence number from payload
uint8_t seq_no = buf[0]; uint8_t seq_no = buf[0];
buf++; buf++;
@ -193,16 +178,14 @@ int recv_timesync_ans(const uint8_t buf[], const uint8_t buf_len) {
else { // we received a probably valid time frame else { // we received a probably valid time frame
uint8_t k = seq_no % TIME_SYNC_SAMPLES;
// pointers to 4 bytes containing UTC seconds since unix epoch, msb // pointers to 4 bytes containing UTC seconds since unix epoch, msb
uint32_t timestamp_sec, *timestamp_ptr; uint32_t timestamp_sec, *timestamp_ptr;
// extract 1 byte timezone from buffer (one step being 15min * 60s = 900s) // extract 1 byte timezone from payload (one step being 15min * 60s = 900s)
// uint32_t timezone_sec = buf[0] * 900; // for future use // uint32_t timezone_sec = buf[0] * 900; // for future use
buf++; buf++;
// extract 4 bytes timestamp from buffer // extract 4 bytes timestamp from payload
// and convert it to uint32_t, octet order is big endian // and convert it to uint32_t, octet order is big endian
timestamp_ptr = (uint32_t *)buf; timestamp_ptr = (uint32_t *)buf;
// swap byte order from msb to lsb, note: this is platform dependent // swap byte order from msb to lsb, note: this is platform dependent
@ -211,15 +194,17 @@ int recv_timesync_ans(const uint8_t buf[], const uint8_t buf_len) {
// extract 1 byte fractional seconds in 2^-8 second steps // extract 1 byte fractional seconds in 2^-8 second steps
// (= 1/250th sec), we convert this to ms // (= 1/250th sec), we convert this to ms
uint16_t timestamp_msec = 4 * buf[0]; uint16_t timestamp_msec = 4 * buf[0];
// calculate absolute time received from gateway
// construct the timepoint when message was seen on gateway time_t t = timestamp_sec + timestamp_msec / 1000;
time_sync_rx[k] += seconds(timestamp_sec) + milliseconds(timestamp_msec);
// we guess timepoint is recent if it is newer than code compile date // we guess timepoint is recent if it is newer than code compile date
if (timeIsValid(myClock::to_time_t(time_sync_rx[k]))) { if (timeIsValid(t)) {
ESP_LOGD(TAG, "[%0.3f] Timesync request #%d of %d rcvd at %d.%03d", ESP_LOGD(TAG, "[%0.3f] Timesync request seq#%d rcvd at %0.3f",
millis() / 1000.0, k + 1, TIME_SYNC_SAMPLES, timestamp_sec, millis() / 1000.0, seq_no, osticks2ms(os_getTime()) / 1000.0);
timestamp_msec);
// store time received from gateway
store_timestamp(timestamp_sec, gwtime_sec);
store_timestamp(timestamp_msec, gwtime_msec);
// inform processing task // inform processing task
xTaskNotify(timeSyncReqTask, seq_no, eSetBits); xTaskNotify(timeSyncReqTask, seq_no, eSetBits);