gif0 does not come up after reboot

stephenw10

Ok, that error is shown if the PPPoE interface is not up at the time. It wasn't on my test box. But I can create a GIF tunnel on a PPPoE interface as long as it's connected and has an IP at that time. And it does then re-establish at boot.
However I tested here with IPv4, it's possible it will refuse to allow a tunnel with a remote IPv6 address even if the PPPoE interface has one. I assume that's the situation you're in?
It's possible your ISP only provides a prefix and the WAN doesn't get a routable v6 IP.

Also I'm testing between local machines which mean the PPP connection estblishes almost instantly at boot so it's possible there is a timing issue. I don't think that is the case though because the GIF tunnel doesn't attempt to establish until the PPPoE is up because it's parent interface is down. The way you have it setup LAN appears to be up to it tries and fails.

What does appear to be a possible bug is that the LAN interface gets a new IP address when the PPPoE comes up and it can track the prefix. But that doesn't trigger the GIF tunnel to restart.
However there are a number of features missing from dynamic IPv6. This is probably one of them.

Anyway I would retry to create the GIF on WAN directly. At least that might give us a different error. I can't easily test an IPv6 PPPoE connection here.

Steve

vex

@stephenw10 Hi Stephen, you're right. The PPPoE interface does not get a routeable address. ifconfig shows:

[2.6.0-RELEASE][admin@pfSense.lan]/root: ifconfig
vtnet0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        description: LAN
        options=800b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,LINKSTATE>
        ether 92:5d:58:1f:81:ff
        inet6 fe80::905d:58ff:fe1f:81ff%vtnet0 prefixlen 64 scopeid 0x1
        inet6 fe80::1:1%vtnet0 prefixlen 64 duplicated scopeid 0x1
        inet6 2001:a62:5a5:5400:905d:58ff:fe1f:81ff prefixlen 64
        inet 10.100.198.2 netmask 0xffffff00 broadcast 10.100.198.255
        media: Ethernet 10Gbase-T <full-duplex>
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
vtnet1: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=800b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,LINKSTATE>
        ether 46:24:0c:f0:9e:d1
        inet6 fe80::4424:cff:fef0:9ed1%vtnet1 prefixlen 64 scopeid 0x2
        media: Ethernet 10Gbase-T <full-duplex>
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
vtnet2: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        description: LAN2
        options=800b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,LINKSTATE>
        ether 06:76:15:c6:76:8b
        inet6 fe80::476:15ff:fec6:768b%vtnet2 prefixlen 64 scopeid 0x3
        inet6 fe80::1:1%vtnet2 prefixlen 64 scopeid 0x3
        inet6 2001:a62:5a5:5401:476:15ff:fec6:768b prefixlen 64
        inet 10.100.100.1 netmask 0xffffff00 broadcast 10.100.100.255
        media: Ethernet 10Gbase-T <full-duplex>
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
enc0: flags=0<> metric 0 mtu 1536
        groups: enc
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
        options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
        inet6 ::1 prefixlen 128
        inet6 fe80::1%lo0 prefixlen 64 scopeid 0x5
        inet 127.0.0.1 netmask 0xff000000
        groups: lo
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
pflog0: flags=100<PROMISC> metric 0 mtu 33160
        groups: pflog
pfsync0: flags=0<> metric 0 mtu 1500
        groups: pfsync
pppoe0: flags=88d1<UP,POINTOPOINT,RUNNING,NOARP,SIMPLEX,MULTICAST> metric 0 mtu 1492
        description: WAN
        inet6 fe80::905d:58ff:fe1f:81ff%pppoe0 prefixlen 64 scopeid 0x8
        nd6 options=23<PERFORMNUD,ACCEPT_RTADV,AUTO_LINKLOCAL>
gif0: flags=8051<UP,POINTOPOINT,RUNNING,MULTICAST> metric 0 mtu 1280
        description: 4IN6
        options=80000<LINKSTATE>
        tunnel inet6 2001:a62:5a5:5400:905d:58ff:fe1f:81ff --> 2001:a60:0:1::ffff
        inet 192.0.0.2 --> 192.0.0.1 netmask 0xfffffff8
        inet6 fe80::8c91:4795:5f5f:cd3e%gif0 prefixlen 64 scopeid 0x9
        groups: gif
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>

I did try to set up new gif interfaces to no avail. Getting the same error as you all over again. Thank you for diving into this and helping me. This is very much appreciated.

Regards
Alex

vex

@stephenw10 I managed to create a second gif while the first one was still down. Setting the parent interface to WAN worked this way.

2022-10-21 17 38 18.png
Unfortunately, the interface still doesn't come up during boot and even more unfortunate is that the IPv4 routing does not work if I use WAN as parent interface. It shows as up, but the tunnel does not work.

dmesg shows

lo0: link state changed to UP
vtnet0: link state changed to UP
vtnet2: link state changed to UP
vtnet1: link state changed to UP
ng0: changing name to 'pppoe0'
vtnet0: DAD detected duplicate IPv6 address fe80:1::1:1: NS in/out/loopback=1/1/0, NA in=0
vtnet0: DAD complete for fe80:1::1:1 - duplicate found
vtnet0: manual intervention required
ng_pppoe[12]: no matching session
pflog0: promiscuous mode enabled

and ifconfig

[2.6.0-RELEASE][admin@pfSense.lan]/root: ifconfig
vtnet0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        description: LAN
        options=800b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,LINKSTATE>
        ether 92:5d:58:1f:81:ff
        inet6 fe80::905d:58ff:fe1f:81ff%vtnet0 prefixlen 64 scopeid 0x1
        inet6 fe80::1:1%vtnet0 prefixlen 64 duplicated scopeid 0x1
        inet6 2001:a62:5a5:a400:905d:58ff:fe1f:81ff prefixlen 64
        inet 10.100.198.2 netmask 0xffffff00 broadcast 10.100.198.255
        media: Ethernet 10Gbase-T <full-duplex>
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
vtnet1: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=800b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,LINKSTATE>
        ether 46:24:0c:f0:9e:d1
        inet6 fe80::4424:cff:fef0:9ed1%vtnet1 prefixlen 64 scopeid 0x2
        media: Ethernet 10Gbase-T <full-duplex>
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
vtnet2: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        description: LAN2
        options=800b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,LINKSTATE>
        ether 06:76:15:c6:76:8b
        inet6 fe80::476:15ff:fec6:768b%vtnet2 prefixlen 64 scopeid 0x3
        inet6 fe80::1:1%vtnet2 prefixlen 64 scopeid 0x3
        inet6 2001:a62:5a5:a401:476:15ff:fec6:768b prefixlen 64
        inet 10.100.100.1 netmask 0xffffff00 broadcast 10.100.100.255
        media: Ethernet 10Gbase-T <full-duplex>
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
enc0: flags=0<> metric 0 mtu 1536
        groups: enc
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
        options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
        inet6 ::1 prefixlen 128
        inet6 fe80::1%lo0 prefixlen 64 scopeid 0x5
        inet 127.0.0.1 netmask 0xff000000
        groups: lo
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
pflog0: flags=100<PROMISC> metric 0 mtu 33160
        groups: pflog
pfsync0: flags=0<> metric 0 mtu 1500
        groups: pfsync
pppoe0: flags=88d1<UP,POINTOPOINT,RUNNING,NOARP,SIMPLEX,MULTICAST> metric 0 mtu 1492
        description: WAN
        inet6 fe80::905d:58ff:fe1f:81ff%pppoe0 prefixlen 64 scopeid 0x8
        nd6 options=23<PERFORMNUD,ACCEPT_RTADV,AUTO_LINKLOCAL>

Don't know where to find logs of gif creation at boot time.

stephenw10

If you have just rebooted it should be in the main system log when it tries to bring up the tunnel.

Does that new tunnel come up if you restart after booting? Despite having no routable IPv6 address on WAN?

Do the PPP logs look like it's trying to pass a v6 IP to the WAN as well as a prefix?

Steve

vex

Hi Stephen,

the following is a log excerpt that I am getting after a reboot:

Oct 22 20:20:19 	check_reload_status 	442 	Syncing firewall
Oct 22 20:20:19 	php-fpm 	414 	/interfaces.php: Configuration Change: admin@2001:a62:5ae:de00:cddc:d09:b164:5252 (Local Database): Interfaces settings changed
Oct 22 20:20:15 	php-fpm 	414 	/index.php: Successful login for user 'admin' from: 2001:a62:5ae:de00:cddc:d09:b164:5252 (Local Database)
Oct 22 20:19:59 	sshguard 	9283 	Now monitoring attacks.
Oct 22 20:19:59 	login 	7620 	login on ttyv0 as root
Oct 22 20:19:57 	root 	76381 	Bootup complete
Oct 22 20:19:57 	php-fpm 	414 	/rc.start_packages: Restarting/Starting all packages.
Oct 22 20:19:57 	kernel 		done.
Oct 22 20:19:57 	syslogd 		kernel boot file is /boot/kernel/kernel
Oct 22 20:19:56 	syslogd 		exiting on signal 15
Oct 22 20:19:56 	kernel 		done.
Oct 22 20:19:56 	php 	458 	rc.bootup: Creating rrd update script
Oct 22 20:19:52 	kernel 		.....done.
Oct 22 20:19:52 	php 	458 	rc.bootup: The command '/usr/local/sbin/strongswanrc stop' returned exit code '1', the output was 'strongswan not running? (check /var/run/daemon-charon.pid).'
Oct 22 20:19:52 	check_reload_status 	442 	Updating all dyndns
Oct 22 20:19:52 	kernel 		done.
Oct 22 20:19:52 	kernel 		done.
Oct 22 20:19:51 	kernel 		done.
Oct 22 20:19:51 	kernel 		done.
Oct 22 20:19:50 	php 	458 	rc.bootup: NTPD is starting up.
Oct 22 20:19:50 	kernel 		done.
Oct 22 20:19:50 	php 	458 	rc.bootup: The command '/usr/bin/timeout -k 45 30 /usr/local/sbin/ntpd -g -q -c /dev/null 216.239.35.0 216.239.35.4 216.239.35.8 216.239.35.12' returned exit code '124', the output was '22 Oct 20:19:20 ntpd[96989]: ntpd 4.2.8p15@1.3728-o Wed Jan 12 15:39:52 UTC 2022 (1): Starting 22 Oct 20:19:20 ntpd[96989]: Command line: /usr/local/sbin/ntpd -g -q -c /dev/null 216.239.35.0 216.239.35.4 216.239.35.8 216.239.35.12 22 Oct 20:19:20 ntpd[96989]: ---------------------------------------------------- 22 Oct 20:19:20 ntpd[96989]: ntp-4 is maintained by Network Time Foundation, 22 Oct 20:19:20 ntpd[96989]: Inc. (NTF), a non-profit 501(c)(3) public-benefit 22 Oct 20:19:20 ntpd[96989]: corporation. Support and training for ntp-4 are 22 Oct 20:19:20 ntpd[96989]: available at https://www.nwtime.org/support 22 Oct 20:19:20 ntpd[96989]: ---------------------------------------------------- 22 Oct 20:19:20 ntpd[96989]: proto: precision = 0.121 usec (-23) 22 Oct 20:19:20 ntpd[96989]: line 0 column 0 syntax error, unexpected $end 22 Oct 20:19:20 ntpd[96989]: basedate set to 2021-12-31 22 Oct 20:19:20 ntpd[96989]: gps base set to 2022-01-02 (week 2191) 22 Oct 20:19:20 ntpd[96989]: Listen and drop on 0 v6wildcard [::]:123 22 Oct 20:19:20 ntpd[96989]: Listen and drop on 1 v4wildcard 0.0.0.0:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 2 vtnet0 [fe80::905d:58ff:fe1f:81ff%1]:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 3 vtnet0 10.100.198.2:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 4 vtnet0 [fe80::1:1%1]:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 5 vtnet0 [2001:a62:5ae:de00:905d:58ff:fe1f:81ff]:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 6 vtnet1 [fe80::4424:cff:fef0:9ed1%2]:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 7 vtnet2 [fe80::476:15ff:fec6:768b%3]:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 8 lo0 [::1]:123 22 Oct 20:19:20 ntpd[96989]: Listen normally on 9 lo0 [fe80::1%5]:123 22 Oct 20:19:20 ntpd[96989]: Listen
Oct 22 20:19:20 	kernel 		done.
Oct 22 20:19:20 	kernel 		done.
Oct 22 20:19:20 	php 	458 	rc.bootup: sync unbound done.
Oct 22 20:19:19 	php-fpm 	413 	/rc.newwanipv6: Gateway, NONE AVAILABLE
Oct 22 20:19:18 	php 	458 	rc.bootup: dhcp6 init complete. Continuing
Oct 22 20:19:18 	php-fpm 	414 	/rc.newwanipv6: Gateway, NONE AVAILABLE
Oct 22 20:19:18 	php-fpm 	414 	/rc.newwanipv6: dpinger: status socket /var/run/dpinger_WAN_DHCP6~fe80::905d:58ff:fe1f:81ff%pppoe0~fe80::2cc:34ff:fe44:b067%pppoe0.sock not found
Oct 22 20:19:18 	php-fpm 	413 	/rc.newwanipv6: rc.newwanipv6: on (IP address: fe80::905d:58ff:fe1f:81ff%pppoe0) (interface: wan) (real interface: pppoe0).
Oct 22 20:19:18 	php-fpm 	413 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Oct 22 20:19:18 	php-fpm 	414 	/rc.newwanipv6: rc.newwanipv6: on (IP address: fe80::905d:58ff:fe1f:81ff%pppoe0) (interface: wan) (real interface: pppoe0).
Oct 22 20:19:18 	php-fpm 	414 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Oct 22 20:19:17 	kernel 		done.
Oct 22 20:19:17 	php 	458 	rc.bootup: Unbound start waiting on dhcp6c.
Oct 22 20:19:17 	php 	458 	rc.bootup: Gateway, NONE AVAILABLE
Oct 22 20:19:17 	ppp 	10808 	[wan] IFACE: Add description "WAN"
Oct 22 20:19:17 	ppp 	10808 	[wan] IFACE: Rename interface ng0 to pppoe0
Oct 22 20:19:17 	ppp 	10808 	[wan] IFACE: Up event
Oct 22 20:19:17 	check_reload_status 	442 	rc.newwanipv6 starting pppoe0
Oct 22 20:19:16 	kernel 		pflog0: promiscuous mode enabled
Oct 22 20:19:16 	kernel 		done.
Oct 22 20:19:16 	php 	458 	rc.bootup: Resyncing OpenVPN instances.
Oct 22 20:19:16 	php 	458 	rc.bootup: calling interface_dhcpv6_configure.
Oct 22 20:19:16 	rtsold 	17891 	Starting dhcp6 client for interface wan(pppoe0)
Oct 22 20:19:16 	rtsold 	17366 	Received RA specifying route fe80::2cc:34ff:fe44:b067 for interface wan(pppoe0)
Oct 22 20:19:16 	check_reload_status 	442 	Rewriting resolv.conf
Oct 22 20:19:16 	kernel 		ng_pppoe[12]: no matching session
Oct 22 20:19:14 	sshguard 	13592 	Now monitoring attacks.
Oct 22 20:19:14 	sshd 	12982 	Server listening on 0.0.0.0 port 22.
Oct 22 20:19:14 	sshd 	12982 	Server listening on :: port 22.
Oct 22 20:19:14 	php 	11645 	/usr/local/sbin/ppp-ipv6: Starting rtsold process
Oct 22 20:19:14 	php 	11645 	/usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
Oct 22 20:19:14 	ppp 	10808 	[wan] 905d:58ff:fe1f:81ff -> 02cc:34ff:fe44:b067
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: LayerUp
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: state change Ack-Sent --> Opened
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: rec'd Configure Ack #1 (Ack-Sent)
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: state change Req-Sent --> Ack-Sent
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: SendConfigAck #218
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: rec'd Configure Request #218 (Req-Sent)
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: LayerFinish
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: state change Req-Sent --> Stopped
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: protocol was rejected by peer
Oct 22 20:19:14 	ppp 	10808 	[wan_link0] LCP: protocol IPCP was rejected
Oct 22 20:19:14 	ppp 	10808 	[wan_link0] LCP: rec'd Protocol Reject #12 (Opened)
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: SendConfigReq #1
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: state change Starting --> Req-Sent
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: Up event
Oct 22 20:19:14 	ppp 	10808 	[wan] SECDNS 0.0.0.0
Oct 22 20:19:14 	ppp 	10808 	[wan] PRIDNS 0.0.0.0
Oct 22 20:19:14 	ppp 	10808 	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Oct 22 20:19:14 	ppp 	10808 	[wan] IPADDR 0.0.0.0
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: SendConfigReq #1
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: state change Starting --> Req-Sent
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: Up event
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: LayerStart
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: state change Initial --> Starting
Oct 22 20:19:14 	ppp 	10808 	[wan] IPV6CP: Open event
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: LayerStart
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: state change Initial --> Starting
Oct 22 20:19:14 	ppp 	10808 	[wan] IPCP: Open event
Oct 22 20:19:14 	ppp 	10808 	[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Oct 22 20:19:14 	ppp 	10808 	[wan_link0] Link: Join bundle "wan"
Oct 22 20:19:14 	ppp 	10808 	[wan_link0] Link: Matched action 'bundle "wan" ""'
Oct 22 20:19:14 	ppp 	10808 	[wan_link0] LCP: authorization successful
Oct 22 20:19:14 	ppp 	10808 	[wan_link0] CHAP: rec'd SUCCESS #114 len: 4
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] CHAP: sending RESPONSE #114 len: 51
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] CHAP: Using authname "XXXXXXXXXXXX@mdsl.mnet-online.de"
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] Name: "ac3.nue2"
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] CHAP: rec'd CHALLENGE #114 len: 36
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: LayerUp
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: auth: peer wants CHAP, I want nothing
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: state change Ack-Sent --> Opened
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MAGICNUM 0xd716b7a0
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MRU 1492
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] PROTOCOMP
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: state change Req-Sent --> Ack-Sent
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MAGICNUM 0x7162e1bf
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] AUTHPROTO CHAP MD5
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MRU 1492
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: SendConfigAck #11
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MAGICNUM 0x7162e1bf
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] AUTHPROTO CHAP MD5
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MRU 1492
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: rec'd Configure Request #11 (Req-Sent)
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MAGICNUM 0xd716b7a0
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] MRU 1492
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] PROTOCOMP
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: SendConfigReq #1
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: state change Starting --> Req-Sent
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: Up event
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] Link: UP event
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] PPPoE: connection successful
Oct 22 20:19:13 	ppp 	10808 	PPPoE: rec'd ACNAME "ac3.nue2"
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] PPPoE: Connecting to ''
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: LayerStart
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: state change Initial --> Starting
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] LCP: Open event
Oct 22 20:19:13 	kernel 		ng0: changing name to 'pppoe0'
Oct 22 20:19:13 	ppp 	10808 	[wan_link0] Link: OPEN event
Oct 22 20:19:13 	ppp 	10808 	[wan] Bundle: Interface ng0 created
Oct 22 20:19:13 	ppp 	10808 	web: web is not running
Oct 22 20:19:13 	ppp 	10808 	process 10808 started, version 5.9
Oct 22 20:19:13 	ppp 	10808 	Multi-link PPP daemon for FreeBSD
Oct 22 20:19:13 	kernel 		vtnet2: link state changed to UP
Oct 22 20:19:13 	check_reload_status 	442 	Linkup starting vtnet2
Oct 22 20:19:13 	kernel 		vtnet1: link state changed to UP
Oct 22 20:19:13 	kernel 		done.
Oct 22 20:19:13 	check_reload_status 	442 	Linkup starting vtnet1
Oct 22 20:19:13 	php 	458 	rc.bootup: The command '/sbin/ifconfig 'gif0' description '4IN6'' returned exit code '1', the output was 'ifconfig: interface gif0 does not exist'
Oct 22 20:19:13 	kernel 		vtnet0: link state changed to UP
Oct 22 20:19:13 	check_reload_status 	442 	Linkup starting vtnet0
Oct 22 20:19:13 	kernel 		lo0: link state changed to UP

4IN6 (gif0) tunnel does not come up with the reboot. If I now manually do the "Save"/"Apply changes"-Wizardry, the gif0 comes up and the logs show:

Oct 22 20:26:43 	check_reload_status 	442 	Reloading filter
Oct 22 20:26:43 	check_reload_status 	442 	Restarting OpenVPN tunnels/interfaces
Oct 22 20:26:43 	check_reload_status 	442 	Restarting IPsec tunnels
Oct 22 20:26:43 	check_reload_status 	442 	updating dyndns 4IN6_TUNNELV4
Oct 22 20:26:43 	rc.gateway_alarm 	78678 	>>> Gateway alarm: 4IN6_TUNNELV4 (Addr:192.0.0.1 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)
Oct 22 20:26:41 	php-fpm 	414 	/interfaces.php: Creating rrd update script
Oct 22 20:26:41 	check_reload_status 	442 	Reloading filter
Oct 22 20:26:39 	check_reload_status 	442 	updating dyndns opt1
Oct 22 20:26:36 	dhcpleases 	64283 	Could not deliver signal HUP to process 90863: No such process.
Oct 22 20:26:35 	check_reload_status 	442 	Restarting IPsec tunnels
Oct 22 20:26:35 	kernel 		gif0: link state changed to UP
Oct 22 20:26:35 	php-fpm 	414 	/interfaces.php: Default gateway setting Interface 4IN6_TUNNELV4 Gateway as default.

What I find slightly interesting, is that the IPv4 tunnel gateway has 100% packet loss in the gateway monitor, although it works flawlessly.

Kind regards
Alex

stephenw10

@vex said in gif0 does not come up after reboot:

Oct 22 20:19:13 php 458 rc.bootup: The command '/sbin/ifconfig 'gif0' description '4IN6'' returned exit code '1', the output was 'ifconfig: interface gif0 does not exist'
Oct 22 20:19:13 kernel vtnet0: link state changed to UP

That's with the gif tunnel using WAN as the parent? Or LAN still?

Is the PPPoE interface first in the list?

I note that you appear to have WAN set to dhcpv6 but the PPPoE is passing an IPv6 address via IPV6CP directly.

The IPv4 gateway may simply not respond to ping. Try setting a monitoring IP somewhere further upstream like 8.8.8.8.

Steve

vex

That's with the gif0 using LAN as parent. PPPoE is first in list, yes.

2022-10-26 21 19 06.png

So instead of using DHCPv6 as configuration type, should I use something else there?

Yeah, I switched to monitoring the IPv6 CG-NAT/AFTR address.

This is the complete log of booting with gif0 and WAN as parent:

Oct 26 21:45:42 	php-fpm 	366 	/index.php: Successful login for user 'admin' from: 10.100.198.249 (Local Database)
Oct 26 21:45:37 	sshguard 	61915 	Now monitoring attacks.
Oct 26 21:45:37 	login 	59892 	login on ttyv0 as root
Oct 26 21:45:36 	root 	51758 	Bootup complete
Oct 26 21:45:35 	php-fpm 	366 	/rc.start_packages: Restarting/Starting all packages.
Oct 26 21:45:35 	kernel 		done.
Oct 26 21:45:35 	syslogd 		kernel boot file is /boot/kernel/kernel
Oct 26 21:45:35 	syslogd 		exiting on signal 15
Oct 26 21:45:35 	php 	411 	rc.bootup: Creating rrd update script
Oct 26 21:45:31 	kernel 		.....done.
Oct 26 21:45:31 	php 	411 	rc.bootup: The command '/usr/local/sbin/strongswanrc stop' returned exit code '1', the output was 'strongswan not running? (check /var/run/daemon-charon.pid).'
Oct 26 21:45:30 	check_reload_status 	395 	Updating all dyndns
Oct 26 21:45:30 	kernel 		done.
Oct 26 21:45:30 	kernel 		done.
Oct 26 21:45:30 	kernel 		done.
Oct 26 21:45:29 	kernel 		done.
Oct 26 21:45:29 	php 	411 	rc.bootup: NTPD is starting up.
Oct 26 21:45:29 	kernel 		done.
Oct 26 21:45:29 	php 	411 	rc.bootup: The command '/usr/bin/timeout -k 45 30 /usr/local/sbin/ntpd -g -q -c /dev/null 216.239.35.0 216.239.35.4 216.239.35.8 216.239.35.12' returned exit code '124', the output was '26 Oct 21:44:59 ntpd[75103]: ntpd 4.2.8p15@1.3728-o Wed Jan 12 15:39:52 UTC 2022 (1): Starting 26 Oct 21:44:59 ntpd[75103]: Command line: /usr/local/sbin/ntpd -g -q -c /dev/null 216.239.35.0 216.239.35.4 216.239.35.8 216.239.35.12 26 Oct 21:44:59 ntpd[75103]: ---------------------------------------------------- 26 Oct 21:44:59 ntpd[75103]: ntp-4 is maintained by Network Time Foundation, 26 Oct 21:44:59 ntpd[75103]: Inc. (NTF), a non-profit 501(c)(3) public-benefit 26 Oct 21:44:59 ntpd[75103]: corporation. Support and training for ntp-4 are 26 Oct 21:44:59 ntpd[75103]: available at https://www.nwtime.org/support 26 Oct 21:44:59 ntpd[75103]: ---------------------------------------------------- 26 Oct 21:44:59 ntpd[75103]: proto: precision = 0.123 usec (-23) 26 Oct 21:44:59 ntpd[75103]: line 0 column 0 syntax error, unexpected $end 26 Oct 21:44:59 ntpd[75103]: basedate set to 2021-12-31 26 Oct 21:44:59 ntpd[75103]: gps base set to 2022-01-02 (week 2191) 26 Oct 21:44:59 ntpd[75103]: Listen and drop on 0 v6wildcard [::]:123 26 Oct 21:44:59 ntpd[75103]: Listen and drop on 1 v4wildcard 0.0.0.0:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 2 vtnet0 [fe80::905d:58ff:fe1f:81ff%1]:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 3 vtnet0 10.100.198.2:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 4 vtnet0 [fe80::1:1%1]:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 5 vtnet0 [2001:a62:5d1:aa00:905d:58ff:fe1f:81ff]:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 6 vtnet1 [fe80::4424:cff:fef0:9ed1%2]:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 7 lo0 [::1]:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 8 lo0 [fe80::1%5]:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 9 lo0 127.0.0.1:123 26 Oct 21:44:59 ntpd[75103]: Listen normally on 10 pppoe0
Oct 26 21:44:59 	kernel 		done.
Oct 26 21:44:59 	php 	411 	rc.bootup: sync unbound done.
Oct 26 21:44:59 	kernel 		done.
Oct 26 21:44:57 	php-fpm 	367 	/rc.newwanipv6: Gateway, NONE AVAILABLE
Oct 26 21:44:57 	php-fpm 	367 	/rc.newwanipv6: rc.newwanipv6: on (IP address: fe80::905d:58ff:fe1f:81ff%pppoe0) (interface: wan) (real interface: pppoe0).
Oct 26 21:44:57 	php-fpm 	367 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Oct 26 21:44:57 	php 	411 	rc.bootup: dhcp6 init complete. Continuing
Oct 26 21:44:56 	php-fpm 	366 	/rc.newwanipv6: Gateway, NONE AVAILABLE
Oct 26 21:44:56 	php-fpm 	366 	/rc.newwanipv6: rc.newwanipv6: on (IP address: fe80::905d:58ff:fe1f:81ff%pppoe0) (interface: wan) (real interface: pppoe0).
Oct 26 21:44:56 	php-fpm 	366 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Oct 26 21:44:56 	php 	411 	rc.bootup: Unbound start waiting on dhcp6c.
Oct 26 21:44:55 	ppp 	9410 	[wan] IFACE: Add description "WAN"
Oct 26 21:44:55 	ppp 	9410 	[wan] IFACE: Rename interface ng0 to pppoe0
Oct 26 21:44:55 	ppp 	9410 	[wan] IFACE: Up event
Oct 26 21:44:55 	check_reload_status 	395 	rc.newwanipv6 starting pppoe0
Oct 26 21:44:55 	rtsold 	41957 	Starting dhcp6 client for interface wan(pppoe0)
Oct 26 21:44:55 	rtsold 	41008 	Received RA specifying route fe80::2cc:34ff:fe44:b067 for interface wan(pppoe0)
Oct 26 21:44:55 	php 	411 	rc.bootup: Unbound start waiting on dhcp6c.
Oct 26 21:44:55 	kernel 		done.
Oct 26 21:44:55 	kernel 		pflog0: promiscuous mode enabled
Oct 26 21:44:55 	kernel 		done.
Oct 26 21:44:55 	php 	411 	rc.bootup: Gateway, NONE AVAILABLE
Oct 26 21:44:55 	php 	411 	rc.bootup: Resyncing OpenVPN instances.
Oct 26 21:44:55 	php 	411 	rc.bootup: calling interface_dhcpv6_configure.
Oct 26 21:44:54 	check_reload_status 	395 	Rewriting resolv.conf
Oct 26 21:44:54 	kernel 		ng_pppoe[12]: no matching session
Oct 26 21:44:53 	sshguard 	12833 	Now monitoring attacks.
Oct 26 21:44:53 	sshd 	12231 	Server listening on 0.0.0.0 port 22.
Oct 26 21:44:53 	sshd 	12231 	Server listening on :: port 22.
Oct 26 21:44:52 	php 	10463 	/usr/local/sbin/ppp-ipv6: Starting rtsold process
Oct 26 21:44:52 	php 	10463 	/usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
Oct 26 21:44:52 	ppp 	9410 	[wan] 905d:58ff:fe1f:81ff -> 02cc:34ff:fe44:b067
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: LayerUp
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: state change Ack-Sent --> Opened
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: rec'd Configure Ack #1 (Ack-Sent)
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: state change Req-Sent --> Ack-Sent
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: SendConfigAck #120
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: rec'd Configure Request #120 (Req-Sent)
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: LayerFinish
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: state change Req-Sent --> Stopped
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: protocol was rejected by peer
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: protocol IPCP was rejected
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: rec'd Protocol Reject #106 (Opened)
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: SendConfigReq #1
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: state change Starting --> Req-Sent
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: Up event
Oct 26 21:44:52 	ppp 	9410 	[wan] SECDNS 0.0.0.0
Oct 26 21:44:52 	ppp 	9410 	[wan] PRIDNS 0.0.0.0
Oct 26 21:44:52 	ppp 	9410 	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Oct 26 21:44:52 	ppp 	9410 	[wan] IPADDR 0.0.0.0
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: SendConfigReq #1
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: state change Starting --> Req-Sent
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: Up event
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: LayerStart
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: state change Initial --> Starting
Oct 26 21:44:52 	ppp 	9410 	[wan] IPV6CP: Open event
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: LayerStart
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: state change Initial --> Starting
Oct 26 21:44:52 	ppp 	9410 	[wan] IPCP: Open event
Oct 26 21:44:52 	ppp 	9410 	[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] Link: Join bundle "wan"
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] Link: Matched action 'bundle "wan" ""'
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: authorization successful
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] CHAP: rec'd SUCCESS #191 len: 4
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] CHAP: sending RESPONSE #191 len: 51
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] CHAP: Using authname "XXXXXXXXXX@mdsl.mnet-online.de"
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] Name: "ac3.nue2"
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] CHAP: rec'd CHALLENGE #191 len: 31
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: LayerUp
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: auth: peer wants CHAP, I want nothing
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: state change Ack-Sent --> Opened
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MAGICNUM 0xe30caada
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MRU 1492
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] PROTOCOMP
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: state change Req-Sent --> Ack-Sent
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MAGICNUM 0x0397bc67
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] AUTHPROTO CHAP MD5
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MRU 1492
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: SendConfigAck #105
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MAGICNUM 0x0397bc67
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] AUTHPROTO CHAP MD5
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MRU 1492
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: rec'd Configure Request #105 (Req-Sent)
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MAGICNUM 0xe30caada
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] MRU 1492
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] PROTOCOMP
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: SendConfigReq #1
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: state change Starting --> Req-Sent
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: Up event
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] Link: UP event
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] PPPoE: connection successful
Oct 26 21:44:52 	ppp 	9410 	PPPoE: rec'd ACNAME "ac3.nue2"
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] PPPoE: Connecting to ''
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: LayerStart
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: state change Initial --> Starting
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] LCP: Open event
Oct 26 21:44:52 	kernel 		ng0: changing name to 'pppoe0'
Oct 26 21:44:52 	ppp 	9410 	[wan_link0] Link: OPEN event
Oct 26 21:44:52 	ppp 	9410 	[wan] Bundle: Interface ng0 created
Oct 26 21:44:52 	ppp 	9410 	web: web is not running
Oct 26 21:44:52 	ppp 	9410 	process 9410 started, version 5.9
Oct 26 21:44:52 	ppp 	9410 	Multi-link PPP daemon for FreeBSD
Oct 26 21:44:52 	kernel 		vtnet1: link state changed to UP
Oct 26 21:44:52 	kernel 		done.
Oct 26 21:44:52 	check_reload_status 	395 	Linkup starting vtnet1
Oct 26 21:44:52 	php 	411 	rc.bootup: The command '/sbin/ifconfig 'gif0' description '4IN6'' returned exit code '1', the output was 'ifconfig: interface gif0 does not exist'
Oct 26 21:44:52 	check_reload_status 	395 	Linkup starting vtnet0
Oct 26 21:44:52 	kernel 		vtnet0: link state changed to UP

As I already mentioned: With this configuration the 4IN6 tunnel does not work.

Thanks again for having a look into this.

stephenw10

Hmm. Even with that don't see it trying to restart the gif tunnel (even if it would fail) after the WAN connects and gets a new IPv6 address and I would expect it to trigger that.
It could be because it's link-local only and that is not seen as a valid address. Though it is valid for a transport link and that's common on WAN. Or potentially it comes up at boot and somethings are suppressed during boot to prevent flapping.

However what you're seeing is exactly this: https://redmine.pfsense.org/issues/8273

Which should be fixed by this: https://redmine.pfsense.org/issues/6507
But that is in 2.6.

Does manually running /etc/rc.newwanipv6 lan after boot bring the gif tunnel up? What is logged when you do that?

Steve

vex

@stephenw10 Hi Stephen,

this is logged when I manually start /etc/rc.newwanipv6 lan:

Oct 27 21:36:59 	php-fpm 	366 	/rc.start_packages: Restarting/Starting all packages.
Oct 27 21:36:58 	check_reload_status 	395 	Starting packages
Oct 27 21:36:58 	php 	80074 	rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - 2001:a62:5d9:f100:905d:58ff:fe1f:81ff -> 2001:a62:5d9:f600:905d:58ff:fe1f:81ff - Restarting packages.
Oct 27 21:36:58 	php 	80074 	rc.newwanipv6: Creating rrd update script
Oct 27 21:36:58 	php 	80074 	rc.newwanipv6: Gateway, NONE AVAILABLE
Oct 27 21:36:58 	kernel 		gif0: link state changed to UP
Oct 27 21:36:58 	kernel 		gif0: link state changed to DOWN
Oct 27 21:36:58 	kernel 		gif0: link state changed to UP
Oct 27 21:36:58 	php 	80074 	rc.newwanipv6: Default gateway setting Interface 4IN6_TUNNELV4 Gateway as default.
Oct 27 21:36:58 	php 	80074 	rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.
Oct 27 21:36:55 	dhcpleases 	6384 	Could not deliver signal HUP to process 80756: No such process.
Oct 27 21:36:54 	check_reload_status 	395 	Reloading filter
Oct 27 21:36:54 	php 	80074 	rc.newwanipv6: Gateway, NONE AVAILABLE
Oct 27 21:36:54 	php 	80074 	rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:a62:5d9:f600:905d:58ff:fe1f:81ff) (interface: lan) (real interface: lan).
Oct 27 21:36:54 	php 	80074 	rc.newwanipv6: rc.newwanipv6: Info: starting on lan.

The gif0 tunnel is up after doing this.

stephenw10

Ok, interesting. So after running some tests here it appears that never gets called because it's not actually a WAN. I've asked internally because it's not clear to me what should happen there currently. As far as I can see it only restarts DNS and DHCPv6 on the tracking interface.

Steve

vex

@stephenw10 Just an hypothetical question: Would this bug be fixed if I paid for one of your support contracts and opened a case?

Regards
Alex

stephenw10

No. Support contracts are not paid development so it would make no difference here.

There are large number of moving parts currently and development time is at minimum. I didn't see much of a response previosuly. Let me retry....

Steve