log fixes

This commit is contained in:
liquidraver
2026-02-26 14:36:31 +01:00
parent ced260c8c3
commit 7370356ae0
5 changed files with 38 additions and 139 deletions
+7 -50
View File
@@ -149,7 +149,6 @@ CompanionMesh::CompanionMesh(mesh::Radio &radio, mesh::MillisecondClock &ms, mes
_batt_cb = nullptr;
_radio_reconfig_cb = nullptr;
_pin_change_cb = nullptr;
_save_schedule_cb = nullptr;
_contact_iter_active = false;
_contact_iter_idx = 0;
_contact_iter_lastmod = 0;
@@ -276,34 +275,10 @@ void CompanionMesh::markChannelsDirty()
void CompanionMesh::flushDirtyContacts()
{
if (_dirty_contacts_expiry) {
_dirty_contacts_expiry = 0;
if (_save_schedule_cb) {
/* Offload flash I/O to system workqueue — main thread
* stays free to drain LoRa ring buffer / process BLE. */
LOG_INF("flushDirtyContacts: scheduling background save");
_save_schedule_cb();
} else {
/* No callback set — save synchronously (fallback) */
LOG_INF("flushDirtyContacts: saving contacts (sync)");
_store->saveContacts(this);
}
}
}
void CompanionMesh::flushAllSync()
{
/* Synchronous flush for reboot path — MUST complete before sys_reboot.
* Clears dirty flags so any pending background work is a no-op. */
if (_dirty_contacts_expiry) {
LOG_INF("flushAllSync: saving contacts");
LOG_INF("flushDirtyContacts: saving contacts (lazy write)");
_store->saveContacts(this);
_dirty_contacts_expiry = 0;
}
if (_dirty_channels_expiry) {
LOG_INF("flushAllSync: saving channels");
_store->saveChannels(this);
_dirty_channels_expiry = 0;
}
}
void CompanionMesh::flushDirtyChannels()
@@ -569,30 +544,22 @@ ContactInfo *CompanionMesh::processAck(const uint8_t *data)
{
uint32_t ack_crc;
memcpy(&ack_crc, data, 4);
LOG_INF("processAck: received ack_crc=0x%08x", ack_crc);
uint32_t sent_time = 0;
int contact_idx = findAndRemoveAck(ack_crc, &sent_time);
LOG_INF("processAck: findAndRemoveAck returned idx=%d sent_time=%u", contact_idx, sent_time);
if (contact_idx >= 0) {
ContactInfo ci;
if (getContactByIdx(contact_idx, ci)) {
LOG_INF("processAck: ACK matched contact '%s', sending push", ci.name);
// Send push notification in Arduino-compatible format:
// [PUSH_CODE_SEND_CONFIRMED] + [4-byte ack_crc] + [4-byte trip_time]
uint8_t ack_push[8]; // 4 bytes ack + 4 bytes trip_time
memcpy(ack_push, data, 4); // ack_crc
uint8_t ack_push[8];
memcpy(ack_push, data, 4);
uint32_t now = (uint32_t)_ms->getMillis();
uint32_t trip_time = now - sent_time;
put_le32(&ack_push[4], trip_time);
LOG_INF("processAck: ack_push ack_crc=0x%08x trip_time=%u", ack_crc, trip_time);
sendPush(PUSH_CODE_SEND_CONFIRMED, ack_push, 8);
return lookupContactByPubKey(ci.id.pub_key, PUB_KEY_SIZE);
}
}
LOG_INF("processAck: no matching pending ACK, checking connections");
return checkConnectionsAck(data);
}
@@ -1151,11 +1118,7 @@ bool CompanionMesh::isAutoAddEnabled() const
bool CompanionMesh::shouldAutoAddContactType(uint8_t contact_type) const
{
LOG_INF("shouldAutoAddContactType: type=%d manual_add=0x%02x autoadd_cfg=0x%02x",
contact_type, prefs.manual_add_contacts, prefs.autoadd_config);
if ((prefs.manual_add_contacts & 1) == 0) {
LOG_INF("shouldAutoAddContactType: returning true (manual mode OFF)");
return true; // Auto-add all when not in manual mode
}
@@ -1174,12 +1137,9 @@ bool CompanionMesh::shouldAutoAddContactType(uint8_t contact_type) const
type_bit = AUTO_ADD_SENSOR;
break;
default:
LOG_INF("shouldAutoAddContactType: unknown type, returning false");
return false;
}
bool result = (prefs.autoadd_config & type_bit) != 0;
LOG_INF("shouldAutoAddContactType: type_bit=0x%02x result=%d", type_bit, result);
return result;
return (prefs.autoadd_config & type_bit) != 0;
}
bool CompanionMesh::shouldOverwriteWhenFull() const
@@ -1285,14 +1245,10 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len)
memcpy(&rsp[i], self_id.pub_key, PUB_KEY_SIZE); i += PUB_KEY_SIZE;
int32_t lat = (int32_t)(prefs.node_lat * 1000000.0);
int32_t lon = (int32_t)(prefs.node_lon * 1000000.0);
LOG_INF("SELF_INFO: lat=%d lon=%d advert_loc=%d multi_acks=%d",
lat, lon, prefs.advert_loc_policy, prefs.multi_acks);
put_le32(&rsp[i], lat); i += 4;
put_le32(&rsp[i], lon); i += 4;
rsp[i++] = prefs.multi_acks;
rsp[i++] = prefs.advert_loc_policy;
LOG_INF("SELF_INFO bytes[36-45]: %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x",
rsp[36], rsp[37], rsp[38], rsp[39], rsp[40], rsp[41], rsp[42], rsp[43], rsp[44], rsp[45]);
// Telemetry modes: (env << 4) | (loc << 2) | base
rsp[i++] = (prefs.telemetry_mode_env << 4) | (prefs.telemetry_mode_loc << 2) | prefs.telemetry_mode_base;
rsp[i++] = prefs.manual_add_contacts;
@@ -1916,8 +1872,9 @@ bool CompanionMesh::handleProtocolFrame(const uint8_t *data, size_t len)
case CMD_REBOOT:
if (len >= 7 && memcmp(&data[1], "reboot", 6) == 0) {
LOG_INF("Reboot requested");
/* Synchronous flush — must complete before reboot */
flushAllSync();
/* Flush any pending lazy writes before reboot */
flushDirtyContacts();
flushDirtyChannels();
sendPacketOk();
sys_reboot(SYS_REBOOT_COLD);
} else {
+6 -28
View File
@@ -223,9 +223,8 @@ int RepeaterMesh::handleRequest(ClientInfo* sender, uint32_t sender_timestamp, u
stats.n_recv_direct = getNumRecvDirect();
stats.err_events = _err_flags;
stats.last_snr = (int16_t)(radio_driver.getLastSNR() * 4);
/* Note: dup counters not implemented in Zephyr SimpleMeshTables */
stats.n_direct_dups = 0;
stats.n_flood_dups = 0;
stats.n_direct_dups = ((mesh::SimpleMeshTables *)getTables())->getNumDirectDups();
stats.n_flood_dups = ((mesh::SimpleMeshTables *)getTables())->getNumFloodDups();
stats.total_rx_air_time_secs = getReceiveAirTime() / 1000;
stats.n_recv_errors = radio_driver.getPacketsRecvErrors();
memcpy(&reply_data[4], &stats, sizeof(stats));
@@ -398,22 +397,9 @@ mesh::Packet* RepeaterMesh::createSelfAdvert() {
}
bool RepeaterMesh::allowPacketForward(const mesh::Packet* packet) {
if (_prefs.disable_fwd) {
LOG_INF("allowPacketForward: BLOCKED - disable_fwd=1");
return false;
}
if (packet->isRouteFlood() && packet->path_len >= _prefs.flood_max) {
LOG_INF("allowPacketForward: BLOCKED - path_len=%d >= flood_max=%d",
packet->path_len, _prefs.flood_max);
return false;
}
if (packet->isRouteFlood() && recv_pkt_region == nullptr) {
LOG_INF("allowPacketForward: BLOCKED - recv_pkt_region=NULL (route_type=0x%02x)",
packet->getRouteType());
return false;
}
LOG_INF("allowPacketForward: ALLOWED (flood=%d path_len=%d)",
packet->isRouteFlood() ? 1 : 0, packet->path_len);
if (_prefs.disable_fwd) return false;
if (packet->isRouteFlood() && packet->path_len >= _prefs.flood_max) return false;
if (packet->isRouteFlood() && recv_pkt_region == nullptr) return false;
return true;
}
@@ -500,24 +486,16 @@ uint32_t RepeaterMesh::getDirectRetransmitDelay(const mesh::Packet* packet) {
}
bool RepeaterMesh::filterRecvFloodPacket(mesh::Packet* pkt) {
LOG_INF("filterRecvFloodPacket: route_type=0x%02x wildcard_flags=0x%02x",
pkt->getRouteType(), region_map.getWildcard().flags);
if (pkt->getRouteType() == ROUTE_TYPE_TRANSPORT_FLOOD) {
recv_pkt_region = region_map.findMatch(pkt, REGION_DENY_FLOOD);
LOG_INF("filterRecvFloodPacket: TRANSPORT_FLOOD -> recv_pkt_region=%s",
recv_pkt_region ? recv_pkt_region->name : "NULL");
} else if (pkt->getRouteType() == ROUTE_TYPE_FLOOD) {
if (region_map.getWildcard().flags & REGION_DENY_FLOOD) {
recv_pkt_region = nullptr;
LOG_INF("filterRecvFloodPacket: FLOOD denied by wildcard");
} else {
recv_pkt_region = &region_map.getWildcard();
LOG_INF("filterRecvFloodPacket: FLOOD -> wildcard region '%s'",
recv_pkt_region->name);
}
} else {
recv_pkt_region = nullptr;
LOG_INF("filterRecvFloodPacket: not a flood packet -> NULL");
}
return false;
}
@@ -963,7 +941,7 @@ void RepeaterMesh::clearStats() {
auto& radio_driver = getRadioDriver(_radio);
radio_driver.resetStats();
resetStats();
/* Note: SimpleMeshTables doesn't have resetStats in Zephyr version */
((mesh::SimpleMeshTables *)getTables())->resetStats();
}
void RepeaterMesh::handleCommand(uint32_t sender_timestamp, char* command, char* reply) {
+25 -4
View File
@@ -10,14 +10,15 @@
namespace mesh {
#define MAX_PACKET_HASHES 64
#define MAX_PACKET_ACKS 32
#define MAX_PACKET_HASHES 128
#define MAX_PACKET_ACKS 64
class SimpleMeshTables : public MeshTables {
uint8_t _hashes[MAX_PACKET_HASHES * MAX_HASH_SIZE];
int _next_idx;
uint32_t _acks[MAX_PACKET_ACKS];
int _next_ack_idx;
uint32_t _direct_dups, _flood_dups;
public:
SimpleMeshTables() {
@@ -25,6 +26,7 @@ public:
_next_idx = 0;
memset(_acks, 0, sizeof(_acks));
_next_ack_idx = 0;
_direct_dups = _flood_dups = 0;
}
bool hasSeen(const Packet *packet) override {
@@ -32,7 +34,14 @@ public:
uint32_t ack;
memcpy(&ack, packet->payload, 4);
for (int i = 0; i < MAX_PACKET_ACKS; i++) {
if (ack == _acks[i]) return true;
if (ack == _acks[i]) {
if (packet->isRouteDirect()) {
_direct_dups++;
} else {
_flood_dups++;
}
return true;
}
}
_acks[_next_ack_idx] = ack;
_next_ack_idx = (_next_ack_idx + 1) % MAX_PACKET_ACKS;
@@ -43,7 +52,14 @@ public:
packet->calculatePacketHash(hash);
const uint8_t *sp = _hashes;
for (int i = 0; i < MAX_PACKET_HASHES; i++, sp += MAX_HASH_SIZE) {
if (memcmp(hash, sp, MAX_HASH_SIZE) == 0) return true;
if (memcmp(hash, sp, MAX_HASH_SIZE) == 0) {
if (packet->isRouteDirect()) {
_direct_dups++;
} else {
_flood_dups++;
}
return true;
}
}
memcpy(&_hashes[_next_idx * MAX_HASH_SIZE], hash, MAX_HASH_SIZE);
_next_idx = (_next_idx + 1) % MAX_PACKET_HASHES;
@@ -72,6 +88,11 @@ public:
}
}
}
uint32_t getNumDirectDups() const { return _direct_dups; }
uint32_t getNumFloodDups() const { return _flood_dups; }
void resetStats() { _direct_dups = _flood_dups = 0; }
};
} /* namespace mesh */
-33
View File
@@ -162,7 +162,6 @@ void Dispatcher::checkRecv()
break; /* ring empty — done */
}
LOG_INF("checkRecv: got raw packet len=%d", len);
logRxRaw(_radio->getLastSNR(), _radio->getLastRSSI(), raw, len);
Packet *pkt = _mgr->allocNew();
@@ -174,7 +173,6 @@ void Dispatcher::checkRecv()
float score = 0.0f;
uint32_t air_time = 0;
LOG_INF("checkRecv: parsing packet");
int i = 0;
pkt->header = raw[i++];
if (pkt->hasTransportCodes()) {
@@ -205,24 +203,6 @@ void Dispatcher::checkRecv()
score = _radio->packetScore(_radio->getLastSNR(), len);
air_time = _radio->getEstAirtimeFor(len);
rx_air_time += air_time;
LOG_INF("checkRecv: header=0x%02x type=%d route=%s path_len=%d payload_len=%d",
pkt->header, pkt->getPayloadType(),
pkt->isRouteDirect() ? "direct" : "flood",
pkt->path_len, pkt->payload_len);
/* Log path hashes to identify forwarding nodes */
if (pkt->path_len > 0) {
LOG_INF("checkRecv: path[0]=0x%02x%s%s",
pkt->path[0],
pkt->path_len > 1 ? " path[1]=0x" : "",
pkt->path_len > 1 ? "" : "");
if (pkt->path_len > 1) {
LOG_INF(" path bytes: %02x %02x %02x %02x",
pkt->path[0],
pkt->path_len > 1 ? pkt->path[1] : 0,
pkt->path_len > 2 ? pkt->path[2] : 0,
pkt->path_len > 3 ? pkt->path[3] : 0);
}
}
#if IS_ENABLED(CONFIG_ZEPHCORE_PACKET_LOGGING)
/* Arduino-compatible packet logging - use printk to bypass log level filtering */
@@ -250,25 +230,20 @@ void Dispatcher::checkRecv()
}
}
#endif
LOG_INF("checkRecv: processing packet");
logRx(pkt, pkt->getRawLength(), score);
if (pkt->isRouteFlood()) {
n_recv_flood++;
int delay = calcRxDelay(score, air_time);
if (delay < 50) {
LOG_INF("checkRecv: processing flood packet immediately");
processRecvPacket(pkt);
} else {
if (delay > (int)MAX_RX_DELAY_MILLIS) delay = MAX_RX_DELAY_MILLIS;
LOG_INF("checkRecv: queueing flood packet, delay=%d", delay);
_mgr->queueInbound(pkt, futureMillis(delay));
}
} else {
n_recv_direct++;
LOG_INF("checkRecv: processing direct packet");
processRecvPacket(pkt);
}
LOG_INF("checkRecv: done");
}
}
@@ -306,7 +281,6 @@ void Dispatcher::checkSend()
}
if (cad_busy_start == 0) {
cad_busy_start = now;
LOG_INF("checkSend: channel busy, starting wait");
}
if (now - cad_busy_start > getCADFailMaxDuration()) {
_err_flags |= ERR_EVENT_CAD_TIMEOUT;
@@ -336,7 +310,6 @@ void Dispatcher::checkSend()
}
return;
}
LOG_INF("checkSend: got outbound type=%d payload_len=%d", outbound->getPayloadType(), outbound->payload_len);
uint8_t raw[MAX_TRANS_UNIT];
int len = 0;
raw[len++] = outbound->header;
@@ -382,7 +355,6 @@ void Dispatcher::checkSend()
* logging can take 1-5 ms). */
if (_radio->isReceiving()) {
uint32_t retry = getCADFailRetryDelay();
LOG_INF("checkSend: channel busy at TX commit, re-queuing delay=%u", retry);
_mgr->queueOutbound(outbound, 0, futureMillis((int)retry));
outbound = nullptr;
if (_tx_queued_cb) {
@@ -391,7 +363,6 @@ void Dispatcher::checkSend()
return;
}
LOG_INF("checkSend: calling startSendRaw len=%d", len);
bool success = _radio->startSendRaw(raw, len);
if (!success) {
uint32_t retry = getCADFailRetryDelay();
@@ -403,7 +374,6 @@ void Dispatcher::checkSend()
_tx_queued_cb(retry, _tx_queued_user_data);
}
} else {
LOG_INF("checkSend: TX started, max_airtime=%u", max_airtime);
outbound_expiry = futureMillis((int)max_airtime);
}
}
@@ -429,15 +399,12 @@ void Dispatcher::releasePacket(Packet *packet)
void Dispatcher::sendPacket(Packet *packet, uint8_t priority, uint32_t delay_millis)
{
LOG_INF("sendPacket: type=%d payload_len=%d path_len=%d pri=%d delay=%u",
packet->getPayloadType(), packet->payload_len, packet->path_len, priority, delay_millis);
if (packet->path_len > MAX_PATH_SIZE || packet->payload_len > MAX_PACKET_PAYLOAD) {
LOG_WRN("sendPacket: rejected - path_len=%d or payload_len=%d too large",
packet->path_len, packet->payload_len);
_mgr->free(packet);
} else {
_mgr->queueOutbound(packet, priority, futureMillis((int)delay_millis));
LOG_INF("sendPacket: queued outbound count=%d", _mgr->getOutboundCount((uint32_t)_ms->getMillis()));
if (_tx_queued_cb && delay_millis > 0) {
_tx_queued_cb(delay_millis, _tx_queued_user_data);
}
-24
View File
@@ -100,18 +100,12 @@ void Mesh::routeDirectRecvAcks(Packet *packet, uint32_t delay_millis)
DispatcherAction Mesh::onRecvPacket(Packet *pkt)
{
LOG_INF("onRecvPacket: header=0x%02x type=%d route=%s path_len=%d payload[0]=0x%02x",
pkt->header, pkt->getPayloadType(),
pkt->isRouteDirect() ? "direct" : "flood",
pkt->path_len, pkt->payload_len > 0 ? pkt->payload[0] : 0);
if (pkt->getPayloadVer() > PAYLOAD_VER_1) {
return ACTION_RELEASE;
}
// Handle direct TRACE packets
if (pkt->isRouteDirect() && pkt->getPayloadType() == PAYLOAD_TYPE_TRACE) {
LOG_INF("TRACE packet received: path_len=%d payload_len=%d", pkt->path_len, pkt->payload_len);
if (pkt->path_len < MAX_PATH_SIZE) {
int i = 0;
uint32_t trace_tag;
@@ -123,9 +117,7 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
uint8_t len = pkt->payload_len - i;
uint8_t offset = pkt->path_len << path_sz;
LOG_INF("TRACE: offset=%d len=%d path_sz=%d flags=0x%02x", offset, len, path_sz, flags);
if (offset >= len) {
LOG_INF("TRACE: calling onTraceRecv (reached end of path)");
onTraceRecv(pkt, trace_tag, auth_code, flags, pkt->path, &pkt->payload[i], len);
} else if (self_id.isHashMatch(&pkt->payload[i + offset], 1 << path_sz) && allowPacketForward(pkt) && !_tables->hasSeen(pkt)) {
pkt->path[pkt->path_len++] = (int8_t)(pkt->getSNR() * 4);
@@ -148,7 +140,6 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
if (pkt->isRouteDirect() && pkt->path_len == 0 && pkt->getPayloadType() == PAYLOAD_TYPE_ACK) {
uint32_t ack_crc;
memcpy(&ack_crc, pkt->payload, 4);
LOG_INF("onRecvPacket: direct zero-hop ACK ack_crc=0x%08x", ack_crc);
onAckRecv(pkt, ack_crc);
return ACTION_RELEASE;
}
@@ -186,7 +177,6 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
case PAYLOAD_TYPE_ACK: {
uint32_t ack_crc;
memcpy(&ack_crc, pkt->payload, 4);
LOG_INF("onRecvPacket: ACK packet ack_crc=0x%08x seen=%d", ack_crc, _tables->hasSeen(pkt) ? 1 : 0);
if (!_tables->hasSeen(pkt)) {
onAckRecv(pkt, ack_crc);
action = routeRecvPacket(pkt);
@@ -197,8 +187,6 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
case PAYLOAD_TYPE_REQ:
case PAYLOAD_TYPE_RESPONSE:
case PAYLOAD_TYPE_TXT_MSG: {
LOG_INF("onRecvPacket: TXT_MSG/PATH/REQ/RESPONSE type=%d payload_len=%d",
pkt->getPayloadType(), pkt->payload_len);
int i = 0;
uint8_t dest_hash = pkt->payload[i++];
uint8_t src_hash = pkt->payload[i++];
@@ -207,11 +195,8 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
if (i + CIPHER_MAC_SIZE >= (int)pkt->payload_len) {
LOG_WRN("onRecvPacket: incomplete packet (i=%d, payload_len=%d)", i, pkt->payload_len);
} else if (!_tables->hasSeen(pkt)) {
LOG_INF("onRecvPacket: checking dest_hash=0x%02x (self match=%d)",
dest_hash, self_id.isHashMatch(&dest_hash));
if (self_id.isHashMatch(&dest_hash)) {
int num = searchPeersByHash(&src_hash);
LOG_INF("onRecvPacket: found %d peers matching src_hash=0x%02x", num, src_hash);
bool found = false;
for (int j = 0; j < num; j++) {
uint8_t secret[PUB_KEY_SIZE];
@@ -219,7 +204,6 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
uint8_t data[MAX_PACKET_PAYLOAD];
int len = Utils::MACThenDecrypt(secret, data, macAndData, pkt->payload_len - i);
LOG_INF("onRecvPacket: decrypt attempt j=%d, result len=%d", j, len);
if (len > 0) {
if (pkt->getPayloadType() == PAYLOAD_TYPE_PATH) {
int k = 0;
@@ -235,7 +219,6 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
}
}
} else {
LOG_INF("onRecvPacket: calling onPeerDataRecv type=%d len=%d", pkt->getPayloadType(), len);
onPeerDataRecv(pkt, pkt->getPayloadType(), j, secret, data, len);
}
found = true;
@@ -247,12 +230,8 @@ DispatcherAction Mesh::onRecvPacket(Packet *pkt)
} else {
LOG_WRN("onRecvPacket: no peer could decrypt message");
}
} else {
LOG_INF("onRecvPacket: dest_hash doesn't match self");
}
action = routeRecvPacket(pkt);
} else {
LOG_INF("onRecvPacket: packet already seen");
}
break;
}
@@ -564,7 +543,6 @@ Packet *Mesh::createPathReturn(const uint8_t *dest_hash, const uint8_t *secret,
Packet *Mesh::createDatagram(uint8_t type, const Identity &dest, const uint8_t *secret, const uint8_t *data, size_t data_len)
{
LOG_INF("createDatagram: type=%d data_len=%u", type, (unsigned)data_len);
if (type == PAYLOAD_TYPE_TXT_MSG || type == PAYLOAD_TYPE_REQ || type == PAYLOAD_TYPE_RESPONSE) {
if (data_len + CIPHER_MAC_SIZE + CIPHER_BLOCK_SIZE - 1 > MAX_PACKET_PAYLOAD) {
LOG_WRN("createDatagram: data too large");
@@ -586,11 +564,9 @@ Packet *Mesh::createDatagram(uint8_t type, const Identity &dest, const uint8_t *
int len = 0;
len += dest.copyHashTo(&packet->payload[len]);
len += self_id.copyHashTo(&packet->payload[len]);
LOG_INF("createDatagram: dest_hash=0x%02x src_hash=0x%02x", packet->payload[0], packet->payload[1]);
len += Utils::encryptThenMAC(secret, &packet->payload[len], data, data_len);
packet->payload_len = len;
LOG_INF("createDatagram: created packet payload_len=%d", len);
return packet;
}