From 08eab77e41dac3a1f2852127303232629fe9a0ff Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Sun, 19 Jul 2026 19:12:28 +0000
Subject: [PATCH 1/6] Catch and diagnose sonpy hard crashes (SIGABRT/abort)

CED's sonpy is a compiled C++ library that, on certain files/channels,
fails an internal assertion and calls abort() (SIGABRT) instead of
raising a catchable Python error. This kills the reader process
mid-stream, which the host (e.g. MATLAB) could previously see as
silently truncated/empty data -- especially on Apple Silicon, where the
'arch -x86_64' wrapper does not reliably propagate a signal death as a
non-zero exit status.

Two complementary changes:

Detection (MATLAB layer). invoke_binary now captures stderr separately
and requires the CLI's completion sentinel ("sonpipe: wrote N ...");
if it is missing, or N does not match the bytes captured, it raises
sonpipe:crash / sonpipe:truncated naming the exact command instead of
returning short data. invoke_text captures stderr to its own file so a
warning or crash text can no longer corrupt the JSON handed to
jsondecode, and surfaces it on failure.

Diagnosis (Python layer). New opt-in breadcrumb logging (debuglog),
enabled via the SONPIPE_LOG environment variable, writes one line
immediately before and after every call into sonpy, flushed with an
unbuffered os.write + fsync so the line survives an abort(). Every sonpy
boundary in sonfile.py (SonFile open, ReadInts, ReadFloats, ReadEvents,
marker reads) and the CLI entry point are instrumented, so the last line
in the log names the exact sonpy call and arguments that crashed.

Adds tests/test_debuglog.py (including a real subprocess abort() that
confirms the pre-call breadcrumb survives) and documents the workflow in
the README Troubleshooting section.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C1UYvbvczg9QvqKg8YNr4k
---
 README.md                               |  55 +++++++++++
 matlab/+sonpipe/private/invoke_binary.m |  76 +++++++++++++--
 matlab/+sonpipe/private/invoke_text.m   |  38 +++++++-
 src/sonpipe/cli.py                      |   6 +-
 src/sonpipe/debuglog.py                 | 119 ++++++++++++++++++++++++
 src/sonpipe/sonfile.py                  |  27 ++++--
 tests/test_debuglog.py                  | 104 +++++++++++++++++++++
 7 files changed, 407 insertions(+), 18 deletions(-)
 create mode 100644 src/sonpipe/debuglog.py
 create mode 100644 tests/test_debuglog.py

diff --git a/README.md b/README.md
index 0346ffd..cc04e7b 100644
--- a/README.md
+++ b/README.md
@@ -235,6 +235,61 @@ 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).
+
+   A typical crash tail looks like:
+
+   ```
+   … read_waveform number=21 index=20 kind=1 start=… count=… tfrom=… tupto=… nmax=…
+   … -> ReadInts args=20,…,…,…          <-- last line: this sonpy call aborted
+   ```
+
+   The `read_waveform` / `read_events` / `read_markers` context line just above
+   shows the resolved sample/tick range, so you can see exactly which arguments
+   sonpipe passed to sonpy — useful for reporting the crash to CED or for adding
+   a guard in sonpipe.
+
+---
+
 ## Development, testing, and CI
 
 **Python (CLI) tests** use a fake `sonpy` shim, so they run anywhere:
diff --git a/matlab/+sonpipe/private/invoke_binary.m b/matlab/+sonpipe/private/invoke_binary.m
index b30901d..fcfeeaa 100644
--- a/matlab/+sonpipe/private/invoke_binary.m
+++ b/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,14 +37,20 @@
 
 	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
@@ -37,9 +58,52 @@
 		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)
diff --git a/matlab/+sonpipe/private/invoke_text.m b/matlab/+sonpipe/private/invoke_text.m
index 1950c44..f26d7c6 100644
--- a/matlab/+sonpipe/private/invoke_text.m
+++ b/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
diff --git a/src/sonpipe/cli.py b/src/sonpipe/cli.py
index c7dbb6b..75c3add 100644
--- a/src/sonpipe/cli.py
+++ b/src/sonpipe/cli.py
@@ -25,7 +25,7 @@
 
 import numpy as np
 
-from . import __version__, channels
+from . import __version__, channels, debuglog
 from .errors import SonpipeError
 from .sonfile import SmrxFile
 
@@ -309,6 +309,10 @@ def build_parser():
 def main(argv=None):
     parser = build_parser()
     args = parser.parse_args(argv)
+    if debuglog.enabled():
+        shown = argv if argv is not None else sys.argv[1:]
+        debuglog.log("main", command=getattr(args, "command", None),
+                     argv=" ".join(str(a) for a in shown))
     try:
         return args.func(args)
     except SonpipeError as exc:
diff --git a/src/sonpipe/debuglog.py b/src/sonpipe/debuglog.py
new file mode 100644
index 0000000..2094fbd
--- /dev/null
+++ b/src/sonpipe/debuglog.py
@@ -0,0 +1,119 @@
+"""Opt-in breadcrumb logging for diagnosing hard crashes.
+
+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
+exception.  ``abort()`` cannot be caught with ``try``/``except`` -- it kills the
+whole interpreter immediately -- so an ordinary traceback is never produced and
+the host (e.g. MATLAB) may only see a truncated or empty result.
+
+To find *where* such a crash happens, sonpipe can write a breadcrumb line
+immediately before and after every call into ``sonpy``.  The lines are written
+with an unbuffered ``os.write`` (and ``fsync``) so they survive an ``abort()``
+that skips Python's normal buffer flush.  The **last line in the log** is then
+the ``sonpy`` call -- with its exact arguments -- that triggered the crash.
+
+Logging is off by default and is controlled by the ``SONPIPE_LOG`` environment
+variable:
+
+* unset / ``""`` / ``"0"`` / ``"false"``  -> disabled (zero overhead)
+* ``"1"`` / ``"true"``                     -> log to the default path
+                                              ``~/.local/var/log/sonpipe-<uid>.log``
+* any other value                          -> treated as a log file path
+                                              (``~`` is expanded)
+
+From MATLAB you can turn it on for a session with::
+
+    setenv('SONPIPE_LOG', '1');   % or a full path
+
+and then re-run the command that crashes; the child process inherits the
+variable.  Turn it back off with ``setenv('SONPIPE_LOG', '')``.
+"""
+
+import os
+import time
+
+_state = {"resolved": False, "path": None}
+
+
+def _default_path():
+    base = os.path.expanduser("~/.local/var/log")
+    try:
+        os.makedirs(base, exist_ok=True)
+    except OSError:
+        base = os.path.expanduser("~")
+    if hasattr(os, "getuid"):
+        who = os.getuid()
+    else:  # pragma: no cover - Windows has no getuid
+        who = os.getpid()
+    return os.path.join(base, "sonpipe-{}.log".format(who))
+
+
+def logfile_path():
+    """Return the resolved log file path, or ``None`` when logging is disabled."""
+    if _state["resolved"]:
+        return _state["path"]
+    val = os.environ.get("SONPIPE_LOG", "")
+    low = val.strip().lower()
+    if low in ("", "0", "false", "no", "off"):
+        path = None
+    elif low in ("1", "true", "yes", "on"):
+        path = _default_path()
+    else:
+        path = os.path.expanduser(val)
+    _state["path"] = path
+    _state["resolved"] = True
+    return path
+
+
+def enabled():
+    return logfile_path() is not None
+
+
+def log(event, **fields):
+    """Append one breadcrumb line, flushed to the OS so it survives an abort()."""
+    path = logfile_path()
+    if path is None:
+        return
+    parts = ["{:.6f}".format(time.time()), "pid={}".format(os.getpid()), event]
+    for key, value in fields.items():
+        parts.append("{}={}".format(key, value))
+    line = (" ".join(parts) + "\n").encode("utf-8", "replace")
+    try:
+        fd = os.open(path, os.O_WRONLY | os.O_CREAT | os.O_APPEND, 0o644)
+        try:
+            os.write(fd, line)
+            try:
+                os.fsync(fd)
+            except OSError:  # pragma: no cover - fsync may be unsupported
+                pass
+        finally:
+            os.close(fd)
+    except OSError:
+        # Logging must never break a read; silently give up if we cannot write.
+        pass
+
+
+def call(name, func, *args, **kwargs):
+    """Invoke ``func(*args, **kwargs)``, logging a breadcrumb around the call.
+
+    When logging is disabled this is a thin passthrough with no overhead beyond
+    a single dict lookup, so it is safe to route every ``sonpy`` call through it.
+
+    The ``->`` line is written (and flushed) *before* the call, so if the call
+    aborts the process, that line is the last thing in the log and names exactly
+    which ``sonpy`` operation -- and with which arguments -- crashed.
+    """
+    if not enabled():
+        return func(*args, **kwargs)
+    arglist = ",".join([repr(a) for a in args]
+                       + ["{}={!r}".format(k, v) for k, v in kwargs.items()])
+    log("-> " + name, args=arglist)
+    result = func(*args, **kwargs)
+    size = getattr(result, "size", None)
+    if size is None:
+        try:
+            size = len(result)
+        except TypeError:
+            size = "n/a"
+    log("<- " + name, size=size)
+    return result
diff --git a/src/sonpipe/sonfile.py b/src/sonpipe/sonfile.py
index 55e452f..4a9358b 100644
--- a/src/sonpipe/sonfile.py
+++ b/src/sonpipe/sonfile.py
@@ -19,7 +19,7 @@
 
 import numpy as np
 
-from . import channels
+from . import channels, debuglog
 from .errors import SonpipeError
 
 
@@ -103,7 +103,8 @@ def __init__(self, path, sonlib=None):
             raise SonpipeError("File not found: {}".format(self.path))
 
         # sonpy opens in read-only mode when the second argument is True.
-        self.f = sonlib.SonFile(self.path, True)
+        debuglog.log("open", path=self.path)
+        self.f = debuglog.call("SonFile", sonlib.SonFile, self.path, True)
         self._check_open_error()
 
         self.timebase = float(self.f.GetTimeBase())
@@ -342,18 +343,23 @@ def read_waveform(self, number, start=None, count=None, t0=None, t1=None,
                 )
             )
         tfrom, tupto, nmax = self._wave_tick_range(index, start, count, t0, t1)
+        debuglog.log("read_waveform", number=number, index=index, kind=kind,
+                     start=start, count=count, t0=t0, t1=t1,
+                     tfrom=tfrom, tupto=tupto, nmax=nmax)
         if nmax <= 0:
             return np.zeros(0, dtype=np.float64 if scaled else _wave_raw_dtype(kind))
 
         if kind == channels.ADC:
-            raw = np.asarray(self.f.ReadInts(index, nmax, tfrom, tupto))
+            raw = np.asarray(debuglog.call(
+                "ReadInts", self.f.ReadInts, index, nmax, tfrom, tupto))
             if scaled:
                 scale = self._num("GetChannelScale", index, default=1.0)
                 offset = self._num("GetChannelOffset", index, default=0.0)
                 return raw.astype(np.float64) * (scale / 6553.6) + offset
             return raw.astype(np.int16)
         else:  # REAL_WAVE
-            raw = np.asarray(self.f.ReadFloats(index, nmax, tfrom, tupto))
+            raw = np.asarray(debuglog.call(
+                "ReadFloats", self.f.ReadFloats, index, nmax, tfrom, tupto))
             return raw.astype(np.float64 if scaled else np.float32)
 
     def read_events(self, number, t0=None, t1=None, chunk=1_000_000):
@@ -366,6 +372,8 @@ def read_events(self, number, t0=None, t1=None, chunk=1_000_000):
         index = self.index_for_number(number)
         kind = self.kind(index)
         tfrom, tupto = self._event_tick_range(t0, t1)
+        debuglog.log("read_events", number=number, index=index, kind=kind,
+                     t0=t0, t1=t1, tfrom=tfrom, tupto=tupto)
 
         reader = self._event_reader_for(kind)
         pieces = []
@@ -389,12 +397,14 @@ def _event_reader_for(self, kind):
         have a plain-event reader, so we pull markers and take their ticks.
         """
         if kind in channels.EVENT_KINDS:
-            return lambda i, n, a, b: self.f.ReadEvents(i, n, a, b)
+            return lambda i, n, a, b: debuglog.call(
+                "ReadEvents", self.f.ReadEvents, i, n, a, b)
 
         marker_method = self._marker_method(kind)
+        marker_name = getattr(marker_method, "__name__", "ReadMarkers")
 
         def read_marker_ticks(i, n, a, b):
-            markers = marker_method(i, n, a, b)
+            markers = debuglog.call(marker_name, marker_method, i, n, a, b)
             return _marker_ticks(markers)
 
         return read_marker_ticks
@@ -432,11 +442,14 @@ def read_markers(self, number, t0=None, t1=None, chunk=1_000_000):
             )
         tfrom, tupto = self._event_tick_range(t0, t1)
         marker_method = self._marker_method(kind)
+        marker_name = getattr(marker_method, "__name__", "ReadMarkers")
+        debuglog.log("read_markers", number=number, index=index, kind=kind,
+                     t0=t0, t1=t1, tfrom=tfrom, tupto=tupto)
 
         out = []
         cursor = tfrom
         while cursor < tupto:
-            markers = marker_method(index, chunk, cursor, tupto)
+            markers = debuglog.call(marker_name, marker_method, index, chunk, cursor, tupto)
             markers = list(markers) if markers is not None else []
             if not markers:
                 break
diff --git a/tests/test_debuglog.py b/tests/test_debuglog.py
new file mode 100644
index 0000000..f088668
--- /dev/null
+++ b/tests/test_debuglog.py
@@ -0,0 +1,104 @@
+"""Tests for the opt-in breadcrumb logging (sonpipe.debuglog)."""
+
+import importlib
+import os
+import signal
+import subprocess
+import sys
+
+import pytest
+
+import fakesonpy
+from sonpipe import debuglog
+
+
+@pytest.fixture(autouse=True)
+def _fresh_debuglog(monkeypatch):
+    # debuglog caches the resolved path; reset it for each test.
+    monkeypatch.setattr(debuglog, "_state", {"resolved": False, "path": None})
+    monkeypatch.delenv("SONPIPE_LOG", raising=False)
+    yield
+
+
+@pytest.mark.parametrize("value", ["", "0", "false", "off", "NO"])
+def test_disabled_values_yield_no_path(monkeypatch, value):
+    monkeypatch.setenv("SONPIPE_LOG", value)
+    monkeypatch.setattr(debuglog, "_state", {"resolved": False, "path": None})
+    assert debuglog.logfile_path() is None
+    assert debuglog.enabled() is False
+
+
+def test_explicit_path_is_used_and_expanded(tmp_path, monkeypatch):
+    target = tmp_path / "sub" / "sonpipe.log"
+    monkeypatch.setenv("SONPIPE_LOG", str(target))
+    monkeypatch.setattr(debuglog, "_state", {"resolved": False, "path": None})
+    assert debuglog.logfile_path() == str(target)
+    assert debuglog.enabled() is True
+
+
+def test_log_writes_line_with_fields(tmp_path, monkeypatch):
+    target = tmp_path / "sonpipe.log"
+    monkeypatch.setenv("SONPIPE_LOG", str(target))
+    monkeypatch.setattr(debuglog, "_state", {"resolved": False, "path": None})
+    debuglog.log("read_waveform", number=1, nmax=50)
+    text = target.read_text()
+    assert "read_waveform" in text
+    assert "number=1" in text
+    assert "nmax=50" in text
+
+
+def test_log_is_noop_when_disabled(tmp_path, monkeypatch):
+    # No SONPIPE_LOG set -> nothing is written anywhere.
+    debuglog.log("should_not_appear", x=1)
+    assert not any(p.name.endswith(".log") for p in tmp_path.iterdir())
+
+
+def test_call_passes_through_and_logs_both_ends(tmp_path, monkeypatch):
+    target = tmp_path / "sonpipe.log"
+    monkeypatch.setenv("SONPIPE_LOG", str(target))
+    monkeypatch.setattr(debuglog, "_state", {"resolved": False, "path": None})
+    result = debuglog.call("Widget", lambda a, b: a + b, 2, 3)
+    assert result == 5
+    text = target.read_text()
+    assert "-> Widget" in text
+    assert "<- Widget" in text
+    assert "args=2,3" in text
+
+
+def test_call_is_transparent_when_disabled():
+    # With logging off, call() is a plain passthrough (and touches no disk).
+    assert debuglog.call("Widget", lambda a, b: a * b, 4, 5) == 20
+
+
+def test_breadcrumb_survives_an_abort(tmp_path):
+    """The '-> name' line must be flushed *before* the call, so it survives an
+    uncatchable abort() -- the exact scenario sonpy's assert triggers."""
+    logpath = tmp_path / "sonpipe.log"
+    driver = (
+        "import os, signal, sys\n"
+        "sys.path[:0] = [{tests!r}, {src!r}]\n"
+        "os.environ['SONPIPE_LOG'] = {log!r}\n"
+        "from sonpipe import debuglog\n"
+        "def boom():\n"
+        "    os.kill(os.getpid(), signal.SIGABRT)\n"
+        "debuglog.call('ReadInts', boom)\n"
+    ).format(
+        tests=os.path.join(os.path.dirname(__file__)),
+        src=os.path.join(os.path.dirname(os.path.dirname(__file__)), "src"),
+        log=str(logpath),
+    )
+    proc = subprocess.run([sys.executable, "-c", driver],
+                          capture_output=True, text=True)
+    # Killed by SIGABRT (negative signal number on POSIX).
+    assert proc.returncode == -signal.SIGABRT
+    lines = logpath.read_text().strip().splitlines()
+    # The last surviving line is the pre-call breadcrumb naming the crash site,
+    # and there is no matching '<- ReadInts' completion line.
+    assert lines[-1].split("pid=")[1].split(" ", 1)[1].startswith("-> ReadInts")
+    assert not any("<- ReadInts" in ln for ln in lines)
+
+
+def test_importable_alongside_fakesonpy():
+    # Guard against import cycles between sonfile and debuglog.
+    importlib.reload(fakesonpy)
+    from sonpipe import sonfile  # noqa: F401

From 8b1444f1cf00ffc2f05a2209b689f6a271027a72 Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Sun, 19 Jul 2026 19:24:29 +0000
Subject: [PATCH 2/6] Instrument metadata/teardown and close sonpy file
 explicitly

Follow-up to the crash-diagnosis work. A breadcrumb log from a real
crash showed the abort happening outside the previously instrumented
read/open calls -- i.e. in the metadata accessors or, most likely, when
sonpy releases the file handle at interpreter shutdown (a teardown-order
assertion that fires after a read has already succeeded).

Two changes:

- Instrument the remaining sonpy boundaries in sonfile.py: GetTimeBase,
  MaxChannels, ChannelType, ChannelDivide, GetMaxTime, GetFileVersion,
  AppID and the _num/_text accessors (ChannelMaxTime, GetChannelScale,
  GetChannelOffset, GetIdealRate, GetChannelTitle/Units/Comment). The log
  now covers every call into sonpy, so a metadata crash is pinpointed the
  same way a read crash is.

- Add SmrxFile.close() plus context-manager support, and have every CLI
  command close the file explicitly (with output flushed first) instead
  of leaving it to garbage collection. Closing while the interpreter is
  healthy makes the release step visible in the log and, in practice,
  avoids the shutdown-order abort() class entirely. A new "done"
  breadcrumb in main() marks a clean finish, so the log's last line
  distinguishes a completed command from a mid-call crash.

Adds close()/context-manager tests and expands the README Troubleshooting
section to explain reading the log tail.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C1UYvbvczg9QvqKg8YNr4k
---
 README.md              |  32 +++++++-----
 src/sonpipe/cli.py     | 107 +++++++++++++++++++++++------------------
 src/sonpipe/sonfile.py |  53 ++++++++++++++++----
 tests/test_sonfile.py  |  27 +++++++++++
 4 files changed, 151 insertions(+), 68 deletions(-)

diff --git a/README.md b/README.md
index cc04e7b..70301d1 100644
--- a/README.md
+++ b/README.md
@@ -276,17 +276,27 @@ Two mechanisms help you catch and locate such a crash:
    `~/.local/var/log/sonpipe-<uid>.log`; any other value → that path
    (`~` is expanded); unset/`0`/`false`/`off` → disabled (zero overhead).
 
-   A typical crash tail looks like:
-
-   ```
-   … read_waveform number=21 index=20 kind=1 start=… count=… tfrom=… tupto=… nmax=…
-   … -> ReadInts args=20,…,…,…          <-- last line: this sonpy call aborted
-   ```
-
-   The `read_waveform` / `read_events` / `read_markers` context line just above
-   shows the resolved sample/tick range, so you can see exactly which arguments
-   sonpipe passed to sonpy — useful for reporting the crash to CED or for adding
-   a guard in sonpipe.
+   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` — the command completed and the data is
+     valid; any crash report came from interpreter shutdown *after* the result
+     was delivered.
+
+   To avoid the teardown-order case, sonpipe now closes the sonpy file handle
+   explicitly at the end of each command (while the interpreter is still
+   healthy) rather than leaving it to garbage collection at shutdown. This makes
+   the release step visible in the log and, in practice, prevents a class of
+   post-read `abort()`s.
 
 ---
 
diff --git a/src/sonpipe/cli.py b/src/sonpipe/cli.py
index 75c3add..6557da4 100644
--- a/src/sonpipe/cli.py
+++ b/src/sonpipe/cli.py
@@ -71,6 +71,9 @@ def _dump_json(obj, pretty):
     else:
         json.dump(obj, sys.stdout, separators=(",", ":"))
     sys.stdout.write("\n")
+    # Flush before the caller closes the file, so the payload is delivered even
+    # if sonpy aborts while its handle is being released.
+    sys.stdout.flush()
 
 
 # --------------------------------------------------------------------------
@@ -78,32 +81,32 @@ def _dump_json(obj, pretty):
 # --------------------------------------------------------------------------
 
 def cmd_header(args):
-    smrx = _open(args.file)
-    out = {
-        "fileinfo": smrx.file_info(),
-        "channelinfo": smrx.all_channel_info(),
-    }
-    _dump_json(out, args.pretty)
-    return 0
+    with _open(args.file) as smrx:
+        out = {
+            "fileinfo": smrx.file_info(),
+            "channelinfo": smrx.all_channel_info(),
+        }
+        _dump_json(out, args.pretty)
+        return 0
 
 
 def cmd_sampleinterval(args):
-    smrx = _open(args.file)
-    info = smrx.channel_info(args.channel)
-    if info is None:
-        raise SonpipeError("Channel {} is not recorded in the file.".format(args.channel))
-    sample_interval = info.get("sampleinterval")
-    out = {
-        "channel": args.channel,
-        "kind": info["kind"],
-        "kind_name": info["kind_name"],
-        "sampleinterval": sample_interval,
-        "samplerate": info.get("samplerate"),
-        "total_samples": info.get("num_samples"),
-        "total_time": info.get("max_time"),
-    }
-    _dump_json(out, args.pretty)
-    return 0
+    with _open(args.file) as smrx:
+        info = smrx.channel_info(args.channel)
+        if info is None:
+            raise SonpipeError("Channel {} is not recorded in the file.".format(args.channel))
+        sample_interval = info.get("sampleinterval")
+        out = {
+            "channel": args.channel,
+            "kind": info["kind"],
+            "kind_name": info["kind_name"],
+            "sampleinterval": sample_interval,
+            "samplerate": info.get("samplerate"),
+            "total_samples": info.get("num_samples"),
+            "total_time": info.get("max_time"),
+        }
+        _dump_json(out, args.pretty)
+        return 0
 
 
 def _write_binary(arr, dtype, endian):
@@ -120,19 +123,19 @@ def _write_binary(arr, dtype, endian):
 
 
 def cmd_read(args):
-    smrx = _open(args.file)
-    info = smrx.channel_info(args.channel)
-    if info is None:
-        raise SonpipeError("Channel {} is not recorded in the file.".format(args.channel))
-    kind = info["kind"]
+    with _open(args.file) as smrx:
+        info = smrx.channel_info(args.channel)
+        if info is None:
+            raise SonpipeError("Channel {} is not recorded in the file.".format(args.channel))
+        kind = info["kind"]
 
-    if kind in channels.WAVEFORM_KINDS:
-        return _read_waveform(smrx, args, info)
-    if kind in channels.EVENT_KINDS:
-        return _read_events(smrx, args, info)
-    if kind in channels.MARKER_KINDS:
-        return _read_markers(smrx, args, info)
-    raise SonpipeError("Unsupported channel kind {} ({}).".format(kind, info["kind_name"]))
+        if kind in channels.WAVEFORM_KINDS:
+            return _read_waveform(smrx, args, info)
+        if kind in channels.EVENT_KINDS:
+            return _read_events(smrx, args, info)
+        if kind in channels.MARKER_KINDS:
+            return _read_markers(smrx, args, info)
+        raise SonpipeError("Unsupported channel kind {} ({}).".format(kind, info["kind_name"]))
 
 
 def _estimate_wave_samples(args, info):
@@ -182,6 +185,7 @@ def _read_waveform(smrx, args, info):
     n = _write_binary(data, dtype, args.endian)
     sys.stderr.write("sonpipe: wrote {} samples ({}) for channel {}\n".format(
         n, dtype, args.channel))
+    sys.stderr.flush()  # sentinel must reach disk before the file handle closes
     return 0
 
 
@@ -200,6 +204,7 @@ def _read_events(smrx, args, info):
     n = _write_binary(times, dtype, args.endian)
     sys.stderr.write("sonpipe: wrote {} event times ({}) for channel {}\n".format(
         n, dtype, args.channel))
+    sys.stderr.flush()  # sentinel must reach disk before the file handle closes
     return 0
 
 
@@ -220,18 +225,19 @@ def _read_markers(smrx, args, info):
 
 def cmd_channels(args):
     """Convenience listing: one line per channel (human/script friendly)."""
-    smrx = _open(args.file)
-    for info in smrx.all_channel_info():
-        sr = info.get("samplerate")
-        sr_str = "{:.4f} Hz".format(sr) if sr else "-"
-        sys.stdout.write("{number}\t{kind_name}\t{ndr_type}\t{sr}\t{title}\n".format(
-            number=info["number"],
-            kind_name=info["kind_name"],
-            ndr_type=info["ndr_type"],
-            sr=sr_str,
-            title=info.get("title", ""),
-        ))
-    return 0
+    with _open(args.file) as smrx:
+        for info in smrx.all_channel_info():
+            sr = info.get("samplerate")
+            sr_str = "{:.4f} Hz".format(sr) if sr else "-"
+            sys.stdout.write("{number}\t{kind_name}\t{ndr_type}\t{sr}\t{title}\n".format(
+                number=info["number"],
+                kind_name=info["kind_name"],
+                ndr_type=info["ndr_type"],
+                sr=sr_str,
+                title=info.get("title", ""),
+            ))
+        sys.stdout.flush()
+        return 0
 
 
 # --------------------------------------------------------------------------
@@ -314,7 +320,12 @@ def main(argv=None):
         debuglog.log("main", command=getattr(args, "command", None),
                      argv=" ".join(str(a) for a in shown))
     try:
-        return args.func(args)
+        rc = args.func(args)
+        # A clean-finish breadcrumb: if the log ends here, the command completed
+        # normally and any abort happened during interpreter shutdown; if the log
+        # instead ends on a dangling '-> <sonpy call>', that call is the crash.
+        debuglog.log("done", command=getattr(args, "command", None), rc=rc)
+        return rc
     except SonpipeError as exc:
         sys.stderr.write("sonpipe: error: {}\n".format(exc))
         return 2
diff --git a/src/sonpipe/sonfile.py b/src/sonpipe/sonfile.py
index 4a9358b..5fb8215 100644
--- a/src/sonpipe/sonfile.py
+++ b/src/sonpipe/sonfile.py
@@ -107,8 +107,41 @@ def __init__(self, path, sonlib=None):
         self.f = debuglog.call("SonFile", sonlib.SonFile, self.path, True)
         self._check_open_error()
 
-        self.timebase = float(self.f.GetTimeBase())
-        self.max_channels = int(self.f.MaxChannels())
+        self.timebase = float(debuglog.call("GetTimeBase", self.f.GetTimeBase))
+        self.max_channels = int(debuglog.call("MaxChannels", self.f.MaxChannels))
+
+    # -- close / teardown --------------------------------------------------
+
+    def close(self):
+        """Release the sonpy file handle while the interpreter is still healthy.
+
+        sonpy's ``SonFile`` closes its file in its C++ destructor. If we leave
+        that to interpreter shutdown, the destructor can run in a torn-down
+        state and fail an internal assertion (abort()/SIGABRT) *after* a read
+        has already succeeded -- a crash with no bad data but an alarming
+        report. Closing explicitly here, at a well-defined point, both makes
+        that step visible in the breadcrumb log and avoids the shutdown-order
+        assertion. Safe to call more than once.
+        """
+        f = getattr(self, "f", None)
+        if f is None:
+            return
+        self.f = None
+        closer = getattr(f, "Close", None) or getattr(f, "close", None)
+        if callable(closer):
+            debuglog.call("Close", closer)
+        else:
+            # No explicit close method; drop the last reference now (rather than
+            # at interpreter shutdown) so the destructor runs while healthy.
+            debuglog.log("del SonFile")
+            del f
+
+    def __enter__(self):
+        return self
+
+    def __exit__(self, *exc):
+        self.close()
+        return False
 
     # -- open / error handling ---------------------------------------------
 
@@ -146,7 +179,7 @@ def index_for_number(self, number):
 
     def kind(self, index):
         """Return the integer channel-type ``kind`` for a sonpy channel *index*."""
-        return int(self.f.ChannelType(index))
+        return int(debuglog.call("ChannelType", self.f.ChannelType, index))
 
     def channel_numbers(self):
         """Return the Spike2 channel numbers of every non-Off channel."""
@@ -161,7 +194,8 @@ def _text(self, method_name, index):
         if method is None:
             return ""
         try:
-            value = _call(method, index)
+            value = debuglog.call(
+                "{}[{}]".format(method_name, index), lambda: _call(method, index))
         except Exception:
             return ""
         if value is None:
@@ -173,7 +207,8 @@ def _num(self, method_name, index, default=None):
         if method is None:
             return default
         try:
-            return float(_call(method, index))
+            return float(debuglog.call(
+                "{}[{}]".format(method_name, index), lambda: _call(method, index)))
         except Exception:
             return default
 
@@ -214,7 +249,7 @@ def channel_info(self, number):
         }
 
         if kind in channels.WAVEFORM_KINDS:
-            divide = int(self.f.ChannelDivide(index))
+            divide = int(debuglog.call("ChannelDivide", self.f.ChannelDivide, index))
             info["divide"] = divide
             sample_interval = divide * self.timebase
             info["sampleinterval"] = sample_interval
@@ -249,7 +284,7 @@ def file_info(self):
             method = getattr(self.f, name, None)
             if method is not None:
                 try:
-                    info[key] = method()
+                    info[key] = debuglog.call(name, method)
                 except Exception:
                     pass
         return info
@@ -258,7 +293,7 @@ def _file_max_ticks(self):
         getter = getattr(self.f, "GetMaxTime", None)
         if getter is not None:
             try:
-                return int(getter())
+                return int(debuglog.call("GetMaxTime", getter))
             except Exception:
                 pass
         # Fall back to the largest per-channel max time.
@@ -283,7 +318,7 @@ def _wave_tick_range(self, index, start, count, t0, t1):
         arguments may be given.  Sample-based reads assume the waveform's first
         sample sits at tick 0, which is the common Spike2 case.
         """
-        divide = int(self.f.ChannelDivide(index))
+        divide = int(debuglog.call("ChannelDivide", self.f.ChannelDivide, index))
         if divide <= 0:
             divide = 1
         max_ticks = int(self._num("ChannelMaxTime", index, default=0.0) or 0)
diff --git a/tests/test_sonfile.py b/tests/test_sonfile.py
index dde1727..8453e6f 100644
--- a/tests/test_sonfile.py
+++ b/tests/test_sonfile.py
@@ -229,3 +229,30 @@ def test_read_markers_on_waveform_errors(smrx_path):
     smrx = open_file(smrx_path)
     with pytest.raises(SonpipeError):
         smrx.read_markers(1)
+
+
+def test_close_is_idempotent_and_releases_handle(smrx_path):
+    f = open_file(smrx_path)
+    assert f.f is not None
+    f.close()
+    assert f.f is None
+    f.close()  # safe to call again
+    assert f.f is None
+
+
+def test_context_manager_closes_on_exit(smrx_path):
+    with open_file(smrx_path) as f:
+        assert f.f is not None
+        data = f.read_waveform(1, start=0, count=4)
+        assert data.size == 4
+    assert f.f is None
+
+
+def test_close_calls_sonpy_close_when_present(smrx_path, monkeypatch):
+    f = open_file(smrx_path)
+    closed = {"n": 0}
+    monkeypatch.setattr(f.f, "Close", lambda: closed.__setitem__("n", closed["n"] + 1),
+                        raising=False)
+    f.close()
+    assert closed["n"] == 1
+    assert f.f is None

From 6f1da8c5d6ee06e69a07f94ffada0a3c7db5469a Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Sun, 19 Jul 2026 19:31:55 +0000
Subject: [PATCH 3/6] Hard-exit past interpreter shutdown to avoid post-read
 sonpy abort

A breadcrumb log from a real crash showed the command running fully to
completion -- read succeeds, file handle released, main() returns rc=0,
'done' logged -- and sonpy then aborting (SIGABRT) during Python's
*interpreter shutdown*, in a static/atexit destructor that runs after all
output has already been delivered. That abort cannot be caught from
Python and does no harm to the result, but it still produces a crash
report and (through the Apple-Silicon arch wrapper) an alarming failure.

Add a process entry point sonpipe.cli:run() that runs main(), flushes
stdout/stderr, and then calls os._exit() -- terminating immediately
without running Python finalizers or C++ static destructors, so the
teardown code where sonpy aborts never executes. Every stream is flushed
first, so no data is lost. main() stays a pure, importable function (no
os._exit), so tests and in-process callers are unaffected.

Wire both entry points to run(): the console script (pyproject
[project.scripts]) and python -m sonpipe (__main__.py). The MATLAB-test
fakecli.py now also calls run() so the double exercises the same exit
path. A 'hard_exit' breadcrumb marks the bypass in the log.

Adds unit + end-to-end subprocess tests for run() and documents the
workaround in the README.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C1UYvbvczg9QvqKg8YNr4k
---
 README.md                          | 31 +++++++++++++++-------
 pyproject.toml                     |  2 +-
 src/sonpipe/__main__.py            |  6 ++---
 src/sonpipe/cli.py                 | 35 ++++++++++++++++++++++++-
 test/+sonpipe/+unittest/fakecli.py |  4 ++-
 tests/test_debuglog.py             | 41 ++++++++++++++++++++++++++++++
 6 files changed, 103 insertions(+), 16 deletions(-)

diff --git a/README.md b/README.md
index 70301d1..352a1e3 100644
--- a/README.md
+++ b/README.md
@@ -288,15 +288,28 @@ Two mechanisms help you catch and locate such a crash:
      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` — the command completed and the data is
-     valid; any crash report came from interpreter shutdown *after* the result
-     was delivered.
-
-   To avoid the teardown-order case, sonpipe now closes the sonpy file handle
-   explicitly at the end of each command (while the interpreter is still
-   healthy) rather than leaving it to garbage collection at shutdown. This makes
-   the release step visible in the log and, in practice, prevents a class of
-   post-read `abort()`s.
+   * 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.)
 
 ---
 
diff --git a/pyproject.toml b/pyproject.toml
index 033ab36..5c77a61 100644
--- a/pyproject.toml
+++ b/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"]
diff --git a/src/sonpipe/__main__.py b/src/sonpipe/__main__.py
index 84ac55f..48b37c6 100644
--- a/src/sonpipe/__main__.py
+++ b/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()
diff --git a/src/sonpipe/cli.py b/src/sonpipe/cli.py
index 6557da4..5c46894 100644
--- a/src/sonpipe/cli.py
+++ b/src/sonpipe/cli.py
@@ -21,6 +21,7 @@
 import argparse
 import json
 import math
+import os
 import sys
 
 import numpy as np
@@ -333,5 +334,37 @@ def main(argv=None):
         return 0
 
 
+def run(argv=None):
+    """Process entry point: run ``main()``, then hard-exit past interpreter teardown.
+
+    On some files CED's sonpy aborts (SIGABRT) during Python's interpreter
+    shutdown -- in a static/atexit destructor that runs *after* the command has
+    already completed and delivered all of its output. There is no way to catch
+    that abort from Python. But because the command is finished and every stream
+    has been flushed by the time ``main()`` returns, we can simply skip the
+    shutdown: ``os._exit`` terminates the process immediately without running
+    Python finalizers or C++ static destructors, so a completed read no longer
+    turns into a crash.
+
+    ``main()`` itself stays a normal, importable function (it does *not* call
+    ``os._exit``), so tests and in-process callers are unaffected.
+    """
+    rc = main(argv)
+    if not isinstance(rc, int):
+        rc = 0
+    # Make sure nothing is left in a buffer before we bypass finalization.
+    for stream in (sys.stdout, sys.stderr):
+        try:
+            stream.flush()
+        except Exception:
+            pass
+    try:
+        sys.stdout.buffer.flush()
+    except Exception:
+        pass
+    debuglog.log("hard_exit", rc=rc)
+    os._exit(rc)
+
+
 if __name__ == "__main__":  # pragma: no cover
-    sys.exit(main())
+    run()
diff --git a/test/+sonpipe/+unittest/fakecli.py b/test/+sonpipe/+unittest/fakecli.py
index 4183263..afed5cc 100644
--- a/test/+sonpipe/+unittest/fakecli.py
+++ b/test/+sonpipe/+unittest/fakecli.py
@@ -30,4 +30,6 @@
 
 
 if __name__ == "__main__":
-    sys.exit(cli.main())
+    # Use run() (not main()) so the MATLAB tests exercise the same hard-exit
+    # entry point as the installed `sonpipe` command.
+    cli.run()
diff --git a/tests/test_debuglog.py b/tests/test_debuglog.py
index f088668..9aa38bd 100644
--- a/tests/test_debuglog.py
+++ b/tests/test_debuglog.py
@@ -102,3 +102,44 @@ def test_importable_alongside_fakesonpy():
     # Guard against import cycles between sonfile and debuglog.
     importlib.reload(fakesonpy)
     from sonpipe import sonfile  # noqa: F401
+
+
+def test_run_hard_exits_with_returncode(monkeypatch):
+    """run() must terminate via os._exit with main()'s return code, bypassing
+    the interpreter teardown where sonpy can abort after a completed command."""
+    from sonpipe import cli
+
+    monkeypatch.setattr(cli, "main", lambda argv=None: 2)
+    seen = {}
+
+    def fake_os_exit(code):
+        seen["code"] = code
+        raise SystemExit(code)  # so the test process itself survives
+
+    monkeypatch.setattr(os, "_exit", fake_os_exit)
+    with pytest.raises(SystemExit) as ei:
+        cli.run()
+    assert seen["code"] == 2
+    assert ei.value.code == 2
+
+
+def test_run_end_to_end_via_subprocess(tmp_path):
+    """`python -m sonpipe` (through run()) exits cleanly and emits data even
+    though run() calls os._exit -- a real end-to-end check of the entry point."""
+    repo = os.path.dirname(os.path.dirname(__file__))
+    smrx = tmp_path / "example.smrx"
+    smrx.write_bytes(b"")
+    driver = (
+        "import sys\n"
+        "sys.path[:0] = [{src!r}, {tests!r}]\n"
+        "import fakesonpy\n"
+        "from sonpipe import sonfile, cli\n"
+        "sonfile.load_sonpy = lambda: fakesonpy\n"
+        "cli.run(['read', {path!r}, '-c', '1', '--start', '0', '--count', '4'])\n"
+    ).format(src=os.path.join(repo, "src"),
+             tests=os.path.join(repo, "tests"),
+             path=str(smrx))
+    proc = subprocess.run([sys.executable, "-c", driver], capture_output=True)
+    assert proc.returncode == 0
+    assert len(proc.stdout) == 4 * 8  # four little-endian doubles
+    assert b"wrote 4 samples" in proc.stderr

From 498df8e243448945600f1a4b23c3513f5c891a71 Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Sun, 19 Jul 2026 19:33:46 +0000
Subject: [PATCH 4/6] Document SONPIPE_LOG in the CLI --help output

Add an epilog to the argument parser describing the SONPIPE_LOG
environment variable (breadcrumb logging for diagnosing a hard sonpy
crash), so it is discoverable from `sonpipe --help` / `python -m sonpipe
--help`, not only in the README.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C1UYvbvczg9QvqKg8YNr4k
---
 src/sonpipe/cli.py | 12 ++++++++++++
 1 file changed, 12 insertions(+)

diff --git a/src/sonpipe/cli.py b/src/sonpipe/cli.py
index 5c46894..312a65e 100644
--- a/src/sonpipe/cli.py
+++ b/src/sonpipe/cli.py
@@ -252,6 +252,18 @@ def build_parser():
             "Stream data from CED Spike2 .smrx/.smr files as raw binary "
             "(via sonpy) for fast ingestion by MATLAB and other tools."
         ),
+        epilog=(
+            "Environment variables:\n"
+            "  SONPIPE_LOG   Diagnose a hard crash. When set, sonpipe writes a\n"
+            "                breadcrumb line before and after every call into\n"
+            "                CED's sonpy, flushed to disk so it survives an\n"
+            "                abort()/SIGABRT. The last line then names the sonpy\n"
+            "                call that crashed. '1'/'true'/'on' logs to\n"
+            "                ~/.local/var/log/sonpipe-<uid>.log; any other value\n"
+            "                is used as the log file path; unset/'0'/'off'\n"
+            "                disables it (the default; zero overhead)."
+        ),
+        formatter_class=argparse.RawDescriptionHelpFormatter,
     )
     parser.add_argument("--version", action="version",
                         version="sonpipe {}".format(__version__))

From dd61d5679f11bda21433f73206ae929f692a8a40 Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Sun, 19 Jul 2026 19:51:57 +0000
Subject: [PATCH 5/6] Make no sonpy call after the sample read; clamp
 over-reads

Breadcrumb logs from a crashing file showed two signatures: (1) a read
returns all its samples (`<- ReadInts size=200001`) and then aborts on
the very next call into sonpy -- the post-read GetChannelScale/
GetChannelOffset lookups used for scaling; and (2) metadata opens abort
in the first sonpy call after SonFile.

Address the read path (the common, recoverable case):

- read_waveform now resolves scale/offset BEFORE the sample read and
  accepts them from the caller. cmd_read passes the values already
  fetched in channel_info, so after ReadInts/ReadFloats the code makes
  *no* further call into sonpy -- a good read can no longer be turned
  into a crash by a follow-up sonpy call on a problematic file.

- _wave_tick_range clamps nmax to the samples actually available from
  tfrom to the channel end, so a request that runs past the last sample
  (e.g. NDR's fixed-size chunking near EOF) is never handed to sonpy as
  an over-read -- another known way to trip its internal assertions.

- Instrument the last un-logged sonpy call (GetOpenError) so a metadata
  crash is named in the log like every other call.

Adds tests for the clamp and for scaling with caller-supplied
scale/offset (verifying sonpy is not consulted after the read).

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C1UYvbvczg9QvqKg8YNr4k
---
 src/sonpipe/cli.py     |  4 ++++
 src/sonpipe/sonfile.py | 30 ++++++++++++++++++++++++++----
 tests/test_sonfile.py  | 39 +++++++++++++++++++++++++++++++++++++++
 3 files changed, 69 insertions(+), 4 deletions(-)

diff --git a/src/sonpipe/cli.py b/src/sonpipe/cli.py
index 312a65e..5eb2763 100644
--- a/src/sonpipe/cli.py
+++ b/src/sonpipe/cli.py
@@ -172,6 +172,10 @@ def _read_waveform(smrx, args, info):
         t0=args.t0,
         t1=args.t1,
         scaled=scaled,
+        # Reuse the scale/offset already fetched in channel_info so no call is
+        # made into sonpy after the sample read (some files abort on it).
+        scale=info.get("scale"),
+        offset=info.get("offset"),
     )
     if args.json:
         _dump_json({
diff --git a/src/sonpipe/sonfile.py b/src/sonpipe/sonfile.py
index 5fb8215..88f0bc1 100644
--- a/src/sonpipe/sonfile.py
+++ b/src/sonpipe/sonfile.py
@@ -151,7 +151,7 @@ def _check_open_error(self):
         if getter is None:
             return
         try:
-            err = getter()
+            err = debuglog.call("GetOpenError", getter)
         except Exception:
             return
         # sonpy returns 0 (or an enum whose int() is 0) on success.
@@ -347,6 +347,14 @@ def _wave_tick_range(self, index, start, count, t0, t1):
 
         if tupto > max_ticks + 1:
             tupto = max_ticks + 1
+        # Never ask sonpy for more samples than actually exist from tfrom to the
+        # end of the channel. Over-reading past the last sample is a known way to
+        # trip sonpy's internal assertions on some files.
+        available = (max_ticks - tfrom) // divide + 1 if tfrom <= max_ticks else 0
+        if available < 0:
+            available = 0
+        if nmax > available:
+            nmax = available
         return tfrom, tupto, int(nmax)
 
     def _event_tick_range(self, t0, t1):
@@ -361,13 +369,21 @@ def _event_tick_range(self, t0, t1):
     # -- reads -------------------------------------------------------------
 
     def read_waveform(self, number, start=None, count=None, t0=None, t1=None,
-                      scaled=True):
+                      scaled=True, scale=None, offset=None):
         """Read waveform samples for a channel and return a numpy array.
 
         For ``Adc`` channels the raw 16-bit integers are converted to real
         units with ``value = adc * scale / 6553.6 + offset`` when ``scaled`` is
         true; otherwise the raw ``int16`` values are returned.  ``RealWave``
         channels are already in real units.
+
+        ``scale``/``offset`` may be supplied by the caller (e.g. from a
+        previously fetched ``channel_info``). When given, they are used directly
+        instead of asking sonpy again *after* the read. This matters because on
+        some files sonpy reads the samples successfully but then aborts
+        (SIGABRT) on the very next call into it; doing no sonpy call after the
+        data read avoids turning a good read into a crash. When not given, the
+        values are read from sonpy as before.
         """
         index = self.index_for_number(number)
         kind = self.kind(index)
@@ -377,6 +393,14 @@ def read_waveform(self, number, start=None, count=None, t0=None, t1=None,
                     number, channels.kind_name(kind), kind
                 )
             )
+        # Resolve scale/offset BEFORE the data read, so that after the read we
+        # make no further calls into sonpy (see the docstring).
+        if kind == channels.ADC and scaled:
+            if scale is None:
+                scale = self._num("GetChannelScale", index, default=1.0)
+            if offset is None:
+                offset = self._num("GetChannelOffset", index, default=0.0)
+
         tfrom, tupto, nmax = self._wave_tick_range(index, start, count, t0, t1)
         debuglog.log("read_waveform", number=number, index=index, kind=kind,
                      start=start, count=count, t0=t0, t1=t1,
@@ -388,8 +412,6 @@ def read_waveform(self, number, start=None, count=None, t0=None, t1=None,
             raw = np.asarray(debuglog.call(
                 "ReadInts", self.f.ReadInts, index, nmax, tfrom, tupto))
             if scaled:
-                scale = self._num("GetChannelScale", index, default=1.0)
-                offset = self._num("GetChannelOffset", index, default=0.0)
                 return raw.astype(np.float64) * (scale / 6553.6) + offset
             return raw.astype(np.int16)
         else:  # REAL_WAVE
diff --git a/tests/test_sonfile.py b/tests/test_sonfile.py
index 8453e6f..00d40a3 100644
--- a/tests/test_sonfile.py
+++ b/tests/test_sonfile.py
@@ -256,3 +256,42 @@ def test_close_calls_sonpy_close_when_present(smrx_path, monkeypatch):
     f.close()
     assert closed["n"] == 1
     assert f.f is None
+
+
+def test_read_waveform_clamps_nmax_to_available(smrx_path, monkeypatch):
+    """A request that runs past the last sample must be clamped, never handed to
+    sonpy as an over-read (a known way to trip its internal asserts)."""
+    f = open_file(smrx_path)
+    seen = {}
+    real = f.f.ReadInts
+
+    def spy(index, nmax, tfrom, tupto):
+        seen["nmax"] = nmax
+        return real(index, nmax, tfrom, tupto)
+
+    monkeypatch.setattr(f.f, "ReadInts", spy)
+    # fakesonpy channel 1 (index 0) has 1000 samples; ask for far more, near end.
+    data = f.read_waveform(1, start=990, count=100000)
+    assert seen["nmax"] == 11          # clamped from 100000 to samples available
+    assert seen["nmax"] < 100          # the key point: not the raw 100000 over-read
+    assert data.size == 10             # sonpy returns the real remaining samples
+
+
+def test_read_waveform_uses_supplied_scale_offset(smrx_path, monkeypatch):
+    """When scale/offset are supplied, read_waveform must NOT call back into
+    sonpy for them after the sample read."""
+    f = open_file(smrx_path)
+    called = {"scale": 0, "offset": 0}
+    monkeypatch.setattr(f.f, "GetChannelScale",
+                        lambda *a, **k: called.__setitem__("scale", called["scale"] + 1) or 2.0,
+                        raising=False)
+    monkeypatch.setattr(f.f, "GetChannelOffset",
+                        lambda *a, **k: called.__setitem__("offset", called["offset"] + 1) or 1.0,
+                        raising=False)
+    data = f.read_waveform(1, start=0, count=4, scaled=True, scale=2.0, offset=1.0)
+    assert called == {"scale": 0, "offset": 0}   # sonpy not consulted after read
+    # The fake's ADC sample i is (i % 2000) - 1000; scaling uses the supplied
+    # scale/offset:  value = adc * scale/6553.6 + offset.
+    for i in range(4):
+        adc = (i % 2000) - 1000
+        assert abs(data[i] - (adc * 2.0 / 6553.6 + 1.0)) < 1e-9

From a8f65acc32d0d8d5f969ddb596b00f160ab37fa7 Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Sun, 19 Jul 2026 20:05:38 +0000
Subject: [PATCH 6/6] Make abort() subprocess test cross-platform (Windows CI)

test_breadcrumb_survives_an_abort asserted returncode == -SIGABRT, which
is POSIX-specific. On Windows there are no real signals; a process that
aborts exits with a positive code. Assert abnormal termination
(returncode != 0) instead; the meaningful checks (the pre-call breadcrumb
survives and no completion line was written) are unchanged.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C1UYvbvczg9QvqKg8YNr4k
---
 tests/test_debuglog.py | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/tests/test_debuglog.py b/tests/test_debuglog.py
index 9aa38bd..a64af08 100644
--- a/tests/test_debuglog.py
+++ b/tests/test_debuglog.py
@@ -89,8 +89,9 @@ def test_breadcrumb_survives_an_abort(tmp_path):
     )
     proc = subprocess.run([sys.executable, "-c", driver],
                           capture_output=True, text=True)
-    # Killed by SIGABRT (negative signal number on POSIX).
-    assert proc.returncode == -signal.SIGABRT
+    # Abnormal termination: a negative signal number on POSIX, or the abort()
+    # exit code on Windows (which has no real signals). Either way, not clean 0.
+    assert proc.returncode != 0
     lines = logpath.read_text().strip().splitlines()
     # The last surviving line is the pre-call breadcrumb naming the crash site,
     # and there is no matching '<- ReadInts' completion line.