diff --git a/CHANGELOG.md b/CHANGELOG.md index c9c0e1b..7d1fd46 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ * The shim now writes to Apple's unified logging system (`os_log`) instead of the deprecated `NSLog` API. Output written to `stdout` and `stderr` appears in Console.app and `log stream` as before, but is now tagged with the `OS_LOG_TYPE_DEFAULT` and `OS_LOG_TYPE_ERROR` levels respectively, so the two streams can be filtered separately. * The `encoding` attribute on the writer is now `"utf-8"` (previously `"utf-16-le"` / `"utf-16-be"`), reflecting the underlying API. +* Null characters (`\x00`) are now replaced with Java's "Modified UTF-8" encoding (`\xc0\x80`), rather than being silently dropped. ## 1.0.3 (November 25 2022) diff --git a/src/nslog.py b/src/nslog.py index 05cb782..28c0ccc 100644 --- a/src/nslog.py +++ b/src/nslog.py @@ -1,74 +1,76 @@ -# Python writes all console output to stdout/stderr. However, in production, -# macOS/iOS devices don't record stdout/stderr; only the Apple System Log -# is preserved. -# -# This handler redirects sys.stdout and sys.stderr to the Apple System Log -# by writing to Apple's unified logging system (os_log) via a small native -# extension module, and monkeypatching that wrapper over sys.stdout and -# sys.stderr. - -import io -import sys - -import _oslog_shim - -# os_log_type_t values, re-exported from the native module so callers can -# pass them to ``nslog()`` without importing the shim themselves. -OS_LOG_TYPE_DEFAULT = _oslog_shim.OS_LOG_TYPE_DEFAULT -OS_LOG_TYPE_INFO = _oslog_shim.OS_LOG_TYPE_INFO -OS_LOG_TYPE_DEBUG = _oslog_shim.OS_LOG_TYPE_DEBUG -OS_LOG_TYPE_ERROR = _oslog_shim.OS_LOG_TYPE_ERROR -OS_LOG_TYPE_FAULT = _oslog_shim.OS_LOG_TYPE_FAULT - - -def nslog(s, level=OS_LOG_TYPE_DEFAULT): - """Log the given Python [`str`][] to the unified system log. - - :param s: the message to log. - :param level: an `OS_LOG_TYPE_*` constant selecting the log level. - Defaults to `OS_LOG_TYPE_DEFAULT`. - """ - # os_log accepts UTF-8 C strings; embedded NULs would truncate the - # visible message, so strip them defensively. - _oslog_shim.emit(level, s.replace("\x00", "").encode("utf-8")) - - -class NSLogWriter(io.TextIOBase): - """An output-only text stream that writes to the unified system log. - - Writes are buffered and flushed one log entry per newline-terminated - line, matching the behavior of the original NSLog-backed implementation. - """ - - def __init__(self, level): - super().__init__() - self._level = level - self.buf = "" - - def write(self, s): - self.buf += s - lines = self.buf.split("\n") - for line in lines[:-1]: - nslog(line, self._level) - self.buf = lines[-1] - return len(s) - - def flush(self): - # os_log entries are always whole lines; if there is partial - # un-newlined output buffered, emit it now so it isn't lost on - # interpreter shutdown. - if self.buf: - nslog(self.buf, self._level) - self.buf = "" - - @property - def encoding(self): - return "utf-8" - - -# Replace stdout and stderr with NSLogWriters. stderr is tagged at the -# error level so it can be filtered separately in Console.app; this is -# a behavioral improvement over the legacy implementation, which merged -# both streams onto a single writer. -sys.stdout = NSLogWriter(OS_LOG_TYPE_DEFAULT) -sys.stderr = NSLogWriter(OS_LOG_TYPE_ERROR) +# Python writes all console output to stdout/stderr. However, in production, +# macOS/iOS devices don't record stdout/stderr; only the Apple System Log +# is preserved. +# +# This handler redirects sys.stdout and sys.stderr to the Apple System Log +# by writing to Apple's unified logging system (os_log) via a small native +# extension module, and monkeypatching that wrapper over sys.stdout and +# sys.stderr. + +import io +import sys + +import _oslog_shim + +# os_log_type_t values, re-exported from the native module so callers can +# pass them to ``nslog()`` without importing the shim themselves. +OS_LOG_TYPE_DEFAULT = _oslog_shim.OS_LOG_TYPE_DEFAULT +OS_LOG_TYPE_INFO = _oslog_shim.OS_LOG_TYPE_INFO +OS_LOG_TYPE_DEBUG = _oslog_shim.OS_LOG_TYPE_DEBUG +OS_LOG_TYPE_ERROR = _oslog_shim.OS_LOG_TYPE_ERROR +OS_LOG_TYPE_FAULT = _oslog_shim.OS_LOG_TYPE_FAULT + + +def nslog(s, level=OS_LOG_TYPE_DEFAULT): + """Log the given Python [`str`][] to the unified system log. + + :param s: the message to log. + :param level: an `OS_LOG_TYPE_*` constant selecting the log level. + Defaults to `OS_LOG_TYPE_DEFAULT`. + """ + # os_log accepts UTF-8 C strings; embedded NULs would truncate the + # visible message, so replace them with Java's "Modified UTF-8" + # encoding of U+0000 (this matches what CPython does with the + # Apple system logger). + _oslog_shim.emit(level, s.replace("\x00", "\xc0\x80").encode("utf-8")) + + +class NSLogWriter(io.TextIOBase): + """An output-only text stream that writes to the unified system log. + + Writes are buffered and flushed one log entry per newline-terminated + line, matching the behavior of the original NSLog-backed implementation. + """ + + def __init__(self, level): + super().__init__() + self._level = level + self.buf = "" + + def write(self, s): + self.buf += s + lines = self.buf.split("\n") + for line in lines[:-1]: + nslog(line, self._level) + self.buf = lines[-1] + return len(s) + + def flush(self): + # os_log entries are always whole lines; if there is partial + # un-newlined output buffered, emit it now so it isn't lost on + # interpreter shutdown. + if self.buf: + nslog(self.buf, self._level) + self.buf = "" + + @property + def encoding(self): + return "utf-8" + + +# Replace stdout and stderr with NSLogWriters. stderr is tagged at the +# error level so it can be filtered separately in Console.app; this is +# a behavioral improvement over the legacy implementation, which merged +# both streams onto a single writer. +sys.stdout = NSLogWriter(OS_LOG_TYPE_DEFAULT) +sys.stderr = NSLogWriter(OS_LOG_TYPE_ERROR) diff --git a/tests/smoke.py b/tests/smoke.py index 71aabe3..f122860 100644 --- a/tests/smoke.py +++ b/tests/smoke.py @@ -1,38 +1,40 @@ -""" -std-nslog smoke test driver. - -This file is a *helper* for `test_smoke.py`, not a test itself. -It imports nslog, and outputs some known strings to the console. -""" - -import sys - -import nslog - - -def main(tag) -> None: - # Importing nslog should have replaced both standard streams with - # NSLogWriter instances; if it didn't, nothing else here is meaningful. - assert isinstance(sys.stdout, nslog.NSLogWriter), ( - f"sys.stdout was not replaced by NSLogWriter (got {type(sys.stdout)!r})" - ) - assert isinstance(sys.stderr, nslog.NSLogWriter), ( - f"sys.stderr was not replaced by NSLogWriter (got {type(sys.stderr)!r})" - ) - - # Exercise stdout, stderr, and direct nslog() calls at multiple log - # levels. Each line is tagged so the CI verifier can pick them out of - # the unified log unambiguously. - print(f"{tag} hello from std-nslog smoke test") - print(f"{tag} this is stderr", file=sys.stderr) - nslog.nslog(f"{tag} explicit info", level=nslog.OS_LOG_TYPE_INFO) - nslog.nslog(f"{tag} explicit error", level=nslog.OS_LOG_TYPE_ERROR) - - # NSLogWriter buffers partial lines until a newline arrives; flush - # explicitly so nothing is dropped before the unified-log query runs. - sys.stdout.flush() - sys.stderr.flush() - - -if __name__ == "__main__": - main(sys.argv[1]) +""" +std-nslog smoke test driver. + +This file is a *helper* for `test_smoke.py`, not a test itself. +It imports nslog, and outputs some known strings to the console. +""" + +import sys + +import nslog + + +def main(tag) -> None: + # Importing nslog should have replaced both standard streams with + # NSLogWriter instances; if it didn't, nothing else here is meaningful. + assert isinstance(sys.stdout, nslog.NSLogWriter), ( + f"sys.stdout was not replaced by NSLogWriter (got {type(sys.stdout)!r})" + ) + assert isinstance(sys.stderr, nslog.NSLogWriter), ( + f"sys.stderr was not replaced by NSLogWriter (got {type(sys.stderr)!r})" + ) + + # Exercise stdout, stderr, and direct nslog() calls at multiple log + # levels. Each line is tagged so the CI verifier can pick them out of + # the unified log unambiguously. + print(f"{tag} hello from std-nslog smoke test") + print(f"{tag} this is stderr", file=sys.stderr) + nslog.nslog(f"{tag} explicit info", level=nslog.OS_LOG_TYPE_INFO) + nslog.nslog(f"{tag} explicit error", level=nslog.OS_LOG_TYPE_ERROR) + + print(f"{tag} string with an \x00 embedded null") + + # NSLogWriter buffers partial lines until a newline arrives; flush + # explicitly so nothing is dropped before the unified-log query runs. + sys.stdout.flush() + sys.stderr.flush() + + +if __name__ == "__main__": + main(sys.argv[1]) diff --git a/tests/test_smoke.py b/tests/test_smoke.py index 55a6b99..94b2949 100644 --- a/tests/test_smoke.py +++ b/tests/test_smoke.py @@ -1,53 +1,55 @@ -from __future__ import annotations - -import subprocess -import sys -import time -import uuid -from pathlib import Path - - -def test_system_log(): - tag = f"std-nslog-smoke-{uuid.uuid4()}" - - result = subprocess.run( - [sys.executable, Path(__file__).parent / "smoke.py", tag], - capture_output=True, - text=True, - check=False, - ) - - # Assert that the smoke test ran without error. - assert result.returncode == 0 - - # Nothing the script `print()`ed should have reached stdio - assert result.stdout == "", ( - f"unexpected bytes on subprocess stdout: {result.stdout!r}" - ) - assert result.stderr == "", ( - f"unexpected bytes on subprocess stderr: {result.stderr!r}" - ) - - # Give the unified logging subsystem a moment to commit the writes, - # then extract the last 10s of system logs. - time.sleep(2) - - log = subprocess.check_output( - ["log", "show", "--last", "10s", "--info"], - text=True, - ) - - missing = [ - msg - for msg in [ - "hello from std-nslog smoke test", - "this is stderr", - "explicit info", - "explicit error", - ] - if f"{tag} {msg}" not in log - ] - assert not missing, ( - "Expected message(s) not found in `log show` output: " - + ", ".join(repr(m) for m in missing) - ) +from __future__ import annotations + +import subprocess +import sys +import time +import uuid +from pathlib import Path + + +def test_system_log(): + tag = f"std-nslog-smoke-{uuid.uuid4()}" + + result = subprocess.run( + [sys.executable, Path(__file__).parent / "smoke.py", tag], + capture_output=True, + text=True, + check=False, + ) + + # Assert that the smoke test ran without error. + assert result.returncode == 0 + + # Nothing the script `print()`ed should have reached stdio + assert result.stdout == "", ( + f"unexpected bytes on subprocess stdout: {result.stdout!r}" + ) + assert result.stderr == "", ( + f"unexpected bytes on subprocess stderr: {result.stderr!r}" + ) + + # Give the unified logging subsystem a moment to commit the writes, + # then extract the last 10s of system logs. + time.sleep(2) + + log = subprocess.check_output( + ["log", "show", "--last", "10s", "--info"], + text=True, + ) + + missing = [ + msg + for msg in [ + "hello from std-nslog smoke test", + "this is stderr", + "explicit info", + "explicit error", + "string with an  embedded null", + ] + if f"{tag} {msg}" not in log + ] + + assert not missing, ( + "Expected message(s) not found in `log show` output: " + + ", ".join(repr(m) for m in missing) + ) diff --git a/tox.ini b/tox.ini index c70ba2c..ca1f4c4 100644 --- a/tox.ini +++ b/tox.ini @@ -12,5 +12,5 @@ commands = pre-commit run --all-files --show-diff-on-failure --color=always skip_install = True dependency_groups = test commands = - uv pip install --find-links=wheelhouse --no-index --only-binary :all: --pre std-nslog + uv pip install --find-links=wheelhouse --no-cache --no-index --only-binary :all: --pre std-nslog python -m pytest {posargs:-v tests}