Modify

Opened 7 years ago

Last modified 4 years ago

#9094 accepted defect

wide-dhcpv6-client fails to restart

Reported by: netztrip <dave-bjoht@…> Owned by: jow
Priority: normal Milestone: Netifd Implementation
Component: packages Version: Trunk
Keywords: wide-dhcpv6-client, ipv6 Cc:

Description

Currently, dhcp6c gets started via hotplug on ifup and killed on ifdown.

After the TERM signal, dhcp6c runs into a 30 second timeout trying to send a DHCP release message. This blocks the port for the new dhcp6c process if the interface comes up too fast.

Log with dhcp6c debugging enabled (ifdown wan && ifup wan):

Mar 20 18:09:25 OpenWrt daemon.info pppd[532]: Terminating on signal 15
Mar 20 18:09:25 OpenWrt daemon.info pppd[532]: Connect time 1.3 minutes.
Mar 20 18:09:25 OpenWrt daemon.info pppd[532]: Sent 50677 bytes, received 182130 bytes.
Mar 20 18:09:25 OpenWrt daemon.notice pppd[532]: Connection terminated.
Mar 20 18:09:25 OpenWrt daemon.info pppd[532]: Connect time 1.3 minutes.
Mar 20 18:09:25 OpenWrt daemon.info pppd[532]: Sent 50677 bytes, received 182130 bytes.
Mar 20 18:09:26 OpenWrt user.info firewall: removing wan (pppoe-wan) from zone wan
Mar 20 18:09:26 OpenWrt user.notice dhcp6c: stopping dhcp6c
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: release_ia: release an IA: PD-0
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: dhcp6_reset_timer: reset a timer on pppoe-wan, state=RELEASE, timeo=0, retrans=1034
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: client6_send: a new XID (50d195) is generated
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set client ID (len 10)
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set server ID (len 27)
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set elapsed time (len 2)
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD prefix
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD
Mar 20 18:09:26 OpenWrt daemon.err dhcp6c[1156]: client6_send: transmit failed: Network is unreachable
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: remove_ia: remove an IA: PD-0
Mar 20 18:09:26 OpenWrt daemon.debug dhcp6c[1156]: remove_siteprefix: remove a site prefix [snip]
Mar 20 18:09:26 OpenWrt daemon.warn radvd[1282]: Exiting, sigterm or sigint received.
Mar 20 18:09:26 OpenWrt daemon.info radvd[1996]: version 1.7 started
Mar 20 18:09:26 OpenWrt daemon.info pppd[532]: Exit.
Mar 20 18:09:26 OpenWrt user.info kernel: ADDRCONF(NETDEV_UP): eth1: link is not ready
Mar 20 18:09:26 OpenWrt daemon.info dnsmasq[1801]: reading /tmp/resolv.conf.auto
Mar 20 18:09:26 OpenWrt daemon.info dnsmasq[1801]: using nameserver [snip]
Mar 20 18:09:26 OpenWrt daemon.info dnsmasq[1801]: using nameserver [snip]
Mar 20 18:09:26 OpenWrt daemon.info dnsmasq[1801]: using local addresses only for domain lan
Mar 20 18:09:27 OpenWrt user.info kernel: ADDRCONF(NETDEV_UP): eth1: link is not ready
Mar 20 18:09:27 OpenWrt daemon.info pppd[2068]: Plugin rp-pppoe.so loaded.
Mar 20 18:09:27 OpenWrt daemon.notice pppd[2068]: pppd 2.4.4 started by root, uid 0
Mar 20 18:09:27 OpenWrt user.info kernel: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Mar 20 18:09:27 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set client ID (len 10)
Mar 20 18:09:27 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set server ID (len 27)
Mar 20 18:09:27 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set elapsed time (len 2)
Mar 20 18:09:27 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD prefix
Mar 20 18:09:27 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD
Mar 20 18:09:27 OpenWrt daemon.err dhcp6c[1156]: client6_send: transmit failed: Network is unreachable
Mar 20 18:09:27 OpenWrt daemon.debug dhcp6c[1156]: dhcp6_reset_timer: reset a timer on pppoe-wan, state=RELEASE, timeo=1, retrans=2091
Mar 20 18:09:29 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set client ID (len 10)
Mar 20 18:09:29 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set server ID (len 27)
Mar 20 18:09:29 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set elapsed time (len 2)
Mar 20 18:09:29 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD prefix
Mar 20 18:09:29 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD
Mar 20 18:09:29 OpenWrt daemon.err dhcp6c[1156]: client6_send: transmit failed: Network is unreachable
Mar 20 18:09:29 OpenWrt daemon.debug dhcp6c[1156]: dhcp6_reset_timer: reset a timer on pppoe-wan, state=RELEASE, timeo=2, retrans=4034
Mar 20 18:09:32 OpenWrt daemon.info pppd[2068]: PPP session is 2110
Mar 20 18:09:32 OpenWrt daemon.info pppd[2068]: Using interface pppoe-wan
Mar 20 18:09:32 OpenWrt daemon.notice pppd[2068]: Connect: pppoe-wan <--> eth1
Mar 20 18:09:33 OpenWrt daemon.info pppd[2068]: CHAP authentication succeeded
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: CHAP authentication succeeded
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: peer from calling number [snip] authorized
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: local  LL address [snip]
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: remote LL address [snip]
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: local  IP address [snip]
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: remote IP address [snip]
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: primary   DNS address [snip]
Mar 20 18:09:33 OpenWrt daemon.notice pppd[2068]: secondary DNS address [snip]
Mar 20 18:09:33 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set client ID (len 10)
Mar 20 18:09:33 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set server ID (len 27)
Mar 20 18:09:33 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set elapsed time (len 2)
Mar 20 18:09:33 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD prefix
Mar 20 18:09:33 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD
Mar 20 18:09:33 OpenWrt daemon.err dhcp6c[1156]: client6_send: transmit failed: Network is unreachable
Mar 20 18:09:33 OpenWrt daemon.debug dhcp6c[1156]: dhcp6_reset_timer: reset a timer on pppoe-wan, state=RELEASE, timeo=3, retrans=7910
Mar 20 18:09:34 OpenWrt user.notice dhcp6c: starting dhcp6c
Mar 20 18:09:34 OpenWrt user.info firewall: adding wan (pppoe-wan) to zone wan
Mar 20 18:09:34 OpenWrt user.notice dhcp6c: Using DUID [snip]
Mar 20 18:09:34 OpenWrt daemon.debug dhcp6c[2258]: get_duid: extracted an existing DUID from /var/dhcp6c_duid: [snip]
Mar 20 18:09:34 OpenWrt daemon.err dhcp6c[2258]: dhcp6_ctl_init: bind(control sock): Address already in use
Mar 20 18:09:34 OpenWrt daemon.err dhcp6c[2258]: client6_init: failed to initialize control channel
Mar 20 18:09:37 OpenWrt daemon.warn radvd[2001]: Exiting, sigterm or sigint received.
Mar 20 18:09:37 OpenWrt daemon.info dnsmasq[1801]: reading /tmp/resolv.conf.auto
Mar 20 18:09:37 OpenWrt daemon.info dnsmasq[1801]: using nameserver [snip]
Mar 20 18:09:37 OpenWrt daemon.info dnsmasq[1801]: using nameserver [snip]
Mar 20 18:09:37 OpenWrt daemon.info dnsmasq[1801]: using nameserver [snip]
Mar 20 18:09:37 OpenWrt daemon.info dnsmasq[1801]: using nameserver [snip]
Mar 20 18:09:37 OpenWrt daemon.info dnsmasq[1801]: using local addresses only for domain lan
Mar 20 18:09:37 OpenWrt daemon.info radvd[2333]: version 1.7 started
Mar 20 18:09:38 OpenWrt user.notice rdate: Synced with ptbtime2.ptb.de
Mar 20 18:09:38 OpenWrt user.notice dyndns: good 82.135.87.244
Mar 20 18:09:41 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set client ID (len 10)
Mar 20 18:09:41 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set server ID (len 27)
Mar 20 18:09:41 OpenWrt daemon.debug dhcp6c[1156]: copy_option: set elapsed time (len 2)
Mar 20 18:09:41 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD prefix
Mar 20 18:09:41 OpenWrt daemon.debug dhcp6c[1156]: copyout_option: set IA_PD
Mar 20 18:09:41 OpenWrt daemon.err dhcp6c[1156]: client6_send: transmit failed: Network is unreachable
Mar 20 18:09:41 OpenWrt daemon.debug dhcp6c[1156]: dhcp6_reset_timer: reset a timer on pppoe-wan, state=RELEASE, timeo=4, retrans=15714
Mar 20 18:09:57 OpenWrt daemon.info dhcp6c[1156]: client6_timo: no responses were received
Mar 20 18:09:57 OpenWrt daemon.debug dhcp6c[1156]: dhcp6_remove_event: removing an event on pppoe-wan, state=RELEASE
Mar 20 18:09:57 OpenWrt daemon.info dhcp6c[1156]: check_exit: exiting

Attachments (1)

wide-dhcpv6-dhcp6ctl.diff (2.6 KB) - added by netztrip <dave-bjoht@…> 7 years ago.

Download all attachments as: .zip

Change History (11)

comment:1 Changed 7 years ago by jow

  • Owner changed from developers to jow
  • Status changed from new to accepted

comment:2 follow-up: Changed 7 years ago by netztrip <dave-bjoht@…>

A possible solution is to keep dhcp6c running and use dhcp6ctl to start/stop managed interfaces. Unfortunately, this triggers another problem with dhcp6c (see bugs.debian.org & sourceforge.net).

The attached diff fixed these issues for me but I'm not sure this is the best solution. Feedback is much appreciated.

Changed 7 years ago by netztrip <dave-bjoht@…>

comment:3 in reply to: ↑ 2 Changed 7 years ago by anonymous

The dhcp6c bug mentioned below has been fixed with this patch in Debian.

But anyway, the fix in wide-dhcpv6-dhcp6ctl.diff seems to be only a workaround.
The real problem is, that dhcp6c is called in the ifdown hotplug-trigger, which means, that the interface pppoe-wan is already gone, which causes

Mar 20 18:09:26 OpenWrt daemon.err dhcp6c[1156]: client6_send: transmit failed: Network is unreachable.

So, on my Debian-system, I would propose to stop dhcp6c with a pre-down stanza in /etc/network/interfaces. Is there a way to achieve this in OpenWrt?

comment:4 Changed 6 years ago by anonymous

I'm having this problem on r29844
The pppoe connection was closed due to some ISP problems, and after reconnetion only the IPv4 settings were restored

    Feb  7 14:25:22 Voltron daemon.info pppd[24027]: No response to 5 echo-requests
    Feb  7 14:25:22 Voltron daemon.notice pppd[24027]: Serial link appears to be disconnected.
    Feb  7 14:25:22 Voltron daemon.info pppd[24027]: Connect time 10840.3 minutes.
    Feb  7 14:25:22 Voltron daemon.info pppd[24027]: Sent 1607512890 bytes, received 1852911136 bytes.
    Feb  7 14:25:22 Voltron daemon.debug radvd[25787]: attempting to reread config file
    Feb  7 14:25:22 Voltron daemon.debug radvd[25787]: resuming normal operation
    Feb  7 14:25:22 Voltron user.info firewall: removing wan (pppoe-wan) from zone wan
    Feb  7 14:25:23 Voltron user.notice dhcp6c: stopping dhcp6c
    Feb  7 14:25:23 Voltron daemon.err dhcp6c[25168]: client6_send: transmit failed: Network is unreachable
    Feb  7 14:25:24 Voltron daemon.err dhcp6c[25168]: client6_send: transmit failed: Network is unreachable
    Feb  7 14:25:26 Voltron daemon.err dhcp6c[25168]: client6_send: transmit failed: Network is unreachable
    Feb  7 14:25:28 Voltron daemon.err radvd[25787]: poll error: Interrupted system call
    Feb  7 14:25:28 Voltron daemon.warn radvd[25787]: Exiting, sigterm or sigint received.
    Feb  7 12:25:28 Voltron daemon.info dnsmasq[15420]: reading /tmp/resolv.conf.auto
    Feb  7 12:25:28 Voltron daemon.info dnsmasq[15420]: using nameserver 193.231.252.201#53
    Feb  7 12:25:28 Voltron daemon.info dnsmasq[15420]: using nameserver 213.154.124.201#53
    Feb  7 12:25:28 Voltron daemon.info dnsmasq[15420]: using local addresses only for domain lan
    Feb  7 14:25:28 Voltron daemon.notice pppd[24027]: Connection terminated.
    Feb  7 14:25:28 Voltron daemon.info pppd[24027]: Connect time 10840.3 minutes.
    Feb  7 14:25:28 Voltron daemon.info pppd[24027]: Sent 1607512890 bytes, received 1852911136 bytes.
    Feb  7 14:25:28 Voltron daemon.notice pppd[24027]: Modem hangup9
    Feb  7 14:25:29 Voltron daemon.info radvd[5929]: version 1.8.3 started
    Feb  7 14:26:13 Voltron daemon.warn pppd[24027]: Timeout waiting for PADO packets
    Feb  7 14:26:13 Voltron daemon.err pppd[24027]: Unable to complete PPPoE Discovery
    Feb  7 14:26:43 Voltron daemon.info pppd[24027]: PPP session is 1058
    Feb  7 14:26:43 Voltron daemon.warn pppd[24027]: Connected to XX:XX:XX:XX:XX:XX via interface eth1
    Feb  7 14:26:43 Voltron daemon.info pppd[24027]: Using interface pppoe-wan
    Feb  7 14:26:43 Voltron daemon.notice pppd[24027]: Connect: pppoe-wan <--> eth1
    Feb  7 14:26:43 Voltron daemon.debug radvd[5930]: attempting to reread config file
    Feb  7 14:26:43 Voltron daemon.debug radvd[5930]: resuming normal operation
    Feb  7 14:26:43 Voltron daemon.debug radvd[5930]: attempting to reread config file
    Feb  7 14:26:43 Voltron daemon.debug radvd[5930]: resuming normal operation
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: PAP authentication succeeded
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: peer from calling number XX:XX:XX:XX:XX:XX authorized
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: local  IP address XX.XXX.XX.XX
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: remote IP address 10.0.0.1
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: primary   DNS address 213.154.124.201
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: secondary DNS address 193.231.252.201
    Feb  7 14:26:46 Voltron daemon.debug radvd[5930]: attempting to reread config file
    Feb  7 14:26:46 Voltron daemon.debug radvd[5930]: resuming normal operation
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: local  LL address fe80::0000:0000:4f73:3c1c
    Feb  7 14:26:46 Voltron daemon.notice pppd[24027]: remote LL address fe80::0000:0000:0000:0001
    Feb  7 14:26:46 Voltron user.notice ifup: Allowing Router Advertisements on wan (pppoe-wan)
    Feb  7 14:26:46 Voltron user.notice ifup: Enabling Router Solicitations on wan (pppoe-wan)
    Feb  7 14:26:47 Voltron user.info firewall: adding wan (pppoe-wan) to zone wan
    Feb  7 14:26:47 Voltron user.notice dhcp6c: starting dhcp6c
    Feb  7 14:26:48 Voltron user.notice dhcp6c: Unable to derive DUID from interface 'pppoe-wan' and no valid user DUID given
    Feb  7 14:26:48 Voltron daemon.err dhcp6c[6314]: get_duid: DUID file corrupted
    Feb  7 14:26:48 Voltron daemon.err dhcp6c[6314]: client6_init: failed to get a DUID
    Feb  7 14:26:51 Voltron daemon.err radvd[5930]: poll error: Interrupted system call
    Feb  7 14:26:51 Voltron daemon.warn radvd[5930]: Exiting, sigterm or sigint received.
    Feb  7 14:26:51 Voltron daemon.info radvd[6533]: version 1.8.3 started
    Feb  7 12:26:53 Voltron daemon.info dnsmasq[15420]: reading /tmp/resolv.conf.auto
    Feb  7 12:26:53 Voltron daemon.info dnsmasq[15420]: using nameserver 2a02:2f01:30:201:0:405:465:1#53
    Feb  7 12:26:53 Voltron daemon.info dnsmasq[15420]: using nameserver 2a02:2f01:30:2:0:405:465:1#53
    Feb  7 12:26:53 Voltron daemon.info dnsmasq[15420]: using nameserver 193.231.252.201#53
    Feb  7 12:26:53 Voltron daemon.info dnsmasq[15420]: using nameserver 213.154.124.201#53
    Feb  7 12:26:53 Voltron daemon.info dnsmasq[15420]: using local addresses only for domain lan

Issuing /etc/init.d/dhcp6c restart results in:

Feb  7 15:37:10 Voltron user.notice dhcp6c: stopping dhcp6c
Feb  7 15:37:10 Voltron daemon.err radvd[6534]: poll error: Interrupted system call
Feb  7 15:37:10 Voltron daemon.warn radvd[6534]: Exiting, sigterm or sigint received.
Feb  7 15:37:10 Voltron daemon.info radvd[7234]: version 1.8.3 started
Feb  7 15:37:10 Voltron user.notice dhcp6c: starting dhcp6c
Feb  7 15:37:10 Voltron user.notice dhcp6c: Unable to derive DUID from interface 'pppoe-wan' and no valid user DUID given
Feb  7 15:37:10 Voltron daemon.err dhcp6c[7262]: get_duid: DUID file corrupted
Feb  7 15:37:10 Voltron daemon.err dhcp6c[7262]: client6_init: failed to get a DUID
Feb  7 13:37:11 Voltron daemon.info dnsmasq[15420]: reading /tmp/resolv.conf.auto
Feb  7 13:37:11 Voltron daemon.info dnsmasq[15420]: using nameserver 193.231.252.201#53
Feb  7 13:37:11 Voltron daemon.info dnsmasq[15420]: using nameserver 213.154.124.201#53
Feb  7 13:37:11 Voltron daemon.info dnsmasq[15420]: using local addresses only for domain lan
Feb  7 15:37:13 Voltron daemon.err radvd[7235]: poll error: Interrupted system call
Feb  7 15:37:13 Voltron daemon.warn radvd[7235]: Exiting, sigterm or sigint received.
Feb  7 15:37:13 Voltron daemon.info radvd[7305]: version 1.8.3 started
Feb  7 13:37:26 Voltron daemon.info dnsmasq[15420]: reading /tmp/resolv.conf.auto
Feb  7 13:37:26 Voltron daemon.info dnsmasq[15420]: using nameserver 2a02:2f01:30:201:0:405:465:1#53
Feb  7 13:37:26 Voltron daemon.info dnsmasq[15420]: using nameserver 2a02:2f01:30:2:0:405:465:1#53
Feb  7 13:37:26 Voltron daemon.info dnsmasq[15420]: using nameserver 193.231.252.201#53
Feb  7 13:37:26 Voltron daemon.info dnsmasq[15420]: using nameserver 213.154.124.201#53
Feb  7 13:37:26 Voltron daemon.info dnsmasq[15420]: using local addresses only for domain lan
Feb  7 15:37:33 Voltron user.notice dhcp6c: stopping dhcp6c
Feb  7 15:37:33 Voltron daemon.err radvd[7306]: poll error: Interrupted system call
Feb  7 15:37:33 Voltron daemon.warn radvd[7306]: Exiting, sigterm or sigint received.
Feb  7 15:37:34 Voltron daemon.info radvd[7393]: version 1.8.3 started
Feb  7 15:37:34 Voltron user.notice dhcp6c: starting dhcp6c
Feb  7 15:37:34 Voltron user.notice dhcp6c: Unable to derive DUID from interface 'pppoe-wan' and no valid user DUID given
Feb  7 15:37:34 Voltron daemon.err dhcp6c[7421]: get_duid: DUID file corrupted
Feb  7 15:37:34 Voltron daemon.err dhcp6c[7421]: client6_init: failed to get a DUID
Feb  7 15:37:37 Voltron daemon.err radvd[7394]: poll error: Interrupted system call
Feb  7 15:37:37 Voltron daemon.warn radvd[7394]: Exiting, sigterm or sigint received.
Feb  7 15:37:37 Voltron daemon.info radvd[7464]: version 1.8.3 started

I have to restart with /etc/init.d/network restart for IPv6 to work again.

comment:5 Changed 6 years ago by jow

  • Milestone set to Netifd Implementation

comment:6 Changed 6 years ago by Laurent Bigonville <l.bigonville@…>

Hi,

Any progress on this? The IPv6 day is the 6th of June, would be great if this was fixed before.

For me this bug makes the native IPv6 connection provided by my ISP difficult to use as the connection is reset every 36 hours which mean I loose have to restart everything again afterward

comment:7 Changed 6 years ago by jow

If there is progress it would be reflected here. You can try a build with netifd and see if it behaves better.

comment:8 Changed 6 years ago by anonymous

I understand that neifd is used by default now. Can anyone using trunk confirm that this is fixed?

comment:9 Changed 5 years ago by Laurent Bigonville <l.bigonville@…>

Yes this seems fixed, I'm running "ATTITUDE ADJUSTMENT (Bleeding Edge, r32656)" and my IPv6 connection works flawlessly even if my DSL connection get reset.

comment:10 Changed 4 years ago by clObxx

<a href=http://silvertoncustomhomes.com/lib/#k7>buy soma</a> buy soma 350 - soma san diego directions

Add Comment

Modify Ticket

Action
as accepted .
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.