Roll back orphaned tunnel on DNAT failure, distinguish suppressed dial retries in logs

danny commented

2026-07-07 16:07:42 +01:00

(Migrated from gitlab.keyop.co.uk)

Closes #31

Background

Found while investigating #4. The ticket originally focused on three unconditional NfDrop-with-no-retry paths in getNfCallback, plus the 5s sshRetryCooldown blanket-dropping packets for every destination sharing an SSH connection pool. Digging into these turned up two genuinely distinct, independently-worth-fixing issues:

1. A failed DNAT insertion leaves an orphaned, silently-unencrypted tunnel (the more severe finding)

getNfCallback calls sshConn.OpenTunnel (which registers the tunnel and starts its local listener) before calling addDNATRulesFunc. If the DNAT insert then fails, the code dropped the current packet but never rolled the tunnel back - it stayed registered as "open". Every later packet to that same destination would then hit sshtunnel.ErrPortTunnelAlreadyOpen and get verdicted NfAccept (issue #4's mechanism, correctly assuming a DNAT rule already exists for an already-open tunnel) - except no DNAT rule was ever successfully inserted. The result: traffic to that destination would silently flow out unencrypted, direct to the real destination, bypassing the tunnel entirely, for as long as the process runs - not fail loudly, not retry, just silently misroute.

Fix: on a DNAT failure, call sshConn.ClosePortTunnel to roll back the just-opened tunnel, so the next packet gets a clean, fresh OpenTunnel+addDNATRulesFunc attempt instead.

2. Cooldown-suppressed dial failures were indistinguishable from fresh ones in the logs

sshConnections.connection()'s 5s sshRetryCooldown deliberately fails every packet on the pool without even attempting a fresh dial while a previous failure is still within the cooldown window. I want to be upfront that I don't think this is itself a bug to fix: the pool has exactly one shared SSH connection, so once it's down every destination behind it is genuinely, equally unreachable - and retrying the full (up to sshDefaultTimeout-bounded) handshake on every single packet during an outage would stall this queue's single-threaded read loop far longer than a fast, clean drop. What was a real gap: both cases (a genuine fresh-attempt failure, and a cooldown-suppressed one) logged an identical message, so an operator watching logs during an outage couldn't tell whether nfq_forwarder was still actively retrying or had backed off.

Fix: a new errDialSuppressedByCooldown sentinel wraps the cached error on the suppressed path, letting getNfCallback log it distinctly (log.Infof, expected backoff behaviour) from a genuine fresh failure (log.Errorf).

Testing

TestGetNfCallbackDNATFailureClosesOrphanedTunnel (renamed from ...Drops) asserts sshConn.ListTunnels() is empty after a failed DNAT insertion.
TestSSHConnectionsDialFailureCachedDuringCooldown and the new TestGetNfCallbackCooldownSuppressedDialLogsDistinctly assert the sentinel wraps only the suppressed call's error, and that the two cases log distinctly.
make lint/make test both clean.

Docs

Added a CLAUDE.md Design notes bullet covering both fixes and the reasoning for not changing the cooldown's blast radius itself.

Part of the same investigation as #4 (v1.1.1) and #32 (v1.1.2). Last ticket in the agreed order: #33 (NfQeueue verdicts always target queue 0 - likely moot for the primary path after #4's fix, worth auditing any other call sites).

Closes #31 ## Background Found while investigating #4. The ticket originally focused on three unconditional `NfDrop`-with-no-retry paths in `getNfCallback`, plus the 5s `sshRetryCooldown` blanket-dropping packets for every destination sharing an SSH connection pool. Digging into these turned up two genuinely distinct, independently-worth-fixing issues: ### 1. A failed DNAT insertion leaves an orphaned, silently-unencrypted tunnel (the more severe finding) `getNfCallback` calls `sshConn.OpenTunnel` (which registers the tunnel and starts its local listener) *before* calling `addDNATRulesFunc`. If the DNAT insert then fails, the code dropped the current packet but never rolled the tunnel back - it stayed registered as "open". Every *later* packet to that same destination would then hit `sshtunnel.ErrPortTunnelAlreadyOpen` and get verdicted `NfAccept` (issue #4's mechanism, correctly assuming a DNAT rule already exists for an already-open tunnel) - except no DNAT rule was ever successfully inserted. The result: traffic to that destination would silently flow out **unencrypted, direct to the real destination**, bypassing the tunnel entirely, for as long as the process runs - not fail loudly, not retry, just silently misroute. **Fix**: on a DNAT failure, call `sshConn.ClosePortTunnel` to roll back the just-opened tunnel, so the next packet gets a clean, fresh `OpenTunnel`+`addDNATRulesFunc` attempt instead. ### 2. Cooldown-suppressed dial failures were indistinguishable from fresh ones in the logs `sshConnections.connection()`'s 5s `sshRetryCooldown` deliberately fails *every* packet on the pool without even attempting a fresh dial while a previous failure is still within the cooldown window. I want to be upfront that I don't think this is itself a bug to fix: the pool has exactly one shared SSH connection, so once it's down every destination behind it is genuinely, equally unreachable - and retrying the full (up to `sshDefaultTimeout`-bounded) handshake on every single packet during an outage would stall this queue's single-threaded read loop far longer than a fast, clean drop. What *was* a real gap: both cases (a genuine fresh-attempt failure, and a cooldown-suppressed one) logged an identical message, so an operator watching logs during an outage couldn't tell whether nfq_forwarder was still actively retrying or had backed off. **Fix**: a new `errDialSuppressedByCooldown` sentinel wraps the cached error on the suppressed path, letting `getNfCallback` log it distinctly (`log.Infof`, expected backoff behaviour) from a genuine fresh failure (`log.Errorf`). ## Testing - `TestGetNfCallbackDNATFailureClosesOrphanedTunnel` (renamed from `...Drops`) asserts `sshConn.ListTunnels()` is empty after a failed DNAT insertion. - `TestSSHConnectionsDialFailureCachedDuringCooldown` and the new `TestGetNfCallbackCooldownSuppressedDialLogsDistinctly` assert the sentinel wraps only the suppressed call's error, and that the two cases log distinctly. - `make lint`/`make test` both clean. ## Docs Added a `CLAUDE.md` Design notes bullet covering both fixes and the reasoning for *not* changing the cooldown's blast radius itself. ## Related Part of the same investigation as #4 (v1.1.1) and #32 (v1.1.2). Last ticket in the agreed order: #33 (`NfQeueue` verdicts always target queue 0 - likely moot for the primary path after #4's fix, worth auditing any other call sites).