diff --git a/CHANGELOG.md b/CHANGELOG.md index 55eba4b..f06bda3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,26 @@ every change carries a descriptive commit message. ## [Unreleased] +## [3.40.5] — 2026-11-08 + +### Fixed + +- **Server request/access log leaked into captured file content.** The HTTP + access log (`log_message`) and the `--log-requests` `REQUEST`/`RESPONSE` + lines wrote to the rebindable `sys.stderr`, so a concurrent card-free request + (the 2 s `/api/status` poll) dropped its log line into the `StringIO` a + card command was capturing — corrupting file content read during a snapshot + scan (the log line appeared in the snapshot, e.g. + `127.0.0.1 - - […] "GET /api/status HTTP/1.1" 200 -ffff…`). The log now + writes to fd 2 via `_log_stderr`, exactly as the APDU tracer already does. + +### Changed + +- **Deduplicated the pySim output capture.** The six handlers that captured + pySim command output by rebinding `sys.stdout`/`sys.stderr` to a `StringIO` + now share one `_capture_app_output` context manager (the same save/set/ + restore semantics, in one place). + ## [3.40.4] — 2026-11-04 ### Added diff --git a/frontend/index.html b/frontend/index.html index 65feb70..f0891e7 100644 --- a/frontend/index.html +++ b/frontend/index.html @@ -1990,7 +1990,7 @@ // ===== Version ===== // Single source of truth for the PWA version: shown in the header and used // by the server version check in pysimConnect(). -const SIMPLE_VERSION = '3.40.4'; +const SIMPLE_VERSION = '3.40.5'; document.getElementById('app-version').textContent = 'v' + SIMPLE_VERSION; // ===== view history (the browser Back/Forward buttons) ===== diff --git a/frontend/sw.js b/frontend/sw.js index e048d5e..4703b01 100644 --- a/frontend/sw.js +++ b/frontend/sw.js @@ -1,4 +1,4 @@ -const CACHE = 'simple-v490'; +const CACHE = 'simple-v491'; const URLS = [ 'index.html', 'help.html', diff --git a/pyproject.toml b/pyproject.toml index 96eceae..3913893 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta" [project] name = "pysim-simple-server" -version = "3.40.4" +version = "3.40.5" description = "HTTP REST server wrapping pysim for the SIMple PWA" license = { text = "GPL-2.0-or-later" } requires-python = ">=3.9" diff --git a/pysim_simple_server/server.py b/pysim_simple_server/server.py index d35f320..60a2bee 100644 --- a/pysim_simple_server/server.py +++ b/pysim_simple_server/server.py @@ -13,6 +13,7 @@ from urllib.parse import unquote_plus from datetime import datetime, timedelta from http.server import BaseHTTPRequestHandler from io import StringIO +from contextlib import contextmanager from pySim.transport import ApduTracer, ProactiveHandler from pySim.cards import UiccCardBase from pysim_simple_server import httpota @@ -37,7 +38,7 @@ from osmocom.tlv import BER_TLV_IE from osmocom.utils import rpad -VERSION = '3.40.4' +VERSION = '3.40.5' MAX_ENVELOPE_SEGMENTS = 5 # max SMS segments for outgoing C-APDU in ENVELOPE @@ -267,6 +268,42 @@ def _cmd_exception(output): return 'command failed' +def _log_stderr(msg): + """Write a server log line to the real stderr fd, bypassing ``sys.stderr``. + + The HTTP handlers temporarily rebind the global ``sys.stderr`` to a + ``StringIO`` to capture pySim command output. Concurrent card-free + requests (the 2 s /api/status poll) log via ``log_message`` / ``_log_req`` + / ``_log_resp``; writing to ``sys.stderr`` would drop those lines into the + active capture buffer and corrupt the file content (the snapshot "access + log line in contents" bug). Writing to fd 2 keeps the request log out of + the capture, exactly as the APDU tracer already does below.""" + os.write(2, msg.encode()) + + +@contextmanager +def _capture_app_output(app): + """Temporarily capture the pySim app's output into a ``StringIO``. + + cmd2 writes command output to ``app.stdout``; stray writes to the global + ``sys.stderr`` (``print(file=sys.stderr)``, ``sys.stderr.write``, logging, + tracebacks) are captured too by rebinding it. Card access is serialized by + ``_CARD_LOCK``, so only one capture is active at a time, and the server's + own request/access logging bypasses it via ``_log_stderr``. Yields the + buffer and restores both streams in ``finally``. + """ + out = StringIO() + old_stdout = app.stdout + old_stderr = sys.stderr + app.stdout = out + sys.stderr = out + try: + yield out + finally: + app.stdout = old_stdout + sys.stderr = old_stderr + + def _parse_help_text(text): result = {'usage': '', 'description': '', 'args': []} lines = text.split('\n') @@ -9472,13 +9509,13 @@ class PysimHandler(BaseHTTPRequestHandler): def _log_req(self, body=None): if self.server.log_requests: if body is not None: - sys.stderr.write("REQUEST %s %s: %s\n" % (self.command, self.path, json.dumps(body))) + _log_stderr("REQUEST %s %s: %s\n" % (self.command, self.path, json.dumps(body))) else: - sys.stderr.write("REQUEST %s %s\n" % (self.command, self.path)) + _log_stderr("REQUEST %s %s\n" % (self.command, self.path)) def _log_resp(self, data): if self.server.log_requests: - sys.stderr.write("RESPONSE %s: %s\n" % (self.path, json.dumps(data, ensure_ascii=False))) + _log_stderr("RESPONSE %s: %s\n" % (self.path, json.dumps(data, ensure_ascii=False))) def do_OPTIONS(self): self._log_req() @@ -9777,19 +9814,12 @@ class PysimHandler(BaseHTTPRequestHandler): self._send_json({'error': _err('app_not_init', lang)}, 503) self._log_resp({'error': _err('app_not_init', lang)}) return - out = StringIO() - old_stdout = app.stdout - old_stderr = sys.stderr - app.stdout = out - sys.stderr = out - try: - app.onecmd_plus_hooks('cardinfo') - output = _strip_ansi(out.getvalue()) - except Exception as e: - output = str(e) + '\n' + traceback.format_exc() - finally: - app.stdout = old_stdout - sys.stderr = old_stderr + with _capture_app_output(app) as out: + try: + app.onecmd_plus_hooks('cardinfo') + output = _strip_ansi(out.getvalue()) + except Exception as e: + output = str(e) + '\n' + traceback.format_exc() resp = {'output': output} self._send_json(resp) self._log_resp(resp) @@ -9931,19 +9961,12 @@ class PysimHandler(BaseHTTPRequestHandler): # transport so a manual Equip recovers too. _ensure_transport(self.server) t0 = time.time() - out = StringIO() - old_stdout = app.stdout - old_stderr = sys.stderr - app.stdout = out - sys.stderr = out - try: - stop = app.onecmd_plus_hooks(cmd) - output = _strip_ansi(out.getvalue()) - except Exception as e: - output = str(e) + '\n' + traceback.format_exc() - finally: - app.stdout = old_stdout - sys.stderr = old_stderr + with _capture_app_output(app) as out: + try: + stop = app.onecmd_plus_hooks(cmd) + output = _strip_ansi(out.getvalue()) + except Exception as e: + output = str(e) + '\n' + traceback.format_exc() elapsed = int((time.time() - t0) * 1000) status = 'OK' if not output or 'not a recognized command' not in output else 'ERROR' if is_equip: @@ -10199,17 +10222,9 @@ class PysimHandler(BaseHTTPRequestHandler): body = self._read_body() self._log_req(body) cmd = body.get('cmd', '') - out = StringIO() - old_stdout = app.stdout - old_stderr = sys.stderr - app.stdout = out - sys.stderr = out - try: + with _capture_app_output(app) as out: app.onecmd_plus_hooks('help ' + cmd) raw = out.getvalue() - finally: - app.stdout = old_stdout - sys.stderr = old_stderr clean = _strip_ansi(raw) parsed = _parse_help_text(clean) self._send_json(parsed) @@ -10307,17 +10322,9 @@ class PysimHandler(BaseHTTPRequestHandler): cmd = 'read_records_decoded' if is_record else 'read_binary_decoded' else: cmd = 'read_records' if is_record else 'read_binary' - out = StringIO() - old_stdout = app.stdout - old_stderr = sys.stderr - app.stdout = out - sys.stderr = out - try: + with _capture_app_output(app) as out: app.onecmd_plus_hooks(cmd) output = _strip_ansi(out.getvalue()) - finally: - app.stdout = old_stdout - sys.stderr = old_stderr finally: apdu_times = _end_apdu_time_collection() exc = _cmd_exception(output) @@ -10403,17 +10410,9 @@ class PysimHandler(BaseHTTPRequestHandler): cmd = 'update_record 1 %s' % data else: cmd = 'update_binary %s' % data - out = StringIO() - old_stdout = app.stdout - old_stderr = sys.stderr - app.stdout = out - sys.stderr = out - try: + with _capture_app_output(app) as out: app.onecmd_plus_hooks(cmd) output = out.getvalue() - finally: - app.stdout = old_stdout - sys.stderr = old_stderr exc = _cmd_exception(output) if exc: resp = {'success': False, 'error': exc} @@ -10472,17 +10471,9 @@ class PysimHandler(BaseHTTPRequestHandler): sel = fid if fid else name _, cleanup = _select_with_parent(lchan, sel, parent_sel, app, parent_path, allow_probe) cur = lchan.selected_file - out = StringIO() - old_stdout = app.stdout - old_stderr = sys.stderr - app.stdout = out - sys.stderr = out - try: + with _capture_app_output(app) as out: app.onecmd_plus_hooks('tree') output = _strip_ansi(out.getvalue()) - finally: - app.stdout = old_stdout - sys.stderr = old_stderr children = _parse_tree_output(output) # EF.PBR (TS 31.102 4.4.2.1): the phonebook files the DF's PBR # references are not in pySim's model, so they are appended to @@ -12178,4 +12169,4 @@ class PysimHandler(BaseHTTPRequestHandler): self._log_resp({'error': _err('not_found', lang)}) def log_message(self, format, *args): - sys.stderr.write('%s - - [%s] %s\n' % (self.client_address[0], self.log_date_time_string(), format % args)) \ No newline at end of file + _log_stderr('%s - - [%s] %s\n' % (self.client_address[0], self.log_date_time_string(), format % args)) \ No newline at end of file diff --git a/tests/test_output_capture.py b/tests/test_output_capture.py new file mode 100644 index 0000000..2e1a865 --- /dev/null +++ b/tests/test_output_capture.py @@ -0,0 +1,91 @@ +"""The request/access log must never enter a pySim output capture. + +Handlers capture pySim output by temporarily rebinding the global ``sys.stderr`` +to a StringIO (``_capture_app_output``). Concurrent card-free requests (the 2 s +/api/status poll) log via ``log_message`` / ``_log_req`` / ``_log_resp``; if +those wrote to ``sys.stderr`` their lines would land in the active capture +buffer and corrupt the file content (the snapshot "access log line in contents" +bug). The log now writes to fd 2 directly, and the capture is a context +manager that restores both streams. +""" + +import io +import pathlib +import sys +import types +import unittest +from unittest import mock + +from pysim_simple_server import server as srv +from pysim_simple_server.server import PysimHandler, _capture_app_output, _log_stderr + + +class LogStderrTests(unittest.TestCase): + def test_log_stderr_writes_to_fd2_not_the_rebindable_stream(self): + writes = [] + err = io.StringIO() + with mock.patch.object(srv.os, 'write', side_effect=lambda fd, data: writes.append((fd, data))), \ + mock.patch('sys.stderr', new=err): + _log_stderr('hello\n') + self.assertEqual(writes, [(2, b'hello\n')]) + self.assertEqual(err.getvalue(), '') + + def test_log_message_goes_to_fd2(self): + h = object.__new__(PysimHandler) + h.client_address = ('127.0.0.1', 1234) + h.log_date_time_string = lambda: '05/Nov/2026 14:09:10' + writes = [] + err = io.StringIO() + with mock.patch.object(srv.os, 'write', side_effect=lambda fd, data: writes.append((fd, data))), \ + mock.patch('sys.stderr', new=err): + h.log_message('"%s" %s %s', 'GET /api/status HTTP/1.1', '200', '-') + self.assertEqual( + writes, + [(2, b'127.0.0.1 - - [05/Nov/2026 14:09:10] ' + b'"GET /api/status HTTP/1.1" 200 -\n')]) + self.assertEqual(err.getvalue(), '', + 'the access log must not land in a redirected sys.stderr') + + +class CaptureOutputTests(unittest.TestCase): + def test_captures_both_streams_and_restores(self): + orig_stdout = io.StringIO() + app = types.SimpleNamespace(stdout=orig_stdout) + real_stderr = sys.stderr + with _capture_app_output(app) as out: + app.stdout.write('AABB\n') + sys.stderr.write('SW: 9000\n') + self.assertIn('AABB\n', out.getvalue()) + self.assertIn('SW: 9000\n', out.getvalue()) + self.assertIs(app.stdout, orig_stdout) + self.assertIs(sys.stderr, real_stderr) + + def test_restores_on_exception(self): + orig_stdout = io.StringIO() + app = types.SimpleNamespace(stdout=orig_stdout) + real_stderr = sys.stderr + with self.assertRaises(RuntimeError): + with _capture_app_output(app) as out: + app.stdout.write('partial\n') + raise RuntimeError('boom') + self.assertIs(app.stdout, orig_stdout) + self.assertIs(sys.stderr, real_stderr) + + +class SourcePinTests(unittest.TestCase): + def test_log_message_uses_fd2(self): + src = pathlib.Path(srv.__file__).read_text() + seg = src[src.index('def log_message('):] + self.assertIn('_log_stderr(', seg) + self.assertNotIn('sys.stderr.write', seg) + + def test_the_handlers_use_the_capture_context_manager(self): + # The six handlers that capture pySim output share one context manager; + # a re-introduced inline ``sys.stderr = out`` block would be a + # thread-safety regression. + src = pathlib.Path(srv.__file__).read_text() + self.assertGreaterEqual(src.count('with _capture_app_output(app) as out:'), 6) + + +if __name__ == '__main__': + unittest.main()