Add debugging

app/event_handlers.py

@@ -44,16 +44,19 @@ async def on_contact_message(event: "Event") -> None:
     The packet processor cannot decrypt these without the node's private key.
     """
     payload = event.payload
+    pubkey_prefix = payload.get("pubkey_prefix", "unknown")
+    text_preview = payload.get("text", "")[:50]
+
+    logger.info("[DM] CONTACT_MSG_RECV from %s: %s%s",
+                pubkey_prefix, text_preview, "..." if len(payload.get("text", "")) > 50 else "")
 
     # Skip CLI command responses (txt_type=1) - these are handled by the command endpoint
     # and should not be stored in the database or broadcast via WebSocket
     txt_type = payload.get("txt_type", 0)
     if txt_type == 1:
-        logger.debug("Skipping CLI response from %s (txt_type=1)", payload.get("pubkey_prefix"))
+        logger.info("[DM] Skipping CLI response from %s (txt_type=1)", pubkey_prefix)
         return
 
-    logger.debug("Received direct message from %s", payload.get("pubkey_prefix"))
-
     # Get full public key if available, otherwise use prefix
     sender_pubkey = payload.get("public_key") or payload.get("pubkey_prefix", "")
     received_at = int(time.time())
@@ -109,21 +112,29 @@ async def on_rx_log_data(event: "Event") -> None:
     handles channel messages (GROUP_TEXT) and advertisements (ADVERT).
     """
     payload = event.payload
-    logger.debug("Received RX log data packet")
 
     if "payload" not in payload:
-        logger.warning("RX_LOG_DATA event missing 'payload' field")
+        logger.warning("[RX] RX_LOG_DATA event missing 'payload' field: %s", payload)
         return
 
     raw_hex = payload["payload"]
     raw_bytes = bytes.fromhex(raw_hex)
+    snr = payload.get("snr")
+    rssi = payload.get("rssi")
 
-    await process_raw_packet(
+    logger.info("[RX] RX_LOG_DATA received: %d bytes, SNR=%.1f, RSSI=%s",
+                len(raw_bytes), snr if snr is not None else 0, rssi)
+
+    result = await process_raw_packet(
         raw_bytes=raw_bytes,
-        snr=payload.get("snr"),
-        rssi=payload.get("rssi"),
+        snr=snr,
+        rssi=rssi,
     )
 
+    logger.info("[RX] Processed: type=%s, decrypted=%s, channel=%s, msg_id=%s",
+                result.get("payload_type"), result.get("decrypted"),
+                result.get("channel_name"), result.get("message_id"))
+
 
 async def on_path_update(event: "Event") -> None:
     """Handle path update events."""
@@ -193,9 +204,15 @@ def register_event_handlers(meshcore) -> None:
     These are handled by the packet processor via RX_LOG_DATA to avoid
     duplicate processing and ensure consistent handling.
     """
+    logger.info("[INIT] Registering event handlers...")
     meshcore.subscribe(EventType.CONTACT_MSG_RECV, on_contact_message)
+    logger.info("[INIT] Subscribed to CONTACT_MSG_RECV (direct messages)")
     meshcore.subscribe(EventType.RX_LOG_DATA, on_rx_log_data)
+    logger.info("[INIT] Subscribed to RX_LOG_DATA (raw packets for channel messages)")
     meshcore.subscribe(EventType.PATH_UPDATE, on_path_update)
+    logger.info("[INIT] Subscribed to PATH_UPDATE")
     meshcore.subscribe(EventType.NEW_CONTACT, on_new_contact)
+    logger.info("[INIT] Subscribed to NEW_CONTACT")
     meshcore.subscribe(EventType.ACK, on_ack)
-    logger.info("Event handlers registered")
+    logger.info("[INIT] Subscribed to ACK")
+    logger.info("[INIT] All event handlers registered successfully")

app/main.py

@@ -30,25 +30,27 @@ async def lifespan(app: FastAPI):
 
     try:
         await radio_manager.connect()
-        logger.info("Connected to radio")
+        logger.info("[STARTUP] Connected to radio at %s", radio_manager.port)
         if radio_manager.meshcore:
+            logger.info("[STARTUP] Registering event handlers for message reception...")
             register_event_handlers(radio_manager.meshcore)
 
             # Sync contacts/channels from radio to DB and clear radio
-            logger.info("Syncing and offloading radio data...")
+            logger.info("[STARTUP] Syncing and offloading radio data...")
             result = await sync_and_offload_all()
-            logger.info("Sync complete: %s", result)
+            logger.info("[STARTUP] Sync complete: %s", result)
 
             # Start periodic sync
             start_periodic_sync()
 
             # Send advertisement to announce our presence
-            logger.info("Sending startup advertisement...")
+            logger.info("[STARTUP] Sending startup advertisement...")
             advert_result = await radio_manager.meshcore.commands.send_advert(flood=True)
-            logger.info("Advertisement sent: %s", advert_result.type)
+            logger.info("[STARTUP] Advertisement sent: %s", advert_result.type)
 
+            logger.info("[STARTUP] Starting auto message fetching...")
             await radio_manager.meshcore.start_auto_message_fetching()
-            logger.info("Auto message fetching started")
+            logger.info("[STARTUP] Auto message fetching started - ready to receive messages")
     except Exception as e:
         logger.warning("Failed to connect to radio on startup: %s", e)
 

app/packet_processor.py

@@ -134,7 +134,7 @@ async def process_raw_packet(
     # If packet_id is None, this is a duplicate packet (same data already exists)
     # Skip processing since we've already handled this exact packet
     if packet_id is None:
-        logger.debug("Duplicate raw packet detected, skipping")
+        logger.info("[PKT] Duplicate packet detected (same bytes), skipping")
         return {
             "packet_id": None,
             "timestamp": ts,
@@ -155,6 +155,9 @@ async def process_raw_packet(
     payload_type = packet_info.payload_type if packet_info else None
     payload_type_name = payload_type.name if payload_type else "Unknown"
 
+    logger.info("[PKT] New packet id=%d, type=%s, %d bytes",
+                packet_id, payload_type_name, len(raw_bytes))
+
     result = {
         "packet_id": packet_id,
         "timestamp": ts,
@@ -217,6 +220,7 @@ async def _process_group_text(
     """
     # Try to decrypt with all known channel keys
     channels = await ChannelRepository.get_all()
+    logger.info("[CHAN] Attempting decryption with %d known channel keys", len(channels))
 
     for channel in channels:
         # Convert hex key to bytes for decryption
@@ -230,10 +234,9 @@ async def _process_group_text(
             continue
 
         # Successfully decrypted!
-        logger.debug(
-            "Decrypted GroupText for channel %s: %s",
-            channel.name, decrypted.message[:50]
-        )
+        logger.info("[CHAN] Decrypted with channel '%s': %s%s",
+                    channel.name, decrypted.message[:50],
+                    "..." if len(decrypted.message) > 50 else "")
 
         # Check for repeat detection (our own message echoed back)
         is_repeat = False
@@ -326,6 +329,7 @@ async def _process_group_text(
         }
 
     # Couldn't decrypt with any known key
+    logger.info("[CHAN] No matching channel key found for GROUP_TEXT packet")
     return None
 
 
@@ -341,10 +345,11 @@ async def _process_advertisement(
     """
     advert = try_parse_advertisement(raw_bytes)
     if not advert:
-        logger.debug("Failed to parse advertisement packet")
+        logger.info("[ADVERT] Failed to parse advertisement packet")
         return
 
-    logger.debug("Parsed advertisement from %s: %s", advert.public_key[:12], advert.name)
+    logger.info("[ADVERT] From %s: name='%s', lat=%.4f, lon=%.4f",
+                advert.public_key[:12], advert.name, advert.lat or 0, advert.lon or 0)
 
     # Try to find existing contact
     existing = await ContactRepository.get_by_key(advert.public_key)

app/radio.py

@@ -137,11 +137,8 @@ class RadioManager:
             if not port:
                 raise RuntimeError("No MeshCore radio found. Please specify MESHCORE_SERIAL_PORT.")
 
-        logger.debug(
-            "Connecting to radio at %s (baud %d)",
-            port,
-            settings.serial_baudrate,
-        )
+        logger.info("[RADIO] Connecting to radio at %s (baud %d)...",
+                    port, settings.serial_baudrate)
         self._meshcore = await MeshCore.create_serial(
             port=port,
             baudrate=settings.serial_baudrate,
@@ -150,7 +147,11 @@ class RadioManager:
         )
         self._port = port
         self._last_connected = True
-        logger.debug("Serial connection established")
+        logger.info("[RADIO] Serial connection established to %s", port)
+        if self._meshcore.self_info:
+            logger.info("[RADIO] Radio info: name='%s', pubkey=%s...",
+                        self._meshcore.self_info.get("name", "unknown"),
+                        self._meshcore.self_info.get("public_key", "")[:16])
 
     async def disconnect(self) -> None:
         """Disconnect from the radio."""