FS#17838 - [dhcpcd] 5.1.4 transaction timeout
Attached to Project:
Arch Linux
Opened by Alexey Stukalov (alyst) - Thursday, 14 January 2010, 19:41 GMT
Last edited by Ronald van Haren (pressh) - Thursday, 01 July 2010, 12:48 GMT
Opened by Alexey Stukalov (alyst) - Thursday, 14 January 2010, 19:41 GMT
Last edited by Ronald van Haren (pressh) - Thursday, 01 July 2010, 12:48 GMT
|
Details
Description
============ After upgrading to dhcpcd-5.1.4-1 I'm unable to connect to my router, both wireless and wired: /var/log/errors.log -------------------- Jan 14 20:02:24 hostname dhcpcd: version 5.1.4 starting Jan 14 20:02:24 hostname NetworkManager: <info> DHCP: device wlan0 state changed normal exit -> preinit Jan 14 20:02:24 hostname dhcpcd: wlan0: broadcasting for a lease Jan 14 20:03:09 hostname NetworkManager: <info> (wlan0): DHCP transaction took too long, stopping it. Jan 14 20:03:09 hostname dhcpcd: received SIGTERM, stopping Jan 14 20:03:09 hostname dhcpcd: wlan0: removing interface Jan 14 20:03:09 hostname NetworkManager: <info> (wlan0): canceled DHCP transaction, dhcp client pid 3152 Additional info =============== * Kernel: 2.6.32.3-1 * With dhcpcd-5.1.3 it worked ok. The problem seems to affect a lot of people, see the discussion: http://bbs.archlinux.org/viewtopic.php?pid=688286 |
This task depends upon
Closed by Ronald van Haren (pressh)
Thursday, 01 July 2010, 12:48 GMT
Reason for closing: None
Additional comments about closing: please don't re-open non-related bug reports with the same error message
Thursday, 01 July 2010, 12:48 GMT
Reason for closing: None
Additional comments about closing: please don't re-open non-related bug reports with the same error message
Other also have problems with this update. There is no info on what you have changed in the packagebuild, so it is pretty hard to edit it and undo the changes.
Here is the forum post with ppl that have similar problems: http://bbs.archlinux.org/viewtopic.php?id=88663
However, it's still not working for wlan0 -- but I'm using wifi via networkmanager (kdemod-networkmanager-git 20091003-1).
If you know how to enable debug output for dhcpcd, when run through networkmanager, pls advise.
Currently, I have the following in /var/log/daemons.log:
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> (wlan0): device state change: 5 -> 7 (reason 0)
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> Activation (wlan0) Beginning DHCP transaction (timeout in 45 seconds)
Jan 14 21:45:22 cemmbk67 dhcpcd: wlan0: reading lease `/var/lib/dhcpcd/dhcpcd-wlan0.lease'
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> dhcpcd started with pid 4885
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) started...
Jan 14 21:45:22 cemmbk67 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) complete.
Jan 14 21:45:22 cemmbk67 dhcpcd: sending commands to master dhcpcd process
Jan 14 21:45:22 cemmbk67 dhcpcd: wlan0: broadcasting for a lease
Jan 14 21:45:22 cemmbk67 dhcpcd: wlan0: sending DHCP_DISCOVER (xid 0x3c180eaf), next in 3.01 seconds
Jan 14 21:45:22 cemmbk67 dhcpcd: control command: /sbin/dhcpcd -B -K -L -c /usr/lib/networkmanager/nm-dhcp-client.action wlan0
Jan 14 21:45:22 cemmbk67 avahi-daemon[2275]: Registering new address record for fe80::222:fbff:fec3:143a on wlan0.*.
Jan 14 21:45:25 cemmbk67 dhcpcd: wlan0: sending DHCP_DISCOVER (xid 0x3c180eaf), next in 7.84 seconds
Jan 14 21:45:33 cemmbk67 dhcpcd: wlan0: sending DHCP_DISCOVER (xid 0x3c180eaf), next in 15.18 seconds
Jan 14 21:45:48 cemmbk67 dhcpcd: wlan0: sending DHCP_DISCOVER (xid 0x3c180eaf), next in 32.71 seconds
Jan 14 21:46:21 cemmbk67 dhcpcd: wlan0: sending DHCP_DISCOVER (xid 0x3c180eaf), next in 63.90 seconds
etc... (without timeout set it lasts forever)
@alyst: I suppose you should be able to just add the debug option to /etc/dhcpcd.conf like one would do with other commandline options. From the upstream changelog I don't see anything which should cause this on first glance.
@alyst: I suppose you should be able to just add the debug option to /etc/dhcpcd.conf like one would do with other commandline options. From the upstream changelog I don't see anything which should cause this on first glance.
dhcpcd: version 5.1.4 starting
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason CARRIER
dhcpcd: eth0: reading lease `/var/lib/dhcpcd/dhcpcd-eth0.lease'
dhcpcd: eth0: broadcasting for a lease
dhcpcd: eth0: sending DHCP_DISCOVER (xid 0x34207770), next in 4.71 seconds
dhcpcd: eth0: sending DHCP_DISCOVER (xid 0x34207770), next in 7.23 seconds
dhcpcd: eth0: sending DHCP_DISCOVER (xid 0x34207770), next in 15.12 seconds
dhcpcd: eth0: sending DHCP_DISCOVER (xid 0x34207770), next in 32.97 seconds
dhcpcd: timed out
Removing /var/lib/dhcpcd/dhcpcd-eth0.lease prevent this problem to occur.
1. first become root and do rm /var/lib/dhcpcd/dhcpcd-eth0.lease and then
2. /etc/rc.d/network restart
3. /etc/rc.d/gw6c restart
4. /etc/rc.d/openntpd restart?
Or is there some script to automate this and in that case in which file to do it?
Can someone attach a full tcpdump (-s0 -w/tmp/dhcp.cap) of the DHCP transactions from a working dhcpcd-5.1.3 and a non working dhcpcd-5.1.4 please?
dhcpcd --debug eth1
dhcpcd: version 5.1.4 starting
dhcpcd: eth1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
dhcpcd: eth1: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason CARRIER
dhcpcd: eth1: reading lease `/var/lib/dhcpcd/dhcpcd-eth1.lease'
dhcpcd: eth1: broadcasting for a lease
dhcpcd: eth1: sending DHCP_DISCOVER (xid 0xa30f717), next in 3.38 seconds
dhcpcd: eth1: sending DHCP_DISCOVER (xid 0xa30f717), next in 8.56 seconds
dhcpcd: eth1: sending DHCP_DISCOVER (xid 0xa30f717), next in 16.82 seconds
dhcpcd: eth1: wrong xid 0x2f778173 (expecting 0xa30f717) from xxx.xxx.xxx.xxx
dhcpcd: eth1: sending DHCP_DISCOVER (xid 0xa30f717), next in 32.71 seconds
dhcpcd: timed out
The old lease was issued on the 14th of Dec, I'm guessing (but not sure) that it was issued by my Linksys router at home. When I had the problem seen above, I had just updated my system via wireless (which seems to not had this problem). I connected the ethernet cable at work where a Windows server issues the lease. As far as I know, there was only one dhcpcd update during this time.
tcpdump-dhcpcd-5.1.4-non_work... (0.6 KiB)
The -k switch I did not either understand how to do, but I did the following to my dhcpcd.conf, I hope it was correct--I hashed nohook and added release before lookup-hostname. I will turn off the puter soon and go to sleep. Hopefully it gets on line tomorrow:
-------
# A hook script is provided to lookup the hostname if not set by the DHCP
# server, but it should not be run by default.
#nohook
release lookup-hostname
noipv4ll
tcpdump -s0 -w/tmp/dhcp.cap -ieth0
And this in another console
dhcpcd -d eth0
Once done, terminate tcpdump with ctrl-c. Rinse and repeat with the other version.
I need both files. The captures above are the plaintext outputs which are useless to me sadly.
gconftool-2 -t string --set /system/gstreamer/0.10/default/musicaudiosink alsasink
Error setting value: Failed to contact configuration server; some possible causes are that you need to enable TCP/IP networking for ORBit, or you have stale NFS locks due to a system crash. See http://projects.gnome.org/gconf/ for information. (Details - 1: Failed to get connection to session: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.)
If I can be of more help I will gladly help but I might need some guidance.
I will attach both files in any case, let me know if I can do more.
dhcp5.1.4.cap (136.7 KiB)
I get this behavior working from the office, at home DHCP via wireless lan works perfectly.
I can also say that using dhclient (4.1.0.p1-2) to get the address works when dhcpcd fails. Can anybody confirm this?
I tried reinstalling dhcpcd 5.1.4-1 and I cannot reproduce the bug.. Strange behavior.
dhcp-5.1.4.cap (3.3 KiB)
dhcpcd-5.1.4 shows valid DHCP requests without a reply back from the server.
However, it is constantly requesting an IP address. I'm guessing that your DHCP server is non authoratitive and this has exposed a possible bug in dhcpcd where we request the lease but fail to clear the request address on a short timeout.
dhcpcd-5.1.4-1:
[root@lenovo pkg]# dhcpcd
dhcpcd: version 5.1.4 starting
dhcpcd: wlan0: broadcasting for a lease
dhcpcd: eth0: waiting for carrier
dhcpcd: wlan0: offered 192.168.1.142 from 192.168.1.1
dhcpcd: wlan0: acknowledged 192.168.1.142 from 192.168.1.1
dhcpcd: wlan0: checking for 192.168.1.142
dhcpcd: wlan0: leased 192.168.1.142 for 86400 seconds
dhcpcd: forking to background
So, All OK
dhcpcd-5.1.4-2:
[root@lenovo home]# dhcpcd
dhcpcd: version 5.1.4 starting
dhcpcd: wlan0: broadcasting for a lease
dhcpcd: eth0: waiting for carrier
dhcpcd: wlan0: offered 192.168.1.142 from 192.168.1.1
dhcpcd: wlan0: NAK: lease not found from 192.168.1.1
dhcpcd: wlan0: broadcasting for a lease
dhcpcd: wlan0: offered 192.168.1.142 from 192.168.1.1
dhcpcd: wlan0: NAK: lease not found from 192.168.1.1
.
.
.
dhcpcd: timed out
NOT WORKS!
Jan 26 18:00:54 fw dhcpd: DHCPDISCOVER from 00:21:70:f4:3d:15 via eth0
Jan 26 18:00:54 fw dhcpd: DHCPOFFER on 200.1.19.55 to 00:21:70:f4:3d:15 via eth0
Jan 26 18:00:54 fw dhcpd: DHCPREQUEST for 0.0.0.0 from 00:21:70:f4:3d:15 via eth0: unknown lease 0.0.0.0.
I downgraded dhcpcd now to 5.1.4-1, which works absolutely properly "for me".
Btw:
Are you sure that the duplicated bug is really related?
I do NOT have that bug with -1 but with -2.
dhcpcd: version 5.1.4 starting
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason CARRIER
dhcpcd: eth0: broadcasting for a lease
dhcpcd: eth0: sending DHCP_DISCOVER (xid 0x3ef1822a), next in 3.44 seconds
dhcpcd: eth0: discarding expired lease
dhcpcd: eth0: offered 192.168.0.19 from 192.168.0.1
dhcpcd: eth0: sending DHCP_REQUEST (xid 0x3ef1822a), next in 4.69 seconds
dhcpcd: eth0: reject NAK
dhcpcd: eth0: sending DHCP_REQUEST (xid 0x3ef1822a), next in 3.82 seconds
dhcpcd: eth0: reject NAK
...
...
dhcpcd: timed out
and the output of the working version:
dhcpcd: version 5.1.4 starting
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason CARRIER
dhcpcd: eth0: broadcasting for a lease
dhcpcd: eth0: sending DHCP_DISCOVER (xid 0x6febeb71), next in 4.21 seconds
dhcpcd: eth0: offered 192.168.0.19 from 192.168.0.1
dhcpcd: eth0: sending DHCP_REQUEST (xid 0x6febeb71), next in 3.71 seconds
dhcpcd: eth0: acknowledged 192.168.0.19 from 192.168.0.1
dhcpcd: eth0: leased 192.168.0.19 for 864000 seconds
dhcpcd: eth0: adding IP address 192.168.0.19/24
dhcpcd: eth0: adding route to 192.168.0.0/24
dhcpcd: eth0: adding default route via 192.168.0.1
dhcpcd: eth0: writing lease `/var/lib/dhcpcd/dhcpcd-eth0.lease'
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason BOUND
dhcpcd: forking to background
dhcp.cap (8.9 KiB)
here is the output in case you need it:
dhcpcd: version 5.1.4 starting
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason CARRIER
dhcpcd: eth0: broadcasting for a lease
dhcpcd: eth0: sending DHCP_DISCOVER (xid 0x71c46fcc), next in 3.45 seconds
dhcpcd: eth0: offered 192.168.0.19 from 192.168.0.1
dhcpcd: eth0: sending DHCP_REQUEST (xid 0x71c46fcc), next in 3.42 seconds
dhcpcd: eth0: acknowledged 192.168.0.19 from 192.168.0.1
dhcpcd: eth0: checking for 192.168.0.19
dhcpcd: eth0: sending ARP probe (1 of 3), next in 1.59 seconds
dhcpcd: eth0: sending ARP probe (2 of 3), next in 1.20 seconds
dhcpcd: eth0: sending ARP probe (3 of 3), next in 2.00 seconds
dhcpcd: eth0: leased 192.168.0.19 for 864000 seconds
dhcpcd: eth0: adding IP address 192.168.0.19/24
dhcpcd: eth0: adding route to 192.168.0.0/24
dhcpcd: eth0: adding default route via 192.168.0.1
dhcpcd: eth0: writing lease `/var/lib/dhcpcd/dhcpcd-eth0.lease'
dhcpcd: eth0: executing `/usr/lib/dhcpcd/dhcpcd-run-hooks', reason BOUND
dhcpcd: forking to background
dhcpcd 5.1.4-2 was not working in 100/100 cases.
5.1.4-1 and 5.1.4.2 weren't working for me.
I took my time to test (to be sure) and there are no failures.
I have double-checked all my settings and still nothing. I can't connect eth0!
while your at it, file also an upstream report, he most likely needs a tcpdump for the latest working version and the current not-working current version. Check for the Roy's comments in this bug report how to do so.