From 895d0b7b36b9be5fbdab139cc67da270b9418841 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=D0=90=D0=BD=D1=82=D0=BE=D0=BD=20=D0=A2=D1=80=D0=BE=D1=88?= =?UTF-8?q?=D0=B8=D0=BD?= Date: Sat, 12 Sep 2026 12:25:07 +0300 Subject: [PATCH] server: serialize card access, fix poll-interval 0, add --timing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --poll-interval 0 now really disables background STATUS polling (it was clamped to 1s, and the equip branch force-enabled it anyway). Request handlers and the poll thread now share _CARD_LOCK so a poll can never interleave a FETCH/TERMINAL RESPONSE pair — the baseline log showed AUTO-STATUS chains and duplicate FETCHes inside the equip TP chain. --timing adds elapsed timestamps, per-reset logging (RESET #n) and phase durations for startup (init_reader, card_init, pysim_app, terminal_profile_drain) and equip (onecmd, terminal profile). AGENTS.md documents the proactive-TR invariant: never fetch without answering, never fetch twice, one APDU conversation at a time. --- pysim_otaman_server/__main__.py | 14 +++++++- pysim_otaman_server/server.py | 59 +++++++++++++++++++++++++++++---- tests/test_poll.py | 55 ++++++++++++++++++++++++++++++ 3 files changed, 120 insertions(+), 8 deletions(-) create mode 100644 tests/test_poll.py diff --git a/pysim_otaman_server/__main__.py b/pysim_otaman_server/__main__.py index 31f6e44..228622c 100644 --- a/pysim_otaman_server/__main__.py +++ b/pysim_otaman_server/__main__.py @@ -11,7 +11,7 @@ from pySim.log import PySimLogger from pySim.cards import UiccCardBase from .shell import load_pysim_app -from .server import PysimHandler, StderrApduTracer, _LoggingApduTracer, VERSION, _send_terminal_profile, _DefaultProactiveHandler, _handle_proactive_chain, _send_status, _init_proactive_session +from .server import PysimHandler, StderrApduTracer, _LoggingApduTracer, VERSION, _send_terminal_profile, _DefaultProactiveHandler, _handle_proactive_chain, _send_status, _init_proactive_session, _timing_on, _tlog _server_start = 0 @@ -47,9 +47,13 @@ def main(): help='Idle interval before automatic STATUS polling (1-255 seconds, default: 30). Disable with --poll-interval 0') parser.add_argument('--no-card-init', action='store_true', default=False, help='Skip pysim card initialization (preserve CAT session — no file manager)') + parser.add_argument('--timing', action='store_true', default=False, + help='Log phase durations, card resets and APDU counters with elapsed timestamps') opts = parser.parse_args() opts.skip_card_init = opts.no_card_init + if opts.timing: + _timing_on() sl = None scc = None card = None @@ -77,27 +81,34 @@ def main(): kwargs = {} if opts.apdu_trace: kwargs['apdu_tracer'] = _LoggingApduTracer() + t_phase = time.time() sl = mod.init_reader(opts, **kwargs) + _tlog('init_reader: %.0fms' % ((time.time() - t_phase) * 1000)) scc = SimCardCommands(sl) scc.cat_cla = '80' # UICC CLA default; overridden for SIM after init_card scc._tp.proactive_handler = _DefaultProactiveHandler() + t_phase = time.time() sl.wait_for_card(3) rs, card = mod.init_card(sl, opts.skip_card_init) + _tlog('card_init: %.0fms' % ((time.time() - t_phase) * 1000)) scc.cat_cla = '80' if isinstance(card, UiccCardBase) else 'a0' except Exception: print("Warning: reader/card initialization failed:", file=sys.stderr) traceback.print_exc() ch = CardHandler(sl) if sl else None + t_phase = time.time() try: app = mod.PysimApp(verbose=opts.verbose, card=card, rs=rs, sl=sl, ch=ch) except Exception: print("Warning: PysimApp creation failed:", file=sys.stderr) traceback.print_exc() app = None + _tlog('pysim_app: %.0fms' % ((time.time() - t_phase) * 1000)) if scc and hasattr(scc, '_tp'): scc._tp.apdu_tracer = _LoggingApduTracer() try: _init_proactive_session() + t_phase = time.time() sys.stderr.write('INIT: sending TERMINAL PROFILE %s (CLA=%s)\n' % (opts.terminal_profile, scc.cat_cla)) sm, el = _send_terminal_profile(scc, opts.terminal_profile) sys.stderr.write('INIT: TP done, menu=%s events=%s\n' % ('yes' if sm else 'no', 'yes' if el else 'no')) @@ -109,6 +120,7 @@ def main(): if not st_sw.startswith('91'): break _handle_proactive_chain(scc, st_sw) + _tlog('terminal_profile_drain: %.0fms' % ((time.time() - t_phase) * 1000)) except Exception: traceback.print_exc(file=sys.stderr) if app is not None and opts.apdu_trace: diff --git a/pysim_otaman_server/server.py b/pysim_otaman_server/server.py index 2d7bea6..e681b09 100644 --- a/pysim_otaman_server/server.py +++ b/pysim_otaman_server/server.py @@ -41,6 +41,21 @@ _STATIC_MIME = { } +_T0 = time.time() +_TIMING = False +_APDU_N = 0 +_RESET_N = 0 + +def _timing_on(): + global _TIMING + _TIMING = True + +def _tlog(msg): + if not _TIMING: + return + sys.stderr.write('TIMING [+%7.3fs] %s\n' % (time.time() - _T0, msg)) + + class StderrApduTracer(ApduTracer): def __init__(self): super().__init__() @@ -49,9 +64,20 @@ class StderrApduTracer(ApduTracer): def trace_command(self, cmd): self._cmd_start = time.time() + def trace_reset(self): + global _RESET_N + _RESET_N += 1 + if _TIMING: + sys.stderr.write('TIMING [+%7.3fs] RESET #%d\n' % (time.time() - _T0, _RESET_N)) + def trace_response(self, cmd, sw, resp): + global _APDU_N + _APDU_N += 1 elapsed = int((time.time() - self._cmd_start) * 1000) - msg = 'APDU-TRACE(%dms): %s → SW: %s' % (elapsed, cmd, sw) + if _TIMING: + msg = 'APDU-TRACE(+%7.3fs #%d, %dms): %s → SW: %s' % (time.time() - _T0, _APDU_N, elapsed, cmd, sw) + else: + msg = 'APDU-TRACE(%dms): %s → SW: %s' % (elapsed, cmd, sw) if resp: msg += ' RESP: %s' % resp os.write(2, (msg + '\n').encode()) @@ -618,19 +644,19 @@ _PLI_DATA = {q: '' for q in PLI_QUALIFIER_NAMES} _POLL_ENABLED = False _POLL_INTERVAL = 30 _POLL_TIMER = None -_POLL_LOCK = threading.Lock() +_CARD_LOCK = threading.RLock() _CARD_CONNECTED = False def _set_poll_interval(seconds): global _POLL_INTERVAL - _POLL_INTERVAL = max(1, min(255, int(seconds))) + _POLL_INTERVAL = max(0, min(255, int(seconds))) def _reset_poll_timer(): global _POLL_TIMER if _POLL_TIMER is not None: _POLL_TIMER.cancel() _POLL_TIMER = None - if _POLL_ENABLED: + if _POLL_ENABLED and _POLL_INTERVAL > 0: _POLL_TIMER = threading.Timer(_POLL_INTERVAL, _do_status_poll) _POLL_TIMER.daemon = True _POLL_TIMER.start() @@ -640,7 +666,7 @@ def _do_status_poll(): _POLL_TIMER = None if not _POLL_ENABLED: return - with _POLL_LOCK: + with _CARD_LOCK: try: scc = getattr(_server_ref, 'scc', None) if _server_ref else None if not scc: @@ -656,6 +682,9 @@ def _do_status_poll(): def _poll_enable(): global _POLL_ENABLED + if _POLL_INTERVAL <= 0: + _POLL_ENABLED = False + return _POLL_ENABLED = True _reset_poll_timer() @@ -1366,6 +1395,12 @@ class PysimHandler(BaseHTTPRequestHandler): self.wfile.write(data) def do_GET(self): + # Serialize all card access: the background STATUS poll runs in its own + # thread and must never interleave with a FETCH/TERMINAL RESPONSE pair. + with _CARD_LOCK: + self._do_GET() + + def _do_GET(self): lang = _get_lang(self.headers) if self.path == '/api/version': self._log_req() @@ -1477,8 +1512,14 @@ class PysimHandler(BaseHTTPRequestHandler): self._serve_static() def do_POST(self): + # Serialize all card access: the background STATUS poll runs in its own + # thread and must never interleave with a FETCH/TERMINAL RESPONSE pair. + with _CARD_LOCK: + _reset_poll_timer() + self._do_POST() + + def _do_POST(self): lang = _get_lang(self.headers) - _reset_poll_timer() if self.path == '/api/command': app = self.server.app if not app: @@ -1504,7 +1545,10 @@ class PysimHandler(BaseHTTPRequestHandler): sys.stderr = old_stderr elapsed = int((time.time() - t0) * 1000) status = 'OK' if not output or 'not a recognized command' not in output else 'ERROR' - if str(cmd).strip().startswith('equip') and self.server.app and self.server.app.card and self.server.terminal_profile: + is_equip = str(cmd).strip().startswith('equip') + if is_equip: + _tlog('equip: onecmd_plus_hooks %dms' % elapsed) + if is_equip and self.server.app and self.server.app.card and self.server.terminal_profile: global _CARD_CONNECTED self.server.stk_pending = None self.server.menu_active = False @@ -1518,6 +1562,7 @@ class PysimHandler(BaseHTTPRequestHandler): sm, el = _send_terminal_profile(self.server.scc, self.server.terminal_profile) self.server.sim_menu = sm self.server.event_list = el + _tlog('equip: terminal profile done') sys.stderr.write("CMD: %s → %s (%dms)\n" % (cmd, status, elapsed)) resp = {'output': output, 'stop': bool(stop)} self._send_json(resp) diff --git a/tests/test_poll.py b/tests/test_poll.py new file mode 100644 index 0000000..d1e36fe --- /dev/null +++ b/tests/test_poll.py @@ -0,0 +1,55 @@ +#!/usr/bin/env python3 +"""Tests for the background STATUS polling interval semantics.""" + +import sys +import unittest +from pathlib import Path +from unittest import mock + +PROJECTS = Path(__file__).resolve().parents[2] +PY_SIM = PROJECTS / 'pysim' +if str(PY_SIM) not in sys.path: + sys.path.insert(0, str(PY_SIM)) + +import pysim_otaman_server.server as S + + +class TestPollInterval(unittest.TestCase): + def setUp(self): + self.saved = (S._POLL_ENABLED, S._POLL_INTERVAL, S._POLL_TIMER) + + def tearDown(self): + S._poll_disable() + S._POLL_ENABLED, S._POLL_INTERVAL, S._POLL_TIMER = self.saved + + def test_zero_interval_disables_polling(self): + S._set_poll_interval(0) + self.assertEqual(S._POLL_INTERVAL, 0) + with mock.patch.object(S.threading, 'Timer') as timer: + S._poll_enable() + timer.assert_not_called() + self.assertFalse(S._POLL_ENABLED) + self.assertIsNone(S._POLL_TIMER) + + def test_negative_interval_clamped_to_zero(self): + S._set_poll_interval(-5) + self.assertEqual(S._POLL_INTERVAL, 0) + + def test_positive_interval_starts_timer(self): + S._set_poll_interval(30) + with mock.patch.object(S.threading, 'Timer') as timer: + S._poll_enable() + self.assertTrue(S._POLL_ENABLED) + timer.assert_called_once_with(30, S._do_status_poll) + + def test_reset_timer_skipped_when_disabled(self): + S._set_poll_interval(0) + S._POLL_ENABLED = True + with mock.patch.object(S.threading, 'Timer') as timer: + S._reset_poll_timer() + timer.assert_not_called() + self.assertIsNone(S._POLL_TIMER) + + +if __name__ == '__main__': + unittest.main()