diff --git a/deploy/README.md b/deploy/README.md index 09b2889..1a65edf 100644 --- a/deploy/README.md +++ b/deploy/README.md @@ -212,6 +212,58 @@ sudo deploy/sipfaxctl status sudo deploy/sipfaxctl logs ``` +## PPP Runtime Requirements + +PPP only works once the host can actually run `pppd` and create a `ppp0` +interface. Three things the base VM does not provide by default: + +1. **The `ppp` package and a kernel with PPP support.** `apt-get install -y ppp` + provides `/usr/sbin/pppd` (setuid-root, group `dip`). The Debian **cloud** + kernel ships **no PPP modules** — `/dev/ppp` will be missing. Install the + generic kernel and boot it: + + ```bash + sudo apt-get install -y ppp linux-image-amd64 + echo ppp_generic | sudo tee /etc/modules-load.d/ppp.conf + # ensure GRUB boots the generic (non-cloud) kernel, then reboot + uname -r # expect e.g. 6.1.0-NN-amd64 (not -cloud-amd64) + ls -l /dev/ppp # must exist + ``` + +2. **A systemd drop-in so the unprivileged service can run setuid pppd.** The + shipped unit's hardening blocks it. Install + [`sipfax.service.d/ppp.conf`](sipfax.service.d/ppp.conf): + + ```bash + sudo install -D -m 0644 deploy/sipfax.service.d/ppp.conf \ + /etc/systemd/system/sipfax.service.d/ppp.conf + sudo systemctl daemon-reload && sudo systemctl restart sipfax.service + # verify: NoNewPrivs must be 0 on the running process + grep NoNewPrivs /proc/$(systemctl show -p MainPID --value sipfax.service)/status + ``` + +3. **Secrets files the service can rewrite.** `pppd` always reads + `/etc/ppp/chap-secrets`; the service renders per-call credentials there and + clears them on teardown, so pre-create them owned by `sipfax`: + + ```bash + sudo touch /etc/ppp/chap-secrets /etc/ppp/pap-secrets + sudo chown sipfax:sipfax /etc/ppp/chap-secrets /etc/ppp/pap-secrets + sudo chmod 600 /etc/ppp/chap-secrets /etc/ppp/pap-secrets + ``` + +## Modulation Note (V.8 vs forced V.22bis) + +Set `SIPFAX_MODEM_START_MODE=v22bis` for the live service. With real Windows +dial-up modems, standards **V.8 negotiation selects V.22bis but the modem then +fails to complete V.22bis training** (it sits on an unscrambled carrier while +the answerer trains) — a timing/interop quirk that does not reproduce in a +spandsp-to-spandsp loopback (see +[`tests/v8handoff_test.c`](../vendor/sipfax-softmodem/tests/v8handoff_test.c)). +**Forcing V.22bis** presents a continuous answer carrier the modem locks onto +and trains reliably. The V.8 handoff code itself is correct (the loopback test +passes); fixing the real-modem path needs lab tuning against the physical modem. + ## Firewall Expectations Restrict SIP and RTP ingress to the FreePBX IP. Replace `` with the diff --git a/deploy/sipfax.service.d/ppp.conf b/deploy/sipfax.service.d/ppp.conf new file mode 100644 index 0000000..857f228 --- /dev/null +++ b/deploy/sipfax.service.d/ppp.conf @@ -0,0 +1,31 @@ +# Drop-in to let the unprivileged sipfax service run pppd. +# +# pppd (from the Debian `ppp` package) is installed setuid-root, mode 4754 +# root:dip, and needs CAP_NET_ADMIN to create the ppp0 interface. The base +# unit's hardening (NoNewPrivileges, RestrictSUIDSGID, a CAP_NET_BIND_SERVICE- +# only bounding set, plus the seccomp-based LockPersonality/SystemCallArchitectures +# which silently re-imply NoNewPrivileges) all block that. Relax exactly what +# pppd needs; the node process itself stays unprivileged and gains nothing +# (only the setuid pppd child escalates). +# +# Install: copy to /etc/systemd/system/sipfax.service.d/ppp.conf, then +# systemctl daemon-reload && systemctl restart sipfax.service +# +# Prerequisites on the host: +# - apt-get install ppp (provides /usr/sbin/pppd, ppp_generic module) +# - a kernel with PPP support (the Debian "cloud" kernel has NONE; install +# linux-image-amd64 and boot it) +# - echo ppp_generic > /etc/modules-load.d/ppp.conf +# - pre-create the secrets files the service rewrites in place: +# touch /etc/ppp/chap-secrets /etc/ppp/pap-secrets +# chown sipfax:sipfax /etc/ppp/chap-secrets /etc/ppp/pap-secrets +# chmod 600 /etc/ppp/chap-secrets /etc/ppp/pap-secrets + +[Service] +NoNewPrivileges=false +RestrictSUIDSGID=false +LockPersonality=false +SystemCallArchitectures= +CapabilityBoundingSet=CAP_NET_BIND_SERVICE CAP_NET_ADMIN CAP_NET_RAW CAP_SETUID CAP_SETGID CAP_SYS_TTY_CONFIG CAP_DAC_OVERRIDE CAP_CHOWN CAP_FOWNER CAP_KILL CAP_AUDIT_WRITE +SupplementaryGroups=dip +ReadWritePaths=/run/lock /etc/ppp diff --git a/src/pppd-supervisor.js b/src/pppd-supervisor.js index 48e4883..20ba089 100644 --- a/src/pppd-supervisor.js +++ b/src/pppd-supervisor.js @@ -133,20 +133,19 @@ export class PppdSupervisor extends EventEmitter { callId }); - const secretOption = this.authProtocol === 'pap' ? 'pap-secrets' : 'chap-secrets'; - const wrapper = [ - 'secrets="$1/' + secretOption + '-$$"', - 'shift', - 'while [ ! -f "$secrets" ]; do sleep 0.02; done', - `exec "$@" ${secretOption} "$secrets"` - ].join('; '); - const child = this.spawnProcess('/bin/sh', ['-c', wrapper, 'sipfax-pppd', sessionDir, this.command, ...args], { + // pppd has no command-line option to select a secrets file; it always + // reads /etc/ppp/{chap,pap}-secrets. Render the per-call credentials there + // before launch (single active call) and remove the file on teardown. + const secretsFile = this.authProtocol === 'pap' + ? '/etc/ppp/pap-secrets' + : '/etc/ppp/chap-secrets'; + renderChapSecrets(credentials, secretsFile); + const child = this.spawnProcess(this.command, args, { stdio: ['ignore', 'pipe', 'pipe'] }); session.process = child; session.startedAt = new Date(); - session.secretsPath = join(sessionDir, `${secretOption}-${child.pid ?? 'unknown'}`); - renderChapSecrets(credentials, session.secretsPath); + session.secretsPath = secretsFile; session.args = args; child.stdout?.on('data', (chunk) => { @@ -288,6 +287,15 @@ export class PppdSupervisor extends EventEmitter { } catch (error) { session.lastError = error.message; } + if (session.secretsPath) { + // The secrets file lives in root-owned /etc/ppp; we own the file but + // not the directory, so clear it in place rather than unlinking it. + try { + writeFileSync(session.secretsPath, '', { mode: 0o600 }); + } catch (error) { + session.lastError = error.message; + } + } } writeEgressDescriptor(callId, descriptor) { diff --git a/vendor/sipfax-softmodem/sipfax-softmodem.c b/vendor/sipfax-softmodem/sipfax-softmodem.c index c13431b..20f8d92 100644 --- a/vendor/sipfax-softmodem/sipfax-softmodem.c +++ b/vendor/sipfax-softmodem/sipfax-softmodem.c @@ -66,6 +66,8 @@ typedef struct { fsk_rx_state_t *v21_rx; fsk_tx_state_t *v21_tx; v22bis_state_t *v22bis; + async_rx_state_t *async_rx; + async_tx_state_t *async_tx; int pty_master_fd; char pty_slave_path[128]; hdlc_rx_t hdlc_rx; @@ -84,6 +86,9 @@ typedef struct { uint64_t pty_bytes_out; int v8_status; int v8_modulations; + int advertised_modulations; + modulation_kind_t pending_modulation; + const char *pending_event; const char *last_event; } worker_t; @@ -122,6 +127,8 @@ static void v8_result(void *user_data, v8_parms_t *result); static void put_v21_bit(void *user_data, int bit); static void put_hdlc_bit(void *user_data, int bit); static void v22bis_status(void *user_data, int status); +static void async_put_byte(void *user_data, int byte); +static int async_get_byte(void *user_data); static int init_spandsp(worker_t *worker); static void release_spandsp(worker_t *worker); @@ -163,12 +170,18 @@ int main(void) { } emit_control(&worker, "started"); + /* Defer entry into data mode until the first input frame arrives, so the + * operator side is fully wired and cannot miss the pty-opened control event + * (a start-up race when forcing a modulation). */ if (parse_int_env("SIPFAX_MODEM_FORCE_DATA_MODE", 0) != 0) { - enter_data_mode(&worker, parse_force_modulation(), "forced-data-mode"); + worker.pending_modulation = parse_force_modulation(); + worker.pending_event = "forced-data-mode"; } else if (worker.start_mode == START_MODE_V22BIS) { - enter_data_mode(&worker, MODULATION_V22BIS, "start-mode-v22bis"); + worker.pending_modulation = MODULATION_V22BIS; + worker.pending_event = "start-mode-v22bis"; } else if (worker.start_mode == START_MODE_V21) { - enter_data_mode(&worker, MODULATION_V21, "start-mode-v21"); + worker.pending_modulation = MODULATION_V21; + worker.pending_event = "start-mode-v21"; } for (;;) { @@ -200,14 +213,27 @@ int main(void) { decode_g711(&worker, pcm, payload, frame_len); worker.frames_in++; + /* Perform a deferred forced-mode handoff now that input is flowing + * (and thus the operator side is listening for pty-opened). */ + if (worker.pending_event != NULL && !worker.data_mode) { + enter_data_mode(&worker, worker.pending_modulation, worker.pending_event); + worker.pending_event = NULL; + } + if (!worker.data_mode && worker.v8) { v8_rx(worker.v8, pcm, (int) frame_len); - if (!worker.data_mode && worker.v8) { + if (!worker.data_mode && worker.v8 && worker.pending_event == NULL) { int generated = v8_tx(worker.v8, pcm, (int) frame_len); if (generated > 0) { encode_g711(&worker, outbound, pcm, (size_t) generated); } } + /* v8_rx/v8_tx have fully returned now; safe to free v8 and start + * the negotiated data modem. */ + if (worker.pending_event != NULL && !worker.data_mode) { + enter_data_mode(&worker, worker.pending_modulation, worker.pending_event); + worker.pending_event = NULL; + } } else if (worker.modulation == MODULATION_V21 && worker.v21_rx) { poll_pty(&worker); fsk_rx(worker.v21_rx, pcm, (int) frame_len); @@ -609,9 +635,13 @@ static void poll_pty(worker_t *worker) { return; } worker->pty_bytes_in += (uint64_t) count; - if (hdlc_tx_enqueue_frame(worker, buffer, (size_t) count) != 0) { - emit_control(worker, "hdlc-tx-queue-full"); - return; + /* Transparent modem: pppd already framed this as async HDLC; queue the + * raw octets for V.14 transmission instead of re-framing them. */ + for (ssize_t i = 0; i < count; i++) { + if (hdlc_tx_enqueue_byte(worker, buffer[i]) != 0) { + emit_control(worker, "hdlc-tx-queue-full"); + return; + } } } } @@ -681,15 +711,29 @@ static void enter_data_mode(worker_t *worker, modulation_kind_t modulation, cons worker->v8 = NULL; } if (worker->modulation == MODULATION_V22BIS) { + /* V.22bis is a synchronous modem, but Windows dial-up carries + * asynchronous PPP (8N1 characters). Insert a V.14 async-to-sync + * layer between the V.22bis bit stream and the HDLC byte framing: + * rx: v22bis bits -> async_rx (strip start/stop) -> hdlc bytes + * tx: hdlc bytes -> async_tx (add start/stop) -> v22bis bits + */ + worker->async_tx = async_tx_init( + NULL, 8, ASYNC_PARITY_NONE, 1, TRUE, async_get_byte, worker); + worker->async_rx = async_rx_init( + NULL, 8, ASYNC_PARITY_NONE, 1, TRUE, async_put_byte, worker); + if (!worker->async_tx || !worker->async_rx) { + fprintf(stderr, "sipfax-softmodem: async (V.14) init failed\n"); + return; + } worker->v22bis = v22bis_init( NULL, 2400, V22BIS_GUARD_TONE_NONE, false, - hdlc_tx_next_bit, - worker, - put_hdlc_bit, - worker + async_tx_get_bit, + worker->async_tx, + async_rx_put_bit, + worker->async_rx ); if (!worker->v22bis) { fprintf(stderr, "sipfax-softmodem: v22bis_init failed\n"); @@ -717,16 +761,30 @@ static void v8_result(void *user_data, v8_parms_t *result) { worker_t *worker = (worker_t *) user_data; worker->v8_status = result->status; worker->v8_modulations = result->modulations; + /* This callback runs synchronously inside v8_rx(), which keeps using the + * v8 context after we return. Do NOT free v8 or start a data modem here: + * enter_data_mode() would v8_free() this very context and then malloc the + * v22bis/async state (often reusing the freed block), which v8_rx then + * corrupts on the way out. Just record the decision; main() performs the + * handoff once v8_rx/v8_tx have fully returned (see tests/v8_tests.c). */ if (result->status == V8_STATUS_V8_CALL) { - if ((result->modulations & V8_MOD_V22) != 0) { - enter_data_mode(worker, MODULATION_V22BIS, "v8-v22bis-selected"); + /* Pick the best modulation common to the caller's offer AND what we + * advertised, not just the caller's offer. Otherwise a V.22-capable + * caller forces V.22bis even when we only offered V.21. */ + int common = result->modulations & worker->advertised_modulations; + if ((common & V8_MOD_V22) != 0) { + worker->pending_modulation = MODULATION_V22BIS; + worker->pending_event = "v8-v22bis-selected"; } else { - enter_data_mode(worker, MODULATION_V21, "v8-v21-selected"); + worker->pending_modulation = MODULATION_V21; + worker->pending_event = "v8-v21-selected"; } } else if (result->status == V8_STATUS_NON_V8_CALL) { - enter_data_mode(worker, MODULATION_V21, "non-v8-v21-fallback"); + worker->pending_modulation = MODULATION_V21; + worker->pending_event = "non-v8-v21-fallback"; } else if (result->status == V8_STATUS_FAILED) { - enter_data_mode(worker, MODULATION_V21, "v8-failed-v21-fallback"); + worker->pending_modulation = MODULATION_V21; + worker->pending_event = "v8-failed-v21-fallback"; } } @@ -754,20 +812,65 @@ static void put_hdlc_bit(void *user_data, int bit) { static void v22bis_status(void *user_data, int status) { worker_t *worker = (worker_t *) user_data; - if (status < 0) { - worker->last_event = "v22bis-carrier-down"; - } else { + /* spandsp SIG_STATUS_* codes are all negative; the previous + * `status < 0` test could never report carrier-up or training. */ + switch (status) { + case SIG_STATUS_CARRIER_UP: worker->last_event = "v22bis-carrier-up"; + break; + case SIG_STATUS_CARRIER_DOWN: + worker->last_event = "v22bis-carrier-down"; + break; + case SIG_STATUS_TRAINING_IN_PROGRESS: + worker->last_event = "v22bis-training"; + break; + case SIG_STATUS_TRAINING_SUCCEEDED: + worker->last_event = "v22bis-trained"; + break; + case SIG_STATUS_TRAINING_FAILED: + worker->last_event = "v22bis-training-failed"; + break; + default: + worker->last_event = "v22bis-status"; + break; } } +/* V.14 async-to-sync glue for the V.22bis path. async_rx hands us each + * decoded character, which feeds the existing HDLC (PPP) byte framer; + * async_tx pulls the next HDLC byte to send, or -1 to transmit idle. */ +static void async_put_byte(void *user_data, int byte) { + worker_t *worker = (worker_t *) user_data; + if (byte < 0) { + return; + } + /* Transparent modem: pppd runs async HDLC itself, so pass the recovered + * octet stream (0x7E flags, byte-stuffing and FCS intact) straight to the + * pty rather than de-framing it here. */ + uint8_t octet = (uint8_t) byte; + if (worker->pty_master_fd >= 0 && write_all(worker->pty_master_fd, &octet, 1) == 0) { + worker->pty_bytes_out++; + } + worker->decoded_bytes++; +} + +static int async_get_byte(void *user_data) { + worker_t *worker = (worker_t *) user_data; + uint8_t byte; + if (hdlc_tx_pop_byte(worker, &byte)) { + return byte; + } + return -1; +} + static int init_spandsp(worker_t *worker) { v8_parms_t parms; memset(&parms, 0, sizeof(parms)); - parms.modem_connect_tone = true; + parms.modem_connect_tone = MODEM_CONNECT_TONES_ANSAM_PR; parms.send_ci = false; parms.call_function = V8_CALL_V_SERIES; - parms.modulations = V8_MOD_V21 | V8_MOD_V22; + worker->advertised_modulations = V8_MOD_V21 | V8_MOD_V22; + parms.modulations = worker->advertised_modulations; parms.protocol = V8_PROTOCOL_NONE; worker->v8 = v8_init(NULL, false, &parms, v8_result, worker); @@ -795,5 +898,13 @@ static void release_spandsp(worker_t *worker) { v22bis_free(worker->v22bis); worker->v22bis = NULL; } + if (worker->async_rx) { + async_rx_free(worker->async_rx); + worker->async_rx = NULL; + } + if (worker->async_tx) { + async_tx_free(worker->async_tx); + worker->async_tx = NULL; + } close_pty(worker); } diff --git a/vendor/sipfax-softmodem/tests/v8handoff_test.c b/vendor/sipfax-softmodem/tests/v8handoff_test.c new file mode 100644 index 0000000..2e43cda --- /dev/null +++ b/vendor/sipfax-softmodem/tests/v8handoff_test.c @@ -0,0 +1,152 @@ +/* Loopback test: does the V.8 -> V.22bis answer-side handoff train, vs forced V.22bis? + * Build against installed spandsp 0.0.6. Two endpoints (caller, answerer), clean + * 4-wire exchange (each side rx = other side's tx only -> no echo), so this isolates + * the handoff PROTOCOL from channel/echo effects. */ +#include +#include +#include +#include +#include +#include + +#define BLOCK 160 + +typedef enum { M_V8, M_V22BIS } modem_mode_t; + +typedef struct { + const char *name; + int calling; + v8_state_t *v8; + v22bis_state_t *v22bis; + modem_mode_t mode; + int pending; + int trained; + long rx_data_bits; + long tx_data_bits; + int guard; +} side_t; + +static int forced = 0; /* 1 = skip V.8, start V.22bis immediately */ + +static void start_v22(side_t *s); + +static void v8_result(void *u, v8_parms_t *r) { + side_t *s = (side_t *)u; + fprintf(stderr, " [%s] v8 result status=%d mods=0x%x\n", s->name, r->status, r->modulations); + if (r->status == V8_STATUS_V8_CALL) + s->pending = 1; /* defer handoff to main loop (after v8_rx returns) */ +} + +static int v22_getbit(void *u) { + side_t *s = (side_t *)u; + if (!s->trained) return 1; + s->tx_data_bits++; + return (int)(s->tx_data_bits & 1); +} +static void v22_putbit(void *u, int bit) { + side_t *s = (side_t *)u; + if (bit >= 0) { if (s->trained) s->rx_data_bits++; } +} +static void v22_status(void *u, int status) { + side_t *s = (side_t *)u; + const char *n = "?"; + switch (status) { + case SIG_STATUS_CARRIER_UP: n="carrier-up"; break; + case SIG_STATUS_CARRIER_DOWN: n="carrier-down"; break; + case SIG_STATUS_TRAINING_IN_PROGRESS: n="training"; break; + case SIG_STATUS_TRAINING_SUCCEEDED: n="TRAINED"; s->trained=1; break; + case SIG_STATUS_TRAINING_FAILED: n="train-FAILED"; break; + } + fprintf(stderr, " [%s] v22bis status %d (%s) rate=%d\n", s->name, status, n, + (status==SIG_STATUS_TRAINING_SUCCEEDED)? v22bis_get_current_bit_rate(s->v22bis) : 0); +} + +static void start_v22(side_t *s) { + s->v22bis = v22bis_init(NULL, 2400, s->guard, s->calling, v22_getbit, s, v22_putbit, s); + v22bis_set_modem_status_handler(s->v22bis, v22_status, s); + s->mode = M_V22BIS; + fprintf(stderr, " [%s] -> V.22bis (%s, guard=%d)\n", s->name, + s->calling?"calling":"answering", s->guard); +} + +static void init_v8(side_t *s) { + v8_parms_t p; memset(&p, 0, sizeof(p)); + p.modem_connect_tone = s->calling ? MODEM_CONNECT_TONES_NONE : MODEM_CONNECT_TONES_ANSAM_PR; + p.send_ci = s->calling ? true : false; + p.call_function = V8_CALL_V_SERIES; + p.modulations = V8_MOD_V21 | V8_MOD_V22; + p.protocol = V8_PROTOCOL_NONE; + s->v8 = v8_init(NULL, s->calling, &p, v8_result, s); + s->mode = M_V8; +} + +static int generate(side_t *s, int16_t *amp) { + int n = 0; + if (s->mode == M_V8 && s->v8) n = v8_tx(s->v8, amp, BLOCK); + else if (s->mode == M_V22BIS && s->v22bis) n = v22bis_tx(s->v22bis, amp, BLOCK); + if (n < BLOCK) { memset(amp + n, 0, (BLOCK - n) * sizeof(int16_t)); n = BLOCK; } + return n; +} +static void receive(side_t *s, const int16_t *amp) { + if (s->mode == M_V8 && s->v8) v8_rx(s->v8, amp, BLOCK); + else if (s->mode == M_V22BIS && s->v22bis) v22bis_rx(s->v22bis, amp, BLOCK); +} + +int main(int argc, char **argv) { + int guard = V22BIS_GUARD_TONE_NONE; + for (int i = 1; i < argc; i++) { + if (!strcmp(argv[i], "forced")) forced = 1; + else if (!strcmp(argv[i], "v8")) forced = 0; + else if (!strcmp(argv[i], "guard1800")) guard = V22BIS_GUARD_TONE_1800HZ; + } + side_t caller = { .name="CALLER", .calling=1, .guard=guard }; + side_t answer = { .name="ANSWER", .calling=0, .guard=guard }; + + fprintf(stderr, "=== MODE: %s, guard=%s ===\n", forced?"FORCED v22bis":"V.8 negotiated", + guard==V22BIS_GUARD_TONE_1800HZ?"1800Hz":"none"); + if (forced) { start_v22(&caller); start_v22(&answer); } + else { init_v8(&caller); init_v8(&answer); } + + /* near-end echo model: rx = remote tx + echo_gain * own tx delayed */ + double echo_gain = 0.0; + int echo_delay = 0; + const char *eg = getenv("ECHO_GAIN"); if (eg) echo_gain = atof(eg); + const char *ed = getenv("ECHO_DELAY"); if (ed) echo_delay = atoi(ed); + fprintf(stderr, "echo_gain=%.2f echo_delay=%d samples\n", echo_gain, echo_delay); + #define DLINE 4096 + static int16_t cdl[DLINE], adl[DLINE]; int dpos = 0; + + int16_t ampC[BLOCK], ampA[BLOCK], rxC[BLOCK], rxA[BLOCK]; + int both_trained_at = -1; + long N = 8000L * 25 / BLOCK; /* up to 25 seconds */ + for (long blk = 0; blk < N; blk++) { + generate(&caller, ampC); + generate(&answer, ampA); + for (int i = 0; i < BLOCK; i++) { + int de = (dpos + i - echo_delay + DLINE) % DLINE; + double ce = echo_gain * cdl[de]; /* caller's own delayed tx */ + double ae = echo_gain * adl[de]; /* answer's own delayed tx */ + int rc = (int)(ampA[i] + ce); /* caller rx = answer tx + own echo */ + int ra = (int)(ampC[i] + ae); /* answer rx = caller tx + own echo */ + rxC[i] = rc>32767?32767:(rc<-32768?-32768:rc); + rxA[i] = ra>32767?32767:(ra<-32768?-32768:ra); + } + for (int i = 0; i < BLOCK; i++) { cdl[(dpos+i)%DLINE]=ampC[i]; adl[(dpos+i)%DLINE]=ampA[i]; } + dpos = (dpos + BLOCK) % DLINE; + receive(&answer, rxA); /* answerer hears caller (+own echo) */ + receive(&caller, rxC); /* caller hears answerer (+own echo) */ + if (caller.pending) { v8_free(caller.v8); caller.v8=NULL; start_v22(&caller); caller.pending=0; } + if (answer.pending) { v8_free(answer.v8); answer.v8=NULL; start_v22(&answer); answer.pending=0; } + if (both_trained_at < 0 && caller.trained && answer.trained) { + both_trained_at = (int)(blk * BLOCK / 8); /* ms */ + fprintf(stderr, ">>> BOTH TRAINED at ~%d ms\n", both_trained_at); + } + if (both_trained_at >= 0 && blk * BLOCK / 8 > both_trained_at + 2000) break; /* 2s of data */ + } + fprintf(stderr, "RESULT: caller.trained=%d answer.trained=%d data bits rx: caller=%ld answer=%ld\n", + caller.trained, answer.trained, caller.rx_data_bits, answer.rx_data_bits); + printf("%s\n", (caller.trained && answer.trained && caller.rx_data_bits>0 && answer.rx_data_bits>0) + ? "PASS (handoff trained, data flowed both ways)" + : "FAIL (did not complete)"); + return 0; +}