[solved] PPPoE IA-PD woes

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.

maverick_slo

Hehe now you nailed it :)
It works perfect with one exception which I dont know if its related…

Tried 10 times.
6 times all ok but in 4 times I got no IPv6 address on my pppoe iface.
Everything works as expected exept gateway monitoring (it shows status pending because ipv6 address is missing on ppoe).

I don`t know why it happens it seems really random.

Thanks!

maverick_slo

Ha! Managed to replicate when pppoe does not obtain ipv6 address…

So if link flaps for 10 seconds or just modem reboots there is no problem.

But when link is down more than that and LCP echo requests start to fail or pppoe reconnect after 5th LCP missing is exectuted, then pppoe does NOT obtain IPv6 address and gateway is marked as pending.
IPv6 from firewall and subnets is working just fine, again just gateway monitoring is impacted...

BR,
Greg

That's good news. My bad for not thouroughly checking for any other posix_Kill() calls for dhcp6c so sorry for that.

I have noticed that sometimes the gateway monitor does not reflect the real state after an up/down event. I tend to no believe it if I can see the addresses are all there and just leave it, the page refresh always seems to sort it out after a while.

I'll merge those commits into one later today and update the PR.

doktornotor

@marjohn56:

The patches are:

718cbc2d3921627e9767e59d539386c843dffcc4
ea4de27b15441763bd227a2a942df522d98775c8
2d81d94e1d96dacae82cf4c60a4f069c066d22ec
e660bd4f34245958a290240c04afacb0823d4b74

At the risk of looking dense - what patches where? Is there some PR for this?

maverick_slo

I would be sarcastic but Ill leave that to you good ol doc :)

https://github.com/pfsense/pfsense/pull/3515

@maverick_slo:

I would be sarcastic but Ill leave that to you good ol doc :)

https://github.com/pfsense/pfsense/pull/3515

:D

Note that if you apply the lot you'll get REASONS working too, you should see some effects from dhcp6 renews no longer triggering wan updates, makes the logs much quieter.

doktornotor

I did not mean to be sarcastic, I wanted to make sure that there's a proper PR for this, otherwise you end up with half of the patches getting lost and things broken

maverick_slo

J/K :)

About my IPv6 on pppoe iface issue, should I start new thread/redmine or is it somehow connected to this?

@maverick_slo:

J/K :)

About my IPv6 on pppoe iface issue, should I start new thread/redmine or is it somehow connected to this?

It's ALL related in there somewhere, but gateway monitoring is not an area of pfsense I'm familiar with, so whether its related to locks and reasons, i'm summing the two, or something else thats always been there I have no idea… at the moment.

I'll snapshot my test system and do the patches, then I'll throw some curved balls at it and see if I can replicate the monitoring issue. On a side note, I'm changing ISP in a couple of weeks and my v6 will no longer be dhcp6 without RA ( that's a mismomer and we should change it! ) but similar to Mav*Slo, so I will be able to see exactly what's going on there.

maverick_slo

No no, gateway monitoring is just consequence…

Look what I mean:

When things are 100% OK:


Status
    up
PPPoE
    up 
Uptime
    00:01:50
MAC Address
    00:00:00:00:00:00
IPv4 Address
    212.xx.xx.xxx
Subnet mask IPv4
    255.255.255.255
Gateway IPv4
    212.xx.xx.xxx
IPv6 Link Local
    fe80::xxx:xxx:xxxx:xxxx%pppoe0
IPv6 Address
    2001:xxxx:xxx:x:xxx:xxx:xxxx:xxxx
Subnet mask IPv6
    64
Gateway IPv6
    fe80::xxx:xxxx:xxxx:xxxx
MTU
    1492
In/out packets
    1543787/651379 (1.61 GiB/46.27 MiB)
In/out packets (pass)
    1543787/651379 (1.61 GiB/46.27 MiB)
In/out packets (block)
    2393/0 (137 KiB/0 B)
In/out errors
    0/0
Collisions
    0

And when there is no IPv6 on PPPoe:


Status
    up
PPPoE
    up 
Uptime
    00:00:23
MAC Address
    00:00:00:00:00:00
IPv4 Address
    212.xx.xx.xxx
Subnet mask IPv4
    255.255.255.255
Gateway IPv4
    212.xx.xx.xxx
IPv6 Link Local
    fe80::xxx:xxx:xxxx:xxxx%pppoe0
Gateway IPv6
    fe80::xxx:xxxx:xxxx:xxxx
MTU
    1492
In/out packets
    1545272/656932 (1.61 GiB/46.65 MiB)
In/out packets (pass)
    1545272/656932 (1.61 GiB/46.65 MiB)
In/out packets (block)
    2418/0 (137 KiB/0 B)
In/out errors
    0/0
Collisions
    0

Can you do a test for me, go to the shell, and firstly check that dhcp6c is running, if it is, then can you send it a SIGHUP, SIGHUP being 'kill -1 PID', see if that makes it recover.

maverick_slo

DHCP6c IS running.

root    39375   0.9  0.1   8348   2328  -  Ss   10:04      0:00.00 /usr/local/sbin/dhcp6c -D -c /var/etc/dhcp6c_opt2.conf -p /var/run/dhcp6c_pppoe0.pid pppoe0

Killed it:


kill -1 39375

No change on pppoe :(

maverick_slo

And quite a lot of:


Mar 12 10:14:33 	php-fpm 	80662 	/rc.newwanip: ROUTING: setting IPv6 default route to fe80::xxx:xxx:xxxx:xxxx%pppoe0
Mar 12 10:14:33 	php-fpm 	60486 	/rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface PPPOE [opt2].
Mar 12 10:14:33 	php-fpm 	60486 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0\. 
Mar 12 10:14:31 	php-fpm 	80662 	/rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface PPPOE [opt2].
Mar 12 10:14:31 	php-fpm 	80662 	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Mar 12 10:14:31 	rtsold 		Starting dhcp6 client for interface opt2(pppoe0)
Mar 12 10:14:31 	rtsold 		Received RA specifying route fe80::xxx:xxx:xxxx:xxxx for interface opt2(pppoe0)