diff --git a/README.md b/README.md index 0346ffd..352a1e3 100644 --- a/README.md +++ b/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-.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-.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: 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 + cleanerErr = onCleanup(@() deletefile(errfile)); %#ok - 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 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 + + 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/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 c7dbb6b..5eb2763 100644 --- a/src/sonpipe/cli.py +++ b/src/sonpipe/cli.py @@ -21,11 +21,12 @@ import argparse import json import math +import os import sys import numpy as np -from . import __version__, channels +from . import __version__, channels, debuglog from .errors import SonpipeError from .sonfile import SmrxFile @@ -71,6 +72,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 +82,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 +124,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): @@ -168,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({ @@ -182,6 +190,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 +209,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 +230,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 # -------------------------------------------------------------------------- @@ -245,6 +256,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-.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__)) @@ -309,8 +332,17 @@ 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) + 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 '-> ', 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 @@ -318,5 +350,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/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-.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..88f0bc1 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,11 +103,45 @@ 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()) - 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 --------------------------------------------- @@ -117,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. @@ -145,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.""" @@ -160,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: @@ -172,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 @@ -213,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 @@ -248,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 @@ -257,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. @@ -282,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) @@ -311,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): @@ -325,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) @@ -341,19 +393,30 @@ 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, + 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 +429,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 +454,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 +499,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/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 new file mode 100644 index 0000000..a64af08 --- /dev/null +++ b/tests/test_debuglog.py @@ -0,0 +1,146 @@ +"""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) + # 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. + 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 + + +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 diff --git a/tests/test_sonfile.py b/tests/test_sonfile.py index dde1727..00d40a3 100644 --- a/tests/test_sonfile.py +++ b/tests/test_sonfile.py @@ -229,3 +229,69 @@ 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 + + +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