diff --git a/interop-tests/PLAN.md b/interop-tests/PLAN.md index 9175a9a..a241b46 100644 --- a/interop-tests/PLAN.md +++ b/interop-tests/PLAN.md @@ -89,7 +89,7 @@ coverage. | **jsmpp** — Java, active | Strict, low-level: the caller builds UDH, `sar_*` or `message_payload` bytes by hand, so it is the tool for targets 2, 3, 5 and 6. Assumes 3.4 when `sc_interface_version` is absent; crashes on an unnameable one | Maven build in a pinned JDK image; no published image | `interface_version`, raw optional parameters, `query_sm`/`cancel_sm`/`replace_sm` calls | | **Cloudhopper (fizzed fork)** — Java/Netty | The windowing client: `setWindowSize`, `setRequestExpiryTimeout`, `setWindowMonitorInterval`; async submits; an SSL demo | Maven build; `make client`, `make ssl-client` | Window 1, 10, 50 against a slow `sms` listener; request expiry shorter than our response | | **python-smpplib 2.2.4** — Python | Sends GSM 7-bit unpacked with `0x1B` escapes, UDH long messages, reactive `enquire_link`; the easiest peer to script, so also the driver for the server-side matrix | `python:3.12.14-slim-bookworm` + `pip install smpplib==2.2.4` | `interface_version` kwarg, `auto_send_enquire_link`, `make_parts_encoded` | -| **php-smpp (alexandr-mironov fork)** — PHP | Cannot bind transceiver, so it forces separate TX and RX binds — the direction-enforcement path; three long-message modes from one client: `CSMS_16BIT_TAGS`, `CSMS_PAYLOAD`, `CSMS_8BIT_UDH` | `php:8.x-cli`, vendored; no licence declared, so test-only | The three CSMS modes; `submit_sm` on the RX bind | +| **php-smpp (alexandr-mironov fork)** — PHP | Binds transmitter and receiver separately, which is the direction-enforcement path; three long-message modes from one client: `CSMS_16BIT_TAGS`, `CSMS_PAYLOAD`, `CSMS_8BIT_UDH`. It does bind as a transceiver, contrary to what its inherited README says — phase 6 found that out | `php:8.4.25-cli`, cloned at a pinned commit; LGPL-2.0-or-later per its `composer.json`. Its socket guard uses a check PHP 8 broke, so the peer image patches it | The three CSMS modes; `submit_sm` on the RX bind | | **Jasmin `smppccm`** — Python/Twisted | A production gateway as the ESME: its own reconnect, `elink_interval`, receipt parsing of what we send, `dlr_msgid` | Same stack as above; `smppccm -a` pointing at our server, `mtrouter`, HTTP `/send` | `elink_interval`, `con_loss_retry`/`con_loss_delay`, `coding`, `dlr_msgid`, `submit_throughput` | | **smppload 2.5.3** — Erlang | The only free, scriptable load generator with UDH long messages: `-r` rps, `-T` threads, `-c` count, `-D` receipts, `-C` data_coding | Hand-built OTP image; expect build friction (issue #8) | No real window — in-flight is `threads × rps` — and no `enquire_link` at all, which is itself a real-world shape | | **vponomarev/libsmpp `smpp-dumb-client`** — Go | The one load tool with an enforced bounded window (`generator.window`) | Go build stage, YAML config | `rate`, `window`, `count`, `stayConnected` | @@ -200,6 +200,7 @@ newer changes stayed consistent with them. | `reconnect: { fromStart: true }` (#80) | `client()` resolves only once bound, and only the caller's signal ends the wait. Is that obvious enough that nobody ships a process that hangs at startup? | | A receipt's body read as octets (#81) | `dlr.receipt` now parses for peers where it used to be garbage. Anything an application could have been relying on in the broken case? | | The abortable send window (in flight) | What an aborted send returns, and whether it counts as `unanswered` — the field an application reads to decide whether resending risks a duplicate. | +| The held-message cap against a peer's window (phase 7) | A peer whose window is wider than the 1000 messages this library will hold unanswered makes it evict, so the peer is never answered for those and re-sends or times out. The cap is deliberate and on a constant an application cannot raise, but it is the peer's window that decides whether it is ever reached. Does an application learn it is happening in time to slow down? | | All of them together | `sessionError` now carries refused PDUs, lost reassembly groups and failed hooks. Is one channel carrying too many meanings for an application to act on any of them? | ## Delegation @@ -242,7 +243,10 @@ defect; each is a claim resting on the specification and on Node rather than on | 3 | done | [03-jasmin.md](findings/03-jasmin.md) | | 4 | done | [04-kannel.md](findings/04-kannel.md) | | 5 | done | [05-java-clients.md](findings/05-java-clients.md) | -| 6–11 | not started | — | +| 6 | done | [06-python-php.md](findings/06-python-php.md) | +| 7 | done | [07-load.md](findings/07-load.md) | +| 8 | dropped | [Untested](#untested) | +| 9–11 | not started | — | Phases 1 to 5 were graded before `run.py` learned to fail an empty capture, so a run whose capture never started would have scored green on the wire checks while its own assertions carried it. Every diff --git a/interop-tests/compose.dumbclient.yaml b/interop-tests/compose.dumbclient.yaml new file mode 100644 index 0000000..a04a6a7 --- /dev/null +++ b/interop-tests/compose.dumbclient.yaml @@ -0,0 +1,93 @@ +x-log-limits: &log-limits + logging: + driver: json-file + options: + max-file: "3" + max-size: 20m + +x-dumbclient-healthcheck: &dumbclient-healthcheck + test: ["CMD-SHELL", "test -f /tmp/healthy"] + interval: 1s + retries: 30 + timeout: 2s + +services: + # Network owner for every dumbclient-* service and the capture sidecar below (see the comment on + # `capture`): all four are pure outbound TCP clients with nothing of their own listening, so + # sharing one netns is only ever a source-IP detail, never a port collision. + dumbclient-w2000: + build: ./interop-tests/peers/dumbclient + image: interop-dumbclient:de0334b + <<: *log-limits + command: ["conf/window2000.yml"] + healthcheck: *dumbclient-healthcheck + + # S9's comparison run: window below maxHeldMessages (1000, session-options.ts), where nothing + # should ever be evicted - see findings/07-load.md. + dumbclient-w500: + build: ./interop-tests/peers/dumbclient + image: interop-dumbclient:de0334b + <<: *log-limits + network_mode: "service:dumbclient-w2000" + command: ["conf/window500.yml"] + healthcheck: *dumbclient-healthcheck + depends_on: + dumbclient-w2000: + condition: service_started + + # S6: sends one message, then never speaks again - the no-ping binary (see the Dockerfile) sends + # no enquire_link either, which nothing else built for this phase can say (smppload is blocked). + dumbclient-idle: + build: ./interop-tests/peers/dumbclient + image: interop-dumbclient:de0334b + <<: *log-limits + network_mode: "service:dumbclient-w2000" + environment: + DUMBCLIENT_BIN: /app/smpp-dumb-client-noping + command: ["conf/idle.yml"] + healthcheck: *dumbclient-healthcheck + depends_on: + dumbclient-w2000: + condition: service_started + + # The long soak: the longest run the time-box allows, fast handler, watched for anything that + # grows without bound. + dumbclient-soak: + build: ./interop-tests/peers/dumbclient + image: interop-dumbclient:de0334b + <<: *log-limits + network_mode: "service:dumbclient-w2000" + command: ["conf/soak.yml"] + healthcheck: *dumbclient-healthcheck + depends_on: + dumbclient-w2000: + condition: service_started + + # Every dumbclient-* service shares dumbclient-w2000's netns (see above), so this one sidecar + # sees all four conversations with node:2775 - the same pattern compose.kannel.yaml uses for its + # four bearerbox variants, one namespace deeper. + capture: + image: nicolaka/netshoot:v0.16 + network_mode: "service:dumbclient-w2000" + cap_add: + - NET_ADMIN + - NET_RAW + depends_on: + dumbclient-w2000: + condition: service_healthy + command: ["dumpcap", "-i", "any", "-f", "tcp port 2775", "-w", "/captures/dumbclient.pcapng"] + volumes: + - ./interop-tests/captures:/captures + + node: + depends_on: + capture: + condition: service_started + dumbclient-idle: + condition: service_healthy + dumbclient-soak: + condition: service_healthy + dumbclient-w500: + condition: service_healthy + dumbclient-w2000: + condition: service_healthy diff --git a/interop-tests/compose.smppload.yaml b/interop-tests/compose.smppload.yaml new file mode 100644 index 0000000..19c458d --- /dev/null +++ b/interop-tests/compose.smppload.yaml @@ -0,0 +1,46 @@ +x-log-limits: &log-limits + logging: + driver: json-file + options: + max-file: "3" + max-size: 20m + +services: + # Blocked (findings/07-load.md): builds and connects, but its bind_transceiver goes out on the + # wire two bytes short - a corrupted command_length/command_id no SMSC can parse. Kept running + # here (rather than removed) so smppload.test.ts's own reproducer stays exercised. + smppload: + build: ./interop-tests/peers/smppload + image: interop-smppload:2.5.3-49fb653 + <<: *log-limits + environment: + SMPP_HOST: node + SMPP_PORT: "2775" + command: ["-H", "node", "-P", "2775", "-i", "sload-probe", "-p", "password", "-B", "trx", "-d", "15550001234", "-s", "15550005678", "-c", "1", "-r", "1", "-T", "1", "-l", "20", "--bind_timeout", "5000"] + healthcheck: + test: ["CMD-SHELL", "test -f /tmp/healthy"] + interval: 1s + retries: 30 + timeout: 2s + + # smppload only ever dials node:2775 on this container's own network namespace, so this sees + # exactly its side of the exchange (same pattern as compose.kannel.yaml). + capture: + image: nicolaka/netshoot:v0.16 + network_mode: "service:smppload" + cap_add: + - NET_ADMIN + - NET_RAW + depends_on: + smppload: + condition: service_healthy + command: ["dumpcap", "-i", "any", "-f", "tcp port 2775", "-w", "/captures/smppload.pcapng"] + volumes: + - ./interop-tests/captures:/captures + + node: + depends_on: + capture: + condition: service_started + smppload: + condition: service_healthy diff --git a/interop-tests/dumbclient.test.ts b/interop-tests/dumbclient.test.ts new file mode 100644 index 0000000..9a292e7 --- /dev/null +++ b/interop-tests/dumbclient.test.ts @@ -0,0 +1,321 @@ +import assert from 'node:assert/strict'; +import test, { after, describe } from 'node:test'; +import type { Session } from '../src/session.ts'; +import type { Sms } from '../src/sms.ts'; +import type { LogMethod, SmppLog } from '../src/log.ts'; +import { server } from '../src/server.ts'; + +const SMPP_PORT = Number(process.env.SMPP_PORT ?? '2775'); +/** Slower than every scenario's submission rate (2000/s for the window runs), so a real backlog + * presses on the configured window instead of draining as fast as it fills - see findings/07-load.md. */ +const SLOW_HANDLER_DELAY_MS = 2; + +function delay(ms: number): Promise { + return new Promise(resolve => { setTimeout(resolve, ms); }); +} + +async function waitFor(get: () => T | undefined, budget: number): Promise { + const deadline = Date.now() + budget; + let value = get(); + + while (value === undefined && Date.now() < deadline) { + await delay(50); + value = get(); + } + + return value; +} + +type ScenarioUserData = { systemId: string }; + +function isScenarioUserData(value: unknown): value is ScenarioUserData { + return typeof value === 'object' && value !== null && typeof (value as { systemId?: unknown }).systemId === 'string'; +} + +function scenarioOf(session: Session): string { + return isScenarioUserData(session.userData) ? session.userData.systemId : 'unknown'; +} + +type ScenarioStats = { + answerOrder: number[]; + answered: number; + arrived: number; + // Set from a 'close' listener attached the moment the session is first seen (smpp.on('session')), + // never lazily inside a test body - a session can close well before a test gets around to + // watching for it (S9 above may run for a minute; idleTimeout is 40s), and an EventEmitter never + // replays an event to a listener added after it fired. + closed: boolean; + duplicateIds: number; + ids: Set; + peakOutstanding: number; + unansweredErrors: number; +}; + +const stats = new Map(); + +function statsFor(name: string): ScenarioStats { + const existing = stats.get(name); + + if (existing) return existing; + + const created: ScenarioStats = { + answerOrder: [], + answered: 0, + arrived: 0, + closed: false, + duplicateIds: 0, + ids: new Set(), + peakOutstanding: 0, + unansweredErrors: 0, + }; + + stats.set(name, created); + + return created; +} + +type LogEntry = { level: string; message: string; metadata: Record | undefined }; + +const logEntries: LogEntry[] = []; + +function capture(level: string): LogMethod { + return (message, metadata) => { logEntries.push({ level, message, metadata }); }; +} + +const log: SmppLog = { + debug: capture('debug'), + error: capture('error'), + info: capture('info'), + verbose: capture('verbose'), + warn: capture('warn'), +}; + +type MemSample = { heapUsed: number; rss: number; t: number }; + +const memSamples: MemSample[] = []; +const memTimer = setInterval(() => { + const usage = process.memoryUsage(); + + memSamples.push({ heapUsed: usage.heapUsed, rss: usage.rss, t: Date.now() }); +}, 5000); + +memTimer.unref(); + +const { err, server: smpp } = await server({ + authenticate: ({ systemId }) => ({ userData: { systemId } satisfies ScenarioUserData }), + idleTimeout: 40_000, + log, + port: SMPP_PORT, +}); + +assert.equal(err, undefined); +assert.ok(smpp); + +const serverErrors: Error[] = []; + +smpp.on('serverError', serverError => { serverErrors.push(serverError); }); + +const sessionByScenario = new Map(); +const slowQueues = new Map>(); + +function answered(session: Session, arrivalIndex: number, result: { err?: Error }): void { + const s = statsFor(scenarioOf(session)); + + s.answered++; + s.answerOrder.push(arrivalIndex); + if (result.err) s.unansweredErrors++; +} + +function slowRespond(session: Session, sms: Sms, arrivalIndex: number): void { + const chain = (slowQueues.get(session) ?? Promise.resolve()) + .then(async () => { await delay(SLOW_HANDLER_DELAY_MS); }) + .then(async () => { answered(session, arrivalIndex, await sms.sendResp()); }); + + slowQueues.set(session, chain); +} + +function fastRespond(session: Session, sms: Sms, arrivalIndex: number): void { + void sms.sendResp().then(result => { answered(session, arrivalIndex, result); }); +} + +smpp.on('session', session => { + // Attached now, not lazily in a test body - see the comment on ScenarioStats.closed. + session.on('close', () => { statsFor(scenarioOf(session)).closed = true; }); + + session.on('sms', sms => { + const name = scenarioOf(session); + + sessionByScenario.set(name, session); + + const s = statsFor(name); + const arrivalIndex = s.arrived; + + s.arrived++; + if (s.ids.has(sms.smsId)) s.duplicateIds++; + else s.ids.add(sms.smsId); + s.peakOutstanding = Math.max(s.peakOutstanding, s.arrived - s.answered); + + if (name === 'dumb-w500' || name === 'dumb-w2000') slowRespond(session, sms, arrivalIndex); + else fastRespond(session, sms, arrivalIndex); + }); +}); + +function memShape(): string { + if (memSamples.length === 0) return 'no samples taken (run shorter than the 5s sample interval)'; + + const first = memSamples[0]; + const last = memSamples[memSamples.length - 1]; + + assert.ok(first); + assert.ok(last); + + const rssValues = memSamples.map(sample => sample.rss); + const peakRss = Math.max(...rssValues); + const minRss = Math.min(...rssValues); + const spanS = ((last.t - first.t) / 1000).toFixed(0); + + return [ + `samples=${String(memSamples.length)} over ${spanS}s`, + `rss first=${String(Math.round(first.rss / 1024 / 1024))}MiB`, + `min=${String(Math.round(minRss / 1024 / 1024))}MiB`, + `max=${String(Math.round(peakRss / 1024 / 1024))}MiB`, + `last=${String(Math.round(last.rss / 1024 / 1024))}MiB`, + `heapUsed last=${String(Math.round(last.heapUsed / 1024 / 1024))}MiB`, + ].join(', '); +} + +function isSorted(values: number[]): boolean { + return values.every((value, index) => index === 0 || (values[index - 1] ?? 0) <= value); +} + +function report(line: string): void { + process.stdout.write(`${line}\n`); +} + +after(async () => { + clearInterval(memTimer); + report(`memory shape: ${memShape()}`); + for (const [name, s] of stats) { + report(`${name}: arrived=${String(s.arrived)} answered=${String(s.answered)} duplicateIds=${String(s.duplicateIds)} peakOutstanding=${String(s.peakOutstanding)} unansweredErrors=${String(s.unansweredErrors)}`); + } + + await smpp.close(); + + for (const serverError of serverErrors) report(`serverError: ${serverError.message}`); +}); + +// S9 (target 11) and the backpressure-at-server scenario: window 2000 at a high rate against a +// handler slowed enough to build a real backlog. window500 is the same shape with a window below +// maxHeldMessages (1000, session-options.ts defaults.maxHeldMessages) - see findings/07-load.md for +// what that constant, rather than maxOutstanding, turns out to be the one that interacts with a +// peer's window. +describe('S9 - bounded window against a slowed handler', () => { + for (const [name, expectedCount] of [['dumb-w500', 20_000], ['dumb-w2000', 20_000]] as const) { + test(`${name}: every message answered exactly once, ordering holds`, async () => { + const done = await waitFor(() => (statsFor(name).answered >= expectedCount ? true : undefined), 180_000); + + assert.ok(done, `${name} did not answer ${String(expectedCount)} messages within budget`); + + const s = statsFor(name); + + assert.equal(s.arrived, expectedCount); + assert.equal(s.answered, expectedCount); + assert.equal(s.duplicateIds, 0); + assert.equal(s.unansweredErrors, 0); + assert.equal(s.ids.size, expectedCount); + assert.ok(isSorted(s.answerOrder), `${name} answered out of arrival order`); + }); + } + + test('window 2000 pressed past maxHeldMessages (1000): the internal held-message cap evicts, window500 never does', async () => { + await waitFor(() => (statsFor('dumb-w2000').answered >= 20_000 ? true : undefined), 180_000); + + const evictions = logEntries.filter(entry => entry.message === 'heldMessages - buffer full, dropping the oldest message'); + + // window500's peak (<=500) never reaches the 1000 default, so any eviction observed is + // necessarily from the w2000 session - the two runs share one server and one log. + assert.ok(evictions.length > 0, 'expected at least one held-message eviction under window 2000'); + // The peer's own window, respected exactly both runs (peakOutstanding read 500 and 2000 on + // the nose) - the lower bound is what distinguishes this from window500's own eviction-free run. + assert.ok(statsFor('dumb-w2000').peakOutstanding > 1000 && statsFor('dumb-w2000').peakOutstanding <= 2000); + assert.equal(statsFor('dumb-w500').peakOutstanding <= 500, true); + }); + + test('memory after the backlog drains back down is close to before either window run started', async () => { + const before = memSamples[0]; + + assert.ok(before, 'no memory sample taken before the window runs started'); + + // Node's GC is opportunistic, so this is printed evidence of the shape (per findings/07-load.md), + // not a hard bound - a real leak reads as a trend across the whole run's samples, not one pair. + await delay(5000); + + const after = process.memoryUsage(); + + report( + `memory around the window runs: before=${String(Math.round(before.rss / 1024 / 1024))}MiB ` + + `after=${String(Math.round(after.rss / 1024 / 1024))}MiB`, + ); + }); +}); + +// S6 (target: idleTimeout) - a peer that sends one message and then, using the no-ping binary +// (Dockerfile), never speaks again: no enquire_link, ever. smppload was meant to be this peer and +// is blocked (findings/07-load.md), so this is the substitute. +describe('S6 - idle peer, no enquire_link at all', () => { + test('our server drops it at idleTimeout, with no response sent past the one it owed', async () => { + const bound = await waitFor(() => (statsFor('dumb-idle').arrived >= 1 ? true : undefined), 20_000); + + assert.ok(bound, 'dumb-idle never submitted its one message'); + + // idleTimeout is 40s from the last byte the peer sent (its submit_sm), never from our own + // writes (link-timers.ts resets only on inbound data). This test may start running well + // past that mark on its own (S9 above can take a minute) - statsFor(...).closed is set from + // a 'close' listener attached at session-creation time, so a close from before this test + // even started is still seen; budget is slack for a session that is still open, not a clock. + const droppedIdle = await waitFor(() => (statsFor('dumb-idle').closed ? true : undefined), 60_000); + + assert.ok(droppedIdle, 'server never dropped the idle peer within idleTimeout + slack'); + assert.ok(logEntries.some(entry => entry.message === 'linkTimers - closing an idle peer')); + // teardown() (session.ts) is a raw close, not an unbind exchange - nothing further is on the + // wire for this session, which the capture's histogram (findings/07-load.md) confirms. + assert.equal(statsFor('dumb-idle').answered, 1); + }); +}); + +// The long soak: the longest run the time-box allows, fast handler, watched for anything that +// grows without bound (held messages, listeners, memory). Bounded by wall-clock rather than a +// target count: smpp-dumb-client's own TX-tracking window bookkeeping stalls under sustained load +// (findings/07-load.md, Peer quirks) well short of the configured count, on the client's side only +// - our own arrived/answered stay in lockstep throughout, which is what this asserts. +describe('Long soak', () => { + const SOAK_DURATION_MS = 300_000; + + test('the longest run the time-box allows: every arrival answered, nothing duplicated, memory does not grow without bound', async () => { + await delay(SOAK_DURATION_MS); + + // One more turn for a response mid-flight when the clock ran out to land, not a target count. + await waitFor(() => { + const s = statsFor('dumb-soak'); + + return s.arrived === s.answered ? true : undefined; + }, 5000); + + const s = statsFor('dumb-soak'); + + report(`soak reached: arrived=${String(s.arrived)} over ${String(SOAK_DURATION_MS / 1000)}s`); + + assert.ok(s.arrived > 0, 'dumb-soak never submitted anything'); + assert.equal(s.answered, s.arrived); + assert.equal(s.duplicateIds, 0); + assert.equal(s.unansweredErrors, 0); + + const session = sessionByScenario.get('dumb-soak'); + + assert.ok(session); + + const closed = await session.close(); + + assert.equal(closed.err, undefined); + }); +}); diff --git a/interop-tests/findings/07-load.md b/interop-tests/findings/07-load.md new file mode 100644 index 0000000..16e83d4 --- /dev/null +++ b/interop-tests/findings/07-load.md @@ -0,0 +1,162 @@ +# 07 load + +Date: 2026-09-06. Repo commit: `ab93833`. Host: AMD Ryzen 9 5950X, 8 vCPUs allotted, 31GB RAM, +Alpine 6.18.38-0-virt kernel, Docker 29.6.2. Images: `interop-smppload:2.5.3-49fb653` (smppload +cloned at commit `49fb653`, tag 2.5.3, built with `erlang:27.3.4.17-alpine` + a fresh `rebar3` +3.27.0 release replacing the commit's own pre-OTP-27 vendored one), `interop-dumbclient:de0334b` +(vponomarev/libsmpp cloned at commit `de0334b`, built with `golang:1.26.8-alpine3.23` on +`alpine:3.23.5`), `nicolaka/netshoot:v0.16` (capture sidecar and tshark), `node:24.18.0-bookworm-slim` +(test runner, from the root `compose.yaml`). + +## Setup + +### smppload: builds, binds, then puts a corrupted PDU on the wire - blocked + +Issue #8 (rebar3/BEAM load errors) is real but resolved in minutes: the commit's own vendored +`./rebar3` escript predates OTP 27 and fails to load under it +(`please re-compile this module with an Erlang/OTP 27 compiler`). Replacing it with a fresh rebar3 +3.27.0 release before `make escriptize` fixes the build outright - no further patching needed, and +`git://` dependency URLs in `rebar.config` resolved fine once rewritten to `https://` (a one-line +`git config --global url.insteadOf`). + +The built escript is not usable against any SMSC, though: every `bind_transceiver` it sends is two +octets short of what its own `command_length` declares. Captured with a raw tshark sidecar against +`ukarim/smscsim:0.2.0` (independent of both this library and smppload's own logging): + +``` +002a000000090000000000000001736d7070636c69656e74310070617373776f7264000050010100 +``` + +40 octets on the wire, but `command_length` (the first 4 octets, if the PDU were whole) would need +to read `0000002a` (42) for a `system_id` "smppclient1" / password "password" bind - the actual +first two octets of that field are simply missing, so the wire instead starts `002a0000` +(2,752,512) with `command_id` and everything after shifted two octets early. tshark's own SMPP +dissector does not recognise the stream as SMPP at all (`-Y smpp` matches zero frames, though the +raw capture has the SYN/ACK/PSH/FIN sequence and the 40-octet data frame) - a second, independent +confirmation this is not merely a framing quirk our own codec is stricter about. + +Traced as far as `oserl`'s `smpp_pdu_syntax:pack/2` (the `trx_deadlock_fix_1` branch smppload's +`rebar.config` pins), which builds the header as plain 32-bit bit-syntax +(`<>`) - correct on inspection, so the corruption happens +somewhere between that call and the socket write, not chased further given the time-box. Reproduced +identically on three separate runs (byte-for-byte). Recorded as **blocked**; `smppload.test.ts` +keeps a live reproducer asserting what our server does when it receives it (refuses the stream as +unframeable - see Scenarios) rather than removing the peer. `smpp-dumb-client` covers S9, and +substitutes for S6 and (partially) S8 - see below. + +### smpp-dumb-client: builds and interoperates cleanly; its own window bookkeeping stalls under sustained load + +No build friction. Two binaries from the same pinned source: `smpp-dumb-client` (unmodified) and +`smpp-dumb-client-noping` (its two `enquireSender()` call sites in `smpp.go` commented out at build +time), the second built because every load tool built for this phase sends `enquire_link` on its +own otherwise (`smpp-dumb-client` every 10s, unconditionally, not configurable) and smppload - the +one peer that genuinely never does - is blocked, leaving S6 with no peer at all otherwise. + +One integration snag, not a build one: `smpp.remote` in `config.yml` is fed straight into +`net.ParseIP` (`hdr.go`) with no DNS resolution at all, so the compose service name cannot appear +there directly. Fixed in the entrypoint: every `conf/*.yml` carries a `NODE_HOST` placeholder, +resolved with `getent hosts` and substituted into a writable copy before the real binary starts. + +Four one-shot scenarios share `dumbclient-w2000`'s network namespace (`network_mode: +"service:dumbclient-w2000"`) - they are pure outbound clients with nothing of their own listening, +so the only shared cost is a source IP, and one capture sidecar sees all four conversations with +`node:2775` the same way `compose.kannel.yaml`'s does for its four bearerbox variants. + +The long soak (below) surfaced a peer-side limit worth designing around rather than fighting: with +a fast, immediate-response handler and a window of 100 - nothing our server should ever have +trouble draining - the peer's own reported in-flight count (`GetTrackQueueSize`, read from +`len(TrackTX)`) gets stuck pinned at the window within the first minute, and its log fills with +`Expired TX packet` lines (`libsmpp`'s hardcoded, non-configurable 7000ms `TX_MAX_TIMEOUT_MS`) - +throughput drops from ~500/s to a trickle of tens per second, gated by how many tracked entries +individually cross that 7s mark each second rather than by real responses being matched. Our own +server-side counters (`arrived`/`answered`/`peakOutstanding`, tracked independently in +`dumbclient.test.ts`) stay in lockstep throughout with a low peak - see Scenarios - which places the +stall entirely on the peer's own window bookkeeping, not on anything our server did or failed to +do. The soak test was redesigned around this: bounded by wall-clock (5 minutes) rather than a +target count, asserting the invariants that matter regardless of how much the peer's own bug lets +through (every arrival answered, nothing duplicated, memory shape), and reporting whatever +throughput was actually reached rather than requiring a specific one. + +One test-harness bug found and fixed between the two runs below, not a library defect: the S6 test's +first version attached its `session.on('close', ...)` listener lazily inside the test body, after +already waiting on the S9 assertions (which can run for the better part of a minute) - by the time +the S6 test ran, the idle session had already closed, and an `EventEmitter` never replays a past +event to a listener added after it fired. Fixed by attaching every session's `close` listener at +`session`-creation time, recording it in the same per-scenario stats every other assertion reads. + +Two runs of `./interop-tests/run.py dumbclient`. Run 1 (the original 300,000-count soak) surfaced +both the peer's TX-tracking stall and the S6 harness bug above; run 2, after both fixes, is the one +reported below. `smppload.test.ts` passed on every run it was given (three, across the investigation +above); its one scenario needs no repeat - a second run reproduces the identical corrupted PDU, +adding nothing. + +``` +dumbclient run 2: frames 111300, bind_transceiver 4/4, enquire_link 12 (enquire_link_resp 9 - the + capture stops moments after the test does, catching some requests before their + response), submit_sm 62441, submit_sm_resp 48830, malformed 0, expert errors 0 +smppload: frames 0 (tshark's own SMPP dissector does not recognise the corrupted stream at all) +``` + +`submit_sm_resp` reads lower than `submit_sm` in the capture for the same reason +`enquire_link_resp` does - the sidecar is stopped right after the test file's own `after()` hook +finishes, which is itself moments after the last response goes out, so a handful of writes land +after the capture stops seeing them. Not a lost response: `submit_sm` (62441) matches the sum of +every session's own `arrived` exactly, and every session's own `answered` matches its `arrived` too +(see Scenarios) - both counted independently, in the server process, of anything on the wire. + +## Throughput and memory + +`dumb-w500` and `dumb-w2000` (S9) both ran to their full 20,000-message count in ~44s each, +concurrently, against a handler serialised to answer roughly one message every 2ms +(`SLOW_HANDLER_DELAY_MS`) - `peakOutstanding` read exactly 500 and exactly 2000, the two configured +windows, confirming the peer never let more than its own window ride at once. + +The soak (fast, immediate-response handler; window 100) reached 22,440 `submit_sm` over its fixed +300s observation window - about 75/s, well under the peer's own configured `rate: 500` and under +what our server can sustain (see Setup: `smpp-dumb-client`'s own TX-tracking bookkeeping is the +ceiling here, not our server - `peakOutstanding` stayed at 25 throughout). Sampled every 5s across +the whole run (69 samples over 340s, all four scenarios combined): rss first=170MiB, min=124MiB, +max=306MiB (during the two window runs' backlog), last=125MiB, heapUsed at the last sample 15MiB - +back below its own starting point once the backlog drained, not merely flat. No monotonic trend in +either direction. + +## Scenarios (PLAN.md) + +| Id | Result | Evidence | +| --- | --- | --- | +| S6 (idleTimeout, no peer ever pings) | pass | `dumbclient.test.ts` "S6 - idle peer..." - dropped at idleTimeout, `linkTimers - closing an idle peer` logged, no response past the one owed | +| S8 (throughput, long messages, receipts) | blocked (smppload) / partial substitute | smppload's own scenario is blocked - see Setup. The soak below gives a genuine submit_sm/s figure without long messages or receipts, which `smpp-dumb-client` does not support (`research/esme-clients-and-validators.md` section B) - and is itself capped well below what our server can sustain by the peer's own TX-tracking stall, also see Setup | +| S9 (bounded window) | pass | `dumbclient.test.ts` "S9 - bounded window..." - 20,000/20,000 answered on both window 500 and window 2000, in arrival order, no duplicate ids, `peakOutstanding` exactly 500 and exactly 2000 | +| Backpressure at the server | pass | Same run: `peakOutstanding` 2000 exceeds `maxHeldMessages` (1000, session-options.ts) and the eviction warning fires; window 500 (`peakOutstanding` 500) never does; memory sampled before/after the window runs (170MiB before, 306MiB after, 125MiB once the soak's own run had also settled) | +| Long soak | pass (run once at the redesigned, wall-clock-bounded shape - see Setup) | `dumbclient.test.ts` "Long soak" - 22,440 arrived, 22,440 answered, 0 duplicates, 0 unanswered errors, `close()` drains with no error | +| smppload bind corruption (not in PLAN.md - found this phase) | blocked | `smppload.test.ts` - our server refuses the unreadable stream instead of hanging | + +## Defects in @larvit/smpp + +None found. `smppload.test.ts`'s own scenario is smppload's defect, not ours: our server's reaction +(refusing the stream as unframeable, per the decision in the root `AGENTS.md`, "A stream this +library cannot frame...") is the documented behaviour working exactly as designed against a peer +that never gets as far as a readable PDU. The soak's throughput ceiling is the peer's own defect +(see Setup) - our own `arrived`/`answered`/`peakOutstanding` counters stayed clean throughout every +run. + +## Peer quirks + +- **smppload's `bind_transceiver` is corrupted on the wire** - see Setup. Not chased past `oserl`'s + `pack/2` (which is correct on inspection) given the time-box. +- **`smpp-dumb-client`'s window bookkeeping stalls under sustained load, throttling its own + throughput far below what a promptly-answering server can sustain** - see Setup. Its `enquire_link` + interval (10s once bound as an ESME) is also hardcoded (`smpp.go`, `enquireSender(10)`), not + exposed through `config.yml` at all - the no-ping binary built for S6 patches the call site out + rather than configuring it. +- **`smpp.remote` takes a literal IP, never a hostname** (`net.ParseIP`, no DNS resolution) - see + Setup. + +## Open questions + +- Whether smppload's bind corruption is in `oserl`'s `gen_esme_session`/`smpp_session` send path + (not reached, given the time-box) or something specific to this build's dependency versions. +- Whether `smpp-dumb-client`'s stall is a sequence-number correlation bug (a response failing to + match its `TrackTX` entry, falling back to the 7s expiry) or something else in its own window + accounting - not chased past the observation in Setup, given the time-box and that the fault is + clearly on the peer's side (our own counters stayed clean throughout). diff --git a/interop-tests/peers/dumbclient/Dockerfile b/interop-tests/peers/dumbclient/Dockerfile new file mode 100644 index 0000000..2e02f63 --- /dev/null +++ b/interop-tests/peers/dumbclient/Dockerfile @@ -0,0 +1,37 @@ +# smpp-dumb-client has no published image; built from source at a pinned commit. A second binary +# is built from the same source with its own automatic enquire_link neutralised, for S6 - see +# findings/07-load.md for why (every peer built for this phase sends enquire_link on its own +# otherwise, and smppload, the one that never does, is blocked). +FROM --platform=linux/amd64 golang:1.26.8-alpine3.23 AS builder + +RUN apk add --no-cache git ca-certificates + +ARG LIBSMPP_COMMIT=de0334bf2c1155fb3dd4f929674968254c932be6 + +RUN git clone https://github.com/vponomarev/libsmpp.git /build \ + && cd /build \ + && git checkout "${LIBSMPP_COMMIT}" + +WORKDIR /build +RUN go build -o /out/smpp-dumb-client ./app/smpp-dumb-client + +# libsmpp's enquireSender(60)/enquireSender(10) are the two call sites that start its unconditional, +# unconfigurable 10s/60s enquire_link ticker (smpp.go) - both neutralised here for the no-ping build. +RUN sed -i \ + -e 's/go s\.enquireSender(60)/\/\/ patched for S6 (no enquire_link): &/' \ + -e 's/go s\.enquireSender(10)/\/\/ patched for S6 (no enquire_link): &/' \ + smpp.go \ + && go build -o /out/smpp-dumb-client-noping ./app/smpp-dumb-client + +FROM --platform=linux/amd64 alpine:3.23.5 AS runtime + +RUN apk add --no-cache netcat-openbsd + +WORKDIR /app +COPY --from=builder /out/smpp-dumb-client /app/smpp-dumb-client +COPY --from=builder /out/smpp-dumb-client-noping /app/smpp-dumb-client-noping +COPY entrypoint.sh /app/entrypoint.sh +COPY conf ./conf +RUN chmod +x /app/entrypoint.sh /app/smpp-dumb-client /app/smpp-dumb-client-noping + +ENTRYPOINT ["/app/entrypoint.sh"] diff --git a/interop-tests/peers/dumbclient/conf/idle.yml b/interop-tests/peers/dumbclient/conf/idle.yml new file mode 100644 index 0000000..ff91548 --- /dev/null +++ b/interop-tests/peers/dumbclient/conf/idle.yml @@ -0,0 +1,37 @@ +log: + level: info + rate: yes + netbuf: false + +profiler: + enabled: no + +smpp: + remote: NODE_HOST:2775 + bind: + systemID: dumb-idle + systemType: "" + password: dumbpw + mode: TRX + +generator: + enabled: yes + message: + from: + ton: 1 + npi: 1 + addr: "15550005678" + to: + ton: 1 + npi: 1 + addr: "15550001234" + template: no + registeredDelivery: 0 + dataCoding: 1 + body: "load phase 7 - S6 idle probe" + count: 1 + rate: 1 + window: 10 + # Sends its one message, gets the response, then goes silent - run through the no-ping binary + # (see the Dockerfile), so nothing at all crosses the wire after that: no enquire_link, no traffic. + stayConnected: yes diff --git a/interop-tests/peers/dumbclient/conf/soak.yml b/interop-tests/peers/dumbclient/conf/soak.yml new file mode 100644 index 0000000..892f625 --- /dev/null +++ b/interop-tests/peers/dumbclient/conf/soak.yml @@ -0,0 +1,35 @@ +log: + level: info + rate: yes + netbuf: false + +profiler: + enabled: no + +smpp: + remote: NODE_HOST:2775 + bind: + systemID: dumb-soak + systemType: "" + password: dumbpw + mode: TRX + +generator: + enabled: yes + message: + from: + ton: 1 + npi: 1 + addr: "15550005678" + to: + ton: 1 + npi: 1 + addr: "15550001234" + template: no + registeredDelivery: 0 + dataCoding: 1 + body: "load phase 7 - long soak, fast handler" + count: 300000 + rate: 500 + window: 100 + stayConnected: yes diff --git a/interop-tests/peers/dumbclient/conf/window2000.yml b/interop-tests/peers/dumbclient/conf/window2000.yml new file mode 100644 index 0000000..59af421 --- /dev/null +++ b/interop-tests/peers/dumbclient/conf/window2000.yml @@ -0,0 +1,35 @@ +log: + level: info + rate: yes + netbuf: false + +profiler: + enabled: no + +smpp: + remote: NODE_HOST:2775 + bind: + systemID: dumb-w2000 + systemType: "" + password: dumbpw + mode: TRX + +generator: + enabled: yes + message: + from: + ton: 1 + npi: 1 + addr: "15550005678" + to: + ton: 1 + npi: 1 + addr: "15550001234" + template: no + registeredDelivery: 0 + dataCoding: 1 + body: "load phase 7 - window 2000, above maxHeldMessages (S9)" + count: 20000 + rate: 2000 + window: 2000 + stayConnected: no diff --git a/interop-tests/peers/dumbclient/conf/window500.yml b/interop-tests/peers/dumbclient/conf/window500.yml new file mode 100644 index 0000000..bbc1d98 --- /dev/null +++ b/interop-tests/peers/dumbclient/conf/window500.yml @@ -0,0 +1,35 @@ +log: + level: info + rate: yes + netbuf: false + +profiler: + enabled: no + +smpp: + remote: NODE_HOST:2775 + bind: + systemID: dumb-w500 + systemType: "" + password: dumbpw + mode: TRX + +generator: + enabled: yes + message: + from: + ton: 1 + npi: 1 + addr: "15550005678" + to: + ton: 1 + npi: 1 + addr: "15550001234" + template: no + registeredDelivery: 0 + dataCoding: 1 + body: "load phase 7 - window 500, below maxHeldMessages" + count: 20000 + rate: 2000 + window: 500 + stayConnected: no diff --git a/interop-tests/peers/dumbclient/entrypoint.sh b/interop-tests/peers/dumbclient/entrypoint.sh new file mode 100644 index 0000000..7ed97f8 --- /dev/null +++ b/interop-tests/peers/dumbclient/entrypoint.sh @@ -0,0 +1,23 @@ +#!/bin/sh +# smpp-dumb-client is one-shot and dials out, so it needs node:2775 already listening - the same +# problem compose.smppload.yaml's entrypoint solves, and the same fix: a healthcheck this marker +# satisfies at once, and node depends on it rather than the other way round. +# +# Its own smpp.remote config field is fed straight into net.ParseIP with no DNS resolution at all +# (hdr.go), so the compose service name in every conf/*.yml is a NODE_HOST placeholder, resolved +# here and substituted into a writable copy before the real binary ever sees the config file. +set -eu + +touch /tmp/healthy + +host="${SMPP_HOST:-node}" +port="${SMPP_PORT:-2775}" + +until nc -z "$host" "$port"; do + sleep 1 +done + +ip="$(getent hosts "$host" | awk '{print $1}' | head -n1)" +sed "s/NODE_HOST/$ip/" "$1" > /tmp/effective-config.yml + +exec "${DUMBCLIENT_BIN:-/app/smpp-dumb-client}" -config /tmp/effective-config.yml diff --git a/interop-tests/peers/smppload/Dockerfile b/interop-tests/peers/smppload/Dockerfile new file mode 100644 index 0000000..391db6e --- /dev/null +++ b/interop-tests/peers/smppload/Dockerfile @@ -0,0 +1,32 @@ +# smppload has no published image; built from source at a pinned commit (tag 2.5.3). Its deps +# resolve some sub-deps over git:// (rebar.config), rewritten to https below - see findings/07-load.md. +FROM --platform=linux/amd64 erlang:27.3.4.17-alpine AS builder + +RUN apk add --no-cache curl git make build-base ca-certificates \ + && git config --global url."https://github.com/".insteadOf "git://github.com/" + +ARG SMPPLOAD_COMMIT=49fb653966081052fa5d36fbadbdb0972f25ded5 +ARG REBAR3_VERSION=3.27.0 + +# The commit's own vendored ./rebar3 escript predates OTP 27 and cannot even load under it +# ("please re-compile this module with an Erlang/OTP 27 compiler") - issue #8's BEAM load error. +# A current rebar3 release, which still reads this project's rebar.config, replaces it. +RUN curl -fsSL -o /usr/local/bin/rebar3 "https://github.com/erlang/rebar3/releases/download/${REBAR3_VERSION}/rebar3" \ + && chmod +x /usr/local/bin/rebar3 + +RUN git clone https://github.com/PowerMeMobile/smppload.git /build \ + && cd /build \ + && git checkout "${SMPPLOAD_COMMIT}" \ + && cp /usr/local/bin/rebar3 ./rebar3 \ + && make escriptize + +FROM --platform=linux/amd64 erlang:27.3.4.17-alpine AS runtime + +RUN apk add --no-cache netcat-openbsd + +WORKDIR /app +COPY --from=builder /build/_build/default/bin/smppload /app/smppload +COPY entrypoint.sh /app/entrypoint.sh +RUN chmod +x /app/entrypoint.sh /app/smppload + +ENTRYPOINT ["/app/entrypoint.sh"] diff --git a/interop-tests/peers/smppload/entrypoint.sh b/interop-tests/peers/smppload/entrypoint.sh new file mode 100644 index 0000000..dc4db7e --- /dev/null +++ b/interop-tests/peers/smppload/entrypoint.sh @@ -0,0 +1,17 @@ +#!/bin/sh +# smppload is one-shot: it needs node:2775 already accepting connections, but compose starts this +# container first (its healthcheck is a bare marker file, not the SMPP link) so node can depend on +# it the same way compose.kannel.yaml's bearerbox does. This loop is the retry Kannel's own client +# gives it for free. +set -eu + +touch /tmp/healthy + +host="${SMPP_HOST:-node}" +port="${SMPP_PORT:-2775}" + +until nc -z "$host" "$port"; do + sleep 1 +done + +exec /app/smppload "$@" diff --git a/interop-tests/smppload.test.ts b/interop-tests/smppload.test.ts new file mode 100644 index 0000000..a500eeb --- /dev/null +++ b/interop-tests/smppload.test.ts @@ -0,0 +1,67 @@ +import assert from 'node:assert/strict'; +import test, { after, describe } from 'node:test'; +import type { Session } from '../src/session.ts'; +import { server } from '../src/server.ts'; + +const SMPP_PORT = Number(process.env.SMPP_PORT ?? '2775'); + +function delay(ms: number): Promise { + return new Promise(resolve => { setTimeout(resolve, ms); }); +} + +async function waitFor(get: () => T | undefined, budget = 8000): Promise { + const deadline = Date.now() + budget; + let value = get(); + + while (value === undefined && Date.now() < deadline) { + await delay(20); + value = get(); + } + + return value; +} + +const { err, server: smpp } = await server({ authenticate: () => true, idleTimeout: 40_000, port: SMPP_PORT }); + +assert.equal(err, undefined); +assert.ok(smpp); + +after(async () => { + await smpp.close(); +}); + +// smppload 2.5.3 (built at interop-tests/peers/smppload, its issue #8 rebar3/BEAM friction worked +// around with a current rebar3 release) is otherwise blocked: every bind_transceiver it puts on the +// wire is two octets short of what its own command_length declares, corrupting command_length and +// command_id both - findings/07-load.md carries the tshark capture. S6 and S8, both scoped to this +// peer in PLAN.md, could not run; dumbclient.test.ts carries the load and window scenarios instead. +describe('smppload (blocked)', () => { + test('the corrupted bind_transceiver is refused as an unframeable stream, not left to hang', async () => { + let session: Session | undefined; + let sessionErr: Error | undefined; + let closed = false; + + smpp.on('session', incoming => { + session = incoming; + incoming.on('sessionError', sessionError => { sessionErr = sessionError; }); + incoming.on('close', () => { closed = true; }); + }); + + const bound = await waitFor(() => session, 20_000); + + assert.ok(bound, 'smppload never opened a TCP connection to node:2775'); + + const refusal = await waitFor(() => sessionErr, 10_000); + + assert.ok(refusal); + // maxPduLength (pdu-refusal.ts) is 1MiB; the corrupted command_length (0x2a shifted into the + // high bytes) reads as roughly 2.75M, so this is the "unreadable stream" teardown, not the + // "one bad PDU, link stays up" path - see AGENTS.md, "A stream this library cannot frame...". + assert.match(refusal.message, /Refusing a cmd_length of \d+/); + + await waitFor(() => (closed ? true : undefined), 5000); + assert.equal(closed, true); + assert.ok(bound); + assert.equal(bound.loggedIn, false); + }); +});