diff --git a/labsim/labsim-pppoe-ha-test.sh b/labsim/labsim-pppoe-ha-test.sh index c63eb2d..87669b1 100755 --- a/labsim/labsim-pppoe-ha-test.sh +++ b/labsim/labsim-pppoe-ha-test.sh @@ -106,7 +106,10 @@ preflight() { fail "$h has no /etc/ppp/peers/pppoe0 -- it cannot dial; re-commit the pppoe subtree" rc=1 fi - if ! r "$h" 'show configuration commands' 2>/dev/null | grep -q 'interfaces pppoe pppoe0 source-interface'; then + # The op-mode WRAPPER, not a bare `show`: over non-interactive ssh the + # bare form is not on PATH, so this silently matched nothing and failed + # both routers that were in fact configured correctly. + if ! r "$h" '/opt/vyatta/bin/vyatta-op-cmd-wrapper show configuration commands' 2>/dev/null | grep -q 'interfaces pppoe pppoe0 source-interface'; then fail "$h has no pppoe0 in config (unsaved commit lost on reboot?)" rc=1 fi diff --git a/labsim/wan-failover-evidence/T0-baseline/state.txt b/labsim/wan-failover-evidence/T0-baseline/state.txt index 9d409a1..41b1b32 100644 --- a/labsim/wan-failover-evidence/T0-baseline/state.txt +++ b/labsim/wan-failover-evidence/T0-baseline/state.txt @@ -1,27 +1,27 @@ -=== 2026-09-05T19:07:59+01:00 === +=== 2026-09-06T00:06:00+01:00 === --- AC sessions --- ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes --------+----------+----------------+-----+--------+-------------------+------------+--------+----------+----------+---------- - ppp0 | simdsl | 198.51.100.117 | | | 52:54:00:e5:95:a2 | | active | 00:01:31 | 1.0 KiB | 792 B + ppp0 | simdsl | 198.51.100.123 | | | 52:54:00:4e:0b:56 | | active | 00:03:19 | 438 B | 204 B --- 172.31.1.252 --- -vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes lease_age=0 dropin=yes role=master -pppoe0 UNKNOWN 198.51.100.117 peer 198.51.100.1/32 -default via 203.0.113.1 dev bond0.53 proto failover metric 1 -Sep 05 18:01:26 apitest vrrp-wan[2994197]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:01:30 apitest vrrp-wan[2995085]: bond0.53 disable commit took 4s -Sep 05 18:03:25 apitest vrrp-wan[3000708]: MASTER: dialling pppoe0 -Sep 05 18:03:25 apitest vrrp-wan[3000872]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:03:29 apitest vrrp-wan[3001568]: bond0.53 enable commit took 4s -Sep 05 18:05:43 apitest vrrp-wan[3005097]: GUARD: lease stale (204s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup Sep 05 18:05:53 apitest vrrp-wan[3005490]: MASTER: dialling pppoe0 Sep 05 18:06:24 apitest vrrp-wan[3007095]: MASTER: dialling pppoe0 +Sep 05 18:08:15 apitest vrrp-wan[3010461]: not MASTER: hanging up pppoe0 +Sep 05 18:08:16 apitest vrrp-wan[3010622]: not MASTER but bond0.53 enabled -> releasing +Sep 05 18:08:40 apitest vrrp-wan[3012085]: bond0.53 disable commit took 24s +Sep 05 18:11:42 apitest vrrp-wan[3016900]: MASTER: dialling pppoe0 +Sep 05 18:11:42 apitest vrrp-wan[3017050]: MASTER with bond0.53 disabled -> enabling +Sep 05 18:11:46 apitest vrrp-wan[3017685]: bond0.53 enable commit took 4s --- 172.31.1.253 --- -vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup -Sep 05 17:57:52 vyos vrrp-wan[2797572]: not MASTER but bond0.53 enabled -> releasing -Sep 05 17:58:16 vyos vrrp-wan[2798935]: bond0.53 disable commit took 24s -Sep 05 18:01:03 vyos vrrp-wan[2802338]: MASTER: dialling pppoe0 -Sep 05 18:01:03 vyos vrrp-wan[2802489]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:01:07 vyos vrrp-wan[2803365]: bond0.53 enable commit took 4s -Sep 05 18:03:02 vyos vrrp-wan[2808661]: not MASTER: hanging up pppoe0 -Sep 05 18:03:02 vyos vrrp-wan[2808822]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:03:26 vyos vrrp-wan[2810178]: bond0.53 disable commit took 24s +vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes lease_age=10 dropin=yes role=master +pppoe0 UNKNOWN 198.51.100.123 peer 198.51.100.1/32 +default nhid 93 dev pppoe0 proto static metric 20 +Sep 05 22:54:48 vyos vrrp-wan[193770]: MASTER: dialling pppoe0 +Sep 05 22:55:18 vyos vrrp-wan[194885]: MASTER: dialling pppoe0 +Sep 05 22:55:49 vyos vrrp-wan[195925]: MASTER: dialling pppoe0 +Sep 05 22:56:19 vyos vrrp-wan[196724]: DIAL FLAP: >=6 attempts in 600s -- holding off 900s +Sep 05 22:57:24 vyos vrrp-wan[199011]: MASTER with bond0.53 disabled -> enabling +Sep 05 22:57:28 vyos vrrp-wan[199711]: bond0.53 enable commit took 4s +Sep 05 22:57:40 vyos vrrp-wan[199948]: GUARD: lease stale (81s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:02:41 vyos vrrp-wan[206596]: MASTER: dialling pppoe0 diff --git a/labsim/wan-failover-evidence/T11-no-peers-file/state.txt b/labsim/wan-failover-evidence/T11-no-peers-file/state.txt index c44f228..4ab41ec 100644 --- a/labsim/wan-failover-evidence/T11-no-peers-file/state.txt +++ b/labsim/wan-failover-evidence/T11-no-peers-file/state.txt @@ -1,25 +1,26 @@ -=== 2026-09-05T19:10:28+01:00 === +=== 2026-09-06T00:08:14+01:00 === --- AC sessions --- - ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes ---------+----------+----+-----+--------+-------------+------------+-------+--------+----------+---------- + ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes +--------+----------+----+-----+--------+-------------------+------------+-------+----------+----------+---------- + | | | | | 52:54:00:e5:95:a2 | | start | 00:00:00 | 0 B | 0 B --- 172.31.1.252 --- -vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup -Sep 05 18:03:25 apitest vrrp-wan[3000872]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:03:29 apitest vrrp-wan[3001568]: bond0.53 enable commit took 4s -Sep 05 18:05:43 apitest vrrp-wan[3005097]: GUARD: lease stale (204s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 -Sep 05 18:05:53 apitest vrrp-wan[3005490]: MASTER: dialling pppoe0 -Sep 05 18:06:24 apitest vrrp-wan[3007095]: MASTER: dialling pppoe0 -Sep 05 18:08:15 apitest vrrp-wan[3010461]: not MASTER: hanging up pppoe0 -Sep 05 18:08:16 apitest vrrp-wan[3010622]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:08:40 apitest vrrp-wan[3012085]: bond0.53 disable commit took 24s +vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=no ppp_up=no ppp_active=yes may_dial=yes lease_age=1 dropin=yes role=master +Sep 05 18:11:42 apitest vrrp-wan[3017050]: MASTER with bond0.53 disabled -> enabling +Sep 05 18:11:46 apitest vrrp-wan[3017685]: bond0.53 enable commit took 4s +-- Boot 7cb878bdb4c74380ae7869ffd0dad9eb -- +Sep 05 23:06:18 apitest vrrp-wan[18533]: MASTER: dialling pppoe0 +Sep 05 23:06:18 apitest vrrp-wan[18704]: MASTER with bond0.53 disabled -> enabling +Sep 05 23:06:22 apitest vrrp-wan[19398]: bond0.53 enable commit took 4s +Sep 05 23:07:35 apitest vrrp-wan[22111]: GUARD: lease stale (206s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:07:43 apitest vrrp-wan[22667]: MASTER: dialling pppoe0 +Sep 05 23:08:14 apitest vrrp-wan[24120]: MASTER: dialling pppoe0 --- 172.31.1.253 --- -vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=no ppp_active=yes may_dial=yes lease_age=0 dropin=yes role=master -default via 203.0.113.1 dev bond0.53 proto failover metric 1 -Sep 05 18:03:02 vyos vrrp-wan[2808822]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:03:26 vyos vrrp-wan[2810178]: bond0.53 disable commit took 24s -Sep 05 18:07:53 vyos vrrp-wan[2815869]: MASTER: dialling pppoe0 -Sep 05 18:07:53 vyos vrrp-wan[2816022]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:07:57 vyos vrrp-wan[2816731]: bond0.53 enable commit took 4s -Sep 05 18:09:10 vyos vrrp-wan[2819736]: GUARD: lease stale (204s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 -Sep 05 18:09:34 vyos vrrp-wan[2820820]: MASTER: dialling pppoe0 -Sep 05 18:10:04 vyos vrrp-wan[2821942]: MASTER: dialling pppoe0 +vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup +Sep 05 22:56:19 vyos vrrp-wan[196724]: DIAL FLAP: >=6 attempts in 600s -- holding off 900s +Sep 05 22:57:24 vyos vrrp-wan[199011]: MASTER with bond0.53 disabled -> enabling +Sep 05 22:57:28 vyos vrrp-wan[199711]: bond0.53 enable commit took 4s +Sep 05 22:57:40 vyos vrrp-wan[199948]: GUARD: lease stale (81s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:02:41 vyos vrrp-wan[206596]: MASTER: dialling pppoe0 +Sep 05 23:06:17 vyos vrrp-wan[213698]: not MASTER: hanging up pppoe0 +Sep 05 23:06:18 vyos vrrp-wan[213859]: not MASTER but bond0.53 enabled -> releasing +Sep 05 23:06:23 vyos vrrp-wan[214503]: bond0.53 disable commit took 5s diff --git a/labsim/wan-failover-evidence/T12-holdoff-keeps-session/state.txt b/labsim/wan-failover-evidence/T12-holdoff-keeps-session/state.txt new file mode 100644 index 0000000..777ffdb --- /dev/null +++ b/labsim/wan-failover-evidence/T12-holdoff-keeps-session/state.txt @@ -0,0 +1,28 @@ +=== 2026-09-06T00:10:11+01:00 === +--- AC sessions --- + ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes +--------+----------+----------------+-----+--------+-------------------+------------+--------+----------+----------+---------- + ppp0 | simdsl | 198.51.100.126 | | | 52:54:00:e5:95:a2 | | active | 00:01:57 | 514 B | 204 B +--- 172.31.1.252 --- +vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=no ppp_up=yes ppp_active=yes may_dial=yes lease_age=23 dropin=yes role=master +pppoe0 UNKNOWN 198.51.100.126 peer 198.51.100.1/32 +default nhid 78 dev pppoe0 proto static metric 20 +Sep 05 18:11:42 apitest vrrp-wan[3017050]: MASTER with bond0.53 disabled -> enabling +Sep 05 18:11:46 apitest vrrp-wan[3017685]: bond0.53 enable commit took 4s +-- Boot 7cb878bdb4c74380ae7869ffd0dad9eb -- +Sep 05 23:06:18 apitest vrrp-wan[18533]: MASTER: dialling pppoe0 +Sep 05 23:06:18 apitest vrrp-wan[18704]: MASTER with bond0.53 disabled -> enabling +Sep 05 23:06:22 apitest vrrp-wan[19398]: bond0.53 enable commit took 4s +Sep 05 23:07:35 apitest vrrp-wan[22111]: GUARD: lease stale (206s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:07:43 apitest vrrp-wan[22667]: MASTER: dialling pppoe0 +Sep 05 23:08:14 apitest vrrp-wan[24120]: MASTER: dialling pppoe0 +--- 172.31.1.253 --- +vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup +Sep 05 22:56:19 vyos vrrp-wan[196724]: DIAL FLAP: >=6 attempts in 600s -- holding off 900s +Sep 05 22:57:24 vyos vrrp-wan[199011]: MASTER with bond0.53 disabled -> enabling +Sep 05 22:57:28 vyos vrrp-wan[199711]: bond0.53 enable commit took 4s +Sep 05 22:57:40 vyos vrrp-wan[199948]: GUARD: lease stale (81s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:02:41 vyos vrrp-wan[206596]: MASTER: dialling pppoe0 +Sep 05 23:06:17 vyos vrrp-wan[213698]: not MASTER: hanging up pppoe0 +Sep 05 23:06:18 vyos vrrp-wan[213859]: not MASTER but bond0.53 enabled -> releasing +Sep 05 23:06:23 vyos vrrp-wan[214503]: bond0.53 disable commit took 5s diff --git a/labsim/wan-failover-evidence/T3-clean-failover/state.txt b/labsim/wan-failover-evidence/T3-clean-failover/state.txt index e0ce455..60988a4 100644 --- a/labsim/wan-failover-evidence/T3-clean-failover/state.txt +++ b/labsim/wan-failover-evidence/T3-clean-failover/state.txt @@ -1,28 +1,28 @@ -=== 2026-09-05T19:08:34+01:00 === +=== 2026-09-06T00:06:31+01:00 === --- AC sessions --- ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes --------+----------+----------------+-----+--------+-------------------+------------+--------+----------+----------+---------- - ppp0 | simdsl | 198.51.100.118 | | | 52:54:00:4e:0b:56 | | active | 00:00:15 | 590 B | 280 B + ppp0 | simdsl | 198.51.100.124 | | | 52:54:00:e5:95:a2 | | active | 00:00:13 | 514 B | 204 B --- 172.31.1.252 --- -vip=172.31.1.1 holds_vip=no wan_disabled=no wan_up=yes ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup +vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes lease_age=3 dropin=yes role=master +pppoe0 UNKNOWN 198.51.100.124 peer 198.51.100.1/32 default via 203.0.113.1 dev bond0.53 proto failover metric 1 -Sep 05 18:03:25 apitest vrrp-wan[3000708]: MASTER: dialling pppoe0 -Sep 05 18:03:25 apitest vrrp-wan[3000872]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:03:29 apitest vrrp-wan[3001568]: bond0.53 enable commit took 4s -Sep 05 18:05:43 apitest vrrp-wan[3005097]: GUARD: lease stale (204s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 -Sep 05 18:05:53 apitest vrrp-wan[3005490]: MASTER: dialling pppoe0 -Sep 05 18:06:24 apitest vrrp-wan[3007095]: MASTER: dialling pppoe0 -Sep 05 18:08:15 apitest vrrp-wan[3010461]: not MASTER: hanging up pppoe0 Sep 05 18:08:16 apitest vrrp-wan[3010622]: not MASTER but bond0.53 enabled -> releasing +Sep 05 18:08:40 apitest vrrp-wan[3012085]: bond0.53 disable commit took 24s +Sep 05 18:11:42 apitest vrrp-wan[3016900]: MASTER: dialling pppoe0 +Sep 05 18:11:42 apitest vrrp-wan[3017050]: MASTER with bond0.53 disabled -> enabling +Sep 05 18:11:46 apitest vrrp-wan[3017685]: bond0.53 enable commit took 4s +-- Boot 7cb878bdb4c74380ae7869ffd0dad9eb -- +Sep 05 23:06:18 apitest vrrp-wan[18533]: MASTER: dialling pppoe0 +Sep 05 23:06:18 apitest vrrp-wan[18704]: MASTER with bond0.53 disabled -> enabling +Sep 05 23:06:22 apitest vrrp-wan[19398]: bond0.53 enable commit took 4s --- 172.31.1.253 --- -vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes lease_age=13 dropin=yes role=master -pppoe0 UNKNOWN 198.51.100.118 peer 198.51.100.1/32 -default via 203.0.113.1 dev bond0.53 proto failover metric 1 -Sep 05 18:01:03 vyos vrrp-wan[2802489]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:01:07 vyos vrrp-wan[2803365]: bond0.53 enable commit took 4s -Sep 05 18:03:02 vyos vrrp-wan[2808661]: not MASTER: hanging up pppoe0 -Sep 05 18:03:02 vyos vrrp-wan[2808822]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:03:26 vyos vrrp-wan[2810178]: bond0.53 disable commit took 24s -Sep 05 18:07:53 vyos vrrp-wan[2815869]: MASTER: dialling pppoe0 -Sep 05 18:07:53 vyos vrrp-wan[2816022]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:07:57 vyos vrrp-wan[2816731]: bond0.53 enable commit took 4s +vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup +Sep 05 22:56:19 vyos vrrp-wan[196724]: DIAL FLAP: >=6 attempts in 600s -- holding off 900s +Sep 05 22:57:24 vyos vrrp-wan[199011]: MASTER with bond0.53 disabled -> enabling +Sep 05 22:57:28 vyos vrrp-wan[199711]: bond0.53 enable commit took 4s +Sep 05 22:57:40 vyos vrrp-wan[199948]: GUARD: lease stale (81s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:02:41 vyos vrrp-wan[206596]: MASTER: dialling pppoe0 +Sep 05 23:06:17 vyos vrrp-wan[213698]: not MASTER: hanging up pppoe0 +Sep 05 23:06:18 vyos vrrp-wan[213859]: not MASTER but bond0.53 enabled -> releasing +Sep 05 23:06:23 vyos vrrp-wan[214503]: bond0.53 disable commit took 5s diff --git a/labsim/wan-failover-evidence/T4-hard-failover-replace/state.txt b/labsim/wan-failover-evidence/T4-hard-failover-replace/state.txt index 14ca0e8..8a2fb10 100644 --- a/labsim/wan-failover-evidence/T4-hard-failover-replace/state.txt +++ b/labsim/wan-failover-evidence/T4-hard-failover-replace/state.txt @@ -1,17 +1,18 @@ -=== hard failover, session-control=replace, 2026-09-05T19:20:56+01:00 === -master labsim-vyos2 (172.31.1.253) destroyed with virsh destroy -- no PADT sent. - --- survivor took over and dialled -- - 172.31.1.252 holds_vip=yes wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes role=master - --- AC: exactly one session throughout, from the survivor's MAC -- - ppp0 simdsl 198.51.100.121 calling-sid 52:54:00:e5:95:a2 active 00:07:01 - --- returning router did NOT dial on boot (the gate) -- - ConditionResult=no ActiveState=inactive NRestarts=0 pppoe0 absent may_dial=no - AC session count after its return: 1 - --- caveat -- - A VM restart recreates its taps, leaving the OVS bond holding stale members - (lacp dead, VLAN 1 unreachable). Re-bonded via ovs_bond_router; the harness - now does this automatically after virsh start. +=== 2026-09-06T00:11:13+01:00 === +--- AC sessions --- + ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes +--------+----------+----------------+-----+--------+-------------------+------------+--------+----------+----------+---------- + ppp0 | simdsl | 198.51.100.127 | | | 52:54:00:4e:0b:56 | | active | 00:00:30 | 514 B | 204 B +--- 172.31.1.252 --- +--- 172.31.1.253 --- +vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes lease_age=10 dropin=yes role=master +pppoe0 UNKNOWN 198.51.100.127 peer 198.51.100.1/32 +default nhid 110 dev pppoe0 proto static metric 20 +Sep 05 22:57:40 vyos vrrp-wan[199948]: GUARD: lease stale (81s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:02:41 vyos vrrp-wan[206596]: MASTER: dialling pppoe0 +Sep 05 23:06:17 vyos vrrp-wan[213698]: not MASTER: hanging up pppoe0 +Sep 05 23:06:18 vyos vrrp-wan[213859]: not MASTER but bond0.53 enabled -> releasing +Sep 05 23:06:23 vyos vrrp-wan[214503]: bond0.53 disable commit took 5s +Sep 05 23:10:43 vyos vrrp-wan[221064]: MASTER: dialling pppoe0 +Sep 05 23:10:44 vyos vrrp-wan[221212]: MASTER with bond0.53 disabled -> enabling +Sep 05 23:10:48 vyos vrrp-wan[221995]: bond0.53 enable commit took 4s diff --git a/labsim/wan-failover-evidence/T5-tengig-down/state.txt b/labsim/wan-failover-evidence/T5-tengig-down/state.txt index 8261bb1..2dd227d 100644 --- a/labsim/wan-failover-evidence/T5-tengig-down/state.txt +++ b/labsim/wan-failover-evidence/T5-tengig-down/state.txt @@ -1,27 +1,28 @@ -=== 2026-09-05T19:09:05+01:00 === +=== 2026-09-06T00:07:02+01:00 === --- AC sessions --- ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes --------+----------+----------------+-----+--------+-------------------+------------+--------+----------+----------+---------- - ppp0 | simdsl | 198.51.100.118 | | | 52:54:00:4e:0b:56 | | active | 00:00:46 | 758 B | 448 B + ppp0 | simdsl | 198.51.100.124 | | | 52:54:00:e5:95:a2 | | active | 00:00:44 | 682 B | 372 B --- 172.31.1.252 --- -vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup -Sep 05 18:03:25 apitest vrrp-wan[3000872]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:03:29 apitest vrrp-wan[3001568]: bond0.53 enable commit took 4s -Sep 05 18:05:43 apitest vrrp-wan[3005097]: GUARD: lease stale (204s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 -Sep 05 18:05:53 apitest vrrp-wan[3005490]: MASTER: dialling pppoe0 -Sep 05 18:06:24 apitest vrrp-wan[3007095]: MASTER: dialling pppoe0 -Sep 05 18:08:15 apitest vrrp-wan[3010461]: not MASTER: hanging up pppoe0 +vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes lease_age=3 dropin=yes role=master +pppoe0 UNKNOWN 198.51.100.124 peer 198.51.100.1/32 +default nhid 67 dev pppoe0 proto static metric 20 Sep 05 18:08:16 apitest vrrp-wan[3010622]: not MASTER but bond0.53 enabled -> releasing Sep 05 18:08:40 apitest vrrp-wan[3012085]: bond0.53 disable commit took 24s +Sep 05 18:11:42 apitest vrrp-wan[3016900]: MASTER: dialling pppoe0 +Sep 05 18:11:42 apitest vrrp-wan[3017050]: MASTER with bond0.53 disabled -> enabling +Sep 05 18:11:46 apitest vrrp-wan[3017685]: bond0.53 enable commit took 4s +-- Boot 7cb878bdb4c74380ae7869ffd0dad9eb -- +Sep 05 23:06:18 apitest vrrp-wan[18533]: MASTER: dialling pppoe0 +Sep 05 23:06:18 apitest vrrp-wan[18704]: MASTER with bond0.53 disabled -> enabling +Sep 05 23:06:22 apitest vrrp-wan[19398]: bond0.53 enable commit took 4s --- 172.31.1.253 --- -vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=yes ppp_active=yes may_dial=yes lease_age=10 dropin=yes role=master -pppoe0 UNKNOWN 198.51.100.118 peer 198.51.100.1/32 -default nhid 483 dev pppoe0 proto static metric 20 -Sep 05 18:01:03 vyos vrrp-wan[2802489]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:01:07 vyos vrrp-wan[2803365]: bond0.53 enable commit took 4s -Sep 05 18:03:02 vyos vrrp-wan[2808661]: not MASTER: hanging up pppoe0 -Sep 05 18:03:02 vyos vrrp-wan[2808822]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:03:26 vyos vrrp-wan[2810178]: bond0.53 disable commit took 24s -Sep 05 18:07:53 vyos vrrp-wan[2815869]: MASTER: dialling pppoe0 -Sep 05 18:07:53 vyos vrrp-wan[2816022]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:07:57 vyos vrrp-wan[2816731]: bond0.53 enable commit took 4s +vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup +Sep 05 22:56:19 vyos vrrp-wan[196724]: DIAL FLAP: >=6 attempts in 600s -- holding off 900s +Sep 05 22:57:24 vyos vrrp-wan[199011]: MASTER with bond0.53 disabled -> enabling +Sep 05 22:57:28 vyos vrrp-wan[199711]: bond0.53 enable commit took 4s +Sep 05 22:57:40 vyos vrrp-wan[199948]: GUARD: lease stale (81s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:02:41 vyos vrrp-wan[206596]: MASTER: dialling pppoe0 +Sep 05 23:06:17 vyos vrrp-wan[213698]: not MASTER: hanging up pppoe0 +Sep 05 23:06:18 vyos vrrp-wan[213859]: not MASTER but bond0.53 enabled -> releasing +Sep 05 23:06:23 vyos vrrp-wan[214503]: bond0.53 disable commit took 5s diff --git a/labsim/wan-failover-evidence/T8-lease-expiry/state.txt b/labsim/wan-failover-evidence/T8-lease-expiry/state.txt index 45b140d..22ea9b0 100644 --- a/labsim/wan-failover-evidence/T8-lease-expiry/state.txt +++ b/labsim/wan-failover-evidence/T8-lease-expiry/state.txt @@ -1,25 +1,26 @@ -=== 2026-09-05T19:09:47+01:00 === +=== 2026-09-06T00:07:44+01:00 === --- AC sessions --- - ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes ---------+----------+----+-----+--------+-------------+------------+-------+--------+----------+---------- + ifname | username | ip | ip6 | ip6-dp | calling-sid | rate-limit | state | uptime | rx-bytes | tx-bytes +--------+----------+----+-----+--------+-------------------+------------+-------+----------+----------+---------- + | | | | | 52:54:00:e5:95:a2 | | start | 00:00:00 | 0 B | 0 B --- 172.31.1.252 --- -vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup -Sep 05 18:03:25 apitest vrrp-wan[3000872]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:03:29 apitest vrrp-wan[3001568]: bond0.53 enable commit took 4s -Sep 05 18:05:43 apitest vrrp-wan[3005097]: GUARD: lease stale (204s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 -Sep 05 18:05:53 apitest vrrp-wan[3005490]: MASTER: dialling pppoe0 -Sep 05 18:06:24 apitest vrrp-wan[3007095]: MASTER: dialling pppoe0 -Sep 05 18:08:15 apitest vrrp-wan[3010461]: not MASTER: hanging up pppoe0 -Sep 05 18:08:16 apitest vrrp-wan[3010622]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:08:40 apitest vrrp-wan[3012085]: bond0.53 disable commit took 24s +vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=no ppp_up=no ppp_active=yes may_dial=yes lease_age=2 dropin=yes role=master +Sep 05 18:11:42 apitest vrrp-wan[3016900]: MASTER: dialling pppoe0 +Sep 05 18:11:42 apitest vrrp-wan[3017050]: MASTER with bond0.53 disabled -> enabling +Sep 05 18:11:46 apitest vrrp-wan[3017685]: bond0.53 enable commit took 4s +-- Boot 7cb878bdb4c74380ae7869ffd0dad9eb -- +Sep 05 23:06:18 apitest vrrp-wan[18533]: MASTER: dialling pppoe0 +Sep 05 23:06:18 apitest vrrp-wan[18704]: MASTER with bond0.53 disabled -> enabling +Sep 05 23:06:22 apitest vrrp-wan[19398]: bond0.53 enable commit took 4s +Sep 05 23:07:35 apitest vrrp-wan[22111]: GUARD: lease stale (206s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:07:43 apitest vrrp-wan[22667]: MASTER: dialling pppoe0 --- 172.31.1.253 --- -vip=172.31.1.1 holds_vip=yes wan_disabled=no wan_up=yes ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=master -default via 203.0.113.1 dev bond0.53 proto failover metric 1 -Sep 05 18:01:07 vyos vrrp-wan[2803365]: bond0.53 enable commit took 4s -Sep 05 18:03:02 vyos vrrp-wan[2808661]: not MASTER: hanging up pppoe0 -Sep 05 18:03:02 vyos vrrp-wan[2808822]: not MASTER but bond0.53 enabled -> releasing -Sep 05 18:03:26 vyos vrrp-wan[2810178]: bond0.53 disable commit took 24s -Sep 05 18:07:53 vyos vrrp-wan[2815869]: MASTER: dialling pppoe0 -Sep 05 18:07:53 vyos vrrp-wan[2816022]: MASTER with bond0.53 disabled -> enabling -Sep 05 18:07:57 vyos vrrp-wan[2816731]: bond0.53 enable commit took 4s -Sep 05 18:09:10 vyos vrrp-wan[2819736]: GUARD: lease stale (204s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +vip=172.31.1.1 holds_vip=no wan_disabled=yes wan_up=no ppp_up=no ppp_active=no may_dial=no lease_age=- dropin=yes role=backup +Sep 05 22:56:19 vyos vrrp-wan[196724]: DIAL FLAP: >=6 attempts in 600s -- holding off 900s +Sep 05 22:57:24 vyos vrrp-wan[199011]: MASTER with bond0.53 disabled -> enabling +Sep 05 22:57:28 vyos vrrp-wan[199711]: bond0.53 enable commit took 4s +Sep 05 22:57:40 vyos vrrp-wan[199948]: GUARD: lease stale (81s > 75s; is vrrp-wan-reconcile.timer running?) -- hanging up pppoe0 +Sep 05 23:02:41 vyos vrrp-wan[206596]: MASTER: dialling pppoe0 +Sep 05 23:06:17 vyos vrrp-wan[213698]: not MASTER: hanging up pppoe0 +Sep 05 23:06:18 vyos vrrp-wan[213859]: not MASTER but bond0.53 enabled -> releasing +Sep 05 23:06:23 vyos vrrp-wan[214503]: bond0.53 disable commit took 5s diff --git a/migration/PPPOE-HA.md b/migration/PPPOE-HA.md index d170434..c772a57 100644 --- a/migration/PPPOE-HA.md +++ b/migration/PPPOE-HA.md @@ -62,12 +62,45 @@ either "I do not hold the VIP" or "the lease is stale". | | | |---|---| -| Clean failover (`force-fault`) | `pppoe0` moves in **26s**, reproducible | +| Clean failover (`force-fault`) | `pppoe0` moves in **20-26s**, reproducible | | 10 gig down → PPPoE | route falls to `pppoe0`; LAN back online in **5s** | | Stale lease | guard hangs up within ~5s | | Missing peers file | `NRestarts=0` — no loop | +| Flap holdoff vs live session | session survives a forged 900s holdoff | | Invariant | AC never showed two `simdsl` sessions | +## Two failure modes found by running it, not by reading it + +**The flap damper tore down a healthy WAN.** `ppp_dial()` checked the hold-off +and returned *before* renewing `may-dial`. That file is a lease the guard +expires after `LEASE_TTL`, so tripping the damper stopped the renewal and the +guard hung up `pppoe0` **on the master** ~80s later: + +``` +DIAL FLAP: >=6 attempts in 600s -- holding off 900s +GUARD: lease stale (81s > 75s) -- hanging up pppoe0 +``` + +A damper meant to suppress repeated *dials* was destroying an established +session instead. An active session now renews the lease and returns before +every other check; everything below only decides whether to start a **new** +session. T12 is the regression test. + +**A missing peers file is silent.** `/etc/ppp/peers/pppoe0` is both pppd's +options file and the gate's second condition, and it is only written by a commit +that touches the pppoe subtree. Without it systemd logs +`skipped because of an unmet condition check` exactly once and then nothing — +a router that cannot dial at all looks identical to a healthy backup. +`ppp_dial()` now says so on every tick, and distinguishes the two causes: +configured-but-not-rendered (re-commit the subtree) versus no `pppoe0` in the +config at all. + +The second cause is the one to watch in production: **a commit that was never +`save`d reverts on reboot and takes `pppoe0` with it.** That is exactly how the +sim secondary lost its WAN and spent hours looking like an ISP problem. After +any hand commit to the pppoe subtree, `save` — or the next reboot produces a +standby that can never take over. + ## Deploying (not yet done) 1. `sudo /config/vyos-known-good save` on both.