From 0e5e71563c2c8ea0416f50a454b7fd6b4a262dfa Mon Sep 17 00:00:00 2001 From: liquidraver <504870+liquidraver@users.noreply.github.com> Date: Sun, 29 Mar 2026 09:51:53 +0200 Subject: [PATCH] logging cleanup --- zephcore/Kconfig | 4 + zephcore/adapters/ble/ZephyrBLE.cpp | 11 +- zephcore/adapters/board/ZephyrBoard.cpp | 2 +- .../adapters/datastore/ZephyrDataStore.cpp | 18 ++- zephcore/adapters/ota/wifi_ota.c | 12 +- zephcore/adapters/radio/SX126xRadio.cpp | 2 +- zephcore/adapters/usb/ZephyrCompanionUSB.cpp | 2 +- zephcore/adapters/usb/ZephyrRepeaterUSB.cpp | 4 +- zephcore/app/CompanionMesh.cpp | 46 +++---- zephcore/app/RepeaterDataStore.cpp | 8 +- zephcore/app/RepeaterMesh.cpp | 4 +- zephcore/helpers/BaseChatMesh.cpp | 36 +++--- zephcore/helpers/ui/display.c | 6 +- zephcore/helpers/ui/input_multi_tap.c | 4 +- zephcore/helpers/ui/ui_task.c | 6 +- .../drivers/lora/lr11xx/lr11xx_lora.c | 27 +--- .../drivers/lora/lr20xx/lr20xx_lora.c | 116 +++++------------- zephcore/src/Dispatcher.cpp | 8 +- zephcore/src/Mesh.cpp | 2 +- zephcore/src/main_repeater.cpp | 2 +- 20 files changed, 124 insertions(+), 196 deletions(-) diff --git a/zephcore/Kconfig b/zephcore/Kconfig index 340baab..2fcd174 100644 --- a/zephcore/Kconfig +++ b/zephcore/Kconfig @@ -38,6 +38,10 @@ module = ZEPHCORE_UI_ACTIONS module-str = zephcore_ui_actions source "$(ZEPHYR_BASE)/subsys/logging/Kconfig.template.log_config" +module = ZEPHCORE_WIFI_OTA +module-str = zephcore_wifi_ota +source "$(ZEPHYR_BASE)/subsys/logging/Kconfig.template.log_config" + menu "ZephCore" menu "Device Role" diff --git a/zephcore/adapters/ble/ZephyrBLE.cpp b/zephcore/adapters/ble/ZephyrBLE.cpp index 3cfd02c..921db7a 100644 --- a/zephcore/adapters/ble/ZephyrBLE.cpp +++ b/zephcore/adapters/ble/ZephyrBLE.cpp @@ -325,7 +325,6 @@ static void disconnected(struct bt_conn *conn, uint8_t reason) /* Clear interface state if BLE was active */ if (active_iface == ZEPHCORE_IFACE_BLE) { active_iface = ZEPHCORE_IFACE_NONE; - LOG_INF("active_iface = IFACE_NONE"); } /* Clear queues, retry state, and congestion */ @@ -534,7 +533,6 @@ static void pairing_complete(struct bt_conn *conn, bool bonded) /* Main handles USB state clearing via on_connected callback */ } active_iface = ZEPHCORE_IFACE_BLE; - LOG_INF("active_iface = IFACE_BLE"); } static void pairing_failed(struct bt_conn *conn, enum bt_security_err reason) @@ -568,7 +566,7 @@ static void overflow_retry_work_fn(struct k_work *work) if (k_msgq_put(&ble_send_queue, &overflow_frame, K_NO_WAIT) == 0) { overflow_pending = false; - LOG_INF("overflow frame queued hdr=0x%02x, kicking drain", + LOG_DBG("overflow frame queued hdr=0x%02x, kicking drain", overflow_frame.buf[0]); kick_tx_drain(); /* Congestion flag cleared by tx_drain at low water mark */ @@ -642,13 +640,13 @@ static void tx_drain_work_fn(struct k_work *work) /* Check retry buffer first */ if (tx_retry_pending) { - LOG_INF("tx_drain[BLE]: retrying len=%u hdr=0x%02x", (unsigned)tx_retry_frame.len, tx_retry_frame.buf[0]); + LOG_DBG("tx_drain[BLE]: retrying len=%u hdr=0x%02x", (unsigned)tx_retry_frame.len, tx_retry_frame.buf[0]); ble_tx_in_progress = true; ble_tx_start_time = k_uptime_get(); err = secure_nus_send(conn, tx_retry_frame.buf, tx_retry_frame.len); if (err == 0) { tx_retry_pending = false; - LOG_INF("tx_drain[BLE]: retry success"); + LOG_DBG("tx_drain[BLE]: retry success"); bt_conn_unref(conn); return; /* Callback will chain to next */ } else if (err == -EAGAIN || err == -ENOMEM) { @@ -700,7 +698,6 @@ static void tx_drain_work_fn(struct k_work *work) if (err == 0) { /* Success - callback will chain to next */ - LOG_DBG("tx_drain[BLE]: queued for TX"); bt_conn_unref(conn); return; } else if (err == -EAGAIN || err == -ENOMEM) { @@ -753,7 +750,7 @@ static ssize_t secure_nus_rx_write(struct bt_conn *conn, const struct bt_gatt_at const uint8_t *data = (const uint8_t *)buf; uint8_t cmd = data[0]; - LOG_INF("NUS RX: len=%u cmd=0x%02x", len, cmd); + LOG_DBG("NUS RX: len=%u cmd=0x%02x", len, cmd); /* Notify main via callback */ if (ble_cbs && ble_cbs->on_rx_frame) { diff --git a/zephcore/adapters/board/ZephyrBoard.cpp b/zephcore/adapters/board/ZephyrBoard.cpp index 0639e68..1680312 100644 --- a/zephcore/adapters/board/ZephyrBoard.cpp +++ b/zephcore/adapters/board/ZephyrBoard.cpp @@ -136,7 +136,7 @@ uint16_t ZephyrBoard::getBattMilliVolts() } raw /= valid_samples; uint16_t mv = (uint16_t)((VBAT_MV_MULTIPLIER * (int64_t)raw) / 4096); - LOG_INF("Battery: raw=%d multiplier=%d mv=%u", (int)raw, VBAT_MV_MULTIPLIER, mv); + LOG_DBG("Battery: raw=%d multiplier=%d mv=%u", (int)raw, VBAT_MV_MULTIPLIER, mv); return mv; #else return 0; diff --git a/zephcore/adapters/datastore/ZephyrDataStore.cpp b/zephcore/adapters/datastore/ZephyrDataStore.cpp index a0e93fe..b196ace 100644 --- a/zephcore/adapters/datastore/ZephyrDataStore.cpp +++ b/zephcore/adapters/datastore/ZephyrDataStore.cpp @@ -57,7 +57,7 @@ bool ZephyrDataStore::mount() LOG_INF("External QSPI LittleFS at %s (automounted, 100 blobs)", extMountPoint()); } else { ext_lfs_mounted = false; - LOG_WRN("External QSPI NOT mounted at %s - using internal only (20 blobs)", extMountPoint()); + LOG_INF("External QSPI NOT mounted at %s - using internal only (20 blobs)", extMountPoint()); } return true; @@ -335,23 +335,22 @@ bool ZephyrDataStore::saveMainIdentity(const mesh::LocalIdentity &identity) void ZephyrDataStore::loadPrefs(NodePrefs &prefs) { bool prefs_exists = exists(PREFS_FILE); - LOG_INF("loadPrefs: exists(%s)=%d", PREFS_FILE, prefs_exists ? 1 : 0); if (!prefs_exists) { - LOG_WRN("loadPrefs: no prefs file found"); + LOG_DBG("loadPrefs: no prefs file found"); return; } uint8_t buf[256]; size_t len = 0; if (!openRead(PREFS_FILE, buf, sizeof(buf), len)) { - LOG_WRN("loadPrefs: read failed"); + LOG_ERR("loadPrefs: read failed"); return; } if (len < 88) { - LOG_WRN("loadPrefs: file too small (%d bytes, need 88)", (int)len); + LOG_ERR("loadPrefs: file too small (%d bytes, need 88)", (int)len); return; } - LOG_INF("loadPrefs: loaded %d bytes from %s", (int)len, PREFS_FILE); + LOG_DBG("loadPrefs: loaded %d bytes from %s", (int)len, PREFS_FILE); size_t off = 0; memcpy(&prefs.airtime_factor, &buf[off], sizeof(float)); @@ -482,7 +481,7 @@ void ZephyrDataStore::savePrefs(const NodePrefs &prefs) /* Total: 96 bytes (Arduino reads 92, ZephCore reads 96) */ bool ok = openWrite(PREFS_FILE, buf, off); - LOG_INF("savePrefs: wrote %s, ok=%d (%d bytes), name='%.16s'", + LOG_DBG("savePrefs: wrote %s, ok=%d (%d bytes), name='%.16s'", PREFS_FILE, ok ? 1 : 0, (int)off, prefs.node_name); } @@ -534,13 +533,12 @@ static void record_to_contact(const uint8_t rec[CONTACT_DATA_SZ], ContactInfo &c void ZephyrDataStore::loadContacts(DataStoreHost *host) { const char *path = contactsFile(); - LOG_INF("loadContacts: path=%s", path); struct fs_file_t file; fs_file_t_init(&file); int rc = fs_open(&file, path, FS_O_READ); if (rc < 0) { - LOG_WRN("loadContacts: no contacts file found"); + LOG_DBG("loadContacts: no contacts file found"); return; } @@ -569,7 +567,6 @@ void ZephyrDataStore::loadContacts(DataStoreHost *host) void ZephyrDataStore::saveContacts(DataStoreHost *host) { const char *path = contactsFile(); - LOG_INF("saveContacts: path=%s", path); if (exists(path)) { fs_unlink(path); @@ -635,7 +632,6 @@ void ZephyrDataStore::loadChannels(DataStoreHost *host) void ZephyrDataStore::saveChannels(DataStoreHost *host) { const char *path = channelsFile(); - LOG_INF("saveChannels: path=%s", path); if (exists(path)) { fs_unlink(path); diff --git a/zephcore/adapters/ota/wifi_ota.c b/zephcore/adapters/ota/wifi_ota.c index 9dbf61f..dd73dd6 100644 --- a/zephcore/adapters/ota/wifi_ota.c +++ b/zephcore/adapters/ota/wifi_ota.c @@ -29,7 +29,7 @@ #include #include -LOG_MODULE_REGISTER(wifi_ota, LOG_LEVEL_INF); +LOG_MODULE_REGISTER(wifi_ota, LOG_LEVEL_DEFAULT); /* ========== Configuration ========== */ @@ -142,7 +142,7 @@ static int home_handler(struct http_client_ctx *client, response_ctx->body_len = strlen(home_html); response_ctx->final_chunk = true; response_ctx->status = HTTP_200_OK; - LOG_INF("Served home page (%u bytes)", (unsigned)response_ctx->body_len); + LOG_DBG("Served home page (%u bytes)", (unsigned)response_ctx->body_len); } return 0; } @@ -291,10 +291,10 @@ static void wifi_mgmt_event_handler(struct net_mgmt_event_callback *cb, { switch (mgmt_event) { case NET_EVENT_WIFI_AP_ENABLE_RESULT: - LOG_INF("WiFi AP enable result event received"); + LOG_DBG("WiFi AP enable result event received"); break; case NET_EVENT_WIFI_AP_DISABLE_RESULT: - LOG_INF("WiFi AP disable result event"); + LOG_DBG("WiFi AP disable result event"); break; case NET_EVENT_WIFI_AP_STA_CONNECTED: LOG_INF("WiFi client CONNECTED to AP"); @@ -319,7 +319,7 @@ static int wifi_ap_start(void) return -ENODEV; } - LOG_INF("Network iface: %p, idx=%d", iface, net_if_get_by_iface(iface)); + LOG_DBG("Network iface: %p, idx=%d", iface, net_if_get_by_iface(iface)); /* Register WiFi management event callback */ net_mgmt_init_event_callback(&wifi_mgmt_cb, wifi_mgmt_event_handler, @@ -376,8 +376,6 @@ static int wifi_ap_start(void) if (ret) { LOG_ERR("net_if_up failed: %d", ret); } - } else { - LOG_INF("Interface is up"); } /* Start DHCP server */ diff --git a/zephcore/adapters/radio/SX126xRadio.cpp b/zephcore/adapters/radio/SX126xRadio.cpp index ebbbf43..3ef5e1d 100644 --- a/zephcore/adapters/radio/SX126xRadio.cpp +++ b/zephcore/adapters/radio/SX126xRadio.cpp @@ -12,7 +12,7 @@ extern "C" { } #include -LOG_MODULE_REGISTER(zephcore_lora, CONFIG_ZEPHCORE_LORA_LOG_LEVEL); +LOG_MODULE_REGISTER(sx126x_radio, CONFIG_ZEPHCORE_LORA_LOG_LEVEL); namespace mesh { diff --git a/zephcore/adapters/usb/ZephyrCompanionUSB.cpp b/zephcore/adapters/usb/ZephyrCompanionUSB.cpp index 2668ad7..324b8a9 100644 --- a/zephcore/adapters/usb/ZephyrCompanionUSB.cpp +++ b/zephcore/adapters/usb/ZephyrCompanionUSB.cpp @@ -222,7 +222,7 @@ size_t zephcore_usb_companion_write_frame(const uint8_t *src, size_t len) uart_poll_out(usb_dev, src[i]); } - LOG_INF("usb_write_frame: sent len=%u hdr=0x%02x", (unsigned)len, src[0]); + LOG_DBG("usb_write_frame: sent len=%u hdr=0x%02x", (unsigned)len, src[0]); return len; } diff --git a/zephcore/adapters/usb/ZephyrRepeaterUSB.cpp b/zephcore/adapters/usb/ZephyrRepeaterUSB.cpp index 997be45..f68d10a 100644 --- a/zephcore/adapters/usb/ZephyrRepeaterUSB.cpp +++ b/zephcore/adapters/usb/ZephyrRepeaterUSB.cpp @@ -85,7 +85,7 @@ static void usbd_msg_callback(struct usbd_context *const ctx, const struct usbd_ uint32_t baudrate = 0; int ret = uart_line_ctrl_get(msg->dev, UART_LINE_CTRL_BAUD_RATE, &baudrate); if (ret == 0) { - LOG_INF("CDC ACM baud rate: %u", baudrate); + LOG_DBG("CDC ACM baud rate: %u", baudrate); if (baudrate == 1200) { enter_bootloader(); } @@ -95,7 +95,7 @@ static void usbd_msg_callback(struct usbd_context *const ctx, const struct usbd_ uint32_t baudrate = 0; uart_line_ctrl_get(msg->dev, UART_LINE_CTRL_DTR, &dtr); uart_line_ctrl_get(msg->dev, UART_LINE_CTRL_BAUD_RATE, &baudrate); - LOG_INF("CDC ACM DTR=%u baud=%u", dtr, baudrate); + LOG_DBG("CDC ACM DTR=%u baud=%u", dtr, baudrate); /* Arduino method: DTR drop (high→low) while baud is 1200 */ if (dtr_was_active && !dtr && baudrate == 1200) { enter_bootloader(); diff --git a/zephcore/app/CompanionMesh.cpp b/zephcore/app/CompanionMesh.cpp index 30ad229..2b2ca7c 100644 --- a/zephcore/app/CompanionMesh.cpp +++ b/zephcore/app/CompanionMesh.cpp @@ -365,7 +365,7 @@ static bool isChannelMessage(const uint8_t *buf) void CompanionMesh::queueOfflineMessage(const uint8_t *data, size_t len) { - LOG_INF("queueOfflineMessage: len=%u type=0x%02x count_before=%d", (unsigned)len, data[0], _offline_queue_count); + LOG_DBG("queueOfflineMessage: len=%u type=0x%02x count_before=%d", (unsigned)len, data[0], _offline_queue_count); if (_offline_queue_count >= OFFLINE_QUEUE_SIZE) { // Queue full - try to drop oldest channel message first int pos = _offline_queue_head; @@ -394,7 +394,7 @@ void CompanionMesh::queueOfflineMessage(const uint8_t *data, size_t len) memcpy(f->buf, data, f->len); _offline_queue_tail = (_offline_queue_tail + 1) % OFFLINE_QUEUE_SIZE; _offline_queue_count++; - LOG_INF("queueOfflineMessage: count_after=%d", _offline_queue_count); + LOG_DBG("queueOfflineMessage: count_after=%d", _offline_queue_count); } bool CompanionMesh::dequeueOfflineMessage(uint8_t *dest, size_t &len) @@ -564,11 +564,11 @@ void CompanionMesh::onDiscoveredContact(ContactInfo &contact, bool is_new, uint8 if (is_new) { uint8_t rsp[CONTACT_FRAME_SIZE]; size_t n = serializeContact(rsp, contact); /* no header — push code is separate */ - LOG_INF("onDiscoveredContact: sending PUSH_CODE_NEW_ADVERT (full contact)"); + LOG_DBG("onDiscoveredContact: sending PUSH_CODE_NEW_ADVERT (full contact)"); sendPush(PUSH_CODE_NEW_ADVERT, rsp, n); } else { // ADVERT: send just pubkey - LOG_INF("onDiscoveredContact: sending PUSH_CODE_ADVERT (pubkey only)"); + LOG_DBG("onDiscoveredContact: sending PUSH_CODE_ADVERT (pubkey only)"); sendPush(PUSH_CODE_ADVERT, contact.id.pub_key, PUB_KEY_SIZE); } } @@ -659,7 +659,7 @@ void CompanionMesh::queueContactMessage(const ContactInfo &contact, mesh::Packet memcpy(&frame[i], text, text_len); i += text_len; - LOG_INF("queueContactMessage: frame_len=%d type=0x%02x", i, frame[0]); + LOG_DBG("queueContactMessage: frame_len=%d type=0x%02x", i, frame[0]); queueOfflineMessage(frame, i); } @@ -744,7 +744,7 @@ void CompanionMesh::onChannelMessageRecv(const mesh::GroupChannel &channel, mesh memcpy(&frame[i], text, text_len); i += text_len; - LOG_INF("onChannelMessageRecv: frame_len=%d channel_idx=%d", i, channel_idx); + LOG_DBG("onChannelMessageRecv: frame_len=%d channel_idx=%d", i, channel_idx); queueOfflineMessage(frame, i); sendPush(PUSH_CODE_MSG_WAITING); } @@ -778,7 +778,7 @@ void CompanionMesh::onChannelDataRecv(const mesh::GroupChannel &channel, mesh::P i += copy_len; } - LOG_INF("onChannelDataRecv: frame_len=%d channel_idx=%d data_type=%d", + LOG_DBG("onChannelDataRecv: frame_len=%d channel_idx=%d data_type=%d", i, channel_idx, (int)data_type); queueOfflineMessage(frame, i); sendPush(PUSH_CODE_MSG_WAITING); @@ -956,12 +956,12 @@ uint8_t CompanionMesh::onContactRequest(const ContactInfo &contact, uint32_t sen void CompanionMesh::onContactResponse(const ContactInfo &contact, const uint8_t *data, uint8_t len) { - LOG_INF("onContactResponse: len=%d from contact", len); + LOG_DBG("onContactResponse: len=%d from contact", len); if (len < 4) return; // Need at least 4-byte tag uint32_t tag; memcpy(&tag, data, 4); - LOG_INF("onContactResponse: tag=%08x, _pending_login=%08x", tag, _pending_login); + LOG_DBG("onContactResponse: tag=%08x, _pending_login=%08x", tag, _pending_login); // Check for login response if (_pending_login && memcmp(&_pending_login, contact.id.pub_key, 4) == 0) { @@ -1085,7 +1085,7 @@ void CompanionMesh::logRxRaw(float snr, float rssi, const uint8_t raw[], int len void CompanionMesh::onTraceRecv(mesh::Packet *packet, uint32_t tag, uint32_t auth_code, uint8_t flags, const uint8_t *path_snrs, const uint8_t *path_hashes, uint8_t path_len) { - LOG_INF("onTraceRecv: tag=0x%08x auth=0x%08x flags=0x%02x path_len=%d", + LOG_DBG("onTraceRecv: tag=0x%08x auth=0x%08x flags=0x%02x path_len=%d", tag, auth_code, flags, path_len); // path_sz is encoded in flags bits 0-1 (0=1, 1=2, 2=4, 3=8 byte hash) @@ -1112,7 +1112,7 @@ void CompanionMesh::onTraceRecv(mesh::Packet *packet, uint32_t tag, uint32_t aut /* Control data response - for repeater discovery, etc */ void CompanionMesh::onControlDataRecv(mesh::Packet *packet) { - LOG_INF("onControlDataRecv: payload_len=%d path_len=%d", packet->payload_len, packet->path_len); + LOG_DBG("onControlDataRecv: payload_len=%d path_len=%d", packet->payload_len, packet->path_len); // Buffer: [PUSH_CODE_CONTROL_DATA][snr*4][rssi][path_len][payload...] if (packet->payload_len + 4 > MAX_FRAME_SIZE) { @@ -1135,7 +1135,7 @@ void CompanionMesh::onControlDataRecv(mesh::Packet *packet) /* Raw data response - for custom packet types */ void CompanionMesh::onRawDataRecv(mesh::Packet *packet) { - LOG_INF("onRawDataRecv: payload_len=%d", packet->payload_len); + LOG_DBG("onRawDataRecv: payload_len=%d", packet->payload_len); // Buffer: [PUSH_CODE_RAW_DATA][snr*4][rssi][reserved][payload...] if (packet->payload_len + 4 > MAX_FRAME_SIZE) { @@ -1636,7 +1636,7 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len) case CMD_SEND_TXT_MSG: // Frame format: cmd(1) + txt_type(1) + attempt(1) + timestamp(4) + pub_key_prefix(6) + text(N) // Minimum: 1 + 1 + 1 + 4 + 6 + 1 = 14 bytes - LOG_INF("CMD_SEND_TXT_MSG: len=%u (min=14)", (unsigned)len); + LOG_DBG("CMD_SEND_TXT_MSG: len=%u (min=14)", (unsigned)len); if (len >= 14) { int i = 1; uint8_t txt_type = data[i++]; @@ -1652,13 +1652,13 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len) text_buf[text_len] = '\0'; const char *text = text_buf; - LOG_INF("CMD_SEND_TXT_MSG: txt_type=%d attempt=%d pubkey=%02x%02x%02x%02x%02x%02x", + LOG_DBG("CMD_SEND_TXT_MSG: txt_type=%d attempt=%d pubkey=%02x%02x%02x%02x%02x%02x", txt_type, attempt, pub_key_prefix[0], pub_key_prefix[1], pub_key_prefix[2], pub_key_prefix[3], pub_key_prefix[4], pub_key_prefix[5]); ContactInfo *contact = lookupContactByPubKey(pub_key_prefix, 6); if (contact && (txt_type == TXT_TYPE_PLAIN || txt_type == TXT_TYPE_CLI_DATA)) { - LOG_INF("CMD_SEND_TXT_MSG: contact='%s' text='%s' text_len=%u", contact->name, text, (unsigned)text_len); + LOG_DBG("CMD_SEND_TXT_MSG: contact='%s' text='%s' text_len=%u", contact->name, text, (unsigned)text_len); uint32_t expected_ack = 0, est_timeout; int result; @@ -1671,7 +1671,7 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len) result = sendMessage(*contact, msg_timestamp, attempt, text, expected_ack, est_timeout); } - LOG_INF("CMD_SEND_TXT_MSG: sendMessage result=%d expected_ack=0x%08x", result, expected_ack); + LOG_DBG("CMD_SEND_TXT_MSG: sendMessage result=%d expected_ack=0x%08x", result, expected_ack); if (result != MSG_SEND_FAILED) { if (expected_ack) { @@ -1759,7 +1759,7 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len) } case CMD_SYNC_NEXT_MESSAGE: { - LOG_INF("CMD_SYNC_NEXT_MESSAGE: queue_count=%d pending=%d", + LOG_DBG("CMD_SYNC_NEXT_MESSAGE: queue_count=%d pending=%d", _offline_queue_count, _sync_pending); /* Phone asking for next = implicit ACK for the previously-peeked message */ @@ -1771,11 +1771,11 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len) uint8_t buf[MAX_FRAME_SIZE]; size_t msg_len; if (peekOfflineMessage(buf, msg_len)) { - LOG_INF("CMD_SYNC_NEXT_MESSAGE: peeked msg_len=%u type=0x%02x", (unsigned)msg_len, buf[0]); + LOG_DBG("CMD_SYNC_NEXT_MESSAGE: peeked msg_len=%u type=0x%02x", (unsigned)msg_len, buf[0]); writeFrame(buf, msg_len); _sync_pending = true; /* will be confirmed on next request or lost on disconnect */ } else { - LOG_INF("CMD_SYNC_NEXT_MESSAGE: queue empty, sending NO_MORE_MSGS"); + LOG_DBG("CMD_SYNC_NEXT_MESSAGE: queue empty, sending NO_MORE_MSGS"); uint8_t rsp[] = { PACKET_NO_MORE_MSGS }; writeFrame(rsp, sizeof(rsp)); @@ -1886,7 +1886,7 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len) * GPS time is more accurate than phone time. Still return OK * so the app doesn't keep retrying. */ if (gps_has_time_sync()) { - LOG_INF("Ignoring phone time sync - GPS time sync active"); + LOG_DBG("Ignoring phone time sync - GPS time sync active"); sendPacketOk(); return true; } @@ -2182,13 +2182,13 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len) const char *password = pw_buf; if (contact) { uint32_t est_timeout; - LOG_INF("CMD_SEND_LOGIN: sending to contact, path_len=%d", contact->out_path_len); + LOG_DBG("CMD_SEND_LOGIN: sending to contact, path_len=%d", contact->out_path_len); int result = sendLogin(*contact, password, est_timeout); - LOG_INF("CMD_SEND_LOGIN: sendLogin returned %d, est_timeout=%u", result, est_timeout); + LOG_DBG("CMD_SEND_LOGIN: sendLogin returned %d, est_timeout=%u", result, est_timeout); if (result != MSG_SEND_FAILED) { clearPendingReqs(); memcpy(&_pending_login, contact->id.pub_key, 4); // match in onContactResponse() - LOG_INF("CMD_SEND_LOGIN: _pending_login set to %08x", _pending_login); + LOG_DBG("CMD_SEND_LOGIN: _pending_login set to %08x", _pending_login); uint8_t rsp[10]; rsp[0] = PACKET_SENT; rsp[1] = (result == MSG_SEND_SENT_FLOOD) ? 1 : 0; diff --git a/zephcore/app/RepeaterDataStore.cpp b/zephcore/app/RepeaterDataStore.cpp index 58dc6ca..7df0864 100644 --- a/zephcore/app/RepeaterDataStore.cpp +++ b/zephcore/app/RepeaterDataStore.cpp @@ -57,7 +57,7 @@ bool RepeaterDataStore::loadIdentity(mesh::LocalIdentity& id) { int ret = fs_open(&file, path, FS_O_READ); if (ret < 0) { - LOG_WRN("No identity file at %s", path); + LOG_DBG("No identity file at %s", path); return false; } @@ -65,7 +65,7 @@ bool RepeaterDataStore::loadIdentity(mesh::LocalIdentity& id) { ssize_t n = fs_read(&file, buf, sizeof(buf)); fs_close(&file); - LOG_INF("loadIdentity: read %d bytes from %s", (int)n, path); + LOG_DBG("loadIdentity: read %d bytes from %s", (int)n, path); if (n >= PRV_KEY_SIZE) { if (id.readFrom(buf, n)) { @@ -127,7 +127,7 @@ bool RepeaterDataStore::loadPrefs(NodePrefs& prefs) { struct fs_dirent entry; ret = fs_stat(path, &entry); - LOG_INF("loadPrefs: file size = %d bytes", ret < 0 ? 0 : (int)entry.size); + LOG_DBG("loadPrefs: file size = %d bytes", ret < 0 ? 0 : (int)entry.size); uint8_t pad[8]; @@ -176,7 +176,7 @@ bool RepeaterDataStore::loadPrefs(NodePrefs& prefs) { } LOG_INF("Loaded prefs from %s", path); - LOG_INF(" name='%s' freq=%.3f sf=%u bw=%.1f tx_pwr=%d", + LOG_DBG(" name='%s' freq=%.3f sf=%u bw=%.1f tx_pwr=%d", prefs.node_name, (double)prefs.freq, prefs.sf, (double)prefs.bw, prefs.tx_power_dbm); /* Validate radio params - use defaults if garbage */ diff --git a/zephcore/app/RepeaterMesh.cpp b/zephcore/app/RepeaterMesh.cpp index 75237c4..3fec911 100644 --- a/zephcore/app/RepeaterMesh.cpp +++ b/zephcore/app/RepeaterMesh.cpp @@ -39,7 +39,7 @@ static void simple_sort(T* arr, int count, Comparator cmp) { } } -LOG_MODULE_REGISTER(zephcore_repeater, LOG_LEVEL_INF); +LOG_MODULE_REGISTER(zephcore_repeater, CONFIG_ZEPHCORE_MAIN_LOG_LEVEL); /* Protocol constants */ #define FIRMWARE_VER_LEVEL 2 @@ -119,7 +119,7 @@ uint8_t RepeaterMesh::handleLoginReq(const mesh::Identity& sender, const uint8_t } else if (strcmp((char*)data, _prefs.guest_password) == 0) { perms = PERM_ACL_GUEST; } else { - LOG_DBG("Invalid password"); + LOG_WRN("Invalid password"); return 0; } diff --git a/zephcore/helpers/BaseChatMesh.cpp b/zephcore/helpers/BaseChatMesh.cpp index 6ef2e71..f29a2c0 100644 --- a/zephcore/helpers/BaseChatMesh.cpp +++ b/zephcore/helpers/BaseChatMesh.cpp @@ -123,7 +123,7 @@ void BaseChatMesh::populateContactFromAdvert(ContactInfo &ci, const mesh::Identi void BaseChatMesh::onAdvertRecv(mesh::Packet *packet, const mesh::Identity &id, uint32_t timestamp, const uint8_t *app_data, size_t app_data_len) { - LOG_INF("onAdvertRecv: timestamp=%u app_data_len=%u", timestamp, (unsigned)app_data_len); + LOG_DBG("onAdvertRecv: timestamp=%u app_data_len=%u", timestamp, (unsigned)app_data_len); AdvertDataParser parser(app_data, app_data_len); if (!(parser.isValid() && parser.hasName())) { @@ -132,7 +132,7 @@ void BaseChatMesh::onAdvertRecv(mesh::Packet *packet, const mesh::Identity &id, return; } - LOG_INF("onAdvertRecv: valid advert from '%s' type=%d", parser.getName(), parser.getType()); + LOG_DBG("onAdvertRecv: valid advert from '%s' type=%d", parser.getName(), parser.getType()); ContactInfo *from = nullptr; for (int i = 0; i < num_contacts; i++) { @@ -157,9 +157,9 @@ void BaseChatMesh::onAdvertRecv(mesh::Packet *packet, const mesh::Identity &id, bool is_new = false; if (from == nullptr) { - LOG_INF("onAdvertRecv: new contact, checking auto-add for type %d", parser.getType()); + LOG_DBG("onAdvertRecv: new contact, checking auto-add for type %d", parser.getType()); if (!shouldAutoAddContactType(parser.getType())) { - LOG_INF("onAdvertRecv: auto-add disabled for type %d, reporting only", parser.getType()); + LOG_DBG("onAdvertRecv: auto-add disabled for type %d, reporting only", parser.getType()); ContactInfo ci; populateContactFromAdvert(ci, id, parser, timestamp); onDiscoveredContact(ci, true, packet->path_len, packet->path); @@ -190,7 +190,7 @@ void BaseChatMesh::onAdvertRecv(mesh::Packet *packet, const mesh::Identity &id, from->sync_since = 0; from->shared_secret_valid = false; } else { - LOG_INF("onAdvertRecv: existing contact, updating"); + LOG_DBG("onAdvertRecv: existing contact, updating"); } // Update contact @@ -204,7 +204,7 @@ void BaseChatMesh::onAdvertRecv(mesh::Packet *packet, const mesh::Identity &id, from->last_advert_timestamp = timestamp; from->lastmod = getRTCClock()->getCurrentTime(); - LOG_INF("onAdvertRecv: calling onDiscoveredContact is_new=%d", is_new); + LOG_DBG("onAdvertRecv: calling onDiscoveredContact is_new=%d", is_new); onDiscoveredContact(*from, is_new, packet->path_len, packet->path); } @@ -230,7 +230,7 @@ void BaseChatMesh::getPeerSharedSecret(uint8_t *dest_secret, int peer_idx) void BaseChatMesh::onPeerDataRecv(mesh::Packet *packet, uint8_t type, int sender_idx, const uint8_t *secret, uint8_t *data, size_t len) { - LOG_INF("onPeerDataRecv: type=%d sender_idx=%d len=%u", type, sender_idx, (unsigned)len); + LOG_DBG("onPeerDataRecv: type=%d sender_idx=%d len=%u", type, sender_idx, (unsigned)len); int i = matching_peer_indexes[sender_idx]; if (i < 0 || i >= num_contacts) { LOG_WRN("onPeerDataRecv: invalid peer index %d (num_contacts=%d)", i, num_contacts); @@ -238,19 +238,19 @@ void BaseChatMesh::onPeerDataRecv(mesh::Packet *packet, uint8_t type, int sender } ContactInfo &from = contacts[i]; - LOG_INF("onPeerDataRecv: from '%s'", from.name); + LOG_DBG("onPeerDataRecv: from '%s'", from.name); if (type == PAYLOAD_TYPE_TXT_MSG && len > 5) { uint32_t timestamp; memcpy(×tamp, data, 4); uint8_t flags = data[4] >> 2; - LOG_INF("onPeerDataRecv TXT_MSG: timestamp=%u flags=%d (data[4]=0x%02x) text='%s'", + LOG_DBG("onPeerDataRecv TXT_MSG: timestamp=%u flags=%d (data[4]=0x%02x) text='%s'", timestamp, flags, data[4], (const char*)&data[5]); data[len] = 0; // null terminate if (flags == TXT_TYPE_PLAIN) { - LOG_INF("onPeerDataRecv: flags match TXT_TYPE_PLAIN, calling onMessageRecv"); + LOG_DBG("onPeerDataRecv: flags match TXT_TYPE_PLAIN, calling onMessageRecv"); from.lastmod = getRTCClock()->getCurrentTime(); onMessageRecv(from, packet, timestamp, (const char *)&data[5]); @@ -312,7 +312,7 @@ void BaseChatMesh::onPeerDataRecv(mesh::Packet *packet, uint8_t type, int sender } } } else if (type == PAYLOAD_TYPE_RESPONSE && len > 0) { - LOG_INF("onPeerDataRecv: RESPONSE received, len=%d, calling onContactResponse", len); + LOG_DBG("onPeerDataRecv: RESPONSE received, len=%d, calling onContactResponse", len); onContactResponse(from, data, len); if (packet->isRouteFlood() && from.out_path_len != OUT_PATH_UNKNOWN) { handleReturnPathRetry(from, packet->path, packet->path_len); @@ -352,11 +352,11 @@ bool BaseChatMesh::onContactPathRecv(ContactInfo &from, uint8_t *in_path, uint8_ void BaseChatMesh::onAckRecv(mesh::Packet *packet, uint32_t ack_crc) { - LOG_INF("onAckRecv: ack_crc=0x%08x route=%s", ack_crc, + LOG_DBG("onAckRecv: ack_crc=0x%08x route=%s", ack_crc, packet->isRouteFlood() ? "flood" : "direct"); ContactInfo *from; if ((from = processAck((uint8_t *)&ack_crc)) != nullptr) { - LOG_INF("onAckRecv: ACK processed successfully for '%s'", from->name); + LOG_DBG("onAckRecv: ACK processed successfully for '%s'", from->name); txt_send_timeout = 0; packet->markDoNotRetransmit(); @@ -364,7 +364,7 @@ void BaseChatMesh::onAckRecv(mesh::Packet *packet, uint32_t ack_crc) handleReturnPathRetry(*from, packet->path, packet->path_len); } } else { - LOG_INF("onAckRecv: ACK not matched (no pending or wrong crc)"); + LOG_DBG("onAckRecv: ACK not matched (no pending or wrong crc)"); } } @@ -448,24 +448,24 @@ int BaseChatMesh::sendMessage(const ContactInfo &recipient, uint32_t timestamp, return MSG_SEND_FAILED; } - LOG_INF("sendMessage: packet created, expected_ack=0x%08x raw_len=%d", + LOG_DBG("sendMessage: packet created, expected_ack=0x%08x raw_len=%d", expected_ack, pkt->getRawLength()); uint32_t t = _radio->getEstAirtimeFor(pkt->getRawLength()); int rc; if (recipient.out_path_len == OUT_PATH_UNKNOWN) { - LOG_INF("sendMessage: sending flood"); + LOG_DBG("sendMessage: sending flood"); sendFloodScoped(recipient, pkt); txt_send_timeout = futureMillis(est_timeout = calcFloodTimeoutMillisFor(t)); rc = MSG_SEND_SENT_FLOOD; } else { - LOG_INF("sendMessage: sending direct path_len=%d", recipient.out_path_len); + LOG_DBG("sendMessage: sending direct path_len=%d", recipient.out_path_len); sendDirect(pkt, recipient.out_path, recipient.out_path_len); txt_send_timeout = futureMillis(est_timeout = calcDirectTimeoutMillisFor(t, recipient.out_path_len)); rc = MSG_SEND_SENT_DIRECT; } - LOG_INF("sendMessage: result=%d est_timeout=%u", rc, est_timeout); + LOG_DBG("sendMessage: result=%d est_timeout=%u", rc, est_timeout); return rc; } diff --git a/zephcore/helpers/ui/display.c b/zephcore/helpers/ui/display.c index 2d3dc64..645dafb 100644 --- a/zephcore/helpers/ui/display.c +++ b/zephcore/helpers/ui/display.c @@ -26,7 +26,7 @@ #include #include -LOG_MODULE_REGISTER(mc_display, CONFIG_ZEPHCORE_BOARD_LOG_LEVEL); +LOG_MODULE_REGISTER(zephcore_display, CONFIG_ZEPHCORE_BOARD_LOG_LEVEL); /* ========== State ========== */ @@ -184,7 +184,7 @@ int mc_display_init(void) * Latin-1 font will typically win. */ int num_fonts = cfb_get_numof_fonts(disp_dev); - LOG_INF("display: %d fonts available", num_fonts); + LOG_DBG("display: %d fonts available", num_fonts); int best_idx = 0; uint8_t best_h = 255; @@ -193,7 +193,7 @@ int mc_display_init(void) uint8_t fw = 0, fh = 0; cfb_get_font_size(disp_dev, i, &fw, &fh); - LOG_INF(" font[%d]: %ux%u", i, fw, fh); + LOG_DBG(" font[%d]: %ux%u", i, fw, fh); if (fh < best_h) { best_h = fh; best_idx = i; diff --git a/zephcore/helpers/ui/input_multi_tap.c b/zephcore/helpers/ui/input_multi_tap.c index d1b5e0f..f463ed1 100644 --- a/zephcore/helpers/ui/input_multi_tap.c +++ b/zephcore/helpers/ui/input_multi_tap.c @@ -46,7 +46,7 @@ static void multi_tap_emit(struct multi_tap_data *data) if (data->tap_count > 0 && data->tap_count <= cfg->num_tap_codes) { uint16_t code = cfg->tap_codes[data->tap_count - 1]; - LOG_INF("multi-tap: %u tap(s) -> emit code %u", data->tap_count, code); + LOG_DBG("multi-tap: %u tap(s) -> emit code %u", data->tap_count, code); input_report_key(dev, code, 1, true, K_FOREVER); input_report_key(dev, code, 0, true, K_FOREVER); } @@ -96,7 +96,7 @@ static void __maybe_unused multi_tap_cb(struct input_event *evt, void *user_data } data->tap_count++; - LOG_INF("multi-tap: tap %u/%u", data->tap_count, cfg->num_tap_codes); + LOG_DBG("multi-tap: tap %u/%u", data->tap_count, cfg->num_tap_codes); if (data->tap_count >= cfg->num_tap_codes) { /* Reached max tap count — emit immediately, no point waiting */ diff --git a/zephcore/helpers/ui/ui_task.c b/zephcore/helpers/ui/ui_task.c index 7a79a76..45721cb 100644 --- a/zephcore/helpers/ui/ui_task.c +++ b/zephcore/helpers/ui/ui_task.c @@ -298,7 +298,7 @@ static void action_page_enter(void) #ifdef CONFIG_ZEPHCORE_UI_DISPLAY enum ui_page page = ui_pages_current(); - LOG_INF("ENTER on page %d", page); + LOG_DBG("ENTER on page %d", page); switch (page) { case UI_PAGE_BLUETOOTH: @@ -418,7 +418,7 @@ static void action_page_enter(void) if ((now_doom - doom_act_time) <= DOOM_ACT_TIMEOUT_MS) { /* Third press — activate Doom! */ doom_act_state = DOOM_ACT_IDLE; - LOG_INF("Doom easter egg activated!"); + LOG_DBG("Doom easter egg activated!"); doom_game_start(); } else { /* Timeout — restart */ @@ -703,8 +703,6 @@ static void ui_input_cb(struct input_event *evt, void *user_data) return; } - LOG_INF("UI input: code=%u value=%u", evt->code, evt->value); - #ifdef CONFIG_ZEPHCORE_UI_DISPLAY /* If display is off, wake it and consume the event */ if (!mc_display_is_on()) { diff --git a/zephcore/patches/zephyr-new/drivers/lora/lr11xx/lr11xx_lora.c b/zephcore/patches/zephyr-new/drivers/lora/lr11xx/lr11xx_lora.c index 20a0510..c6666cf 100644 --- a/zephcore/patches/zephyr-new/drivers/lora/lr11xx/lr11xx_lora.c +++ b/zephcore/patches/zephyr-new/drivers/lora/lr11xx/lr11xx_lora.c @@ -167,7 +167,7 @@ static void lr11xx_hardware_reset(struct lr11xx_data *data, { void *ctx = &data->hal_ctx; - LOG_WRN("LR1110 hardware reset (BUSY stuck recovery)"); + LOG_INF("LR1110 hardware reset (BUSY stuck recovery)"); lr11xx_hal_reset(ctx); @@ -210,8 +210,6 @@ static void lr11xx_hardware_reset(struct lr11xx_data *data, data->rx_boost_applied = false; lr11xx_hal_enable_dio1_irq(&data->hal_ctx); - - LOG_WRN("LR1110 recovered from hardware reset"); } /* ── Apply modem configuration ──────────────────────────────────────── */ @@ -285,8 +283,6 @@ static void lr11xx_start_rx(struct lr11xx_data *data, { void *ctx = &data->hal_ctx; - LOG_DBG("start_rx: t=%lld", k_uptime_get()); - /* Standby first — wake from any sleep state */ data->hal_ctx.radio_is_sleeping = true; lr11xx_status_t rc = lr11xx_system_set_standby(ctx, @@ -376,9 +372,6 @@ static void lr11xx_dio1_work_handler(struct k_work *work) goto safety_check; } - LOG_DBG("DIO1 IRQ: 0x%08x tx=%d t=%lld", irq, data->tx_active, - k_uptime_get()); - /* CMD_ERROR (bit 22) is expected — LR1110 firmware sets it on * several write commands (SetModParams, SetSyncWord, SetRxBoosted, * SetRx) as a benign side effect on all FW versions (0x0307, 0x0401). @@ -386,7 +379,7 @@ static void lr11xx_dio1_work_handler(struct k_work *work) * behavior but never notices because it doesn't read IRQ after writes. * ERROR (bit 23) indicates an actual hardware fault. */ if (irq & LR11XX_SYSTEM_IRQ_ERROR) { - LOG_WRN("IRQ hardware ERROR: 0x%08x", irq); + LOG_ERR("IRQ hardware ERROR: 0x%08x", irq); } /* Any valid IRQ clears the stuck counter */ @@ -450,7 +443,6 @@ static void lr11xx_dio1_work_handler(struct k_work *work) if (irq & LR11XX_SYSTEM_IRQ_CAD_DONE) { bool detected = (irq & LR11XX_SYSTEM_IRQ_CAD_DETECTED) != 0; - LOG_DBG("CAD done: %s", detected ? "activity" : "free"); data->cad_active = false; if (data->cad_cb) { @@ -471,7 +463,6 @@ static void lr11xx_dio1_work_handler(struct k_work *work) /* ── TX done ── */ if (irq & LR11XX_SYSTEM_IRQ_TX_DONE) { - LOG_DBG("TX done"); data->tx_active = false; /* Full restart — modem was reconfigured for TX */ @@ -486,7 +477,6 @@ static void lr11xx_dio1_work_handler(struct k_work *work) /* ── Timeout ── */ if (irq & LR11XX_SYSTEM_IRQ_TIMEOUT) { - LOG_DBG("Timeout IRQ — restarting RX"); if (!data->tx_active) { lr11xx_restart_rx(data); rx_restarted = true; @@ -497,7 +487,7 @@ static void lr11xx_dio1_work_handler(struct k_work *work) if (irq & LR11XX_SYSTEM_IRQ_CRC_ERROR || ((irq & LR11XX_SYSTEM_IRQ_HEADER_ERROR) && !(irq & LR11XX_SYSTEM_IRQ_SYNC_WORD_HEADER_VALID))) { - LOG_WRN("RX error: CRC=%d HDR=%d", + LOG_DBG("RX error: CRC=%d HDR=%d", (irq & LR11XX_SYSTEM_IRQ_CRC_ERROR) ? 1 : 0, (irq & LR11XX_SYSTEM_IRQ_HEADER_ERROR) ? 1 : 0); @@ -532,7 +522,7 @@ safety_check: * Without this, the radio stays in STDBY_RC (fallback mode) and * never receives again — permanently deaf. */ if (!rx_restarted && data->in_rx_mode && !data->tx_active) { - LOG_WRN("DIO1 safety: no IRQ handled (0x%08x rc=%d), " + LOG_ERR("DIO1 safety: no IRQ handled (0x%08x rc=%d), " "restarting RX", irq, rc); lr11xx_restart_rx(data); } @@ -653,7 +643,6 @@ static int lr11xx_lora_send_async(const struct device *dev, if (data->modem_cfg.cad.mode == LORA_CAD_MODE_LBT) { int cad_ret = lr11xx_lora_cad(dev, K_MSEC(200)); if (cad_ret > 0) { - LOG_DBG("LBT: channel busy"); return -EBUSY; } if (cad_ret < 0 && cad_ret != -ENOSYS) { @@ -709,8 +698,6 @@ static int lr11xx_lora_send_async(const struct device *dev, lr11xx_radio_set_tx(ctx, 5000); k_mutex_unlock(&data->spi_mutex); - - LOG_DBG("TX started: len=%u", data_len); return 0; } @@ -764,10 +751,6 @@ static int lr11xx_lora_recv_async(const struct device *dev, lr11xx_start_rx(data, cfg); k_mutex_unlock(&data->spi_mutex); - - LOG_INF("recv_async started (continuous RX%s)", - data->rx_boost_enabled ? ", boosted" : ""); - return 0; } @@ -828,7 +811,7 @@ void lr11xx_set_rx_boost(const struct device *dev, bool enable) } data->rx_boost_enabled = enable; - LOG_INF("RX boost %s", enable ? "enabled" : "disabled"); + LOG_DBG("RX boost %s", enable ? "enabled" : "disabled"); if (data->in_rx_mode && data->configured) { /* Radio is fully configured — safe to apply immediately */ diff --git a/zephcore/patches/zephyr-new/drivers/lora/lr20xx/lr20xx_lora.c b/zephcore/patches/zephyr-new/drivers/lora/lr20xx/lr20xx_lora.c index df151c9..a99dddc 100644 --- a/zephcore/patches/zephyr-new/drivers/lora/lr20xx/lr20xx_lora.c +++ b/zephcore/patches/zephyr-new/drivers/lora/lr20xx/lr20xx_lora.c @@ -103,8 +103,9 @@ struct lr20xx_data { uint8_t rx_buf[256]; }; -/* ── Debug: dump full chip state ────────────────────────────────────── */ +/* ── Debug: dump full chip state (log builds only) ──────────────────── */ +#if IS_ENABLED(CONFIG_LOG) static void dump_chip_state(void *ctx, struct lr20xx_hal_context *hal, const char *label) { @@ -122,6 +123,10 @@ static void dump_chip_state(void *ctx, struct lr20xx_hal_context *hal, LOG_INF("[%s] cmd=%d mode=%d err=0x%04x irq=0x%08x BUSY=%d DIO9=%d", label, s1.command_status, s2.chip_mode, err, irq, busy, dio9); } +#define DUMP_CHIP_STATE(ctx, hal, label) dump_chip_state(ctx, hal, label) +#else +#define DUMP_CHIP_STATE(ctx, hal, label) do { } while (0) +#endif /* IS_ENABLED(CONFIG_LOG) */ /* ── Helpers ────────────────────────────────────────────────────────── */ @@ -366,10 +371,10 @@ static void lr20xx_apply_modem_config(struct lr20xx_data *data, lr20xx_status_t rc; rc = lr20xx_radio_common_set_pkt_type(ctx, LR20XX_RADIO_COMMON_PKT_TYPE_LORA); - LOG_INF("modem_cfg: set_pkt_type=%d", rc); + LOG_DBG("modem_cfg: set_pkt_type=%d", rc); rc = lr20xx_radio_common_set_rf_freq(ctx, mc->frequency); - LOG_INF("modem_cfg: set_rf_freq(%u)=%d", mc->frequency, rc); + LOG_DBG("modem_cfg: set_rf_freq(%u)=%d", mc->frequency, rc); /* Always configure the RX path after setting frequency * (reference does this on every set_rf_freq call). */ @@ -379,8 +384,6 @@ static void lr20xx_apply_modem_config(struct lr20xx_data *data, ? LR20XX_RADIO_COMMON_RX_PATH_BOOST_MODE_4 : LR20XX_RADIO_COMMON_RX_PATH_BOOST_MODE_NONE); data->rx_boost_applied = data->rx_boost_enabled; - LOG_INF("modem_cfg: set_rx_path(LF, boost=%d)=%d", - data->rx_boost_enabled, rc); /* LR20xx uses PPM offset instead of explicit LDRO. * PPM_1_4 (1 bin every 4) is equivalent to LDRO for high-SF @@ -394,7 +397,7 @@ static void lr20xx_apply_modem_config(struct lr20xx_data *data, bw_enum_to_lr20xx(mc->bandwidth)), }; rc = lr20xx_radio_lora_set_modulation_params(ctx, &mod); - LOG_INF("modem_cfg: set_mod(SF%d BW%d CR%d PPM%d)=%d", + LOG_DBG("modem_cfg: set_mod(SF%d BW%d CR%d PPM%d)=%d", mod.sf, mod.bw, mod.cr, mod.ppm, rc); /* DCDC workaround removed — LDO mode, RadioLib doesn't do it */ @@ -409,13 +412,13 @@ static void lr20xx_apply_modem_config(struct lr20xx_data *data, : LR20XX_RADIO_LORA_IQ_STANDARD, }; rc = lr20xx_radio_lora_set_packet_params(ctx, &pkt); - LOG_INF("modem_cfg: set_pkt(pre=%d len=%d crc=%d iq=%d)=%d", + LOG_DBG("modem_cfg: set_pkt(pre=%d len=%d crc=%d iq=%d)=%d", pkt.preamble_len_in_symb, pkt.pld_len_in_bytes, pkt.crc, pkt.iq, rc); rc = lr20xx_radio_lora_set_syncword(ctx, mc->public_network ? 0x34 : 0x12); - LOG_INF("modem_cfg: set_syncword(0x%02x)=%d", + LOG_DBG("modem_cfg: set_syncword(0x%02x)=%d", mc->public_network ? 0x34 : 0x12, rc); if (tx_mode) { @@ -435,33 +438,22 @@ static void lr20xx_apply_modem_config(struct lr20xx_data *data, lr20xx_get_pa_cfg_for_power(mc->tx_power, &pa, &half_power); rc = lr20xx_radio_common_set_pa_cfg(ctx, &pa); - LOG_INF("modem_cfg: set_pa_cfg(sel=%d mode=%d duty=%d slices=%d hf_duty=%d)=%d", + LOG_DBG("modem_cfg: set_pa_cfg(sel=%d mode=%d duty=%d slices=%d hf_duty=%d)=%d", pa.pa_sel, pa.pa_lf_mode, pa.pa_lf_duty_cycle, pa.pa_lf_slices, pa.pa_hf_duty_cycle, rc); - LOG_INF("modem_cfg: PA SPI bytes: 0x%02x 0x%02x 0x%02x", - (uint8_t)((pa.pa_sel << 7) | pa.pa_lf_mode), - (uint8_t)((pa.pa_lf_duty_cycle << 4) | pa.pa_lf_slices), - pa.pa_hf_duty_cycle); rc = lr20xx_radio_common_set_tx_params(ctx, half_power, LR20XX_RADIO_COMMON_RAMP_48_US); - LOG_INF("modem_cfg: set_tx_params(half_pwr=%d ramp=0x05)=%d", + LOG_DBG("modem_cfg: set_tx_params(half_pwr=%d ramp=0x05)=%d", half_power, rc); - - dump_chip_state(ctx, &data->hal_ctx, "post-PA"); } rc = lr20xx_system_set_dio_irq_cfg(ctx, LR20XX_SYSTEM_DIO_9, LR20XX_SYSTEM_IRQ_ALL_MASK & ~(LR20XX_SYSTEM_IRQ_FIFO_RX | LR20XX_SYSTEM_IRQ_FIFO_TX)); - LOG_INF("modem_cfg: set_dio_irq=%d", rc); + LOG_DBG("modem_cfg: set_dio_irq=%d", rc); - /* Verify packet type is still LoRa after all config */ - lr20xx_radio_common_pkt_type_t pkt_check = 0xFF; - lr20xx_radio_common_get_pkt_type(ctx, &pkt_check); - - dump_chip_state(ctx, &data->hal_ctx, tx_mode ? "modem-TX" : "modem-RX"); - LOG_INF("modem_cfg: pkt_type_verify=%d (1=LORA)", pkt_check); + DUMP_CHIP_STATE(ctx, &data->hal_ctx, tx_mode ? "modem-TX" : "modem-RX"); } /* ── RX duty cycle ──────────────────────────────────────────────────── */ @@ -548,13 +540,10 @@ static void lr20xx_start_rx(struct lr20xx_data *data, void *ctx = &data->hal_ctx; lr20xx_status_t rc; - LOG_INF("start_rx: t=%lld", k_uptime_get()); - /* Standby first — wake from any state (radio_is_sleeping is managed * by the HAL via sleep opcode detection; do not set it here). */ rc = lr20xx_system_set_standby_mode(ctx, LR20XX_SYSTEM_STANDBY_MODE_RC); - LOG_INF("start_rx: standby=%d", rc); if (rc != LR20XX_STATUS_OK) { LOG_ERR("standby failed (rc=%d) — triggering HW reset", rc); lr20xx_hardware_reset(data, cfg); @@ -574,9 +563,8 @@ static void lr20xx_start_rx(struct lr20xx_data *data, lr20xx_apply_rx_duty_cycle(data); /* apply may have disabled duty cycle if preamble too short */ } else { - rc = lr20xx_radio_common_set_rx_with_timeout_in_rtc_step( + lr20xx_radio_common_set_rx_with_timeout_in_rtc_step( ctx, 0xFFFFFF); - LOG_INF("start_rx: set_rx(continuous)=%d", rc); } /* Clear any IRQ flags set during modem configuration */ @@ -584,8 +572,6 @@ static void lr20xx_start_rx(struct lr20xx_data *data, data->in_rx_mode = true; data->tx_active = false; - - dump_chip_state(ctx, &data->hal_ctx, "start-RX"); } /* ── Lightweight RX restart (no modem reconfig) ─────────────────────── */ @@ -629,9 +615,6 @@ static void lr20xx_dio1_work_handler(struct k_work *work) goto safety_check; } - LOG_DBG("DIO1 IRQ: 0x%08x tx=%d t=%lld", irq, data->tx_active, - k_uptime_get()); - if (irq & LR20XX_SYSTEM_IRQ_ERROR) { LOG_WRN("IRQ hardware ERROR: 0x%08x", irq); } @@ -810,7 +793,7 @@ static int lr20xx_lora_config(const struct device *dev, /* FE cal raw value: ceil(freq / 4MHz), bit 15 = HF flag */ uint16_t fe_raw = (uint16_t)((config->frequency + 3999999U) / 4000000U); - LOG_INF("config: FE cal freq=%uHz raw=0x%04x", config->frequency, fe_raw); + LOG_DBG("config: FE cal freq=%uHz raw=0x%04x", config->frequency, fe_raw); lr20xx_radio_common_front_end_calibration_value_t cal = { .rx_path = LR20XX_RADIO_COMMON_RX_PATH_LF, @@ -818,12 +801,12 @@ static int lr20xx_lora_config(const struct device *dev, }; lr20xx_status_t cal_rc = lr20xx_radio_common_calibrate_front_end_helper( &data->hal_ctx, &cal, 1); - LOG_INF("config: FE cal=%d", cal_rc); + LOG_DBG("config: FE cal=%d", cal_rc); - dump_chip_state(&data->hal_ctx, &data->hal_ctx, "config-FEcal"); + DUMP_CHIP_STATE(&data->hal_ctx, &data->hal_ctx, "config-FEcal"); k_mutex_unlock(&data->spi_mutex); - LOG_INF("config: %uHz SF%d BW%d CR%d pwr=%d tx=%d", + LOG_DBG("config: %uHz SF%d BW%d CR%d pwr=%d tx=%d", config->frequency, config->datarate, config->bandwidth, config->coding_rate, config->tx_power, config->tx); @@ -890,19 +873,14 @@ static int lr20xx_lora_send_async(const struct device *dev, lr20xx_hal_disable_dio1_irq(&data->hal_ctx); - LOG_INF("=== TX BEGIN len=%u ===", data_len); - dump_chip_state(ctx, &data->hal_ctx, "TX-enter"); - /* Standby */ lr20xx_status_t rc = lr20xx_system_set_standby_mode(ctx, LR20XX_SYSTEM_STANDBY_MODE_RC); - LOG_INF("TX: standby=%d", rc); if (rc != LR20XX_STATUS_OK) { LOG_ERR("TX standby failed — HW reset"); lr20xx_hardware_reset(data, cfg); } - dump_chip_state(ctx, &data->hal_ctx, "TX-standby"); /* Clear errors before modem config */ lr20xx_system_clear_errors(ctx); @@ -922,37 +900,24 @@ static int lr20xx_lora_send_async(const struct device *dev, ? LR20XX_RADIO_LORA_IQ_INVERTED : LR20XX_RADIO_LORA_IQ_STANDARD, }; - rc = lr20xx_radio_lora_set_packet_params(ctx, &pkt); - LOG_INF("TX: set_pkt_params(len=%d)=%d", data_len, rc); + lr20xx_radio_lora_set_packet_params(ctx, &pkt); /* Write to TX FIFO */ - rc = lr20xx_radio_fifo_write_tx(ctx, buf, (uint16_t)data_len); - LOG_INF("TX: fifo_write(%u bytes)=%d", data_len, rc); + lr20xx_radio_fifo_write_tx(ctx, buf, (uint16_t)data_len); /* Clear ALL errors + IRQs right before set_tx */ lr20xx_system_clear_errors(ctx); lr20xx_system_clear_irq_status(ctx, LR20XX_SYSTEM_IRQ_ALL_MASK); - dump_chip_state(ctx, &data->hal_ctx, "TX-pre-setTX"); - lr20xx_hal_enable_dio1_irq(&data->hal_ctx); data->tx_signal = async; data->tx_active = true; - /* THE CRITICAL CALL — set_tx sends opcode 0x020D */ - lr20xx_status_t tx_rc = lr20xx_radio_common_set_tx(ctx, 5000); - LOG_INF("TX: set_tx(5000ms)=%d (0=OK, HAL-level)", tx_rc); - - dump_chip_state(ctx, &data->hal_ctx, "TX-post-setTX"); - - /* Wait 10ms and re-check — did the chip stay in TX or fall out? */ - k_msleep(10); - dump_chip_state(ctx, &data->hal_ctx, "TX-10ms-later"); + lr20xx_radio_common_set_tx(ctx, 5000); k_mutex_unlock(&data->spi_mutex); - LOG_INF("=== TX END ==="); return 0; } @@ -1007,9 +972,6 @@ static int lr20xx_lora_recv_async(const struct device *dev, k_mutex_unlock(&data->spi_mutex); - LOG_INF("recv_async: continuous RX%s", - data->rx_boost_enabled ? ", boosted" : ""); - return 0; } @@ -1074,7 +1036,7 @@ void lr20xx_set_rx_boost(const struct device *dev, bool enable) } data->rx_boost_enabled = enable; - LOG_INF("RX boost %s", enable ? "enabled" : "disabled"); + LOG_DBG("RX boost %s", enable ? "enabled" : "disabled"); if (data->in_rx_mode && data->configured) { k_mutex_lock(&data->spi_mutex, K_FOREVER); @@ -1371,7 +1333,7 @@ static int lr20xx_hw_init(struct lr20xx_data *data, const uint8_t cmd[2] = { 0x01, 0x01 }; uint8_t raw[4] = { 0 }; lr20xx_hal_read(ctx, cmd, 2, raw, 4); - LOG_INF("GET_VERSION raw bytes: 0x%02x 0x%02x 0x%02x 0x%02x", + LOG_DBG("GET_VERSION raw bytes: 0x%02x 0x%02x 0x%02x 0x%02x", raw[0], raw[1], raw[2], raw[3]); if (raw[0] == 0x01) { LOG_WRN("*** CHIP IDENTIFIES AS LR1110 (LR11x0 family!) ***"); @@ -1380,26 +1342,25 @@ static int lr20xx_hw_init(struct lr20xx_data *data, } else if (raw[0] == 0x03) { LOG_WRN("*** CHIP IDENTIFIES AS LR1121 (LR11x0 family!) ***"); } else { - LOG_INF("Chip type byte=0x%02x (LR20xx if not 0x01-0x03)", raw[0]); + LOG_DBG("Chip type byte=0x%02x (LR20xx if not 0x01-0x03)", raw[0]); } } - dump_chip_state(ctx, &data->hal_ctx, "post-reset"); + DUMP_CHIP_STATE(ctx, &data->hal_ctx, "post-reset"); /* SIMO DC-DC workaround REMOVED — datasheet §22.6 says it's only * needed when SetRegMode simo_usage=0x02 (SIMO_NORMAL). * We run in LDO mode (default, simo_usage=0x00). */ - LOG_INF("init: LDO mode — SIMO workaround skipped (per DS §22.6)"); if (cfg->tcxo_voltage_mv > 0) { uint32_t tcxo_ticks = (cfg->tcxo_startup_delay_ms * 1000U) / 31U; lr20xx_status_t tcxo_rc = lr20xx_system_set_tcxo_mode(ctx, get_tcxo_voltage(cfg->tcxo_voltage_mv), tcxo_ticks); - LOG_INF("init: set_tcxo(%dmV, %u ticks)=%d", + LOG_DBG("init: set_tcxo(%dmV, %u ticks)=%d", cfg->tcxo_voltage_mv, tcxo_ticks, tcxo_rc); } else { - LOG_INF("init: TCXO disabled (XTAL mode)"); + LOG_DBG("init: TCXO disabled (XTAL mode)"); } /* RadioLib does NOT call cfg_lfclk or set_reg_mode. @@ -1407,30 +1368,26 @@ static int lr20xx_hw_init(struct lr20xx_data *data, * DCDC mode + wrong SET_REG_MODE encoding was likely * preventing TX. */ lr20xx_status_t st; - LOG_INF("init: LDO mode (RadioLib-compatible, no DCDC)"); lr20xx_configure_rfswitch(ctx, cfg); - LOG_INF("RF switch: en=0x%02x stby=0x%02x rx=0x%02x tx=0x%02x txhp=0x%02x", + LOG_DBG("RF switch: en=0x%02x stby=0x%02x rx=0x%02x tx=0x%02x txhp=0x%02x", cfg->rfswitch_enable, cfg->rfswitch_standby, cfg->rfswitch_rx, cfg->rfswitch_tx, cfg->rfswitch_tx_hp); st = lr20xx_system_set_dio_function(ctx, LR20XX_SYSTEM_DIO_9, LR20XX_SYSTEM_DIO_FUNC_IRQ, LR20XX_SYSTEM_DIO_DRIVE_NONE); - LOG_INF("init: set_dio9_func(IRQ)=%d", st); st = lr20xx_radio_common_set_rx_tx_fallback_mode(ctx, LR20XX_RADIO_FALLBACK_STDBY_RC); - LOG_INF("init: set_fallback(STDBY_RC)=%d", st); - dump_chip_state(ctx, &data->hal_ctx, "pre-cal"); + DUMP_CHIP_STATE(ctx, &data->hal_ctx, "pre-cal"); lr20xx_system_clear_errors(ctx); lr20xx_system_clear_irq_status(ctx, LR20XX_SYSTEM_IRQ_ALL_MASK); /* Calibrate all analog blocks: 0x6F = LF_RC|HF_RC|PLL|AAF|MU|PA_OFF */ st = lr20xx_system_calibrate(ctx, 0x6F); - LOG_INF("init: calibrate(0x6F)=%d", st); /* RadioLib waits for BUSY to go LOW after calibrate. * We poll the BUSY pin (max 500ms timeout). */ @@ -1443,11 +1400,9 @@ static int lr20xx_hw_init(struct lr20xx_data *data, break; } } - LOG_INF("init: calibrate BUSY wait %lldms", - k_uptime_get() - cal_start); } - dump_chip_state(ctx, &data->hal_ctx, "post-cal"); + DUMP_CHIP_STATE(ctx, &data->hal_ctx, "post-cal"); /* Front-end calibration at 868 MHz LF. * raw_value = ceil(868000000/4000000) = 217 = 0x00D9 */ @@ -1458,21 +1413,18 @@ static int lr20xx_hw_init(struct lr20xx_data *data, { .rx_path = 0, .frequency_in_hertz = 0 }, }; st = lr20xx_radio_common_calibrate_front_end_helper(ctx, fe_cal, 1); - LOG_INF("init: FE_cal(868MHz LF, raw=0x00D9)=%d", st); - dump_chip_state(ctx, &data->hal_ctx, "post-FEcal"); + DUMP_CHIP_STATE(ctx, &data->hal_ctx, "post-FEcal"); /* Verify: set packet type to LoRa and read it back */ st = lr20xx_radio_common_set_pkt_type(ctx, LR20XX_RADIO_COMMON_PKT_TYPE_LORA); - LOG_INF("init: set_pkt_type(LORA)=%d", st); /* dcdc_reset removed — not needed in LDO mode, RadioLib doesn't do it */ lr20xx_radio_common_pkt_type_t pkt_readback = 0xFF; lr20xx_radio_common_get_pkt_type(ctx, &pkt_readback); - LOG_INF("init: pkt_type readback=%d (expect 1=LORA)", pkt_readback); - dump_chip_state(ctx, &data->hal_ctx, "init-done"); + DUMP_CHIP_STATE(ctx, &data->hal_ctx, "init-done"); lr20xx_system_clear_errors(ctx); lr20xx_hal_enable_dio1_irq(&data->hal_ctx); diff --git a/zephcore/src/Dispatcher.cpp b/zephcore/src/Dispatcher.cpp index d7bbe64..533353c 100644 --- a/zephcore/src/Dispatcher.cpp +++ b/zephcore/src/Dispatcher.cpp @@ -207,7 +207,7 @@ void Dispatcher::checkRecv() Packet *pkt = _mgr->allocNew(); if (pkt == nullptr) { - LOG_WRN("checkRecv: packet alloc failed"); + LOG_ERR("checkRecv: packet alloc failed"); break; } @@ -301,7 +301,7 @@ void Dispatcher::checkSend() } if (now - cad_busy_start > getCADFailMaxDuration()) { _err_flags |= ERR_EVENT_CAD_TIMEOUT; - LOG_WRN("checkSend: CAD timeout exceeded"); + LOG_ERR("checkSend: CAD timeout exceeded"); } else { uint32_t retry = getCADFailRetryDelay(); next_tx_time = futureMillis((int)retry); @@ -338,7 +338,7 @@ void Dispatcher::checkSend() len += Packet::writePath(&raw[len], outbound->path, outbound->path_len); if (len + outbound->payload_len > MAX_TRANS_UNIT) { - LOG_WRN("checkSend: packet too large len=%d+%d > %d", len, outbound->payload_len, MAX_TRANS_UNIT); + LOG_ERR("checkSend: packet too large len=%d+%d > %d", len, outbound->payload_len, MAX_TRANS_UNIT); _mgr->free(outbound); outbound = nullptr; } else { @@ -416,7 +416,7 @@ void Dispatcher::releasePacket(Packet *packet) void Dispatcher::sendPacket(Packet *packet, uint8_t priority, uint32_t delay_millis) { if (!Packet::isValidPathLen(packet->path_len) || packet->payload_len > MAX_PACKET_PAYLOAD) { - LOG_WRN("sendPacket: rejected - path_len=%d or payload_len=%d invalid", + LOG_ERR("sendPacket: rejected - path_len=%d or payload_len=%d invalid", packet->path_len, packet->payload_len); _mgr->free(packet); } else { diff --git a/zephcore/src/Mesh.cpp b/zephcore/src/Mesh.cpp index 20e724c..23cac45 100644 --- a/zephcore/src/Mesh.cpp +++ b/zephcore/src/Mesh.cpp @@ -630,7 +630,7 @@ Packet *Mesh::createDatagram(uint8_t type, const Identity &dest, const uint8_t * Packet *packet = obtainNewPacket(); if (packet == nullptr) { - LOG_WRN("createDatagram: packet alloc failed"); + LOG_ERR("createDatagram: packet alloc failed"); return nullptr; } diff --git a/zephcore/src/main_repeater.cpp b/zephcore/src/main_repeater.cpp index 16a3ef6..ec97f76 100644 --- a/zephcore/src/main_repeater.cpp +++ b/zephcore/src/main_repeater.cpp @@ -12,7 +12,7 @@ #include #include -LOG_MODULE_REGISTER(zephcore_repeater_main, CONFIG_ZEPHCORE_LORA_LOG_LEVEL); +LOG_MODULE_REGISTER(zephcore_repeater_main, CONFIG_ZEPHCORE_MAIN_LOG_LEVEL); #include #include