Feat/ach rescue on connect #38
@@ -14,6 +14,27 @@ This runbook describes how to break the loop and recover control.
|
||||
|
||||
---
|
||||
|
||||
## ⚠ There are TWO failure modes under "wedged unit"
|
||||
|
||||
Same root cause — an offset/connector fault drives the geophone above trigger,
|
||||
the unit records back-to-back, ACH set to "after event recorded" dials
|
||||
constantly — but the *recovery* differs, because the thing blocking you is
|
||||
different.
|
||||
|
||||
| | **BE9558H (2026-05)** | **BE12599 (2026-09)** |
|
||||
|---|---|---|
|
||||
| What blocks you | Modem mode-flipping kills inbound TCP | Device never enters S3 mode at all |
|
||||
| Device state | Alive, in S3 mode, responsive once reached | Stuck repeating an **AT modem-init** string, deaf to S3 |
|
||||
| Fix direction | **Inbound** — clear Destination, slow-drip a Stop | **Inverted** — point Destination at our own ACH server and let the unit call *us* |
|
||||
| Winning tool | `scripts/slow_drip.sh` | `bridges/ach_server.py --stop-monitoring` |
|
||||
|
||||
**Tell them apart with the ALEOS serial log** (see "Turn on ALEOS_SERIAL debug"
|
||||
below). If the device is emitting `ATQ1/ATE0/ATS0=2` every ~75 s, it is in the
|
||||
BE12599 mode and **no amount of inbound work will reach it** — skip to
|
||||
"Second incident" below.
|
||||
|
||||
---
|
||||
|
||||
## Symptoms
|
||||
|
||||
- Terra-View / SFM `/device/info` either hangs or fails on `count_events()`.
|
||||
@@ -253,3 +274,206 @@ service).
|
||||
|
||||
Total time from "i was wondering if its possible to" first attempt to
|
||||
recovery: ~7 hours of intermittent debugging across one evening.
|
||||
|
||||
---
|
||||
|
||||
# Second incident — BE12599, 2026-09-16/17
|
||||
|
||||
**Unit:** BE12599 at `166.246.64.226:9034`, RV50, job *I-80 North Fork Bridge
|
||||
— Abut 1 West* (Fay Company). Same job as BE9558H, which is a coincidence.
|
||||
|
||||
**Fault:** the connector fault documented in `docs/offset_investigation.md`
|
||||
§8e progressed until the Tran pedestal reached **0.400 in/s** — its trigger
|
||||
level. Constant triggering → constant recording → ACH "after event recorded"
|
||||
→ continuous dialing. Same disease as BE9558H.
|
||||
|
||||
**But the recovery was the opposite direction**, and none of the Step 1–4
|
||||
procedure above worked. Total time ≈ 5 h, of which ~90 min was spent on two
|
||||
red herrings documented below.
|
||||
|
||||
---
|
||||
|
||||
## Turn on ALEOS_SERIAL debug FIRST
|
||||
|
||||
This is the single highest-value diagnostic and it should be step zero on any
|
||||
future incident. ACEmanager → **Admin → Log → ALEOS_SERIAL log level →
|
||||
DEBUG**, then view the serial log.
|
||||
|
||||
It is the only thing that tells you what the *device* is actually saying.
|
||||
Everything before we did this was guesswork.
|
||||
|
||||
## What the log showed — the device was never in S3 mode
|
||||
|
||||
Every ~75 seconds, verbatim:
|
||||
|
||||
```
|
||||
ALEOS_SERIAL_HIF: 29 byte(s) in buffer: 'ATQ1^MATE0^MATS0=2^M^MRADIO RING^M'
|
||||
ALEOS_SERIAL_HMC: TCP recvhost fd 65535 len 29 state TCPMode::kClosed
|
||||
ALEOS_SERIAL_HMC: tcpmode trying to send to invalid socket
|
||||
ALEOS_SERIAL_HMC: Connect to IP: 0.0.0.0 Port 0
|
||||
ALEOS_SERIAL_HMC: Initialize Auto answer on port 9034
|
||||
ALEOS_SERIAL_HMC: Cannot connect to 0.0.0.0
|
||||
```
|
||||
|
||||
Read that carefully:
|
||||
|
||||
- `ATQ1` (quiet) / `ATE0` (echo off) / `ATS0=2` (auto-answer after 2 rings).
|
||||
**There is no `ATD`.** The device is not dialing — it is trying to
|
||||
*configure* its modem.
|
||||
- The modem's serial port is in TCP data mode, so it never interprets these
|
||||
as AT commands. It treats them as payload and tries to ship them to a TCP
|
||||
socket that does not exist.
|
||||
- The device therefore never receives `OK`, never progresses, and **retries
|
||||
the identical 29 bytes forever**.
|
||||
|
||||
**Consequence: the device is not running the S3 protocol parser.** You can
|
||||
land a byte-perfect S3 frame on it and it will be ignored. This is why every
|
||||
inbound approach failed, and it is the structural difference from BE9558H.
|
||||
|
||||
### Why `slow_drip` lied
|
||||
|
||||
`slow_drip` returned the *success* signature except for the one field that
|
||||
mattered:
|
||||
|
||||
```json
|
||||
{"duration_s":120.0,"drips_sent":38,"bytes_sent":920,
|
||||
"bytes_received":0,"send_error":null}
|
||||
```
|
||||
|
||||
Full duration, no broken pipe — but zero bytes back. Cause is in the log
|
||||
above: each 75 s cycle re-runs `Initialize Auto answer on port 9034`, which
|
||||
orphans the held session (`data in for unknown reason 3 removing from
|
||||
select`, `OnMsg recv error: 107 - Transport endpoint is not connected`). Our
|
||||
local TCP stayed open so `sendall` never raised — but the modem stopped
|
||||
bridging after the first re-init, so every drip after that went into a socket
|
||||
nobody was reading.
|
||||
|
||||
⚠ **`send_error: null` + full duration is NOT success. Only
|
||||
`bytes_received > 0` is success.**
|
||||
|
||||
---
|
||||
|
||||
## ⚠ Two red herrings that cost ~90 minutes
|
||||
|
||||
### 1. The trusted-IP whitelist (this was the real reason inbound never worked)
|
||||
|
||||
The RV50s run with **Security → Trusted IPs (Friends List) enabled**. A
|
||||
source IP that is not on the list is dropped **silently** — inbound presents
|
||||
as `Connection error: timed out`, never a refusal.
|
||||
|
||||
Brian's dev-box public IP is **dynamic** and had changed, so `tmi-dev` was no
|
||||
longer whitelisted. Every inbound attempt failed identically across four
|
||||
different modem and device states, which looked exactly like the BE9558H
|
||||
mode-flipping symptom and sent us chasing modem configuration for over an
|
||||
hour.
|
||||
|
||||
**Check this before diagnosing anything else.** Note that SFM in Docker
|
||||
egresses via the *host's public IP*, not its LAN IP.
|
||||
|
||||
### 2. A 502 from SFM does not mean TCP connected
|
||||
|
||||
`sfm/server.py` raises **502 for both** failure classes:
|
||||
|
||||
```python
|
||||
raise HTTPException(status_code=502, detail=f"Protocol error: {exc}")
|
||||
raise HTTPException(status_code=502, detail=f"Connection error: {exc}")
|
||||
```
|
||||
|
||||
We read an early 502 as "TCP connected, modem bridged, device mute" and built
|
||||
a whole theory on it. It was almost certainly a connect timeout.
|
||||
**Always read the `detail` string** — "connect failed" and "device didn't
|
||||
answer" are completely different problems and the status code will not
|
||||
separate them.
|
||||
|
||||
---
|
||||
|
||||
## What actually worked — invert the direction
|
||||
|
||||
The key observation is in the log above:
|
||||
|
||||
> `TCP recvhost ... state TCPMode::kClosed` → `Connect to IP: 0.0.0.0 Port 0`
|
||||
|
||||
**The modem auto-dials its Destination whenever serial data arrives while
|
||||
closed.** So instead of fighting for inbound, give it somewhere to dial:
|
||||
point `Destination Address` at our own `ach_server` and the device's own
|
||||
75-second attempts become **device-initiated sessions the modem bridges
|
||||
correctly**. No race, no contention, worst case a 75-second wait.
|
||||
|
||||
### Procedure
|
||||
|
||||
1. **Run the rescue server** on a host the modem can reach (public IP +
|
||||
forwarded port):
|
||||
|
||||
```bash
|
||||
cd /home/serversdown/seismo-relay
|
||||
.venv/bin/python -u bridges/ach_server.py --port 12345 \
|
||||
-o bridges/captures/<unit>-diag --stop-monitoring -v
|
||||
```
|
||||
|
||||
2. **Point the modem at it** — ACEmanager → Serial → Port Configuration →
|
||||
`Destination Address` = your public IP, `Destination Port` = 12345.
|
||||
|
||||
3. **Wait for the call-in.** `--stop-monitoring` fires SUB 0x97 at step 1.5,
|
||||
after the handshake and *before* the event walk. Confirm via
|
||||
`rescue.json` in the session directory:
|
||||
|
||||
```json
|
||||
{"peer": "166.246.64.226:60921", "stop_monitoring": "ok"}
|
||||
```
|
||||
|
||||
4. **Restore the modem's Destination** once you are done, then finish the
|
||||
device side (disable ACH, erase) through whichever channel works.
|
||||
|
||||
On BE12599 the first call-in landed at 20:58:11 and reported
|
||||
`stop_monitoring: ok`; a second at 20:58:20 confirmed it. `is_monitoring:
|
||||
false` was still true **6½ hours later** — the fix is durable.
|
||||
|
||||
---
|
||||
|
||||
## Hard-won gotchas (do not re-derive)
|
||||
|
||||
- **Never leave the Destination pointed at a host with nothing listening.**
|
||||
That is the worst state available: the device still dials, the modem still
|
||||
flips, inbound stays blocked, and nothing is delivered. An 8-minute gap
|
||||
with the listener down produced a spurious inbound timeout that cost
|
||||
another round of misdiagnosis.
|
||||
|
||||
- **Stopping monitoring removes your call-in channel.** ACH is "after event
|
||||
recorded"; no new events means no new dials. The backlog sitting in memory
|
||||
does *not* re-arm it. After a successful stop the unit goes quiet and you
|
||||
need the modem cycled (works — produced a call-in), the scheduled daily call
|
||||
(BE12599 calls at **05:00:14 device-local**, per §8e), or working inbound.
|
||||
**Plan the order before you fire the stop.**
|
||||
|
||||
- **`--events-only` silently breaks dedup.** It skips the device-info step,
|
||||
so the serial is never read; `ach_state.json` then keys on
|
||||
`peer:ephemeral_port`, which is unique per connection. Every session looks
|
||||
like a new unit, starts from key 0, and re-downloads the same event. Four
|
||||
sessions on BE12599 downloaded the identical event four times and made zero
|
||||
progress on the backlog. Events also file as `serial=UNKNOWN` with a
|
||||
`M000…` BW filename (serial_numeric 0) instead of `N599…`.
|
||||
**Do not use `--events-only` when you intend to download anything.**
|
||||
|
||||
- **`/device/events/index` reported `lifetime_count: 0`** on a unit with years
|
||||
of history. Suspected decode bug in the SUB 0x08 field offset — do not
|
||||
trust that number. The 88-byte payload is preserved in the `raw_hex` field
|
||||
if someone wants to chase it.
|
||||
|
||||
- **Memory used cross-checks the event keys exactly:**
|
||||
`last_key − buffer_start = memory_total − memory_free`. On BE12599:
|
||||
`0x011230ec − 0x01110000 = 78,060` and `983,028 − 904,968 = 78,060`.
|
||||
Useful sanity check that you are reading the keys right.
|
||||
|
||||
---
|
||||
|
||||
## Final state (2026-09-17 ~01:30 local)
|
||||
|
||||
- `is_monitoring: false`, held 6½ hours
|
||||
- Battery 6.76 V
|
||||
- Memory 78,060 / 983,028 bytes used (8%)
|
||||
- `first_key 01121728`, `last_key 011230ec` — ~6.6 KB of addressable event
|
||||
chain, roughly 3 events
|
||||
- ACH still **enabled** — to be disabled after the backlog is preserved
|
||||
- Modem Destination still pointed at tmi-dev — to be restored
|
||||
- ⚠ **Do not re-enable ACH until the connector is serviced.** Tran is still
|
||||
sitting at 0.400 and the loop restarts the moment monitoring resumes.
|
||||
|
||||
@@ -0,0 +1,134 @@
|
||||
# Plan — "Rescue Listener": a first-class tool for the inverted rescue
|
||||
|
||||
**Status:** proposal, not started. Written 2026-09-17 ~01:40 local, straight
|
||||
off the BE12599 incident. Open questions at the bottom need Brian's answer
|
||||
before anything is built.
|
||||
|
||||
**Background:** `docs/runbooks/wedged_unit_recovery.md`, "Second incident —
|
||||
BE12599". The manual version of this worked; this plan is about making it a
|
||||
tool instead of a sequence of remembered steps at 1 AM.
|
||||
|
||||
---
|
||||
|
||||
## The problem, stated plainly
|
||||
|
||||
When a unit is wedged in the BE12599 mode — geophone offset above trigger,
|
||||
recording back-to-back, ACH dialing constantly, device stuck repeating an AT
|
||||
modem-init string and therefore **deaf to S3 over inbound** — the only channel
|
||||
that works is the one the *device* opens.
|
||||
|
||||
Recovering it currently means:
|
||||
|
||||
1. Remember that `bridges/ach_server.py` exists and takes the right flags
|
||||
2. Start it by hand on a box the modem can reach, with a public port forwarded
|
||||
3. Go into ACEmanager and repoint the modem's Destination
|
||||
4. Watch a terminal for a call-in
|
||||
5. Read `rescue.json` to find out whether it worked
|
||||
6. Go back into ACEmanager and repoint the modem to where it belongs
|
||||
7. **Not forget step 6**, because leaving the Destination pointed at a dead
|
||||
listener is worse than never having started
|
||||
|
||||
That is six manual steps and one landmine, executed under pressure while a
|
||||
unit floods the office server.
|
||||
|
||||
## What the tool should be
|
||||
|
||||
**A "rescue listener" an operator can start for one unit, which handles
|
||||
whatever that unit says when it calls in, and refuses to go away until the
|
||||
operator confirms the modem has been pointed back.**
|
||||
|
||||
Lifecycle:
|
||||
|
||||
1. **Start** — operator names the target unit and starts a rescue listener.
|
||||
The tool reports the exact address/port to enter in ACEmanager, plus the
|
||||
actions it will take.
|
||||
2. **Operator repoints the modem** to that address.
|
||||
3. **Wait** — listener sits there. Live status: "waiting for call-in",
|
||||
elapsed, last-seen.
|
||||
4. **Act** — on call-in, run the configured rescue actions automatically,
|
||||
in a safe order, each independently guarded. Report per-action outcome.
|
||||
5. **Hold** — the listener **stays up** and keeps reporting, because the
|
||||
modem is still pointed at it.
|
||||
6. **Confirm & stop** — the operator explicitly confirms the Destination has
|
||||
been restored (to `0.0.0.0`, or to the office Instantel ACH server).
|
||||
Only then does the listener shut down.
|
||||
|
||||
Step 6 is the whole point of making this a tool. It is the step that is
|
||||
easiest to skip and most expensive to skip.
|
||||
|
||||
## Default action set
|
||||
|
||||
Ordered deliberately — see "order matters" below.
|
||||
|
||||
| # | Action | Default | Why |
|
||||
|---|---|---|---|
|
||||
| 1 | **Stop monitoring** (SUB 0x97) | ✅ on | Halts recording; ends the trigger→record→dial loop at its source. Already implemented as `--stop-monitoring`. |
|
||||
| 2 | **Drain events** to a diagnostics store | ⚙ configurable | The backlog is usually evidence, not garbage — see the BE12599 offset investigation. Must NOT land in the prod SFM DB. |
|
||||
| 3 | **Disable ACH** (SUB 0x2C/0x7E/0x7F) | ❌ off by default | Stops the dialing — **and stops your only channel**. Opt-in, and ideally gated on step 1 having succeeded. |
|
||||
| 4 | **Erase events** | ❌ off by default | Destructive. Only after a verified drain. |
|
||||
|
||||
### Order matters — the lesson from BE12599
|
||||
|
||||
Stopping monitoring *removes the call-in trigger*. ACH fires on "after event
|
||||
recorded"; with recording stopped, the unit has no reason to dial again, even
|
||||
though the backlog is still sitting in its memory. So a naive
|
||||
"stop + disable + erase, all at once" rescue can silence the unit before
|
||||
you've collected anything, leaving you with no channel and a device full of
|
||||
evidence.
|
||||
|
||||
The tool should either sequence around this or warn loudly about it. My
|
||||
instinct is: **stop monitoring immediately** (it's the bleeding), then drain
|
||||
across however many call-ins it takes, and treat disable-ACH/erase as a
|
||||
separate, explicit "finish" action once the operator is satisfied.
|
||||
|
||||
## Where it should live — open question, with a proposal
|
||||
|
||||
The natural tier is **SFM** (device-side, per the three-tier model in
|
||||
CLAUDE.md). But the rescue listener must be reachable *from the cellular
|
||||
network*, which is a deployment constraint SFM's usual profile doesn't have.
|
||||
|
||||
**Proposal worth considering:** run it at the office, beside the real Instantel
|
||||
ACH server, on a **different port** (e.g. 12346 while Instantel holds 12345).
|
||||
Then the ACEmanager change is a **port change, not an IP change** — smaller,
|
||||
faster, less to get wrong, and trivially reversible. It also means the office
|
||||
public IP (already stable and known) is the destination, rather than whatever
|
||||
Brian's dynamic home IP happens to be that week.
|
||||
|
||||
The tmi-dev approach used on BE12599 worked, but required a router forward and
|
||||
ran into the dynamic-IP problem in the same session.
|
||||
|
||||
## Open questions
|
||||
|
||||
1. **Where does it run?** Office beside Instantel ACH (port swap), SFM on the
|
||||
NAS, or ad-hoc on tmi-dev? Affects everything else.
|
||||
2. **What drives it?** Terra-View admin page (fits "operator UI"), an SFM
|
||||
endpoint pair (`POST /device/rescue_listener/start` + `/stop` + `/status`),
|
||||
or a CLI wrapper? A long-lived listener doesn't fit the request/response
|
||||
endpoint shape well — probably needs a background task with a status poll.
|
||||
3. **How does it identify the unit?** It can't know the serial until the
|
||||
device calls in and the handshake reads it. Allowlist by modem IP? Accept
|
||||
anything and report what showed up?
|
||||
4. **Where do drained events go?** A per-incident diagnostics store
|
||||
(`bridges/captures/<unit>-diag`) seems right — explicitly *not* the prod
|
||||
SFM DB. Does that store need to be a first-class thing with its own
|
||||
retention, or is a directory fine?
|
||||
5. **How is "confirm the modem is repointed" verified?** Operator attestation
|
||||
(a button), or can we actually probe it? If the listener stops seeing
|
||||
call-ins that's weak evidence; if inbound to the unit starts working that's
|
||||
stronger.
|
||||
6. **Multi-unit?** One listener per incident, or one listener that handles any
|
||||
unit that dials in? Probably the former for safety.
|
||||
7. **Timeout / abandonment policy.** If nobody ever confirms, does it run
|
||||
forever? Alert after N hours?
|
||||
|
||||
## What already exists
|
||||
|
||||
- `bridges/ach_server.py` — the listener itself, with `--stop-monitoring`,
|
||||
`--disable-ach`, `--rescue` (added on `feat/ach-rescue-on-connect`, commit
|
||||
`9f1050b`), `--clear-after-download`, `--max-events`, `--allow-ip`.
|
||||
- Per-session `rescue.json` recording per-action outcomes.
|
||||
- Isolated per-output-dir SQLite + waveform store, so a diagnostics capture is
|
||||
already separate from prod by construction.
|
||||
|
||||
So the gap is not protocol work — it's lifecycle, operator surface, and the
|
||||
confirmation gate. Most of the risk is in questions 1 and 2.
|
||||
Reference in New Issue
Block a user