server: serialize card access, fix poll-interval 0, add --timing
--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.
This commit is contained in:
@@ -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:
|
||||
|
||||
@@ -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,8 +64,19 @@ 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)
|
||||
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
|
||||
@@ -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):
|
||||
lang = _get_lang(self.headers)
|
||||
# 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)
|
||||
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)
|
||||
|
||||
@@ -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()
|
||||
Reference in New Issue
Block a user