v3.18.3: the test-run card-exchange log

Verifying a script from the log was impossible: the runner wrote no card
lines, SCP80's plaintext C-APDU / secured packet / PoR landed only in the
report, and a menu selection logged nothing (the interactive path showed just
"STATUS poll (menu-select 9000)" / "STATUS -> 9000").

Every step now writes a `TEST-RUN step N:` line family to stderr, request
before response:

- generic actions: the APDU/raw event data sent and the SW/RESP received
  (`APDU TX=...`, `ENVELOPE(Event Download) ... data=...`, `READ/UPDATE ... -> SW=...`);
- SCP80: `C-APDU=` (or `SP=`), `SECURED=<hex> (N B) TAR=... SPI1=... SPI2=... CNTR=...`,
  the response SW, and the PoR - `PoR[inline] status=... TAR=... CNTR=... raw=...`
  plus `R-APDU SW=... data=...` (with the bad-format note);
- expectations: `FETCH=<apdu> -> SW=... <raw>`, `CMD 0x.. <NAME> qual=..`,
  `TR=<apdu> -> SW=...`, and `PoR[sms-submit] ...` + `R-APDU` for the SEND
  SHORT MESSAGE transport;
- status: `STATUS 1/N -> <sw>` per attempt;
- menu selection: `MENU-SELECT ENVELOPE=<apdu> item=<id> ('<text>') -> SW=...`
  (both the runner action and /api/menu-select; the old STATUS lines stay as
  context).

The shared secured-packet sender logs each segment's answer
(`OTA SEND: ENVELOPE i/N -> <SW>`), the scp80 step's report `sent` now carries
the C-APDU/SP hex, and `--apdu-trace` remains the raw transport view.

help EN/RU and docs/test-scripts.md gained the "reading the run log" note.
Tests: 816 frontend + 718 Python; sw cache simple-v385.
This commit is contained in:
2026-10-04 19:50:55 +03:00
parent 9109b68924
commit c444468d2a
8 changed files with 189 additions and 14 deletions
+28
View File
@@ -93,6 +93,34 @@ PoR-in-submit:
5. **Counters**: the run starts from the preset's stored counter and persists
each accepted packet's next value; consecutive runs continue correctly.
### Reading the run log
Every step writes a semantic line to the server log under its step number,
request before response:
```
TEST-RUN step 1: SCP80 C-APDU=80E2900000
TEST-RUN step 1: SCP80 SECURED=0100…1A2B (N B) TAR=B00001 SPI1=16 SPI2=21 CNTR=0000000A
TEST-RUN step 1: SCP80 -> SW=9000
TEST-RUN step 1: PoR[inline] status=por_ok TAR=B00001 CNTR=0000000A raw=0271…aabb
TEST-RUN step 1: R-APDU SW=9000 data=AABB
TEST-RUN step 2: STATUS 1/2 -> 9102
TEST-RUN step 3: FETCH=8012000002 -> SW=9000 D03C8103012500…
TEST-RUN step 3: CMD 0x25 SET UP MENU qual=00
TEST-RUN step 3: TR=81030125008202828183020000 -> SW=9000
TEST-RUN step 4: MENU-SELECT ENVELOPE=80c2000009d30702020181900101 item=1 ('One') -> SW=9103
```
- A PoR delivered as SEND SHORT MESSAGE is logged on the step that fetches it:
`PoR[sms-submit] …` followed by the same `R-APDU` line.
- Other actions log their send/response pair too (`APDU TX=… -> SW=…`,
`ENVELOPE(Event Download) … -> SW=…`, `READ MF/… -> SW=…`).
- The shared secured-packet sender logs each segment's answer
(`OTA SEND: ENVELOPE i/N -> <SW>`).
- `--apdu-trace` adds the raw transport view
(`APDU-TRACE(…): <cmd> → SW: … RESP: …`) for every APDU, including the
file-manager reads and pySim's auto-handler traffic.
## Document shape
```json
+1
View File
@@ -568,6 +568,7 @@
<li><strong>Уровни ошибок</strong> &mdash; несовпадение помечает шаг как <em>Ошибка</em> (скрипт останавливается) или <em>Предупреждение</em> (продолжает); каждая проверка показывается с ожидаемым и фактическим значением.</li>
<li><strong>Шаблоны</strong> &mdash; Empty, <em>Обзор меню STK</em>, <em>Апплет через SCP80</em>; редактор шагов — формный (поля действия Event вводятся объектом JSON), отдельные скрипты экспортируются/импортируются как JSON.</li>
</ul>
<p class="text-sm mb-3">Каждый шаг пишет семантическую строку в журнал сервера под своим номером (<code class="font-mono text-sm">TEST-RUN step N: …</code>), запрос перед ответом: отправленный APDU/данные и полученный SW, для SCP80 — открытый C-APDU, собранный защищённый пакет и R-APDU из PoR, для ожидания — тройка FETCH / команда / TERMINAL RESPONSE, а для выбора пункта меню — полный ENVELOPE с определённым пунктом. Запустите сервер с <code class="font-mono text-sm">--apdu-trace</code>, чтобы добавить и журнал сырых транспортных APDU.</p>
<h3 id="bip" class="text-lg font-medium mb-2">8.10 BIP-терминал (обычный TCP)</h3>
<p class="text-sm mb-2">Пилюля <strong>BIP</strong> запускает терминальную сторону Bearer Independent Protocol для карт, использующих TCP без HTTP OTA (SCP81): апплет или пуш-триггер может открыть канал и обменяться сырыми данными. Одновременно работает только одна BIP-сессия &mdash; запуск здесь останавливает слушатель SCP81, а запуск слушателя SCP81 останавливает эту сессию (в обоих случаях сообщается, что было заменено).</p>
+1
View File
@@ -567,6 +567,7 @@
<li><strong>Fail levels</strong> &mdash; a mismatch flags the step as <em>Error</em> (terminates the script) or <em>Warning</em> (continues); each check is reported with expected vs actual values.</li>
<li><strong>Templates</strong> &mdash; Empty, <em>STK menu browsing</em>, <em>Applet via SCP80</em>; the step editor is form-based (the event action's fields are a JSON object) and individual scripts export/import as JSON.</li>
</ul>
<p class="text-sm mb-3">Every step logs a semantic line to the server log under its step number (<code class="font-mono text-sm">TEST-RUN step N: …</code>), request before response: the APDU/data sent and the SW received, for SCP80 the plaintext C-APDU, the built secured packet and the PoR's R-APDU, for an expectation the FETCH / command / TERMINAL RESPONSE trio, and for a menu selection the complete ENVELOPE with the resolved item. Start the server with <code class="font-mono text-sm">--apdu-trace</code> to add the raw transport APDU log as well.</p>
<h3 id="bip" class="text-lg font-medium mb-2">8.10 BIP terminal (generic TCP)</h3>
<p class="text-sm mb-2">The <strong>BIP</strong> pill runs the terminal side of the Bearer Independent Protocol for cards that use TCP without HTTP OTA (SCP81): an applet or a push trigger can open a channel and exchange raw data. Only one BIP session runs at a time &mdash; starting here stops a running SCP81 listener, and starting the SCP81 listener stops this session (both report what was replaced).</p>
+1 -1
View File
@@ -1877,7 +1877,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.18.2';
const SIMPLE_VERSION = '3.18.3';
document.getElementById('app-version').textContent = 'v' + SIMPLE_VERSION;
// ===== Tab switching =====
+1 -1
View File
@@ -1,4 +1,4 @@
const CACHE = 'simple-v384';
const CACHE = 'simple-v385';
const URLS = [
'index.html',
'help.html',
+1 -1
View File
@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
[project]
name = "pysim-simple-server"
version = "3.18.2"
version = "3.18.3"
description = "HTTP REST server wrapping pysim for the SIMple PWA"
requires-python = ">=3.8"
# pysim is a git-only dependency installed explicitly by setup.bat/setup.sh.
+73 -4
View File
@@ -34,7 +34,7 @@ from osmocom.tlv import BER_TLV_IE
from osmocom.utils import rpad
VERSION = '3.18.2'
VERSION = '3.18.3'
MAX_ENVELOPE_SEGMENTS = 5 # max SMS segments for outgoing C-APDU in ENVELOPE
@@ -1370,6 +1370,7 @@ def _send_secured_packet(scc, sp_hex, oa_number, sm_sc=None, include_cpi=True,
submit_handler=submit_handler,
handle_proactive=handle_proactive,
poll_status=(i == total - 1))
sys.stderr.write('OTA SEND: ENVELOPE %d/%d -> %s\n' % (i + 1, total, sw))
if sw != '9000' and not sw.startswith('91'):
# A warning (62xx/63xx, e.g. the live card's 6200 for a low
# counter) may still hold the PoR: pass it on so the caller can
@@ -5792,6 +5793,16 @@ def _test_action_checks(step, sw, data, por, kind):
return checks
def _test_log(msg):
"""One semantic run-log line, prefixed with the current step number: the
verification trail (the plaintext C-APDU, the built secured packet, the
PoR R-APDU, the FETCH/TR of an expectation, the menu selection's ENVELOPE).
The raw transport view stays with `--apdu-trace`."""
step = _TEST_RUN.get('index')
n = (step + 1) if isinstance(step, int) else 0
sys.stderr.write('TEST-RUN step %d: %s\n' % (n, msg))
def _test_run_status(scc, step):
p = step['params']
data, sw = '', ''
@@ -5799,6 +5810,7 @@ def _test_run_status(scc, step):
for n in range(p['attempts']):
data, sw = _send_status(scc)
used = n + 1
_test_log('STATUS %d/%d -> %s' % (used, p['attempts'], sw))
if testscript.match_value(step['check']['sw'], sw):
break
if n + 1 < p['attempts'] and p['interval_ms']:
@@ -5885,20 +5897,44 @@ def _test_run_scp80(server, step, ctx):
if p.get('sp'):
sp_hex = p['sp']
source = 'sp'
_test_log('SCP80 SP=%s' % sp_hex)
else:
sp_hex, _ = _build_secured_packet(spi1, spi2, kic, kid, tar, counter,
p['apdu'], kic_key, kid_key)
source = 'apdu'
_test_log('SCP80 C-APDU=%s' % p['apdu'])
_test_log('SCP80 SECURED=%s (%d B) TAR=%s SPI1=%s SPI2=%s CNTR=%s'
% (sp_hex, len(sp_hex) // 2, tar or '-', spi1, spi2, counter))
result = _send_secured_packet(scc, sp_hex, server.sms_oa, sm_sc=server.sms_sc,
handle_proactive=False)
sw = result.get('sw') or ''
data = result.get('response_data') or ''
segments = result.get('segments') or 0
_test_log('SCP80 -> SW=%s%s' % (sw or '(none)',
' (%d segment(s))' % segments if segments > 1 else ''))
por = None
if data:
por = _decode_por(spi1, spi2, kic, kid, counter, kic_key, kid_key, data)
sent = 'SCP80 %s TAR=%s SPI1=%s SPI2=%s cntr=%s%s' % (
if por:
dec = por.get('decoded') or {}
extra = ''
if por.get('bad_format'):
extra = ' bad_format=%s (%s)' % (por['bad_format'],
por.get('bad_format_name') or '')
_test_log('PoR[inline] status=%s TAR=%s CNTR=%s%s raw=%s'
% (por.get('response_status'), por.get('tar'),
por.get('cntr'), extra, por.get('raw') or data))
_test_log('R-APDU SW=%s data=%s'
% (dec.get('last_status_word') or '(none)',
dec.get('last_response_data') or '(none)'))
elif data:
_test_log('PoR[inline] undecodable raw=%s' % data)
else:
_test_log('PoR[inline] none')
sent = 'SCP80 %s TAR=%s SPI1=%s SPI2=%s cntr=%s%s %s' % (
source, tar or '-', spi1, spi2, counter,
(' kvn=%d' % kvn) if kvn else '')
(' kvn=%d' % kvn) if kvn else '',
('SP=%s' % sp_hex) if source == 'sp' else ('C-APDU=%s' % p['apdu']))
if sw and _counter_tracked(spi1):
# The card answered and the packet asks for a counter check, so the
# SCP80 counter was consumed: advance the working value of this key
@@ -5955,6 +5991,9 @@ def _test_run_action(server, step, ctx):
bytes.fromhex(p['data']) if p['data'] else None,
drain=False, src=p.get('src'))
sent = 'ENVELOPE(Event Download) type=0x%02X' % p['event']
_test_log('%s src=%s data=%s -> SW=%s%s'
% (sent, p.get('src') or '82', p['data'] or '(none)', sw or '(none)',
(' RESP=%s' % data) if data else ''))
elif kind == 'event':
# The semantic event download: the builder owns the byte layout.
data_hex = events.build(p['event'], p.get('fields') or {})
@@ -5962,6 +6001,9 @@ def _test_run_action(server, step, ctx):
drain=False, src=p.get('src'))
sent = 'ENVELOPE(Event Download) type=0x%02X (%s) data=%s' % (
p['event'], events.event_name(p['event']), data_hex)
_test_log('%s src=%s -> SW=%s%s'
% (sent, p.get('src') or '82', sw or '(none)',
(' RESP=%s' % data) if data else ''))
elif kind == 'menu-select':
item_id = p.get('item_id')
if item_id is None:
@@ -5972,13 +6014,20 @@ def _test_run_action(server, step, ctx):
data, sw = scc._tp.send_apdu(sent)
if not (sw or '').startswith('91'):
server.menu_active = False
_test_log('MENU-SELECT ENVELOPE=%s item=%d%s -> SW=%s%s'
% (sent, item_id, (' (%r)' % p['text']) if 'text' in p else '',
sw or '(none)', (' RESP=%s' % data) if data else ''))
elif kind == 'apdu':
sent = p['apdu']
data, sw = scc._tp.send_apdu(sent)
_test_log('APDU TX=%s -> SW=%s%s'
% (sent, sw or '(none)', (' RESP=%s' % data) if data else ''))
elif kind == 'status':
data, sw, sent = _test_run_status(scc, step)
elif kind in ('file-write', 'file-read'):
data, sw, sent = _test_run_file(server, step)
_test_log('%s -> SW=%s%s' % (sent, sw or '(none)',
(' RESP=%dB' % (len(data) // 2)) if data else ''))
elif kind == 'scp80':
data, sw, sent, por, counter = _test_run_scp80(server, step, ctx)
else:
@@ -6092,17 +6141,34 @@ def _test_run_expect(server, step, pending, ctx=None):
'no proactive command pending - the previous step must end with SW 91XX '
'(or add a status action); the UICC announces pending commands in the '
'response to a command (TS 102 221 7.4.2.1)')
fdata, fetch_sw = scc._tp.send_apdu('%s120000%02x' % (scc.cat_cla, pending))
fetch_apdu = '%s120000%02x' % (scc.cat_cla, pending)
fdata, fetch_sw = scc._tp.send_apdu(fetch_apdu)
if not fdata:
_test_log('FETCH=%s -> SW=%s (no data)' % (fetch_apdu, fetch_sw))
raise testscript.ScriptError('FETCH returned no data (SW %s)' % fetch_sw)
raw = bytes.fromhex(fdata)
_test_log('FETCH=%s -> SW=%s %s' % (fetch_apdu, fetch_sw, raw.hex().upper()))
cmd_num, cmd_type, dev_src, dev_dst, cmd_qual = _parse_proactive_header(raw)
log_entry = _log_proactive(cmd_type, raw, cmd_qual, cmd_num)
type_name = PROACTIVE_TYPE_NAMES.get(cmd_type, 'UNKNOWN')
_test_log('CMD 0x%02X %s qual=%s' % (
cmd_type, type_name, ('%02X' % cmd_qual) if cmd_qual is not None else '-'))
# A SEND SHORT MESSAGE carries the PoR when the packet asked for it in
# submit mode (SPI2 bit 0x20): decode it with the triggering scp80 step's
# context so the checks can assert the PoR contents.
por = _test_expect_por(ctx, raw) if cmd_type == 0x13 else None
if cmd_type == 0x13:
if por is not None:
dec = por.get('decoded') or {}
_test_log('PoR[sms-submit] status=%s TAR=%s CNTR=%s raw=%s'
% (por.get('response_status'), por.get('tar'),
por.get('cntr'), por.get('raw') or '(none)'))
_test_log('R-APDU SW=%s data=%s'
% (dec.get('last_status_word') or '(none)',
dec.get('last_response_data') or '(none)'))
else:
_test_log('PoR[sms-submit] none (no decodable PDU or no scp80 '
'context)')
if cmd_type == 0x25:
# The card may re-send its menu (e.g. after an applet install); keep
# the cache that text-based menu selection resolves against current.
@@ -6185,6 +6251,7 @@ def _test_run_expect(server, step, pending, ctx=None):
tr = testscript.build_tr(cmd_num, cmd_type, dev_dst, dev_src, step['respond'])
tr_rv = scc._tp.send_apdu('%s140000%02x%s' % (scc.cat_cla, len(tr), tr.hex()))
tr_sw = tr_rv[1]
_test_log('TR=%s -> SW=%s' % (tr.hex().upper(), tr_sw))
_record_tr(log_entry, tr, tr_sw)
status = testscript.combine_levels([c['level'] if not c['ok'] else 'ok' for c in checks])
result = {'status': status, 'sw': tr_sw, 'data': raw.hex().upper(),
@@ -7410,6 +7477,8 @@ class PysimHandler(BaseHTTPRequestHandler):
menu_tlv = bytes([0xD3, 0x07, 0x02, 0x02, 0x01, 0x81, 0x90, 0x01, item_id])
env_hex = '%sc20000%02x%s' % (scc.cat_cla, len(menu_tlv), menu_tlv.hex())
data, sw = scc._tp.send_apdu(env_hex)
sys.stderr.write('MENU-SELECT: ENVELOPE %s item=%d -> %s\n'
% (env_hex, item_id, sw))
resp = {'type': 'done', 'sw': sw}
on_fetch = _make_menu_fetch_handler(self.server, resp)
if sw.startswith('91'):
+83 -7
View File
@@ -729,12 +729,84 @@ class TestRunnerActions(RunnerTestCase):
# 12 07 01 3F007F106F3A (one file: MF/7F10/6F3A).
REFRESH_FCN_CMD = 'D0128103010100820283811207013F007F106F3A'
def test_the_run_log_carries_the_card_exchange_details(self):
# the semantic lines a verification needs: the plaintext C-APDU, the
# built secured packet, the FETCH/CMD/TR pair of an expectation and
# the menu selection's ENVELOPE with the resolved item
import contextlib
import io
scc = FakeScc()
scc.push('80F2', '', '9102')
scc.push('8012', self.SETUP_MENU_CMD, '9000')
scc.push('8014', '', '9000')
scc.push('80C2', '', '9000')
preset = {'kic': '15', 'kid': '15', 'kicKey': 'AA' * 16, 'kidKey': 'BB' * 16,
'counter': '0000000A', 'tars': preset_tars()}
buf = io.StringIO()
with mock.patch.object(S, '_build_secured_packet', return_value=('CC' * 10, {})), \
mock.patch.object(S, '_send_secured_packet',
return_value={'success': True, 'sw': '9000',
'response_data': None}):
with contextlib.redirect_stderr(buf):
run = self.run_script(FakeServer(scc), [
{'type': 'action', 'kind': 'scp80',
'params': {'apdu': '80E2900000'}},
{'type': 'action', 'kind': 'status', 'params': {'attempts': 2},
'check': {'sw': {'mode': 'mask', 'value': '91??'}}},
{'type': 'expect', 'command': 'SET UP MENU',
'respond': {'result': 'ok'}},
{'type': 'action', 'kind': 'menu-select',
'params': {'text': 'One'}},
], preset)
self.assertEqual(run['status'], 'ok', run['steps'])
log = buf.getvalue()
self.assertIn('TEST-RUN step 1: SCP80 C-APDU=80E2900000', log)
self.assertIn('TEST-RUN step 1: SCP80 SECURED=' + 'CC' * 10, log)
self.assertIn('TEST-RUN step 1: SCP80 -> SW=9000', log)
self.assertIn('TEST-RUN step 1: PoR[inline] none', log)
self.assertIn('TEST-RUN step 2: STATUS 1/2 -> 9102', log)
self.assertIn('TEST-RUN step 3: FETCH=', log)
self.assertIn('TEST-RUN step 3: CMD 0x25 SET UP MENU', log)
self.assertIn('TEST-RUN step 3: TR=', log)
self.assertIn('TEST-RUN step 4: MENU-SELECT ENVELOPE=', log)
self.assertIn("item=1 ('One')", log)
def test_the_run_log_carries_the_inline_por(self):
# the decoded PoR and its R-APDU are logged with the raw packet
import contextlib
import io
scc = FakeScc()
preset = {'kic': '15', 'kid': '15', 'kicKey': 'AA' * 16, 'kidKey': 'BB' * 16,
'counter': '0000000A', 'tars': preset_tars()}
decoded = {'response_status': 'por_ok', 'tar': '000000', 'cntr': '0000000A',
'raw': '0271000021AABB',
'decoded': {'last_status_word': '9000', 'last_response_data': 'AABB'}}
buf = io.StringIO()
with mock.patch.object(S, '_build_secured_packet', return_value=('AA' * 10, {})), \
mock.patch.object(S, '_send_secured_packet',
return_value={'success': True, 'sw': '9000',
'response_data': '0271000021AABB'}), \
mock.patch.object(S, '_decode_por', return_value=decoded):
with contextlib.redirect_stderr(buf):
run = self.run_script(FakeServer(scc), [
{'type': 'action', 'kind': 'scp80',
'params': {'apdu': '80E2900000'}},
], preset)
self.assertEqual(run['status'], 'ok', run['steps'])
log = buf.getvalue()
self.assertIn('TEST-RUN step 1: PoR[inline] status=por_ok', log)
self.assertIn('raw=0271000021AABB', log)
self.assertIn('TEST-RUN step 1: R-APDU SW=9000 data=AABB', log)
def test_expect_decodes_the_submit_por(self):
import contextlib
import io
scc = FakeScc()
preset = {'kic': '15', 'kid': '15', 'kicKey': 'AA' * 16, 'kidKey': 'BB' * 16,
'counter': '0000000A', 'tars': preset_tars()}
decoded = {'response_status': 'por_ok', 'tar': '000000',
'decoded': {'last_status_word': '9000', 'last_response_data': 'AABB'}}
buf = io.StringIO()
with mock.patch.object(S, '_build_secured_packet', return_value=('AA' * 10, {})), \
mock.patch.object(S, '_send_secured_packet',
return_value={'success': True, 'sw': '9102',
@@ -742,14 +814,18 @@ class TestRunnerActions(RunnerTestCase):
mock.patch.object(S, '_decode_por', return_value=decoded) as dec:
scc.push('8012', self.SEND_SM_POR_CMD, '9000')
scc.push('8014', '', '9000')
run = self.run_script(FakeServer(scc), [
{'type': 'action', 'kind': 'scp80', 'params': {'apdu': '80E2900000'},
'check': {'sw': {'mode': 'mask', 'value': '91??'}, 'por': 'none'}},
{'type': 'expect', 'command': 'SEND SHORT MESSAGE',
'checks': [{'kind': 'por', 'status': 'por_ok', 'sw': '9000'}],
'respond': {'result': 'ok'}},
], preset)
with contextlib.redirect_stderr(buf):
run = self.run_script(FakeServer(scc), [
{'type': 'action', 'kind': 'scp80', 'params': {'apdu': '80E2900000'},
'check': {'sw': {'mode': 'mask', 'value': '91??'}, 'por': 'none'}},
{'type': 'expect', 'command': 'SEND SHORT MESSAGE',
'checks': [{'kind': 'por', 'status': 'por_ok', 'sw': '9000'}],
'respond': {'result': 'ok'}},
], preset)
self.assertEqual(run['status'], 'ok', run['steps'])
log = buf.getvalue()
self.assertIn('TEST-RUN step 2: PoR[sms-submit] status=por_ok', log)
self.assertIn('TEST-RUN step 2: R-APDU SW=9000 data=AABB', log)
self.assertEqual(run['steps'][1]['por']['response_status'], 'por_ok')
labels = {c['label']: c for c in run['steps'][1]['checks']}
self.assertTrue(labels['PoR status']['ok'], labels)