Log the node time on startup

This commit is contained in:
Jack Kingsman committed 2026-03-16 22:44:53 -07:00
1 parent a0459edf62
commit bc16d804e9
6 files changed
+25 -141

No files matched your search

+18
View File
@@ -1,5 +1,6 @@
import asyncio import asyncio
import logging import logging
from datetime import datetime, timezone
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)
@@ -180,6 +181,23 @@ async def run_post_connect_setup(radio_manager) -> None:
else "unknown", else "unknown",
radio_manager.max_channels, radio_manager.max_channels,
) )
try:
time_result = await mc.commands.get_time()
radio_time = (
time_result.payload.get("time")
if time_result is not None and time_result.payload
else None
)
if isinstance(radio_time, int):
logger.info(
"Radio clock at connect: epoch=%d utc=%s",
radio_time,
datetime.fromtimestamp(radio_time, timezone.utc).strftime(
"%Y-%m-%d %H:%M:%S UTC"
),
)
except Exception as exc:
logger.debug("Failed to query radio clock after device info: %s", exc)
logger.info("Max channel slots: %d", radio_manager.max_channels) logger.info("Max channel slots: %d", radio_manager.max_channels)
except Exception as exc: except Exception as exc:
logger.debug("Failed to query device info capabilities: %s", exc) logger.debug("Failed to query device info capabilities: %s", exc)
-103
View File
@@ -6,7 +6,6 @@ Uses httpx.AsyncClient or direct function calls with real in-memory SQLite.
import hashlib import hashlib
import json import json
import logging
import time import time
from unittest.mock import AsyncMock, MagicMock, patch from unittest.mock import AsyncMock, MagicMock, patch
@@ -124,108 +123,6 @@ class TestHealthEndpoint:
class TestDebugEndpoint: class TestDebugEndpoint:
"""Test the debug support snapshot endpoint.""" """Test the debug support snapshot endpoint."""
@pytest.mark.asyncio
async def test_support_snapshot_returns_logs_and_live_radio_audits(self, test_db, client):
"""Debug snapshot should include recent logs plus live radio/contact/channel state."""
from meshcore import EventType
from app.config import clear_recent_log_lines
from app.routers.debug import (
LOG_COPY_BOUNDARY_LINE,
LOG_COPY_BOUNDARY_MESSAGE,
DebugApplicationInfo,
)
clear_recent_log_lines()
contact_key = "ab" * 32
channel_key = "CD" * 16
await _insert_contact(contact_key, "Alice", last_contacted=1700000000)
await ChannelRepository.upsert(key=channel_key, name="#flightless", on_radio=False)
await MessageRepository.create(
msg_type="CHAN",
text="Alice: hello",
received_at=1700000001,
conversation_key=channel_key,
sender_timestamp=1700000001,
)
radio_manager.max_channels = 2
radio_manager.path_hash_mode = 1
radio_manager.path_hash_mode_supported = True
radio_manager._connection_info = "Serial: /dev/ttyUSB0"
radio_manager.note_channel_slot_loaded(channel_key, 0)
mock_mc = MagicMock()
mock_mc.self_info = {"name": "TestNode", "radio_freq": 910.525}
mock_mc.stop_auto_message_fetching = AsyncMock()
mock_mc.start_auto_message_fetching = AsyncMock()
mock_mc.commands.send_device_query = AsyncMock(
return_value=MagicMock(type=EventType.DEVICE_INFO, payload={"max_channels": 2})
)
mock_mc.commands.get_stats_core = AsyncMock(
return_value=MagicMock(type=EventType.STATS_CORE, payload={"heap_free": 1234})
)
mock_mc.commands.get_stats_radio = AsyncMock(
return_value=MagicMock(type=EventType.STATS_RADIO, payload={"tx_good": 9})
)
mock_mc.commands.get_contacts = AsyncMock(
return_value=MagicMock(
type=EventType.OK,
payload={contact_key: {"adv_name": "Alice"}},
)
)
def _channel_event(slot: int) -> MagicMock:
if slot == 0:
return MagicMock(
type=EventType.CHANNEL_INFO,
payload={
"channel_name": "#flightless",
"channel_secret": bytes.fromhex(channel_key),
},
)
return MagicMock(type=EventType.OK, payload={})
mock_mc.commands.get_channel = AsyncMock(side_effect=_channel_event)
radio_manager._meshcore = mock_mc
logging.getLogger("tests.debug").warning("support snapshot marker")
with patch(
"app.routers.debug._build_application_info",
return_value=DebugApplicationInfo(
version="3.2.0",
commit_hash="deadbeef",
git_branch="main",
git_dirty=False,
python_version="3.12.0",
),
):
response = await client.get("/api/debug")
assert response.status_code == 200
payload = response.json()
assert payload["application"]["commit_hash"] == "deadbeef"
assert payload["runtime"]["channel_slot_reuse_enabled"] is True
assert payload["runtime"]["channels_with_incoming_messages"] == 1
assert payload["logs"][:4] == [LOG_COPY_BOUNDARY_LINE] * 4
assert payload["logs"][4] == LOG_COPY_BOUNDARY_MESSAGE
assert payload["logs"][5:9] == [LOG_COPY_BOUNDARY_LINE] * 4
assert any("support snapshot marker" in line for line in payload["logs"])
radio_probe = payload["radio_probe"]
assert radio_probe["performed"] is True
assert radio_probe["device_info"] == {"max_channels": 2}
assert radio_probe["stats_core"] == {"heap_free": 1234}
assert radio_probe["stats_radio"] == {"tx_good": 9}
assert radio_probe["contacts"]["expected_and_found"] == 1
assert radio_probe["contacts"]["expected_but_not_found"] == []
assert radio_probe["contacts"]["found_but_not_expected"] == []
assert radio_probe["channels"]["matched_slots"] == 2
assert radio_probe["channels"]["wrong_slots"] == []
@pytest.mark.asyncio @pytest.mark.asyncio
async def test_support_snapshot_returns_runtime_when_disconnected(self, test_db, client): async def test_support_snapshot_returns_runtime_when_disconnected(self, test_db, client):
"""Debug snapshot should still return logs and runtime state when radio is disconnected.""" """Debug snapshot should still return logs and runtime state when radio is disconnected."""
+2 -7
View File
@@ -448,7 +448,7 @@ class TestAdvertisementParsing:
assert result.lat is None assert result.lat is None
assert result.lon is None assert result.lon is None
def test_parse_advertisement_discards_out_of_range_gps(self, caplog): def test_parse_advertisement_discards_out_of_range_gps(self):
"""Out-of-range advert coordinates are treated as missing.""" """Out-of-range advert coordinates are treated as missing."""
from app.decoder import parse_advertisement from app.decoder import parse_advertisement
@@ -464,8 +464,7 @@ class TestAdvertisementParsing:
payload.extend(b"Tacompton") payload.extend(b"Tacompton")
raw_packet = bytes.fromhex("11") + bytes(payload) raw_packet = bytes.fromhex("11") + bytes(payload)
with caplog.at_level("WARNING"): result = parse_advertisement(bytes(payload), raw_packet=raw_packet)
result = parse_advertisement(bytes(payload), raw_packet=raw_packet)
assert result is not None assert result is not None
assert ( assert (
@@ -475,10 +474,6 @@ class TestAdvertisementParsing:
assert result.device_role == 2 assert result.device_role == 2
assert result.lat is None assert result.lat is None
assert result.lon is None assert result.lon is None
assert "Dropping location data for nonsensical packet -- packet" in caplog.text
assert raw_packet.hex().upper() in caplog.text
assert "-593.497573/-1659.939204" in caplog.text
assert "Outta this world!" in caplog.text
def test_parse_advertisement_extracts_public_key(self): def test_parse_advertisement_extracts_public_key(self):
"""Advertisement parsing extracts the public key correctly.""" """Advertisement parsing extracts the public key correctly."""
+4 -10
View File
@@ -1,5 +1,3 @@
import logging
from fastapi import FastAPI from fastapi import FastAPI
from fastapi.testclient import TestClient from fastapi.testclient import TestClient
@@ -14,15 +12,13 @@ from app.frontend_static import (
) )
def test_missing_dist_logs_error_and_keeps_app_running(tmp_path, caplog): def test_missing_dist_keeps_app_running(tmp_path):
app = FastAPI() app = FastAPI()
missing_dist = tmp_path / "frontend" / "dist" missing_dist = tmp_path / "frontend" / "dist"
with caplog.at_level(logging.ERROR): registered = register_frontend_static_routes(app, missing_dist)
registered = register_frontend_static_routes(app, missing_dist)
assert registered is False assert registered is False
assert "Frontend build directory not found" in caplog.text
# Register the fallback like main.py does # Register the fallback like main.py does
register_frontend_missing_fallback(app) register_frontend_missing_fallback(app)
@@ -33,16 +29,14 @@ def test_missing_dist_logs_error_and_keeps_app_running(tmp_path, caplog):
assert FRONTEND_BUILD_INSTRUCTIONS in resp.json()["detail"] assert FRONTEND_BUILD_INSTRUCTIONS in resp.json()["detail"]
def test_missing_index_logs_error_and_skips_frontend_routes(tmp_path, caplog): def test_missing_index_skips_frontend_routes(tmp_path):
app = FastAPI() app = FastAPI()
dist_dir = tmp_path / "frontend" / "dist" dist_dir = tmp_path / "frontend" / "dist"
dist_dir.mkdir(parents=True) dist_dir.mkdir(parents=True)
with caplog.at_level(logging.ERROR): registered = register_frontend_static_routes(app, dist_dir)
registered = register_frontend_static_routes(app, dist_dir)
assert registered is False assert registered is False
assert "Frontend index file not found" in caplog.text
def test_valid_dist_serves_static_and_spa_fallback(tmp_path): def test_valid_dist_serves_static_and_spa_fallback(tmp_path):
-12
View File
@@ -526,7 +526,6 @@ class TestReconnectLock:
with ( with (
patch("app.radio.settings") as mock_settings, patch("app.radio.settings") as mock_settings,
patch("app.radio.logger") as mock_logger,
patch("app.websocket.broadcast_health"), patch("app.websocket.broadcast_health"),
patch("app.websocket.broadcast_error") as mock_broadcast_error, patch("app.websocket.broadcast_error") as mock_broadcast_error,
): ):
@@ -536,11 +535,6 @@ class TestReconnectLock:
result = await rm.reconnect(broadcast_on_success=False) result = await rm.reconnect(broadcast_on_success=False)
assert result is False assert result is False
mock_logger.warning.assert_called_once_with(
"Could not connect to serial port /dev/serial/by-id/test-radio. "
"Did the radio get disconnected or change serial ports?",
exc_info=False,
)
assert mock_broadcast_error.call_args.args == ( assert mock_broadcast_error.call_args.args == (
"Reconnection failed", "Reconnection failed",
"Could not connect to serial port /dev/serial/by-id/test-radio. " "Could not connect to serial port /dev/serial/by-id/test-radio. "
@@ -1084,7 +1078,6 @@ class TestPostConnectSetupOrdering:
) )
with ( with (
patch("app.services.radio_lifecycle.logger") as mock_logger,
patch("app.websocket.broadcast_error") as mock_broadcast_error, patch("app.websocket.broadcast_error") as mock_broadcast_error,
patch("app.websocket.broadcast_health") as mock_broadcast_health, patch("app.websocket.broadcast_health") as mock_broadcast_health,
): ):
@@ -1092,8 +1085,6 @@ class TestPostConnectSetupOrdering:
await prepare_connected_radio(rm, broadcast_on_success=True) await prepare_connected_radio(rm, broadcast_on_success=True)
assert rm.post_connect_setup.await_count == 2 assert rm.post_connect_setup.await_count == 2
mock_logger.warning.assert_called_once()
mock_logger.error.assert_called_once()
mock_broadcast_error.assert_called_once_with( mock_broadcast_error.assert_called_once_with(
"Radio startup appears stuck", "Radio startup appears stuck",
"Initial radio offload took too long. Reboot the radio and restart the server.", "Initial radio offload took too long. Reboot the radio and restart the server.",
@@ -1111,7 +1102,6 @@ class TestPostConnectSetupOrdering:
rm.post_connect_setup = AsyncMock(side_effect=[asyncio.TimeoutError(), None]) rm.post_connect_setup = AsyncMock(side_effect=[asyncio.TimeoutError(), None])
with ( with (
patch("app.services.radio_lifecycle.logger") as mock_logger,
patch("app.websocket.broadcast_error") as mock_broadcast_error, patch("app.websocket.broadcast_error") as mock_broadcast_error,
patch("app.websocket.broadcast_health") as mock_broadcast_health, patch("app.websocket.broadcast_health") as mock_broadcast_health,
): ):
@@ -1119,7 +1109,5 @@ class TestPostConnectSetupOrdering:
assert rm.post_connect_setup.await_count == 2 assert rm.post_connect_setup.await_count == 2
assert rm._last_connected is True assert rm._last_connected is True
mock_logger.warning.assert_called_once()
mock_logger.error.assert_not_called()
mock_broadcast_error.assert_not_called() mock_broadcast_error.assert_not_called()
mock_broadcast_health.assert_called_once_with(True, "Serial: /dev/ttyUSB0") mock_broadcast_health.assert_called_once_with(True, "Serial: /dev/ttyUSB0")
+1 -9
View File
@@ -1599,12 +1599,10 @@ class TestMessagePollLoopRaces:
patch("app.radio_sync.settings.enable_message_poll_fallback", False), patch("app.radio_sync.settings.enable_message_poll_fallback", False),
patch("asyncio.sleep", side_effect=mock_sleep), patch("asyncio.sleep", side_effect=mock_sleep),
patch("app.radio_sync.poll_for_messages", new_callable=AsyncMock, return_value=2), patch("app.radio_sync.poll_for_messages", new_callable=AsyncMock, return_value=2),
patch("app.radio_sync.logger") as mock_logger,
patch("app.radio_sync.broadcast_error") as mock_broadcast_error, patch("app.radio_sync.broadcast_error") as mock_broadcast_error,
): ):
await _message_poll_loop() await _message_poll_loop()
mock_logger.error.assert_called_once()
mock_broadcast_error.assert_called_once_with( mock_broadcast_error.assert_called_once_with(
"A periodic poll task has discovered radio inconsistencies.", "A periodic poll task has discovered radio inconsistencies.",
"Please check the logs for recommendations (search " "Please check the logs for recommendations (search "
@@ -1621,12 +1619,10 @@ class TestMessagePollLoopRaces:
patch("app.radio_sync.settings.enable_message_poll_fallback", True), patch("app.radio_sync.settings.enable_message_poll_fallback", True),
patch("asyncio.sleep", side_effect=mock_sleep), patch("asyncio.sleep", side_effect=mock_sleep),
patch("app.radio_sync.poll_for_messages", new_callable=AsyncMock, return_value=2), patch("app.radio_sync.poll_for_messages", new_callable=AsyncMock, return_value=2),
patch("app.radio_sync.logger") as mock_logger,
patch("app.radio_sync.broadcast_error") as mock_broadcast_error, patch("app.radio_sync.broadcast_error") as mock_broadcast_error,
): ):
await _message_poll_loop() await _message_poll_loop()
mock_logger.warning.assert_called_once()
mock_broadcast_error.assert_not_called() mock_broadcast_error.assert_not_called()
@@ -1672,13 +1668,9 @@ class TestChannelSendCacheAudit:
mock_mc = MagicMock() mock_mc = MagicMock()
mock_mc.commands.get_channel = AsyncMock(return_value=mismatch_result) mock_mc.commands.get_channel = AsyncMock(return_value=mismatch_result)
with ( with patch("app.radio_sync.broadcast_error") as mock_broadcast_error:
patch("app.radio_sync.logger") as mock_logger,
patch("app.radio_sync.broadcast_error") as mock_broadcast_error,
):
assert await audit_channel_send_cache(mock_mc) is False assert await audit_channel_send_cache(mock_mc) is False
mock_logger.error.assert_called_once()
mock_broadcast_error.assert_called_once() mock_broadcast_error.assert_called_once()
assert radio_manager.get_cached_channel_slot(chan_key) is None assert radio_manager.get_cached_channel_slot(chan_key) is None