[solved] PPPoE IA-PD woes

maverick_slo

Hi all!

First of all I have perfectly fine working IPv6, here is my config:

DHCPv6 IA-PD
I get /56 prefix
I get /64 WAN connecting segment
Created /64`s out of that /56
See attached images for detailed config (dhcpv6_1 and dhcpv6_2)

Now to the problem…
Everything works just fine after reboot or pppoe disconnect and then reconnect....

BUT when I:
a) unplug modem from ISP and plug it in
b) Reboot or restart ISP modem
c) detach and re-attach UTP cable to PPPoE iface (quickly or for a longer time it doesn`t matter)

I loose IPv6 connectivity completley on my hosts which are on those /64 networks derived from delegated /56.
Gateway monitoring shows IPv6 as pending and no monitor IP is specified, see attached image (gateway_status).

If I then disconnect PPPoE and reconnect all comes back online like it should.

DHCPv6C SUCCESFULL LOG:


Mar 8 11:13:50 	dhcp6c 	58179 	got an expected reply, sleeping.
Mar 8 11:13:50 	dhcp6c 	58179 	removing server (ID: 00:03:00:01:00:c1:64:d8:3f:00)
Mar 8 11:13:50 	dhcp6c 	58179 	removing an event on pppoe0, state=REQUEST
Mar 8 11:13:50 	dhcp6c 	58179 	script "/var/etc/dhcp6c_opt2_script.sh" terminated
Mar 8 11:13:50 	dhcp6c 	58179 	executes /var/etc/dhcp6c_opt2_script.sh
Mar 8 11:13:50 	dhcp6c 	58179 	create a prefix 2001:xxxx:xxx:xxx::/56 pltime=140733193647232, vltime=604800
Mar 8 11:13:50 	dhcp6c 	58179 	make an IA: PD-0
Mar 8 11:13:50 	dhcp6c 	58179 	Domain search list[0] domain.net.
Mar 8 11:13:50 	dhcp6c 	58179 	nameserver[1] 2001:xxxx:xxxx:x::10
Mar 8 11:13:50 	dhcp6c 	58179 	nameserver[0] 2001:xxxx:xxxx:x::12
Mar 8 11:13:50 	dhcp6c 	58179 	dhcp6c Received REQUEST
Mar 8 11:13:50 	dhcp6c 	58179 	get DHCP option domain search list, len 10
Mar 8 11:13:50 	dhcp6c 	58179 	get DHCP option DNS, len 32
Mar 8 11:13:50 	dhcp6c 	58179 	IA_PD prefix: 2001:xxxx:xxx:xxx::/56 pltime=259200 vltime=604800
Mar 8 11:13:50 	dhcp6c 	58179 	get DHCP option IA_PD prefix, len 25
Mar 8 11:13:50 	dhcp6c 	58179 	IA_PD: ID=0, T1=129600, T2=207360
Mar 8 11:13:50 	dhcp6c 	58179 	get DHCP option IA_PD, len 41
Mar 8 11:13:50 	dhcp6c 	58179 	DUID: DUID HERE
Mar 8 11:13:50 	dhcp6c 	58179 	get DHCP option client ID, len 14
Mar 8 11:13:50 	dhcp6c 	58179 	DUID: DUID HERE
Mar 8 11:13:50 	dhcp6c 	58179 	get DHCP option server ID, len 10
Mar 8 11:13:50 	dhcp6c 	58179 	receive reply from fe80::2c1:aaaa:aaaa:aaaa%pppoe0 on pppoe0
Mar 8 11:13:50 	dhcp6c 	58179 	reset a timer on pppoe0, state=REQUEST, timeo=0, retrans=909
Mar 8 11:13:50 	dhcp6c 	58179 	send request to ff02::1:2%pppoe0
Mar 8 11:13:50 	dhcp6c 	58179 	set IA_PD
Mar 8 11:13:50 	dhcp6c 	58179 	set IA_PD prefix
Mar 8 11:13:50 	dhcp6c 	58179 	set elapsed time (len 2)
Mar 8 11:13:50 	dhcp6c 	58179 	set server ID (len 10)
Mar 8 11:13:50 	dhcp6c 	58179 	set client ID (len 14)
Mar 8 11:13:50 	dhcp6c 	58179 	a new XID (73f3b0) is generated
Mar 8 11:13:50 	dhcp6c 	58179 	Sending Request
Mar 8 11:13:50 	dhcp6c 	58179 	picked a server (ID: 00:03:00:01:00:c1:64:d8:3f:00)
Mar 8 11:13:49 	dhcp6c 	58179 	reset timer for pppoe0 to 0.996924
Mar 8 11:13:49 	dhcp6c 	58179 	server ID: 00:03:00:01:00:c1:64:d8:3f:00, pref=-1
Mar 8 11:13:49 	dhcp6c 	58179 	get DHCP option domain search list, len 10
Mar 8 11:13:49 	dhcp6c 	58179 	get DHCP option DNS, len 32
Mar 8 11:13:49 	dhcp6c 	58179 	IA_PD prefix: 2001:xxxx:xxx:xxx::/56 pltime=259200 vltime=604800
Mar 8 11:13:49 	dhcp6c 	58179 	get DHCP option IA_PD prefix, len 25
Mar 8 11:13:49 	dhcp6c 	58179 	IA_PD: ID=0, T1=129600, T2=207360
Mar 8 11:13:49 	dhcp6c 	58179 	get DHCP option IA_PD, len 41
Mar 8 11:13:49 	dhcp6c 	58179 	DUID: DUID HERE
Mar 8 11:13:49 	dhcp6c 	58179 	get DHCP option client ID, len 14
Mar 8 11:13:49 	dhcp6c 	58179 	DUID: DUID HERE
Mar 8 11:13:49 	dhcp6c 	58179 	get DHCP option server ID, len 10
Mar 8 11:13:49 	dhcp6c 	58179 	receive advertise from fe80::2c1:aaaa:aaaa:aaaa%pppoe0 on pppoe0
Mar 8 11:13:49 	dhcp6c 	58179 	reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1091
Mar 8 11:13:49 	dhcp6c 	58179 	send solicit to ff02::1:2%pppoe0
Mar 8 11:13:49 	dhcp6c 	58179 	set IA_PD
Mar 8 11:13:49 	dhcp6c 	58179 	set elapsed time (len 2)
Mar 8 11:13:49 	dhcp6c 	58179 	set client ID (len 14)
Mar 8 11:13:49 	dhcp6c 	58179 	a new XID (cb9c6c) is generated
Mar 8 11:13:49 	dhcp6c 	58179 	Sending Solicit
Mar 8 11:13:48 	dhcp6c 	58179 	reset a timer on pppoe0, state=INIT, timeo=0, retrans=891
Mar 8 11:13:48 	dhcp6c 	58067 	called
Mar 8 11:13:48 	dhcp6c 	58067 	called
Mar 8 11:13:48 	dhcp6c 	58067 	<3>end of sentence [;] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>end of closure [}] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<13>begin of closure [{] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<13>[0] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<13>[pd] (2)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>[id-assoc] (8)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>end of sentence [;] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>end of closure [}] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>end of sentence [;] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>["/var/etc/dhcp6c_opt2_script.sh"] (32)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>[script] (6)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>end of sentence [;] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>[0] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>[ia-pd] (5)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>[send] (4)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>begin of closure [{] (1)
Mar 8 11:13:48 	dhcp6c 	58067 	<5>[pppoe0] (6)
Mar 8 11:13:48 	dhcp6c 	58067 	<3>[interface] (9)
Mar 8 11:13:48 	dhcp6c 	58067 	skip opening control port
Mar 8 11:13:48 	dhcp6c 	58067 	failed initialize control message authentication
Mar 8 11:13:48 	dhcp6c 	58067 	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Mar 8 11:13:48 	dhcp6c 	58067 	extracted an existing DUID from /var/db/dhcp6c_duid: DUID HERE

Nad what happens after I disconnect and reconnect UTP cable for 2 seconds:


Mar 8 11:18:45 	dhcp6c 	58179 	exiting
Mar 8 11:18:45 	dhcp6c 	58179 	script "/var/etc/dhcp6c_opt2_script.sh" terminated
Mar 8 11:18:45 	dhcp6c 	58179 	executes /var/etc/dhcp6c_opt2_script.sh
Mar 8 11:18:45 	dhcp6c 	58179 	removing an event on pppoe0, state=RELEASE
Mar 8 11:18:45 	dhcp6c 	58179 	script "/var/etc/dhcp6c_opt2_script.sh" terminated
Mar 8 11:18:45 	dhcp6c 	58179 	executes /var/etc/dhcp6c_opt2_script.sh
Mar 8 11:18:45 	dhcp6c 	58179 	status code: success
Mar 8 11:18:45 	dhcp6c 	58179 	dhcp6c Received RELEASE
Mar 8 11:18:45 	dhcp6c 	58179 	status code: no binding
Mar 8 11:18:45 	dhcp6c 	58179 	get DHCP option status code, len 12
Mar 8 11:18:45 	dhcp6c 	58179 	IA_PD: ID=0, T1=60, T2=120
Mar 8 11:18:45 	dhcp6c 	58179 	get DHCP option IA_PD, len 28
Mar 8 11:18:45 	dhcp6c 	58179 	status code: success
Mar 8 11:18:45 	dhcp6c 	58179 	get DHCP option status code, len 9
Mar 8 11:18:45 	dhcp6c 	58179 	DUID: DUID HERE
Mar 8 11:18:45 	dhcp6c 	58179 	get DHCP option client ID, len 14
Mar 8 11:18:45 	dhcp6c 	58179 	DUID: DUID HERE
Mar 8 11:18:45 	dhcp6c 	58179 	get DHCP option server ID, len 10
Mar 8 11:18:45 	dhcp6c 	58179 	receive reply from fe80::2c1:aaaa:aaaa:aaaa%pppoe0 on pppoe0
Mar 8 11:18:45 	dhcp6c 	58179 	reset a timer on pppoe0, state=RELEASE, timeo=4, retrans=14498
Mar 8 11:18:45 	dhcp6c 	58179 	send release to ff02::1:2%pppoe0
Mar 8 11:18:45 	dhcp6c 	58179 	set IA_PD
Mar 8 11:18:45 	dhcp6c 	58179 	set IA_PD prefix
Mar 8 11:18:45 	dhcp6c 	58179 	set elapsed time (len 2)
Mar 8 11:18:45 	dhcp6c 	58179 	set server ID (len 10)
Mar 8 11:18:45 	dhcp6c 	58179 	set client ID (len 14)
Mar 8 11:18:45 	dhcp6c 	58179 	Sending Release
Mar 8 11:18:38 	dhcp6c 	58179 	reset a timer on pppoe0, state=RELEASE, timeo=3, retrans=7281
Mar 8 11:18:38 	dhcp6c 	58179 	transmit failed: Can't assign requested address
Mar 8 11:18:38 	dhcp6c 	58179 	set IA_PD
Mar 8 11:18:38 	dhcp6c 	58179 	set IA_PD prefix
Mar 8 11:18:38 	dhcp6c 	58179 	set elapsed time (len 2)
Mar 8 11:18:38 	dhcp6c 	58179 	set server ID (len 10)
Mar 8 11:18:38 	dhcp6c 	58179 	set client ID (len 14)
Mar 8 11:18:38 	dhcp6c 	58179 	Sending Release
Mar 8 11:18:34 	dhcp6c 	58179 	reset a timer on pppoe0, state=RELEASE, timeo=2, retrans=3606
Mar 8 11:18:34 	dhcp6c 	58179 	send release to ff02::1:2%pppoe0
Mar 8 11:18:34 	dhcp6c 	58179 	set IA_PD
Mar 8 11:18:34 	dhcp6c 	58179 	set IA_PD prefix
Mar 8 11:18:34 	dhcp6c 	58179 	set elapsed time (len 2)
Mar 8 11:18:34 	dhcp6c 	58179 	set server ID (len 10)
Mar 8 11:18:34 	dhcp6c 	58179 	set client ID (len 14)
Mar 8 11:18:34 	dhcp6c 	58179 	Sending Release
Mar 8 11:18:33 	dhcp6c 	58179 	reset a timer on pppoe0, state=RELEASE, timeo=1, retrans=1844
Mar 8 11:18:33 	dhcp6c 	58179 	send release to ff02::1:2%pppoe0
Mar 8 11:18:33 	dhcp6c 	58179 	set IA_PD
Mar 8 11:18:33 	dhcp6c 	58179 	set IA_PD prefix
Mar 8 11:18:33 	dhcp6c 	58179 	set elapsed time (len 2)
Mar 8 11:18:33 	dhcp6c 	58179 	set server ID (len 10)
Mar 8 11:18:33 	dhcp6c 	58179 	set client ID (len 14)
Mar 8 11:18:33 	dhcp6c 	58179 	Sending Release
Mar 8 11:18:32 	dhcp6c 	58179 	removing an event on pppoe0, state=INIT
Mar 8 11:18:32 	dhcp6c 	58179 	reset a timer on pppoe0, state=INIT, timeo=0, retrans=256
Mar 8 11:18:32 	dhcp6c 	58179 	remove a site prefix 2001:xxxx:xxx:xxx::/56
Mar 8 11:18:32 	dhcp6c 	58179 	remove an IA: PD-0
Mar 8 11:18:32 	dhcp6c 	58179 	send release to ff02::1:2%pppoe0
Mar 8 11:18:32 	dhcp6c 	58179 	set IA_PD
Mar 8 11:18:32 	dhcp6c 	58179 	set IA_PD prefix
Mar 8 11:18:32 	dhcp6c 	58179 	set elapsed time (len 2)
Mar 8 11:18:32 	dhcp6c 	58179 	set server ID (len 10)
Mar 8 11:18:32 	dhcp6c 	58179 	set client ID (len 14)
Mar 8 11:18:32 	dhcp6c 	58179 	a new XID (7c6018) is generated
Mar 8 11:18:32 	dhcp6c 	58179 	Sending Release
Mar 8 11:18:32 	dhcp6c 	58179 	reset a timer on pppoe0, state=RELEASE, timeo=0, retrans=911
Mar 8 11:18:32 	dhcp6c 	58179 	release an IA: PD-0
Mar 8 11:18:32 	dhcp6c 	58179 	Start address release

So this is it.

I`ve tried with "Do not allow PD/Address release", same thing…
Tried also some other options from GUI, nothing helps.

Also tried unplugging UTP and let pppoe die completley and same thing.

If link flaps for 1 second I loose IPv6.

I posted here before opening redmine ticket to see, if maybe this is config error on my side.

Thanks in advance :)
gateway_status.png_thumb

dhcpv6_2.PNG_thumb

dhcpv6_1.PNG_thumb

maverick_slo

Awww just saw this: https://redmine.pfsense.org/issues/7330
Same?

the_MiCrO

I think it is the same …

maverick_slo

Well we got half working PPPoE then :(

In addition I`ve noticed that sometimes pppoe does not get IPv6 address and sometimes does.
IPv6 on hosts works just fine it only affects gateway monitoring (status PENDING always)…

Sigh...

maverick_slo

This thing is completley broken…
It releases my /56 which is ok, then releases my /64 on wan which is also ok, then it renews only wan /64 and not /56 as well... If link even blinks, I'm without IPv6...

@maverick_slo:

This thing is completley broken…
It releases my /56 which is ok, then releases my /64 on wan which is also ok, then it renews only wan /64 and not /56 as well... If link even blinks, I'm without IPv6...

One of my testers is suffering from a similar issue, WAN flap causes loss of IPv6 in certain cases. We are working on a fix for it and it may be the same issue that is causing your problem. We think we have nailed it but testing is not complete yet, but so far it's looks to have resolved it.

Can I ask what hardware you are using, modem and pfsense hardware and which ISP you are with?

maverick_slo

Hi!
Modem is some generic ftth crap, I use intel nics and isp is Telekom from my country…
Care to share fix?

maverick_slo

Hmm I`ve applied: https://github.com/pfsense/pfsense/pull/3515.diff
via system patches…

Same thing, so this does not fix my issue...

Mar 11 11:10:04 	dhcp6c 	23264 	exiting
Mar 11 11:10:04 	dhcp6c 	23264 	script "/var/etc/dhcp6c_opt2_script.sh" terminated
Mar 11 11:10:03 	dhcp6c 		dhcp6c EXIT or RELEASE on pppoe0 running rc.newwanipv6
Mar 11 11:10:03 	dhcp6c 	23264 	executes /var/etc/dhcp6c_opt2_script.sh
Mar 11 11:10:03 	dhcp6c 	23264 	removing an event on pppoe0, state=INIT
Mar 11 11:10:03 	dhcp6c 	23264 	reset a timer on pppoe0, state=INIT, timeo=0, retrans=118
Mar 11 11:10:03 	dhcp6c 	23264 	remove a site prefix 2001:xxxx:xxx:xxx::/56
Mar 11 11:10:03 	dhcp6c 	23264 	remove an IA: PD-0
Mar 11 11:10:03 	dhcp6c 	23264 	Bypassing address release because of -n flag

So it removes my /56 prefix and after pppoe reconnects prefix never comes back…

So what do the logs say when it comes back up. Also need to see youy system logs. As a note, I don't post patch links for processes we are testing, you do that at your own risk.

Which mode are you running dhcp6c in 'Do not wait for a RA' or default?

maverick_slo

Above log is what it produces from moment i disconnect utp to a moment pppoe is back up and running.
I use default mode, so I wait for ra.
If I set it otherwise it won't work…

Can you post your system log showing the same times plus the next sixty seconds. I want to see what RTSOLD is doing.

maverick_slo

Sure just gimme a sec my 7 month baby is sleeping on me

maverick_slo

Forgot to ask…
With or without patch applied?

severach

Here in Michigan we're recovering from power problems. Comcast is having trouble keeping their stuff working. To restore IPv6 I:

LAN
IPv6 Configuration Type: Static
IPv6 address: (blank)
Save
Ignore error: The following input errors were detected: The field IPv6 address is required.
IPv6 Configuration Type: Track Interface
Save
Apply

Connectivity is restored.

maverick_slo

OK without patch…

DHCP6C logs:

Mar 11 21:04:46 	dhcp6c 	50640 	exiting
Mar 11 21:04:46 	dhcp6c 	50640 	script "/var/etc/dhcp6c_opt2_script.sh" terminated
Mar 11 21:04:46 	dhcp6c 	50640 	executes /var/etc/dhcp6c_opt2_script.sh
Mar 11 21:04:46 	dhcp6c 	50640 	removing an event on pppoe0, state=INIT
Mar 11 21:04:46 	dhcp6c 	50640 	reset a timer on pppoe0, state=INIT, timeo=0, retrans=118
Mar 11 21:04:46 	dhcp6c 	50640 	remove a site prefix 2001:xxxx:xxx:xxx::/56
Mar 11 21:04:46 	dhcp6c 	50640 	remove an IA: PD-0
Mar 11 21:04:46 	dhcp6c 	50640 	Bypassing address release because of -n flag

System log:


Mar 11 21:08:41 	gateway.rasca.local 		nginx: 2017/03/11 21:08:41 [error] 89046#100576: send() failed (54: Connection reset by peer)
Mar 11 21:08:20 	kernel 		em1_vlan8: promiscuous mode enabled
Mar 11 21:06:07 	kernel 		em0_vlan7: promiscuous mode enabled
Mar 11 21:06:07 	kernel 		em0: promiscuous mode enabled
Mar 11 21:06:07 	SnortStartup 	30040 	Snort START for Snort LAN192(26951_em1_vlan8)...
Mar 11 21:05:36 	check_reload_status 		Reloading filter
Mar 11 21:05:36 	check_reload_status 		Syncing firewall
Mar 11 21:05:33 	php-fpm 	6743 	/rc.start_packages: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was ''
Mar 11 21:05:28 	supervise/syslog-ng 	52432 	Daemon exited gracefully, not restarting; exitcode='0'
Mar 11 21:05:28 	php-fpm 	6743 	/rc.start_packages: Reloading syslog-ng for configuration sync
Mar 11 21:05:27 	check_reload_status 		Syncing firewall
Mar 11 21:05:26 	check_reload_status 		Syncing firewall
Mar 11 21:05:24 	php-fpm 	6743 	/rc.start_packages: [lightsquid] Updating cronjobs...
Mar 11 21:05:24 	check_reload_status 		Syncing firewall
Mar 11 21:05:22 	check_reload_status 		Syncing firewall
Mar 11 21:05:20 	php-fpm 	6743 	/rc.start_packages: [lightsquid] Removing old cronjobs...
Mar 11 21:05:20 	php-fpm 	6743 	/rc.start_packages: [lightsquid] Successfully created '/usr/local/etc/lightsquid/lightsquid.cfg' configuration file.
Mar 11 21:05:20 	php-fpm 	6743 	/rc.start_packages: [lightsquid] Loaded default '/usr/local/etc/lightsquid/lightsquid.cfg.sample' configuration file.
Mar 11 21:05:20 	check_reload_status 		Reloading filter
Mar 11 21:05:19 	php-fpm 	6743 	/rc.start_packages: [squid] Starting a proxy monitor script
Mar 11 21:05:19 	php-fpm 	6743 	/rc.start_packages: [squid] Reloading for configuration sync...
Mar 11 21:05:18 	php-fpm 	6743 	/rc.start_packages: [squid] Stopping any running proxy monitors
Mar 11 21:05:18 	check_reload_status 		Syncing firewall
Mar 11 21:05:16 	php-fpm 	6743 	/rc.start_packages: [squid] Removing freshclam cronjob.
Mar 11 21:05:16 	php-fpm 	6743 	/rc.start_packages: [squid] Antivirus features disabled.
Mar 11 21:05:16 	php-fpm 	6743 	/rc.start_packages: [squid] Adding cronjobs ...
Mar 11 21:05:12 	php-fpm 	6743 	/rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Mar 11 21:05:12 	SnortStartup 	66694 	Ignoring additional START command since Snort is already starting...
Mar 11 21:05:12 	php-fpm 	6743 	/rc.start_packages: Restarting/Starting all packages.
Mar 11 21:05:10 	check_reload_status 		Starting packages
Mar 11 21:05:10 	php-fpm 	83243 	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 212.xx.xx.xxx -> 212.xx.xx.xxx - Restarting packages.
Mar 11 21:05:08 	php-fpm 	83243 	/rc.newwanip: Creating rrd update script
Mar 11 21:05:08 	php-fpm 	83243 	/rc.newwanip: Resyncing OpenVPN instances for interface PPPOE.
Mar 11 21:05:06 	dhcpleases 		kqueue error: unkown
Mar 11 21:05:06 	php-fpm 	83243 	/rc.newwanip: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1489262706] unbound[91239:0] error: bind: address already in use [1489262706] unbound[91239:0] fatal error: could not open ports'
Mar 11 21:05:05 	check_reload_status 		Reloading filter
Mar 11 21:05:05 	check_reload_status 		updating dyndns opt2
Mar 11 21:05:03 	dhcpleases 		kqueue error: unkown
Mar 11 21:05:00 	dhcpleases 		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Mar 11 21:04:59 	dhcpleases 		/etc/hosts changed size from original!
Mar 11 21:04:58 	php-fpm 	35400 	/rc.filter_configure_sync: Gateways status could not be determined, considering all as up/active. (Group: GWGRP_IPv6)
Mar 11 21:04:57 	php-fpm 	83243 	/rc.newwanip: Removing static route for monitor 2001:xxxx:xxxx:xxxx:xxxx and adding a new route through fe80::xxx:xxxx:xxxx:xxxx%pppoe0
Mar 11 21:04:57 	php-fpm 	83243 	/rc.newwanip: ROUTING: setting IPv6 default route to fe80::xxx:xxxx:xxxx:xxxx%pppoe0
Mar 11 21:04:57 	check_reload_status 		Reloading filter
Mar 11 21:04:56 	dhcpleases 		Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Mar 11 21:04:56 	php-fpm 	83243 	/rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: GWGRP_IPv6)
Mar 11 21:04:56 	php-fpm 	83243 	/rc.newwanip: rc.newwanip: on (IP address: xxx.xx.xx.185) (interface: PPPOE[opt2]) (real interface: pppoe0).
Mar 11 21:04:56 	php-fpm 	83243 	/rc.newwanip: rc.newwanip: Info: starting on pppoe0.
Mar 11 21:04:55 	php-fpm 	10045 	/rc.newwanipv6: Removing static route for monitor 2001:xxxx:xxxx:xxxx:xxxx and adding a new route through fe80::xxx:xxxx:xxxx:xxxx%pppoe0
Mar 11 21:04:55 	php-fpm 	10045 	/rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::xxx:xxxx:xxxx:xxxx%pppoe0
Mar 11 21:04:55 	php-fpm 	10045 	/rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:xxxx:xxx:x:xxx:xxx:xxxx:xxxx) (interface: opt2) (real interface: pppoe0).
Mar 11 21:04:55 	php-fpm 	10045 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Mar 11 21:04:55 	rtsold 		RTSOLD Lock in place
Mar 11 21:04:55 	rtsold 		Received RA specifying route fe80::xxx:xxxx:xxxx:xxxx for interface opt2(pppoe0)
Mar 11 21:04:55 	dhcpleases 		/etc/hosts changed size from original!
Mar 11 21:04:55 	check_reload_status 		rc.newwanip starting pppoe0
Mar 11 21:04:54 	ppp 		[opt2] xxx.xx.xx.185 -> xxx.xx.xx.174
Mar 11 21:04:54 	ppp 		[opt2] IPCP: LayerUp
Mar 11 21:04:54 	ppp 		[opt2] IPCP: state change Ack-Sent --> Opened
Mar 11 21:04:54 	ppp 		[opt2] IPADDR xxx.xx.xx.185
Mar 11 21:04:54 	ppp 		[opt2] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Mar 11 21:04:54 	ppp 		[opt2] IPADDR xxx.xx.xx.185
Mar 11 21:04:54 	ppp 		[opt2] IPCP: SendConfigReq #3
Mar 11 21:04:54 	ppp 		[opt2] xxx.xx.xx.185 is OK
Mar 11 21:04:54 	ppp 		[opt2] IPADDR xxx.xx.xx.185
Mar 11 21:04:54 	ppp 		[opt2] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Mar 11 21:04:54 	ppp 		[opt2] IFACE: Rename interface ng0 to pppoe0
Mar 11 21:04:54 	ppp 		[opt2] IFACE: Up event
Mar 11 21:04:54 	check_reload_status 		rc.newwanipv6 starting pppoe0
Mar 11 21:04:54 	check_reload_status 		Restarting ipsec tunnels
Mar 11 21:04:54 	php-fpm 	66848 	/rc.linkup: ROUTING: setting IPv6 default route to fe80::xxx:xxxx:xxxx:xxxx%pppoe0
Mar 11 21:04:54 	php 		/usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
Mar 11 21:04:54 	ppp 		[opt2] 020e:xxxx:xxxx:xxxx -> 02c1:xxxx:xxxx:xxxx
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: LayerUp
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: state change Ack-Sent --> Opened
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: rec'd Configure Ack #1 (Ack-Sent)
Mar 11 21:04:54 	ppp 		[opt2] IPADDR 0.0.0.0
Mar 11 21:04:54 	ppp 		[opt2] IPCP: SendConfigReq #2
Mar 11 21:04:54 	ppp 		[opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 11 21:04:54 	ppp 		[opt2] IPCP: rec'd Configure Reject #1 (Ack-Sent)
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: state change Req-Sent --> Ack-Sent
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: SendConfigAck #1
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: rec'd Configure Request #1 (Req-Sent)
Mar 11 21:04:54 	ppp 		[opt2] IPCP: state change Req-Sent --> Ack-Sent
Mar 11 21:04:54 	ppp 		[opt2] IPADDR xxx.xx.xx.174
Mar 11 21:04:54 	ppp 		[opt2] IPCP: SendConfigAck #1
Mar 11 21:04:54 	ppp 		[opt2] xxx.xx.xx.174 is OK
Mar 11 21:04:54 	ppp 		[opt2] IPADDR xxx.xx.xx.174
Mar 11 21:04:54 	ppp 		[opt2] IPCP: rec'd Configure Request #1 (Req-Sent)
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: SendConfigReq #1
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: state change Starting --> Req-Sent
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: Up event
Mar 11 21:04:54 	ppp 		[opt2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 11 21:04:54 	ppp 		[opt2] IPADDR 0.0.0.0
Mar 11 21:04:54 	ppp 		[opt2] IPCP: SendConfigReq #1
Mar 11 21:04:54 	ppp 		[opt2] IPCP: state change Starting --> Req-Sent
Mar 11 21:04:54 	ppp 		[opt2] IPCP: Up event
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: LayerStart
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: state change Initial --> Starting
Mar 11 21:04:54 	ppp 		[opt2] IPV6CP: Open event
Mar 11 21:04:54 	ppp 		[opt2] IPCP: LayerStart
Mar 11 21:04:54 	ppp 		[opt2] IPCP: state change Initial --> Starting
Mar 11 21:04:54 	ppp 		[opt2] IPCP: Open event
Mar 11 21:04:54 	ppp 		[opt2] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Mar 11 21:04:54 	ppp 		[opt2_link0] Link: Join bundle "opt2"
Mar 11 21:04:54 	ppp 		[opt2_link0] Link: Matched action 'bundle "opt2" ""'
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: authorization successful
Mar 11 21:04:54 	ppp 		[opt2_link0] CHAP: rec'd SUCCESS #1 len: 4
Mar 11 21:04:54 	ppp 		[opt2_link0] CHAP: sending RESPONSE #1 len: 37
Mar 11 21:04:54 	ppp 		[opt2_link0] CHAP: Using authname "xxxxxx@xxxxx.net"
Mar 11 21:04:54 	ppp 		[opt2_link0] Name: "asr-bb"
Mar 11 21:04:54 	ppp 		[opt2_link0] CHAP: rec'd CHALLENGE #1 len: 27
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: LayerUp
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: auth: peer wants CHAP, I want nothing
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: state change Ack-Sent --> Opened
Mar 11 21:04:54 	ppp 		[opt2_link0] MAGICNUM 0x5g54356
Mar 11 21:04:54 	ppp 		[opt2_link0] MRU 1492
Mar 11 21:04:54 	ppp 		[opt2_link0] PROTOCOMP
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
Mar 11 21:04:54 	ppp 		[opt2_link0] MAGICNUM 0x5g54356
Mar 11 21:04:54 	ppp 		[opt2_link0] MRU 1492
Mar 11 21:04:54 	ppp 		[opt2_link0] PROTOCOMP
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: SendConfigReq #2
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: state change Req-Sent --> Ack-Sent
Mar 11 21:04:54 	ppp 		[opt2_link0] MAGICNUM 0x5g54356
Mar 11 21:04:54 	ppp 		[opt2_link0] AUTHPROTO CHAP MD5
Mar 11 21:04:54 	ppp 		[opt2_link0] MRU 1492
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: SendConfigAck #1
Mar 11 21:04:54 	ppp 		[opt2_link0] MAGICNUM 0x5g54356
Mar 11 21:04:54 	ppp 		[opt2_link0] AUTHPROTO CHAP MD5
Mar 11 21:04:54 	ppp 		[opt2_link0] MRU 1492
Mar 11 21:04:54 	ppp 		[opt2_link0] LCP: rec'd Configure Request #1 (Req-Sent)
Mar 11 21:04:52 	ppp 		[opt2_link0] MAGICNUM 0x5g54356
Mar 11 21:04:52 	ppp 		[opt2_link0] MRU 1492
Mar 11 21:04:52 	ppp 		[opt2_link0] PROTOCOMP
Mar 11 21:04:52 	ppp 		[opt2_link0] LCP: SendConfigReq #1
Mar 11 21:04:52 	ppp 		[opt2_link0] LCP: state change Starting --> Req-Sent
Mar 11 21:04:52 	ppp 		[opt2_link0] LCP: Up event
Mar 11 21:04:52 	ppp 		[opt2_link0] Link: UP event
Mar 11 21:04:52 	ppp 		[opt2_link0] PPPoE: connection successful
Mar 11 21:04:51 	ppp 		PPPoE: rec'd ACNAME "asr-bb"
Mar 11 21:04:51 	ppp 		[opt2_link0] PPPoE: Connecting to ''
Mar 11 21:04:51 	ppp 		[opt2_link0] LCP: LayerStart
Mar 11 21:04:51 	ppp 		[opt2_link0] LCP: state change Initial --> Starting
Mar 11 21:04:51 	ppp 		[opt2_link0] LCP: Open event
Mar 11 21:04:51 	kernel 		ng0: changing name to 'pppoe0'
Mar 11 21:04:51 	ppp 		[opt2_link0] Link: OPEN event
Mar 11 21:04:51 	ppp 		[opt2] Bundle: Interface ng0 created
Mar 11 21:04:51 	ppp 		web: web is not running
Mar 11 21:04:51 	ppp 		process 4070 terminated
Mar 11 21:04:51 	ppp 		[opt2_link0] Link: Shutdown
Mar 11 21:04:51 	ppp 		[opt2] Bundle: Shutdown
Mar 11 21:04:50 	ppp 		waiting for process 4070 to die...
Mar 11 21:04:49 	ppp 		waiting for process 4070 to die...
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: state change Closed --> Initial
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: Down event
Mar 11 21:04:49 	ppp 		[opt2_link0] Link: DOWN event
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: LayerFinish
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: state change Closing --> Closed
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: rec'd Terminate Ack #3 (Closing)
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: LayerDown
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: SendTerminateReq #3
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: state change Closed --> Initial
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: Down event
Mar 11 21:04:49 	ppp 		[opt2] IPCP: state change Closed --> Initial
Mar 11 21:04:49 	ppp 		[opt2] IPCP: Down event
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: Close event
Mar 11 21:04:49 	ppp 		[opt2] IPCP: Close event
Mar 11 21:04:49 	ppp 		[opt2] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Mar 11 21:04:49 	ppp 		[opt2_link0] Link: Leave bundle "opt2"
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: state change Opened --> Closing
Mar 11 21:04:49 	ppp 		[opt2_link0] LCP: Close event
Mar 11 21:04:49 	ppp 		[opt2_link0] Link: CLOSE event
Mar 11 21:04:49 	ppp 		[opt2] IPCP: rec'd Terminate Ack #5 (Closed)
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: rec'd Terminate Ack #3 (Closed)
Mar 11 21:04:49 	ppp 		[opt2] Bundle: closing link "opt2_link0"...
Mar 11 21:04:49 	ppp 		[opt2] Bundle: No NCPs left. Closing links...
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: LayerFinish
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: state change Closing --> Closed
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: rec'd Terminate Ack #2 (Closing)
Mar 11 21:04:49 	ppp 		[opt2] IPCP: LayerFinish
Mar 11 21:04:49 	ppp 		[opt2] IPCP: state change Closing --> Closed
Mar 11 21:04:49 	ppp 		[opt2] IPCP: rec'd Terminate Ack #4 (Closing)
Mar 11 21:04:49 	ppp 		[opt2] IPCP: SendTerminateReq #5
Mar 11 21:04:49 	ppp 		[opt2] IPV6CP: SendTerminateReq #3
Mar 11 21:04:49 	ppp 		[opt2] IFACE: Rename interface pppoe0 to pppoe0
Mar 11 21:04:49 	ppp 		[opt2] IFACE: Down event
Mar 11 21:04:49 	check_reload_status 		Rewriting resolv.conf
Mar 11 21:04:48 	ppp 		waiting for process 4070 to die...
Mar 11 21:04:47 	ppp 		waiting for process 4070 to die...
Mar 11 21:04:46 	ppp 		waiting for process 4070 to die...
Mar 11 21:04:46 	php-fpm 	72868 	/rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface PPPOE [opt2].
Mar 11 21:04:46 	php-fpm 	72868 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Mar 11 21:04:45 	ppp 		waiting for process 4070 to die...
Mar 11 21:04:45 	ppp 		[opt2] IPV6CP: LayerDown
Mar 11 21:04:45 	ppp 		[opt2] IPV6CP: SendTerminateReq #2
Mar 11 21:04:45 	ppp 		[opt2] IPV6CP: state change Opened --> Closing
Mar 11 21:04:45 	ppp 		[opt2] IPV6CP: Close event
Mar 11 21:04:45 	ppp 		[opt2] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
Mar 11 21:04:45 	check_reload_status 		Rewriting resolv.conf
Mar 11 21:04:44 	ppp 		[opt2] IPCP: LayerDown
Mar 11 21:04:44 	ppp 		[opt2] IPCP: SendTerminateReq #4
Mar 11 21:04:44 	ppp 		[opt2] IPCP: state change Opened --> Closing
Mar 11 21:04:44 	ppp 		[opt2] IPCP: Close event
Mar 11 21:04:44 	ppp 		[opt2] IFACE: Close event
Mar 11 21:04:44 	ppp 		caught fatal signal TERM
Mar 11 21:04:44 	ppp 		waiting for process 4070 to die...
Mar 11 21:04:44 	ppp 		process 72353 started, version 5.8 (nobody@pfSense_master_amd64-pfSense_devel-job-04 20:47 20-Oct-2016)
Mar 11 21:04:44 	ppp 		Multi-link PPP daemon for FreeBSD
Mar 11 21:04:43 	kernel 		em3: link state changed to UP
Mar 11 21:04:43 	check_reload_status 		Linkup starting em3
Mar 11 21:04:39 	check_reload_status 		Reloading filter
Mar 11 21:04:38 	kernel 		em3: link state changed to DOWN
Mar 11 21:04:38 	check_reload_status 		Linkup starting em3

BR

maverick_slo

On disconnect via interfaces page and reconnect there is this in syslog:

Mar 11 21:19:47 rtsold Starting dhcp6 client for interface opt2(pppoe0)
Mar 11 21:19:47 rtsold Received RA specifying route fe80::xxx:xxxx:xxxx:xxxxfor interface opt2(pppoe0)

So it is not removing lock when PPPoE is disconnected via link event.
If you disconnect pppoe via interfaces page then it removes lock and runs dhcp6 client just fine.

@maverick_slo:

On disconnect via interfaces page and reconnect there is this in syslog:

Mar 11 21:19:47 rtsold Starting dhcp6 client for interface opt2(pppoe0)
Mar 11 21:19:47 rtsold Received RA specifying route fe80::xxx:xxxx:xxxx:xxxxfor interface opt2(pppoe0)

So it is not removing lock when PPPoE is disconnected via link event.
If you disconnect pppoe via interfaces page then it removes lock and runs dhcp6 client just fine.

Yes, and that works, now pull the cable and show the system log that gets displayed there.

Also, can you add this patch, do not remove the others, just add this one and see if it makes any difference. It's the only other place I can find where dhcp6c is killed directly. It needs to be killed using a process, that process also removes any locks.

2d81d94e1d96dacae82cf4c60a4f069c066d22ec

maverick_slo

Ummm see post before last one.. There are logs what happens on cable unplug…
Tried patch aswell same results...

And that is not what the log should say if you have the correct patches in place.

Mar 11 21:04:55 rtsold RTSOLD Lock in place

has been replaced.

The current debug message says "RTSOLD Lock in place - sending SIGHUP to dhcp6c.". I changed it so I could be sure testers were running the correct patches.

The patches are:

718cbc2d3921627e9767e59d539386c843dffcc4
ea4de27b15441763bd227a2a942df522d98775c8
2d81d94e1d96dacae82cf4c60a4f069c066d22ec

Applied in that order.

And one more to add, just found another posix_kill() that would leave the lock behind.

e660bd4f34245958a290240c04afacb0823d4b74

maverick_slo

Hmm yes I know it changed to RTSOLD Lock in place - sending SIGHUP to dhcp6c. But patch unfortunatley has no effect. Will try latest tomorrow and report back.