Hi,
To make testing easier for the fix of ‘ESP32 time drifts quite quickly’, I made a basic logging system for the device code. If the node knows GPS time it will use UTC time for all log messages. We also now show the current threadname (when relevant) in the log messages.
This will eventually also allow us to do different levels of logging (INFO, DEBUG, WARN, ERROR etc).
If you are developing the logs will now look different.
00:00:06 [Screen] Setting idle framerate
00:00:06 [RadioIf] Completed sending (id=0x2e50c657 Fr0x58 To0xff, WantAck0, HopLim2 encrypted)
00:00:08 [RadioIf] Can not send yet, busyRx
00:00:10 [RadioIf] Can not send yet, busyRx
00:00:10 [RadioIf] Can not send yet, busyRx
00:00:11 [RadioIf] Lora RX (id=0x2e50c657 Fr0x58 To0xff, WantAck0, HopLim1 encrypted rxSNR=2.75)
00:00:11 [Router] Rx someone rebroadcasting for us (id=0x2e50c657 Fr0x58 To0xff, WantAck0, HopLim1 encrypted rxSNR=2.75)
00:00:11 [Router] Found existing packet record for fr=0x28979058,to=0xffffffff,id=777045591
00:00:11 [Router] Ignoring incoming msg, because we've already seen it (id=0x2e50c657 Fr0x58 To0xff, WantAck0, HopLim1 encrypted rxSNR=2.75)
00:00:12 [RadioIf] Starting low level send (id=0x2e50c657 Fr0x58 To0xff, WantAck0, HopLim3 encrypted)
00:00:14 [RadioIf] Completed sending (id=0x2e50c657 Fr0x58 To0xff, WantAck0, HopLim3 encrypted)
00:00:19 [RadioIf] Lora RX (id=0x21d3898e Fr0x98 To0x58, WantAck0, HopLim3 encrypted rxSNR=2.25)
00:00:19 [Router] Adding packet record (id=0x21d3898e Fr0x98 To0x58, WantAck0, HopLim3 encrypted rxSNR=2.25)
00:00:19 [Router] FIXME not implemented addRoute
00:00:19 [Router] FIXME-update-db Sniffing packet
00:00:19 [Router] Delivering rx packet (id=0x21d3898e Fr0x98 To0x58, WantAck0, HopLim3 Portnum=3 rxSNR=2.25)
Trigger powerFSM 3
00:00:19 [Router] Forwarding to phone (id=0x21d3898e Fr0x98 To0x58, WantAck0, HopLim3 Portnum=3 rxSNR=2.25)
00:00:19 [Router] Update DB node 0xabf84098, rx_time=0
00:00:19 [Router] Received position from=0xabf84098, id=0x21d3898e, payloadlen=22
00:00:19 [Router] Setting RTC 1608880684 secs
07:18:04 [Router] Read RTC time as 1608880684 (cur millis 19904) quality=1
07:18:04 [Router] DB update position node=0xabf84098 time=1608880684, latI=241726216, lonI=1206357806
07:18:04 [Router] Node status update: 1 online, 2 total
07:18:04 [Router] Plugin position handled=0
07:18:04 Telling client we have new packets 4
07:18:04 Telling client we have new packets 4
07:18:04 No BLE notify
07:18:06 [Power] Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
07:18:16 [SendOwner] Sending our nodeinfo to mesh (wantReplies=1)
07:18:16 [SendOwner] sending owner !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] Update DB node 0x28979058, rx_time=1608880696
07:18:16 [SendOwner] Received nodeinfo from=0x28979058, id=0x2e50c65a, payloadlen=42
07:18:16 [SendOwner] old user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] updating changed=0 user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] sending owner !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] Sending response
07:18:16 [SendOwner] Update DB node 0x28979058, rx_time=1608880696
07:18:16 [SendOwner] Received nodeinfo from=0x28979058, id=0x2e50c65b, payloadlen=42
07:18:16 [SendOwner] old user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] updating changed=0 user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] Plugin nodeinfo handled=0
07:18:16 [SendOwner] Enqueuing local (id=0x2e50c65b Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
07:18:16 [SendOwner] Plugin nodeinfo handled=0
07:18:16 [SendOwner] Rebroadcasting received floodmsg to neighbors (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim3 Portnum=4 WANTRESP rxtime=1608880696)
07:18:16 [SendOwner] enqueuing for send (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim2 encrypted rxtime=1608880696)
07:18:16 [SendOwner] (bw=125, sf=12, cr=4/8) packet symLen=32 ms, payloadSize=66, time 4890 ms
07:18:16 [SendOwner] txGood=2,rxGood=2,rxBad=0
07:18:16 [SendOwner] FIXME-update-db Sniffing packet
07:18:16 [SendOwner] Delivering rx packet (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim3 Portnum=4 WANTRESP rxtime=1608880696)
Trigger powerFSM 3
07:18:16 [SendOwner] Forwarding to phone (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim3 Portnum=4 WANTRESP rxtime=1608880696)
07:18:16 [SendOwner] Update DB node 0x28979058, rx_time=1608880696
07:18:16 [SendOwner] Received nodeinfo from=0x28979058, id=0x2e50c65a, payloadlen=42
07:18:16 [SendOwner] old user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] updating changed=0 user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] sending owner !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] Sending response
07:18:16 [SendOwner] Update DB node 0x28979058, rx_time=1608880696
07:18:16 [SendOwner] Received nodeinfo from=0x28979058, id=0x2e50c65c, payloadlen=42
07:18:16 [SendOwner] old user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] updating changed=0 user !246f28979058/Unknown 9058/?58
07:18:16 [SendOwner] Plugin nodeinfo handled=0
07:18:16 [SendOwner] Enqueuing local (id=0x2e50c65c Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
07:18:16 [SendOwner] Plugin nodeinfo handled=0
07:18:16 [SendOwner] Adding packet record (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim3 Portnum=4 WANTRESP rxtime=1608880696)
07:18:16 [SendOwner] enqueuing for send (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim3 encrypted rxtime=1608880696)
07:18:16 [SendOwner] (bw=125, sf=12, cr=4/8) packet symLen=32 ms, payloadSize=66, time 4890 ms
07:18:16 [SendOwner] txGood=2,rxGood=2,rxBad=0
07:18:16 Telling client we have new packets 5
07:18:16 Telling client we have new packets 5
07:18:16 No BLE notify
07:18:16 [Router] Adding packet record (id=0x2e50c65b Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
07:18:16 [Router] FIXME not implemented addRoute
07:18:16 [Router] FIXME-update-db Sniffing packet
07:18:16 [Router] Delivering rx packet (id=0x2e50c65b Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
Trigger powerFSM 3
07:18:16 [Router] Forwarding to phone (id=0x2e50c65b Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
07:18:16 [Router] Update DB node 0x28979058, rx_time=1608880696
07:18:16 [Router] Received nodeinfo from=0x28979058, id=0x2e50c65b, payloadlen=42
07:18:16 [Router] old user !246f28979058/Unknown 9058/?58
07:18:16 [Router] updating changed=0 user !246f28979058/Unknown 9058/?58
07:18:16 [Router] Plugin nodeinfo handled=0
07:18:16 [Router] Adding packet record (id=0x2e50c65c Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
07:18:16 [Router] FIXME not implemented addRoute
07:18:16 [Router] FIXME-update-db Sniffing packet
07:18:16 [Router] Delivering rx packet (id=0x2e50c65c Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
Trigger powerFSM 3
07:18:16 [Router] Forwarding to phone (id=0x2e50c65c Fr0x58 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880696)
07:18:16 [Router] Update DB node 0x28979058, rx_time=1608880696
07:18:16 [Router] Received nodeinfo from=0x28979058, id=0x2e50c65c, payloadlen=42
07:18:16 [Router] old user !246f28979058/Unknown 9058/?58
07:18:16 [Router] updating changed=0 user !246f28979058/Unknown 9058/?58
07:18:16 [Router] Plugin nodeinfo handled=0
07:18:16 [Screen] Screen: Joined: Unknown 9058
Screen: Joined: Unknown 9058
Telling client we have new packets 7
07:18:17 Telling client we have new packets 7
07:18:17 No BLE notify
07:18:18 [RadioIf] Starting low level send (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim2 encrypted rxtime=1608880696)
07:18:23 [RadioIf] Completed sending (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim2 encrypted rxtime=1608880696)
07:18:26 [RadioIf] Can not send yet, busyRx
07:18:26 [RadioIf] Can not send yet, busyRx
07:18:26 [Power] Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
07:18:28 [RadioIf] Can not send yet, busyRx
07:18:30 [RadioIf] Lora RX (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim1 encrypted rxSNR=2.75)
07:18:30 [Router] Rx someone rebroadcasting for us (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim1 encrypted rxSNR=2.75)
07:18:30 [Router] Found existing packet record for fr=0x28979058,to=0xffffffff,id=777045594
07:18:30 [Router] Ignoring incoming msg, because we've already seen it (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim1 encrypted rxSNR=2.75)
07:18:32 [RadioIf] Can not send yet, busyRx
07:18:32 [RadioIf] Can not send yet, busyRx
07:18:33 [RadioIf] Can not send yet, busyRx
07:18:34 [RadioIf] Can not send yet, busyRx
07:18:35 [RadioIf] Lora RX (id=0x21d3898f Fr0x98 To0x58, WantAck0, HopLim3 encrypted rxSNR=1.75)
07:18:35 [Router] Adding packet record (id=0x21d3898f Fr0x98 To0x58, WantAck0, HopLim3 encrypted rxSNR=1.75)
07:18:35 [Router] FIXME not implemented addRoute
07:18:35 [Router] FIXME-update-db Sniffing packet
07:18:35 [Router] Delivering rx packet (id=0x21d3898f Fr0x98 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880715 rxSNR=1.75)
Trigger powerFSM 3
07:18:35 [Router] Forwarding to phone (id=0x21d3898f Fr0x98 To0x58, WantAck0, HopLim3 Portnum=4 rxtime=1608880715 rxSNR=1.75)
07:18:35 [Router] Update DB node 0xabf84098, rx_time=1608880715
07:18:35 [Router] Received nodeinfo from=0xabf84098, id=0x21d3898f, payloadlen=36
07:18:35 [Router] old user !2462abf84098/Node 98/N9
07:18:35 [Router] updating changed=0 user !2462abf84098/Node 98/N9
07:18:35 [Router] Plugin nodeinfo handled=0
07:18:35 Telling client we have new packets 8
07:18:35 Telling client we have new packets 8
07:18:35 No BLE notify
07:18:36 [RadioIf] Starting low level send (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim3 encrypted rxtime=1608880696)
07:18:41 [RadioIf] Completed sending (id=0x2e50c65a Fr0x58 To0xff, WantAck0, HopLim3 encrypted rxtime=1608880696)
07:18:46 [Power] Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
07:19:07 [Power] Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
07:19:27 [Power] Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
07:19:47 [Power] Battery: usbPower=1, isCharging=0, batMv=0, batPct=0