Fix repeatable sonpy SIGABRT crashes; add crash detection and diagnostics

README.md

@@ -235,6 +235,84 @@ Helpers: `sonpipe.channels(f)` (NDR-style channel struct array),
 
 ---
 
+## Troubleshooting: diagnosing a hard crash
+
+CED's `sonpy` is a compiled C++ library. On some files/channels it fails an
+internal **assertion** and calls `abort()` (`SIGABRT`) instead of raising a
+Python error. `abort()` cannot be caught with `try`/`except` — it terminates
+the whole reader process immediately — so there is no Python traceback, and the
+host may otherwise see only truncated or empty output.
+
+Two mechanisms help you catch and locate such a crash:
+
+1. **The MATLAB layer detects it.** A successful `read` prints a completion
+   sentinel (`sonpipe: wrote N …`) to stderr as its final act. The MATLAB
+   `invoke_binary` helper requires that sentinel and checks that `N` matches the
+   bytes captured; if the reader died mid-stream (even when an intermediate
+   `arch -x86_64` wrapper masks the non-zero exit status), you get a
+   `sonpipe:crash` / `sonpipe:truncated` error naming the exact command instead
+   of silently short data.
+
+2. **Breadcrumb logging pinpoints *where* it crashed.** Set the `SONPIPE_LOG`
+   environment variable and re-run the command that crashes. sonpipe writes one
+   line immediately before and after every call into `sonpy`, flushed to disk so
+   it survives the `abort()`. The **last line** in the log is then the `sonpy`
+   call — with its exact arguments — that triggered the crash.
+
+   ```bash
+   # shell
+   SONPIPE_LOG=1 sonpipe read recording.smrx -c 21 --t0 100 --t1 110 > /dev/null
+   #   -> logs to ~/.local/var/log/sonpipe-<uid>.log
+   SONPIPE_LOG=/tmp/sonpipe.log sonpipe read …      # or an explicit path
+   ```
+   ```matlab
+   % MATLAB: turn on for the session, re-run the failing read, then turn off
+   setenv('SONPIPE_LOG', '1');
+   ... % the call that crashes
+   setenv('SONPIPE_LOG', '');
+   ```
+
+   Accepted values: `1`/`true`/`on` → default path
+   `~/.local/var/log/sonpipe-<uid>.log`; any other value → that path
+   (`~` is expanded); unset/`0`/`false`/`off` → disabled (zero overhead).
+
+   Every call into sonpy is logged — `SonFile` (open), the metadata accessors
+   (`ChannelType`, `ChannelDivide`, `ChannelMaxTime`, `GetChannelScale`, …), the
+   reads (`ReadInts` / `ReadFloats` / `ReadEvents` / marker reads), and the
+   `Close`/teardown — plus a `done` line when the command finishes cleanly.
+   Reading the **last line** tells you where it died:
+
+   * ends on a dangling `-> ReadInts args=…` (no matching `<- ReadInts`) — that
+     sonpy read aborted; the `read_waveform`/`read_events`/`read_markers`
+     context line just above shows the resolved `tfrom/tupto/nmax`, so you can
+     see the exact arguments sonpipe passed;
+   * ends on a dangling `-> Close` / `del SonFile` — sonpy aborted while
+     releasing the file handle (a teardown-order assertion);
+   * ends on `done command=… rc=0` followed by `hard_exit rc=0` — the command
+     completed and the data is valid.
+
+   **Shutdown-crash workaround.** On some files CED's sonpy passes an internal
+   assertion during normal work but then calls `abort()` (SIGABRT) during
+   Python's *interpreter shutdown* — in a static/`atexit` destructor that runs
+   **after** the command has already finished and delivered all of its output.
+   That abort cannot be caught from Python, but it also does no harm to the
+   result. sonpipe therefore does two things to keep a finished read from
+   turning into a crash:
+
+   * it **closes the sonpy file handle explicitly** at the end of each command,
+     while the interpreter is still healthy (rather than at garbage collection);
+   * the process entry point (`sonpipe.cli:run`, used by both the `sonpipe`
+     command and `python -m sonpipe`) flushes all output and then calls
+     `os._exit()`, which terminates immediately **without** running the
+     interpreter-shutdown code where sonpy aborts.
+
+   Because every stream is flushed before the hard exit, no data is lost; the
+   crash simply never happens. The `hard_exit` breadcrumb marks this point in
+   the log. (`main()` itself does not hard-exit, so importing and calling it
+   in-process — as the tests do — is unaffected.)
+
+---
+
 ## Development, testing, and CI
 
 **Python (CLI) tests** use a fake `sonpy` shim, so they run anywhere:

matlab/+sonpipe/private/invoke_binary.m

@@ -10,8 +10,23 @@
 %   "capture the pipe and typecast" pattern with an on-disk buffer (MATLAB's
 %   system() mangles binary captured directly to a char array).
 %
-%   Informational messages from the CLI go to stderr and are not captured here,
-%   so the temporary file contains pure sample bytes.
+%   Informational messages from the CLI go to stderr and are captured to a
+%   separate temporary file so the binary file stays pure sample bytes while we
+%   can still inspect the CLI's diagnostics.
+%
+%   Crash detection. The underlying sonpy reader is a C++ library that, on some
+%   files/channels, fails a runtime assertion and calls abort() (SIGABRT)
+%   instead of raising a catchable Python error. That kills the whole reader
+%   process mid-stream. Relying on the process exit status alone is not enough
+%   to notice this: on Apple Silicon the CLI runs behind an 'arch -x86_64'
+%   wrapper, and an intermediate wrapper process does not reliably propagate a
+%   signal death as a non-zero status -- so a hard crash can otherwise look like
+%   success and return truncated (or empty) data with no error. To catch it, we
+%   also require the CLI's completion sentinel: a successful read prints
+%   'sonpipe: wrote N ...' to stderr as its final act, and N must match the
+%   number of samples we captured. A missing sentinel or a count mismatch means
+%   the reader died mid-stream, and we raise an error that reports the exact
+%   command and the captured diagnostics.
 %
 %   This is a private helper for the +sonpipe package.
 
@@ -22,24 +37,73 @@
 
 	exe = sonpipe.executable();
 	tmp = [tempname() '.bin'];
-	cleaner = onCleanup(@() deletefile(tmp));
+	errfile = [tempname() '.err'];
+	cleaner    = onCleanup(@() deletefile(tmp));     %#ok<NASGU>
+	cleanerErr = onCleanup(@() deletefile(errfile)); %#ok<NASGU>
 
-	cmd = sprintf('%s %s > "%s"', exe, args, tmp);
+	cmd = sprintf('%s %s > "%s" 2> "%s"', exe, args, tmp, errfile);
 	[status, msg] = sonpipe.runcmd(cmd);
+	stderrTxt = readTextFile(errfile);
+	if isempty(stderrTxt)
+		stderrTxt = msg; % fall back to whatever runcmd captured
+	end
 	if status ~= 0
 		error('sonpipe:cliError', ...
 			'sonpipe failed (status %d) for command:\n  %s\n%s', ...
-			status, cmd, msg);
+			status, cmd, stderrTxt);
 	end
 
 	fid = fopen(tmp, 'r', 'l'); % little-endian
 	if fid < 0
 		error('sonpipe:tmpRead', ...
 			'Could not read sonpipe output file: %s', tmp);
 	end
-	closer = onCleanup(@() fclose(fid));
+	closer = onCleanup(@() fclose(fid)); %#ok<NASGU>
 	data = fread(fid, Inf, ['*' precision]);
 	data = data(:);
+
+	% Validate against the CLI's completion sentinel to catch a mid-stream crash
+	% that the exit status may have hidden (see the crash-detection note above).
+	expected = parseWroteCount(stderrTxt);
+	if isnan(expected)
+		error('sonpipe:crash', ...
+			['sonpipe did not report completion for command:\n  %s\n' ...
+			 'The reader process appears to have crashed before finishing ' ...
+			 '(a sonpy assertion/abort reads as SIGABRT). Captured messages:\n%s'], ...
+			cmd, stderrTxt);
+	elseif expected ~= numel(data)
+		error('sonpipe:truncated', ...
+			['sonpipe reported %d value(s) but %d were captured for command:\n  %s\n' ...
+			 'The output is truncated -- the reader likely crashed mid-stream. ' ...
+			 'Captured messages:\n%s'], ...
+			expected, numel(data), cmd, stderrTxt);
+	end
+end
+
+function n = parseWroteCount(stderrTxt)
+% Parse the sample/event count from the CLI's completion sentinel, e.g.
+%   "sonpipe: wrote 12345 samples (double) for channel 3"
+%   "sonpipe: wrote 0 event times (double) for channel 5"
+% Returns NaN if no sentinel is present (i.e. the read did not finish).
+	n = NaN;
+	if isempty(stderrTxt)
+		return;
+	end
+	tok = regexp(stderrTxt, 'wrote\s+(\d+)\s+(?:samples|event times)', 'tokens', 'once');
+	if ~isempty(tok)
+		n = str2double(tok{1});
+	end
+end
+
+function txt = readTextFile(fname)
+	txt = '';
+	if exist(fname, 'file')
+		fid = fopen(fname, 'r');
+		if fid >= 0
+			txt = fread(fid, Inf, '*char')';
+			fclose(fid);
+		end
+	end
 end
 
 function deletefile(fname)

matlab/+sonpipe/private/invoke_text.m

@@ -4,8 +4,17 @@
 %   TXT = invoke_text(ARGS)
 %
 %   ARGS is the argument string passed to the sonpipe CLI (everything after the
-%   executable name). Returns the captured stdout as a char row vector. Raises
-%   an error if the CLI exits with a nonzero status.
+%   executable name). Returns the captured stdout (the JSON payload) as a char
+%   row vector. Raises an error if the CLI exits with a nonzero status.
+%
+%   The CLI's informational/diagnostic messages go to stderr, which is captured
+%   to a separate temporary file. Keeping stderr out of the returned text means
+%   a warning (or a crash's abort text) can never corrupt the JSON that the
+%   caller hands to jsondecode; on failure the captured stderr is included in
+%   the error so the reason is visible. If the reader crashes hard (a sonpy
+%   assertion/abort, which reads as SIGABRT), set the SONPIPE_LOG environment
+%   variable to '1' before the call to get a breadcrumb log pinpointing the
+%   crashing sonpy call.
 %
 %   This is a private helper for the +sonpipe package.
 
@@ -14,11 +23,32 @@
 	end
 
 	exe = sonpipe.executable();
-	cmd = [exe ' ' args];
+	errfile = [tempname() '.err'];
+	cleanerErr = onCleanup(@() deletefile(errfile)); %#ok<NASGU>
+
+	cmd = sprintf('%s %s 2> "%s"', exe, args, errfile);
 	[status, txt] = sonpipe.runcmd(cmd);
 	if status ~= 0
+		stderrTxt = readTextFile(errfile);
 		error('sonpipe:cliError', ...
 			'sonpipe failed (status %d) for command:\n  %s\n%s', ...
-			status, cmd, txt);
+			status, cmd, stderrTxt);
+	end
+end
+
+function txt = readTextFile(fname)
+	txt = '';
+	if exist(fname, 'file')
+		fid = fopen(fname, 'r');
+		if fid >= 0
+			txt = fread(fid, Inf, '*char')';
+			fclose(fid);
+		end
+	end
+end
+
+function deletefile(fname)
+	if exist(fname, 'file')
+		delete(fname);
 	end
 end

pyproject.toml

@@ -38,7 +38,7 @@ Source = "https://github.com/VH-Lab/sonpipe"
 "sonpy (CED)" = "https://pypi.org/project/sonpy/"
 
 [project.scripts]
-sonpipe = "sonpipe.cli:main"
+sonpipe = "sonpipe.cli:run"
 
 [tool.setuptools.packages.find]
 where = ["src"]

src/sonpipe/__main__.py

@@ -1,8 +1,6 @@
 """Enable ``python -m sonpipe``."""
 
-import sys
-
-from .cli import main
+from .cli import run
 
 if __name__ == "__main__":
-    sys.exit(main())
+    run()