Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    Pre bug report check: Loss of v4 address after ppp IPV6CP LayerDown event

    General pfSense Questions
    2
    8
    205
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • S
      StrixTechnica
      last edited by

      I'm losing my IPv4 address after a mishap involving IPv6 assignment during ppp bring-up similar to what @MrHedgehog described in this post last September — and I think I know why but I thought it best to check here before filing a bug report on Redgate.

      Hopefully, someone can make a suggestion about how best to work around it until fixed properly or point to a configuration mistake on my part, as may be appropriate.

      Router is a Netgate SG-4200 running pfSense plus 24.11. mpd is version 5.9.

      The observable symptoms are similar to what @MrHedgehog reported, though causes may differ: v4 address is assigned, a v6 interface identifier is negotiated (mpd IPV6CP FSM transitions from Ack-Rcvd --> Opened), and mpd emits an IPV6CP: LayerUp event. After 4-5 seconds, the peer then retransmits a IPV6CP Configure Request with the same serial number despite that sequence number already having been acknowledged.

      Because mpd is now in state Opened, it decides something has gone wrong, emits an IPV6CP: LayerDown event, re-Ack's the original IPV6CP Config Request (again) and retries SendConfigReq with a new serial number. This succeeds and system.log indicates receipt of RA routes and normal restart of packages, but the IPv4 address has gone and, 5 seconds later, system.log records a gateway alarm with 28% packet loss to the v4 gateway.

      Assumption 1: the IPV6CP: LayerDown event causes mpd to invoke down-script /usr/local/sbin/ppp-linkdown as defined in /var/etc/mpd_wan.conf. This contains:

      if [ "${PROTOCOL}" == "inet6" ]; then
        /usr/local/sbin/ppp-ipv6 ${IF} down
fi
# delete the node just in case mpd cannot do that
/usr/sbin/ngctl shutdown ${IF}:

      Assumption 2: ngctl shutdown kills all state, including pppoe0's v4 address, but mpd doesn't know this, doesn't update IPCP state and therefore never attempts to renegotiate its v4 configuration.

      Given that ngctl shutdown desynchronises link state (and the system doesn't notice the change/lack of v4 address either), I'd argue it shouldn't be there but, if it must be, then one solution would be to check to see whether ${IF} has an inet address.

      As a temporary work-around, perhaps it's sufficient just to comment out the ngctl shutdown line (which will prove that that's the culprit), especially if it's only there "just in case" as the comment suggests.

      It'd be great if someone could confirm those two assumptions or tell me what I've misunderstood. Meanwhile, here are some log excerpts:

      ppp.log: fail case, IPV6CP-related entries only
      Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: Open event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Initial --> Starting
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: LayerStart
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: Up event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Starting --> Req-Sent
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: SendConfigReq #3
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Ack #3 (Req-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Rcvd)
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: SendConfigAck #0
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: state change Ack-Rcvd --> Opened
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: LayerUp
Mar 17 02:00:38 gw ppp[3716]: [wan]   92ec:77ff:fe90:18e3 -> 9e89:1eff:fe2c:0000
Mar 17 02:00:42 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Request #0 (Opened)
Mar 17 02:00:42 gw ppp[3716]: [wan] IPV6CP: LayerDown
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: SendConfigReq #4
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: SendConfigAck #0
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: state change Opened --> Ack-Sent
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Ack #4 (Ack-Sent)
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: state change Ack-Sent --> Opened
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: LayerUp
Mar 17 02:00:45 gw ppp[3716]: [wan]   92ec:77ff:fe90:18e3 -> 9e89:1eff:fe2c:0000
      Full ppp.log: fail case
      Mar 17 02:00:37 gw ppp[3716]: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: Open event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Initial --> Starting
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: LayerStart
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: Open event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Initial --> Starting
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: LayerStart
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: Up event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Starting --> Req-Sent
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigReq #5
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: Up event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Starting --> Req-Sent
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: SendConfigReq #3
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Request #0 (Req-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.gw
Mar 17 02:00:37 gw ppp[3716]: [wan]     x.x.x.gw is OK
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigAck #0
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.gw
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Req-Sent --> Ack-Sent
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Reject #5 (Ack-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigReq #6
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Ack #3 (Req-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Nak #6 (Ack-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.wan
Mar 17 02:00:37 gw ppp[3716]: [wan]     x.x.x.wan is OK
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS x.x.x.dns1
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS x.x.x.dns2
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigReq #7
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.wan
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS x.x.x.dns1
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS x.x.x.dns2
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Ack #7 (Ack-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.wan
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS x.x.x.dns1
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS x.x.x.dns2
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Ack-Sent --> Opened
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: LayerUp
Mar 17 02:00:37 gw ppp[3716]: [wan]   x.x.x.wan -> x.x.x.gw
Mar 17 02:00:38 gw ppp[3716]: [wan] IFACE: Up event
Mar 17 02:00:38 gw ppp[3716]: [wan] IFACE: Rename interface ng0 to pppoe0
Mar 17 02:00:38 gw ppp[3716]: [wan] IFACE: Add description "WAN"
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Rcvd)
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: SendConfigAck #0
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: state change Ack-Rcvd --> Opened
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: LayerUp
Mar 17 02:00:38 gw ppp[3716]: [wan]   92ec:77ff:fe90:18e3 -> 9e89:1eff:fe2c:0000
Mar 17 02:00:42 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Request #0 (Opened)
Mar 17 02:00:42 gw ppp[3716]: [wan] IPV6CP: LayerDown
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: SendConfigReq #4
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: SendConfigAck #0
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: state change Opened --> Ack-Sent
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Ack #4 (Ack-Sent)
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: state change Ack-Sent --> Opened
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: LayerUp
Mar 17 02:00:45 gw ppp[3716]: [wan]   92ec:77ff:fe90:18e3 -> 9e89:1eff:fe2c:0000
      ppp.log: succeed case
      Mar 17 08:16:51 gw ppp[12843]: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: Open event
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: state change Initial --> Starting
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: LayerStart
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: Open event
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: state change Initial --> Starting
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: LayerStart
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: Up event
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: state change Starting --> Req-Sent
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: SendConfigReq #1
Mar 17 08:16:51 gw ppp[12843]: [wan]   IPADDR 0.0.0.0
Mar 17 08:16:51 gw ppp[12843]: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 17 08:16:51 gw ppp[12843]: [wan]   PRIDNS 0.0.0.0
Mar 17 08:16:51 gw ppp[12843]: [wan]   SECDNS 0.0.0.0
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: Up event
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: state change Starting --> Req-Sent
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: SendConfigReq #1
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: rec'd Configure Request #0 (Req-Sent)
Mar 17 08:16:51 gw ppp[12843]: [wan]   IPADDR x.x.x.gw
Mar 17 08:16:51 gw ppp[12843]: [wan]     x.x.x.gw is OK
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: SendConfigAck #0
Mar 17 08:16:51 gw ppp[12843]: [wan]   IPADDR x.x.x.gw
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: state change Req-Sent --> Ack-Sent
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent)
Mar 17 08:16:51 gw ppp[12843]: [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
Mar 17 08:16:51 gw ppp[12843]: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: SendConfigReq #2
Mar 17 08:16:51 gw ppp[12843]: [wan]   IPADDR 0.0.0.0
Mar 17 08:16:51 gw ppp[12843]: [wan]   PRIDNS 0.0.0.0
Mar 17 08:16:51 gw ppp[12843]: [wan]   SECDNS 0.0.0.0
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Mar 17 08:16:51 gw ppp[12843]: [wan]   IPADDR x.x.x.wan
Mar 17 08:16:51 gw ppp[12843]: [wan]     x.x.x.wan is OK
Mar 17 08:16:51 gw ppp[12843]: [wan]   PRIDNS x.x.x.dns1
Mar 17 08:16:51 gw ppp[12843]: [wan]   SECDNS x.x.x.dns2
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: SendConfigReq #3
Mar 17 08:16:51 gw ppp[12843]: [wan]   IPADDR x.x.x.wan
Mar 17 08:16:51 gw ppp[12843]: [wan]   PRIDNS x.x.x.dns1
Mar 17 08:16:51 gw ppp[12843]: [wan]   SECDNS x.x.x.dns2
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Mar 17 08:16:51 gw ppp[12843]: [wan]   IPADDR x.x.x.wan
Mar 17 08:16:51 gw ppp[12843]: [wan]   PRIDNS x.x.x.dns1
Mar 17 08:16:51 gw ppp[12843]: [wan]   SECDNS x.x.x.dns2
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: state change Ack-Sent --> Opened
Mar 17 08:16:51 gw ppp[12843]: [wan] IPCP: LayerUp
Mar 17 08:16:51 gw ppp[12843]: [wan]   x.x.x.wan -> x.x.x.gw
Mar 17 08:16:52 gw ppp[12843]: [wan] IFACE: Up event
Mar 17 08:16:52 gw ppp[12843]: [wan] IFACE: Rename interface ng0 to pppoe0
Mar 17 08:16:52 gw ppp[12843]: [wan] IFACE: Add description "WAN"
Mar 17 08:16:52 gw ppp[12843]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Rcvd)
Mar 17 08:16:52 gw ppp[12843]: [wan] IPV6CP: SendConfigAck #0
Mar 17 08:16:52 gw ppp[12843]: [wan] IPV6CP: state change Ack-Rcvd --> Opened
Mar 17 08:16:52 gw ppp[12843]: [wan] IPV6CP: LayerUp
Mar 17 08:16:52 gw ppp[12843]: [wan]   92ec:77ff:fe90:18e3 -> 9e89:1eff:fe2c:0000
      system.log: excluding noise from avahi, pfBlockerNG etc
      Mar 17 02:00:37 gw ppp[3716]: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: Open event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Initial --> Starting
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: LayerStart
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: Open event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Initial --> Starting
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: LayerStart
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: Up event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Starting --> Req-Sent
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigReq #5
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: Up event
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Starting --> Req-Sent
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: SendConfigReq #3
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Request #0 (Req-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.gw
Mar 17 02:00:37 gw ppp[3716]: [wan]     x.x.x.gw is OK
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigAck #0
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.gw
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Req-Sent --> Ack-Sent
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Reject #5 (Ack-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigReq #6
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS 0.0.0.0
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Ack #3 (Req-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Nak #6 (Ack-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.wan
Mar 17 02:00:37 gw ppp[3716]: [wan]     x.x.x.wan is OK
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS x.x.x.dns1
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS x.x.x.dns2
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: SendConfigReq #7
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.wan
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS x.x.x.dns1
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS x.x.x.dns2
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: rec'd Configure Ack #7 (Ack-Sent)
Mar 17 02:00:37 gw ppp[3716]: [wan]   IPADDR x.x.x.wan
Mar 17 02:00:37 gw ppp[3716]: [wan]   PRIDNS x.x.x.dns1
Mar 17 02:00:37 gw ppp[3716]: [wan]   SECDNS x.x.x.dns2
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: state change Ack-Sent --> Opened
Mar 17 02:00:37 gw ppp[3716]: [wan] IPCP: LayerUp
Mar 17 02:00:37 gw ppp[3716]: [wan]   x.x.x.wan -> x.x.x.gw
Mar 17 02:00:37 gw check_reload_status[661]: Rewriting resolv.conf
Mar 17 02:00:38 gw check_reload_status[661]: rc.newwanip starting pppoe0
Mar 17 02:00:38 gw ppp[3716]: [wan] IFACE: Up event
Mar 17 02:00:38 gw ppp[3716]: [wan] IFACE: Rename interface ng0 to pppoe0
Mar 17 02:00:38 gw ppp[3716]: [wan] IFACE: Add description "WAN"
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Rcvd)
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: SendConfigAck #0
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: state change Ack-Rcvd --> Opened
Mar 17 02:00:38 gw ppp[3716]: [wan] IPV6CP: LayerUp
Mar 17 02:00:38 gw ppp[3716]: [wan]   92ec:77ff:fe90:18e3 -> 9e89:1eff:fe2c:0000
Mar 17 02:00:38 gw php[77690]: /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0 
Mar 17 02:00:38 gw php[77690]: /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode
Mar 17 02:00:38 gw php[77690]: /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
Mar 17 02:00:39 gw php-fpm[69736]: /rc.newwanip: rc.newwanip: Info: starting on pppoe0.
Mar 17 02:00:39 gw php-fpm[69736]: /rc.newwanip: rc.newwanip: on (IP address: x.x.x.wan) (interface: WAN[wan]) (real interface: pppoe0).
Mar 17 02:00:40 gw php-fpm[73986]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Mar 17 02:00:40 gw php-fpm[73986]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001::wan6) (interface: wan) (real interface: pppoe0).
Mar 17 02:00:41 gw check_reload_status[661]: Rewriting resolv.conf
Mar 17 02:00:41 gw php-fpm[69736]: /rc.newwanip: Default gateway setting Interface WAN_DHCP Gateway as default.
Mar 17 02:00:41 gw rtsold[95665]: Received RA specifying route fe80::wan6 for interface wan(pppoe0)
Mar 17 02:00:41 gw rtsold[96466]: RTSOLD Lock in place - sending SIGHUP to dhcp6c
Mar 17 02:00:42 gw check_reload_status[661]: rc.newwanipv6 starting pppoe0
Mar 17 02:00:42 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Request #0 (Opened)
Mar 17 02:00:42 gw ppp[3716]: [wan] IPV6CP: LayerDown
Mar 17 02:00:43 gw php-fpm[45313]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Mar 17 02:00:43 gw php-fpm[45313]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001::wan6) (interface: wan) (real interface: pppoe0).
Mar 17 02:00:44 gw php-fpm[45313]: /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1742176844] unbound[28279:0] error: bind: address already in use [1742176844] unbound[28279:0] fatal error: could not open ports' 
Mar 17 02:00:44 gw php-fpm[69736]: /rc.newwanip: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1742176844] unbound[29234:0] error: bind: address already in use [1742176844] unbound[29234:0] fatal error: could not open ports' 
Mar 17 02:00:45 gw check_reload_status[661]: Rewriting resolv.conf
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: SendConfigReq #4
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: SendConfigAck #0
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: state change Opened --> Ack-Sent
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: rec'd Configure Ack #4 (Ack-Sent)
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: state change Ack-Sent --> Opened
Mar 17 02:00:45 gw ppp[3716]: [wan] IPV6CP: LayerUp
Mar 17 02:00:45 gw ppp[3716]: [wan]   92ec:77ff:fe90:18e3 -> 9e89:1eff:fe2c:0000
Mar 17 02:00:45 gw php[36307]: /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0 
Mar 17 02:00:45 gw php[36307]: /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode
Mar 17 02:00:45 gw php[36307]: /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
Mar 17 02:00:47 gw php-fpm[17124]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Mar 17 02:00:47 gw php-fpm[17124]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001::wan6) (interface: wan) (real interface: pppoe0).
Mar 17 02:00:47 gw check_reload_status[661]: Rewriting resolv.conf
Mar 17 02:00:48 gw rtsold[52819]: Received RA specifying route fe80::wan6 for interface wan(pppoe0)
Mar 17 02:00:48 gw rtsold[53634]: RTSOLD Lock in place - sending SIGHUP to dhcp6c
Mar 17 02:00:48 gw check_reload_status[661]: rc.newwanipv6 starting pppoe0
Mar 17 02:00:49 gw rc.gateway_alarm[59468]: >>> Gateway alarm: WAN_DHCP (Addr:x.x.x.gw Alarm:1 RTT:10.480ms RTTsd:.528ms Loss:28%)
Mar 17 02:00:49 gw check_reload_status[661]: updating dyndns WAN_DHCP
Mar 17 02:00:49 gw check_reload_status[661]: Restarting IPsec tunnels
Mar 17 02:00:49 gw check_reload_status[661]: Restarting OpenVPN tunnels/interfaces
Mar 17 02:00:49 gw check_reload_status[661]: Reloading filter
Mar 17 02:00:49 gw php-fpm[609]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Mar 17 02:00:49 gw php-fpm[609]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001::wan6) (interface: wan) (real interface: pppoe0).
Mar 17 02:01:22 gw php-fpm[69736]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Mar 17 02:01:22 gw php-fpm[69736]: /rc.newwanip: Creating rrd update script
Mar 17 02:01:24 gw php-fpm[69736]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - x.x.x.wan ->  x.x.x.wan - Restarting packages.
Mar 17 02:01:24 gw check_reload_status[661]: Starting packages
Mar 17 02:01:24 gw check_reload_status[661]: Reloading filter
Mar 17 02:01:24 gw check_reload_status[661]: Reloading filter
Mar 17 02:01:24 gw snmpd[96993]: disk_OS_get_disks: adding device 'da0' to device list
Mar 17 02:01:24 gw snmpd[96993]: disk_OS_get_disks: adding device 'nda0' to device list
Mar 17 02:01:25 gw php-fpm[20730]: /rc.start_packages: Restarting/Starting all packages.
Mar 17 02:01:31 gw ntopng[48722]: 17/Mar/2025 02:01:31 [boot.lua:23] [connectivity_utils.lua:64] WARNING: Connectivity check failed [Used https://github.com]
Mar 17 02:01:31 gw php[74026]: [pfBlockerNG] DNSBL parser daemon started
Mar 17 02:03:47 gw php-fpm[45313]: /rc.newwanipv6: Removing static route for monitor 2001::gw6 and adding a new route through fe80::wan6%pppoe0
Mar 17 02:03:47 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:05 gw php-fpm[73986]: /rc.newwanipv6: Removing static route for monitor 2001::gw6 and adding a new route through fe80::wan6%pppoe0
Mar 17 02:04:05 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:13 gw php-fpm[17124]: /rc.newwanipv6: Removing static route for monitor 2001::gw6 and adding a new route through fe80::wan6%pppoe0
Mar 17 02:04:14 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:31 gw php-fpm[609]: /rc.newwanipv6: Removing static route for monitor 2001::gw6 and adding a new route through fe80::wan6%pppoe0
Mar 17 02:04:32 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:40 gw php-fpm[45313]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
Mar 17 02:04:40 gw php-fpm[45313]: /rc.newwanipv6: Creating rrd update script
Mar 17 02:04:40 gw php-fpm[45313]: /rc.newwanipv6: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection -  -> 2001::wan6 - Restarting packages.
Mar 17 02:04:40 gw check_reload_status[661]: Starting packages
Mar 17 02:04:40 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:40 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:41 gw php-fpm[608]: /rc.start_packages: Restarting/Starting all packages.
Mar 17 02:04:49 gw ntopng[7576]: 17/Mar/2025 02:04:49 [boot.lua:23] [connectivity_utils.lua:64] WARNING: Connectivity check failed [Used https://github.com]
Mar 17 02:04:49 gw php-fpm[73986]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
Mar 17 02:04:49 gw php-fpm[73986]: /rc.newwanipv6: Creating rrd update script
Mar 17 02:04:49 gw php-fpm[73986]: /rc.newwanipv6: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection -  -> 2001::wan6 - Restarting packages.
Mar 17 02:04:49 gw check_reload_status[661]: Starting packages
Mar 17 02:04:49 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:49 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:50 gw php-fpm[20730]: /rc.start_packages: Restarting/Starting all packages.
Mar 17 02:04:57 gw ntopng[6246]: 17/Mar/2025 02:04:57 [boot.lua:23] [connectivity_utils.lua:64] WARNING: Connectivity check failed [Used https://github.com]
Mar 17 02:04:58 gw php-fpm[17124]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
Mar 17 02:04:58 gw php-fpm[17124]: /rc.newwanipv6: Creating rrd update script
Mar 17 02:04:58 gw php-fpm[17124]: /rc.newwanipv6: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection -  -> 2001::wan6 - Restarting packages.
Mar 17 02:04:58 gw check_reload_status[661]: Starting packages
Mar 17 02:04:58 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:58 gw check_reload_status[661]: Reloading filter
Mar 17 02:04:59 gw php-fpm[45313]: /rc.start_packages: Restarting/Starting all packages.
      S 1 Reply Last reply Reply Quote 1
      • stephenw10S
        stephenw10 Netgate Administrator
        last edited by

        If you disable IPv6 entirely does it connect at v4 reliably?

        S 1 Reply Last reply Reply Quote 0
        • S
          StrixTechnica @stephenw10
          last edited by

          If you disable IPv6 entirely does it connect at v4 reliably?

          @stephenw10 last time this happened, which was on an SG-1100 running pfSense 23.09.1-RELEASE, yes, it did. It is only when there is a double IPV6CP request that v4 goes away, presumably because of the the IPV6CP: LayerDown event intervening between the requests.

          The LayerDown message is emitted immediately after receipt of the duplicate IPV6CP config request datagram, which is about 4 or 5 seconds after the original copy was received and ACK'd. Just like before, ifconfig shows the v4 address assigned to the PPPoE interface in that 5-second window before the second IPV6CP datagram is received. There's nothing to upset the v4 address when v6 is disabled.

          I originally configured v6 very late December 2023 but it wasn't until late March 2024 that I first noticed a missing v4 address when a v6 address was present. I disabled v6 in early April until I could find time to diagnose the problem. I re-enabled v6 when I upgraded to an SG4200 to see if the problem would recur, and it has.

          1 Reply Last reply Reply Quote 0
          • S
            StrixTechnica @StrixTechnica
            last edited by

            Update

            Assumption 1: the IPV6CP: LayerDown event causes mpd to invoke down-script /usr/local/sbin/ppp-linkdown as defined in /var/etc/mpd_wan.conf.

            It does, indeed, however—

            Assumption 2: ngctl shutdown kills all state, including pppoe0's v4 address

            —this wasn't the source of the problem. I had the opportunity to do some more digging and the problem turns out to arise a little later in the ppp-linkdown script:

            # cleanup all VIPs, see https://redmine.pfsense.org/issues/11629
while
        aliases=$(/sbin/ifconfig ${IF} | /usr/bin/grep netmask)
        if [ -z "${aliases}" ]; then
                break
        fi
do ifconfig ${IF} -alias ;  done

            This gets executed even when ppp-linkdown is invoked for protocol inet6, and invocation of ifconfig ${IF} -alias removes the IPv4 address, even if it is the only address left on the interface. This seems to be expected behaviour, given the way that loop is written.

            Wrapping it inside a conditional solves the problem:

            if [ ${IF} == "inet" ]; then
        while
                aliases=$(/sbin/ifconfig ${IF} | /usr/bin/grep netmask)
                if [ -z "${aliases}" ]; then
                        break
                fi
        do ifconfig ${IF} -alias ;  done
fi

            On the ISP side, tcpdump reveals that the true sequencing and timing is different from that implied by the logs. I guess is unsurprising given that mpd is only single-threaded.

            In two fail cases, the ISP sends the duplicate IPV6CP Configuration Request 733ms and 979ms after sending the first, where the ACK from mpd is not sent until 1079ms and 1046ms after the first Config Request. That could be a timeout yet, in the two success cases, the ACK is sent after 1041ms and it would be surprising if the timeout were that finely balanced.

            I'm working with the ISP to identify what happened.

            Meanwhile, I shall file a redmine ticket in respect of the ifconfig ${IF} -alias issue.

            S 1 Reply Last reply Reply Quote 1
            • stephenw10S
              stephenw10 Netgate Administrator
              last edited by

              Nice catch! 👍

              S 1 Reply Last reply Reply Quote 0
              • S
                StrixTechnica @stephenw10
                last edited by

                @stephenw10 Thank you!

                1 Reply Last reply Reply Quote 0
                • S
                  StrixTechnica @StrixTechnica
                  last edited by

                  @StrixTechnica said in Pre bug report check: Loss of v4 address after ppp IPV6CP LayerDown event:

                  This should, of course, be:

                  if [ "${PROTOCOL}" = "inet" ]; then
        while
                aliases=$(/sbin/ifconfig "${IF}" | /usr/bin/grep netmask)
                if [ -z "${aliases}" ]; then
                        break
                fi
        do ifconfig "${IF}" -alias; done
fi

                  😊

                  1 Reply Last reply Reply Quote 1
                  • stephenw10S
                    stephenw10 Netgate Administrator
                    last edited by

                    For reference: https://redmine.pfsense.org/issues/16103

                    1 Reply Last reply Reply Quote 0
                    • First post
                      Last post
                    Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.