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.
    

Log in to reply