diff --git a/OpticalChannelTester/App.cpp b/OpticalChannelTester/App.cpp index 9efc5cd..a7a9be1 100644 --- a/OpticalChannelTester/App.cpp +++ b/OpticalChannelTester/App.cpp @@ -1,31 +1,52 @@ #include "App.h" #include "Config.h" +#include "Log.h" #include #include #include #include +namespace { +const char *appStateName(AppState state) { + static const char *names[] = {"IDLE", "MENU", "SOLO_MEASURE", "MASTER_DISCOVER", + "MASTER_WAIT_READY", "MASTER_WAIT_RESULT", "SLAVE_READY", "SLAVE_WAIT_START", + "SLAVE_MEASURE", "SLAVE_WAIT_ACK", "FINISHED"}; + const uint8_t index = static_cast(state); + return index < sizeof(names) / sizeof(names[0]) ? names[index] : "UNKNOWN"; +} + +const char *buttonEventName(ButtonEvent event) { + static const char *names[] = {"NONE", "SHORT", "LONG", "REPEAT"}; + const uint8_t index = static_cast(event); + return index < sizeof(names) / sizeof(names[0]) ? names[index] : "UNKNOWN"; +} +} + App::App() : startButton_(GPIO_BUTTON_START), modeButton_(GPIO_BUTTON_MODE), measurement_(receiver_) {} void App::begin() { Serial.begin(SERIAL_BAUD); + Log::printf("BOOT", "firmware start, Serial=%lu baud", SERIAL_BAUD); startButton_.begin(); modeButton_.begin(); pwm_.begin(); bootCheckStartedMs_ = millis(); bootResetCandidate_ = startButton_.pressed() && modeButton_.pressed(); + Log::printf("BOOT", "buttons initialized, factory-reset candidate=%s", bootResetCandidate_ ? "YES" : "NO"); if (!bootResetCandidate_) finishInitialization(false); } void App::finishInitialization(bool factoryReset) { if (initialized_) return; + Log::printf("BOOT", "initialization continues, factory-reset=%s", factoryReset ? "YES" : "NO"); if (factoryReset) { - store_.defaults(settings_); store_.save(settings_); Serial.println("FACTORY DEFAULTS RESTORED"); + store_.defaults(settings_); store_.save(settings_); Log::event("BOOT", "FACTORY DEFAULTS RESTORED"); } else if (!store_.load(settings_)) { - store_.save(settings_); Serial.println("NVS invalid/missing: defaults loaded"); + store_.save(settings_); Log::event("BOOT", "NVS invalid/missing: defaults loaded"); } params_ = store_.params(settings_); - if (!display_.begin()) Serial.println("OLED unavailable; continuing through Serial"); + if (!display_.begin()) Log::event("BOOT", "OLED unavailable; Serial UI remains fully operational"); initialized_ = true; - if (!receiver_.begin()) { Serial.println("FATAL: capture peripheral init failed"); finish(false, FailReason::UNSUPPORTED); return; } + if (!receiver_.begin()) { Log::event("BOOT", "FATAL: capture peripheral init failed"); finish(false, FailReason::UNSUPPORTED); return; } + Log::printf("BOOT", "capture initialized: %s", receiver_.highRateBackend() ? "RMT DMA" : "RMT ping-pong"); printConfiguration(); showIdle(); } @@ -33,6 +54,10 @@ void App::update() { const uint32_t now = millis(); const ButtonEvent startEvent = startButton_.update(now); const ButtonEvent modeEvent = modeButton_.update(now); + if (startEvent != ButtonEvent::NONE) + Log::printf("INPUT", "START %s state=%s", buttonEventName(startEvent), appStateName(state_)); + if (modeEvent != ButtonEvent::NONE) + Log::printf("INPUT", "MODE %s state=%s", buttonEventName(modeEvent), appStateName(state_)); if (!initialized_) { if (!startButton_.pressed() || !modeButton_.pressed()) finishInitialization(false); else if (now - bootCheckStartedMs_ >= FACTORY_RESET_HOLD_MS) finishInitialization(true); @@ -40,20 +65,26 @@ void App::update() { } if (state_ != AppState::IDLE && state_ != AppState::MENU && state_ != AppState::FINISHED && startEvent == ButtonEvent::LONG) { abortTest(); return; } + if (state_ != AppState::IDLE && state_ != AppState::MENU && state_ != AppState::FINISHED && + modeEvent != ButtonEvent::NONE) Log::event("ACTION", "MODE ignored while test is active"); if (state_ == AppState::IDLE || state_ == AppState::FINISHED) { if (modeEvent == ButtonEvent::SHORT) { - settings_.role = (settings_.role + 1U) % 3U; store_.save(settings_); params_ = store_.params(settings_); showIdle(); - Serial.printf("MODE: %s\n", roleName(static_cast(settings_.role))); + settings_.role = (settings_.role + 1U) % 3U; const bool saved = store_.save(settings_); + params_ = store_.params(settings_); showIdle(); + Log::printf("ACTION", "role changed to %s, NVS=%s", roleName(static_cast(settings_.role)), saved ? "OK" : "FAILED"); } else if (modeEvent == ButtonEvent::LONG) { - state_ = AppState::MENU; menuItem_ = 0; showMenu(); - } else if (startEvent == ButtonEvent::SHORT) startTest(); + state_ = AppState::MENU; menuItem_ = 0; Log::event("ACTION", "settings menu entered"); showMenu(); + } else if (startEvent == ButtonEvent::SHORT) { Log::event("ACTION", "test start requested"); startTest(); } return; } if (state_ == AppState::MENU) { - if (modeEvent == ButtonEvent::SHORT) { menuItem_ = (menuItem_ + 1U) % 7U; showMenu(); } + if (modeEvent == ButtonEvent::SHORT) { + menuItem_ = (menuItem_ + 1U) % 7U; Log::printf("ACTION", "menu item selected index=%u", menuItem_); showMenu(); + } else if (modeEvent == ButtonEvent::LONG) { - sanitizeRange(); store_.save(settings_); params_ = store_.params(settings_); + sanitizeRange(); const bool saved = store_.save(settings_); params_ = store_.params(settings_); + Log::printf("ACTION", "settings menu saved and closed, NVS=%s", saved ? "OK" : "FAILED"); state_ = AppState::IDLE; printConfiguration(); showIdle(); } else if (startEvent == ButtonEvent::SHORT) changeMenu(+1); else if (startEvent == ButtonEvent::LONG || startEvent == ButtonEvent::REPEAT) changeMenu(-1); @@ -97,7 +128,9 @@ void App::changeMenu(int d) { case 5: value = &settings_.repeatIndex; count = countOf(REPEAT_OPTIONS); break; default: value = &settings_.dutyIndex; count = countOf(DUTY_OPTIONS_PCT); break; } - *value = static_cast((*value + count + d) % count); sanitizeRange(); params_ = store_.params(settings_); showMenu(); + *value = static_cast((*value + count + d) % count); + Log::printf("ACTION", "menu item=%u changed direction=%+d new-index=%u", menuItem_, d, *value); + sanitizeRange(); params_ = store_.params(settings_); showMenu(); } void App::showMenu() { @@ -119,6 +152,11 @@ void App::startTest() { params_ = store_.params(settings_); stageCount_ = frequencyPointCount(params_.startHz, params_.endHz, params_.stepHz); stageIndex_ = 0; pendingReason_ = FailReason::NONE; if (!stageCount_) { finish(false, FailReason::UNSUPPORTED); return; } + Log::printf("TEST", "starting role=%s stages=%lu", roleName(static_cast(settings_.role)), stageCount_); + if (SERIAL_MINIMAL_LOG) + Log::printf("CONFIG", "mode=%s range=%lu..%luHz step=%luHz accuracy=%.2f%% time=%lums repeats=%u duty=%u%% stages=%lu", + roleName(static_cast(settings_.role)), params_.startHz, params_.endHz, params_.stepHz, + params_.accuracyPct, params_.testTimeMs, params_.repeats, params_.dutyPct, stageCount_); printConfiguration(); const Role role = static_cast(settings_.role); if (role == Role::SOLO) { @@ -126,7 +164,7 @@ void App::startTest() { state_ = AppState::SOLO_MEASURE; } else if (!radio_.begin()) finish(false, FailReason::LINK_LOST); else if (role == Role::MASTER) startMasterDiscovery(); - else { state_ = AppState::SLAVE_READY; display_.show("SLAVE READY", "WAIT MASTER"); Serial.println("SLAVE READY"); } + else { state_ = AppState::SLAVE_READY; Log::event("TEST", "Slave armed and waiting for Master"); display_.show("SLAVE READY", "WAIT MASTER"); } } bool App::prepareStage() { @@ -134,11 +172,20 @@ bool App::prepareStage() { const uint32_t maxHz = TARGET_IS_C3 ? C3_STRICT_MAX_HZ : (receiver_.highRateBackend() ? S3_STRICT_MAX_HZ : C3_STRICT_MAX_HZ); if (requestedHz_ > maxHz) { finish(false, FailReason::UNSUPPORTED); return false; } - if (!pwm_.start(requestedHz_, params_.dutyPct, actual_)) { finish(false, FailReason::RESOLUTION); return false; } + Log::printf("PWM", "starting GPIO=%u requested=%luHz duty=%u%%", GPIO_PWM, requestedHz_, params_.dutyPct); + if (!pwm_.start(requestedHz_, params_.dutyPct, actual_)) { + Log::printf("PWM", "START FAILED GPIO=%u requested=%luHz; LEDC attach/write/read failed", + GPIO_PWM, requestedHz_); + finish(false, FailReason::RESOLUTION); return false; + } const FailReason resolution = validateResolution(actual_.actualHz, actual_.actualDutyPct, params_.accuracyPct, receiver_.tickHz(), actual_.bits); - if (resolution != FailReason::NONE) { finish(false, resolution); return false; } - Serial.printf("STAGE %lu/%lu requested=%luHz actual=%luHz duty=%.2f%% bits=%u\n", + if (resolution != FailReason::NONE) { + Log::printf("PWM", "resolution rejected: actual=%luHz duty=%.3f%% bits=%u RXclock=%luHz tolerance=%.3f%%", + actual_.actualHz, actual_.actualDutyPct, actual_.bits, receiver_.tickHz(), params_.accuracyPct); + finish(false, resolution); return false; + } + Log::printf("PWM", "stage=%lu/%lu requested=%luHz actual=%luHz duty=%.2f%% bits=%u STARTED", stageIndex_ + 1, stageCount_, requestedHz_, actual_.actualHz, actual_.actualDutyPct, actual_.bits); char f[12], one[24], two[24]; Display::formatFrequency(actual_.actualHz, f, sizeof(f)); snprintf(one, sizeof(one), "F %s D %.1f%%", f, actual_.actualDutyPct); @@ -150,10 +197,16 @@ bool App::prepareStage() { } bool App::startLocalMeasurement(float hz, float duty) { - return measurement_.start(hz, duty, params_.accuracyPct, params_.testTimeMs, params_.repeats, PWM_SETTLE_CYCLES); + Log::printf("MEASURE", "arming expected=%.3fHz duty=%.3f%% tolerance=%.3f%% settle=%u cycles window=%lums x%u; per-pulse logging suspended", + hz, duty, params_.accuracyPct, PWM_SETTLE_CYCLES, params_.testTimeMs, params_.repeats); + const bool ok = measurement_.start(hz, duty, params_.accuracyPct, params_.testTimeMs, params_.repeats, PWM_SETTLE_CYCLES); + Log::printf("MEASURE", "receiver start %s, RMT chunk=%u symbols", ok ? "OK" : "FAILED", + receiver_.receiveChunkSymbols()); + return ok; } void App::stagePassed() { + Log::printf("TEST", "stage %lu/%lu PASS; PWM stopping", stageIndex_ + 1, stageCount_); pwm_.stop(); if (++stageIndex_ >= stageCount_) { finish(true, FailReason::NONE); return; } if (static_cast(settings_.role) == Role::SOLO) { if (prepareStage()) state_ = AppState::SOLO_MEASURE; } @@ -168,7 +221,8 @@ void App::startMasterDiscovery() { session_ = esp_random(); if (!session_) session_ = 1; sequence_ = 1; havePeer_ = false; radio_.flush(); pendingPacket_ = makePacket(MessageType::DISCOVER); radio_.sendBroadcast(pendingPacket_); lastSendMs_ = millis(); deadlineMs_ = millis() + LINK_DISCOVERY_TIMEOUT_MS; retries_ = 0; - state_ = AppState::MASTER_DISCOVER; display_.show("MASTER SEARCH", "WAIT SLAVE"); Serial.println("ESP-NOW DISCOVER"); + state_ = AppState::MASTER_DISCOVER; Log::printf("ESP-NOW", "discovery started session=%08lX", session_); + display_.show("MASTER SEARCH", "WAIT SLAVE"); } ProtocolPacket App::makePacket(MessageType type) const { @@ -182,7 +236,9 @@ ProtocolPacket App::makePacket(MessageType type) const { } void App::sendCurrent(MessageType type) { - ++sequence_; pendingPacket_ = makePacket(type); radio_.sendTo(peer_, pendingPacket_); lastSendMs_ = millis(); + ++sequence_; pendingPacket_ = makePacket(type); + const bool ok = radio_.sendTo(peer_, pendingPacket_); lastSendMs_ = millis(); + if (!ok) Log::printf("ESP-NOW", "sendCurrent %s FAILED", messageName(type)); } bool App::packetForCurrent(const ProtocolPacket &p) const { @@ -194,7 +250,8 @@ void App::handleRadio() { while (radio_.receive(r)) { const MessageType type = static_cast(r.packet.type); if (state_ != AppState::SLAVE_MEASURE) - Serial.printf("ESP-NOW RX type=%u session=%08lX stage=%u seq=%u\n", r.packet.type, r.packet.session, r.packet.stage, r.packet.sequence); + Log::printf("ESP-NOW", "RX %s session=%08lX stage=%u seq=%u", + messageName(type), r.packet.session, r.packet.stage, r.packet.sequence); if (state_ == AppState::SLAVE_READY && type == MessageType::DISCOVER) { memcpy(peer_, r.mac, 6); havePeer_ = true; session_ = r.packet.session; stageIndex_ = 0; sequence_ = r.packet.sequence; ProtocolPacket ack = makePacket(MessageType::DISCOVER_ACK); ack.sequence = r.packet.sequence; radio_.sendTo(peer_, ack); @@ -203,7 +260,7 @@ void App::handleRadio() { if (state_ == AppState::MASTER_DISCOVER && type == MessageType::DISCOVER_ACK && r.packet.session == session_) { memcpy(peer_, r.mac, 6); havePeer_ = true; requestedHz_ = frequencyAt(params_.startHz, params_.endHz, params_.stepHz, stageIndex_); sendCurrent(MessageType::PREPARE); state_ = AppState::MASTER_WAIT_READY; retries_ = 0; deadlineMs_ = millis() + LINK_REPLY_TIMEOUT_MS; - char mac[20]; Radio::macText(peer_, mac, sizeof(mac)); Serial.printf("SLAVE SELECTED %s\n", mac); continue; + char mac[20]; Radio::macText(peer_, mac, sizeof(mac)); Log::printf("ESP-NOW", "Slave selected %s", mac); continue; } if (state_ == AppState::SLAVE_WAIT_START && type == MessageType::DISCOVER && r.packet.session == session_ && !memcmp(peer_, r.mac, 6)) { @@ -244,11 +301,15 @@ void App::updateMaster() { const uint32_t now = millis(); if (state_ == AppState::MASTER_DISCOVER) { if (now >= deadlineMs_) { finish(false, FailReason::LINK_LOST); return; } - if (now - lastSendMs_ >= LINK_RETRY_INTERVAL_MS) { radio_.sendBroadcast(pendingPacket_); lastSendMs_ = now; } + if (now - lastSendMs_ >= LINK_RETRY_INTERVAL_MS) { + Log::printf("ESP-NOW", "DISCOVER retry=%u", retries_ + 1); radio_.sendBroadcast(pendingPacket_); + lastSendMs_ = now; ++retries_; + } return; } if (now < deadlineMs_) return; if (retries_ >= LINK_PACKET_RETRIES) { finish(false, FailReason::LINK_LOST); return; } + Log::printf("ESP-NOW", "%s retry=%u", messageName(static_cast(pendingPacket_.type)), retries_ + 1); radio_.sendTo(peer_, pendingPacket_); ++retries_; deadlineMs_ = now + (state_ == AppState::MASTER_WAIT_RESULT ? params_.testTimeMs * params_.repeats + LINK_REPLY_TIMEOUT_MS : LINK_REPLY_TIMEOUT_MS); @@ -263,28 +324,34 @@ void App::updateSlave() { pendingPacket_.reason = static_cast(measurement_.reason()); pendingPacket_.periods = measurement_.stats().periods; pendingPacket_.minPeriodTicks = measurement_.stats().minPeriod; pendingPacket_.maxPeriodTicks = measurement_.stats().maxPeriod; pendingPacket_.sequence = ++sequence_; radio_.sendTo(peer_, pendingPacket_); + Log::printf("TEST", "Slave result prepared: %s reason=%s periods=%lu", + pendingPacket_.passed ? "PASS" : "FAIL", failName(static_cast(pendingPacket_.reason)), pendingPacket_.periods); state_ = AppState::SLAVE_WAIT_ACK; retries_ = 0; deadlineMs_ = millis() + LINK_REPLY_TIMEOUT_MS; } else if (state_ == AppState::SLAVE_WAIT_ACK && millis() >= deadlineMs_) { if (retries_++ >= LINK_PACKET_RETRIES) finish(false, FailReason::LINK_LOST); - else { radio_.sendTo(peer_, pendingPacket_); deadlineMs_ = millis() + LINK_REPLY_TIMEOUT_MS; } + else { Log::printf("ESP-NOW", "RESULT retry=%u", retries_); radio_.sendTo(peer_, pendingPacket_); deadlineMs_ = millis() + LINK_REPLY_TIMEOUT_MS; } } } void App::sendAbort() { if (havePeer_) sendCurrent(MessageType::ABORT); } -void App::abortTest() { sendAbort(); measurement_.abort(); finish(false, FailReason::ABORTED); } +void App::abortTest() { + Log::event("ACTION", "abort requested: sending ABORT, stopping receiver and PWM"); + sendAbort(); measurement_.abort(); finish(false, FailReason::ABORTED); +} void App::finish(bool pass, FailReason reason) { + Log::printf("TEST", "finishing result=%s reason=%s", pass ? "PASS" : "FAIL", failName(reason)); pwm_.stop(); receiver_.stop(); if (state_ != AppState::IDLE && state_ != AppState::MENU) radio_.end(); state_ = AppState::FINISHED; pendingReason_ = reason; char one[24]; if (pass) { snprintf(one, sizeof(one), "PASS %luHz-%lu", params_.startHz, params_.endHz); display_.show(one, "START=REPEAT"); } else { snprintf(one, sizeof(one), "FAIL AT %lu", requestedHz_); display_.show(one, failName(reason)); } - Serial.printf("TEST %s: %s\n", pass ? "PASS" : "FAIL", failName(reason)); } void App::printConfiguration() { + if (SERIAL_MINIMAL_LOG) return; const char *board = TARGET_IS_C3 ? "ESP32-C3" : "ESP32-S3"; uint8_t mac[6] = {}; esp_read_mac(mac, ESP_MAC_WIFI_STA); Serial.printf("\nOptical Channel Tester | %s | mode=%s\n", board, roleName(static_cast(settings_.role))); @@ -300,23 +367,17 @@ void App::printConfiguration() { } uint64_t App::actualNominalTotalUs() { - uint64_t total = 0; - const uint32_t count = frequencyPointCount(params_.startHz, params_.endHz, params_.stepHz); - for (uint32_t i = 0; i < count; ++i) { - ActualPwm preview = {}; - const uint32_t requested = frequencyAt(params_.startHz, params_.endHz, params_.stepHz, i); - const uint32_t actualHz = pwm_.preview(requested, params_.dutyPct, preview) ? preview.actualHz : requested; - total += (1000000ULL * PWM_SETTLE_CYCLES + actualHz - 1) / actualHz; - total += static_cast(params_.testTimeMs) * 1000ULL * params_.repeats; - } - return total; + // ALL is only an estimate. Do not attach/detach LEDC for every frequency: + // large sweeps can perform hundreds of unnecessary driver reconfigurations + // immediately before the real test and leave no observable PWM on failure. + return nominalTotalUs(params_, PWM_SETTLE_CYCLES); } void App::printStageStats(const StageStats &s, uint32_t hz) { if (!s.periods) return; - Serial.printf("STATS %luHz periods=%lu period ticks min/avg/max=%lu/%llu/%lu active=%lu/%llu/%lu\n", - hz, s.periods, s.minPeriod, s.periodSum / s.periods, s.maxPeriod, - s.minActive, s.activeSum / s.periods, s.maxActive); - if (s.reason != FailReason::NONE) Serial.printf("FIRST BAD repeat=%u period=%lu f=%.3f duty=%.3f reason=%s\n", - s.firstBadRepeat, s.firstBadPeriod, s.badFrequency, s.badDuty, failName(s.reason)); + const float measuredHz = static_cast(receiver_.tickHz()) * s.periods / s.periodSum; + const float measuredDuty = 100.0f * s.activeSum / s.periodSum; + Log::printf("RESULT", "%luHz %s periods=%lu measured=%.2fHz duty=%.2f%%%s%s", + hz, s.reason == FailReason::NONE ? "PASS" : "FAIL", s.periods, measuredHz, measuredDuty, + s.reason == FailReason::NONE ? "" : " reason=", s.reason == FailReason::NONE ? "" : failName(s.reason)); } diff --git a/OpticalChannelTester/Config.h b/OpticalChannelTester/Config.h index a2cc8a4..8a465e0 100644 --- a/OpticalChannelTester/Config.h +++ b/OpticalChannelTester/Config.h @@ -26,6 +26,9 @@ constexpr uint8_t GPIO_SCL = 9; constexpr uint8_t OLED_ADDRESS = 0x3C; constexpr uint8_t ESPNOW_WIFI_CHANNEL = 6; constexpr uint32_t SERIAL_BAUD = 115200; +constexpr bool SERIAL_ACTION_LOG = true; +constexpr bool SERIAL_LOG_TIMESTAMPS = true; +constexpr bool SERIAL_MINIMAL_LOG = true; #define BUTTON_ACTIVE_LEVEL LOW #define RX_SIGNAL_INVERTED false @@ -43,11 +46,17 @@ constexpr uint32_t LINK_REPLY_TIMEOUT_MS = 800; constexpr uint8_t LINK_PACKET_RETRIES = 3; constexpr uint32_t LINK_RETRY_INTERVAL_MS = 100; constexpr uint8_t NO_SIGNAL_TIMEOUT_PERIODS = 8; +constexpr uint16_t RMT_MIN_RECEIVE_SYMBOLS = 48; +constexpr uint16_t RMT_MAX_RECEIVE_SYMBOLS = 512; +constexpr uint32_t RMT_TARGET_CHUNK_US = 5000; -constexpr uint32_t C3_STRICT_MAX_HZ = 100000; +constexpr uint32_t C3_STRICT_MAX_HZ = 1000000; constexpr uint32_t S3_STRICT_MAX_HZ = 1000000; -constexpr uint32_t C3_GUARANTEED_HZ = 10000; constexpr uint32_t CAPTURE_RESOLUTION_HZ = 80000000; +// Arduino-ESP32 uses the 40 MHz crystal as the default LEDC clock on C3/S3. +// Keep this explicit so the resolution calculation never asks LEDC for an +// impossible frequency/resolution combination. +constexpr uint32_t LEDC_SOURCE_CLOCK_HZ = 40000000; constexpr uint8_t LEDC_CHANNEL = 0; constexpr uint8_t LEDC_MAX_BITS = 14; diff --git a/OpticalChannelTester/Core.cpp b/OpticalChannelTester/Core.cpp index 009f17d..893039a 100644 --- a/OpticalChannelTester/Core.cpp +++ b/OpticalChannelTester/Core.cpp @@ -63,6 +63,15 @@ bool dutyWithin(float measured, float expected, float tolerance) { return fabsf(measured - expected) <= tolerance + 0.0001f; } +uint8_t choosePwmResolution(uint32_t frequencyHz, uint32_t sourceClockHz, + uint8_t maxBits) { + if (!frequencyHz || !sourceClockHz || !maxBits) return 0; + uint8_t bits = maxBits; + while (bits > 1 && static_cast(frequencyHz) * (1ULL << bits) > sourceClockHz) + --bits; + return bits; +} + FailReason validateResolution(uint32_t frequencyHz, float dutyPct, float accuracyPct, uint32_t captureHz, uint8_t pwmBits) { if (!frequencyHz || !captureHz || !pwmBits) return FailReason::RESOLUTION; @@ -98,4 +107,3 @@ FailReason evaluatePeriod(const PulsePeriod &p, uint32_t tickHz, float expectedH } return reason; } - diff --git a/OpticalChannelTester/Core.h b/OpticalChannelTester/Core.h index 4a2688b..64041cc 100644 --- a/OpticalChannelTester/Core.h +++ b/OpticalChannelTester/Core.h @@ -63,9 +63,10 @@ uint32_t frequencyAt(uint32_t startHz, uint32_t endHz, uint32_t stepHz, uint32_t uint64_t nominalTotalUs(const TestParams &p, uint32_t settleCycles); bool periodWithin(float measuredHz, float expectedHz, float tolerancePct); bool dutyWithin(float measuredPct, float expectedPct, float tolerancePct); +uint8_t choosePwmResolution(uint32_t frequencyHz, uint32_t sourceClockHz, + uint8_t maxBits); FailReason validateResolution(uint32_t frequencyHz, float dutyPct, float accuracyPct, uint32_t captureResolutionHz, uint8_t pwmBits); FailReason evaluatePeriod(const PulsePeriod &period, uint32_t tickHz, float expectedHz, float expectedDuty, float tolerancePct, uint8_t repeat, StageStats &stats); - diff --git a/OpticalChannelTester/Display.cpp b/OpticalChannelTester/Display.cpp index 6cbb409..03b916f 100644 --- a/OpticalChannelTester/Display.cpp +++ b/OpticalChannelTester/Display.cpp @@ -1,5 +1,6 @@ #include "Display.h" #include "Config.h" +#include "Log.h" #include #include @@ -9,6 +10,7 @@ bool Display::begin() { Wire.begin(GPIO_SDA, GPIO_SCL); ok_ = oled_.begin(SSD1306_SWITCHCAPVCC, OLED_ADDRESS); if (ok_) { oled_.setTextColor(SSD1306_WHITE); oled_.setTextSize(1); } + Log::printf("OLED", "initialization %s, I2C address=0x%02X", ok_ ? "OK" : "FAILED", OLED_ADDRESS); return ok_; } @@ -22,9 +24,11 @@ void Display::fit(char *s) { } void Display::show(const char *a, const char *b) { - if (!ok_) return; char one[32], two[32]; snprintf(one, sizeof(one), "%s", a ? a : ""); snprintf(two, sizeof(two), "%s", b ? b : ""); + // Serial is the primary UI mirror and remains available when OLED is absent. + Log::printf("UI", "%s | %s", one, two); + if (!ok_) return; fit(one); fit(two); oled_.clearDisplay(); oled_.setCursor(0, 3); oled_.print(one); oled_.setCursor(0, 19); oled_.print(two); oled_.display(); @@ -41,4 +45,3 @@ void Display::formatDuration(uint64_t us, char *out, size_t n) { if (minutes < 60) snprintf(out, n, "%02llu:%02llu", minutes, (us / 1000000ULL) % 60ULL); else snprintf(out, n, "%llu:%02llu", minutes / 60ULL, minutes % 60ULL); } - diff --git a/OpticalChannelTester/Log.cpp b/OpticalChannelTester/Log.cpp new file mode 100644 index 0000000..4565f2f --- /dev/null +++ b/OpticalChannelTester/Log.cpp @@ -0,0 +1,24 @@ +#include "Log.h" +#include "Config.h" +#include +#include + +namespace Log { +void event(const char *component, const char *message) { + if (!SERIAL_ACTION_LOG) return; + if (SERIAL_MINIMAL_LOG && strcmp(component, "INPUT") && strcmp(component, "UI") && + strcmp(component, "CONFIG") && strcmp(component, "RESULT")) return; + if (SERIAL_LOG_TIMESTAMPS) Serial.printf("[%10lu][%-8s] %s\n", millis(), component, message); + else Serial.printf("[%-8s] %s\n", component, message); +} + +void printf(const char *component, const char *format, ...) { + if (!SERIAL_ACTION_LOG) return; + char text[192]; + va_list args; + va_start(args, format); + vsnprintf(text, sizeof(text), format, args); + va_end(args); + event(component, text); +} +} diff --git a/OpticalChannelTester/Log.h b/OpticalChannelTester/Log.h new file mode 100644 index 0000000..26d465f --- /dev/null +++ b/OpticalChannelTester/Log.h @@ -0,0 +1,9 @@ +#pragma once +#include + +namespace Log { +void event(const char *component, const char *message); +void printf(const char *component, const char *format, ...) + __attribute__((format(printf, 2, 3))); +} + diff --git a/OpticalChannelTester/Measurement.cpp b/OpticalChannelTester/Measurement.cpp index ea8a988..f220aaa 100644 --- a/OpticalChannelTester/Measurement.cpp +++ b/OpticalChannelTester/Measurement.cpp @@ -44,9 +44,13 @@ MeasureState Measurement::update() { tolerance_, repeat + 1, stats_); if (r != FailReason::NONE) { fail(r); return state_; } } - const uint64_t expectedPeriodMs = static_cast(1000.0f / expectedHz_) + 1; - const uint64_t settleTimeout = (static_cast(PWM_SETTLE_CYCLES + NO_SIGNAL_TIMEOUT_PERIODS) * - expectedPeriodMs) + 20; + uint64_t expectedPeriodMs = static_cast(ceilf(1000.0f / expectedHz_)); + if (!expectedPeriodMs) expectedPeriodMs = 1; + const uint64_t edgeBasedTimeout = + static_cast(PWM_SETTLE_CYCLES + NO_SIGNAL_TIMEOUT_PERIODS) * expectedPeriodMs + 20; + const uint64_t rmtBatchTimeout = + static_cast(RMT_MIN_RECEIVE_SYMBOLS + NO_SIGNAL_TIMEOUT_PERIODS) * expectedPeriodMs + 20; + const uint64_t settleTimeout = edgeBasedTimeout > rmtBatchTimeout ? edgeBasedTimeout : rmtBatchTimeout; if (state_ == MeasureState::SETTLING && millis() - startedMs_ > settleTimeout) fail(FailReason::NO_SIGNAL); if (state_ == MeasureState::RUNNING && measurementStartTick_) { const uint32_t now = millis(); diff --git a/OpticalChannelTester/Protocol.cpp b/OpticalChannelTester/Protocol.cpp index f7c4c8b..fe24d71 100644 --- a/OpticalChannelTester/Protocol.cpp +++ b/OpticalChannelTester/Protocol.cpp @@ -1,6 +1,13 @@ #include "Protocol.h" #include +const char *messageName(MessageType type) { + static const char *names[] = {"DISCOVER", "DISCOVER_ACK", "PREPARE", "READY", + "START_STAGE", "RESULT", "ACK", "ABORT"}; + const uint8_t index = static_cast(type); + return index < sizeof(names) / sizeof(names[0]) ? names[index] : "UNKNOWN"; +} + uint16_t packetCrc(const ProtocolPacket &p) { const uint8_t *data = reinterpret_cast(&p); uint16_t crc = 0xFFFF; @@ -19,4 +26,3 @@ bool validPacket(const ProtocolPacket &p) { return p.magic == PROTOCOL_MAGIC && p.version == PROTOCOL_VERSION && p.type <= static_cast(MessageType::ABORT) && p.crc == packetCrc(p); } - diff --git a/OpticalChannelTester/Protocol.h b/OpticalChannelTester/Protocol.h index 7946b64..61f1f80 100644 --- a/OpticalChannelTester/Protocol.h +++ b/OpticalChannelTester/Protocol.h @@ -8,6 +8,8 @@ enum class MessageType : uint8_t { DISCOVER, DISCOVER_ACK, PREPARE, READY, START_STAGE, RESULT, ACK, ABORT }; +const char *messageName(MessageType type); + #pragma pack(push, 1) struct ProtocolPacket { uint16_t magic; diff --git a/OpticalChannelTester/Pwm.cpp b/OpticalChannelTester/Pwm.cpp index 5ea68b0..c776f09 100644 --- a/OpticalChannelTester/Pwm.cpp +++ b/OpticalChannelTester/Pwm.cpp @@ -1,12 +1,18 @@ #include "Pwm.h" #include "Config.h" +#include "Core.h" -void PwmGenerator::begin() { pinMode(GPIO_PWM, OUTPUT); stop(); } +void PwmGenerator::begin() { + // Match LEDC_SOURCE_CLOCK_HZ and make the timer calculation deterministic. + ledcSetClockSource(LEDC_USE_XTAL_CLK); + pinMode(GPIO_PWM, OUTPUT); + stop(); +} bool PwmGenerator::start(uint32_t hz, uint8_t dutyPct, ActualPwm &a) { stop(); - uint8_t bits = LEDC_MAX_BITS; - while (bits > 1 && static_cast(hz) * (1ULL << bits) > 80000000ULL) --bits; + const uint8_t bits = choosePwmResolution(hz, LEDC_SOURCE_CLOCK_HZ, LEDC_MAX_BITS); + if (!bits) return false; if (!ledcAttachChannel(GPIO_PWM, hz, bits, LEDC_CHANNEL)) return false; const uint32_t top = (1UL << bits) - 1UL; const uint32_t duty = (static_cast(top) * dutyPct + 50U) / 100U; @@ -18,20 +24,6 @@ bool PwmGenerator::start(uint32_t hz, uint8_t dutyPct, ActualPwm &a) { return true; } -bool PwmGenerator::preview(uint32_t hz, uint8_t dutyPct, ActualPwm &a) { - stop(); - uint8_t bits = LEDC_MAX_BITS; - while (bits > 1 && static_cast(hz) * (1ULL << bits) > 80000000ULL) --bits; - if (!ledcAttachChannel(GPIO_PWM, hz, bits, LEDC_CHANNEL)) return false; - ledcWriteChannel(LEDC_CHANNEL, 0); // query hardware without emitting test pulses - const uint32_t actualHz = ledcReadFreq(GPIO_PWM); - const uint32_t top = (1UL << bits) - 1UL; - const uint32_t duty = (static_cast(top) * dutyPct + 50U) / 100U; - a = {hz, actualHz, 100.0f * duty / top, bits}; - ledcDetach(GPIO_PWM); pinMode(GPIO_PWM, OUTPUT); digitalWrite(GPIO_PWM, PWM_SAFE_LEVEL); - return actualHz != 0; -} - void PwmGenerator::stop() { if (running_) ledcDetach(GPIO_PWM); pinMode(GPIO_PWM, OUTPUT); digitalWrite(GPIO_PWM, PWM_SAFE_LEVEL); diff --git a/OpticalChannelTester/Pwm.h b/OpticalChannelTester/Pwm.h index 0601562..4a757ee 100644 --- a/OpticalChannelTester/Pwm.h +++ b/OpticalChannelTester/Pwm.h @@ -6,7 +6,6 @@ struct ActualPwm { uint32_t requestedHz; uint32_t actualHz; float actualDutyPct; class PwmGenerator { public: void begin(); - bool preview(uint32_t frequencyHz, uint8_t dutyPct, ActualPwm &actual); bool start(uint32_t frequencyHz, uint8_t dutyPct, ActualPwm &actual); void stop(); bool running() const { return running_; } diff --git a/OpticalChannelTester/Radio.cpp b/OpticalChannelTester/Radio.cpp index 075bef8..a8011b4 100644 --- a/OpticalChannelTester/Radio.cpp +++ b/OpticalChannelTester/Radio.cpp @@ -1,5 +1,6 @@ #include "Radio.h" #include "Config.h" +#include "Log.h" #include #include #include @@ -8,21 +9,26 @@ Radio *Radio::instance_ = nullptr; static const uint8_t BROADCAST_MAC[6] = {0xff, 0xff, 0xff, 0xff, 0xff, 0xff}; bool Radio::begin() { - if (active_) return true; + if (active_) { Log::event("ESP-NOW", "already active"); return true; } WiFi.mode(WIFI_STA); WiFi.disconnect(); - if (esp_wifi_set_channel(ESPNOW_WIFI_CHANNEL, WIFI_SECOND_CHAN_NONE) != ESP_OK) return false; + if (esp_wifi_set_channel(ESPNOW_WIFI_CHANNEL, WIFI_SECOND_CHAN_NONE) != ESP_OK) { + Log::event("ESP-NOW", "Wi-Fi channel setup FAILED"); return false; + } queue_ = xQueueCreate(8, sizeof(ReceivedPacket)); - if (!queue_ || esp_now_init() != ESP_OK) return false; + if (!queue_ || esp_now_init() != ESP_OK) { Log::event("ESP-NOW", "initialization FAILED"); return false; } instance_ = this; if (esp_now_register_recv_cb(onReceive) != ESP_OK) { end(); return false; } active_ = true; - return ensurePeer(BROADCAST_MAC); + const bool ok = ensurePeer(BROADCAST_MAC); + Log::printf("ESP-NOW", "started channel=%u broadcast-peer=%s", ESPNOW_WIFI_CHANNEL, ok ? "OK" : "FAILED"); + return ok; } void Radio::end() { if (active_) { esp_now_unregister_recv_cb(); esp_now_deinit(); } if (queue_) { vQueueDelete(queue_); queue_ = nullptr; } active_ = false; if (instance_ == this) instance_ = nullptr; + Log::event("ESP-NOW", "stopped"); } bool Radio::ensurePeer(const uint8_t mac[6]) { @@ -35,9 +41,16 @@ bool Radio::ensurePeer(const uint8_t mac[6]) { bool Radio::sendBroadcast(ProtocolPacket p) { return sendTo(BROADCAST_MAC, p); } bool Radio::sendTo(const uint8_t mac[6], ProtocolPacket p) { - if (!active_ || !ensurePeer(mac)) return false; + char peer[20]; macText(mac, peer, sizeof(peer)); + if (!active_ || !ensurePeer(mac)) { + Log::printf("ESP-NOW", "TX %s to %s FAILED: inactive/peer", messageName(static_cast(p.type)), peer); + return false; + } finalizePacket(p); - return esp_now_send(mac, reinterpret_cast(&p), sizeof(p)) == ESP_OK; + const bool ok = esp_now_send(mac, reinterpret_cast(&p), sizeof(p)) == ESP_OK; + Log::printf("ESP-NOW", "TX %s to %s session=%08lX stage=%u seq=%u %s", + messageName(static_cast(p.type)), peer, p.session, p.stage, p.sequence, ok ? "QUEUED" : "FAILED"); + return ok; } bool Radio::receive(ReceivedPacket &r) { diff --git a/OpticalChannelTester/Receiver.cpp b/OpticalChannelTester/Receiver.cpp index f55bc94..afe4a83 100644 --- a/OpticalChannelTester/Receiver.cpp +++ b/OpticalChannelTester/Receiver.cpp @@ -19,11 +19,15 @@ bool PulseReceiver::begin() { queue_ = xQueueCreate(16, sizeof(SymbolBlock)); rmt_rx_channel_config_t cfg = {}; cfg.clk_src = RMT_CLK_SRC_DEFAULT; cfg.resolution_hz = CAPTURE_RESOLUTION_HZ; - cfg.mem_block_symbols = 512; cfg.gpio_num = static_cast(GPIO_RX); + cfg.gpio_num = static_cast(GPIO_RX); cfg.flags.invert_in = RX_SIGNAL_INVERTED; #if CONFIG_IDF_TARGET_ESP32S3 + cfg.mem_block_symbols = 512; cfg.flags.with_dma = true; #else + // C3 has 48 RMT symbols per channel and no RMT DMA. A request for 512 + // consumes all available blocks and fails with "no free rx channels". + cfg.mem_block_symbols = RMT_MIN_RECEIVE_SYMBOLS; cfg.flags.with_dma = false; // C3 uses hardware RMT ping-pong partial reception #endif if (!queue_ || rmt_new_rx_channel(&cfg, &channel_) != ESP_OK) return false; @@ -42,13 +46,20 @@ bool PulseReceiver::begin() { bool PulseReceiver::start(uint32_t expectedHz) { resetStream(); #if OPTICAL_USE_RMT_DMA + // In partial RX mode the callback is delivered when this user buffer fills. + // Keep chunks near 5 ms so low-frequency input is reported before NO SIGNAL. + uint64_t symbols = (static_cast(expectedHz) * RMT_TARGET_CHUNK_US + 999999ULL) / 1000000ULL; + if (symbols < RMT_MIN_RECEIVE_SYMBOLS) symbols = RMT_MIN_RECEIVE_SYMBOLS; + if (symbols > RMT_MAX_RECEIVE_SYMBOLS) symbols = RMT_MAX_RECEIVE_SYMBOLS; + receiveChunkSymbols_ = static_cast(symbols); if (rmt_enable(channel_) != ESP_OK) return false; rmt_receive_config_t cfg = {}; cfg.signal_range_min_ns = 20; const uint64_t maxNs = 4000000000ULL / (expectedHz ? expectedHz : 1); cfg.signal_range_max_ns = maxNs > 100000000ULL ? 100000000UL : static_cast(maxNs); cfg.flags.en_partial_rx = true; - if (rmt_receive(channel_, dmaBuffer_, sizeof(dmaBuffer_), &cfg) != ESP_OK) { + if (rmt_receive(channel_, receiveBuffer_, + receiveChunkSymbols_ * sizeof(receiveBuffer_[0]), &cfg) != ESP_OK) { rmt_disable(channel_); return false; } #else @@ -86,7 +97,11 @@ bool PulseReceiver::consumeEdge(const Edge &e, PulsePeriod &out) { out = {rise_, period, active}; rise_ = tick; haveFall_ = false; return true; } - if (!haveRise_ || haveFall_) { overflow_ = true; return false; } + // Reception can begin in the middle of a HIGH pulse. In that case the first + // observable edge is falling and there is no complete period to validate. + // Ignore only this leading partial pulse and synchronize on the next rise. + if (!haveRise_) return false; + if (haveFall_) { overflow_ = true; return false; } fall_ = tick; haveFall_ = true; return false; } diff --git a/OpticalChannelTester/Receiver.h b/OpticalChannelTester/Receiver.h index 6a24a56..90f3d83 100644 --- a/OpticalChannelTester/Receiver.h +++ b/OpticalChannelTester/Receiver.h @@ -1,6 +1,7 @@ #pragma once #include #include +#include "Config.h" #include "Core.h" #if ESP_IDF_VERSION >= ESP_IDF_VERSION_VAL(5, 5, 0) @@ -20,6 +21,7 @@ class PulseReceiver { bool poll(PulsePeriod &period); bool overflowed(); uint32_t tickHz() const; + uint16_t receiveChunkSymbols() const { return receiveChunkSymbols_; } bool highRateBackend() const { #if OPTICAL_USE_RMT_DMA && CONFIG_IDF_TARGET_ESP32S3 return true; @@ -37,7 +39,8 @@ class PulseReceiver { static bool IRAM_ATTR onRmt(rmt_channel_handle_t, const rmt_rx_done_event_data_t *, void *); bool nextRmtEdge(Edge &edge); rmt_channel_handle_t channel_ = nullptr; - rmt_symbol_word_t dmaBuffer_[512]; + rmt_symbol_word_t receiveBuffer_[RMT_MAX_RECEIVE_SYMBOLS]; + uint16_t receiveChunkSymbols_ = 0; SymbolBlock block_ = {}; uint16_t blockIndex_ = 0; uint8_t phase_ = 0; diff --git a/OpticalChannelTester/SettingsStore.cpp b/OpticalChannelTester/SettingsStore.cpp index 38952c3..f4a55cb 100644 --- a/OpticalChannelTester/SettingsStore.cpp +++ b/OpticalChannelTester/SettingsStore.cpp @@ -1,5 +1,6 @@ #include "SettingsStore.h" #include "Config.h" +#include "Log.h" #include namespace { constexpr uint16_t SETTINGS_VERSION = 1; constexpr char NAMESPACE[] = "opt-test"; } @@ -20,20 +21,21 @@ bool SettingsStore::valid(const Settings &s) const { bool SettingsStore::load(Settings &s) { Preferences prefs; - if (!prefs.begin(NAMESPACE, true)) { defaults(s); return false; } + if (!prefs.begin(NAMESPACE, true)) { defaults(s); Log::event("NVS", "open for read FAILED; defaults selected"); return false; } const size_t got = prefs.getBytes("settings", &s, sizeof(s)); prefs.end(); - if (got != sizeof(s) || !valid(s)) { defaults(s); return false; } + if (got != sizeof(s) || !valid(s)) { defaults(s); Log::event("NVS", "missing/corrupt settings; defaults selected"); return false; } + Log::event("NVS", "settings loaded and validated"); return true; } bool SettingsStore::save(Settings &s) { s.version = SETTINGS_VERSION; s.checksum = settingsChecksum(s); - if (!valid(s)) return false; + if (!valid(s)) { Log::event("NVS", "save rejected: invalid settings"); return false; } Preferences prefs; - if (!prefs.begin(NAMESPACE, false)) return false; + if (!prefs.begin(NAMESPACE, false)) { Log::event("NVS", "open for write FAILED"); return false; } const bool ok = prefs.putBytes("settings", &s, sizeof(s)) == sizeof(s); - prefs.end(); return ok; + prefs.end(); Log::printf("NVS", "settings save %s", ok ? "OK" : "FAILED"); return ok; } TestParams SettingsStore::params(const Settings &s) const { @@ -42,4 +44,3 @@ TestParams SettingsStore::params(const Settings &s) const { TEST_TIME_OPTIONS_MS[s.timeIndex], REPEAT_OPTIONS[s.repeatIndex], DUTY_OPTIONS_PCT[s.dutyIndex]}; } - diff --git a/README.md b/README.md index 31fd909..52e9484 100644 --- a/README.md +++ b/README.md @@ -18,6 +18,7 @@ - Preferences/NVS с версией структуры, checksum, проверкой индексов и восстановлением defaults; - работа через Serial при отсутствующем OLED; - безопасное выключение PWM при PASS, FAIL, ABORT и потере связи. +- полный журнал действий в Serial с временными метками; OLED необязателен. ## Файлы @@ -29,6 +30,7 @@ Arduino sketch находится в каталоге `OpticalChannelTester`: - `Buttons.*` — автомат двух кнопок; - `SettingsStore.*` — NVS; - `Display.*` — OLED и компактное форматирование; +- `Log.*` — журнал действий и Serial-зеркало интерфейса; - `Pwm.*` — LEDC; - `Receiver.*` — RMT RX / совместимый fallback; - `Measurement.*` — строгая проверка периодов; @@ -68,6 +70,32 @@ Arduino sketch находится в каталоге `OpticalChannelTester`: Подключите SSD1306 128×32: `VCC → 3.3 V`, `GND → GND`, `SDA/SCL` по таблице. Адрес по умолчанию `0x3C`. Если OLED не отвечает, тест продолжает работать и пишет диагностику в Serial 115200. +### Работа вообще без OLED + +OLED можно не подключать. Откройте Serial Monitor на **115200 baud**: каждый экран всегда дублируется одной строкой вида: + +```text +[ 1250][UI ] MODE: SOLO | START=RUN +``` + +В Serial также выводятся: + +- каждое распознанное нажатие START/MODE и текущее состояние автомата; +- вход, изменение и сохранение каждого пункта меню; +- загрузка, проверка и сохранение NVS; +- запуск/остановка PWM и реальные параметры LEDC; +- начало этапа, число отбрасываемых периодов и параметры измерительного окна; +- все действия ESP-NOW, peer, session/stage/sequence, ACK и повторы; +- статистика этапа, первый плохой период и итоговая причина завершения; +- все строки, которые были бы показаны на OLED. + +Во время строгого измерительного окна отдельные импульсы намеренно не печатаются: они проверяются потоково, а итоговая статистика выводится после окна. Это предотвращает влияние Serial на точность и переполнение очереди RMT. Журнал действий включён параметрами в `Config.h`: + +```cpp +constexpr bool SERIAL_ACTION_LOG = true; +constexpr bool SERIAL_LOG_TIMESTAMPS = true; +``` + ### Кнопки По умолчанию задано: @@ -174,8 +202,8 @@ PWM_SETTLE_CYCLES / actualFrequency + TEST_TIME * REPEATS | Target | Arduino-ESP32 | Flash | RAM | Результат | |---|---:|---:|---:|---| -| ESP32-C3 | 3.3.10 | 1,020,337 B (77%) | 39,460 B (12%) | PASS | -| ESP32-S3 | 3.3.10 | 947,712 B (72%) | 48,620 B (14%) | PASS | +| ESP32-C3 | 3.3.10 | 1,024,299 B (78%) | 39,460 B (12%) | PASS | +| ESP32-S3 | 3.3.10 | 950,608 B (72%) | 48,620 B (14%) | PASS | Локальные unit-тесты: `core tests: PASS`, `button tests: PASS`. Они покрывают неделимый диапазон, END без дубля, ALL, границы допусков, немедленный FAIL, resolution, checksum настроек, CRC протокола и отсутствие short после long.