diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index 9ee61b9..8ab81f4 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -10,6 +10,103 @@ This log tracks all bug fixes and behavioral changes to prevent re-doing work du --- +## 2026-05-18: OTASim two-station GUI connect end-to-end + +**Fixed:** Two `ultra_gui -sim` instances pointed at the same +`ota_simulator serve` daemon could PING/PONG but never complete the +CONNECT/MODE_CHANGE handshake. The connect attempt would stall and the +two GUIs sat in state 1 (PING_SENT) or state 2 (PONG_RECEIVED) for the +session lifetime. + +**Root causes (three independent bugs, all compounding):** + +1. **OTASim client RX buffer cap was 20 s.** + `kMaxRxBufferSamples = 960000` at 48 kHz meant the client could + silently accumulate up to 20 seconds of audio before dropping any + samples. Server's session-clock tick emits continuous samples at + real-time rate (silence + audio, like a real soundcard); when the + GUI render loop briefly stalled (waterfall scroll, ImGui spike) the + audio piled up and never recovered. Real audio frames then sat + behind multi-second silence, well past the ARQ timeouts and the + modem's sync-search window. + +2. **`-sim` mode left modem callsign at default `8P9QC`.** + The GUI's `Connect to ` uses the OTASim `--station-id` as + the destination callsign in the frame header. But the modem's local + callsign defaulted to `8P9QC` from settings; nothing forced it to + match the `--station-id`. `deliverFrame()` parses the header, sees + `dst=ALPHA` vs `local=8P9QC`, classifies the frame as "different + station", and drops it silently at TRACE level. LDPC was decoding + 3/3 CWs successfully, the frame was then dropped before reaching + the protocol layer. + +3. **`--log-file` only captured the App-constructor startup logs.** + `App::initLog()` unconditionally called `ultra::setLogFile(g_gui_log_file)` + after opening `logs/gui.log`, overriding whatever `main_gui.cpp` had + set from `--log-file`. So per-station log files would receive ~12 + lines of modem init and then go silent for the rest of the session, + making per-station debug impossible without juggling working + directories. + +**Changed:** + +- `src/otasim_client/ota_audio_backend.cpp` — `kMaxRxBufferSamples` + reduced from `960000` (20 s) to `23040` (480 ms). Behaves like a + real soundcard's driver buffer: continuous samples in, consumer + drains at real-time rate, oldest drops on consumer stall. 480 ms + ≈ 8x a 60 Hz render budget, which absorbs typical jitter without + building multi-second latency. +- `src/otasim_client/ota_audio_backend.{cpp,hpp}` — optional + `#ifdef ULTRA_OTASIM_AUDIO_DIAGNOSTICS` counters log RX queue depth + every 100 packets. Off by default. +- `src/gui/app.cpp` — in `-sim` mode with non-empty `--station-id`, + force the modem's local callsign to the station id (overrides the + settings callsign for the protocol-address check only). Without this, + every inbound frame is dropped as "different station". +- `src/gui/app.cpp` — `initLog()` adopts `ultra::g_log_file` if it is + already set externally (by `main_gui.cpp`'s `--log-file` parser), + instead of blindly opening `logs/gui.log` and clobbering the user's + chosen sink. +- `tests/test_ultra_gui_ota_client.cpp` — extended to time the + passthrough latency (must be < 150 ms in-process) and to bound the + idle RX backlog at the new soundcard-like cap. + +**ACK diversity + CONNECT_ACK rescue retry are intentional.** Once the +handshake completes you will see each ACK delivered twice (~440 ms +apart) and one proactive CONNECT_ACK re-send. Both mechanisms exist +for real HF where the dominant loss mode is plain cumulative ACKs +disappearing into a fade — see comment in +`src/protocol/selective_repeat_arq.cpp:1266`. On OTASim's clean AWGN +channel they are visible but harmless; SR-ARQ correctly de-duplicates +at the base/bitmap level. Do not propose disabling them. + +**Verification:** + +```bash +cmake --build build -j4 +ctest --test-dir build -R "Otasim|UltraGuiOta|UltraTncSimAudio|SessionContext" \ + --output-on-failure -j1 # 3/3 (or 4/4) pass + +# Manual two-station QSO over OTASim (localhost): +./build/ota_simulator serve --bind 127.0.0.1:50051 --udp-bind 127.0.0.1:50052 \ + --tokens /tmp/ota_tokens.conf & +./build/ultra_gui -sim --ota-host 127.0.0.1:50051 \ + --station-id ALPHA --token alpha_tok --monitor-audio \ + --log-file /tmp/alpha.log --log-level debug & +./build/ultra_gui -sim --ota-host 127.0.0.1:50051 \ + --station-id BRAVO --token bravo_tok --monitor-audio \ + --log-file /tmp/bravo.log --log-level debug & +# In one GUI: Connect to other station. +# Expected: both reach state 3 (CONNECTED), MODE_CHANGE to OFDM-CHIRP +# DQPSK R1/4, in-session ACKs decode in OFDM control profile. +``` + +Verified end-to-end on 2026-05-18: full PING → PONG → CONNECT → +CONNECT_ACK → MODE_CHANGE → CONNECTED on two macOS GUIs against a +local `ota_simulator serve` daemon. + +--- + ## 2026-05-15: CONNECT call-collision handling **Fixed:** Inbound CONNECT frames arriving while the local station was in diff --git a/src/gui/app.cpp b/src/gui/app.cpp index 22e4167..eb6f440 100644 --- a/src/gui/app.cpp +++ b/src/gui/app.cpp @@ -46,6 +46,16 @@ static void initLog() { if (g_log_initialized) return; g_log_initialized = true; + // If --log-file was passed (main_gui.cpp set ultra::g_log_file before + // App is constructed), adopt that as our gui-log sink too. Otherwise + // every call into guiLog() would overwrite the user's chosen destination + // with our own logs/gui.log. + if (ultra::g_log_file != nullptr) { + g_gui_log_file = ultra::g_log_file; + g_gui_log_path = "(via --log-file)"; + return; + } + #ifdef _WIN32 auto tryOpenLog = [](const char* path) -> FILE* { if (!path || path[0] == '\0') { @@ -366,11 +376,22 @@ App::App(const Options& opts) : options_(opts), simulation_enabled_(opts.enable_ guiLog("Waterfall disabled by startup option"); } - // Initialize protocol with saved callsign + // Initialize protocol with saved callsign. In -sim mode the OTASim + // --station-id is what the peer uses to address us at the protocol + // level (the GUI's "Connect to " passes the station id); so + // force the modem's local callsign to match, otherwise deliverFrame() + // would drop every incoming frame as "different station". ultra::gui::startupTrace("App", "callsign-init-enter"); - size_t local_call_len = boundedCStringLen(settings_.callsign); - if (local_call_len > 0) { - std::string local_call(settings_.callsign, local_call_len); + std::string local_call; + if (simulation_enabled_ && !options_.station_id.empty()) { + local_call = options_.station_id; + } else { + size_t local_call_len = boundedCStringLen(settings_.callsign); + if (local_call_len > 0) { + local_call.assign(settings_.callsign, local_call_len); + } + } + if (!local_call.empty()) { ultra::gui::startupTrace("App", "callsign-set-protocol-enter"); protocol_.setLocalCallsign(local_call); ultra::gui::startupTrace("App", "callsign-set-protocol-exit"); @@ -1126,9 +1147,38 @@ void App::initOtaAudio() { appendRxLogLine("[OTASIM] Connecting to " + options_.ota_host + " as " + options_.station_id + " in session " + (options_.session_id.empty() ? "lobby" : options_.session_id)); + + if (options_.monitor_audio && ota_monitor_device_id_ == 0) { + SDL_AudioSpec want{}; + SDL_AudioSpec have{}; + want.freq = 48000; + want.format = AUDIO_F32SYS; + want.channels = 1; + want.samples = 2048; + want.callback = nullptr; + const char* device_name = options_.monitor_device.empty() + ? nullptr + : options_.monitor_device.c_str(); + SDL_AudioDeviceID dev = SDL_OpenAudioDevice(device_name, 0, &want, &have, 0); + if (dev == 0) { + guiLog("OTASim monitor: SDL_OpenAudioDevice failed: %s", SDL_GetError()); + appendRxLogLine(std::string("[OTASIM] Monitor unavailable: ") + SDL_GetError()); + } else { + ota_monitor_device_id_ = dev; + SDL_PauseAudioDevice(dev, 0); + guiLog("OTASim monitor: playing RX through SDL device '%s'", + device_name ? device_name : "(default)"); + appendRxLogLine(std::string("[OTASIM] Monitor: ") + + (device_name ? device_name : "(default output)")); + } + } } void App::stopOtaAudio() { + if (ota_monitor_device_id_ != 0) { + SDL_CloseAudioDevice(ota_monitor_device_id_); + ota_monitor_device_id_ = 0; + } if (ota_audio_) { ota_audio_->close(); ota_audio_.reset(); @@ -1157,6 +1207,16 @@ void App::pollOtaRx() { if (waterfall_) { waterfall_->addSamples(samples.data(), samples.size()); } + if (ota_monitor_device_id_ != 0) { + // ~500ms cap at 48kHz mono float = 24000 samples = 96000 bytes + constexpr Uint32 kMaxQueueBytes = 96000; + if (SDL_GetQueuedAudioSize(ota_monitor_device_id_) > kMaxQueueBytes) { + SDL_ClearQueuedAudio(ota_monitor_device_id_); + } + SDL_QueueAudio(ota_monitor_device_id_, + samples.data(), + static_cast(samples.size() * sizeof(float))); + } } } @@ -1958,6 +2018,14 @@ ptt::PttConfig App::pttConfigFromSettings(const AppSettings& settings) const { } bool App::ensurePttReadyLocked(const AppSettings& settings) { + if (simulation_enabled_) { + if (ptt_driver_) { + ptt_driver_->close(); + ptt_driver_.reset(); + } + ptt_config_ = ptt::PttConfig{}; + return true; + } const ptt::PttConfig config = pttConfigFromSettings(settings); if (config.mode == ptt::PttMode::None) { if (ptt_driver_) { @@ -2016,6 +2084,18 @@ void App::updateWaterfallFrequencyDisplay() { return; } + if (simulation_enabled_) { + std::lock_guard lock(ptt_driver_mutex_); + if (ptt_driver_) { + ptt_driver_->close(); + ptt_driver_.reset(); + ptt_config_ = ptt::PttConfig{}; + cat_frequency_next_open_attempt_ms_ = 0; + } + waterfall_->setRadioFrequency(std::nullopt, false); + return; + } + const ptt::PttConfig config = pttConfigFromSettings(settings_); if (config.mode != ptt::PttMode::Cat && config.mode != ptt::PttMode::HamlibBuiltin) { diff --git a/src/gui/app.hpp b/src/gui/app.hpp index bf2854d..54518c4 100644 --- a/src/gui/app.hpp +++ b/src/gui/app.hpp @@ -42,6 +42,8 @@ class App { std::string token; std::string station_id; std::string session_id = "lobby"; + bool monitor_audio = false; // -sim: also play RX audio through local speakers + std::string monitor_device; // -sim: optional SDL output device name // Monitor mode: skip the full PING/CONNECT handshake and force // the decoder into a specific waveform/rate. Useful for OTA @@ -198,6 +200,7 @@ class App { std::vector recorded_tx_samples_; // Real TX audio queued to output void writeRecordingToFile(); // Save recording buffers to disk std::unique_ptr ota_audio_; + uint32_t ota_monitor_device_id_ = 0; // SDL_AudioDeviceID; 0 = closed // ======================================== // UI Rendering diff --git a/src/gui/main_gui.cpp b/src/gui/main_gui.cpp index b876bda..d4e451e 100644 --- a/src/gui/main_gui.cpp +++ b/src/gui/main_gui.cpp @@ -194,6 +194,8 @@ void printGuiUsage(const char* prog) { std::printf(" --token OTASim auth token for -sim\n"); std::printf(" --station-id OTASim station id for -sim\n"); std::printf(" --session-id OTASim session id (default: lobby)\n"); + std::printf(" --monitor-audio Play OTASim RX through local speakers\n"); + std::printf(" --monitor-device SDL audio output device for --monitor-audio\n"); std::printf(" -rec [path] Record received audio\n"); std::printf(" --software, -sw Use software renderer and safe startup\n"); std::printf(" --opengl, --gl Use OpenGL renderer\n"); @@ -502,6 +504,15 @@ int main(int argc, char* argv[]) { return 1; } opts.session_id = argv[++i]; + } else if (arg == "--monitor-audio") { + opts.monitor_audio = true; + } else if (arg == "--monitor-device") { + if (i + 1 >= argc) { + std::fprintf(stderr, "Missing value for --monitor-device\n"); + closeStartupLog(); + return 1; + } + opts.monitor_device = argv[++i]; } else if (arg == "--help" || arg == "-h") { printGuiUsage(argv[0]); closeStartupLog(); diff --git a/src/otasim_client/ota_audio_backend.cpp b/src/otasim_client/ota_audio_backend.cpp index 5ba703b..6b131e9 100644 --- a/src/otasim_client/ota_audio_backend.cpp +++ b/src/otasim_client/ota_audio_backend.cpp @@ -5,6 +5,7 @@ #include #include #include +#include #include #include @@ -25,7 +26,15 @@ namespace service = ultra::ota_simulator_service; constexpr uint32_t kFallbackMaxPacketSamples = static_cast((8192 - service::kOtaAudioHeaderBytes) / sizeof(float)); constexpr size_t kPrimeSamples = 8; -constexpr size_t kMaxRxBufferSamples = 960000; +// 480 ms of audio at 48 kHz mono. Mirrors a real soundcard's bounded +// driver buffer: the server emits continuous samples at real-time rate +// (silence + audio just like a radio's RX line), the consumer drains +// at real-time rate; if the consumer stalls (slow render frame, GC) +// the oldest samples drop. 480 ms = ~8x a 60 Hz render budget, which +// absorbs typical jitter without piling up multi-second latency. The +// previous 20 s cap let 5+ seconds of silence sit in front of the +// first real audio and stalled the connect handshake. +constexpr size_t kMaxRxBufferSamples = 23040; constexpr auto kRpcDeadline = std::chrono::milliseconds(1500); constexpr auto kHeartbeatInterval = std::chrono::seconds(2); constexpr auto kReconnectInterval = std::chrono::seconds(5); @@ -624,6 +633,9 @@ void OtaAudioBackend::pushRxPacket(uint64_t start_sample, std::span std::vector copy(samples.begin() + static_cast(offset), samples.end()); rx_pending_.emplace(start_sample, std::move(copy)); drainReadyRxLocked(); +#ifdef ULTRA_OTASIM_AUDIO_DIAGNOSTICS + logRxDiagnosticsLocked("push"); +#endif } void OtaAudioBackend::drainReadyRxLocked() { @@ -643,6 +655,26 @@ void OtaAudioBackend::drainReadyRxLocked() { } } +#ifdef ULTRA_OTASIM_AUDIO_DIAGNOSTICS +void OtaAudioBackend::logRxDiagnosticsLocked(const char* context) { + if ((++rx_diagnostic_packet_counter_ % 100) != 0) { + return; + } + size_t pending_samples = 0; + for (const auto& [_, samples] : rx_pending_) { + pending_samples += samples.size(); + } + std::clog << "[INFO] otasim.client_rx" + << " context=" << context + << " station=" << config_.station_id + << " session=" << config_.session_id + << " rx_pending_blocks=" << rx_pending_.size() + << " rx_pending_samples=" << pending_samples + << " rx_buffer_samples=" << rx_buffer_.size() + << " rx_next_sample=" << rx_next_sample_ << "\n"; +} +#endif + void OtaAudioBackend::setStatus(OtaAudioConnectionState state, std::string text, int attempt) { std::lock_guard lock(mutex_); setStatusLocked(state, std::move(text), attempt); diff --git a/src/otasim_client/ota_audio_backend.hpp b/src/otasim_client/ota_audio_backend.hpp index 1275fb8..dfe629b 100644 --- a/src/otasim_client/ota_audio_backend.hpp +++ b/src/otasim_client/ota_audio_backend.hpp @@ -77,6 +77,9 @@ class OtaAudioBackend { void rxLoop(); void pushRxPacket(uint64_t start_sample, std::span samples); void drainReadyRxLocked(); +#ifdef ULTRA_OTASIM_AUDIO_DIAGNOSTICS + void logRxDiagnosticsLocked(const char* context); +#endif void setStatus(OtaAudioConnectionState state, std::string text, int attempt = 0); void setStatusLocked(OtaAudioConnectionState state, std::string text, int attempt = 0); @@ -109,6 +112,9 @@ class OtaAudioBackend { uint64_t rx_next_sample_ = 0; std::map> rx_pending_; std::vector rx_buffer_; +#ifdef ULTRA_OTASIM_AUDIO_DIAGNOSTICS + uint64_t rx_diagnostic_packet_counter_ = 0; +#endif }; } // namespace ultra::otasim_client diff --git a/tests/test_ultra_gui_ota_client.cpp b/tests/test_ultra_gui_ota_client.cpp index 300164e..e962afb 100644 --- a/tests/test_ultra_gui_ota_client.cpp +++ b/tests/test_ultra_gui_ota_client.cpp @@ -216,21 +216,34 @@ bool containsSamples(const std::vector& haystack, const std::vector& expected) { +std::chrono::milliseconds waitForSamples(otasim_client::OtaAudioBackend& backend, + const std::vector& expected, + std::chrono::milliseconds timeout) { std::vector received; - const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(5); + const auto start = std::chrono::steady_clock::now(); + const auto deadline = start + timeout; while (std::chrono::steady_clock::now() < deadline) { - auto chunk = backend.getRxSamples(256); + auto chunk = backend.getRxSamples(2048); received.insert(received.end(), chunk.begin(), chunk.end()); if (containsSamples(received, expected)) { - return; + return std::chrono::duration_cast( + std::chrono::steady_clock::now() - start); + } + if (chunk.empty()) { + std::this_thread::sleep_for(std::chrono::milliseconds(1)); } - std::this_thread::sleep_for(std::chrono::milliseconds(20)); } throw std::runtime_error("timed out waiting for passthrough audio"); } +std::vector latencyPayload(size_t samples) { + std::vector out(samples); + for (size_t i = 0; i < out.size(); ++i) { + out[i] = static_cast((i % 251) + 1) * 0.001f; + } + return out; +} + } // namespace int main(int argc, char** argv) { @@ -273,7 +286,19 @@ int main(int argc, char** argv) { const std::vector tx{0.125f, -0.25f, 0.5f, -0.75f, 0.875f, -1.0f, 0.375f, -0.625f}; check(alice.queueTxSamples(tx, &error), "alice TX failed: " + error); - waitForSamples(bob, tx); + (void)waitForSamples(bob, tx, std::chrono::seconds(5)); + + std::this_thread::sleep_for(std::chrono::seconds(5)); + const size_t idle_buffer = bob.getRxBufferSize(); + check(idle_buffer <= 26000, + "bob exceeded soundcard-like rx buffer cap: " + std::to_string(idle_buffer)); + + const std::vector latency_tx = latencyPayload(4096); + check(alice.queueTxSamples(latency_tx, &error), "alice latency TX failed: " + error); + const auto latency = waitForSamples(bob, latency_tx, std::chrono::seconds(2)); + check(latency < std::chrono::milliseconds(150), + "OTASim localhost audio latency too high: " + + std::to_string(latency.count()) + " ms"); alice.close(); bob.close();