* 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

@@ -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();

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;

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      
+    #if MESH_PACKET_LOGGING
-      Serial.printf("PACKET: recv, len=%d (type=%d, route=%s, payload_len=%d) SNR=%d RSSI=%d score=%d\n", 
+    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));

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;

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