From e44806d39aebfa0f500f9abddec5990ddc700b89 Mon Sep 17 00:00:00 2001 From: Stefan Appelhoff Date: Thu, 27 Aug 2026 10:24:13 +0200 Subject: [PATCH 1/7] fix: make thread shutdown interruptible and abort sockets on teardown --- src/recording.cpp | 78 ++++++++++++++++++++++++++++++++++++++++------- src/recording.h | 8 +++-- 2 files changed, 73 insertions(+), 13 deletions(-) diff --git a/src/recording.cpp b/src/recording.cpp index 0b8b43e..74dcc4b 100644 --- a/src/recording.cpp +++ b/src/recording.cpp @@ -1,6 +1,7 @@ #include "recording.h" //#include "conversions.h" +#include #include #include #ifdef XDFZ_SUPPORT @@ -36,7 +37,7 @@ inline bool timed_join(thread_p &thread, std::chrono::milliseconds duration = ma const auto start = Clock::now(); while (Clock::now() - start < duration) { if (try_join_once(thread)) return true; - std::this_thread::sleep_for(std::chrono::milliseconds(500)); + std::this_thread::sleep_for(std::chrono::milliseconds(20)); } return false; } @@ -72,7 +73,7 @@ inline void timed_join_or_detach( else ++it; } - std::this_thread::sleep_for(std::chrono::milliseconds(500)); + std::this_thread::sleep_for(std::chrono::milliseconds(20)); } if (!threads.empty()) { std::cout << threads.size() << " stream threads still running!" << std::endl; @@ -103,10 +104,21 @@ recording::~recording() { try { // set the shutdown flag (from now on no more new streams) shutdown_ = true; + shutdown_cv_.notify_all(); + + // close all inlets to unblock any pending network I/O immediately + { + std::lock_guard lock(inlets_mut_); + for (auto &in : active_inlets_) { + if (in) { + try { in->close_stream(); } catch (...) {} + } + } + } // stop the threads timed_join_or_detach(stream_threads_, max_join_wait); - if (!timed_join(boundary_thread_, max_join_wait + boundary_interval)) { + if (!timed_join(boundary_thread_, max_join_wait)) { std::cout << "boundary_thread didn't finish in time!" << std::endl; boundary_thread_->detach(); } @@ -119,6 +131,15 @@ recording::~recording() { void recording::requestStop() noexcept { shutdown_ = true; + shutdown_cv_.notify_all(); + { + std::lock_guard lock(inlets_mut_); + for (auto &in : active_inlets_) { + if (in) { + try { in->close_stream(); } catch (...) {} + } + } + } } void recording::record_from_query_results(const std::string &query) { @@ -173,6 +194,10 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l // open an inlet to read from (and subscribe to data immediately) in.reset(new lsl::stream_inlet(src)); + { + std::lock_guard lock(inlets_mut_); + active_inlets_.push_back(in); + } auto it = sync_options_by_stream_.find(src.name() + " (" + src.hostname() + ")"); if (it != sync_options_by_stream_.end()) in->set_postprocessing(it->second); @@ -276,6 +301,12 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l leave_footers_phase(phase_locked); throw; } + if (in) { + std::lock_guard lock(inlets_mut_); + active_inlets_.erase( + std::remove(active_inlets_.begin(), active_inlets_.end(), in), + active_inlets_.end()); + } } catch (std::exception &e) { std::cout << "Error in the record_from_streaminfo thread: " << e.what() << std::endl; } @@ -285,7 +316,15 @@ void recording::record_boundaries() { try { auto next_boundary = Clock::now() + boundary_interval; while (!shutdown_) { - std::this_thread::sleep_for(std::chrono::milliseconds(500)); + { + std::unique_lock cv_lock(shutdown_mut_); + if (shutdown_cv_.wait_for(cv_lock, std::chrono::milliseconds(500), [this] { + return shutdown_.load(); + })) { + break; + } + } + if (Clock::now() > next_boundary) { file_.write_boundary_chunk(); next_boundary = Clock::now() + boundary_interval; @@ -301,7 +340,15 @@ void recording::record_offsets( try { while (!shutdown_ && !offset_shutdown) { // sleep for the interval - std::this_thread::sleep_for(offset_interval); + { + std::unique_lock cv_lock(shutdown_mut_); + if (shutdown_cv_.wait_for(cv_lock, offset_interval, [this, &offset_shutdown] { + return shutdown_.load() || offset_shutdown.load(); + })) { + break; + } + } + // query the time offset double offset, now; try { @@ -311,9 +358,10 @@ void recording::record_offsets( std::cerr << "Timeout in time correction query for stream " << streamid << std::endl; } + if (shutdown_ || offset_shutdown) break; file_.write_stream_offset(streamid, now, offset); // also append to the offset lists - std::lock_guard lock(offset_mut_); + std::lock_guard offset_lock(offset_mut_); offset_lists_[streamid].emplace_back(now - offset, offset); } } catch (std::exception &e) { @@ -382,8 +430,8 @@ void recording::typed_transfer_loop(streamid_t streamid, double srate, const inl // Pull the first sample first_timestamp = 0.0; while(!shutdown_ && first_timestamp == 0.0) - first_timestamp = last_timestamp = in->pull_sample(chunk, 4.0); - if (!shutdown_) { + first_timestamp = last_timestamp = in->pull_sample(chunk, 0.1); + if (!shutdown_ && first_timestamp != 0.0) { timestamps.push_back(first_timestamp); file_.write_data_chunk(streamid, timestamps, chunk, (uint32_t)in->get_channel_count()); sample_count += timestamps.size(); @@ -403,17 +451,25 @@ void recording::typed_transfer_loop(streamid_t streamid, double srate, const inl last_timestamp = ts; } // write the actual chunk - file_.write_data_chunk(streamid, timestamps, chunk, in->get_channel_count()); - sample_count += timestamps.size(); + if (!timestamps.empty()) { + file_.write_data_chunk(streamid, timestamps, chunk, in->get_channel_count()); + sample_count += timestamps.size(); + } next_pull += chunk_interval; - std::this_thread::sleep_until(next_pull); + std::unique_lock cv_lock(shutdown_mut_); + if (shutdown_cv_.wait_until(cv_lock, next_pull, [this] { return shutdown_.load(); })) { + break; + } } } catch (std::exception &e) { std::cerr << "Error in transfer thread: " << e.what() << std::endl; offset_shutdown = true; + shutdown_cv_.notify_all(); timed_join_or_detach(offset_thread); throw; } + offset_shutdown = true; + shutdown_cv_.notify_all(); timed_join_or_detach(offset_thread); } diff --git a/src/recording.h b/src/recording.h index 0b198ba..56fb4fc 100644 --- a/src/recording.h +++ b/src/recording.h @@ -29,8 +29,8 @@ const auto max_footers_wait = std::chrono::seconds(2); // maximum waiting time for subscribing to a stream, in seconds (if exceeded, stream subscription // will take place later) const double max_open_wait = 5; -// maximum time that we wait to join a thread, in seconds -const std::chrono::seconds max_join_wait(5); +// maximum time that we wait to join a thread +const auto max_join_wait = std::chrono::seconds(2); using streamid_t = uint32_t; @@ -87,6 +87,10 @@ class recording { // phase-of-recording state (headers, streaming data, or footers) std::atomic shutdown_; // whether we are trying to shut down + std::condition_variable shutdown_cv_; // condition variable to wake threads immediately on shutdown + std::mutex shutdown_mut_; // mutex for shutdown condition variable + std::vector active_inlets_; // active inlets to abort on teardown + std::mutex inlets_mut_; // mutex to protect active inlets list uint32_t headers_to_finish_; // the number of streams that still need to write their header // (i.e., are not yet ready to write streaming content) uint32_t streaming_to_finish_; // the number of streams that still need to finish the streaming From c5d3038a6b57f4af7952d06cf93959842fcd3ba3 Mon Sep 17 00:00:00 2001 From: Stefan Appelhoff Date: Thu, 27 Aug 2026 10:24:14 +0200 Subject: [PATCH 2/7] test: add automated integration test for instant shutdown and XDF validation --- scripts/test_recording_teardown.py | 121 +++++++++++++++++++++++++++++ 1 file changed, 121 insertions(+) create mode 100644 scripts/test_recording_teardown.py diff --git a/scripts/test_recording_teardown.py b/scripts/test_recording_teardown.py new file mode 100644 index 0000000..209d112 --- /dev/null +++ b/scripts/test_recording_teardown.py @@ -0,0 +1,121 @@ +#!/usr/bin/env python +""" +Automated integration test for LabRecorder teardown and XDF integrity. +Tests that LabRecorder stops cleanly and instantly (< 500 ms) and produces valid XDF footers. +""" + +import argparse +import os +import subprocess +import sys +import time +import pylsl +import pyxdf + + +def run_test(cli_path, output_xdf="test_recording.xdf"): + if not os.path.exists(cli_path): + print(f"Error: LabRecorderCLI binary not found at '{cli_path}'") + return False + + if os.path.exists(output_xdf): + os.remove(output_xdf) + + print(f"--- Starting LSL test streams ---") + info_eeg = pylsl.StreamInfo("TestEEG", "EEG", 8, 100, "float32", "test_eeg_source_123") + outlet_eeg = pylsl.StreamOutlet(info_eeg) + + info_marker = pylsl.StreamInfo("TestMarker", "Markers", 1, 0, "string", "test_marker_source_123") + outlet_marker = pylsl.StreamOutlet(info_marker) + + time.sleep(0.5) + + print(f"--- Launching LabRecorderCLI ({cli_path}) ---") + proc = subprocess.Popen( + [cli_path, output_xdf, "name='TestEEG'", "name='TestMarker'"], + stdin=subprocess.PIPE, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + text=True, + ) + + print(f"--- Streaming samples for 2 seconds ---") + start_time = time.time() + sample_val = 0.0 + while time.time() - start_time < 2.0: + outlet_eeg.push_sample([sample_val] * 8) + sample_val += 1.0 + time.sleep(0.01) + + print(f"--- Triggering shutdown (Enter key to stdin) ---") + t0 = time.perf_counter() + try: + stdout, stderr = proc.communicate(input="\n", timeout=4.0) + except subprocess.TimeoutExpired: + proc.kill() + print("FAIL: LabRecorderCLI hung during shutdown (> 4.0s)!") + return False + + stop_duration = time.perf_counter() - t0 + print(f"--- Teardown completed in {stop_duration:.3f} seconds ---") + + if stop_duration > 1.5: + print(f"FAIL: Shutdown took too long ({stop_duration:.3f}s > 1.5s)") + return False + else: + print(f"PASS: Instant shutdown verified (< 1.5s)") + + if not os.path.exists(output_xdf): + print(f"FAIL: Output file '{output_xdf}' was not created!") + return False + + file_size_kb = os.path.getsize(output_xdf) / 1024.0 + print(f"--- Output XDF file size: {file_size_kb:.2f} KB ---") + + print(f"--- Validating XDF file with pyxdf ---") + try: + streams, header = pyxdf.load_xdf(output_xdf) + except Exception as e: + print(f"FAIL: pyxdf failed to load XDF: {e}") + return False + + if len(streams) != 2: + print(f"FAIL: Expected 2 streams in XDF, got {len(streams)}") + return False + + eeg_stream = next((s for s in streams if s["info"]["name"][0] == "TestEEG"), None) + if not eeg_stream: + print("FAIL: TestEEG stream not found in XDF") + return False + + if len(eeg_stream["time_series"]) == 0: + print("FAIL: TestEEG has 0 recorded samples!") + return False + + print(f"PASS: TestEEG has {len(eeg_stream['time_series'])} samples recorded.") + + # Check footer + if "footer" not in eeg_stream or eeg_stream["footer"]["info"] is None: + print("FAIL: TestEEG is missing footer info!") + return False + + print("PASS: Stream footers are present and valid.") + print("=== ALL INTEGRATION TESTS PASSED ===") + + # Cleanup + if os.path.exists(output_xdf): + os.remove(output_xdf) + + return True + + +if __name__ == "__main__": + parser = argparse.ArgumentParser(description="Test LabRecorder teardown and XDF validity") + parser.add_argument( + "--bin", + default="./build/install/bin/LabRecorderCLI", + help="Path to LabRecorderCLI binary", + ) + args = parser.parse_args() + success = run_test(args.bin) + sys.exit(0 if success else 1) From 54ffd28dc2068a677ec71c43a21a203848706424 Mon Sep 17 00:00:00 2001 From: Stefan Appelhoff Date: Sun, 20 Sep 2026 12:50:35 +0200 Subject: [PATCH 3/7] Bound every wait in recording teardown and stop dropping buffered samples Follow-up to the interruptible-teardown work, addressing review feedback. Shutdown flags are now published under the mutex that the condition variable predicates read them under. Setting an atomic outside that mutex and then notifying leaves a window in which a waiter that has just evaluated its predicate as false enters the wait and misses the notification, so the offset thread could still sleep out its full five-second interval. The blocking calls that a stop could not interrupt are now issued in short slices that observe the shutdown flag: - stream_inlet::info() was called twice with the default infinite timeout. close_stream() only stops the data receiver, so an unreachable metadata endpoint blocked a stop indefinitely. The info is now fetched once and reused for the header and the nominal rate. - open_stream() could hold a stop for up to max_open_wait. - time_correction() could hold it for the full query timeout. - The watchlist resolver blocked for a whole resolve_interval; it now resolves briefly and waits out the rest interruptibly. - The phase gates could park a stream for max_headers_wait with no way out, so a stream could lose its footer waiting for one that had hung. Joining is bounded for the first time: try_join_once() called std::thread::join(), which has no timeout, so polling it could never enforce max_join_wait. Threads are now paired with a future that becomes ready when the body returns, which can be waited on with a deadline. Closing the inlets the moment stop is pressed discards everything still buffered in them; a recording of 40 markers came back with 2. Inlets are now closed only after the stream threads have been given a grace period to drain and write their footers, and the transfer loop does a final non-blocking pull on the way out, so a stop no longer costs samples that had already arrived. Also fixed along the way: record_offsets() wrote uninitialised offset and timestamp values into the file when a time correction query timed out; the inlet bookkeeping leaked a registration on every exception path; and a stream that failed mid-recording was left without a footer although its header was already on disk. scripts/test_recording_teardown.py now covers a plain stop, a stop before the first sample, a stop while subscribing to a source that has gone away, repeated start/stop cycles, and that no buffered sample is lost. It checks the exit status and the footers of every stream, holds one stated teardown budget instead of documenting one and asserting another, and runs on all three platforms in CI. --- .github/workflows/build.yml | 36 ++- .gitignore | 1 + scripts/test_recording_teardown.py | 408 +++++++++++++++++++++----- src/recording.cpp | 454 +++++++++++++++++------------ src/recording.h | 118 +++++++- 5 files changed, 717 insertions(+), 300 deletions(-) diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 8b29136..6f5048e 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -38,10 +38,10 @@ jobs: fail-fast: false matrix: config: - - { name: "Ubuntu 22.04", os: ubuntu-22.04 } - - { name: "Ubuntu 24.04", os: ubuntu-24.04 } - - { name: "macOS", os: macos-14, cmake_extra: '-DCMAKE_OSX_ARCHITECTURES="x86_64;arm64"' } - - { name: "Windows", os: windows-latest } + - { name: "Ubuntu 22.04", os: ubuntu-22.04, cli: "install/bin/LabRecorderCLI" } + - { name: "Ubuntu 24.04", os: ubuntu-24.04, cli: "install/bin/LabRecorderCLI" } + - { name: "macOS", os: macos-14, cmake_extra: '-DCMAKE_OSX_ARCHITECTURES="x86_64;arm64"', cli: "install/LabRecorderCLI" } + - { name: "Windows", os: windows-latest, cli: "install/LabRecorderCLI.exe" } steps: - name: Checkout @@ -97,17 +97,27 @@ jobs: # ----------------------------------------------------------------------- # Test CLI # ----------------------------------------------------------------------- - - name: Test CLI (Linux) - if: runner.os == 'Linux' - run: ./install/bin/LabRecorderCLI --help || true + - name: Test CLI + shell: bash + run: ./${{ matrix.config.cli }} --help || true + + # ----------------------------------------------------------------------- + # Integration test: teardown latency and XDF integrity + # ----------------------------------------------------------------------- + - name: Set up Python + uses: actions/setup-python@v5 + with: + python-version: '3.12' - - name: Test CLI (macOS) - if: runner.os == 'macOS' - run: ./install/LabRecorderCLI --help || true + - name: Install integration test dependencies + run: python -m pip install --upgrade pip pylsl pyxdf - - name: Test CLI (Windows) - if: runner.os == 'Windows' - run: ./install/LabRecorderCLI.exe --help || true + # pylsl brings its own liblsl; it only has to speak the same wire protocol as the liblsl + # bundled with the recorder, not be the same build. Set PYLSL_LIB here if that ever stops + # holding. + - name: Test recording teardown + shell: bash + run: python scripts/test_recording_teardown.py --bin "${{ matrix.config.cli }}" # ----------------------------------------------------------------------- # Package diff --git a/.gitignore b/.gitignore index 2333b58..deafc5b 100644 --- a/.gitignore +++ b/.gitignore @@ -18,3 +18,4 @@ liblsl.deb install-qt.sh .DS_Store .codegraph/ +__pycache__/ diff --git a/scripts/test_recording_teardown.py b/scripts/test_recording_teardown.py index 209d112..43a62f2 100644 --- a/scripts/test_recording_teardown.py +++ b/scripts/test_recording_teardown.py @@ -1,121 +1,367 @@ #!/usr/bin/env python -""" -Automated integration test for LabRecorder teardown and XDF integrity. -Tests that LabRecorder stops cleanly and instantly (< 500 ms) and produces valid XDF footers. +"""Integration test for LabRecorderCLI teardown and XDF integrity. + +Starts LSL outlets, records them with LabRecorderCLI, stops the recording and checks that + +* the recorder exits within ``--max-stop`` seconds (1.0 s by default) and with status 0, +* every recorded stream has a stream footer whose sample count matches its data, +* pyxdf does not report the file as damaged, and +* nothing that was sent before the stop is missing from the file. + +The cases cover a plain stop, a stop before any sample arrives, a stop while the recorder is +still subscribing to a source that has gone away, and repeated start/stop cycles. + +Requires ``pylsl`` and ``pyxdf``. """ import argparse +import contextlib +import logging import os import subprocess import sys +import tempfile +import threading import time + import pylsl import pyxdf +EEG_NAME = "TeardownTestEEG" +MARKER_NAME = "TeardownTestMarkers" +NAMES = (EEG_NAME, MARKER_NAME) +EEG_CHANNELS = 8 +EEG_RATE = 100.0 -def run_test(cli_path, output_xdf="test_recording.xdf"): - if not os.path.exists(cli_path): - print(f"Error: LabRecorderCLI binary not found at '{cli_path}'") - return False +# time given to LSL to make a new outlet discoverable, and to flush the last samples over TCP +SETTLE = 0.5 - if os.path.exists(output_xdf): - os.remove(output_xdf) - print(f"--- Starting LSL test streams ---") - info_eeg = pylsl.StreamInfo("TestEEG", "EEG", 8, 100, "float32", "test_eeg_source_123") - outlet_eeg = pylsl.StreamOutlet(info_eeg) +class TestFailure(AssertionError): + """Raised when a case does not hold up.""" - info_marker = pylsl.StreamInfo("TestMarker", "Markers", 1, 0, "string", "test_marker_source_123") - outlet_marker = pylsl.StreamOutlet(info_marker) - time.sleep(0.5) +def check(condition, message): + if not condition: + raise TestFailure(message) - print(f"--- Launching LabRecorderCLI ({cli_path}) ---") - proc = subprocess.Popen( - [cli_path, output_xdf, "name='TestEEG'", "name='TestMarker'"], - stdin=subprocess.PIPE, - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - text=True, + +def make_outlets(): + """Create the EEG and marker outlets used by every case.""" + eeg_info = pylsl.StreamInfo( + EEG_NAME, "EEG", EEG_CHANNELS, EEG_RATE, "float32", "teardown_test_eeg" + ) + marker_info = pylsl.StreamInfo( + MARKER_NAME, "Markers", 1, pylsl.IRREGULAR_RATE, "string", "teardown_test_markers" ) + return pylsl.StreamOutlet(eeg_info), pylsl.StreamOutlet(marker_info) + + +class Recorder: + """A running LabRecorderCLI, with its output read as it appears. + + Reading the output as it appears is what lets a case wait for the recorder to actually be + collecting before it sends anything: an outlet does not replay what it pushed before the + recorder subscribed, so pushing too early silently loses samples. + """ + + def __init__(self, cli_path, xdf_path): + self._proc = subprocess.Popen( + [cli_path, xdf_path, f"name='{EEG_NAME}'", f"name='{MARKER_NAME}'"], + stdin=subprocess.PIPE, + stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, + text=True, + bufsize=1, + ) + self.lines = [] + self._reader = threading.Thread(target=self._read_output, daemon=True) + self._reader.start() - print(f"--- Streaming samples for 2 seconds ---") - start_time = time.time() - sample_val = 0.0 - while time.time() - start_time < 2.0: - outlet_eeg.push_sample([sample_val] * 8) - sample_val += 1.0 - time.sleep(0.01) + def _read_output(self): + for line in self._proc.stdout: + self.lines.append(line.rstrip()) - print(f"--- Triggering shutdown (Enter key to stdin) ---") - t0 = time.perf_counter() + def wait_for(self, needles, timeout=20.0): + """Block until every needle has shown up in the output.""" + deadline = time.time() + timeout + while time.time() < deadline: + joined = "\n".join(self.lines) + if all(needle in joined for needle in needles): + return + if self._proc.poll() is not None: + raise TestFailure( + f"LabRecorderCLI exited (status {self._proc.returncode}) before it was ready" + ) + time.sleep(0.02) + raise TestFailure(f"LabRecorderCLI did not report {needles!r} within {timeout} s") + + def wait_until_collecting(self): + self.wait_for([f"Started data collection for stream {name}." for name in NAMES]) + + def stop(self): + """Send the quit key and return how long the recorder took to exit.""" + started = time.perf_counter() + self._proc.stdin.write("\n") + self._proc.stdin.flush() + self._proc.stdin.close() + try: + # generously above any bound asserted on, so a hang is reported as a hang rather + # than as a timeout of this harness + self._proc.wait(timeout=30.0) + except subprocess.TimeoutExpired: + self._proc.kill() + self._proc.wait() + raise TestFailure("LabRecorderCLI did not exit within 30 s of the stop request") + duration = time.perf_counter() - started + self._reader.join(timeout=5.0) + check( + self._proc.returncode == 0, + f"LabRecorderCLI exited with status {self._proc.returncode}", + ) + return duration + + def terminate(self): + if self._proc.poll() is None: + self._proc.kill() + self._proc.wait() + + +@contextlib.contextmanager +def recorder(cli_path, xdf_path): + """Run LabRecorderCLI over both test streams, making sure it is gone afterwards.""" + rec = Recorder(cli_path, xdf_path) try: - stdout, stderr = proc.communicate(input="\n", timeout=4.0) - except subprocess.TimeoutExpired: - proc.kill() - print("FAIL: LabRecorderCLI hung during shutdown (> 4.0s)!") - return False + yield rec + finally: + rec.terminate() + for line in rec.lines: + print(f" | {line}") + - stop_duration = time.perf_counter() - t0 - print(f"--- Teardown completed in {stop_duration:.3f} seconds ---") +# pyxdf reports a damaged file through its logger rather than by raising, so these are the +# substrings that mark a load as failed. Other warnings (about jitter or clock offsets, say) say +# something about the data, not about the file being intact, and are only printed. +INTEGRITY_WARNINGS = ("footer", "truncat", "corrupt", "incomplete", "unexpected", "not parse") - if stop_duration > 1.5: - print(f"FAIL: Shutdown took too long ({stop_duration:.3f}s > 1.5s)") - return False - else: - print(f"PASS: Instant shutdown verified (< 1.5s)") - if not os.path.exists(output_xdf): - print(f"FAIL: Output file '{output_xdf}' was not created!") - return False +def load_xdf_strict(xdf_path): + """Load an XDF file and fail if pyxdf reports it as damaged.""" + records = [] - file_size_kb = os.path.getsize(output_xdf) / 1024.0 - print(f"--- Output XDF file size: {file_size_kb:.2f} KB ---") + class Collector(logging.Handler): + def emit(self, record): + records.append(record) - print(f"--- Validating XDF file with pyxdf ---") + handler = Collector(level=logging.WARNING) + logger = logging.getLogger("pyxdf") + logger.addHandler(handler) try: - streams, header = pyxdf.load_xdf(output_xdf) - except Exception as e: - print(f"FAIL: pyxdf failed to load XDF: {e}") - return False + streams, header = pyxdf.load_xdf(xdf_path) + finally: + logger.removeHandler(handler) - if len(streams) != 2: - print(f"FAIL: Expected 2 streams in XDF, got {len(streams)}") - return False + problems = [] + for record in records: + message = record.getMessage() + if record.levelno >= logging.ERROR or any( + marker in message.lower() for marker in INTEGRITY_WARNINGS + ): + problems.append(message) + else: + print(f" (pyxdf) {message}") + if problems: + raise TestFailure(f"pyxdf reported a damaged file: {'; '.join(problems)}") + return streams, header - eeg_stream = next((s for s in streams if s["info"]["name"][0] == "TestEEG"), None) - if not eeg_stream: - print("FAIL: TestEEG stream not found in XDF") - return False - if len(eeg_stream["time_series"]) == 0: - print("FAIL: TestEEG has 0 recorded samples!") - return False +def stream_by_name(streams, name): + for stream in streams: + if stream["info"]["name"][0] == name: + return stream + raise TestFailure(f"stream {name!r} is missing from the recording") - print(f"PASS: TestEEG has {len(eeg_stream['time_series'])} samples recorded.") - # Check footer - if "footer" not in eeg_stream or eeg_stream["footer"]["info"] is None: - print("FAIL: TestEEG is missing footer info!") - return False +def check_footer(stream): + """Check that a stream carries a footer consistent with its data.""" + name = stream["info"]["name"][0] + footer = stream.get("footer") + check(footer and footer.get("info"), f"stream {name!r} has no footer") - print("PASS: Stream footers are present and valid.") - print("=== ALL INTEGRATION TESTS PASSED ===") + info = footer["info"] + recorded = len(stream["time_series"]) + reported = int(info["sample_count"][0]) + check( + reported == recorded, + f"stream {name!r} footer claims {reported} samples but holds {recorded}", + ) + # these are written from the same footer and must be parseable for dejittering to work + float(info["first_timestamp"][0]) + float(info["last_timestamp"][0]) - # Cleanup - if os.path.exists(output_xdf): - os.remove(output_xdf) - return True +def check_stop(duration, max_stop): + print(f" teardown took {duration:.3f} s (budget {max_stop:.3f} s)") + check( + duration <= max_stop, + f"teardown took {duration:.3f} s, which is above the {max_stop:.3f} s budget", + ) -if __name__ == "__main__": - parser = argparse.ArgumentParser(description="Test LabRecorder teardown and XDF validity") +def push_eeg_for(outlet, seconds): + """Push EEG samples at the nominal rate for the given duration.""" + deadline = time.time() + seconds + value = 0.0 + while time.time() < deadline: + outlet.push_sample([value] * EEG_CHANNELS) + value += 1.0 + time.sleep(1.0 / EEG_RATE) + + +def case_normal_stop(cli_path, xdf_path, max_stop): + """Record both streams for two seconds, then stop.""" + eeg, markers = make_outlets() + time.sleep(SETTLE) + with recorder(cli_path, xdf_path) as rec: + rec.wait_until_collecting() + push_eeg_for(eeg, 2.0) + time.sleep(SETTLE) + duration = rec.stop() + + check_stop(duration, max_stop) + streams, _ = load_xdf_strict(xdf_path) + check(len(streams) == 2, f"expected 2 streams in the recording, got {len(streams)}") + + eeg_stream = stream_by_name(streams, EEG_NAME) + check(len(eeg_stream["time_series"]) > 0, "no EEG samples were recorded") + # the marker stream stays silent on purpose: a stream that never sends must still be + # closed out properly + check_footer(eeg_stream) + check_footer(stream_by_name(streams, MARKER_NAME)) + del eeg, markers + + +def case_stop_before_first_sample(cli_path, xdf_path, max_stop): + """Stop once the recorder is collecting but before either stream has sent anything.""" + eeg, markers = make_outlets() + time.sleep(SETTLE) + with recorder(cli_path, xdf_path) as rec: + rec.wait_until_collecting() + duration = rec.stop() + + check_stop(duration, max_stop) + streams, _ = load_xdf_strict(xdf_path) + check(len(streams) == 2, f"expected 2 streams in the recording, got {len(streams)}") + for name in NAMES: + stream = stream_by_name(streams, name) + check( + len(stream["time_series"]) == 0, + f"stream {name!r} recorded samples although none were sent", + ) + check_footer(stream) + del eeg, markers + + +def case_stop_while_subscribing(cli_path, xdf_path, max_stop): + """Stop while the recorder is still subscribing, so it is blocked on the network. + + The sources are dropped as soon as the recorder has found them, which leaves it waiting on + an endpoint that will never answer -- the case the data receiver alone cannot unblock. + """ + eeg, markers = make_outlets() + time.sleep(SETTLE) + with recorder(cli_path, xdf_path) as rec: + rec.wait_for([f"Found {name}" for name in NAMES]) + del eeg, markers + duration = rec.stop() + + check_stop(duration, max_stop) + # the file is checked for integrity, but not for content: how far the recorder got before + # the sources went away is timing dependent + load_xdf_strict(xdf_path) + + +def case_repeated_shutdown(cli_path, xdf_path, max_stop): + """Run three start/stop cycles, so leaked threads or stale state show up.""" + for cycle in range(3): + print(f" cycle {cycle + 1}/3") + case_normal_stop(cli_path, xdf_path, max_stop) + + +def case_no_buffered_samples_lost(cli_path, xdf_path, max_stop): + """Every marker pushed before the stop must end up in the file.""" + marker_count = 40 + eeg, markers = make_outlets() + time.sleep(SETTLE) + with recorder(cli_path, xdf_path) as rec: + rec.wait_until_collecting() + push_eeg_for(eeg, 1.0) + for i in range(marker_count): + markers.push_sample([f"marker-{i}"]) + # let the markers reach the recorder; whatever is still sitting in its inlet at the + # stop has to be drained rather than dropped + time.sleep(SETTLE) + duration = rec.stop() + + check_stop(duration, max_stop) + streams, _ = load_xdf_strict(xdf_path) + marker_stream = stream_by_name(streams, MARKER_NAME) + recorded = len(marker_stream["time_series"]) + check( + recorded == marker_count, + f"{marker_count} markers were sent but {recorded} were recorded", + ) + check_footer(marker_stream) + del eeg, markers + + +CASES = [ + ("normal stop", case_normal_stop), + ("stop before first sample", case_stop_before_first_sample), + ("stop while subscribing", case_stop_while_subscribing), + ("repeated shutdown", case_repeated_shutdown), + ("no buffered samples lost", case_no_buffered_samples_lost), +] + + +def main(): + parser = argparse.ArgumentParser(description=__doc__.splitlines()[0]) + parser.add_argument("--bin", required=True, help="path to the LabRecorderCLI binary") parser.add_argument( - "--bin", - default="./build/install/bin/LabRecorderCLI", - help="Path to LabRecorderCLI binary", + "--max-stop", + type=float, + default=1.0, + help="upper bound in seconds for how long teardown may take (default: %(default)s)", ) args = parser.parse_args() - success = run_test(args.bin) - sys.exit(0 if success else 1) + + if not os.path.exists(args.bin): + print(f"LabRecorderCLI binary not found at {args.bin!r}") + return 1 + # absolute, and with native separators: CreateProcess does not accept a relative path + # spelled with forward slashes + cli_path = os.path.abspath(args.bin) + + failures = [] + with tempfile.TemporaryDirectory() as workdir: + for name, case in CASES: + xdf_path = os.path.join(workdir, f"{name.replace(' ', '_')}.xdf") + print(f"--- {name} ---") + try: + case(cli_path, xdf_path, args.max_stop) + except TestFailure as exc: + print(f"FAIL: {name}: {exc}") + failures.append(name) + else: + print(f"PASS: {name}") + + print() + if failures: + print(f"{len(failures)}/{len(CASES)} cases failed: {', '.join(failures)}") + return 1 + print(f"all {len(CASES)} cases passed") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/src/recording.cpp b/src/recording.cpp index 74dcc4b..6548274 100644 --- a/src/recording.cpp +++ b/src/recording.cpp @@ -10,75 +10,81 @@ #include #endif +namespace { + +// time spent waiting between two resolves of a watchlist query; the resolve itself already takes +// resolve_timeout, so together they keep the resolve_interval cadence +const auto resolve_pause = std::chrono::duration_cast( + std::chrono::duration(resolve_interval - resolve_timeout)); + +/// convert a timeout given in seconds into a Clock duration +inline Clock::duration seconds_to_duration(double seconds) { + return std::chrono::duration_cast(std::chrono::duration(seconds)); +} + +} // namespace + // Thread utilities -using Clock = std::chrono::high_resolution_clock; /** - * @brief try_join_once joins and deconstructs the thread if possible - * @param thread unique_ptr to a std::tread. Will be reset on success - * @return true if the thread was successfully joined, false otherwise + * @brief timed_join Waits up to duration for the worker to finish, then joins it + * @param w unique_ptr to a worker. Will be reset on success + * @param duration max duration to wait + * @return true if the worker finished and was joined, false if it is still running */ -inline bool try_join_once(std::unique_ptr &thread) { - if (thread && thread->joinable()) { - thread->join(); - thread.reset(); - return true; - } - return false; +inline bool timed_join(worker_p &w, std::chrono::milliseconds duration = max_join_wait) { + if (!w) return true; + // wait on the future rather than calling join() directly: join() has no timeout, so a single + // call against a hung thread would never return and no deadline could be enforced + if (w->done.wait_for(duration) != std::future_status::ready) return false; + w->thread.join(); + w.reset(); + return true; } /** - * @brief timed_join Tries to join the passed thread until it succeeds or duration passes - * @param thread unique_ptr to a std::tread. Will be reset on success - * @param duration max duration to try joining - * @return true on success, false otherwise + * @brief timed_join_or_detach Join the worker or detach it if not possible within specified + * duration + * @param w unique_ptr to a worker. Will be reset either way + * @param duration max duration to wait */ -inline bool timed_join(thread_p &thread, std::chrono::milliseconds duration = max_join_wait) { - const auto start = Clock::now(); - while (Clock::now() - start < duration) { - if (try_join_once(thread)) return true; - std::this_thread::sleep_for(std::chrono::milliseconds(20)); +inline void timed_join_or_detach(worker_p &w, std::chrono::milliseconds duration = max_join_wait) { + if (!timed_join(w, duration)) { + w->thread.detach(); + w.reset(); + std::cerr << "Thread didn't join in time!" << std::endl; } - return false; } /** - * @brief timed_join_or_detach Join the thread or detach it if not possible within specified - * duration - * @param thread unique_ptr to a std::tread. Will be reset on success - * @param duration max duration to try joining + * @brief timed_join_some Join whichever workers finish within duration, leave the rest in place + * @param workers list of workers. Joined ones are erased from it + * @param duration duration to wait, shared across all workers */ -inline void timed_join_or_detach( - thread_p &thread, std::chrono::milliseconds duration = max_join_wait) { - if (!timed_join(thread, duration)) { - thread->detach(); - std::cerr << "Thread didn't join in time!" << std::endl; +inline void timed_join_some(std::list &workers, std::chrono::milliseconds duration) { + const auto deadline = Clock::now() + duration; + for (auto it = workers.begin(); it != workers.end();) { + const auto remaining = + std::chrono::duration_cast(deadline - Clock::now()); + if (timed_join(*it, std::max(remaining, std::chrono::milliseconds(0)))) + it = workers.erase(it); + else + ++it; } } /** - * @brief timed_join_or_detach Join the thread or detach it if not possible within specified - * duration - * @param threads list of unique_ptrs to std::threads. Guaranteed to be empty - * afterwards. - * @param duration duration to try joining + * @brief timed_join_or_detach Join the workers or detach those that don't finish in time + * @param workers list of workers. Guaranteed to be empty afterwards. + * @param duration duration to wait, shared across all workers */ inline void timed_join_or_detach( - std::list &threads, std::chrono::milliseconds duration = max_join_wait) { - const auto start = Clock::now(); - while (Clock::now() - start < duration && !threads.empty()) { - for (auto it = threads.begin(); it != threads.end();) { - if (try_join_once(*it)) - it = threads.erase(it); - else - ++it; - } - std::this_thread::sleep_for(std::chrono::milliseconds(20)); - } - if (!threads.empty()) { - std::cout << threads.size() << " stream threads still running!" << std::endl; - for (auto &t : threads) t->detach(); - threads.clear(); + std::list &workers, std::chrono::milliseconds duration = max_join_wait) { + timed_join_some(workers, duration); + if (!workers.empty()) { + std::cout << workers.size() << " stream threads still running!" << std::endl; + for (auto &w : workers) w->thread.detach(); + workers.clear(); } } @@ -91,86 +97,147 @@ recording::recording(const std::string &filename, const std::vector(&recording::record_boundaries, this); + boundary_thread_ = spawn_worker([this] { record_boundaries(); }); } recording::~recording() { try { - // set the shutdown flag (from now on no more new streams) - shutdown_ = true; - shutdown_cv_.notify_all(); - - // close all inlets to unblock any pending network I/O immediately - { - std::lock_guard lock(inlets_mut_); - for (auto &in : active_inlets_) { - if (in) { - try { in->close_stream(); } catch (...) {} - } - } - } - - // stop the threads - timed_join_or_detach(stream_threads_, max_join_wait); - if (!timed_join(boundary_thread_, max_join_wait)) { - std::cout << "boundary_thread didn't finish in time!" << std::endl; - boundary_thread_->detach(); + // set the shutdown flag (from now on no more new streams) and wake every waiting thread + requestStop(); + + // give the stream threads a moment to drain their inlets and write their footers by + // themselves; closing an inlet discards what it still holds, so that is a last resort + timed_join_some(stream_threads_, teardown_grace); + if (!stream_threads_.empty()) { + // a thread is stuck in a blocking socket call; closing its inlet aborts that call + close_active_inlets(); + timed_join_or_detach(stream_threads_, max_join_wait); } + timed_join_or_detach(boundary_thread_, max_join_wait); std::cout << "Closing the file." << std::endl; } catch (std::exception &e) { std::cout << "Error while closing the recording: " << e.what() << std::endl; } } -void recording::requestStop() noexcept -{ - shutdown_ = true; +void recording::requestStop() noexcept { + { + // publish the flag under the mutex that the shutdown_cv_ predicates read it under: a + // waiter that has just evaluated its predicate as false would otherwise miss the + // notification below and sleep out its full interval + std::lock_guard lock(shutdown_mut_); + shutdown_ = true; + } shutdown_cv_.notify_all(); + + // the phase gates test shutdown_ under phase_mut_, so take and release it for the same reason + { std::lock_guard lock(phase_mut_); } + ready_for_streaming_.notify_all(); + ready_for_footers_.notify_all(); +} + +bool recording::wait_until_shutdown(Clock::time_point deadline, const std::atomic *extra) { + std::unique_lock lock(shutdown_mut_); + return shutdown_cv_.wait_until( + lock, deadline, [this, extra] { return shutdown_.load() || (extra && extra->load()); }); +} + +void recording::stop_offsets(const offset_flag_p &offset_shutdown) noexcept { { - std::lock_guard lock(inlets_mut_); - for (auto &in : active_inlets_) { - if (in) { - try { in->close_stream(); } catch (...) {} - } + std::lock_guard lock(shutdown_mut_); + *offset_shutdown = true; + } + shutdown_cv_.notify_all(); +} + +void recording::register_inlet(const inlet_p &in) { + std::lock_guard lock(inlets_mut_); + active_inlets_.push_back(in); +} + +void recording::unregister_inlet(const inlet_p &in) noexcept { + if (!in) return; + std::lock_guard lock(inlets_mut_); + active_inlets_.erase( + std::remove(active_inlets_.begin(), active_inlets_.end(), in), active_inlets_.end()); +} + +void recording::close_active_inlets() noexcept { + std::lock_guard lock(inlets_mut_); + for (auto &in : active_inlets_) { + try { + in->close_stream(); + } catch (std::exception &e) { + std::cerr << "Error while closing an inlet: " << e.what() << std::endl; } } } +bool recording::open_inlet(const inlet_p &in) { + // subscribe in short slices: a single open_stream(max_open_wait) would keep us from noticing a + // stop for up to max_open_wait seconds + const auto deadline = Clock::now() + seconds_to_duration(max_open_wait); + while (Clock::now() < deadline && !shutdown_) { + try { + in->open_stream(network_poll_interval); + return true; + } catch (lsl::timeout_error &) {} + } + return false; +} + +lsl::stream_info recording::fetch_info(const inlet_p &in) { + // the metadata receiver is separate from the data receiver, so close_stream() does not abort + // this call; poll in short slices instead, or an unreachable source blocks us indefinitely. + // A stop does not cut this off immediately: a source that is still reachable gets a short + // grace period, so its header (and with it its footer) still makes it into the file. + auto deadline = Clock::time_point::max(); + while (Clock::now() < deadline) { + if (shutdown_ && deadline == Clock::time_point::max()) + deadline = Clock::now() + teardown_grace; + try { + return in->info(network_poll_interval); + } catch (lsl::timeout_error &) {} + } + throw shutdown_requested("stopped while retrieving the stream metadata"); +} + void recording::record_from_query_results(const std::string &query) { try { std::set known_uids; // set of previously seen stream uid's std::set known_source_ids; // set of previously seen source id's - std::list threads; // our spawned threads + std::list threads; // our spawned threads std::cout << "Watching for a stream with properties " << query << std::endl; while (!shutdown_) { - // periodically re-resolve the query - const std::vector results = lsl::resolve_stream(query, 0, resolve_interval); + // periodically re-resolve the query. The resolve itself is kept short and the rest of + // the interval is spent in an interruptible wait, so a stop is noticed quickly. + const std::vector results = + lsl::resolve_stream(query, 0, resolve_timeout); // for each result... for (const auto &result : results) { // if it is a new stream... - std::string _uid = result.uid(); - std::string _src_id = result.source_id(); if (!known_uids.count(result.uid())) // and doesn't have a previously seen source id... if (!result.source_id().empty() && - (!known_source_ids.count(result.source_id()))) { + (!known_source_ids.count(result.source_id()))) { std::cout << "Found a new stream named " << result.name() << ", adding it to the recording." << std::endl; // start a new recording thread - threads.emplace_back(new std::thread( - &recording::record_from_streaminfo, this, result, false)); + threads.emplace_back(spawn_worker( + [this, result] { record_from_streaminfo(result, false); })); // ... and add it to the lists of known id's known_uids.insert(result.uid()); if (!result.source_id().empty()) known_source_ids.insert(result.source_id()); } } + if (wait_for_shutdown(resolve_pause)) break; } // wait for all our threads to join timed_join_or_detach(threads, max_join_wait); @@ -180,39 +247,38 @@ void recording::record_from_query_results(const std::string &query) { } void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_locked) { + inlet_p in; try { - double first_timestamp, last_timestamp; + // initialised here because a stream that fails mid-recording still writes a footer + double first_timestamp = 0.0, last_timestamp = 0.0; uint64_t sample_count = 0; + double nominal_srate = 0; // obtain a fresh streamid streamid_t streamid = fresh_streamid(); - inlet_p in; - // --- headers phase try { enter_headers_phase(phase_locked); // open an inlet to read from (and subscribe to data immediately) - in.reset(new lsl::stream_inlet(src)); - { - std::lock_guard lock(inlets_mut_); - active_inlets_.push_back(in); - } + in = std::make_shared(src); + register_inlet(in); auto it = sync_options_by_stream_.find(src.name() + " (" + src.hostname() + ")"); if (it != sync_options_by_stream_.end()) in->set_postprocessing(it->second); - try { - in->open_stream(max_open_wait); + if (open_inlet(in)) std::cout << "Opened the stream " << src.name() << "." << std::endl; - } catch (lsl::timeout_error &) { + else if (!shutdown_) std::cout << "Subscribing to the stream " << src.name() << " is taking relatively long; collection from this stream will be delayed." << std::endl; - } - // retrieve the stream header & get its XML version - file_.write_stream_header(streamid, in->info().as_xml()); + // retrieve the stream header & get its XML version. The nominal rate is taken from + // the same info, saving a second round trip to the source. + const lsl::stream_info info = fetch_info(in); + nominal_srate = info.nominal_srate(); + file_.write_stream_header(streamid, info.as_xml()); std::cout << "Received header for stream " << src.name() << "." << std::endl; leave_headers_phase(phase_locked); @@ -232,33 +298,31 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l enter_streaming_phase(phase_locked); std::cout << "Started data collection for stream " << src.name() << "." << std::endl; - const double nominal_srate = in->info().nominal_srate(); - // now write the actual sample chunks... switch (src.channel_format()) { case lsl::cf_int8: - typed_transfer_loop(streamid, nominal_srate, in, first_timestamp, - last_timestamp, sample_count); + typed_transfer_loop( + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); break; case lsl::cf_int16: - typed_transfer_loop(streamid, nominal_srate, in, first_timestamp, - last_timestamp, sample_count); + typed_transfer_loop( + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); break; case lsl::cf_int32: - typed_transfer_loop(streamid, nominal_srate, in, first_timestamp, - last_timestamp, sample_count); + typed_transfer_loop( + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); break; case lsl::cf_float32: - typed_transfer_loop(streamid, nominal_srate, in, first_timestamp, - last_timestamp, sample_count); + typed_transfer_loop( + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); break; case lsl::cf_double64: - typed_transfer_loop(streamid, nominal_srate, in, first_timestamp, - last_timestamp, sample_count); + typed_transfer_loop( + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); break; case lsl::cf_string: - typed_transfer_loop(streamid, nominal_srate, in, - first_timestamp, last_timestamp, sample_count); + typed_transfer_loop( + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); break; default: // unsupported channel format @@ -267,9 +331,12 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l } leave_streaming_phase(phase_locked); - } catch (std::exception &) { + } catch (std::exception &e) { leave_streaming_phase(phase_locked); - throw; + // the header is already on disk, so fall through to the footer instead of leaving the + // stream without one + std::cerr << "Error while recording from " << src.name() << ": " << e.what() + << std::endl; } // --- footers phase @@ -301,34 +368,19 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l leave_footers_phase(phase_locked); throw; } - if (in) { - std::lock_guard lock(inlets_mut_); - active_inlets_.erase( - std::remove(active_inlets_.begin(), active_inlets_.end(), in), - active_inlets_.end()); - } + } catch (shutdown_requested &e) { + std::cout << "Recording from " << src.name() << " ended: " << e.what() << std::endl; } catch (std::exception &e) { std::cout << "Error in the record_from_streaminfo thread: " << e.what() << std::endl; } + unregister_inlet(in); } void recording::record_boundaries() { try { - auto next_boundary = Clock::now() + boundary_interval; while (!shutdown_) { - { - std::unique_lock cv_lock(shutdown_mut_); - if (shutdown_cv_.wait_for(cv_lock, std::chrono::milliseconds(500), [this] { - return shutdown_.load(); - })) { - break; - } - } - - if (Clock::now() > next_boundary) { - file_.write_boundary_chunk(); - next_boundary = Clock::now() + boundary_interval; - } + if (wait_for_shutdown(boundary_interval)) break; + file_.write_boundary_chunk(); } } catch (std::exception &e) { std::cout << "Error in the record_boundaries thread: " << e.what() << std::endl; @@ -336,32 +388,34 @@ void recording::record_boundaries() { } void recording::record_offsets( - streamid_t streamid, const inlet_p &in, std::atomic &offset_shutdown) noexcept { + streamid_t streamid, inlet_p in, offset_flag_p offset_shutdown) noexcept { try { - while (!shutdown_ && !offset_shutdown) { + while (!shutdown_ && !*offset_shutdown) { // sleep for the interval - { - std::unique_lock cv_lock(shutdown_mut_); - if (shutdown_cv_.wait_for(cv_lock, offset_interval, [this, &offset_shutdown] { - return shutdown_.load() || offset_shutdown.load(); - })) { + if (wait_for_shutdown(offset_interval, offset_shutdown.get())) break; + + // query the time offset, again in short slices so that a stop is noticed promptly + double offset = 0, now = 0; + bool have_offset = false; + const auto deadline = Clock::now() + max_time_correction_wait; + while (!shutdown_ && !*offset_shutdown && Clock::now() < deadline) { + try { + offset = in->time_correction(network_poll_interval); + now = lsl::local_clock(); + have_offset = true; break; - } + } catch (lsl::timeout_error &) {} } - - // query the time offset - double offset, now; - try { - offset = in->time_correction(2); - now = lsl::local_clock(); - } catch (lsl::timeout_error &) { + if (!have_offset) { + if (shutdown_ || *offset_shutdown) break; std::cerr << "Timeout in time correction query for stream " << streamid << std::endl; + continue; } - if (shutdown_ || offset_shutdown) break; + file_.write_stream_offset(streamid, now, offset); // also append to the offset lists - std::lock_guard offset_lock(offset_mut_); + std::lock_guard lock(offset_mut_); offset_lists_[streamid].emplace_back(now - offset, offset); } } catch (std::exception &e) { @@ -389,8 +443,11 @@ void recording::leave_headers_phase(bool phase_locked) { void recording::enter_streaming_phase(bool phase_locked) { if (phase_locked) { std::unique_lock lock(phase_mut_); - ready_for_streaming_.wait_for( - lock, max_headers_wait, [this]() { return this->ready_for_streaming(); }); + // on shutdown the gate is dropped: the transfer loop exits immediately anyway, and waiting + // out max_headers_wait for a stream that is never going to report in only delays the + // footer of this one + ready_for_streaming_.wait_for(lock, max_headers_wait, + [this]() { return this->ready_for_streaming() || shutdown_.load(); }); streaming_to_finish_++; } } @@ -407,8 +464,9 @@ void recording::leave_streaming_phase(bool phase_locked) { void recording::enter_footers_phase(bool phase_locked) { if (phase_locked) { std::unique_lock lock(phase_mut_); - ready_for_footers_.wait_for( - lock, max_footers_wait, [this]() { return this->ready_for_footers(); }); + // see enter_streaming_phase: a footer written slightly out of order beats no footer at all + ready_for_footers_.wait_for(lock, max_footers_wait, + [this]() { return this->ready_for_footers() || shutdown_.load(); }); } } @@ -416,10 +474,12 @@ template void recording::typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, double &first_timestamp, double &last_timestamp, uint64_t &sample_count) { // optionally start an offset collection thread for this stream - std::atomic offset_shutdown{false}; - thread_p offset_thread(offsets_enabled_ ? new std::thread(&recording::record_offsets, this, - streamid, in, std::ref(offset_shutdown)) - : nullptr); + auto offset_shutdown = std::make_shared>(false); + worker_p offset_thread(offsets_enabled_ + ? spawn_worker([this, streamid, in, offset_shutdown] { + record_offsets(streamid, in, offset_shutdown); + }) + : nullptr); try { double sample_interval = srate ? 1.0 / srate : 0; @@ -427,21 +487,9 @@ void recording::typed_transfer_loop(streamid_t streamid, double srate, const inl std::vector chunk; std::vector timestamps; - // Pull the first sample - first_timestamp = 0.0; - while(!shutdown_ && first_timestamp == 0.0) - first_timestamp = last_timestamp = in->pull_sample(chunk, 0.1); - if (!shutdown_ && first_timestamp != 0.0) { - timestamps.push_back(first_timestamp); - file_.write_data_chunk(streamid, timestamps, chunk, (uint32_t)in->get_channel_count()); - sample_count += timestamps.size(); - } - - auto next_pull = Clock::now(); - while (!shutdown_) { - // get a chunk from the stream - in->pull_chunk_multiplexed(chunk, ×tamps, 1e-6); - // for each sample... + // deduce the timestamps that can be deduced and write the chunk out + auto write_chunk = [&] { + if (timestamps.empty()) return; for (double &ts : timestamps) { // if the time stamp can be deduced from the previous one... if (last_timestamp + sample_interval == ts) { @@ -450,26 +498,48 @@ void recording::typed_transfer_loop(streamid_t streamid, double srate, const inl } else last_timestamp = ts; } - // write the actual chunk - if (!timestamps.empty()) { - file_.write_data_chunk(streamid, timestamps, chunk, in->get_channel_count()); - sample_count += timestamps.size(); - } + file_.write_data_chunk(streamid, timestamps, chunk, in->get_channel_count()); + sample_count += timestamps.size(); + }; + // Pull the first sample + first_timestamp = 0.0; + while (!shutdown_ && first_timestamp == 0.0) + first_timestamp = last_timestamp = in->pull_sample(chunk, network_poll_interval); + if (first_timestamp != 0.0) { + // written directly: the very first sample anchors the stream and must keep its + // timestamp even when the nominal interval is zero + timestamps.assign(1, first_timestamp); + file_.write_data_chunk(streamid, timestamps, chunk, (uint32_t)in->get_channel_count()); + sample_count += timestamps.size(); + } + + auto next_pull = Clock::now() + chunk_interval; + while (!shutdown_) { + // get a chunk from the stream + in->pull_chunk_multiplexed(chunk, ×tamps, 1e-6); + write_chunk(); + if (wait_until_shutdown(next_pull)) break; next_pull += chunk_interval; - std::unique_lock cv_lock(shutdown_mut_); - if (shutdown_cv_.wait_until(cv_lock, next_pull, [this] { return shutdown_.load(); })) { - break; + } + + if (first_timestamp != 0.0) { + // one final non-blocking pull, so that samples already buffered in the inlet when the + // stop arrived end up in the file rather than being dropped + try { + in->pull_chunk_multiplexed(chunk, ×tamps, 0.0); + write_chunk(); + } catch (std::exception &e) { + // the inlet was closed under us during teardown; the footer matters more + std::cerr << "Could not drain stream " << streamid << " on stop: " << e.what() + << std::endl; } } - } catch (std::exception &e) { - std::cerr << "Error in transfer thread: " << e.what() << std::endl; - offset_shutdown = true; - shutdown_cv_.notify_all(); + } catch (std::exception &) { + stop_offsets(offset_shutdown); timed_join_or_detach(offset_thread); throw; } - offset_shutdown = true; - shutdown_cv_.notify_all(); + stop_offsets(offset_shutdown); timed_join_or_detach(offset_thread); } diff --git a/src/recording.h b/src/recording.h index 56fb4fc..9b63da2 100644 --- a/src/recording.h +++ b/src/recording.h @@ -5,13 +5,18 @@ #include #include #include +#include #include #include #include #include +#include #include +#include +#include #include #include +#include // timings in the recording process (e.g., rate of boundary chunks and for cases where a stream // hangs) approx. interval between boundary chunks @@ -20,6 +25,9 @@ const auto boundary_interval = std::chrono::seconds(10); const auto offset_interval = std::chrono::seconds(5); // approx. interval between resolves for outstanding streams on the watchlist, in seconds const double resolve_interval = 5; +// timeout of a single resolve attempt, in seconds; the rest of resolve_interval is spent in an +// interruptible wait so that a shutdown request need not wait out a resolve +const double resolve_timeout = 1; // approx. interval between pulling chunks from outlets const auto chunk_interval = std::chrono::milliseconds(500); // maximum waiting time for moving past the headers phase while recording @@ -29,15 +37,59 @@ const auto max_footers_wait = std::chrono::seconds(2); // maximum waiting time for subscribing to a stream, in seconds (if exceeded, stream subscription // will take place later) const double max_open_wait = 5; +// maximum waiting time for a single time correction query +const auto max_time_correction_wait = std::chrono::seconds(2); +// blocking network calls are issued in slices of this length (in seconds) so that a shutdown +// request is noticed promptly instead of after the full timeout +const double network_poll_interval = 0.2; +// time granted to the stream threads to drain their inlets and write their footers before the +// inlets are forcibly closed +const auto teardown_grace = std::chrono::milliseconds(300); // maximum time that we wait to join a thread const auto max_join_wait = std::chrono::seconds(2); +// steady_clock (not high_resolution_clock, which is an alias for the wall clock in some standard +// libraries) so that waits are unaffected by clock adjustments +using Clock = std::chrono::steady_clock; + using streamid_t = uint32_t; -// pointer to a thread -using thread_p = std::unique_ptr; +/// thrown by the interruptible helpers when the recording is being torn down +class shutdown_requested : public std::runtime_error { +public: + explicit shutdown_requested(const std::string &what) : std::runtime_error(what) {} +}; + +/** + * A thread paired with a future that becomes ready once the thread body has returned. + * + * std::thread::join() blocks indefinitely, so polling it cannot enforce a deadline: a single call + * against a hung thread never comes back. The future can be waited on with a timeout, and only + * once it is ready do we join (which then returns promptly). A std::packaged_task future is used + * rather than std::async because the latter blocks in its future destructor. + */ +struct worker { + std::thread thread; + std::future done; +}; +// pointer to a worker thread +using worker_p = std::unique_ptr; + +/// start a worker thread running fn +template worker_p spawn_worker(F &&fn) { + auto task = std::make_shared>(std::forward(fn)); + auto w = std::make_unique(); + w->done = task->get_future(); + // the task is kept alive by the lambda, so the worker may be detached safely + w->thread = std::thread([task] { (*task)(); }); + return w; +} + // pointer to a stream inlet using inlet_p = std::shared_ptr; +// pointer to a per-stream flag asking that stream's offset thread to finish. Shared rather than +// referenced so that an offset thread which had to be detached cannot outlive its flag. +using offset_flag_p = std::shared_ptr>; // a list of clock offset estimates (time,value) using offset_list = std::list>; // a map from streamid to offset_list @@ -55,11 +107,11 @@ class recording { /** * Construct a new background recording process. * @param filename The file name to record to (should end in .xdf). - * @param streams An array of LSL streaminfo's that identify the set of streams to record into + * @param streams An array of LSL streaminfos that identify the set of streams to record into *the file. * @param watchfor An optional "watchlist" of LSL query predicates (see lsl::resolve_bypred) to *resolve streams to record from. This can be a specific stream that you know should be recorded - *but is not yet online, or a more generic query (e.g., "record from everything that's out + *but is not yet online, or a more generic query (e.g., "record from everything that is out *there"). * @param collect_offsets Whether to collect time offset measurements periodically. */ @@ -72,6 +124,8 @@ class recording { */ ~recording(); + /// Ask all recording threads to wrap up. Returns immediately; the threads are joined by the + /// destructor. void requestStop() noexcept; private: @@ -86,11 +140,11 @@ class recording { std::atomic streamid_; // the highest streamid allocated so far // phase-of-recording state (headers, streaming data, or footers) - std::atomic shutdown_; // whether we are trying to shut down - std::condition_variable shutdown_cv_; // condition variable to wake threads immediately on shutdown - std::mutex shutdown_mut_; // mutex for shutdown condition variable - std::vector active_inlets_; // active inlets to abort on teardown - std::mutex inlets_mut_; // mutex to protect active inlets list + std::atomic shutdown_; // whether we are trying to shut down + std::condition_variable + shutdown_cv_; // signals shutdown so that every interruptible wait returns at once + std::mutex shutdown_mut_; // protects publication of shutdown_ and of the per-stream offset + // shutdown flags, which the shutdown_cv_ predicates read under it uint32_t headers_to_finish_; // the number of streams that still need to write their header // (i.e., are not yet ready to write streaming content) uint32_t streaming_to_finish_; // the number of streams that still need to finish the streaming @@ -103,14 +157,19 @@ class recording { // recording jobs and are now ready to write a footer std::mutex phase_mut_; // a mutex to protect the phase state + // inlets with potentially pending network I/O, to be aborted if their thread does not stop in + // time + std::vector active_inlets_; + std::mutex inlets_mut_; // a mutex to protect the active inlet list + // data structure to collect the time offsets for every stream offset_lists offset_lists_; // the clock offset lists for each stream (to be written into the footer) std::mutex offset_mut_; // a mutex to protect the offset lists // data for shutdown / final joining - std::list stream_threads_; // the spawned stream handling threads - thread_p boundary_thread_; // the spawned boundary-recording thread + std::list stream_threads_; // the spawned stream handling threads + worker_p boundary_thread_; // the spawned boundary-recording thread // for enabling online sync options std::map sync_options_by_stream_; @@ -135,7 +194,7 @@ class recording { // record ClockOffset chunks from a given stream void record_offsets( - streamid_t streamid, const inlet_p &in, std::atomic &offset_shutdown) noexcept; + streamid_t streamid, inlet_p in, offset_flag_p offset_shutdown) noexcept; // sample collection loop for a numeric stream @@ -143,6 +202,37 @@ class recording { void typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, double &first_timestamp, double &last_timestamp, uint64_t &sample_count); + // === interruptible waiting & bounded network calls === + + /// wait until deadline, returning true if the wait was cut short by a shutdown request + /// @param extra an optional additional flag (e.g. a per-stream offset shutdown) that also ends + /// the wait + bool wait_until_shutdown(Clock::time_point deadline, const std::atomic *extra = nullptr); + + /// wait for timeout, returning true if the wait was cut short by a shutdown request + bool wait_for_shutdown(Clock::duration timeout, const std::atomic *extra = nullptr) { + return wait_until_shutdown(Clock::now() + timeout, extra); + } + + /// publish a per-stream offset shutdown flag and wake the corresponding offset thread + void stop_offsets(const offset_flag_p &offset_shutdown) noexcept; + + /// subscribe to a stream, giving up after max_open_wait + /// @return whether the subscription completed (if not, it will take place later) + /// @throws shutdown_requested if the recording was stopped while subscribing + bool open_inlet(const inlet_p &in); + + /// retrieve the full stream info, including the extended description + /// @throws shutdown_requested if the recording was stopped while retrieving the metadata + lsl::stream_info fetch_info(const inlet_p &in); + + // === inlet bookkeeping === + + void register_inlet(const inlet_p &in); + void unregister_inlet(const inlet_p &in) noexcept; + /// close every registered inlet, aborting any blocking socket call in progress + void close_active_inlets() noexcept; + // === phase registration & condition checks === // writing is coordinated across threads in three phases to keep the file chunks sorted @@ -159,9 +249,9 @@ class recording { void leave_footers_phase(bool) { /* Nothing to do. Ignore warning. */ } - /// a condition that indicates that we're ready to write streaming content into the file + /// a condition that indicates that we are ready to write streaming content into the file bool ready_for_streaming() const { return headers_to_finish_ <= 0; } - /// a condition that indicates that we're ready to write footers into the file + /// a condition that indicates that we are ready to write footers into the file bool ready_for_footers() const { return streaming_to_finish_ <= 0 && headers_to_finish_ <= 0; } /// allocate a fresh stream id From c81229299bc689d5404f7d2604133e6d9f467b3f Mon Sep 17 00:00:00 2001 From: Stefan Appelhoff Date: Sun, 20 Sep 2026 21:25:36 +0200 Subject: [PATCH 4/7] Keep recording state alive for threads that outlive teardown, and drain a gated stream Addresses the second round of review on the teardown work. The future-based join added in the previous commit is the first version that can actually reach the detach path, because the blocking join() it replaced never returned for a hung thread. Detached threads ran on a raw `this` and wrote into the file, the mutexes and the offset lists, all of which the destructor had already destroyed. Recording state and the thread bodies now live in a shared implementation object that every thread holds a reference to, so the state outlives a teardown that had to leave a thread running, and the last one to finish closes the file. A harness that stalls a stream thread past the join deadline faults with an access violation and writes no footer before this change, and exits cleanly with both footers intact after it. The gate that lets a stream wait for another stream's header is released on shutdown, which meant a stream could reach its transfer loop with the shutdown already set, pull no first sample, and then skip the final drain because it had no first timestamp to compare against -- writing a zero-sample footer although its inlet had been subscribed and buffering the whole time. The first sample now anchors the stream wherever it arrives from, including from the drain, and the drain is unconditional. Two things found while testing this: Splitting the time correction query into network_poll_interval slices was unsound: the query needs a round trip to complete, so restarting it every 200 ms means it need never finish. It goes back to a single call with the full budget, as before the teardown work. Teardown stays bounded because the transfer thread now stops waiting for the offset thread after the teardown grace period and leaves it running, which is safe now that a thread left running keeps its state alive. Recording threads all logged through unsynchronised << chains, so their output interleaved mid-line. Lines are now composed and written under a mutex. scripts/test_recording_teardown.py gains a case for the gated stream: it holds one stream at the headers gate behind another whose source has gone away, buffers 40 samples into it and stops. Before the drain fix that case records 0 of 40. --- scripts/test_recording_teardown.py | 72 ++++- src/clirecorder.cpp | 2 + src/recording.cpp | 460 +++++++++++++++++++++++------ src/recording.h | 226 +------------- 4 files changed, 443 insertions(+), 317 deletions(-) diff --git a/scripts/test_recording_teardown.py b/scripts/test_recording_teardown.py index 43a62f2..aa0ceee 100644 --- a/scripts/test_recording_teardown.py +++ b/scripts/test_recording_teardown.py @@ -65,9 +65,12 @@ class Recorder: recorder subscribed, so pushing too early silently loses samples. """ - def __init__(self, cli_path, xdf_path): + def __init__(self, cli_path, xdf_path, stream_order=NAMES): + # the recorder spawns one thread per stream in the order given here, and each thread + # registers with the headers phase as it starts. A case that needs one stream to be held + # at the headers-to-streaming gate by another therefore has to control this order. self._proc = subprocess.Popen( - [cli_path, xdf_path, f"name='{EEG_NAME}'", f"name='{MARKER_NAME}'"], + [cli_path, xdf_path] + [f"name='{name}'" for name in stream_order], stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, @@ -99,6 +102,9 @@ def wait_for(self, needles, timeout=20.0): def wait_until_collecting(self): self.wait_for([f"Started data collection for stream {name}." for name in NAMES]) + def saw(self, needle): + return needle in "\n".join(self.lines) + def stop(self): """Send the quit key and return how long the recorder took to exit.""" started = time.perf_counter() @@ -128,9 +134,9 @@ def terminate(self): @contextlib.contextmanager -def recorder(cli_path, xdf_path): +def recorder(cli_path, xdf_path, stream_order=NAMES): """Run LabRecorderCLI over both test streams, making sure it is gone afterwards.""" - rec = Recorder(cli_path, xdf_path) + rec = Recorder(cli_path, xdf_path, stream_order) try: yield rec finally: @@ -218,6 +224,13 @@ def push_eeg_for(outlet, seconds): time.sleep(1.0 / EEG_RATE) +def push_eeg_samples(outlet, count): + """Push exactly count EEG samples at the nominal rate.""" + for value in range(count): + outlet.push_sample([float(value)] * EEG_CHANNELS) + time.sleep(1.0 / EEG_RATE) + + def case_normal_stop(cli_path, xdf_path, max_stop): """Record both streams for two seconds, then stop.""" eeg, markers = make_outlets() @@ -315,12 +328,63 @@ def case_no_buffered_samples_lost(cli_path, xdf_path, max_stop): del eeg, markers +def case_gated_stream_is_drained(cli_path, xdf_path, max_stop): + """A stream held at the headers gate must still write what its inlet buffered. + + A stream that is through its own header waits for every other stream's header before it may + write data. If a stop arrives while it waits there, it reaches its transfer loop with the + shutdown already set and never pulls a first sample -- but its inlet has been subscribed and + buffering the whole time, so that data has to be drained on the way out. + + The marker stream is listed first so its thread registers with the headers phase before the + EEG thread can leave it, then it is taken away so its header never arrives and the EEG thread + stays at the gate. + """ + sample_count = 40 + eeg, markers = make_outlets() + time.sleep(SETTLE) + with recorder(cli_path, xdf_path, stream_order=(MARKER_NAME, EEG_NAME)) as rec: + # The recorder resolves for a second before it opens anything, so the marker outlet has + # to survive long enough to be resolved and be gone before its metadata is fetched. + # Waiting for the "Found" line instead would be too late: it is printed when the resolve + # returns, microseconds before the inlets are opened. + time.sleep(0.6) + del markers + rec.wait_for([f"Found {name}" for name in NAMES]) + rec.wait_for([f"Received header for stream {EEG_NAME}."]) + check( + not rec.saw(f"Started data collection for stream {EEG_NAME}."), + "precondition not met: the EEG stream was not held at the headers gate" + + ( + " (the marker header arrived before its outlet was removed)" + if rec.saw(f"Received header for stream {MARKER_NAME}.") + else "" + ), + ) + + push_eeg_samples(eeg, sample_count) + time.sleep(SETTLE) + duration = rec.stop() + + check_stop(duration, max_stop) + streams, _ = load_xdf_strict(xdf_path) + eeg_stream = stream_by_name(streams, EEG_NAME) + recorded = len(eeg_stream["time_series"]) + check( + recorded == sample_count, + f"{sample_count} samples were buffered at the gate but {recorded} were recorded", + ) + check_footer(eeg_stream) + del eeg + + CASES = [ ("normal stop", case_normal_stop), ("stop before first sample", case_stop_before_first_sample), ("stop while subscribing", case_stop_while_subscribing), ("repeated shutdown", case_repeated_shutdown), ("no buffered samples lost", case_no_buffered_samples_lost), + ("gated stream is drained", case_gated_stream_is_drained), ] diff --git a/src/clirecorder.cpp b/src/clirecorder.cpp index 59e3736..55772fa 100644 --- a/src/clirecorder.cpp +++ b/src/clirecorder.cpp @@ -1,6 +1,8 @@ #include "recording.h" #include "xdfwriter.h" +#include + int main(int argc, char **argv) { if (argc < 3 || (argc == 2 && std::string(argv[1]) == "-h")) { std::cout << "Usage: " << argv[0] << " outputfile.xdf 'searchstr' ['searchstr2' ...]\n\n" diff --git a/src/recording.cpp b/src/recording.cpp index 6548274..ea84fba 100644 --- a/src/recording.cpp +++ b/src/recording.cpp @@ -1,17 +1,127 @@ #include "recording.h" //#include "conversions.h" +#include "xdfwriter.h" #include +#include +#include +#include +#include +#include +#include +#include +#include #include #include +#include +#include #ifdef XDFZ_SUPPORT #include #include #include #endif +// timings in the recording process (e.g., rate of boundary chunks and for cases where a stream +// hangs) approx. interval between boundary chunks +const auto boundary_interval = std::chrono::seconds(10); +// approx. interval between offset measurements +const auto offset_interval = std::chrono::seconds(5); +// approx. interval between resolves for outstanding streams on the watchlist, in seconds +const double resolve_interval = 5; +// timeout of a single resolve attempt, in seconds; the rest of resolve_interval is spent in an +// interruptible wait so that a shutdown request need not wait out a resolve +const double resolve_timeout = 1; +// approx. interval between pulling chunks from outlets +const auto chunk_interval = std::chrono::milliseconds(500); +// maximum waiting time for moving past the headers phase while recording +const auto max_headers_wait = std::chrono::seconds(10); +// maximum waiting time for moving into the footers phase while recording +const auto max_footers_wait = std::chrono::seconds(2); +// maximum waiting time for subscribing to a stream, in seconds (if exceeded, stream subscription +// will take place later) +const double max_open_wait = 5; +// maximum waiting time for a single time correction query, in seconds +const double max_time_correction_wait = 2; +// blocking network calls are issued in slices of this length (in seconds) so that a shutdown +// request is noticed promptly instead of after the full timeout +const double network_poll_interval = 0.2; +// time granted to the stream threads to drain their inlets and write their footers before the +// inlets are forcibly closed +const auto teardown_grace = std::chrono::milliseconds(300); +// maximum time that we wait to join a thread +const auto max_join_wait = std::chrono::seconds(2); + +// steady_clock (not high_resolution_clock, which is an alias for the wall clock in some standard +// libraries) so that waits are unaffected by clock adjustments +using Clock = std::chrono::steady_clock; + +using streamid_t = uint32_t; + +/// thrown by the interruptible helpers when the recording is being torn down +class shutdown_requested : public std::runtime_error { +public: + explicit shutdown_requested(const std::string &what) : std::runtime_error(what) {} +}; + +/** + * A thread paired with a future that becomes ready once the thread body has returned. + * + * std::thread::join() blocks indefinitely, so polling it cannot enforce a deadline: a single call + * against a hung thread never comes back. The future can be waited on with a timeout, and only + * once it is ready do we join (which then returns promptly). A std::packaged_task future is used + * rather than std::async because the latter blocks in its future destructor. + */ +struct worker { + std::thread thread; + std::future done; +}; +// pointer to a worker thread +using worker_p = std::unique_ptr; + +/// start a worker thread running fn +template worker_p spawn_worker(F &&fn) { + auto task = std::make_shared>(std::forward(fn)); + auto w = std::make_unique(); + w->done = task->get_future(); + // the task is kept alive by the lambda, so the worker may be detached safely + w->thread = std::thread([task] { (*task)(); }); + return w; +} + +// pointer to a stream inlet +using inlet_p = std::shared_ptr; +// pointer to a per-stream flag asking that stream's offset thread to finish. Shared rather than +// referenced so that an offset thread which had to be detached cannot outlive its flag. +using offset_flag_p = std::shared_ptr>; +// a list of clock offset estimates (time,value) +using offset_list = std::list>; +// a map from streamid to offset_list +using offset_lists = std::map; + namespace { +/// Write one line, atomically with respect to the other recording threads. +/// +/// Every stream has its own thread and they all report progress; an unsynchronised chain of << +/// lets two of them interleave in the middle of a line, which garbles the log and defeats anything +/// that reads it. +template void log_line(std::ostream &out, Args &&...args) { + std::ostringstream line; + (line << ... << std::forward(args)); + line << '\n'; + static std::mutex log_mut; + std::lock_guard lock(log_mut); + out << line.str() << std::flush; +} + +template void log_out(Args &&...args) { + log_line(std::cout, std::forward(args)...); +} + +template void log_err(Args &&...args) { + log_line(std::cerr, std::forward(args)...); +} + // time spent waiting between two resolves of a watchlist query; the resolve itself already takes // resolve_timeout, so together they keep the resolve_interval cadence const auto resolve_pause = std::chrono::duration_cast( @@ -52,7 +162,7 @@ inline void timed_join_or_detach(worker_p &w, std::chrono::milliseconds duration if (!timed_join(w, duration)) { w->thread.detach(); w.reset(); - std::cerr << "Thread didn't join in time!" << std::endl; + log_err("Thread didn't join in time!"); } } @@ -82,31 +192,181 @@ inline void timed_join_or_detach( std::list &workers, std::chrono::milliseconds duration = max_join_wait) { timed_join_some(workers, duration); if (!workers.empty()) { - std::cout << workers.size() << " stream threads still running!" << std::endl; + log_out(workers.size(), " stream threads still running!"); for (auto &w : workers) w->thread.detach(); workers.clear(); } } -recording::recording(const std::string &filename, const std::vector &streams, - const std::vector &watchfor, std::map syncOptions, - bool collect_offsets) - : file_(filename), offsets_enabled_(collect_offsets), unsorted_(false), streamid_(0), - shutdown_(false), headers_to_finish_(0), streaming_to_finish_(0), - sync_options_by_stream_(std::move(syncOptions)) { +/** + * The recording state, and the thread bodies that operate on it. + * + * Every recording thread holds a shared_ptr to this, as does the recording object. A thread that + * could not be joined within the teardown deadline is left running rather than blocking the + * caller, which is typically the UI thread, so the state it writes into has to be able to outlive + * the recording object. Whoever drops the last reference destroys it, and that is what closes the + * file. + */ +struct recording::impl : std::enable_shared_from_this { + impl(const std::string &filename, std::map syncOptions, bool collect_offsets) + : file_(filename), offsets_enabled_(collect_offsets), unsorted_(false), streamid_(0), + shutdown_(false), headers_to_finish_(0), streaming_to_finish_(0), + sync_options_by_stream_(std::move(syncOptions)) {} + + /// Deliberately joins nothing: the last recording thread to finish drops the final reference, + /// so this runs on that very thread and joining here would be a self-join. stop_and_join() + /// leaves the worker containers empty, so there is nothing left to clean up. + ~impl() = default; + + /// Spawn the recording threads. Separate from the constructor because the threads need a + /// shared_ptr to this, which shared_from_this() cannot hand out during construction. + void start( + const std::vector &streams, const std::vector &watchfor); + + /// Ask the threads to finish and wait a bounded amount of time for them, leaving any that are + /// still stuck running. Called from the recording object, never from a recording thread. + void stop_and_join() noexcept; + + void requestStop() noexcept; + + // the file stream + XDFWriter file_; // the file output stream + // static information + bool offsets_enabled_; // whether to collect time offset information alongside with the stream + // contents + bool unsorted_; // whether this file may contain unsorted chunks (e.g., of late streams) + + // streamid allocation + std::atomic streamid_; // the highest streamid allocated so far + + // phase-of-recording state (headers, streaming data, or footers) + std::atomic shutdown_; // whether we are trying to shut down + std::condition_variable + shutdown_cv_; // signals shutdown so that every interruptible wait returns at once + std::mutex shutdown_mut_; // protects publication of shutdown_ and of the per-stream offset + // shutdown flags, which the shutdown_cv_ predicates read under it + uint32_t headers_to_finish_; // the number of streams that still need to write their header + // (i.e., are not yet ready to write streaming content) + uint32_t streaming_to_finish_; // the number of streams that still need to finish the streaming + // phase (i.e., are not yet ready for writing their footer) + std::condition_variable + ready_for_streaming_; // condition variable signaling that all streams have finished writing + // their headers and are now ready to write streaming content + std::condition_variable + ready_for_footers_; // condition variable signaling that all streams have finished their + // recording jobs and are now ready to write a footer + std::mutex phase_mut_; // a mutex to protect the phase state + + // inlets with potentially pending network I/O, to be aborted if their thread does not stop in + // time + std::vector active_inlets_; + std::mutex inlets_mut_; // a mutex to protect the active inlet list + + // data structure to collect the time offsets for every stream + offset_lists + offset_lists_; // the clock offset lists for each stream (to be written into the footer) + std::mutex offset_mut_; // a mutex to protect the offset lists + + // data for shutdown / final joining + std::list stream_threads_; // the spawned stream handling threads + worker_p boundary_thread_; // the spawned boundary-recording thread + + // for enabling online sync options + std::map sync_options_by_stream_; + + // === recording thread functions === + + /// record from results of a query (spawn a recording thread for every result produced by the + /// query) + /// @param query The query string + void record_from_query_results(const std::string &query); + + /// record from a given stream (identified by its streaminfo) + /// @param src the stream_info from which to record + /// @param phase_locked whether this is a stream that is locked to the phases (1. Headers, 2. + /// Streaming Content, 3. Footers) + /// Late-added streams (e.g. forgotten devices) are not phase-locked. + void record_from_streaminfo(const lsl::stream_info &src, bool phase_locked); + + /// record boundary markers every few seconds + void record_boundaries(); + + // record ClockOffset chunks from a given stream + void record_offsets(streamid_t streamid, inlet_p in, offset_flag_p offset_shutdown) noexcept; + + // sample collection loop for a numeric stream + template + void typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, + double &first_timestamp, double &last_timestamp, uint64_t &sample_count); + + // === interruptible waiting & bounded network calls === + + /// wait until deadline, returning true if the wait was cut short by a shutdown request + /// @param extra an optional additional flag (e.g. a per-stream offset shutdown) that also ends + /// the wait + bool wait_until_shutdown(Clock::time_point deadline, const std::atomic *extra = nullptr); + + /// wait for timeout, returning true if the wait was cut short by a shutdown request + bool wait_for_shutdown(Clock::duration timeout, const std::atomic *extra = nullptr) { + return wait_until_shutdown(Clock::now() + timeout, extra); + } + + /// publish a per-stream offset shutdown flag and wake the corresponding offset thread + void stop_offsets(const offset_flag_p &offset_shutdown) noexcept; + + /// subscribe to a stream, giving up after max_open_wait + /// @return whether the subscription completed (if not, it will take place later) + bool open_inlet(const inlet_p &in); + + /// retrieve the full stream info, including the extended description + /// @throws shutdown_requested if the recording was stopped while retrieving the metadata + lsl::stream_info fetch_info(const inlet_p &in); + + // === inlet bookkeeping === + + void register_inlet(const inlet_p &in); + void unregister_inlet(const inlet_p &in) noexcept; + /// close every registered inlet, aborting any blocking socket call in progress + void close_active_inlets() noexcept; + + // === phase registration & condition checks === + // writing is coordinated across threads in three phases to keep the file chunks sorted + + void enter_headers_phase(bool phase_locked); + void leave_headers_phase(bool phase_locked); + void enter_streaming_phase(bool phase_locked); + void leave_streaming_phase(bool phase_locked); + void enter_footers_phase(bool phase_locked); + void leave_footers_phase(bool) { /* Nothing to do. Ignore warning. */ + } + + /// a condition that indicates that we are ready to write streaming content into the file + bool ready_for_streaming() const { return headers_to_finish_ <= 0; } + /// a condition that indicates that we are ready to write footers into the file + bool ready_for_footers() const { return streaming_to_finish_ <= 0 && headers_to_finish_ <= 0; } + + /// allocate a fresh stream id + streamid_t fresh_streamid() { return ++streamid_; } +}; + +void recording::impl::start( + const std::vector &streams, const std::vector &watchfor) { + // the threads hold a reference to us, so the state they write into outlives a teardown that + // had to leave one of them running + auto self = shared_from_this(); // create a recording thread for each stream for (const auto &stream : streams) stream_threads_.emplace_back( - spawn_worker([this, stream] { record_from_streaminfo(stream, true); })); + spawn_worker([self, stream] { self->record_from_streaminfo(stream, true); })); // create a resolve-and-record thread for each item in the watchlist for (const auto &query : watchfor) stream_threads_.emplace_back( - spawn_worker([this, query] { record_from_query_results(query); })); + spawn_worker([self, query] { self->record_from_query_results(query); })); // create a boundary chunk writer thread - boundary_thread_ = spawn_worker([this] { record_boundaries(); }); + boundary_thread_ = spawn_worker([self] { self->record_boundaries(); }); } -recording::~recording() { +void recording::impl::stop_and_join() noexcept { try { // set the shutdown flag (from now on no more new streams) and wake every waiting thread requestStop(); @@ -120,13 +380,30 @@ recording::~recording() { timed_join_or_detach(stream_threads_, max_join_wait); } timed_join_or_detach(boundary_thread_, max_join_wait); - std::cout << "Closing the file." << std::endl; + log_out("Closing the file."); } catch (std::exception &e) { - std::cout << "Error while closing the recording: " << e.what() << std::endl; + log_out("Error while closing the recording: ", e.what()); + } +} + +recording::recording(const std::string &filename, const std::vector &streams, + const std::vector &watchfor, std::map syncOptions, + bool collect_offsets) + : impl_(std::make_shared(filename, std::move(syncOptions), collect_offsets)) { + try { + impl_->start(streams, watchfor); + } catch (...) { + // some threads may already be running, and our destructor will not run if we throw + impl_->stop_and_join(); + throw; } } -void recording::requestStop() noexcept { +recording::~recording() { impl_->stop_and_join(); } + +void recording::requestStop() noexcept { impl_->requestStop(); } + +void recording::impl::requestStop() noexcept { { // publish the flag under the mutex that the shutdown_cv_ predicates read it under: a // waiter that has just evaluated its predicate as false would otherwise miss the @@ -142,13 +419,13 @@ void recording::requestStop() noexcept { ready_for_footers_.notify_all(); } -bool recording::wait_until_shutdown(Clock::time_point deadline, const std::atomic *extra) { +bool recording::impl::wait_until_shutdown(Clock::time_point deadline, const std::atomic *extra) { std::unique_lock lock(shutdown_mut_); return shutdown_cv_.wait_until( lock, deadline, [this, extra] { return shutdown_.load() || (extra && extra->load()); }); } -void recording::stop_offsets(const offset_flag_p &offset_shutdown) noexcept { +void recording::impl::stop_offsets(const offset_flag_p &offset_shutdown) noexcept { { std::lock_guard lock(shutdown_mut_); *offset_shutdown = true; @@ -156,30 +433,30 @@ void recording::stop_offsets(const offset_flag_p &offset_shutdown) noexcept { shutdown_cv_.notify_all(); } -void recording::register_inlet(const inlet_p &in) { +void recording::impl::register_inlet(const inlet_p &in) { std::lock_guard lock(inlets_mut_); active_inlets_.push_back(in); } -void recording::unregister_inlet(const inlet_p &in) noexcept { +void recording::impl::unregister_inlet(const inlet_p &in) noexcept { if (!in) return; std::lock_guard lock(inlets_mut_); active_inlets_.erase( std::remove(active_inlets_.begin(), active_inlets_.end(), in), active_inlets_.end()); } -void recording::close_active_inlets() noexcept { +void recording::impl::close_active_inlets() noexcept { std::lock_guard lock(inlets_mut_); for (auto &in : active_inlets_) { try { in->close_stream(); } catch (std::exception &e) { - std::cerr << "Error while closing an inlet: " << e.what() << std::endl; + log_err("Error while closing an inlet: ", e.what()); } } } -bool recording::open_inlet(const inlet_p &in) { +bool recording::impl::open_inlet(const inlet_p &in) { // subscribe in short slices: a single open_stream(max_open_wait) would keep us from noticing a // stop for up to max_open_wait seconds const auto deadline = Clock::now() + seconds_to_duration(max_open_wait); @@ -192,7 +469,7 @@ bool recording::open_inlet(const inlet_p &in) { return false; } -lsl::stream_info recording::fetch_info(const inlet_p &in) { +lsl::stream_info recording::impl::fetch_info(const inlet_p &in) { // the metadata receiver is separate from the data receiver, so close_stream() does not abort // this call; poll in short slices instead, or an unreachable source blocks us indefinitely. // A stop does not cut this off immediately: a source that is still reachable gets a short @@ -208,12 +485,12 @@ lsl::stream_info recording::fetch_info(const inlet_p &in) { throw shutdown_requested("stopped while retrieving the stream metadata"); } -void recording::record_from_query_results(const std::string &query) { +void recording::impl::record_from_query_results(const std::string &query) { try { std::set known_uids; // set of previously seen stream uid's std::set known_source_ids; // set of previously seen source id's std::list threads; // our spawned threads - std::cout << "Watching for a stream with properties " << query << std::endl; + log_out("Watching for a stream with properties ", query); while (!shutdown_) { // periodically re-resolve the query. The resolve itself is kept short and the rest of // the interval is spent in an interruptible wait, so a stop is noticed quickly. @@ -226,11 +503,11 @@ void recording::record_from_query_results(const std::string &query) { // and doesn't have a previously seen source id... if (!result.source_id().empty() && (!known_source_ids.count(result.source_id()))) { - std::cout << "Found a new stream named " << result.name() - << ", adding it to the recording." << std::endl; + log_out("Found a new stream named ", result.name(), ", adding it to the recording."); // start a new recording thread - threads.emplace_back(spawn_worker( - [this, result] { record_from_streaminfo(result, false); })); + threads.emplace_back(spawn_worker([self = shared_from_this(), result] { + self->record_from_streaminfo(result, false); + })); // ... and add it to the lists of known id's known_uids.insert(result.uid()); if (!result.source_id().empty()) @@ -242,11 +519,11 @@ void recording::record_from_query_results(const std::string &query) { // wait for all our threads to join timed_join_or_detach(threads, max_join_wait); } catch (std::exception &e) { - std::cout << "Error in the record_from_query_results thread: " << e.what() << std::endl; + log_out("Error in the record_from_query_results thread: ", e.what()); } } -void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_locked) { +void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool phase_locked) { inlet_p in; try { // initialised here because a stream that fails mid-recording still writes a footer @@ -267,19 +544,17 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l if (it != sync_options_by_stream_.end()) in->set_postprocessing(it->second); if (open_inlet(in)) - std::cout << "Opened the stream " << src.name() << "." << std::endl; + log_out("Opened the stream ", src.name(), "."); else if (!shutdown_) - std::cout - << "Subscribing to the stream " << src.name() - << " is taking relatively long; collection from this stream will be delayed." - << std::endl; + log_out("Subscribing to the stream ", src.name(), + " is taking relatively long; collection from this stream will be delayed."); // retrieve the stream header & get its XML version. The nominal rate is taken from // the same info, saving a second round trip to the source. const lsl::stream_info info = fetch_info(in); nominal_srate = info.nominal_srate(); file_.write_stream_header(streamid, info.as_xml()); - std::cout << "Received header for stream " << src.name() << "." << std::endl; + log_out("Received header for stream ", src.name(), "."); leave_headers_phase(phase_locked); } catch (std::exception &) { @@ -296,7 +571,7 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l // "forgot to turn on" before the recording started; in that case the file would have to // be post-processed to be in properly sorted (seekable) format enter_streaming_phase(phase_locked); - std::cout << "Started data collection for stream " << src.name() << "." << std::endl; + log_out("Started data collection for stream ", src.name(), "."); // now write the actual sample chunks... switch (src.channel_format()) { @@ -335,8 +610,7 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l leave_streaming_phase(phase_locked); // the header is already on disk, so fall through to the footer instead of leaving the // stream without one - std::cerr << "Error while recording from " << src.name() << ": " << e.what() - << std::endl; + log_err("Error while recording from ", src.name(), ": ", e.what()); } // --- footers phase @@ -362,54 +636,49 @@ void recording::record_from_streaminfo(const lsl::stream_info &src, bool phase_l } file_.write_stream_footer(streamid, footer.str()); - std::cout << "Wrote footer for stream " << src.name() << "." << std::endl; + log_out("Wrote footer for stream ", src.name(), "."); leave_footers_phase(phase_locked); } catch (std::exception &) { leave_footers_phase(phase_locked); throw; } } catch (shutdown_requested &e) { - std::cout << "Recording from " << src.name() << " ended: " << e.what() << std::endl; + log_out("Recording from ", src.name(), " ended: ", e.what()); } catch (std::exception &e) { - std::cout << "Error in the record_from_streaminfo thread: " << e.what() << std::endl; + log_out("Error in the record_from_streaminfo thread: ", e.what()); } unregister_inlet(in); } -void recording::record_boundaries() { +void recording::impl::record_boundaries() { try { while (!shutdown_) { if (wait_for_shutdown(boundary_interval)) break; file_.write_boundary_chunk(); } } catch (std::exception &e) { - std::cout << "Error in the record_boundaries thread: " << e.what() << std::endl; + log_out("Error in the record_boundaries thread: ", e.what()); } } -void recording::record_offsets( +void recording::impl::record_offsets( streamid_t streamid, inlet_p in, offset_flag_p offset_shutdown) noexcept { try { while (!shutdown_ && !*offset_shutdown) { // sleep for the interval if (wait_for_shutdown(offset_interval, offset_shutdown.get())) break; - // query the time offset, again in short slices so that a stop is noticed promptly - double offset = 0, now = 0; - bool have_offset = false; - const auto deadline = Clock::now() + max_time_correction_wait; - while (!shutdown_ && !*offset_shutdown && Clock::now() < deadline) { - try { - offset = in->time_correction(network_poll_interval); - now = lsl::local_clock(); - have_offset = true; - break; - } catch (lsl::timeout_error &) {} - } - if (!have_offset) { - if (shutdown_ || *offset_shutdown) break; - std::cerr << "Timeout in time correction query for stream " << streamid - << std::endl; + // Query the time offset in one call with the whole budget, not in short slices: the + // query needs a round trip to complete, and restarting it every network_poll_interval + // means it never finishes, so no offset is ever recorded. Teardown does not depend on + // this returning quickly -- the transfer thread stops waiting for us after + // teardown_grace and leaves us running, and we keep the file alive while we do. + double offset, now; + try { + offset = in->time_correction(max_time_correction_wait); + now = lsl::local_clock(); + } catch (lsl::timeout_error &) { + log_err("Timeout in time correction query for stream ", streamid); continue; } @@ -419,19 +688,19 @@ void recording::record_offsets( offset_lists_[streamid].emplace_back(now - offset, offset); } } catch (std::exception &e) { - std::cout << "Error in the record_offsets thread: " << e.what() << std::endl; + log_out("Error in the record_offsets thread: ", e.what()); } - std::cout << "Offsets thread is finished" << std::endl; + log_out("Offsets thread is finished"); } -void recording::enter_headers_phase(bool phase_locked) { +void recording::impl::enter_headers_phase(bool phase_locked) { if (phase_locked) { std::lock_guard lock(phase_mut_); headers_to_finish_++; } } -void recording::leave_headers_phase(bool phase_locked) { +void recording::impl::leave_headers_phase(bool phase_locked) { if (phase_locked) { std::unique_lock lock(phase_mut_); headers_to_finish_--; @@ -440,7 +709,7 @@ void recording::leave_headers_phase(bool phase_locked) { } } -void recording::enter_streaming_phase(bool phase_locked) { +void recording::impl::enter_streaming_phase(bool phase_locked) { if (phase_locked) { std::unique_lock lock(phase_mut_); // on shutdown the gate is dropped: the transfer loop exits immediately anyway, and waiting @@ -452,7 +721,7 @@ void recording::enter_streaming_phase(bool phase_locked) { } } -void recording::leave_streaming_phase(bool phase_locked) { +void recording::impl::leave_streaming_phase(bool phase_locked) { if (phase_locked) { std::unique_lock lock(phase_mut_); streaming_to_finish_--; @@ -461,7 +730,7 @@ void recording::leave_streaming_phase(bool phase_locked) { } } -void recording::enter_footers_phase(bool phase_locked) { +void recording::impl::enter_footers_phase(bool phase_locked) { if (phase_locked) { std::unique_lock lock(phase_mut_); // see enter_streaming_phase: a footer written slightly out of order beats no footer at all @@ -471,13 +740,14 @@ void recording::enter_footers_phase(bool phase_locked) { } template -void recording::typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, +void recording::impl::typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, double &first_timestamp, double &last_timestamp, uint64_t &sample_count) { // optionally start an offset collection thread for this stream auto offset_shutdown = std::make_shared>(false); + auto self = shared_from_this(); worker_p offset_thread(offsets_enabled_ - ? spawn_worker([this, streamid, in, offset_shutdown] { - record_offsets(streamid, in, offset_shutdown); + ? spawn_worker([self, streamid, in, offset_shutdown] { + self->record_offsets(streamid, in, offset_shutdown); }) : nullptr); try { @@ -491,6 +761,12 @@ void recording::typed_transfer_loop(streamid_t streamid, double srate, const inl auto write_chunk = [&] { if (timestamps.empty()) return; for (double &ts : timestamps) { + if (first_timestamp == 0.0) { + // the first sample anchors the stream and is written verbatim: at a nominal + // interval of zero the deduction below would otherwise zero out its timestamp + first_timestamp = last_timestamp = ts; + continue; + } // if the time stamp can be deduced from the previous one... if (last_timestamp + sample_interval == ts) { last_timestamp = ts + sample_interval; @@ -502,16 +778,15 @@ void recording::typed_transfer_loop(streamid_t streamid, double srate, const inl sample_count += timestamps.size(); }; - // Pull the first sample + // Wait for the first sample, unless the stop got here first. A stream held at the headers + // gate reaches this point with the shutdown already set, having pulled nothing, while its + // inlet has been subscribed and buffering the whole time -- the drain below picks that up. first_timestamp = 0.0; - while (!shutdown_ && first_timestamp == 0.0) - first_timestamp = last_timestamp = in->pull_sample(chunk, network_poll_interval); - if (first_timestamp != 0.0) { - // written directly: the very first sample anchors the stream and must keep its - // timestamp even when the nominal interval is zero - timestamps.assign(1, first_timestamp); - file_.write_data_chunk(streamid, timestamps, chunk, (uint32_t)in->get_channel_count()); - sample_count += timestamps.size(); + while (!shutdown_ && first_timestamp == 0.0) { + const double ts = in->pull_sample(chunk, network_poll_interval); + if (ts == 0.0) continue; + timestamps.assign(1, ts); + write_chunk(); } auto next_pull = Clock::now() + chunk_interval; @@ -523,23 +798,20 @@ void recording::typed_transfer_loop(streamid_t streamid, double srate, const inl next_pull += chunk_interval; } - if (first_timestamp != 0.0) { - // one final non-blocking pull, so that samples already buffered in the inlet when the - // stop arrived end up in the file rather than being dropped - try { - in->pull_chunk_multiplexed(chunk, ×tamps, 0.0); - write_chunk(); - } catch (std::exception &e) { - // the inlet was closed under us during teardown; the footer matters more - std::cerr << "Could not drain stream " << streamid << " on stop: " << e.what() - << std::endl; - } + // one final non-blocking pull, so that samples already buffered in the inlet when the stop + // arrived end up in the file rather than being dropped + try { + in->pull_chunk_multiplexed(chunk, ×tamps, 0.0); + write_chunk(); + } catch (std::exception &e) { + // the inlet was closed under us during teardown; the footer matters more + log_err("Could not drain stream ", streamid, " on stop: ", e.what()); } } catch (std::exception &) { stop_offsets(offset_shutdown); - timed_join_or_detach(offset_thread); + timed_join_or_detach(offset_thread, teardown_grace); throw; } stop_offsets(offset_shutdown); - timed_join_or_detach(offset_thread); + timed_join_or_detach(offset_thread, teardown_grace); } diff --git a/src/recording.h b/src/recording.h index 9b63da2..5eee784 100644 --- a/src/recording.h +++ b/src/recording.h @@ -1,101 +1,12 @@ #ifndef RECORDING_H #define RECORDING_H -#include "xdfwriter.h" -#include -#include -#include -#include -#include -#include #include #include #include -#include -#include #include -#include -#include #include -// timings in the recording process (e.g., rate of boundary chunks and for cases where a stream -// hangs) approx. interval between boundary chunks -const auto boundary_interval = std::chrono::seconds(10); -// approx. interval between offset measurements -const auto offset_interval = std::chrono::seconds(5); -// approx. interval between resolves for outstanding streams on the watchlist, in seconds -const double resolve_interval = 5; -// timeout of a single resolve attempt, in seconds; the rest of resolve_interval is spent in an -// interruptible wait so that a shutdown request need not wait out a resolve -const double resolve_timeout = 1; -// approx. interval between pulling chunks from outlets -const auto chunk_interval = std::chrono::milliseconds(500); -// maximum waiting time for moving past the headers phase while recording -const auto max_headers_wait = std::chrono::seconds(10); -// maximum waiting time for moving into the footers phase while recording -const auto max_footers_wait = std::chrono::seconds(2); -// maximum waiting time for subscribing to a stream, in seconds (if exceeded, stream subscription -// will take place later) -const double max_open_wait = 5; -// maximum waiting time for a single time correction query -const auto max_time_correction_wait = std::chrono::seconds(2); -// blocking network calls are issued in slices of this length (in seconds) so that a shutdown -// request is noticed promptly instead of after the full timeout -const double network_poll_interval = 0.2; -// time granted to the stream threads to drain their inlets and write their footers before the -// inlets are forcibly closed -const auto teardown_grace = std::chrono::milliseconds(300); -// maximum time that we wait to join a thread -const auto max_join_wait = std::chrono::seconds(2); - -// steady_clock (not high_resolution_clock, which is an alias for the wall clock in some standard -// libraries) so that waits are unaffected by clock adjustments -using Clock = std::chrono::steady_clock; - -using streamid_t = uint32_t; - -/// thrown by the interruptible helpers when the recording is being torn down -class shutdown_requested : public std::runtime_error { -public: - explicit shutdown_requested(const std::string &what) : std::runtime_error(what) {} -}; - -/** - * A thread paired with a future that becomes ready once the thread body has returned. - * - * std::thread::join() blocks indefinitely, so polling it cannot enforce a deadline: a single call - * against a hung thread never comes back. The future can be waited on with a timeout, and only - * once it is ready do we join (which then returns promptly). A std::packaged_task future is used - * rather than std::async because the latter blocks in its future destructor. - */ -struct worker { - std::thread thread; - std::future done; -}; -// pointer to a worker thread -using worker_p = std::unique_ptr; - -/// start a worker thread running fn -template worker_p spawn_worker(F &&fn) { - auto task = std::make_shared>(std::forward(fn)); - auto w = std::make_unique(); - w->done = task->get_future(); - // the task is kept alive by the lambda, so the worker may be detached safely - w->thread = std::thread([task] { (*task)(); }); - return w; -} - -// pointer to a stream inlet -using inlet_p = std::shared_ptr; -// pointer to a per-stream flag asking that stream's offset thread to finish. Shared rather than -// referenced so that an offset thread which had to be detached cannot outlive its flag. -using offset_flag_p = std::shared_ptr>; -// a list of clock offset estimates (time,value) -using offset_list = std::list>; -// a map from streamid to offset_list -using offset_lists = std::map; - - /** * A recording process using the lab streaming layer. * An instance of this class is created with a list of stream references to record from. @@ -120,142 +31,19 @@ class recording { bool collect_offsets = true); /** Destructor. - * Stops the recording and closes the file. + * Asks the recording threads to finish and waits a bounded amount of time for them. A thread + * that is still stuck after that is left running; the file is closed once it finishes. */ ~recording(); - /// Ask all recording threads to wrap up. Returns immediately; the threads are joined by the - /// destructor. + /// Ask all recording threads to wrap up. Returns immediately. void requestStop() noexcept; private: - // the file stream - XDFWriter file_; // the file output stream - // static information - bool offsets_enabled_; // whether to collect time offset information alongside with the stream - // contents - bool unsorted_; // whether this file may contain unsorted chunks (e.g., of late streams) - - // streamid allocation - std::atomic streamid_; // the highest streamid allocated so far - - // phase-of-recording state (headers, streaming data, or footers) - std::atomic shutdown_; // whether we are trying to shut down - std::condition_variable - shutdown_cv_; // signals shutdown so that every interruptible wait returns at once - std::mutex shutdown_mut_; // protects publication of shutdown_ and of the per-stream offset - // shutdown flags, which the shutdown_cv_ predicates read under it - uint32_t headers_to_finish_; // the number of streams that still need to write their header - // (i.e., are not yet ready to write streaming content) - uint32_t streaming_to_finish_; // the number of streams that still need to finish the streaming - // phase (i.e., are not yet ready for writing their footer) - std::condition_variable - ready_for_streaming_; // condition variable signaling that all streams have finished writing - // their headers and are now ready to write streaming content - std::condition_variable - ready_for_footers_; // condition variable signaling that all streams have finished their - // recording jobs and are now ready to write a footer - std::mutex phase_mut_; // a mutex to protect the phase state - - // inlets with potentially pending network I/O, to be aborted if their thread does not stop in - // time - std::vector active_inlets_; - std::mutex inlets_mut_; // a mutex to protect the active inlet list - - // data structure to collect the time offsets for every stream - offset_lists - offset_lists_; // the clock offset lists for each stream (to be written into the footer) - std::mutex offset_mut_; // a mutex to protect the offset lists - - // data for shutdown / final joining - std::list stream_threads_; // the spawned stream handling threads - worker_p boundary_thread_; // the spawned boundary-recording thread - - // for enabling online sync options - std::map sync_options_by_stream_; - - // === recording thread functions === - - /// record from results of a query (spawn a recording thread for every result produced by the - /// query) - /// @param query The query string - void record_from_query_results(const std::string &query); - - /// record from a given stream (identified by its streaminfo) - /// @param src the stream_info from which to record - /// @param phase_locked whether this is a stream that is locked to the phases (1. Headers, 2. - /// Streaming Content, 3. Footers) - /// Late-added streams (e.g. forgotten devices) are not phase-locked. - void record_from_streaminfo(const lsl::stream_info &src, bool phase_locked); - - - /// record boundary markers every few seconds - void record_boundaries(); - - // record ClockOffset chunks from a given stream - void record_offsets( - streamid_t streamid, inlet_p in, offset_flag_p offset_shutdown) noexcept; - - - // sample collection loop for a numeric stream - template - void typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, - double &first_timestamp, double &last_timestamp, uint64_t &sample_count); - - // === interruptible waiting & bounded network calls === - - /// wait until deadline, returning true if the wait was cut short by a shutdown request - /// @param extra an optional additional flag (e.g. a per-stream offset shutdown) that also ends - /// the wait - bool wait_until_shutdown(Clock::time_point deadline, const std::atomic *extra = nullptr); - - /// wait for timeout, returning true if the wait was cut short by a shutdown request - bool wait_for_shutdown(Clock::duration timeout, const std::atomic *extra = nullptr) { - return wait_until_shutdown(Clock::now() + timeout, extra); - } - - /// publish a per-stream offset shutdown flag and wake the corresponding offset thread - void stop_offsets(const offset_flag_p &offset_shutdown) noexcept; - - /// subscribe to a stream, giving up after max_open_wait - /// @return whether the subscription completed (if not, it will take place later) - /// @throws shutdown_requested if the recording was stopped while subscribing - bool open_inlet(const inlet_p &in); - - /// retrieve the full stream info, including the extended description - /// @throws shutdown_requested if the recording was stopped while retrieving the metadata - lsl::stream_info fetch_info(const inlet_p &in); - - // === inlet bookkeeping === - - void register_inlet(const inlet_p &in); - void unregister_inlet(const inlet_p &in) noexcept; - /// close every registered inlet, aborting any blocking socket call in progress - void close_active_inlets() noexcept; - - // === phase registration & condition checks === - // writing is coordinated across threads in three phases to keep the file chunks sorted - - void enter_headers_phase(bool phase_locked); - - void leave_headers_phase(bool phase_locked); - - void enter_streaming_phase(bool phase_locked); - - void leave_streaming_phase(bool phase_locked); - - void enter_footers_phase(bool phase_locked); - - void leave_footers_phase(bool) { /* Nothing to do. Ignore warning. */ - } - - /// a condition that indicates that we are ready to write streaming content into the file - bool ready_for_streaming() const { return headers_to_finish_ <= 0; } - /// a condition that indicates that we are ready to write footers into the file - bool ready_for_footers() const { return streaming_to_finish_ <= 0 && headers_to_finish_ <= 0; } - - /// allocate a fresh stream id - streamid_t fresh_streamid() { return ++streamid_; } + struct impl; + /// Shared rather than unique: a recording thread that had to be left running keeps the state + /// it writes into -- the file, the mutexes, the offset lists -- alive until it is done. + std::shared_ptr impl_; }; #endif From 8f39fe7dfe38eca118e5afdb0253bb501cf7cfaa Mon Sep 17 00:00:00 2001 From: Chadwick Boulay Date: Sun, 20 Sep 2026 19:51:42 -0400 Subject: [PATCH 5/7] Finalize recording workers before closing the recorder Poll clock correction without restarting liblsl's background measurement, and join every worker before releasing the writer. A slow worker must not leave the CLI with buffered output owned by a detached thread at process exit. Add deterministic finalization regressions to CI and verify real clock offsets in the integration suite. --- .github/workflows/build.yml | 4 ++ BUILD.md | 22 ++++++- CMakeLists.txt | 18 ++++++ scripts/test_recording_teardown.py | 22 +++++++ src/recording.cpp | 83 ++++++++++++------------- src/recording.h | 7 +-- tests/fake_lsl/lsl_cpp.h | 98 ++++++++++++++++++++++++++++++ tests/recording_finalization.cpp | 64 +++++++++++++++++++ 8 files changed, 272 insertions(+), 46 deletions(-) create mode 100644 tests/fake_lsl/lsl_cpp.h create mode 100644 tests/recording_finalization.cpp diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 6f5048e..b9b691a 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -80,6 +80,7 @@ jobs: -DCMAKE_BUILD_TYPE=${{ env.BUILD_TYPE }} -DCMAKE_INSTALL_PREFIX=${{ github.workspace }}/install -DLSL_FETCH_IF_MISSING=ON + -DLABRECORDER_BUILD_TESTING=ON ${{ matrix.config.cmake_extra }} # ----------------------------------------------------------------------- @@ -88,6 +89,9 @@ jobs: - name: Build run: cmake --build build --config ${{ env.BUILD_TYPE }} --parallel + - name: Test recording finalization + run: ctest --test-dir build -C ${{ env.BUILD_TYPE }} --output-on-failure + # ----------------------------------------------------------------------- # Install # ----------------------------------------------------------------------- diff --git a/BUILD.md b/BUILD.md index c3973b9..1e6f780 100644 --- a/BUILD.md +++ b/BUILD.md @@ -92,6 +92,27 @@ The command line install feature does not put build products in the sample place If any significant changes are made to the project (such as changing Qt or Visual Stuido version) it is recommended that you delete or rename the build folder and start over. Various partial cleaning processes do not work well. +## Recording tests + +Enable the deterministic shutdown tests when configuring, then build and run CTest: + +```sh +cmake -S . -B build -DLABRECORDER_BUILD_TESTING=ON +cmake --build build --config Release +ctest --test-dir build -C Release --output-on-failure +``` + +These tests compile the recording implementation and XDF writer against a controlled inlet. +They cover delayed clock measurements, stopping during an unavailable measurement, and a +worker that exceeds the join warning deadline. Every case checks that the file is finalized +immediately when the recording is destroyed. + +The real-stream integration suite additionally requires `pylsl` and `pyxdf`: + +```sh +python scripts/test_recording_teardown.py --bin /path/to/LabRecorderCLI +``` + ## Linux * Ubuntu (/Debian) @@ -122,4 +143,3 @@ If any significant changes are made to the project (such as changing Qt or Visua 1. You may need to specify additional cmake options. . Build everything and copy the files to the `install` folder: * `cmake --build . --target install` - diff --git a/CMakeLists.txt b/CMakeLists.txt index a7d904e..661f453 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -30,6 +30,7 @@ set(CMAKE_EXPORT_COMPILE_COMMANDS ON) # Build Options # ============================================================================= option(LABRECORDER_BUILD_GUI "Build the GUI application (requires Qt6)" ON) +option(LABRECORDER_BUILD_TESTING "Build deterministic recording tests" OFF) # ============================================================================= # LSL Discovery Options @@ -218,6 +219,23 @@ target_link_libraries(${PROJECT_NAME}CLI PRIVATE LSL::lsl ) +if(LABRECORDER_BUILD_TESTING) + enable_testing() + add_executable(test_recording_finalization + tests/recording_finalization.cpp + src/recording.cpp + ) + # Compile the real recording implementation against a controlled inlet. Do not link + # liblsl into this target: its timeout behavior is supplied by the test double. + target_include_directories(test_recording_finalization PRIVATE tests/fake_lsl src) + target_link_libraries(test_recording_finalization PRIVATE xdfwriter Threads::Threads) + foreach(scenario IN ITEMS delayed unavailable stalled) + add_test(NAME recording_finalization_${scenario} + COMMAND test_recording_finalization ${scenario}) + set_tests_properties(recording_finalization_${scenario} PROPERTIES TIMEOUT 20) + endforeach() +endif() + # ============================================================================= # Copy config file to build directory for testing # ============================================================================= diff --git a/scripts/test_recording_teardown.py b/scripts/test_recording_teardown.py index aa0ceee..02ae91e 100644 --- a/scripts/test_recording_teardown.py +++ b/scripts/test_recording_teardown.py @@ -378,6 +378,27 @@ def case_gated_stream_is_drained(cli_path, xdf_path, max_stop): del eeg +def case_clock_offsets_collected(cli_path, xdf_path, max_stop): + """Run past the first offset query and verify short waits still obtain its result.""" + eeg, markers = make_outlets() + time.sleep(SETTLE) + with recorder(cli_path, xdf_path) as rec: + rec.wait_until_collecting() + # Offset queries begin after five seconds. Allow the local LSL probe exchange to + # complete across several 200 ms waits before stopping. + push_eeg_for(eeg, 6.5) + duration = rec.stop() + + check_stop(duration, max_stop) + streams, _ = load_xdf_strict(xdf_path) + for name in NAMES: + stream = stream_by_name(streams, name) + check_footer(stream) + offsets = stream["footer"]["info"]["clock_offsets"][0] + check(offsets and offsets.get("offset"), f"stream {name!r} has no clock offsets") + del eeg, markers + + CASES = [ ("normal stop", case_normal_stop), ("stop before first sample", case_stop_before_first_sample), @@ -385,6 +406,7 @@ def case_gated_stream_is_drained(cli_path, xdf_path, max_stop): ("repeated shutdown", case_repeated_shutdown), ("no buffered samples lost", case_no_buffered_samples_lost), ("gated stream is drained", case_gated_stream_is_drained), + ("clock offsets collected", case_clock_offsets_collected), ] diff --git a/src/recording.cpp b/src/recording.cpp index ea84fba..69b1b96 100644 --- a/src/recording.cpp +++ b/src/recording.cpp @@ -48,7 +48,7 @@ const double network_poll_interval = 0.2; // time granted to the stream threads to drain their inlets and write their footers before the // inlets are forcibly closed const auto teardown_grace = std::chrono::milliseconds(300); -// maximum time that we wait to join a thread +// time before reporting a slow worker; finalization still waits for it to finish const auto max_join_wait = std::chrono::seconds(2); // steady_clock (not high_resolution_clock, which is an alias for the wall clock in some standard @@ -83,15 +83,14 @@ template worker_p spawn_worker(F &&fn) { auto task = std::make_shared>(std::forward(fn)); auto w = std::make_unique(); w->done = task->get_future(); - // the task is kept alive by the lambda, so the worker may be detached safely + // the task is kept alive by the lambda until its body returns w->thread = std::thread([task] { (*task)(); }); return w; } // pointer to a stream inlet using inlet_p = std::shared_ptr; -// pointer to a per-stream flag asking that stream's offset thread to finish. Shared rather than -// referenced so that an offset thread which had to be detached cannot outlive its flag. +// Per-stream stop flag shared with the offset worker until it has been joined. using offset_flag_p = std::shared_ptr>; // a list of clock offset estimates (time,value) using offset_list = std::list>; @@ -100,6 +99,8 @@ using offset_lists = std::map; namespace { +std::mutex log_mut; + /// Write one line, atomically with respect to the other recording threads. /// /// Every stream has its own thread and they all report progress; an unsynchronised chain of << @@ -109,7 +110,6 @@ template void log_line(std::ostream &out, Args &&...args) { std::ostringstream line; (line << ... << std::forward(args)); line << '\n'; - static std::mutex log_mut; std::lock_guard lock(log_mut); out << line.str() << std::flush; } @@ -153,16 +153,15 @@ inline bool timed_join(worker_p &w, std::chrono::milliseconds duration = max_joi } /** - * @brief timed_join_or_detach Join the worker or detach it if not possible within specified - * duration + * @brief join_worker Join the worker, reporting when it exceeds the expected duration * @param w unique_ptr to a worker. Will be reset either way - * @param duration max duration to wait + * @param duration time before reporting that finalization is still waiting */ -inline void timed_join_or_detach(worker_p &w, std::chrono::milliseconds duration = max_join_wait) { +inline void join_worker(worker_p &w, std::chrono::milliseconds duration = max_join_wait) { if (!timed_join(w, duration)) { - w->thread.detach(); + log_err("Waiting for a recording worker to finish before closing the file."); + w->thread.join(); w.reset(); - log_err("Thread didn't join in time!"); } } @@ -184,16 +183,16 @@ inline void timed_join_some(std::list &workers, std::chrono::milliseco } /** - * @brief timed_join_or_detach Join the workers or detach those that don't finish in time + * @brief join_workers Join all workers before their writer can be destroyed * @param workers list of workers. Guaranteed to be empty afterwards. * @param duration duration to wait, shared across all workers */ -inline void timed_join_or_detach( +inline void join_workers( std::list &workers, std::chrono::milliseconds duration = max_join_wait) { timed_join_some(workers, duration); if (!workers.empty()) { log_out(workers.size(), " stream threads still running!"); - for (auto &w : workers) w->thread.detach(); + for (auto &w : workers) w->thread.join(); workers.clear(); } } @@ -201,11 +200,10 @@ inline void timed_join_or_detach( /** * The recording state, and the thread bodies that operate on it. * - * Every recording thread holds a shared_ptr to this, as does the recording object. A thread that - * could not be joined within the teardown deadline is left running rather than blocking the - * caller, which is typically the UI thread, so the state it writes into has to be able to outlive - * the recording object. Whoever drops the last reference destroys it, and that is what closes the - * file. + * Every recording thread holds a shared_ptr to this, as does the recording object. + * stop_and_join() joins all workers, including nested workers, before the recording handle + * releases its reference and closes the file. A fast stop must not leave buffered output owned + * by a detached worker that process exit could kill before the writer flushes. */ struct recording::impl : std::enable_shared_from_this { impl(const std::string &filename, std::map syncOptions, bool collect_offsets) @@ -213,9 +211,7 @@ struct recording::impl : std::enable_shared_from_this { shutdown_(false), headers_to_finish_(0), streaming_to_finish_(0), sync_options_by_stream_(std::move(syncOptions)) {} - /// Deliberately joins nothing: the last recording thread to finish drops the final reference, - /// so this runs on that very thread and joining here would be a self-join. stop_and_join() - /// leaves the worker containers empty, so there is nothing left to clean up. + /// stop_and_join() leaves the worker containers empty before this state is destroyed. ~impl() = default; /// Spawn the recording threads. Separate from the constructor because the threads need a @@ -223,8 +219,8 @@ struct recording::impl : std::enable_shared_from_this { void start( const std::vector &streams, const std::vector &watchfor); - /// Ask the threads to finish and wait a bounded amount of time for them, leaving any that are - /// still stuck running. Called from the recording object, never from a recording thread. + /// Ask the threads to finish and join them all before closing the file. + /// Called from the recording object, never from a recording thread. void stop_and_join() noexcept; void requestStop() noexcept; @@ -351,8 +347,7 @@ struct recording::impl : std::enable_shared_from_this { void recording::impl::start( const std::vector &streams, const std::vector &watchfor) { - // the threads hold a reference to us, so the state they write into outlives a teardown that - // had to leave one of them running + // Each worker owns its state until it has finished; stop_and_join() joins them all. auto self = shared_from_this(); // create a recording thread for each stream for (const auto &stream : streams) @@ -377,9 +372,9 @@ void recording::impl::stop_and_join() noexcept { if (!stream_threads_.empty()) { // a thread is stuck in a blocking socket call; closing its inlet aborts that call close_active_inlets(); - timed_join_or_detach(stream_threads_, max_join_wait); + join_workers(stream_threads_, max_join_wait); } - timed_join_or_detach(boundary_thread_, max_join_wait); + join_worker(boundary_thread_, max_join_wait); log_out("Closing the file."); } catch (std::exception &e) { log_out("Error while closing the recording: ", e.what()); @@ -517,7 +512,7 @@ void recording::impl::record_from_query_results(const std::string &query) { if (wait_for_shutdown(resolve_pause)) break; } // wait for all our threads to join - timed_join_or_detach(threads, max_join_wait); + join_workers(threads, max_join_wait); } catch (std::exception &e) { log_out("Error in the record_from_query_results thread: ", e.what()); } @@ -668,16 +663,22 @@ void recording::impl::record_offsets( // sleep for the interval if (wait_for_shutdown(offset_interval, offset_shutdown.get())) break; - // Query the time offset in one call with the whole budget, not in short slices: the - // query needs a round trip to complete, and restarting it every network_poll_interval - // means it never finishes, so no offset is ever recorded. Teardown does not depend on - // this returning quickly -- the transfer thread stops waiting for us after - // teardown_grace and leaves us running, and we keep the file alive while we do. - double offset, now; - try { - offset = in->time_correction(max_time_correction_wait); - now = lsl::local_clock(); - } catch (lsl::timeout_error &) { + // liblsl's background measurement survives a time_correction() timeout. Polling + // waits for that same result; it does not restart the packet exchange. + const auto deadline = Clock::now() + seconds_to_duration(max_time_correction_wait); + double offset = 0, now = 0; + bool have_offset = false; + while (!shutdown_ && !*offset_shutdown && Clock::now() < deadline) { + const double remaining = std::chrono::duration(deadline - Clock::now()).count(); + try { + offset = in->time_correction(std::max(0.0, std::min(network_poll_interval, remaining))); + now = lsl::local_clock(); + have_offset = true; + break; + } catch (lsl::timeout_error &) {} + } + if (shutdown_ || *offset_shutdown) break; + if (!have_offset) { log_err("Timeout in time correction query for stream ", streamid); continue; } @@ -809,9 +810,9 @@ void recording::impl::typed_transfer_loop(streamid_t streamid, double srate, con } } catch (std::exception &) { stop_offsets(offset_shutdown); - timed_join_or_detach(offset_thread, teardown_grace); + join_worker(offset_thread, teardown_grace); throw; } stop_offsets(offset_shutdown); - timed_join_or_detach(offset_thread, teardown_grace); + join_worker(offset_thread, teardown_grace); } diff --git a/src/recording.h b/src/recording.h index 5eee784..09607c6 100644 --- a/src/recording.h +++ b/src/recording.h @@ -31,8 +31,8 @@ class recording { bool collect_offsets = true); /** Destructor. - * Asks the recording threads to finish and waits a bounded amount of time for them. A thread - * that is still stuck after that is left running; the file is closed once it finishes. + * Stops and joins every recording thread, then closes and flushes the file. Network waits + * observe shutdown promptly; a slow disk write must finish before destruction returns. */ ~recording(); @@ -41,8 +41,7 @@ class recording { private: struct impl; - /// Shared rather than unique: a recording thread that had to be left running keeps the state - /// it writes into -- the file, the mutexes, the offset lists -- alive until it is done. + /// Workers retain the state while running; destruction joins them before releasing it. std::shared_ptr impl_; }; diff --git a/tests/fake_lsl/lsl_cpp.h b/tests/fake_lsl/lsl_cpp.h new file mode 100644 index 0000000..a7caef3 --- /dev/null +++ b/tests/fake_lsl/lsl_cpp.h @@ -0,0 +1,98 @@ +#pragma once + +// A deterministic inlet for recording finalization tests. Only this test target +// sees it; the recorder and XDF writer are compiled unchanged, without a live +// network dependency. +#include +#include +#include +#include +#include +#include +#include + +namespace lsl { +using clock = std::chrono::steady_clock; +enum channel_format_t { cf_int8, cf_int16, cf_int32, cf_float32, cf_double64, cf_string }; +struct timeout_error : std::runtime_error { + timeout_error() : std::runtime_error("test timeout") {} +}; +struct inlet_state { + enum mode { delayed_result, unavailable, stalled_worker } behavior; + std::atomic query_started{false}, query_finished{false}; + std::atomic query_calls{0}; + clock::time_point result_ready; + explicit inlet_state(mode behavior) : behavior(behavior) {} +}; + +class stream_info { + public: + std::shared_ptr state; + explicit stream_info(std::shared_ptr state) : state(std::move(state)) {} + std::string name() const { return "FinalizationTest"; } + std::string hostname() const { return "localhost"; } + std::string uid() const { return "finalization-test"; } + std::string source_id() const { return uid(); } + channel_format_t channel_format() const { return cf_float32; } + double nominal_srate() const { return 100; } + std::string as_xml() const { + return "FinalizationTest1" + "float32100"; + } +}; + +inline double local_clock() { + return std::chrono::duration(clock::now().time_since_epoch()).count(); +} +inline std::vector resolve_stream(const std::string &, int, double) { return {}; } + +class stream_inlet { + stream_info info_; + bool sent_sample_ = false; + + public: + explicit stream_inlet(const stream_info &info) : info_(info) {} + void open_stream(double) {} + void close_stream() {} + void set_postprocessing(int) {} + stream_info info(double) { return info_; } + int get_channel_count() const { return 1; } + template double pull_sample(std::vector &sample, double timeout) { + if (!sent_sample_) { + sent_sample_ = true; + sample.assign(1, T{}); + return 123; + } + std::this_thread::sleep_for(std::chrono::duration(timeout)); + return 0; + } + template + void pull_chunk_multiplexed(std::vector &chunk, std::vector *timestamps, double) { + chunk.clear(); + timestamps->clear(); + } + double time_correction(double timeout) { + auto &state = *info_.state; + if (state.query_calls++ == 0) + state.result_ready = clock::now() + std::chrono::milliseconds(600); + state.query_started = true; + if (state.behavior == inlet_state::stalled_worker) { + // Deliberately exceed both the offset grace and outer join deadline. Even + // an unexpectedly slow worker must finish before the caller can exit the + // process. + std::this_thread::sleep_for(std::chrono::milliseconds(2600)); + } else { + const auto deadline = clock::now() + std::chrono::duration_cast( + std::chrono::duration(timeout)); + if (state.behavior == inlet_state::unavailable || deadline < state.result_ready) { + std::this_thread::sleep_until(deadline); + throw timeout_error(); + } + std::this_thread::sleep_until(state.result_ready); + } + state.query_finished = true; + return 0.0123; + } +}; +} // namespace lsl diff --git a/tests/recording_finalization.cpp b/tests/recording_finalization.cpp new file mode 100644 index 0000000..040d97e --- /dev/null +++ b/tests/recording_finalization.cpp @@ -0,0 +1,64 @@ +#include "recording.h" +#include +#include +#include +#include +#include +#include +#include + +static void require(bool value, const char *message) { + if (!value) throw std::runtime_error(message); +} + +int main(int argc, char **argv) { + try { + require(argc == 2, "expected delayed, unavailable, or stalled"); + const std::string scenario = argv[1]; + const auto mode = scenario == "delayed" ? lsl::inlet_state::delayed_result + : scenario == "unavailable" ? lsl::inlet_state::unavailable + : lsl::inlet_state::stalled_worker; + auto state = std::make_shared(mode); + const auto filename = "finalization-" + scenario + ".xdf"; + auto rec = std::make_unique( + filename, std::vector{lsl::stream_info(state)}, + std::vector{}, std::map{}); + const auto deadline = lsl::clock::now() + std::chrono::seconds(10); + while ( + !(scenario == "delayed" ? state->query_finished.load() : state->query_started.load()) && + lsl::clock::now() < deadline) + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + require(state->query_started, "offset worker never started"); + const auto stop = lsl::clock::now(); + rec.reset(); + const auto elapsed = std::chrono::duration(lsl::clock::now() - stop).count(); + + // Read immediately, with no grace period after destruction: this is what a + // CLI caller needs before exiting. A detached owner leaves this small file + // in the writer's buffer. + std::ifstream file(filename, std::ios::binary); + const std::string contents((std::istreambuf_iterator(file)), {}); + require(contents.substr(0, 4) == "XDF:", + "writer was not flushed before destruction returned"); + require(contents.find("1") != std::string::npos, + "stream footer is missing or inconsistent"); + require(contents.find("") != std::string::npos, + "stream footer was not completely flushed"); + if (scenario == "delayed") { + require(state->query_finished, "short waits never obtained the delayed offset"); + require(state->query_calls > 1, "test did not exercise polling across timeouts"); + require(contents.find("") != std::string::npos, "offset missing from footer"); + } else if (scenario == "unavailable") { + require(elapsed < 1.0, "stop waited for the full offset query budget"); + } else { + require(state->query_finished, "destructor abandoned a running writer owner"); + } + file.close(); + std::filesystem::remove(filename); + std::cout << scenario << ": file finalized; stop took " << elapsed << " s\n"; + return 0; + } catch (const std::exception &e) { + std::cerr << e.what() << '\n'; + return 1; + } +} From 81d0048906fa0ebf543e42428fc0f7e74e1d082c Mon Sep 17 00:00:00 2001 From: Chadwick Boulay Date: Sun, 20 Sep 2026 20:28:38 -0400 Subject: [PATCH 6/7] Finalize recordings asynchronously with explicit completion and bounded exit Keep the interface responsive while workers drain and the writer closes. Report finishing and stalled states, require confirmation for GUI force quit, and enforce a configurable CLI finalization deadline with nonzero exit on timeout. Checkpoint complete XDF chunks, flush footers immediately, and report worker or output errors instead of premature success. Preserve interruptible waits and buffered-sample draining. Add backend, CLI, and Qt state-machine regressions including a permanently stalled worker and forced process exit. --- BUILD.md | 6 +- CMakeLists.txt | 27 +++++- README.md | 11 ++- src/clirecorder.cpp | 66 ++++++++++--- src/mainwindow.cpp | 108 +++++++++++++++------ src/mainwindow.h | 9 +- src/recording.cpp | 162 +++++++++++++++++-------------- src/recording.h | 23 +++-- src/tcpinterface.cpp | 8 ++ src/tcpinterface.h | 1 + tests/cli_finalization.py | 77 +++++++++++++++ tests/fake_lsl/lsl_cpp.h | 25 ++++- tests/gui_finalization.cpp | 107 ++++++++++++++++++++ tests/gui_force_exit.py | 6 ++ tests/gui_recording_stub.cpp | 33 +++++++ tests/recording_finalization.cpp | 39 ++++++-- xdfwriter/xdfwriter.cpp | 30 ++++++ xdfwriter/xdfwriter.h | 7 ++ 18 files changed, 615 insertions(+), 130 deletions(-) create mode 100644 tests/cli_finalization.py create mode 100644 tests/gui_finalization.cpp create mode 100644 tests/gui_force_exit.py create mode 100644 tests/gui_recording_stub.cpp diff --git a/BUILD.md b/BUILD.md index 1e6f780..03aa553 100644 --- a/BUILD.md +++ b/BUILD.md @@ -104,8 +104,10 @@ ctest --test-dir build -C Release --output-on-failure These tests compile the recording implementation and XDF writer against a controlled inlet. They cover delayed clock measurements, stopping during an unavailable measurement, and a -worker that exceeds the join warning deadline. Every case checks that the file is finalized -immediately when the recording is destroyed. +worker that exceeds the join warning deadline. Completion is checked only after the file is +closed; stop requests remain nonblocking. A subprocess test verifies bounded CLI exit with a +worker that never returns, and GUI builds test event-loop responsiveness, stalled-state controls, +remote status, restart rejection, and deferred window close. The Qt test uses the offscreen platform. The real-stream integration suite additionally requires `pylsl` and `pyxdf`: diff --git a/CMakeLists.txt b/CMakeLists.txt index 661f453..3a4b181 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -229,11 +229,36 @@ if(LABRECORDER_BUILD_TESTING) # liblsl into this target: its timeout behavior is supplied by the test double. target_include_directories(test_recording_finalization PRIVATE tests/fake_lsl src) target_link_libraries(test_recording_finalization PRIVATE xdfwriter Threads::Threads) - foreach(scenario IN ITEMS delayed unavailable stalled) + foreach(scenario IN ITEMS delayed unavailable stalled failed abandoned) add_test(NAME recording_finalization_${scenario} COMMAND test_recording_finalization ${scenario}) set_tests_properties(recording_finalization_${scenario} PROPERTIES TIMEOUT 20) endforeach() + find_package(Python3 REQUIRED COMPONENTS Interpreter) + add_executable(test_recording_cli src/clirecorder.cpp src/recording.cpp) + target_include_directories(test_recording_cli PRIVATE tests/fake_lsl src) + target_link_libraries(test_recording_cli PRIVATE xdfwriter Threads::Threads) + add_test(NAME recording_cli_timeout + COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/cli_finalization.py + $) + set_tests_properties(recording_cli_timeout PROPERTIES TIMEOUT 25) + if(LABRECORDER_BUILD_GUI) + add_executable(test_gui_finalization tests/gui_finalization.cpp tests/gui_recording_stub.cpp + src/mainwindow.cpp src/mainwindow.h src/mainwindow.ui src/tcpinterface.cpp src/tcpinterface.h) + target_include_directories(test_gui_finalization PRIVATE src) + target_link_libraries(test_gui_finalization PRIVATE Qt6::Widgets Qt6::Network LSL::lsl Threads::Threads) + if(WIN32) + add_custom_command(TARGET test_gui_finalization POST_BUILD + COMMAND ${CMAKE_COMMAND} -E copy_if_different + $ $) + endif() + add_test(NAME recording_gui_finalization COMMAND test_gui_finalization) + add_test(NAME recording_gui_force_exit + COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/gui_force_exit.py + $) + set_tests_properties(recording_gui_finalization recording_gui_force_exit PROPERTIES TIMEOUT 25 + ENVIRONMENT "QT_QPA_PLATFORM=offscreen") + endif() endif() # ============================================================================= diff --git a/README.md b/README.md index 8664d72..d751584 100644 --- a/README.md +++ b/README.md @@ -63,9 +63,13 @@ The Block/Task field can be overwriten or selected among a list of items found i -Click "Start" to start a recording. If everything goes well, the status bar will now display the time since you started the recording, and more importantly, the current file size (the number before the kb) will grow slowly. This is a way to check whether you are still in fact recording data. The recording program cannot be closed while you are recording (as a safety measure). +Click "Start" to start a recording. If everything goes well, the status bar will now display the time since you started the recording, and more importantly, the current file size (the number before the kb) will grow slowly. This is a way to check whether you are still in fact recording data. Closing the window requests Stop and waits for finalization while keeping the interface responsive. -When you are done recording, click the "Stop" button. You can now close the program. See [the xdf repository](https://github.com/sccn/xdf) for tools and information on how to use the XDF files. +When you are done recording, click **Stop**. The status changes to **Finishing recording…**; a new recording cannot start until the file is finalized. **Stopped — file finalized** means the workers have finished and the file has been flushed and closed. + +If finalization takes more than five seconds, **Force quit…** becomes available. You can keep waiting or explicitly force the application to exit. A forced exit may leave an incomplete file or lose buffered samples; it never reports successful finalization. Completed chunks are flushed periodically and footers immediately to improve recovery, but this cannot guarantee recovery from a stalled disk or forced exit. + +`LabRecorderCLI` waits at most five seconds after Enter. Use `--stop-timeout SECONDS` before the output filename to change that deadline (greater than zero, at most 3600). Exit status **0** means finalization succeeded; **3** means the deadline expired and the file may be incomplete; **4** means recording or finalization failed. See [the xdf repository](https://github.com/sccn/xdf) for tools and information on how to use the XDF files. ## Preparing a Full Study @@ -89,9 +93,12 @@ Currently supported commands include: * `select none` * `start` * `stop` +* `status` * `update` * `filename ...` +`stop` acknowledges the request with `OK`; this is not a completion notification. Poll `status` for a newline-terminated state: `recording`, `finishing`, `stalled`, `stopped`, or `error`. Wait for `stopped` before restarting or using the file. `start` is rejected with `ERROR ` while a recording is active or finalizing. + `filename` is followed by a series of space-delimited options enclosed in curly braces. e.g. {root:C:\root_data_dir} * `root` - Sets the root data directory. * `template` - sets the File Name / Template. Will unselect BIDS option. May contain wildcards. diff --git a/src/clirecorder.cpp b/src/clirecorder.cpp index 55772fa..bb00bd8 100644 --- a/src/clirecorder.cpp +++ b/src/clirecorder.cpp @@ -1,22 +1,41 @@ #include "recording.h" #include "xdfwriter.h" +#include +#include #include +#include int main(int argc, char **argv) { - if (argc < 3 || (argc == 2 && std::string(argv[1]) == "-h")) { - std::cout << "Usage: " << argv[0] << " outputfile.xdf 'searchstr' ['searchstr2' ...]\n\n" - << "searchstr can be anything accepted by lsl_resolve_bypred\n"; - std::cout << "Keep in mind that your shell might remove quotes\n"; - std::cout << "Examples:\n\t" << argv[0] << " foo.xdf 'type=\"EEG\"' "; - std::cout << " 'host=\"LabPC1\" or host=\"LabPC2\"'\n\t"; - std::cout << argv[0] << " foo.xdf'name=\"Tobii and type=\"Eyetracker\"'\n"; + int output_arg = 1; + double stop_timeout = 5.0; + if (argc > 1 && std::string(argv[1]) == "--stop-timeout") { + try { + if (argc < 3) throw std::invalid_argument("missing value"); + size_t used = 0; + stop_timeout = std::stod(argv[2], &used); + if (used != std::string(argv[2]).size() || !std::isfinite(stop_timeout) || + stop_timeout <= 0 || stop_timeout > 3600) + throw std::invalid_argument("must be greater than zero and at most 3600 seconds"); + output_arg = 3; + } catch (const std::exception &e) { + std::cerr << "Invalid --stop-timeout: " << e.what() << std::endl; + return 1; + } + } + if (argc < output_arg + 2 || std::string(argv[output_arg]) == "--help" || + std::string(argv[output_arg]) == "-h") { + std::cout + << "Usage: " << argv[0] + << " [--stop-timeout SECONDS] outputfile.xdf 'searchstr' ['searchstr2' ...]\n" + << "Search strings use lsl_resolve_bypred syntax.\n" + << "Stop timeout defaults to 5 seconds; an unfinished file exits with status 3.\n"; return 1; } std::vector infos = lsl::resolve_streams(), recordstreams; - for (int i = 2; i < argc; ++i) { + for (int i = output_arg + 1; i < argc; ++i) { bool matched = false; for (const auto &info : infos) { if (info.matches_query(argv[i])) { @@ -35,7 +54,32 @@ int main(int argc, char **argv) { std::vector watchfor; std::map sync_options; std::cout << "Starting the recording, press Enter to quit" << std::endl; - recording r(argv[1], recordstreams, watchfor, sync_options, true); - std::cin.get(); - return 0; + try { + recording r(argv[output_arg], recordstreams, watchfor, sync_options, true); + std::cin.get(); + r.requestStop(); + const auto timeout = std::chrono::duration_cast( + std::chrono::duration(stop_timeout)); + if (!r.waitForFinished(timeout)) { + // Even reporting the timeout must not hang if a stalled worker holds an iostream + // lock or stderr is backed by a blocked pipe. Allow a brief best-effort diagnostic. + std::thread([] { + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + std::_Exit(3); + }).detach(); + std::cerr << "Finalization timed out. The recording may be incomplete: " + << argv[output_arg] << std::endl; + // No destructors/atexit handlers: a stalled worker could hold their locks too. + std::_Exit(3); + } + const auto error = r.finalizationError(); + if (!error.empty()) { + std::cerr << "Finalization failed: " << error << std::endl; + return 4; + } + return 0; + } catch (const std::exception &e) { + std::cerr << "Recording failed: " << e.what() << std::endl; + return 4; + } } diff --git a/src/mainwindow.cpp b/src/mainwindow.cpp index be82724..746dc7e 100644 --- a/src/mainwindow.cpp +++ b/src/mainwindow.cpp @@ -15,6 +15,7 @@ using QRegExp = QRegularExpression; #endif #include +#include #include // recording class @@ -88,29 +89,69 @@ MainWindow::MainWindow(QWidget *parent, const char *config_file) timer = std::make_unique(this); connect(&*timer, &QTimer::timeout, this, &MainWindow::statusUpdate); - timer->start(1000); + timer->start(100); QString cfgfilepath = find_config_file(config_file); load_config(cfgfilepath); } -void MainWindow::statusUpdate() const { - if (currentRecording) { - auto elapsed = static_cast(lsl::local_clock() - startTime); - QString recFilename = replaceFilename(QDir::cleanPath(ui->lineEdit_template->text())); - auto fileinfo = QFileInfo(QDir::cleanPath(ui->rootEdit->text()) + '/' + recFilename); - fileinfo.refresh(); - auto size = fileinfo.size(); - QString timeString = QStringLiteral("Recording to %1 (%2; %3kb)") - .arg(QDir::toNativeSeparators(recFilename), - QTime(0,0).addSecs(elapsed).toString("hh:mm:ss"), - QString::number(size / 1000)); - statusBar()->showMessage(timeString); +void MainWindow::setRemoteState(const QString &state) { + if (rcs) rcs->recordingState = state; +} + +void MainWindow::statusUpdate() { + if (!currentRecording) return; + if (finishing) { + if (currentRecording->isFinished()) { + const auto error = currentRecording->finalizationError(); + currentRecording.reset(); + finishing = false; + ui->startButton->setEnabled(true); + ui->stopButton->setEnabled(false); + ui->stopButton->setText("Stop"); + setRemoteState(error.empty() ? "stopped" : "error"); + statusBar()->showMessage(error.empty() ? QStringLiteral("Stopped — file finalized") + : QStringLiteral("Finalization failed — recording may be incomplete")); + if (!error.empty()) { + closeWhenFinished = false; + QMessageBox::critical(this, "Recording incomplete", + QString::fromStdString(error) + "\n" + recordingPath); + } + if (closeWhenFinished) close(); + } else if (finalizationTimer.elapsed() >= 5000) { + setRemoteState("stalled"); + statusBar()->showMessage(QStringLiteral("Still finishing — file is not finalized. Wait, or choose Force quit.")); + ui->stopButton->setText(QStringLiteral("Force quit…")); + ui->stopButton->setEnabled(true); + } + return; } + const auto elapsed = static_cast(lsl::local_clock() - startTime); + const QFileInfo fileinfo(recordingPath); + statusBar()->showMessage(QStringLiteral("Recording to %1 (%2; %3kb)") + .arg(QDir::toNativeSeparators(recordingPath), + QTime(0, 0).addSecs(elapsed).toString("hh:mm:ss"), QString::number(fileinfo.size() / 1000))); +} + +void MainWindow::confirmForceQuit() { + QMessageBox dialog(QMessageBox::Warning, "Recording is still finishing", + "The file has not been finalized. Force quitting may lose buffered samples or leave " + "an incomplete recording.\n" + recordingPath, QMessageBox::NoButton, this); + auto *wait = dialog.addButton("Keep waiting", QMessageBox::RejectRole); + auto *quit = dialog.addButton("Force quit", QMessageBox::DestructiveRole); + dialog.setDefaultButton(wait); + dialog.setEscapeButton(wait); + dialog.exec(); + if (dialog.clickedButton() == quit && currentRecording && !currentRecording->isFinished()) + std::_Exit(3); } void MainWindow::closeEvent(QCloseEvent *ev) { - if (currentRecording) ev->ignore(); + if (!currentRecording) { ev->accept(); return; } + ev->ignore(); + closeWhenFinished = true; + if (!finishing) stopRecording(); + else if (finalizationTimer.elapsed() >= 5000) confirmForceQuit(); } void MainWindow::blockSelected(const QString &block) { @@ -466,8 +507,18 @@ void MainWindow::startRecording() { } qInfo() << "Missing: " << missingStreams; - currentRecording = std::make_unique(recFilename.toStdString(), - requestedAndAvailableStreams, watchfor, syncOptionsByStreamName, true); + try { + currentRecording = std::make_unique(recFilename.toStdString(), + requestedAndAvailableStreams, watchfor, syncOptionsByStreamName, true); + } catch (const std::exception &e) { + setRemoteState("error"); + QMessageBox::critical(this, "Cannot start recording", QString::fromStdString(e.what())); + return; + } + recordingPath = recFilename; + finishing = false; + closeWhenFinished = false; + setRemoteState("recording"); ui->stopButton->setEnabled(true); ui->startButton->setEnabled(false); startTime = (int)lsl::local_clock(); @@ -479,18 +530,18 @@ void MainWindow::startRecording() { } void MainWindow::stopRecording() { - - if (currentRecording) { - try { - currentRecording = nullptr; - } catch (std::exception &e) { qWarning() << "exception on stop: " << e.what(); } - ui->startButton->setEnabled(true); - ui->stopButton->setEnabled(false); - statusBar()->showMessage("Stopped"); - } else if (!hideWarnings) { - QMessageBox::information( - this, "Not recording", "There is not ongoing recording", QMessageBox::Ok); + if (!currentRecording) return; + if (finishing) { + if (finalizationTimer.elapsed() >= 5000) confirmForceQuit(); + return; } + finishing = true; + finalizationTimer.start(); + currentRecording->requestStop(); + ui->startButton->setEnabled(false); + ui->stopButton->setEnabled(false); + setRemoteState("finishing"); + statusBar()->showMessage(QStringLiteral("Finishing recording…")); } void MainWindow::selectAllStreams() { @@ -640,6 +691,8 @@ void MainWindow::enableRcs(bool bEnable) { } else if (bEnable) { uint16_t port = ui->rcsport->value(); rcs = std::make_unique(port); + setRemoteState(!currentRecording ? "stopped" : !finishing ? "recording" + : finalizationTimer.elapsed() >= 5000 ? "stalled" : "finishing"); // TODO: Add some method to RemoteControlSocket to report if its server is listening (i.e. was successful). connect(rcs.get(), &RemoteControlSocket::refresh_streams, this, &MainWindow::refreshStreams); connect(rcs.get(), &RemoteControlSocket::start, this, &MainWindow::rcsStartRecording); @@ -669,6 +722,7 @@ void MainWindow::rcsStartRecording() { } void MainWindow::rcsStopRecording() { + if (finishing) return; // Remote retries must never open a force-quit dialog. hideWarnings = true; stopRecording(); } diff --git a/src/mainwindow.h b/src/mainwindow.h index abeaad4..994de5b 100644 --- a/src/mainwindow.h +++ b/src/mainwindow.h @@ -1,6 +1,7 @@ #ifndef MAINWINDOW_H #define MAINWINDOW_H #include +#include #include #include #include @@ -42,7 +43,7 @@ class MainWindow : public QMainWindow { ~MainWindow() noexcept override; private slots: - void statusUpdate(void) const; + void statusUpdate(void); void closeEvent(QCloseEvent *ev) override; void blockSelected(const QString &block); std::vector refreshStreams(void); @@ -69,6 +70,12 @@ private slots: void save_config(QString filename); std::unique_ptr currentRecording; + bool finishing = false; + bool closeWhenFinished = false; + QElapsedTimer finalizationTimer; + QString recordingPath; + void confirmForceQuit(); + void setRemoteState(const QString &state); std::unique_ptr rcs; int startTime; diff --git a/src/recording.cpp b/src/recording.cpp index 69b1b96..17d4e8d 100644 --- a/src/recording.cpp +++ b/src/recording.cpp @@ -45,8 +45,7 @@ const double max_time_correction_wait = 2; // blocking network calls are issued in slices of this length (in seconds) so that a shutdown // request is noticed promptly instead of after the full timeout const double network_poll_interval = 0.2; -// time granted to the stream threads to drain their inlets and write their footers before the -// inlets are forcibly closed +// initial grace for workers to drain their inlets and write their footers const auto teardown_grace = std::chrono::milliseconds(300); // time before reporting a slow worker; finalization still waits for it to finish const auto max_join_wait = std::chrono::seconds(2); @@ -200,10 +199,9 @@ inline void join_workers( /** * The recording state, and the thread bodies that operate on it. * - * Every recording thread holds a shared_ptr to this, as does the recording object. - * stop_and_join() joins all workers, including nested workers, before the recording handle - * releases its reference and closes the file. A fast stop must not leave buffered output owned - * by a detached worker that process exit could kill before the writer flushes. + * Workers and the background finalizer retain this state. The UI handle owns only a + * completion signal. The finalizer joins all workers, closes the file, and releases the state + * before publishing completion; callers can poll or wait with their own finite deadline. */ struct recording::impl : std::enable_shared_from_this { impl(const std::string &filename, std::map syncOptions, bool collect_offsets) @@ -220,8 +218,8 @@ struct recording::impl : std::enable_shared_from_this { const std::vector &streams, const std::vector &watchfor); /// Ask the threads to finish and join them all before closing the file. - /// Called from the recording object, never from a recording thread. - void stop_and_join() noexcept; + /// Called only from the background finalizer, never from the UI or a recording worker. + std::string stop_and_join(); void requestStop() noexcept; @@ -236,6 +234,7 @@ struct recording::impl : std::enable_shared_from_this { std::atomic streamid_; // the highest streamid allocated so far // phase-of-recording state (headers, streaming data, or footers) + std::atomic recording_failed_{false}; std::atomic shutdown_; // whether we are trying to shut down std::condition_variable shutdown_cv_; // signals shutdown so that every interruptible wait returns at once @@ -253,11 +252,6 @@ struct recording::impl : std::enable_shared_from_this { // recording jobs and are now ready to write a footer std::mutex phase_mut_; // a mutex to protect the phase state - // inlets with potentially pending network I/O, to be aborted if their thread does not stop in - // time - std::vector active_inlets_; - std::mutex inlets_mut_; // a mutex to protect the active inlet list - // data structure to collect the time offsets for every stream offset_lists offset_lists_; // the clock offset lists for each stream (to be written into the footer) @@ -318,13 +312,6 @@ struct recording::impl : std::enable_shared_from_this { /// @throws shutdown_requested if the recording was stopped while retrieving the metadata lsl::stream_info fetch_info(const inlet_p &in); - // === inlet bookkeeping === - - void register_inlet(const inlet_p &in); - void unregister_inlet(const inlet_p &in) noexcept; - /// close every registered inlet, aborting any blocking socket call in progress - void close_active_inlets() noexcept; - // === phase registration & condition checks === // writing is coordinated across threads in three phases to keep the file chunks sorted @@ -361,42 +348,89 @@ void recording::impl::start( boundary_thread_ = spawn_worker([self] { self->record_boundaries(); }); } -void recording::impl::stop_and_join() noexcept { - try { - // set the shutdown flag (from now on no more new streams) and wake every waiting thread - requestStop(); - - // give the stream threads a moment to drain their inlets and write their footers by - // themselves; closing an inlet discards what it still holds, so that is a last resort - timed_join_some(stream_threads_, teardown_grace); - if (!stream_threads_.empty()) { - // a thread is stuck in a blocking socket call; closing its inlet aborts that call - close_active_inlets(); - join_workers(stream_threads_, max_join_wait); - } - join_worker(boundary_thread_, max_join_wait); - log_out("Closing the file."); - } catch (std::exception &e) { - log_out("Error while closing the recording: ", e.what()); +std::string recording::impl::stop_and_join() { + requestStop(); + // This runs exclusively on the background finalizer. A slow worker can delay + // completion, but it cannot block the UI, its timeout, or its force-quit action. + timed_join_some(stream_threads_, teardown_grace); + if (!stream_threads_.empty()) { + // Keep draining rather than closing every inlet and discarding buffered samples. + join_workers(stream_threads_, max_join_wait); } + join_worker(boundary_thread_, max_join_wait); + file_.close(); + return recording_failed_ ? "A recording worker failed; the file may be incomplete. See the log." + : ""; } +struct recording::completion { + std::mutex mutex; + std::condition_variable changed; + bool startup_finished = false; + bool stop_requested = false; + std::promise result; +}; + recording::recording(const std::string &filename, const std::vector &streams, const std::vector &watchfor, std::map syncOptions, bool collect_offsets) - : impl_(std::make_shared(filename, std::move(syncOptions), collect_offsets)) { + : completion_(std::make_shared()), result_(completion_->result.get_future().share()) { + auto state = std::make_shared(filename, std::move(syncOptions), collect_offsets); + // Start the finalizer before workers so partial startup failures can also be cleaned + // up off the caller's thread. Its control mutex is never used by recording workers. + std::thread([state, done = completion_]() mutable { + { + std::unique_lock lock(done->mutex); + done->changed.wait(lock, [&] { return done->startup_finished && done->stop_requested; }); + } + std::string error; + try { + error = state->stop_and_join(); + } catch (const std::exception &e) { + error = e.what(); + } catch (...) { + error = "Unknown error finalizing the recording."; + } + state.reset(); + // Includes writer close/flush and inlet destruction, not merely thread completion. + done->result.set_value(std::move(error)); + }).detach(); try { - impl_->start(streams, watchfor); + state->start(streams, watchfor); } catch (...) { - // some threads may already be running, and our destructor will not run if we throw - impl_->stop_and_join(); + { + std::lock_guard lock(completion_->mutex); + completion_->startup_finished = true; + completion_->stop_requested = true; + } + completion_->changed.notify_one(); throw; } + { + std::lock_guard lock(completion_->mutex); + completion_->startup_finished = true; + } + completion_->changed.notify_one(); +} + +recording::~recording() { requestStop(); } + +void recording::requestStop() noexcept { + { + std::lock_guard lock(completion_->mutex); + completion_->stop_requested = true; + } + completion_->changed.notify_one(); } -recording::~recording() { impl_->stop_and_join(); } +bool recording::waitForFinished(std::chrono::milliseconds timeout) const { + return result_.wait_for(timeout) == std::future_status::ready; +} -void recording::requestStop() noexcept { impl_->requestStop(); } +std::string recording::finalizationError() const { + if (!isFinished()) throw std::logic_error("Recording is still finalizing"); + return result_.get(); +} void recording::impl::requestStop() noexcept { { @@ -428,29 +462,6 @@ void recording::impl::stop_offsets(const offset_flag_p &offset_shutdown) noexcep shutdown_cv_.notify_all(); } -void recording::impl::register_inlet(const inlet_p &in) { - std::lock_guard lock(inlets_mut_); - active_inlets_.push_back(in); -} - -void recording::impl::unregister_inlet(const inlet_p &in) noexcept { - if (!in) return; - std::lock_guard lock(inlets_mut_); - active_inlets_.erase( - std::remove(active_inlets_.begin(), active_inlets_.end(), in), active_inlets_.end()); -} - -void recording::impl::close_active_inlets() noexcept { - std::lock_guard lock(inlets_mut_); - for (auto &in : active_inlets_) { - try { - in->close_stream(); - } catch (std::exception &e) { - log_err("Error while closing an inlet: ", e.what()); - } - } -} - bool recording::impl::open_inlet(const inlet_p &in) { // subscribe in short slices: a single open_stream(max_open_wait) would keep us from noticing a // stop for up to max_open_wait seconds @@ -514,6 +525,7 @@ void recording::impl::record_from_query_results(const std::string &query) { // wait for all our threads to join join_workers(threads, max_join_wait); } catch (std::exception &e) { + recording_failed_ = true; log_out("Error in the record_from_query_results thread: ", e.what()); } } @@ -534,7 +546,6 @@ void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool p // open an inlet to read from (and subscribe to data immediately) in = std::make_shared(src); - register_inlet(in); auto it = sync_options_by_stream_.find(src.name() + " (" + src.hostname() + ")"); if (it != sync_options_by_stream_.end()) in->set_postprocessing(it->second); @@ -605,6 +616,7 @@ void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool p leave_streaming_phase(phase_locked); // the header is already on disk, so fall through to the footer instead of leaving the // stream without one + recording_failed_ = true; log_err("Error while recording from ", src.name(), ": ", e.what()); } @@ -640,18 +652,24 @@ void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool p } catch (shutdown_requested &e) { log_out("Recording from ", src.name(), " ended: ", e.what()); } catch (std::exception &e) { + recording_failed_ = true; log_out("Error in the record_from_streaminfo thread: ", e.what()); } - unregister_inlet(in); } void recording::impl::record_boundaries() { try { + auto next_boundary = Clock::now() + boundary_interval; while (!shutdown_) { - if (wait_for_shutdown(boundary_interval)) break; - file_.write_boundary_chunk(); + if (wait_for_shutdown(std::chrono::seconds(1))) break; + if (Clock::now() >= next_boundary) { + file_.write_boundary_chunk(); + next_boundary = Clock::now() + boundary_interval; + } + file_.checkpoint(); } } catch (std::exception &e) { + recording_failed_ = true; log_out("Error in the record_boundaries thread: ", e.what()); } } @@ -689,6 +707,7 @@ void recording::impl::record_offsets( offset_lists_[streamid].emplace_back(now - offset, offset); } } catch (std::exception &e) { + recording_failed_ = true; log_out("Error in the record_offsets thread: ", e.what()); } log_out("Offsets thread is finished"); @@ -805,7 +824,8 @@ void recording::impl::typed_transfer_loop(streamid_t streamid, double srate, con in->pull_chunk_multiplexed(chunk, ×tamps, 0.0); write_chunk(); } catch (std::exception &e) { - // the inlet was closed under us during teardown; the footer matters more + // Preserve a footer, but report that draining failed. + recording_failed_ = true; log_err("Could not drain stream ", streamid, " on stop: ", e.what()); } } catch (std::exception &) { diff --git a/src/recording.h b/src/recording.h index 09607c6..0ea148d 100644 --- a/src/recording.h +++ b/src/recording.h @@ -2,6 +2,8 @@ #define RECORDING_H #include +#include +#include #include #include #include @@ -30,19 +32,28 @@ class recording { const std::vector &watchfor, std::map syncOptions, bool collect_offsets = true); - /** Destructor. - * Stops and joins every recording thread, then closes and flushes the file. Network waits - * observe shutdown promptly; a slow disk write must finish before destruction returns. - */ + /// Requests shutdown without waiting. Callers must observe completion before normal exit. ~recording(); /// Ask all recording threads to wrap up. Returns immediately. void requestStop() noexcept; + /// Wait at most timeout for all workers AND the output file to finish. Does not request stop. + bool waitForFinished(std::chrono::milliseconds timeout) const; + bool isFinished() const { return waitForFinished(std::chrono::milliseconds(0)); } + /// Available after completion: empty on success, otherwise a finalization error. + std::string finalizationError() const; + /// Retain a completion receipt when releasing the nonblocking recording handle. + std::shared_future completionResult() const { return result_; } + recording(const recording &) = delete; + recording &operator=(const recording &) = delete; private: struct impl; - /// Workers retain the state while running; destruction joins them before releasing it. - std::shared_ptr impl_; + struct completion; + // The finalizer owns impl, never the UI handle. Dropping the handle cannot close a file + // or join a thread on the caller; completion is published only after impl is destroyed. + std::shared_ptr completion_; + std::shared_future result_; }; #endif diff --git a/src/tcpinterface.cpp b/src/tcpinterface.cpp index 044486b..4422b22 100644 --- a/src/tcpinterface.cpp +++ b/src/tcpinterface.cpp @@ -17,6 +17,14 @@ void RemoteControlSocket::addClient() { void RemoteControlSocket::handleLine(QString s, QTcpSocket *sock) { qInfo() << s; + if (s == "status") { + sock->write(recordingState.toUtf8() + '\n'); + return; + } + if (s == "start" && recordingState != "stopped" && recordingState != "error") { + sock->write("ERROR " + recordingState.toUtf8() + '\n'); + return; + } if (s == "start") emit start(); else if (s == "stop") diff --git a/src/tcpinterface.h b/src/tcpinterface.h index 3eeef1e..080cf41 100644 --- a/src/tcpinterface.h +++ b/src/tcpinterface.h @@ -13,6 +13,7 @@ class RemoteControlSocket : public QObject { QList clients; public: RemoteControlSocket(uint16_t port); + QString recordingState = "stopped"; signals: void refresh_streams(); diff --git a/tests/cli_finalization.py b/tests/cli_finalization.py new file mode 100644 index 0000000..640e223 --- /dev/null +++ b/tests/cli_finalization.py @@ -0,0 +1,77 @@ +"""Exercise process exit with the real CLI/recorder and a controlled LSL inlet.""" +import os +from pathlib import Path +import queue +import subprocess +import sys +import tempfile +import threading +import time + + +def run_case(binary, directory, stalled): + path = Path(directory) / ("stalled.xdf" if stalled else "complete.xdf") + env = dict(os.environ) + if stalled: + env["LSL_TEST_STALL"] = "1" + else: + env.pop("LSL_TEST_STALL", None) + proc = subprocess.Popen( + [binary, "--stop-timeout", "0.5", str(path), "test"], + stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, + text=True, env=env, + ) + lines = queue.Queue() + output = [] + + def read(): + for line in proc.stdout: + output.append(line) + lines.put(line) + + reader = threading.Thread(target=read, daemon=True) + reader.start() + try: + needle = "TEST: offset query stalled" if stalled else "Started data collection" + deadline = time.monotonic() + 12 + while True: + line = lines.get(timeout=max(0.01, deadline - time.monotonic())) + if needle in line: + break + start = time.monotonic() + proc.stdin.write("\n") + proc.stdin.flush() + proc.wait(timeout=2) + reader.join(timeout=1) + elapsed = time.monotonic() - start + assert proc.returncode == (3 if stalled else 0), "".join(output) + assert elapsed < 1.5, f"CLI did not honor its timeout: {elapsed}" + data = path.read_bytes() + assert data.startswith(b"XDF:"), "no recoverable XDF header was flushed" + if stalled: + assert "Finalization timed out" in "".join(output) + # A permanently stalled worker cannot close the writer. Periodic checkpoints + # must nevertheless have preserved complete header and sample chunks. + tags = [] + pos = 4 + while pos < len(data): + width = data[pos] + assert width in (1, 4, 8) + length = int.from_bytes(data[pos + 1:pos + 1 + width], "little") + pos += 1 + width + assert pos + length <= len(data), "checkpoint ended inside an XDF chunk" + tags.append(int.from_bytes(data[pos:pos + 2], "little")) + pos += length + assert 2 in tags and 3 in tags, "recorded samples were not checkpointed" + else: + assert b"" in data, "success reported before footer flush" + print(f"{'stalled' if stalled else 'normal'}: exit={proc.returncode}, {elapsed:.3f}s") + finally: + if proc.poll() is None: + proc.kill() + proc.wait() + + +with tempfile.TemporaryDirectory() as directory: + run_case(sys.argv[1], directory, False) + run_case(sys.argv[1], directory, True) diff --git a/tests/fake_lsl/lsl_cpp.h b/tests/fake_lsl/lsl_cpp.h index a7caef3..3ddfa2a 100644 --- a/tests/fake_lsl/lsl_cpp.h +++ b/tests/fake_lsl/lsl_cpp.h @@ -5,6 +5,8 @@ // network dependency. #include #include +#include +#include #include #include #include @@ -18,7 +20,13 @@ struct timeout_error : std::runtime_error { timeout_error() : std::runtime_error("test timeout") {} }; struct inlet_state { - enum mode { delayed_result, unavailable, stalled_worker } behavior; + enum mode { + delayed_result, + unavailable, + stalled_worker, + permanent_stall, + failed_transfer + } behavior; std::atomic query_started{false}, query_finished{false}; std::atomic query_calls{0}; clock::time_point result_ready; @@ -34,6 +42,7 @@ class stream_info { std::string uid() const { return "finalization-test"; } std::string source_id() const { return uid(); } channel_format_t channel_format() const { return cf_float32; } + bool matches_query(const std::string &) const { return true; } double nominal_srate() const { return 100; } std::string as_xml() const { return "FinalizationTest1" @@ -46,6 +55,11 @@ inline double local_clock() { return std::chrono::duration(clock::now().time_since_epoch()).count(); } inline std::vector resolve_stream(const std::string &, int, double) { return {}; } +inline std::vector resolve_streams() { + return {stream_info(std::make_shared(std::getenv("LSL_TEST_STALL") + ? inlet_state::permanent_stall + : inlet_state::delayed_result))}; +} class stream_inlet { stream_info info_; @@ -59,6 +73,10 @@ class stream_inlet { stream_info info(double) { return info_; } int get_channel_count() const { return 1; } template double pull_sample(std::vector &sample, double timeout) { + if (info_.state->behavior == inlet_state::failed_transfer) { + info_.state->query_started = true; + throw std::runtime_error("simulated transfer failure"); + } if (!sent_sample_) { sent_sample_ = true; sample.assign(1, T{}); @@ -77,6 +95,11 @@ class stream_inlet { if (state.query_calls++ == 0) state.result_ready = clock::now() + std::chrono::milliseconds(600); state.query_started = true; + if (state.behavior == inlet_state::permanent_stall) { + std::cout << "TEST: offset query stalled" << std::endl; + for (;;) + std::this_thread::sleep_for(std::chrono::hours(1)); + } if (state.behavior == inlet_state::stalled_worker) { // Deliberately exceed both the offset grace and outer join deadline. Even // an unexpectedly slow worker must finish before the caller can exit the diff --git a/tests/gui_finalization.cpp b/tests/gui_finalization.cpp new file mode 100644 index 0000000..908f763 --- /dev/null +++ b/tests/gui_finalization.cpp @@ -0,0 +1,107 @@ +#include "mainwindow.h" +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +extern std::atomic release_finalization; +extern std::atomic recording_starts; + +static void require(bool value, const char *message) { + if (!value) throw std::runtime_error(message); +} +static void pump(int milliseconds) { + QElapsedTimer timer; + timer.start(); + do { + QApplication::processEvents(); + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } while (timer.elapsed() < milliseconds); +} +static QByteArray command(QTcpSocket &socket, const char *text) { + socket.write(text); + socket.flush(); + QElapsedTimer deadline; + deadline.start(); + while (!socket.bytesAvailable() && deadline.elapsed() < 3000) + pump(1); + return socket.readAll(); +} + +int main(int argc, char **argv) { + QApplication app(argc, argv); + try { + QTemporaryDir directory; + QTcpServer reservation; + require(reservation.listen(QHostAddress::LocalHost, 0), "cannot reserve port"); + const auto port = reservation.serverPort(); + reservation.close(); + const auto config = directory.filePath("test.cfg"); + QFile file(config); + require(file.open(QIODevice::WriteOnly), "cannot write config"); + file.write(("StudyRoot=" + directory.path() + + "\nPathTemplate=test.xdf\nRCSEnabled=1\nRCSPort=" + QString::number(port) + + '\n') + .toUtf8()); + file.close(); + const auto configBytes = config.toUtf8(); + MainWindow window(nullptr, configBytes.constData()); + window.show(); + QTcpSocket socket; + socket.connectToHost(QHostAddress::LocalHost, port); + require(socket.waitForConnected(1000), "cannot connect remote control"); + require(command(socket, "start\n") == "OK", "start was not accepted"); + require(recording_starts == 1, "recording was not started"); + int heartbeats = 0; + QTimer heartbeat; + QObject::connect(&heartbeat, &QTimer::timeout, [&] { ++heartbeats; }); + heartbeat.start(10); + QElapsedTimer stop; + stop.start(); + require(command(socket, "stop\n") == "OK", "stop was not accepted"); + require(stop.elapsed() < 200, "stop blocked the GUI"); + require(command(socket, "status\n") == "finishing\n", "premature stopped status"); + require(command(socket, "start\n") == "ERROR finishing\n", "start allowed while finishing"); + auto *start = window.findChild("startButton"); + auto *stopButton = window.findChild("stopButton"); + require(start && stopButton && !start->isEnabled(), "Start enabled before completion"); + pump(5200); + require(heartbeats > 100, "GUI event loop stopped during stalled finalization"); + require(command(socket, "status\n") == "stalled\n", "stall was not reported"); + require(stopButton->isEnabled() && stopButton->text().contains("Force quit"), + "force-quit action unavailable"); + // Closing while stalled must offer an escape, with Keep waiting as the safe default. + const bool forceQuit = argc > 1 && std::string(argv[1]) == "--force-quit"; + QTimer::singleShot(0, [forceQuit] { + for (auto *widget : QApplication::topLevelWidgets()) + if (auto *dialog = qobject_cast(widget)) { + if (forceQuit) { + for (auto *button : dialog->buttons()) + if (button->text() == "Force quit") button->click(); + } else dialog->reject(); + } + }); + window.close(); + require(!forceQuit, "Force quit did not terminate the process"); + require(window.isVisible(), "Keep waiting closed the window"); + release_finalization = true; + pump(300); + require(command(socket, "status\n") == "stopped\n", "completion not reported"); + require(!window.isVisible(), "pending close was not completed"); + std::cout << "GUI stayed responsive, rejected restart, and closed only after completion\n"; + return 0; + } catch (const std::exception &e) { + release_finalization = true; + std::cerr << e.what() << '\n'; + return 1; + } +} diff --git a/tests/gui_force_exit.py b/tests/gui_force_exit.py new file mode 100644 index 0000000..17e527c --- /dev/null +++ b/tests/gui_force_exit.py @@ -0,0 +1,6 @@ +"""A GUI with permanently pending completion must honor confirmed Force quit.""" +import subprocess +import sys + +result = subprocess.run([sys.argv[1], "--force-quit"], timeout=20) +assert result.returncode == 3, f"expected forced-exit status 3, got {result.returncode}" diff --git a/tests/gui_recording_stub.cpp b/tests/gui_recording_stub.cpp new file mode 100644 index 0000000..7b5e401 --- /dev/null +++ b/tests/gui_recording_stub.cpp @@ -0,0 +1,33 @@ +// Isolate the Qt state machine from stream discovery and recording timing. Backend +// completion semantics are tested separately against the real recording.cpp. +#include "recording.h" +#include +#include + +std::atomic release_finalization{false}; +std::atomic recording_starts{0}; + +struct recording::completion { + std::atomic stopping{false}; + std::promise result; +}; + +recording::recording(const std::string &, const std::vector &, + const std::vector &, std::map, bool) + : completion_(std::make_shared()), + result_(completion_->result.get_future().share()) { + ++recording_starts; +} +recording::~recording() { requestStop(); } +void recording::requestStop() noexcept { + if (completion_->stopping.exchange(true)) return; + std::thread([done = completion_] { + while (!release_finalization) + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + done->result.set_value(""); + }).detach(); +} +bool recording::waitForFinished(std::chrono::milliseconds timeout) const { + return result_.wait_for(timeout) == std::future_status::ready; +} +std::string recording::finalizationError() const { return result_.get(); } diff --git a/tests/recording_finalization.cpp b/tests/recording_finalization.cpp index 040d97e..e5d8dd0 100644 --- a/tests/recording_finalization.cpp +++ b/tests/recording_finalization.cpp @@ -13,10 +13,11 @@ static void require(bool value, const char *message) { int main(int argc, char **argv) { try { - require(argc == 2, "expected delayed, unavailable, or stalled"); + require(argc == 2, "expected a finalization test scenario"); const std::string scenario = argv[1]; const auto mode = scenario == "delayed" ? lsl::inlet_state::delayed_result : scenario == "unavailable" ? lsl::inlet_state::unavailable + : scenario == "failed" ? lsl::inlet_state::failed_transfer : lsl::inlet_state::stalled_worker; auto state = std::make_shared(mode); const auto filename = "finalization-" + scenario + ".xdf"; @@ -30,17 +31,39 @@ int main(int argc, char **argv) { std::this_thread::sleep_for(std::chrono::milliseconds(1)); require(state->query_started, "offset worker never started"); const auto stop = lsl::clock::now(); - rec.reset(); + if (scenario == "abandoned") { + const auto done = rec->completionResult(); + rec.reset(); + require(lsl::clock::now() - stop < std::chrono::milliseconds(100), + "dropping a handle blocked on a stalled worker"); + require(done.wait_for(std::chrono::seconds(6)) == std::future_status::ready, + "background cleanup did not finish"); + require(done.get().empty() && state->query_finished, + "background cleanup did not preserve worker lifetime"); + std::filesystem::remove(filename); + return 0; + } + rec->requestStop(); + rec->requestStop(); // Idempotent, including while a worker is stalled. + require(lsl::clock::now() - stop < std::chrono::milliseconds(100), + "Stop blocked the caller"); + if (scenario == "stalled") + require(!rec->waitForFinished(std::chrono::milliseconds(100)), + "stalled worker reported done"); + require(rec->waitForFinished(std::chrono::seconds(6)), "finalization did not finish"); + require(rec->finalizationError().empty() == (scenario != "failed"), + "finalization did not accurately report worker failure"); const auto elapsed = std::chrono::duration(lsl::clock::now() - stop).count(); + rec.reset(); - // Read immediately, with no grace period after destruction: this is what a - // CLI caller needs before exiting. A detached owner leaves this small file - // in the writer's buffer. + // Completion must include closing and flushing the writer, not just requesting stop. std::ifstream file(filename, std::ios::binary); const std::string contents((std::istreambuf_iterator(file)), {}); require(contents.substr(0, 4) == "XDF:", - "writer was not flushed before destruction returned"); - require(contents.find("1") != std::string::npos, + "writer was not flushed before completion"); + require(contents.find(scenario == "failed" + ? "0" + : "1") != std::string::npos, "stream footer is missing or inconsistent"); require(contents.find("") != std::string::npos, "stream footer was not completely flushed"); @@ -50,7 +73,7 @@ int main(int argc, char **argv) { require(contents.find("") != std::string::npos, "offset missing from footer"); } else if (scenario == "unavailable") { require(elapsed < 1.0, "stop waited for the full offset query budget"); - } else { + } else if (scenario == "stalled") { require(state->query_finished, "destructor abandoned a running writer owner"); } file.close(); diff --git a/xdfwriter/xdfwriter.cpp b/xdfwriter/xdfwriter.cpp index 2e89314..4e72901 100644 --- a/xdfwriter/xdfwriter.cpp +++ b/xdfwriter/xdfwriter.cpp @@ -28,6 +28,7 @@ XDFWriter::XDFWriter(const std::string &filename) file_.push( boost::iostreams::file_descriptor_sink(filename, std::ios::binary | std::ios::trunc)); #endif + file_.exceptions(std::ios::badbit | std::ios::failbit); // [MagicCode] file_ << "XDF:"; // [FileHeader] chunk @@ -46,6 +47,33 @@ void XDFWriter::_write_chunk( _write_chunk_header(tag, content.length(), streamid_p); // [Content] file_ << content; + flush_if_due(tag == chunk_tag_t::fileheader || tag == chunk_tag_t::streamheader || + tag == chunk_tag_t::streamfooter); +} + +void XDFWriter::flush_if_due(bool force) { + const auto now = std::chrono::steady_clock::now(); + if (force || now - last_flush_ >= std::chrono::seconds(1)) { + // Only called after a complete chunk, under write_mut (or during construction). + // This preserves recoverable output on force-quit; it is not a disk fsync. + file_.flush(); + last_flush_ = now; + } +} + +void XDFWriter::close() { + std::lock_guard lock(write_mut); + flush_if_due(true); +#ifdef XDFZ_SUPPORT + file_.reset(); +#else + file_.close(); +#endif +} + +void XDFWriter::checkpoint() { + std::lock_guard lock(write_mut); + flush_if_due(true); } void XDFWriter::_write_chunk_header( @@ -80,6 +108,7 @@ void XDFWriter::write_stream_offset(streamid_t streamid, double now, double offs write_little_endian(file_, now - offset); // [OffsetValue] write_little_endian(file_, offset); + flush_if_due(); } void XDFWriter::write_boundary_chunk() { @@ -89,4 +118,5 @@ void XDFWriter::write_boundary_chunk() { 0xD5, 0x46, 0x73, 0x83, 0xCB, 0xE4}; _write_chunk_header(chunk_tag_t::boundary, sizeof(boundary_uuid)); write_sample_values(file_, boundary_uuid, sizeof(boundary_uuid)); + flush_if_due(true); } diff --git a/xdfwriter/xdfwriter.h b/xdfwriter/xdfwriter.h index 5d48012..d627239 100644 --- a/xdfwriter/xdfwriter.h +++ b/xdfwriter/xdfwriter.h @@ -3,6 +3,7 @@ #include "conversions.h" #include +#include #include #include #include @@ -36,6 +37,8 @@ class XDFWriter { void _write_chunk_header( chunk_tag_t tag, std::size_t length, const streamid_t *streamid_p = nullptr); std::mutex write_mut; + std::chrono::steady_clock::time_point last_flush_ = std::chrono::steady_clock::now(); + void flush_if_due(bool force = false); // write a generic chunk void _write_chunk( @@ -47,6 +50,10 @@ class XDFWriter { * @param filename Filename to write to */ XDFWriter(const std::string &filename); + /// Flush and close after all writing threads have finished; reports output failures. + void close(); + /// Flush completed chunks to the OS while the recording remains open. + void checkpoint(); template void write_data_chunk(streamid_t streamid, const std::vector ×tamps, From 292386a618b1aafb657a7fb45bd927f9ebdc3a91 Mon Sep 17 00:00:00 2001 From: Chadwick Boulay Date: Sun, 20 Sep 2026 22:04:36 -0400 Subject: [PATCH 7/7] Catch up streams to the stop cutoff before finalizing --- CMakeLists.txt | 5 +- README.md | 12 +- scripts/test_recording_teardown.py | 55 ++++++- src/clirecorder.cpp | 5 +- src/mainwindow.cpp | 48 ++++-- src/mainwindow.h | 1 - src/recording.cpp | 236 ++++++++++++++++++++++------- src/recording.h | 12 +- tests/cli_finalization.py | 6 +- tests/fake_lsl/lsl_cpp.h | 49 +++++- tests/gui_finalization.cpp | 19 +++ tests/gui_recording_stub.cpp | 16 ++ tests/recording_finalization.cpp | 86 ++++++++++- 13 files changed, 461 insertions(+), 89 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index 3a4b181..2919219 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -229,7 +229,7 @@ if(LABRECORDER_BUILD_TESTING) # liblsl into this target: its timeout behavior is supplied by the test double. target_include_directories(test_recording_finalization PRIVATE tests/fake_lsl src) target_link_libraries(test_recording_finalization PRIVATE xdfwriter Threads::Threads) - foreach(scenario IN ITEMS delayed unavailable stalled failed abandoned) + foreach(scenario IN ITEMS delayed unavailable stalled failed abandoned catchup cutoff clocksync unknown_clock finish_now independent_progress nonadvancing) add_test(NAME recording_finalization_${scenario} COMMAND test_recording_finalization ${scenario}) set_tests_properties(recording_finalization_${scenario} PROPERTIES TIMEOUT 20) @@ -253,10 +253,11 @@ if(LABRECORDER_BUILD_TESTING) $ $) endif() add_test(NAME recording_gui_finalization COMMAND test_gui_finalization) + add_test(NAME recording_gui_finish_now COMMAND test_gui_finalization --finish-now) add_test(NAME recording_gui_force_exit COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/gui_force_exit.py $) - set_tests_properties(recording_gui_finalization recording_gui_force_exit PROPERTIES TIMEOUT 25 + set_tests_properties(recording_gui_finalization recording_gui_force_exit recording_gui_finish_now PROPERTIES TIMEOUT 25 ENVIRONMENT "QT_QPA_PLATFORM=offscreen") endif() endif() diff --git a/README.md b/README.md index d751584..4bd3ec2 100644 --- a/README.md +++ b/README.md @@ -65,11 +65,15 @@ The Block/Task field can be overwriten or selected among a list of items found i Click "Start" to start a recording. If everything goes well, the status bar will now display the time since you started the recording, and more importantly, the current file size (the number before the kb) will grow slowly. This is a way to check whether you are still in fact recording data. Closing the window requests Stop and waits for finalization while keeping the interface responsive. -When you are done recording, click **Stop**. The status changes to **Finishing recording…**; a new recording cannot start until the file is finalized. **Stopped — file finalized** means the workers have finished and the file has been flushed and closed. +When you are done recording, click **Stop**. This fixes a cutoff in the recorder's clock. Inlets stay subscribed to catch up on delayed data timestamped at or before that cutoff. The interface distinguishes **Catching up**, **Waiting for pre-stop data**, and **Closing recording file**. A new recording cannot start until the file is flushed and closed. -If finalization takes more than five seconds, **Force quit…** becomes available. You can keep waiting or explicitly force the application to exit. A forced exit may leave an incomplete file or lose buffered samples; it never reports successful finalization. Completed chunks are flushed periodically and footers immediately to improve recovery, but this cannot guarantee recovery from a stalled disk or forced exit. +Catch-up continues while pre-stop timestamps advance, even if it takes longer than five seconds. Each stream gets a **two-second inactivity grace**, measured since its last advancing pre-stop timestamp (or the start of catch-up). Samples arriving out of order are accepted during that grace; receiving a post-stop sample does not close the inlet immediately. Silent marker streams, disconnected sources, and non-advancing timestamps therefore cannot hold collection open indefinitely. Data arriving after the grace expires may be missed: neither silence nor crossing the cutoff proves that an outlet's buffers are empty. -`LabRecorderCLI` waits at most five seconds after Enter. Use `--stop-timeout SECONDS` before the output filename to change that deadline (greater than zero, at most 3600). Exit status **0** means finalization succeeded; **3** means the deadline expired and the file may be incomplete; **4** means recording or finalization failed. See [the xdf repository](https://github.com/sccn/xdf) for tools and information on how to use the XDF files. +Comparison uses an LSL clock-correction estimate, without modifying the timestamps written to XDF or correcting an already clock-synchronized inlet twice. Clock estimates and source timestamps can be imperfect. If no correction is available, arrivals are preserved during a finite grace, potentially including post-stop samples, and the footer records this limitation. Each stream footer's `collection_end` records the recorder-clock `stop_time`, the grace interval, and a reason: `cutoff_observed`, `inactivity_timeout`, `clock_unavailable`, `unreliable_timestamps`, `user_requested`, or `transfer_error`. `cutoff_observed` means a later timestamp was seen and the grace elapsed; it is not a guarantee against arbitrarily delayed or reordered samples. + +**Finish now…** lets you end catch-up early and finalize the samples already saved; its confirmation explains that additional data may be missed. If a worker or file operation makes no progress for five seconds, **Force quit…** becomes available. Progress on one stream cannot hide a stalled worker on another. Force quitting may leave an incomplete file or lose buffered samples; it never reports successful finalization. Completed chunks are flushed periodically and footers immediately to improve recovery. **Stopped — file finalized** means the workers finished and the file was flushed and closed; the status also notes streams that ended without observing the cutoff. + +`LabRecorderCLI` uses a five-second **inactivity** timeout after Enter, extended by progress rather than elapsed time alone. Use `--stop-timeout SECONDS` before the output filename to change it (greater than zero, at most 3600; values below the two-second grace can interrupt normal catch-up). Exit status **0** means the file finalized, subject to its footer's collection-end reasons; **3** means a worker exceeded the inactivity timeout and the file may be incomplete; **4** means recording or finalization failed. A continuously advancing backlog has no fixed overall deadline. See [the xdf repository](https://github.com/sccn/xdf) for tools and information on how to use the XDF files. ## Preparing a Full Study @@ -97,7 +101,7 @@ Currently supported commands include: * `update` * `filename ...` -`stop` acknowledges the request with `OK`; this is not a completion notification. Poll `status` for a newline-terminated state: `recording`, `finishing`, `stalled`, `stopped`, or `error`. Wait for `stopped` before restarting or using the file. `start` is rejected with `ERROR ` while a recording is active or finalizing. +`stop` acknowledges the request with `OK`; this is not a completion notification. Poll `status` for a newline-terminated state: `recording`, `finishing` (initial stop request), `catching_up`, `waiting`, `closing`, `stalled`, `stopped`, or `error`. Wait for `stopped` before restarting or using the file. `start` is rejected with `ERROR ` while a recording is active or finalizing. `filename` is followed by a series of space-delimited options enclosed in curly braces. e.g. {root:C:\root_data_dir} * `root` - Sets the root data directory. diff --git a/scripts/test_recording_teardown.py b/scripts/test_recording_teardown.py index 02ae91e..f59b37f 100644 --- a/scripts/test_recording_teardown.py +++ b/scripts/test_recording_teardown.py @@ -3,7 +3,7 @@ Starts LSL outlets, records them with LabRecorderCLI, stops the recording and checks that -* the recorder exits within ``--max-stop`` seconds (1.0 s by default) and with status 0, +* the recorder exits within ``--max-stop`` seconds (4.0 s by default) and with status 0, * every recorded stream has a stream footer whose sample count matches its data, * pyxdf does not report the file as damaged, and * nothing that was sent before the stop is missing from the file. @@ -399,6 +399,56 @@ def case_clock_offsets_collected(cli_path, xdf_path, max_stop): del eeg, markers +def case_delayed_upstream(cli_path, xdf_path, max_stop): + """Keep receiving old data for longer than the CLI's five-second stop timeout.""" + eeg, markers = make_outlets() + time.sleep(SETTLE) + with recorder(cli_path, xdf_path, stream_order=(EEG_NAME,)) as rec: + rec.wait_for([f"Started data collection for stream {EEG_NAME}"]) + # Establish clock mapping while simulating an inlet that is already behind. + # Later backlog timestamps must advance beyond any locally buffered samples. + warmup_until = time.monotonic() + 6.5 + while time.monotonic() < warmup_until: + eeg.push_sample([0.0] * EEG_CHANNELS, timestamp=pylsl.local_clock() - 30) + time.sleep(1 / EEG_RATE) + old = pylsl.local_clock() - 20 + # Include a deducible interval followed by a gap: timestamp compression + # must not move the gap's sample backwards by one nominal interval. + second = old + 1 / EEG_RATE + expected = [old, second, second + 1 / EEG_RATE + 1 / EEG_RATE] + expected += [old + i for i in range(3, 7)] + def backlog(): + for i, timestamp in enumerate(expected): + time.sleep(0.8) + eeg.push_sample([10000.0 + i] * EEG_CHANNELS, timestamp=timestamp) + # A future timestamp followed by another pre-stop timestamp must not + # cause an immediate close that drops the reordered sample. + eeg.push_sample([99999.0] * EEG_CHANNELS, timestamp=pylsl.local_clock() + 100) + time.sleep(0.3) + eeg.push_sample([10007.0] * EEG_CHANNELS, timestamp=old + 7) + publisher = threading.Thread(target=backlog) + publisher.start() + try: + duration = rec.stop() + finally: + publisher.join() + check(5 < duration < 10, f"catch-up did not extend the stop deadline: {duration}") + streams, _ = load_xdf_strict(xdf_path) + stream = stream_by_name(streams, EEG_NAME) + check_footer(stream) + values = stream["time_series"][:, 0].tolist() + check(all(10000.0 + i in values for i in range(8)), "late pre-stop samples were lost") + check(99999.0 not in values, "post-stop sample was retained") + raw, _ = pyxdf.load_xdf(xdf_path, synchronize_clocks=False, dejitter_timestamps=False) + raw_stream = stream_by_name(raw, EEG_NAME) + for i, timestamp in enumerate(expected + [old + 7]): + index = raw_stream["time_series"][:, 0].tolist().index(10000.0 + i) + check(raw_stream["time_stamps"][index] == timestamp, "stored timestamp was rewritten") + reason = stream["footer"]["info"]["collection_end"][0]["reason"][0] + check(reason == "cutoff_observed", f"wrong collection end reason: {reason}") + del eeg, markers + + CASES = [ ("normal stop", case_normal_stop), ("stop before first sample", case_stop_before_first_sample), @@ -407,6 +457,7 @@ def case_clock_offsets_collected(cli_path, xdf_path, max_stop): ("no buffered samples lost", case_no_buffered_samples_lost), ("gated stream is drained", case_gated_stream_is_drained), ("clock offsets collected", case_clock_offsets_collected), + ("delayed upstream catch-up", case_delayed_upstream), ] @@ -416,7 +467,7 @@ def main(): parser.add_argument( "--max-stop", type=float, - default=1.0, + default=4.0, help="upper bound in seconds for how long teardown may take (default: %(default)s)", ) args = parser.parse_args() diff --git a/src/clirecorder.cpp b/src/clirecorder.cpp index bb00bd8..838ed13 100644 --- a/src/clirecorder.cpp +++ b/src/clirecorder.cpp @@ -29,7 +29,7 @@ int main(int argc, char **argv) { << "Usage: " << argv[0] << " [--stop-timeout SECONDS] outputfile.xdf 'searchstr' ['searchstr2' ...]\n" << "Search strings use lsl_resolve_bypred syntax.\n" - << "Stop timeout defaults to 5 seconds; an unfinished file exits with status 3.\n"; + << "Stop inactivity timeout defaults to 5 seconds; an unfinished file exits with status 3.\n"; return 1; } @@ -60,7 +60,8 @@ int main(int argc, char **argv) { r.requestStop(); const auto timeout = std::chrono::duration_cast( std::chrono::duration(stop_timeout)); - if (!r.waitForFinished(timeout)) { + while (!r.waitForFinished(std::chrono::milliseconds(50))) { + if (r.finalizationProgress().idle < timeout) continue; // Even reporting the timeout must not hang if a stalled worker holds an iostream // lock or stderr is backed by a blocked pipe. Allow a brief best-effort diagnostic. std::thread([] { diff --git a/src/mainwindow.cpp b/src/mainwindow.cpp index 746dc7e..3ba5c96 100644 --- a/src/mainwindow.cpp +++ b/src/mainwindow.cpp @@ -104,13 +104,16 @@ void MainWindow::statusUpdate() { if (finishing) { if (currentRecording->isFinished()) { const auto error = currentRecording->finalizationError(); + const auto fallback = currentRecording->finalizationProgress().fallback_streams; currentRecording.reset(); finishing = false; ui->startButton->setEnabled(true); ui->stopButton->setEnabled(false); ui->stopButton->setText("Stop"); setRemoteState(error.empty() ? "stopped" : "error"); - statusBar()->showMessage(error.empty() ? QStringLiteral("Stopped — file finalized") + statusBar()->showMessage(error.empty() ? (fallback + ? QStringLiteral("Stopped — file finalized; %1 stream(s) ended without confirming the cutoff").arg(fallback) + : QStringLiteral("Stopped — file finalized")) : QStringLiteral("Finalization failed — recording may be incomplete")); if (!error.empty()) { closeWhenFinished = false; @@ -118,11 +121,21 @@ void MainWindow::statusUpdate() { QString::fromStdString(error) + "\n" + recordingPath); } if (closeWhenFinished) close(); - } else if (finalizationTimer.elapsed() >= 5000) { - setRemoteState("stalled"); - statusBar()->showMessage(QStringLiteral("Still finishing — file is not finalized. Wait, or choose Force quit.")); - ui->stopButton->setText(QStringLiteral("Force quit…")); - ui->stopButton->setEnabled(true); + } else { + const auto progress = currentRecording->finalizationProgress(); + const bool stalled = progress.idle >= std::chrono::seconds(5); + setRemoteState(stalled ? "stalled" : progress.catching_up ? "catching_up" + : progress.collecting ? "waiting" : "closing"); + statusBar()->showMessage(stalled + ? QStringLiteral("Waiting without progress — file is not finalized. Wait, or choose Force quit.") + : progress.catching_up + ? QStringLiteral("Catching up to stop time — %1 stream(s) still collecting").arg(progress.collecting) + : progress.collecting + ? QStringLiteral("Waiting for pre-stop data — %1 stream(s) still open").arg(progress.collecting) + : QStringLiteral("Closing recording file…")); + ui->stopButton->setText(stalled ? QStringLiteral("Force quit…") + : progress.collecting ? QStringLiteral("Finish now…") : QStringLiteral("Stop")); + ui->stopButton->setEnabled(stalled || progress.collecting); } return; } @@ -136,13 +149,21 @@ void MainWindow::statusUpdate() { void MainWindow::confirmForceQuit() { QMessageBox dialog(QMessageBox::Warning, "Recording is still finishing", "The file has not been finalized. Force quitting may lose buffered samples or leave " - "an incomplete recording.\n" + recordingPath, QMessageBox::NoButton, this); + "an incomplete recording. Finish now stops collecting additional data and then " + "finalizes the file with the samples already saved.\n" + recordingPath, QMessageBox::NoButton, this); auto *wait = dialog.addButton("Keep waiting", QMessageBox::RejectRole); - auto *quit = dialog.addButton("Force quit", QMessageBox::DestructiveRole); + auto *finish = currentRecording && currentRecording->finalizationProgress().collecting + ? dialog.addButton("Finish now (may miss data)", QMessageBox::ActionRole) : nullptr; + auto *quit = currentRecording && currentRecording->finalizationProgress().idle >= std::chrono::seconds(5) + ? dialog.addButton("Force quit", QMessageBox::DestructiveRole) : nullptr; dialog.setDefaultButton(wait); dialog.setEscapeButton(wait); dialog.exec(); - if (dialog.clickedButton() == quit && currentRecording && !currentRecording->isFinished()) + if (finish && dialog.clickedButton() == finish && currentRecording) { + currentRecording->finishCollecting(); + statusUpdate(); + } + if (quit && dialog.clickedButton() == quit && currentRecording && !currentRecording->isFinished()) std::_Exit(3); } @@ -151,7 +172,8 @@ void MainWindow::closeEvent(QCloseEvent *ev) { ev->ignore(); closeWhenFinished = true; if (!finishing) stopRecording(); - else if (finalizationTimer.elapsed() >= 5000) confirmForceQuit(); + else if (currentRecording->finalizationProgress().idle >= std::chrono::seconds(5) || + currentRecording->finalizationProgress().collecting) confirmForceQuit(); } void MainWindow::blockSelected(const QString &block) { @@ -532,11 +554,11 @@ void MainWindow::startRecording() { void MainWindow::stopRecording() { if (!currentRecording) return; if (finishing) { - if (finalizationTimer.elapsed() >= 5000) confirmForceQuit(); + if (currentRecording->finalizationProgress().idle >= std::chrono::seconds(5) || + currentRecording->finalizationProgress().collecting) confirmForceQuit(); return; } finishing = true; - finalizationTimer.start(); currentRecording->requestStop(); ui->startButton->setEnabled(false); ui->stopButton->setEnabled(false); @@ -692,7 +714,7 @@ void MainWindow::enableRcs(bool bEnable) { uint16_t port = ui->rcsport->value(); rcs = std::make_unique(port); setRemoteState(!currentRecording ? "stopped" : !finishing ? "recording" - : finalizationTimer.elapsed() >= 5000 ? "stalled" : "finishing"); + : currentRecording->finalizationProgress().idle >= std::chrono::seconds(5) ? "stalled" : "finishing"); // TODO: Add some method to RemoteControlSocket to report if its server is listening (i.e. was successful). connect(rcs.get(), &RemoteControlSocket::refresh_streams, this, &MainWindow::refreshStreams); connect(rcs.get(), &RemoteControlSocket::start, this, &MainWindow::rcsStartRecording); diff --git a/src/mainwindow.h b/src/mainwindow.h index 994de5b..043ac65 100644 --- a/src/mainwindow.h +++ b/src/mainwindow.h @@ -72,7 +72,6 @@ private slots: std::unique_ptr currentRecording; bool finishing = false; bool closeWhenFinished = false; - QElapsedTimer finalizationTimer; QString recordingPath; void confirmForceQuit(); void setRemoteState(const QString &state); diff --git a/src/recording.cpp b/src/recording.cpp index 17d4e8d..75e3ca0 100644 --- a/src/recording.cpp +++ b/src/recording.cpp @@ -6,9 +6,11 @@ #include #include #include +#include #include #include #include +#include #include #include #include @@ -196,16 +198,40 @@ inline void join_workers( } } +// Shared control and progress only. No file or inlet operation runs under this mutex. +struct recording::completion { + std::mutex mutex; + std::condition_variable changed; + bool startup_finished = false; + bool stop_requested = false; + std::atomic cutoff{0}; + std::atomic finish_collecting{false}; + std::atomic fallback_streams{0}; + Clock::time_point stopped{}, changed_at{}; + struct stream_progress { + bool collecting = true, done = false, advancing = false; + Clock::time_point advanced = Clock::now(); + }; + std::map streams; + std::promise result; + + void note(streamid_t id, bool collecting, bool done = false, bool advancing = false) { + std::lock_guard lock(mutex); + streams[id] = {collecting, done, advancing, Clock::now()}; + changed_at = Clock::now(); + } +}; + /** - * The recording state, and the thread bodies that operate on it. - * - * Workers and the background finalizer retain this state. The UI handle owns only a - * completion signal. The finalizer joins all workers, closes the file, and releases the state - * before publishing completion; callers can poll or wait with their own finite deadline. + * Workers and the background finalizer retain this state. The UI handle owns only + * control/progress and completion. The finalizer joins all workers and closes the + * file before publishing completion; callers can enforce their own inactivity limit. */ struct recording::impl : std::enable_shared_from_this { - impl(const std::string &filename, std::map syncOptions, bool collect_offsets) - : file_(filename), offsets_enabled_(collect_offsets), unsorted_(false), streamid_(0), + impl(const std::string &filename, std::map syncOptions, + bool collect_offsets, std::shared_ptr control) + : control_(std::move(control)), file_(filename), offsets_enabled_(collect_offsets), + unsorted_(false), streamid_(0), shutdown_(false), headers_to_finish_(0), streaming_to_finish_(0), sync_options_by_stream_(std::move(syncOptions)) {} @@ -223,6 +249,7 @@ struct recording::impl : std::enable_shared_from_this { void requestStop() noexcept; + std::shared_ptr control_; // the file stream XDFWriter file_; // the file output stream // static information @@ -287,7 +314,8 @@ struct recording::impl : std::enable_shared_from_this { // sample collection loop for a numeric stream template void typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, - double &first_timestamp, double &last_timestamp, uint64_t &sample_count); + double &first_timestamp, double &last_timestamp, uint64_t &sample_count, bool clocksync, + std::string &end_reason); // === interruptible waiting & bounded network calls === @@ -363,21 +391,13 @@ std::string recording::impl::stop_and_join() { : ""; } -struct recording::completion { - std::mutex mutex; - std::condition_variable changed; - bool startup_finished = false; - bool stop_requested = false; - std::promise result; -}; - recording::recording(const std::string &filename, const std::vector &streams, const std::vector &watchfor, std::map syncOptions, bool collect_offsets) : completion_(std::make_shared()), result_(completion_->result.get_future().share()) { - auto state = std::make_shared(filename, std::move(syncOptions), collect_offsets); + auto state = std::make_shared(filename, std::move(syncOptions), collect_offsets, completion_); // Start the finalizer before workers so partial startup failures can also be cleaned - // up off the caller's thread. Its control mutex is never used by recording workers. + // up off the caller's thread. The control mutex protects only short state updates. std::thread([state, done = completion_]() mutable { { std::unique_lock lock(done->mutex); @@ -401,6 +421,8 @@ recording::recording(const std::string &filename, const std::vector lock(completion_->mutex); completion_->startup_finished = true; + completion_->cutoff = lsl::local_clock(); + completion_->stopped = completion_->changed_at = Clock::now(); completion_->stop_requested = true; } completion_->changed.notify_one(); @@ -418,11 +440,41 @@ recording::~recording() { requestStop(); } void recording::requestStop() noexcept { { std::lock_guard lock(completion_->mutex); - completion_->stop_requested = true; + if (!completion_->stop_requested) { + completion_->cutoff = lsl::local_clock(); + completion_->stopped = completion_->changed_at = Clock::now(); + completion_->stop_requested = true; + } } completion_->changed.notify_one(); } +void recording::finishCollecting() noexcept { + requestStop(); + completion_->finish_collecting = true; +} + +recording::FinalizationProgress recording::finalizationProgress() const { + FinalizationProgress result; + result.fallback_streams = completion_->fallback_streams; + std::lock_guard lock(completion_->mutex); + if (!completion_->stop_requested) return result; + const auto now = Clock::now(); + auto oldest = std::max(completion_->stopped, completion_->changed_at); + for (const auto &entry : completion_->streams) { + const auto &stream = entry.second; + if (stream.done) continue; + const auto advanced = std::max(completion_->stopped, stream.advanced); + oldest = std::min(oldest, advanced); + if (stream.collecting) { + ++result.collecting; + if (stream.advancing && now - advanced < std::chrono::milliseconds(500)) ++result.catching_up; + } + } + result.idle = std::chrono::duration_cast(now - oldest); + return result; +} + bool recording::waitForFinished(std::chrono::milliseconds timeout) const { return result_.wait_for(timeout) == std::future_status::ready; } @@ -531,14 +583,21 @@ void recording::impl::record_from_query_results(const std::string &query) { } void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool phase_locked) { + // obtain a fresh streamid + streamid_t streamid = fresh_streamid(); + control_->note(streamid, true); + // Publish completion even on an exception; no writer or inlet lock is held here. + auto progress_guard = std::shared_ptr(nullptr, [this, streamid](void *) { + control_->note(streamid, false, true); + }); inlet_p in; try { // initialised here because a stream that fails mid-recording still writes a footer double first_timestamp = 0.0, last_timestamp = 0.0; uint64_t sample_count = 0; double nominal_srate = 0; - // obtain a fresh streamid - streamid_t streamid = fresh_streamid(); + bool clocksync = false; + std::string end_reason = "transfer_error"; // --- headers phase try { @@ -547,7 +606,10 @@ void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool p // open an inlet to read from (and subscribe to data immediately) in = std::make_shared(src); auto it = sync_options_by_stream_.find(src.name() + " (" + src.hostname() + ")"); - if (it != sync_options_by_stream_.end()) in->set_postprocessing(it->second); + if (it != sync_options_by_stream_.end()) { + in->set_postprocessing(it->second); + clocksync = (it->second & lsl::post_clocksync) != 0; + } if (open_inlet(in)) log_out("Opened the stream ", src.name(), "."); @@ -583,27 +645,33 @@ void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool p switch (src.channel_format()) { case lsl::cf_int8: typed_transfer_loop( - streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count, + clocksync, end_reason); break; case lsl::cf_int16: typed_transfer_loop( - streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count, + clocksync, end_reason); break; case lsl::cf_int32: typed_transfer_loop( - streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count, + clocksync, end_reason); break; case lsl::cf_float32: typed_transfer_loop( - streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count, + clocksync, end_reason); break; case lsl::cf_double64: typed_transfer_loop( - streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count, + clocksync, end_reason); break; case lsl::cf_string: typed_transfer_loop( - streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count); + streamid, nominal_srate, in, first_timestamp, last_timestamp, sample_count, + clocksync, end_reason); break; default: // unsupported channel format @@ -631,6 +699,10 @@ void recording::impl::record_from_streaminfo(const lsl::stream_info &src, bool p footer << "" << first_timestamp << "" << last_timestamp << "" << sample_count << ""; + footer << "" << end_reason + << "" << control_->cutoff.load() + << "recorder" + << "2"; footer << ""; { // including the clock_offset list @@ -761,7 +833,8 @@ void recording::impl::enter_footers_phase(bool phase_locked) { template void recording::impl::typed_transfer_loop(streamid_t streamid, double srate, const inlet_p &in, - double &first_timestamp, double &last_timestamp, uint64_t &sample_count) { + double &first_timestamp, double &last_timestamp, uint64_t &sample_count, bool clocksync, + std::string &end_reason) { // optionally start an offset collection thread for this stream auto offset_shutdown = std::make_shared>(false); auto self = shared_from_this(); @@ -789,7 +862,7 @@ void recording::impl::typed_transfer_loop(streamid_t streamid, double srate, con } // if the time stamp can be deduced from the previous one... if (last_timestamp + sample_interval == ts) { - last_timestamp = ts + sample_interval; + last_timestamp = ts; ts = 0; } else last_timestamp = ts; @@ -798,36 +871,83 @@ void recording::impl::typed_transfer_loop(streamid_t streamid, double srate, con sample_count += timestamps.size(); }; - // Wait for the first sample, unless the stop got here first. A stream held at the headers - // gate reaches this point with the shutdown already set, having pulled nothing, while its - // inlet has been subscribed and buffering the whole time -- the drain below picks that up. - first_timestamp = 0.0; - while (!shutdown_ && first_timestamp == 0.0) { - const double ts = in->pull_sample(chunk, network_poll_interval); - if (ts == 0.0) continue; - timestamps.assign(1, ts); - write_chunk(); - } - - auto next_pull = Clock::now() + chunk_interval; - while (!shutdown_) { - // get a chunk from the stream - in->pull_chunk_multiplexed(chunk, ×tamps, 1e-6); - write_chunk(); - if (wait_until_shutdown(next_pull)) break; - next_pull += chunk_interval; - } - - // one final non-blocking pull, so that samples already buffered in the inlet when the stop - // arrived end up in the file rather than being dropped - try { - in->pull_chunk_multiplexed(chunk, ×tamps, 0.0); + // Bounded batches prevent a continuously producing outlet from trapping a pull + // inside liblsl's vector pull_chunk helper and delaying stop/cutoff checks. + std::vector sample; + bool stopping = false, have_correction = clocksync, saw_cutoff = false; + bool unmapped_samples = false, invalid_timestamps = false; + double correction = 0, high_water = -std::numeric_limits::infinity(); + auto last_advance = Clock::now(); + const auto inactivity_grace = std::chrono::seconds(2); + auto observe_stop = [&] { + if (control_->cutoff.load() && !stopping) { + stopping = true; + last_advance = Clock::now(); + } + if (stopping && !have_correction) { + try { + correction = in->time_correction(0.0); + have_correction = std::isfinite(correction); + } catch (const std::exception &) { + // Losing clock service must not discard samples still available from + // the data connection. Preserve them during the fallback grace. + } + } + }; + for (;;) { + // Mapping is needed even if offset chunks are disabled. A zero-timeout + // query starts/reuses liblsl's measurement without waiting. + observe_stop(); + if (stopping && control_->finish_collecting) { + end_reason = "user_requested"; + break; + } + chunk.clear(); + timestamps.clear(); + bool advanced = false; + for (size_t n = 0; n < 1024; ++n) { + const double ts = in->pull_sample(sample, n == 0 ? network_poll_interval : 0.0); + // Stop can arrive while pull_sample is waiting. Compare this sample + // too, without losing data pulled just as the request arrived. + if (!stopping && control_->cutoff.load()) observe_stop(); + if (!ts) break; + const double stop = control_->cutoff.load(); + const double local_ts = ts + correction; + if (stopping && !have_correction) unmapped_samples = true; + if (stopping && !std::isfinite(local_ts)) invalid_timestamps = true; + if (stopping && have_correction && std::isfinite(local_ts)) { + if (local_ts > stop) { + saw_cutoff = true; + continue; + } + if (local_ts > high_water) { + high_water = local_ts; + advanced = true; + } + } + // Preserve inlet timestamps; correction is for comparison only. If the + // clock mapping is unavailable, preserve arrivals during a finite grace. + timestamps.push_back(ts); + chunk.insert(chunk.end(), sample.begin(), sample.end()); + } write_chunk(); - } catch (std::exception &e) { - // Preserve a footer, but report that draining failed. - recording_failed_ = true; - log_err("Could not drain stream ", streamid, " on stop: ", e.what()); + if (!stopping || advanced) { + last_advance = Clock::now(); + control_->note(streamid, true, false, advanced); + } + if (stopping && Clock::now() - last_advance >= inactivity_grace) { + // Even a post-cutoff sample is not proof of completeness for reordered + // or sparse streams. Leave the inlet open for the same reorder grace. + end_reason = invalid_timestamps ? "unreliable_timestamps" + : (!have_correction || unmapped_samples) ? "clock_unavailable" + : saw_cutoff ? "cutoff_observed" : "inactivity_timeout"; + break; + } + if (!stopping) wait_for_shutdown(chunk_interval); } + control_->note(streamid, false); + if (end_reason != "cutoff_observed") ++control_->fallback_streams; + log_out("Collection ended for stream ", streamid, ": ", end_reason); } catch (std::exception &) { stop_offsets(offset_shutdown); join_worker(offset_thread, teardown_grace); diff --git a/src/recording.h b/src/recording.h index 0ea148d..3abf92a 100644 --- a/src/recording.h +++ b/src/recording.h @@ -35,8 +35,18 @@ class recording { /// Requests shutdown without waiting. Callers must observe completion before normal exit. ~recording(); - /// Ask all recording threads to wrap up. Returns immediately. + /// Fix the recorder-clock cutoff and request catch-up/finalization. Returns immediately. void requestStop() noexcept; + struct FinalizationProgress { + size_t collecting = 0; + size_t catching_up = 0; + size_t fallback_streams = 0; + // Longest inactivity of any outstanding worker (other streams cannot hide a stall). + std::chrono::milliseconds idle{0}; + }; + FinalizationProgress finalizationProgress() const; + /// End catch-up early, preserving footers and recording the explicit truncation reason. + void finishCollecting() noexcept; /// Wait at most timeout for all workers AND the output file to finish. Does not request stop. bool waitForFinished(std::chrono::milliseconds timeout) const; bool isFinished() const { return waitForFinished(std::chrono::milliseconds(0)); } diff --git a/tests/cli_finalization.py b/tests/cli_finalization.py index 640e223..fb7d192 100644 --- a/tests/cli_finalization.py +++ b/tests/cli_finalization.py @@ -17,7 +17,7 @@ def run_case(binary, directory, stalled): else: env.pop("LSL_TEST_STALL", None) proc = subprocess.Popen( - [binary, "--stop-timeout", "0.5", str(path), "test"], + [binary, "--stop-timeout", "0.5" if stalled else "5", str(path), "test"], stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True, env=env, ) @@ -41,11 +41,11 @@ def read(): start = time.monotonic() proc.stdin.write("\n") proc.stdin.flush() - proc.wait(timeout=2) + proc.wait(timeout=5) reader.join(timeout=1) elapsed = time.monotonic() - start assert proc.returncode == (3 if stalled else 0), "".join(output) - assert elapsed < 1.5, f"CLI did not honor its timeout: {elapsed}" + assert elapsed < (1.5 if stalled else 4), f"CLI did not honor its timeout: {elapsed}" data = path.read_bytes() assert data.startswith(b"XDF:"), "no recoverable XDF header was flushed" if stalled: diff --git a/tests/fake_lsl/lsl_cpp.h b/tests/fake_lsl/lsl_cpp.h index 3ddfa2a..ea48fb0 100644 --- a/tests/fake_lsl/lsl_cpp.h +++ b/tests/fake_lsl/lsl_cpp.h @@ -8,6 +8,8 @@ #include #include #include +#include +#include #include #include #include @@ -15,6 +17,7 @@ namespace lsl { using clock = std::chrono::steady_clock; +constexpr int post_clocksync = 1; enum channel_format_t { cf_int8, cf_int16, cf_int32, cf_float32, cf_double64, cf_string }; struct timeout_error : std::runtime_error { timeout_error() : std::runtime_error("test timeout") {} @@ -25,11 +28,22 @@ struct inlet_state { unavailable, stalled_worker, permanent_stall, - failed_transfer + failed_transfer, + queued, + queued_unknown, + stalled_transfer } behavior; std::atomic query_started{false}, query_finished{false}; std::atomic query_calls{0}; clock::time_point result_ready; + std::mutex mutex; + std::deque> samples; + std::atomic pulled{0}; + void enqueue(double delay, double timestamp) { + std::lock_guard lock(mutex); + samples.emplace_back(clock::now() + std::chrono::duration_cast( + std::chrono::duration(delay)), timestamp); + } explicit inlet_state(mode behavior) : behavior(behavior) {} }; @@ -64,21 +78,46 @@ inline std::vector resolve_streams() { class stream_inlet { stream_info info_; bool sent_sample_ = false; + bool clocksync_ = false; public: explicit stream_inlet(const stream_info &info) : info_(info) {} void open_stream(double) {} void close_stream() {} - void set_postprocessing(int) {} + void set_postprocessing(int flags) { clocksync_ = (flags & post_clocksync) != 0; } stream_info info(double) { return info_; } int get_channel_count() const { return 1; } template double pull_sample(std::vector &sample, double timeout) { + if (info_.state->behavior == inlet_state::queued || + info_.state->behavior == inlet_state::queued_unknown) { + const auto until = clock::now() + std::chrono::duration(timeout); + do { + { + std::lock_guard lock(info_.state->mutex); + auto &samples = info_.state->samples; + if (!samples.empty() && samples.front().first <= clock::now()) { + const auto ts = samples.front().second; + samples.pop_front(); + sample.assign(1, T{}); + ++info_.state->pulled; + return ts + (clocksync_ ? 100.0 : 0.0); + } + } + if (timeout == 0) break; + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } while (clock::now() < until); + return 0; + } if (info_.state->behavior == inlet_state::failed_transfer) { info_.state->query_started = true; throw std::runtime_error("simulated transfer failure"); } if (!sent_sample_) { sent_sample_ = true; + if (info_.state->behavior == inlet_state::stalled_transfer) { + info_.state->query_started = true; + std::this_thread::sleep_for(std::chrono::seconds(3)); + } sample.assign(1, T{}); return 123; } @@ -92,6 +131,12 @@ class stream_inlet { } double time_correction(double timeout) { auto &state = *info_.state; + if (state.behavior == inlet_state::queued || state.behavior == inlet_state::stalled_transfer) return 100.0; + if (state.behavior == inlet_state::queued_unknown) { + if (state.query_calls++ % 2) throw std::runtime_error("clock service lost"); + throw timeout_error(); + } + std::lock_guard lock(state.mutex); if (state.query_calls++ == 0) state.result_ready = clock::now() + std::chrono::milliseconds(600); state.query_started = true; diff --git a/tests/gui_finalization.cpp b/tests/gui_finalization.cpp index 908f763..4039170 100644 --- a/tests/gui_finalization.cpp +++ b/tests/gui_finalization.cpp @@ -15,6 +15,7 @@ extern std::atomic release_finalization; extern std::atomic recording_starts; +extern std::atomic simulate_catchup; static void require(bool value, const char *message) { if (!value) throw std::runtime_error(message); @@ -74,6 +75,24 @@ int main(int argc, char **argv) { auto *start = window.findChild("startButton"); auto *stopButton = window.findChild("stopButton"); require(start && stopButton && !start->isEnabled(), "Start enabled before completion"); + simulate_catchup = true; + pump(5200); + require(command(socket, "status\n") == "catching_up\n", "progressing catch-up timed out"); + require(stopButton->text().contains("Finish now"), "controlled finish action unavailable"); + if (argc > 1 && std::string(argv[1]) == "--finish-now") { + QTimer::singleShot(0, [] { + for (auto *widget : QApplication::topLevelWidgets()) + if (auto *dialog = qobject_cast(widget)) + for (auto *button : dialog->buttons()) + if (button->text().startsWith("Finish now")) button->click(); + }); + stopButton->click(); + pump(300); + require(release_finalization, "Finish now did not reach the backend"); + require(command(socket, "status\n") == "stopped\n", "Finish now did not finalize"); + return 0; + } + simulate_catchup = false; pump(5200); require(heartbeats > 100, "GUI event loop stopped during stalled finalization"); require(command(socket, "status\n") == "stalled\n", "stall was not reported"); diff --git a/tests/gui_recording_stub.cpp b/tests/gui_recording_stub.cpp index 7b5e401..3d76692 100644 --- a/tests/gui_recording_stub.cpp +++ b/tests/gui_recording_stub.cpp @@ -6,9 +6,11 @@ std::atomic release_finalization{false}; std::atomic recording_starts{0}; +std::atomic simulate_catchup{false}; struct recording::completion { std::atomic stopping{false}; + std::chrono::steady_clock::time_point stopped; std::promise result; }; @@ -21,6 +23,7 @@ recording::recording(const std::string &, const std::vector &, recording::~recording() { requestStop(); } void recording::requestStop() noexcept { if (completion_->stopping.exchange(true)) return; + completion_->stopped = std::chrono::steady_clock::now(); std::thread([done = completion_] { while (!release_finalization) std::this_thread::sleep_for(std::chrono::milliseconds(5)); @@ -31,3 +34,16 @@ bool recording::waitForFinished(std::chrono::milliseconds timeout) const { return result_.wait_for(timeout) == std::future_status::ready; } std::string recording::finalizationError() const { return result_.get(); } + +recording::FinalizationProgress recording::finalizationProgress() const { + FinalizationProgress progress; + if (simulate_catchup) { + completion_->stopped = std::chrono::steady_clock::now(); + progress.collecting = progress.catching_up = 1; + return progress; + } + progress.idle = std::chrono::duration_cast( + std::chrono::steady_clock::now() - completion_->stopped); + return progress; +} +void recording::finishCollecting() noexcept { release_finalization = true; } diff --git a/tests/recording_finalization.cpp b/tests/recording_finalization.cpp index e5d8dd0..e7bf154 100644 --- a/tests/recording_finalization.cpp +++ b/tests/recording_finalization.cpp @@ -11,10 +11,94 @@ static void require(bool value, const char *message) { if (!value) throw std::runtime_error(message); } +static void independent_progress_test() { + auto stalled = std::make_shared(lsl::inlet_state::stalled_transfer); + auto active = std::make_shared(lsl::inlet_state::queued); + const std::string filename = "finalization-independent.xdf"; + recording rec(filename, {lsl::stream_info(stalled), lsl::stream_info(active)}, {}, {}, false); + const auto deadline = lsl::clock::now() + std::chrono::seconds(2); + while (!stalled->query_started && lsl::clock::now() < deadline) + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + require(stalled->query_started, "stalled transfer never started"); + for (int i = 0; i < 7; ++i) active->enqueue(0.1 + i * 0.5, lsl::local_clock() - 110 + i); + rec.requestStop(); + std::this_thread::sleep_for(std::chrono::milliseconds(2500)); + require(rec.finalizationProgress().idle >= std::chrono::milliseconds(2400), + "activity on one inlet concealed another inlet's stall"); + require(rec.waitForFinished(std::chrono::seconds(6)), "workers did not eventually finish"); + std::filesystem::remove(filename); +} + +static void catchup_test(const std::string &scenario) { + const bool unknown = scenario == "unknown_clock"; + auto state = std::make_shared(unknown + ? lsl::inlet_state::queued_unknown : lsl::inlet_state::queued); + const std::string filename = "finalization-" + scenario + ".xdf"; + std::map options; + if (scenario == "clocksync") options["FinalizationTest (localhost)"] = lsl::post_clocksync; + // Deliberately disable offset chunks: cutoff comparison must still use clock mapping. + recording rec(filename, {lsl::stream_info(state)}, {}, options, false); + const double raw_now = lsl::local_clock() - 100.0; + const bool slow = scenario == "catchup"; + const bool early = scenario == "finish_now"; + const bool duplicates = scenario == "nonadvancing"; + if (duplicates) { + for (int i = 0; i < 15; ++i) state->enqueue(0.1 + i * 0.3, raw_now - 1); + } else if (slow) { + for (int i = 0; i < 7; ++i) state->enqueue(0.1 + i, raw_now - 10 + i); + } else { + state->enqueue(0.1, raw_now - 1); + state->enqueue(0.3, raw_now + 0.2); // excluded, even after repeated Stop + state->enqueue(0.6, raw_now - 0.5); // older sample arriving AFTER crossing cutoff + } + rec.requestStop(); + const auto started = lsl::clock::now(); + bool intervened = false; + while (!rec.waitForFinished(std::chrono::milliseconds(20))) { + const auto elapsed = lsl::clock::now() - started; + if (!intervened && elapsed > std::chrono::milliseconds(400)) { + if (early) rec.finishCollecting(); + else rec.requestStop(); + intervened = true; + } + if (slow && elapsed < std::chrono::seconds(7)) + require(rec.finalizationProgress().idle < std::chrono::milliseconds(1500), + "advancing backlog was mistaken for a stall"); + require(elapsed < std::chrono::seconds(12), "catch-up did not finish"); + } + require(rec.finalizationError().empty(), "catch-up failed"); + if (slow) require(lsl::clock::now() - started > std::chrono::seconds(7), + "catch-up stopped before delayed upstream samples arrived"); + std::ifstream file(filename, std::ios::binary); + const std::string data((std::istreambuf_iterator(file)), {}); + const int count = duplicates ? state->pulled.load() : slow ? 7 : early ? 1 : unknown ? 3 : 2; + if (duplicates) { + require(count < 15, "non-advancing timestamps kept collection open indefinitely"); + require(lsl::clock::now() - started < std::chrono::seconds(3), "fallback grace was not bounded"); + } + require(data.find("" + std::to_string(count) + "") != std::string::npos, + "cutoff lost pre-stop data or retained post-stop data"); + const auto reason = early ? "user_requested" : unknown ? "clock_unavailable" + : (slow || duplicates) ? "inactivity_timeout" : "cutoff_observed"; + require(data.find(std::string("") + reason + "") != std::string::npos, + "footer does not explain why collection ended"); + file.close(); + std::filesystem::remove(filename); +} + int main(int argc, char **argv) { try { require(argc == 2, "expected a finalization test scenario"); const std::string scenario = argv[1]; + if (scenario == "independent_progress") { + independent_progress_test(); + return 0; + } + if (scenario == "catchup" || scenario == "cutoff" || scenario == "clocksync" || + scenario == "unknown_clock" || scenario == "finish_now" || scenario == "nonadvancing") { + catchup_test(scenario); + return 0; + } const auto mode = scenario == "delayed" ? lsl::inlet_state::delayed_result : scenario == "unavailable" ? lsl::inlet_state::unavailable : scenario == "failed" ? lsl::inlet_state::failed_transfer @@ -72,7 +156,7 @@ int main(int argc, char **argv) { require(state->query_calls > 1, "test did not exercise polling across timeouts"); require(contents.find("") != std::string::npos, "offset missing from footer"); } else if (scenario == "unavailable") { - require(elapsed < 1.0, "stop waited for the full offset query budget"); + require(elapsed < 3.0, "stop waited for the full offset query budget"); } else if (scenario == "stalled") { require(state->query_finished, "destructor abandoned a running writer owner"); }