Dhcp6c dies silently
-
I have an SG-2220 running current PFsense, and recently upgraded to gigabit cable Internet service with my provider (Midco). Since I did so, I've had a problem with IPv6 connectivity: Specifically that about every 24 hours, 'dhcp6c' silently dies. IPv6 works fine before its death, and if I manually restart it, the external interface takes an IPv6 address just fine, but approximately once every 24 hours, 'dhcp6c' just dies. Nothing in the log. I've turned on debug output for 'dhcp6c' and nothing is logged at all.
The command I'm running to start 'dhcp6c' myself (taken from the process as originally launched by PFsense) is:
/usr/local/sbin/dhcp6c -D -n -c /var/etc/dhcp6c_wan.conf -p /var/run/dhcp6c_igb0.pid igb0
This is the complete output from when I launched it yesterday; the output ends where it does because there was nothing more from this process after it started, until I had to manually relaunch it this morning to reacquire my IPv6 address.
Jul 16 06:13:46 jupiter dhcp6c[72580]: extracted an existing DUID from /var/db/dhcp6c_duid: 00:01:00:01:20:76:f9:d8:00:08:a2:0b:9a:7e Jul 16 06:13:46 jupiter dhcp6c[72580]: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory Jul 16 06:13:46 jupiter dhcp6c[72580]: failed initialize control message authentication Jul 16 06:13:46 jupiter dhcp6c[72580]: skip opening control port Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[interface] (9) Jul 16 06:13:46 jupiter dhcp6c[72580]: <5>[igb0] (4) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>begin of closure [{] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[send] (4) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[ia-na] (5) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[0] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>comment [# request stateful address] (26) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[send] (4) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[ia-pd] (5) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[0] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>comment [# request prefix delegation] (27) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[request] (7) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[domain-name-servers] (19) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[request] (7) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[domain-name] (11) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[script] (6) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>["/var/etc/dhcp6c_wan_script.sh"] (31) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>comment [# we'd like some nameservers please] (35) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of closure [}] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[id-assoc] (8) Jul 16 06:13:46 jupiter dhcp6c[72580]: <13>[na] (2) Jul 16 06:13:46 jupiter dhcp6c[72580]: <13>[0] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <13>begin of closure [{] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of closure [}] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[id-assoc] (8) Jul 16 06:13:46 jupiter dhcp6c[72580]: <13>[pd] (2) Jul 16 06:13:46 jupiter dhcp6c[72580]: <13>[0] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <13>begin of closure [{] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[prefix-interface] (16) Jul 16 06:13:46 jupiter dhcp6c[72580]: <5>[igb1] (4) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>begin of closure [{] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[sla-id] (6) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[0] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[sla-len] (7) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>[0] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of closure [}] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of closure [}] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: <3>end of sentence [;] (1) Jul 16 06:13:46 jupiter dhcp6c[72580]: called Jul 16 06:13:46 jupiter dhcp6c[72580]: called Jul 16 06:13:46 jupiter dhcp6c[72615]: reset a timer on igb0, state=INIT, timeo=0, retrans=383 Jul 16 06:13:47 jupiter dhcp6c[72615]: Sending Solicit Jul 16 06:13:47 jupiter dhcp6c[72615]: a new XID (33e823) is generated Jul 16 06:13:47 jupiter dhcp6c[72615]: set client ID (len 14) Jul 16 06:13:47 jupiter dhcp6c[72615]: set identity association Jul 16 06:13:47 jupiter dhcp6c[72615]: set elapsed time (len 2) Jul 16 06:13:47 jupiter dhcp6c[72615]: set option request (len 4) Jul 16 06:13:47 jupiter dhcp6c[72615]: set IA_PD Jul 16 06:13:47 jupiter dhcp6c[72615]: send solicit to ff02::1:2%igb0 Jul 16 06:13:47 jupiter dhcp6c[72615]: reset a timer on igb0, state=SOLICIT, timeo=0, retrans=1088 Jul 16 06:13:47 jupiter dhcp6c[72615]: receive advertise from fe80::25f:86ff:fe92:c819%igb0 on igb0 Jul 16 06:13:47 jupiter dhcp6c[72615]: get DHCP option client ID, len 14 Jul 16 06:13:47 jupiter dhcp6c[72615]: DUID: 00:01:00:01:20:76:f9:d8:00:08:a2:0b:9a:7e Jul 16 06:13:47 jupiter dhcp6c[72615]: get DHCP option server ID, len 14 Jul 16 06:13:47 jupiter dhcp6c[72615]: DUID: 00:01:00:01:56:96:2f:e5:00:1a:64:99:7b:bc Jul 16 06:13:47 jupiter dhcp6c[72615]: get DHCP option DNS, len 32 Jul 16 06:13:47 jupiter dhcp6c[72615]: get DHCP option identity association, len 40 Jul 16 06:13:47 jupiter dhcp6c[72615]: IA_NA: ID=0, T1=302400, T2=483840 Jul 16 06:13:47 jupiter dhcp6c[72615]: get DHCP option IA address, len 24 Jul 16 06:13:47 jupiter dhcp6c[72615]: IA_NA address: [redacted] pltime=604800 vltime=2592000 Jul 16 06:13:47 jupiter dhcp6c[72615]: get DHCP option IA_PD, len 41 Jul 16 06:13:47 jupiter dhcp6c[72615]: IA_PD: ID=0, T1=302400, T2=483840 Jul 16 06:13:47 jupiter dhcp6c[72615]: get DHCP option IA_PD prefix, len 25 Jul 16 06:13:47 jupiter dhcp6c[72615]: IA_PD prefix: [redacted]/64 pltime=604800 vltime=140733195980032 Jul 16 06:13:47 jupiter dhcp6c[72615]: server ID: 00:01:00:01:56:96:2f:e5:00:1a:64:99:7b:bc, pref=-1 Jul 16 06:13:47 jupiter dhcp6c[72615]: reset timer for igb0 to 0.952253 Jul 16 06:13:48 jupiter dhcp6c[72615]: picked a server (ID: 00:01:00:01:56:96:2f:e5:00:1a:64:99:7b:bc) Jul 16 06:13:48 jupiter dhcp6c[72615]: Sending Request Jul 16 06:13:48 jupiter dhcp6c[72615]: a new XID (10d959) is generated Jul 16 06:13:48 jupiter dhcp6c[72615]: set client ID (len 14) Jul 16 06:13:48 jupiter dhcp6c[72615]: set server ID (len 14) Jul 16 06:13:48 jupiter dhcp6c[72615]: set IA address Jul 16 06:13:48 jupiter dhcp6c[72615]: set identity association Jul 16 06:13:48 jupiter dhcp6c[72615]: set elapsed time (len 2) Jul 16 06:13:48 jupiter dhcp6c[72615]: set option request (len 4) Jul 16 06:13:48 jupiter dhcp6c[72615]: set IA_PD prefix Jul 16 06:13:48 jupiter dhcp6c[72615]: set IA_PD Jul 16 06:13:48 jupiter dhcp6c[72615]: send request to ff02::1:2%igb0 Jul 16 06:13:48 jupiter dhcp6c[72615]: reset a timer on igb0, state=REQUEST, timeo=0, retrans=977 Jul 16 06:13:48 jupiter dhcp6c[72615]: receive reply from fe80::25f:86ff:fe92:c819%igb0 on igb0 Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option client ID, len 14 Jul 16 06:13:48 jupiter dhcp6c[72615]: DUID: 00:01:00:01:20:76:f9:d8:00:08:a2:0b:9a:7e Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option server ID, len 14 Jul 16 06:13:48 jupiter dhcp6c[72615]: DUID: 00:01:00:01:56:96:2f:e5:00:1a:64:99:7b:bc Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option DNS, len 32 Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option identity association, len 46 Jul 16 06:13:48 jupiter dhcp6c[72615]: IA_NA: ID=0, T1=302400, T2=483840 Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option status code, len 2 Jul 16 06:13:48 jupiter dhcp6c[72615]: status code: success Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option IA address, len 24 Jul 16 06:13:48 jupiter dhcp6c[72615]: IA_NA address: [redacted] pltime=604800 vltime=2592000 Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option IA_PD, len 47 Jul 16 06:13:48 jupiter dhcp6c[72615]: IA_PD: ID=0, T1=302400, T2=483840 Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option status code, len 2 Jul 16 06:13:48 jupiter dhcp6c[72615]: status code: success Jul 16 06:13:48 jupiter dhcp6c[72615]: get DHCP option IA_PD prefix, len 25 Jul 16 06:13:48 jupiter dhcp6c[72615]: IA_PD prefix: [redacted]/64 pltime=604800 vltime=2592000 Jul 16 06:13:48 jupiter dhcp6c[72615]: dhcp6c Received REQUEST Jul 16 06:13:48 jupiter dhcp6c[72615]: nameserver[0] [redacted] Jul 16 06:13:48 jupiter dhcp6c[72615]: nameserver[1] [redacted] Jul 16 06:13:48 jupiter dhcp6c[72615]: make an IA: PD-0 Jul 16 06:13:48 jupiter dhcp6c[72615]: status code for PD-0: success Jul 16 06:13:48 jupiter dhcp6c[72615]: create a prefix [redacted]/64 pltime=140733193992832, vltime=140733195980032 Jul 16 06:13:48 jupiter dhcp6c[72615]: add an address [redacted]/64 on igb1 Jul 16 06:13:48 jupiter dhcp6c[72615]: make an IA: NA-0 Jul 16 06:13:48 jupiter dhcp6c[72615]: status code for NA-0: success Jul 16 06:13:48 jupiter dhcp6c[72615]: create an address [redacted] pltime=604800, vltime=2592000 Jul 16 06:13:48 jupiter dhcp6c[72615]: add an address [redacted]/128 on igb0 Jul 16 06:13:48 jupiter dhcp6c[72615]: executes /var/etc/dhcp6c_wan_script.sh Jul 16 06:13:50 jupiter dhcp6c[72615]: script "/var/etc/dhcp6c_wan_script.sh" terminated Jul 16 06:13:50 jupiter dhcp6c[72615]: removing an event on igb0, state=REQUEST Jul 16 06:13:50 jupiter dhcp6c[72615]: removing server (ID: 00:01:00:01:56:96:2f:e5:00:1a:64:99:7b:bc) Jul 16 06:13:50 jupiter dhcp6c[72615]: got an expected reply, sleeping.