From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001 From: cj-vana Date: Sun, 17 May 2026 12:06:00 -0600 Subject: [PATCH 14/14] Stabilize firmware bot response tokens --- examples/companion_radio/FirmwareBot.cpp | 52 ++++++++++++------ examples/companion_radio/FirmwareBot.h | 1 + examples/companion_radio/MyMesh.cpp | 67 +++++++++++++++++++++--- examples/companion_radio/MyMesh.h | 1 + 4 files changed, 96 insertions(+), 25 deletions(-) diff --git a/examples/companion_radio/FirmwareBot.cpp b/examples/companion_radio/FirmwareBot.cpp index afd44d41..21312c55 100644 --- a/examples/companion_radio/FirmwareBot.cpp +++ b/examples/companion_radio/FirmwareBot.cpp @@ -366,8 +366,17 @@ BotWriteResult writeAckResponse(const BotMessage& message, const BotCommand& com } BotFingerprint fingerprintFor(const BotMessage& message) { + return fingerprintFor(message, NULL, 0); +} + +BotFingerprint fingerprintFor(const BotMessage& message, const uint8_t* channel_id, size_t channel_id_len) { uint64_t hash = 1469598103934665603ULL; - hash = fnv1aUpdateChannel(hash, message); + if (message.channel_kind == BOT_CHANNEL_DM || !channel_id || channel_id_len == 0) { + hash = fnv1aUpdateChannel(hash, message); + } else { + hash = fnv1aUpdate(hash, 0xC7); + hash = fnv1aUpdateBytes(hash, channel_id, channel_id_len); + } hash = fnv1aUpdateBytes(hash, message.sender_key_prefix, sizeof(message.sender_key_prefix)); hash = fnv1aUpdateTextLower(hash, message.sender_name, boundedStrLen(message.sender_name, sizeof(message.sender_name))); hash = fnv1aUpdateU32(hash, message.sender_timestamp); @@ -381,6 +390,24 @@ BotFingerprint fingerprintFor(const BotMessage& message) { return fingerprint; } +static int hexNibble(char c); + +bool parseRequestTokenPrefix(const char* text, size_t text_len, uint16_t* token, size_t* prefix_len) { + if (token) *token = 0; + if (prefix_len) *prefix_len = 0; + if (!text || text_len < 7) return false; + if (text[0] != '[' || text[5] != ']' || text[6] != ' ') return false; + uint16_t value = 0; + for (int i = 0; i < 4; i++) { + int n = hexNibble(text[1 + i]); + if (n < 0) return false; + value = (uint16_t)((value << 4) | (uint16_t)n); + } + if (token) *token = value; + if (prefix_len) *prefix_len = 7; + return true; +} + BotFingerprint responseFingerprintFor(const BotMessage& message, const char* response_text, size_t response_text_len) { uint64_t hash = 1469598103934665603ULL; hash = fnv1aUpdateChannel(hash, message); @@ -389,6 +416,13 @@ BotFingerprint responseFingerprintFor(const BotMessage& message, const char* res hash = fnv1aUpdateBytes(hash, message.sender_key_prefix, message.sender_key_prefix_len); } + uint16_t token = 0; + size_t prefix_len = 0; + if (parseRequestTokenPrefix(response_text, response_text_len, &token, &prefix_len)) { + response_text += prefix_len; + response_text_len -= prefix_len; + } + char normalized[BOT_MAX_RESPONSE_LEN + 1]; size_t normalized_len = 0; normalizeText(response_text, response_text_len, normalized, sizeof(normalized), &normalized_len); @@ -423,22 +457,6 @@ static int hexNibble(char c) { return -1; } -bool parseRequestTokenPrefix(const char* text, size_t text_len, uint16_t* token, size_t* prefix_len) { - if (token) *token = 0; - if (prefix_len) *prefix_len = 0; - if (!text || text_len < 7) return false; // "[XXXX] " = 7 chars minimum - if (text[0] != '[' || text[5] != ']' || text[6] != ' ') return false; - uint16_t value = 0; - for (int i = 0; i < 4; i++) { - int n = hexNibble(text[1 + i]); - if (n < 0) return false; - value = (uint16_t)((value << 4) | (uint16_t)n); - } - if (token) *token = value; - if (prefix_len) *prefix_len = 7; - return true; -} - BotWriteResult prependRequestToken(BotFingerprint request_fingerprint, char* text, size_t text_len, size_t buf_len, size_t* new_len) { if (new_len) *new_len = text_len; diff --git a/examples/companion_radio/FirmwareBot.h b/examples/companion_radio/FirmwareBot.h index 708432a2..f1726712 100644 --- a/examples/companion_radio/FirmwareBot.h +++ b/examples/companion_radio/FirmwareBot.h @@ -17,6 +17,7 @@ BotWriteResult writeResponseForChannel(BotChannelKind channel_kind, bool allow_p BotWriteResult writeAckResponse(const BotMessage& message, const BotCommand& command, char* output, size_t output_len, size_t* written); BotFingerprint fingerprintFor(const BotMessage& message); +BotFingerprint fingerprintFor(const BotMessage& message, const uint8_t* channel_id, size_t channel_id_len); BotFingerprint responseFingerprintFor(const BotMessage& message, const char* response_text, size_t response_text_len); uint16_t requestToken(BotFingerprint request_fingerprint); void formatRequestToken(uint16_t token, char out[5]); diff --git a/examples/companion_radio/MyMesh.cpp b/examples/companion_radio/MyMesh.cpp index 9121d42c..1a7ddb7a 100644 --- a/examples/companion_radio/MyMesh.cpp +++ b/examples/companion_radio/MyMesh.cpp @@ -121,6 +121,16 @@ #define LAZY_CONTACTS_WRITE_DELAY 5000 #if CMESH_BOT_ENABLED +#ifndef CMESH_BOT_DEBUG +#define CMESH_BOT_DEBUG 0 +#endif +#if CMESH_BOT_DEBUG +#define BOT_DEBUG_PRINTF(...) Serial.printf(__VA_ARGS__) +#define BOT_DEBUG_PRINTLN(value) Serial.println(value) +#else +#define BOT_DEBUG_PRINTF(...) +#define BOT_DEBUG_PRINTLN(value) +#endif #endif #define PUBLIC_GROUP_PSK "izOH6cXN6mrJ5e26oRXNcg==" @@ -1055,6 +1065,7 @@ bool MyMesh::handleBotCLI(const char *args) { void MyMesh::observeBotDirectMessage(const ContactInfo &from, uint32_t sender_timestamp, const uint8_t *sender_prefix, size_t sender_prefix_len, const char *text, const mesh::Packet *packet) { + BOT_DEBUG_PRINTF("CBOT-DBG: DM rx from=%s text=%.40s enabled=%d\r\n", from.name, text, bot_prefs.enabled); BotMessage message; memset(&message, 0, sizeof(message)); message.channel_kind = BotPolicy::classifyChannel(NULL, 0, true, bot_prefs); @@ -1090,6 +1101,7 @@ void MyMesh::observeBotDirectMessage(const ContactInfo &from, uint32_t sender_ti void MyMesh::observeBotChannelMessage(uint8_t channel_idx, const char *channel_name, const char *text, uint32_t sender_timestamp, const mesh::Packet *packet) { + BOT_DEBUG_PRINTF("CBOT-DBG: CH rx ch=%s text=%.40s enabled=%d\r\n", channel_name ? channel_name : "?", text, bot_prefs.enabled); BotMessage message; memset(&message, 0, sizeof(message)); size_t channel_len = botBoundedStrLen(channel_name, BOT_MAX_CHANNEL_NAME_LEN); @@ -1429,7 +1441,7 @@ bool MyMesh::dispatchBotTraceDirectLink(const BotMessage &message, const Contact return true; } - BotFingerprint request_fingerprint = FirmwareBot::fingerprintFor(message); + BotFingerprint request_fingerprint = botRequestFingerprintFor(message, channel_idx); BotFingerprint response_fingerprint = FirmwareBot::responseFingerprintFor(message, final_response, final_response_len); BotFingerprint fingerprint; @@ -1503,7 +1515,7 @@ bool MyMesh::handleBotTraceCommand(const BotMessage &message, const ContactInfo } if (!have_path || !botTracePathShapeValid(path_len, flags)) return false; - BotFingerprint request_fingerprint = FirmwareBot::fingerprintFor(message); + BotFingerprint request_fingerprint = botRequestFingerprintFor(message, channel_idx); char response[BOT_MAX_RESPONSE_LEN + 1]; size_t response_len = botFormatTraceSent(response, sizeof(response), (uint8_t)(path_len / hash_size)); char final_response[BOT_MAX_RESPONSE_LEN + 1]; @@ -1737,6 +1749,16 @@ bool MyMesh::observeKnownBotResponse(const BotMessage &message, bool authoritati return false; } +BotFingerprint MyMesh::botRequestFingerprintFor(const BotMessage &message, uint8_t channel_idx) { + if (message.channel_kind != BOT_CHANNEL_DM && channel_idx != 0xFF) { + ChannelDetails channel; + if (getChannel(channel_idx, channel)) { + return FirmwareBot::fingerprintFor(message, channel.channel.hash, sizeof(channel.channel.hash)); + } + } + return FirmwareBot::fingerprintFor(message); +} + bool MyMesh::observeBotGroupResponse(const BotMessage &message) { if (!BotPolicy::isPrefixlessCommandAllowed(message.channel_kind)) return false; @@ -1749,6 +1771,9 @@ bool MyMesh::observeBotGroupResponse(const BotMessage &message) { if (FirmwareBot::parseRequestTokenPrefix(message.text, message.text_len, &token, &token_prefix_len)) { if (ResponseCoordinator::suppressByRequestToken(bot_coordinator_pending, BOT_COORDINATOR_PENDING_SLOTS, token)) { token_suppressed = true; + BOT_DEBUG_PRINTF("CBOT-DBG: token suppress %04x\r\n", (unsigned)token); + } else { + BOT_DEBUG_PRINTF("CBOT-DBG: token miss %04x\r\n", (unsigned)token); } } @@ -1763,9 +1788,12 @@ bool MyMesh::observeBotGroupResponse(const BotMessage &message) { } void MyMesh::recordBotObservation(const BotMessage &message, const ContactInfo *direct_recipient, uint8_t channel_idx) { + BOT_DEBUG_PRINTF("CBOT-DBG: record kind=%d direct=%d enabled=%d\r\n", (int)message.channel_kind, direct_recipient != NULL, bot_prefs.enabled); bot_stats.observed_messages++; BotPolicyDecision decision = BotPolicy::decide(message.channel_kind); + BOT_DEBUG_PRINTF("CBOT-DBG: policy decision=%d\r\n", (int)decision); if (decision == BOT_POLICY_IGNORE) { + BOT_DEBUG_PRINTLN("CBOT-DBG: IGNORE -> drop"); bot_stats.ignored_messages++; return; } @@ -1776,24 +1804,28 @@ void MyMesh::recordBotObservation(const BotMessage &message, const ContactInfo * } if (!bot_prefs.enabled) { + BOT_DEBUG_PRINTLN("CBOT-DBG: bot disabled -> drop"); bot_stats.ignored_messages++; return; } - if (observeKnownBotResponse(message, direct_recipient != NULL)) return; - if (!direct_recipient && observeBotGroupResponse(message)) return; + if (observeKnownBotResponse(message, direct_recipient != NULL)) { BOT_DEBUG_PRINTLN("CBOT-DBG: known-bot suppress"); return; } + if (!direct_recipient && observeBotGroupResponse(message)) { BOT_DEBUG_PRINTLN("CBOT-DBG: group-response suppress"); return; } sendQueuedBotResponses(); BotCommand command; if (!FirmwareBot::parseCommand(message.text, message.text_len, &command, BotPolicy::isPrefixlessCommandAllowed(message.channel_kind))) { + BOT_DEBUG_PRINTF("CBOT-DBG: parseCommand FAILED text=%.40s prefixless=%d\r\n", message.text, BotPolicy::isPrefixlessCommandAllowed(message.channel_kind)); if (message.text_len > 0 && (message.text[0] == '!' || message.text[0] == '/')) bot_stats.parse_errors++; return; } + BOT_DEBUG_PRINTF("CBOT-DBG: parsed cmd.id=%d name=%s args=%.30s\r\n", (int)command.id, command.name, command.args); if ((command.id != BOT_COMMAND_UNKNOWN && command.id != BOT_COMMAND_UNSUPPORTED && !BotPrefsCodec::commandEnabled(bot_prefs, command.id)) || FirmwareBot::isCommandOnCooldown(bot_command_cooldowns, BOT_COMMAND_COOLDOWN_SLOTS, command.id, _ms->getMillis())) { + BOT_DEBUG_PRINTLN("CBOT-DBG: cmd disabled or on cooldown -> drop"); bot_stats.ignored_messages++; return; } @@ -1868,7 +1900,7 @@ void MyMesh::recordBotObservation(const BotMessage &message, const ContactInfo * return; } - BotFingerprint request_fingerprint = FirmwareBot::fingerprintFor(message); + BotFingerprint request_fingerprint = botRequestFingerprintFor(message, channel_idx); BotFingerprint response_fingerprint = FirmwareBot::responseFingerprintFor(message, final_response, final_response_len); BotFingerprint fingerprint; uint32_t due_at_millis = 0; @@ -1884,7 +1916,11 @@ void MyMesh::recordBotObservation(const BotMessage &message, const ContactInfo * queue_depth, bot_prefs.normal_delay_ms, bot_prefs.normal_jitter_ms, bot_prefs.hop_step_ms, &fingerprint, &due_at_millis); + BOT_DEBUG_PRINTF("CBOT-DBG: schedule result=%d due=%lu now=%lu reqfp=%08lx%08lx\r\n", + (int)schedule, (unsigned long)due_at_millis, (unsigned long)_ms->getMillis(), + (unsigned long)(request_fingerprint.value >> 32), (unsigned long)(request_fingerprint.value & 0xFFFFFFFFul)); if (schedule == BOT_COORDINATOR_NO_SPACE || schedule == BOT_COORDINATOR_NOT_NORMAL) { + BOT_DEBUG_PRINTLN("CBOT-DBG: schedule FAILED -> drop"); bot_stats.send_failures++; return; } @@ -1894,8 +1930,11 @@ void MyMesh::recordBotObservation(const BotMessage &message, const ContactInfo * FirmwareBot::recordCommandCooldown(bot_command_cooldowns, BOT_COMMAND_COOLDOWN_SLOTS, command.id, _ms->getMillis(), BOT_COMMAND_COOLDOWN_MILLIS); if (!enqueueBotResponse(message, direct_recipient, channel_idx, final_response, final_response_len, fingerprint, response_fingerprint)) { + BOT_DEBUG_PRINTLN("CBOT-DBG: enqueueBotResponse FAILED -> drop"); ResponseCoordinator::cancel(bot_coordinator_pending, BOT_COORDINATOR_PENDING_SLOTS, fingerprint); bot_stats.send_failures++; + } else { + BOT_DEBUG_PRINTF("CBOT-DBG: queued response, text=%.40s\r\n", final_response); } } @@ -1904,6 +1943,8 @@ void MyMesh::sendQueuedBotResponses() { while (true) { BotCoordinatorReady ready = ResponseCoordinator::poll(bot_coordinator_pending, BOT_COORDINATOR_PENDING_SLOTS, now); if (ready.result == BOT_COORDINATOR_READY_NONE) return; + BOT_DEBUG_PRINTF("CBOT-DBG: poll result=%d reqfp=%08lx\r\n", (int)ready.result, + (unsigned long)(ready.request_fingerprint.value & 0xFFFFFFFFul)); if (ready.result == BOT_COORDINATOR_READY_SUPPRESSED) { bot_stats.suppressed_responses++; @@ -1945,12 +1986,14 @@ void MyMesh::sendQueuedBotResponses() { bool success = false; if (pending->direct) { ContactInfo *recipient = lookupContactByPubKey(pending->recipient_pub_key, PUB_KEY_SIZE); + BOT_DEBUG_PRINTF("CBOT-DBG: send DM lookup=%s text=%.40s\r\n", recipient ? "FOUND" : "NULL", pending->text); if (recipient) { uint32_t expected_ack = 0; uint32_t est_timeout = 0; uint32_t timestamp = getRTCClock()->getCurrentTimeUnique(); int result = sendMessage(*recipient, timestamp, 0, pending->text, expected_ack, est_timeout); success = result != MSG_SEND_FAILED; + BOT_DEBUG_PRINTF("CBOT-DBG: sendMessage result=%d success=%d\r\n", result, success); if (success && expected_ack) { expected_ack_table[next_ack_idx].msg_sent = _ms->getMillis(); expected_ack_table[next_ack_idx].ack = expected_ack; @@ -1960,9 +2003,11 @@ void MyMesh::sendQueuedBotResponses() { } } else if (pending->channel_idx != 0xFF) { ChannelDetails channel; + bool have_ch = getChannel(pending->channel_idx, channel); uint32_t timestamp = getRTCClock()->getCurrentTimeUnique(); - success = getChannel(pending->channel_idx, channel) && - sendGroupMessage(timestamp, channel.channel, _prefs.node_name, pending->text, pending->text_len); + success = have_ch && sendGroupMessage(timestamp, channel.channel, _prefs.node_name, pending->text, pending->text_len); + BOT_DEBUG_PRINTF("CBOT-DBG: send CH idx=%u have=%d success=%d text=%.40s\r\n", + (unsigned)pending->channel_idx, have_ch, success, pending->text); } if (success) { @@ -1970,6 +2015,7 @@ void MyMesh::sendQueuedBotResponses() { ResponseCoordinator::recordRecent(bot_coordinator_recent, BOT_COORDINATOR_RECENT_SLOTS, pending->response_fingerprint, now); } else { + BOT_DEBUG_PRINTLN("CBOT-DBG: send FAILED -> bot stays silent"); bot_stats.send_failures++; } pending->active = false; @@ -2521,9 +2567,14 @@ void MyMesh::begin(bool has_display) { MESH_DEBUG_PRINTLN("RX Boosted Gain Mode: %s", radio_driver.getRxBoostedGainMode() ? "Enabled" : "Disabled"); #if CMESH_BOT_ENABLED - if (!_store->loadBotPrefs(bot_prefs)) bot_prefs.prefs_load_failures++; + bool loaded = _store->loadBotPrefs(bot_prefs); + if (!loaded) bot_prefs.prefs_load_failures++; BotPrefsCodec::validate(bot_prefs); applyBotPrefs(); + BOT_DEBUG_PRINTF("CBOT-DBG: boot: loaded=%d enabled=%d bot_ch=%s testing_ch=%s mask=0x%08lx delay=%u jitter=%u hop_step=%u\r\n", + loaded, bot_prefs.enabled, bot_prefs.bot_channel, bot_prefs.testing_channel, + (unsigned long)bot_prefs.command_mask, bot_prefs.normal_delay_ms, bot_prefs.normal_jitter_ms, + bot_prefs.hop_step_ms); #endif } diff --git a/examples/companion_radio/MyMesh.h b/examples/companion_radio/MyMesh.h index 46c3ff3c..cfd402df 100644 --- a/examples/companion_radio/MyMesh.h +++ b/examples/companion_radio/MyMesh.h @@ -215,6 +215,7 @@ private: void recordBotObservation(const BotMessage &message, const ContactInfo *direct_recipient, uint8_t channel_idx); bool observeKnownBotResponse(const BotMessage &message, bool authoritative_sender); bool observeBotGroupResponse(const BotMessage &message); + BotFingerprint botRequestFingerprintFor(const BotMessage &message, uint8_t channel_idx); void buildBotCommandContext(BotCommandContext &context, BotCommandId command_id); bool enqueueBotResponse(const BotMessage &message, const ContactInfo *direct_recipient, uint8_t channel_idx, const char *text, size_t text_len, BotFingerprint request_fingerprint,