logging cleanup

This commit is contained in:
liquidraver
2026-03-29 09:51:53 +02:00
parent 33fa19a7f5
commit 0e5e71563c
20 changed files with 124 additions and 196 deletions
+4
View File
@@ -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"
+4 -7
View File
@@ -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) {
+1 -1
View File
@@ -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;
@@ -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);
+5 -7
View File
@@ -29,7 +29,7 @@
#include <stdio.h>
#include <string.h>
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 */
+1 -1
View File
@@ -12,7 +12,7 @@ extern "C" {
}
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(zephcore_lora, CONFIG_ZEPHCORE_LORA_LOG_LEVEL);
LOG_MODULE_REGISTER(sx126x_radio, CONFIG_ZEPHCORE_LORA_LOG_LEVEL);
namespace mesh {
+1 -1
View File
@@ -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;
}
+2 -2
View File
@@ -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();
+23 -23
View File
@@ -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;
+4 -4
View File
@@ -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 */
+2 -2
View File
@@ -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;
}
+18 -18
View File
@@ -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(&timestamp, 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;
}
+3 -3
View File
@@ -26,7 +26,7 @@
#include <stdio.h>
#include <zephyr/logging/log.h>
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;
+2 -2
View File
@@ -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 */
+2 -4
View File
@@ -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()) {
@@ -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 */
@@ -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);
+4 -4
View File
@@ -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 {
+1 -1
View File
@@ -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;
}
+1 -1
View File
@@ -12,7 +12,7 @@
#include <zephyr/sys/util.h>
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(zephcore_repeater_main, CONFIG_ZEPHCORE_LORA_LOG_LEVEL);
LOG_MODULE_REGISTER(zephcore_repeater_main, CONFIG_ZEPHCORE_MAIN_LOG_LEVEL);
#include <zephyr/device.h>
#include <zephyr/devicetree.h>