From fc02d8fbcb150531fca0bac631003f7173471ed4 Mon Sep 17 00:00:00 2001 From: Scott Powell Date: Thu, 20 Feb 2025 12:41:47 +1100 Subject: [PATCH] * Mesh/Dispatcher: MESH_DEBUG_ and MESH_PACKET_LOGGING now output date-time. (new getLogDateTime() virtual) * MESH_PACKET_LOGGING now parity with dynamic/file logging (src/dest hashes) --- examples/simple_repeater/main.cpp | 22 ++++++------ examples/simple_room_server/main.cpp | 8 +++++ src/Dispatcher.cpp | 41 ++++++++++++++++------ src/Dispatcher.h | 1 + src/Mesh.cpp | 51 ++++++++++++++++++---------- 5 files changed, 85 insertions(+), 38 deletions(-) diff --git a/examples/simple_repeater/main.cpp b/examples/simple_repeater/main.cpp index 5f46f222..ed3d9b25 100644 --- a/examples/simple_repeater/main.cpp +++ b/examples/simple_repeater/main.cpp @@ -229,14 +229,6 @@ class MyMesh : public mesh::Mesh { #endif } - const char* get_curr_time_str() { - static char tmp[32]; - uint32_t now = getRTCClock()->getCurrentTime(); - DateTime dt = DateTime(now); - sprintf(tmp, "%02d:%02d:%02d - %d/%d/%d U", dt.hour(), dt.minute(), dt.second(), dt.day(), dt.month(), dt.year()); - return tmp; - } - protected: float getAirtimeBudgetFactor() const override { return _prefs.airtime_factor; @@ -246,11 +238,19 @@ protected: return !_prefs.disable_fwd; } + const char* getLogDateTime() override { + static char tmp[32]; + uint32_t now = getRTCClock()->getCurrentTime(); + DateTime dt = DateTime(now); + sprintf(tmp, "%02d:%02d:%02d - %d/%d/%d U", dt.hour(), dt.minute(), dt.second(), dt.day(), dt.month(), dt.year()); + return tmp; + } + void logRx(mesh::Packet* pkt, int len, float score) override { if (_logging) { File f = openAppend(PACKET_LOG_FILE); if (f) { - f.print(get_curr_time_str()); + f.print(getLogDateTime()); f.printf(": RX, len=%d (type=%d, route=%s, payload_len=%d) SNR=%d RSSI=%d score=%d", len, pkt->getPayloadType(), pkt->isRouteDirect() ? "D" : "F", pkt->payload_len, (int)_radio->getLastSNR(), (int)_radio->getLastRSSI(), (int)(score*1000)); @@ -269,7 +269,7 @@ protected: if (_logging) { File f = openAppend(PACKET_LOG_FILE); if (f) { - f.print(get_curr_time_str()); + f.print(getLogDateTime()); f.printf(": TX, len=%d (type=%d, route=%s, payload_len=%d)", len, pkt->getPayloadType(), pkt->isRouteDirect() ? "D" : "F", pkt->payload_len); @@ -287,7 +287,7 @@ protected: if (_logging) { File f = openAppend(PACKET_LOG_FILE); if (f) { - f.print(get_curr_time_str()); + f.print(getLogDateTime()); f.printf(": TX FAIL!, len=%d (type=%d, route=%s, payload_len=%d)\n", len, pkt->getPayloadType(), pkt->isRouteDirect() ? "D" : "F", pkt->payload_len); f.close(); diff --git a/examples/simple_room_server/main.cpp b/examples/simple_room_server/main.cpp index 6e2638ec..0d7b4f64 100644 --- a/examples/simple_room_server/main.cpp +++ b/examples/simple_room_server/main.cpp @@ -284,6 +284,14 @@ protected: return (int) ((pow(_prefs.rx_delay_base, 0.85f - score) - 1.0) * air_time); } + const char* getLogDateTime() override { + static char tmp[32]; + uint32_t now = getRTCClock()->getCurrentTime(); + DateTime dt = DateTime(now); + sprintf(tmp, "%02d:%02d:%02d - %d/%d/%d U", dt.hour(), dt.minute(), dt.second(), dt.day(), dt.month(), dt.year()); + return tmp; + } + uint32_t getRetransmitDelay(const mesh::Packet* packet) override { uint32_t t = (_radio->getEstAirtimeFor(packet->path_len + packet->payload_len + 2) * _prefs.tx_delay_factor); return getRNG()->nextInt(0, 6)*t; diff --git a/src/Dispatcher.cpp b/src/Dispatcher.cpp index cda3c444..be282794 100644 --- a/src/Dispatcher.cpp +++ b/src/Dispatcher.cpp @@ -46,7 +46,8 @@ void Dispatcher::loop() { releasePacket(outbound); // return to pool outbound = NULL; } else if (millisHasNowPassed(outbound_expiry)) { - MESH_DEBUG_PRINTLN("Dispatcher::loop(): WARNING: outbound packed send timed out!"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Dispatcher::loop(): WARNING: outbound packed send timed out!"); _radio->onSendFinished(); logTxFail(outbound, 2 + outbound->path_len + outbound->payload_len); @@ -79,7 +80,8 @@ void Dispatcher::checkRecv() { if (len > 0) { pkt = _mgr->allocNew(); if (pkt == NULL) { - MESH_DEBUG_PRINTLN("Dispatcher::checkRecv(): WARNING: received data, no unused packets available!"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Dispatcher::checkRecv(): WARNING: received data, no unused packets available!"); } else { int i = 0; #ifdef NODE_ID @@ -95,7 +97,8 @@ void Dispatcher::checkRecv() { pkt->path_len = raw[i++]; if (pkt->path_len > MAX_PATH_SIZE || i + pkt->path_len > len) { - MESH_DEBUG_PRINTLN("Dispatcher::checkRecv(): partial or corrupt packet received, len=%d", len); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Dispatcher::checkRecv(): partial or corrupt packet received, len=%d", len); _mgr->free(pkt); // put back into pool pkt = NULL; } else { @@ -113,10 +116,17 @@ void Dispatcher::checkRecv() { } } if (pkt) { - #if MESH_PACKET_LOGGING - Serial.printf("PACKET: recv, len=%d (type=%d, route=%s, payload_len=%d) SNR=%d RSSI=%d score=%d\n", + #if MESH_PACKET_LOGGING + Serial.print(getLogDateTime()); + Serial.printf(": RX, len=%d (type=%d, route=%s, payload_len=%d) SNR=%d RSSI=%d score=%d", 2 + pkt->path_len + pkt->payload_len, pkt->getPayloadType(), pkt->isRouteDirect() ? "D" : "F", pkt->payload_len, (int)_radio->getLastSNR(), (int)_radio->getLastRSSI(), (int)(score*1000)); + if (pkt->getPayloadType() == PAYLOAD_TYPE_PATH || pkt->getPayloadType() == PAYLOAD_TYPE_REQ + || pkt->getPayloadType() == PAYLOAD_TYPE_RESPONSE || pkt->getPayloadType() == PAYLOAD_TYPE_TXT_MSG) { + Serial.printf(" [%02X -> %02X]\n", (uint32_t)pkt->payload[1], (uint32_t)pkt->payload[0]); + } else { + Serial.printf("\n"); + } #endif logRx(pkt, 2 + pkt->path_len + pkt->payload_len, score); // hook for custom logging @@ -125,10 +135,12 @@ void Dispatcher::checkRecv() { int _delay = calcRxDelay(score, air_time); if (_delay < 50) { - MESH_DEBUG_PRINTLN("Dispatcher::checkRecv(), score delay below threshold (%d)", _delay); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Dispatcher::checkRecv(), score delay below threshold (%d)", _delay); processRecvPacket(pkt); // is below the score delay threshold, so process immediately } else { - MESH_DEBUG_PRINTLN("Dispatcher::checkRecv(), score delay is: %d millis", _delay); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Dispatcher::checkRecv(), score delay is: %d millis", _delay); if (_delay > MAX_RX_DELAY_MILLIS) { _delay = MAX_RX_DELAY_MILLIS; } @@ -173,7 +185,8 @@ void Dispatcher::checkSend() { memcpy(&raw[len], outbound->path, outbound->path_len); len += outbound->path_len; if (len + outbound->payload_len > MAX_TRANS_UNIT) { - MESH_DEBUG_PRINTLN("Dispatcher::checkSend(): FATAL: Invalid packet queued... too long, len=%d", len + outbound->payload_len); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Dispatcher::checkSend(): FATAL: Invalid packet queued... too long, len=%d", len + outbound->payload_len); _mgr->free(outbound); outbound = NULL; } else { @@ -185,8 +198,15 @@ void Dispatcher::checkSend() { outbound_expiry = futureMillis(max_airtime); #if MESH_PACKET_LOGGING - Serial.printf("PACKET: send, len=%d (type=%d, route=%s, payload_len=%d)\n", + Serial.print(getLogDateTime()); + Serial.printf(": TX, len=%d (type=%d, route=%s, payload_len=%d)", len, outbound->getPayloadType(), outbound->isRouteDirect() ? "D" : "F", outbound->payload_len); + if (outbound->getPayloadType() == PAYLOAD_TYPE_PATH || outbound->getPayloadType() == PAYLOAD_TYPE_REQ + || outbound->getPayloadType() == PAYLOAD_TYPE_RESPONSE || outbound->getPayloadType() == PAYLOAD_TYPE_TXT_MSG) { + Serial.printf(" [%02X -> %02X]\n", (uint32_t)outbound->payload[1], (uint32_t)outbound->payload[0]); + } else { + Serial.printf("\n"); + } #endif } } @@ -208,7 +228,8 @@ void Dispatcher::releasePacket(Packet* packet) { void Dispatcher::sendPacket(Packet* packet, uint8_t priority, uint32_t delay_millis) { if (packet->path_len > MAX_PATH_SIZE || packet->payload_len > MAX_PACKET_PAYLOAD) { - MESH_DEBUG_PRINTLN("Dispatcher::sendPacket(): ERROR: invalid packet... path_len=%d, payload_len=%d", (uint32_t) packet->path_len, (uint32_t) packet->payload_len); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Dispatcher::sendPacket(): ERROR: invalid packet... path_len=%d, payload_len=%d", (uint32_t) packet->path_len, (uint32_t) packet->payload_len); _mgr->free(packet); } else { _mgr->queueOutbound(packet, priority, futureMillis(delay_millis)); diff --git a/src/Dispatcher.h b/src/Dispatcher.h index d77e1f18..e2ba60cb 100644 --- a/src/Dispatcher.h +++ b/src/Dispatcher.h @@ -120,6 +120,7 @@ protected: virtual void logRx(Packet* packet, int len, float score) { } // hooks for custom logging virtual void logTx(Packet* packet, int len) { } virtual void logTxFail(Packet* packet, int len) { } + virtual const char* getLogDateTime() { return ""; } virtual float getAirtimeBudgetFactor() const; virtual int calcRxDelay(float score, uint32_t air_time) const; diff --git a/src/Mesh.cpp b/src/Mesh.cpp index 96092f30..dbc17ad5 100644 --- a/src/Mesh.cpp +++ b/src/Mesh.cpp @@ -30,7 +30,8 @@ int Mesh::searchChannelsByHash(const uint8_t* hash, GroupChannel channels[], int DispatcherAction Mesh::onRecvPacket(Packet* pkt) { if (pkt->getPayloadVer() > PAYLOAD_VER_1) { // not supported in this firmware version - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): unsupported packet version"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): unsupported packet version"); return ACTION_RELEASE; } @@ -54,7 +55,8 @@ DispatcherAction Mesh::onRecvPacket(Packet* pkt) { uint32_t ack_crc; memcpy(&ack_crc, &pkt->payload[i], 4); i += 4; if (i > pkt->payload_len) { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): incomplete ACK packet"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): incomplete ACK packet"); } else if (!_tables->hasSeen(pkt)) { onAckRecv(pkt, ack_crc); action = routeRecvPacket(pkt); @@ -71,7 +73,8 @@ DispatcherAction Mesh::onRecvPacket(Packet* pkt) { uint8_t* macAndData = &pkt->payload[i]; // MAC + encrypted data if (i + 2 >= pkt->payload_len) { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): incomplete data packet"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): incomplete data packet"); } else if (!_tables->hasSeen(pkt)) { // NOTE: this is a 'first packet wins' impl. When receiving from multiple paths, the first to arrive wins. // For flood mode, the path may not be the 'best' in terms of hops. @@ -114,7 +117,8 @@ DispatcherAction Mesh::onRecvPacket(Packet* pkt) { if (found) { pkt->markDoNotRetransmit(); // packet was for this node, so don't retransmit } else { - MESH_DEBUG_PRINTLN("recv matches no peers, src_hash=%02X", (uint32_t)src_hash); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" recv matches no peers, src_hash=%02X", (uint32_t)src_hash); } } action = routeRecvPacket(pkt); @@ -128,7 +132,8 @@ DispatcherAction Mesh::onRecvPacket(Packet* pkt) { uint8_t* macAndData = &pkt->payload[i]; // MAC + encrypted data if (i + 2 >= pkt->payload_len) { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): incomplete data packet"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): incomplete data packet"); } else if (!_tables->hasSeen(pkt)) { if (self_id.isHashMatch(&dest_hash)) { Identity sender(sender_pub_key); @@ -155,7 +160,8 @@ DispatcherAction Mesh::onRecvPacket(Packet* pkt) { uint8_t* macAndData = &pkt->payload[i]; // MAC + encrypted data if (i + 2 >= pkt->payload_len) { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): incomplete data packet"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): incomplete data packet"); } else if (!_tables->hasSeen(pkt)) { // scan channels DB, for all matching hashes of 'channel_hash' (max 2 matches supported ATM) GroupChannel channels[2]; @@ -184,9 +190,11 @@ DispatcherAction Mesh::onRecvPacket(Packet* pkt) { const uint8_t* signature = &pkt->payload[i]; i += SIGNATURE_SIZE; if (i > pkt->payload_len) { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): incomplete advertisement packet"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): incomplete advertisement packet"); } else if (self_id.matches(id.pub_key)) { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): receiving SELF advert packet"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): receiving SELF advert packet"); } else if (!_tables->hasSeen(pkt)) { uint8_t* app_data = &pkt->payload[i]; int app_data_len = pkt->payload_len - i; @@ -204,17 +212,20 @@ DispatcherAction Mesh::onRecvPacket(Packet* pkt) { is_ok = id.verify(signature, message, msg_len); } if (is_ok) { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): valid advertisement received!"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): valid advertisement received!"); onAdvertRecv(pkt, id, timestamp, app_data, app_data_len); action = routeRecvPacket(pkt); } else { - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): received advertisement with forged signature! (app_data_len=%d)", app_data_len); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): received advertisement with forged signature! (app_data_len=%d)", app_data_len); } } break; } default: - MESH_DEBUG_PRINTLN("Mesh::onRecvPacket(): unknown payload type, header: %d", (int) pkt->header); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::onRecvPacket(): unknown payload type, header: %d", (int) pkt->header); // Don't flood route unknown packet types! action = routeRecvPacket(pkt); break; } @@ -239,7 +250,8 @@ Packet* Mesh::createAdvert(const LocalIdentity& id, const uint8_t* app_data, siz Packet* packet = obtainNewPacket(); if (packet == NULL) { - MESH_DEBUG_PRINTLN("Mesh::createAdvert(): error, packet pool empty"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::createAdvert(): error, packet pool empty"); return NULL; } @@ -283,7 +295,8 @@ Packet* Mesh::createPathReturn(const uint8_t* dest_hash, const uint8_t* secret, Packet* packet = obtainNewPacket(); if (packet == NULL) { - MESH_DEBUG_PRINTLN("Mesh::createPathReturn(): error, packet pool empty"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::createPathReturn(): error, packet pool empty"); return NULL; } packet->header = (PAYLOAD_TYPE_PATH << PH_TYPE_SHIFT); // ROUTE_TYPE_* set later @@ -324,7 +337,8 @@ Packet* Mesh::createDatagram(uint8_t type, const Identity& dest, const uint8_t* Packet* packet = obtainNewPacket(); if (packet == NULL) { - MESH_DEBUG_PRINTLN("Mesh::createDatagram(): error, packet pool empty"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::createDatagram(): error, packet pool empty"); return NULL; } packet->header = (type << PH_TYPE_SHIFT); // ROUTE_TYPE_* set later @@ -348,7 +362,8 @@ Packet* Mesh::createAnonDatagram(uint8_t type, const LocalIdentity& sender, cons Packet* packet = obtainNewPacket(); if (packet == NULL) { - MESH_DEBUG_PRINTLN("Mesh::createAnonDatagram(): error, packet pool empty"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::createAnonDatagram(): error, packet pool empty"); return NULL; } packet->header = (type << PH_TYPE_SHIFT); // ROUTE_TYPE_* set later @@ -373,7 +388,8 @@ Packet* Mesh::createGroupDatagram(uint8_t type, const GroupChannel& channel, con Packet* packet = obtainNewPacket(); if (packet == NULL) { - MESH_DEBUG_PRINTLN("Mesh::createGroupDatagram(): error, packet pool empty"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::createGroupDatagram(): error, packet pool empty"); return NULL; } packet->header = (type << PH_TYPE_SHIFT); // ROUTE_TYPE_* set later @@ -390,7 +406,8 @@ Packet* Mesh::createGroupDatagram(uint8_t type, const GroupChannel& channel, con Packet* Mesh::createAck(uint32_t ack_crc) { Packet* packet = obtainNewPacket(); if (packet == NULL) { - MESH_DEBUG_PRINTLN("Mesh::createAck(): error, packet pool empty"); + MESH_DEBUG_PRINT(getLogDateTime()); + MESH_DEBUG_PRINTLN(" Mesh::createAck(): error, packet pool empty"); return NULL; } packet->header = (PAYLOAD_TYPE_ACK << PH_TYPE_SHIFT); // ROUTE_TYPE_* set later