Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 244773 - net-misc/networkmanager-0.6.6 - Device DHCP transaction took too long (>45s), stopping it
Summary: net-misc/networkmanager-0.6.6 - Device DHCP transaction took too long (>45s),...
Status: RESOLVED INVALID
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: [OLD] Core system (show other bugs)
Hardware: All Linux
: High normal
Assignee: Steev Klimaszewski (RETIRED)
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-10-28 15:22 UTC by Enrico Tagliavini
Modified: 2008-12-15 14:40 UTC (History)
1 user (show)

See Also:
Package list:
Runtime testing required: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Enrico Tagliavini 2008-10-28 15:22:23 UTC
Often networkmanager fails to obtain ip via dhcp for my wired network. The log report:

Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  starting...
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  New VPN service 'vpnc' (org.freedesktop.NetworkManager.vpnc).
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <debug> [1225202122.556278] GentooReadConfig(): Enabling DHCP for device wlan0.
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <debug> [1225202122.556487] GentooReadConfig(): Found hostname.
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  wlan0: Device is fully-supported using driver '(null)'.
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  wlan0: driver supports SSID scans (scan_capa 0x01).
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing.
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  Now managing wireless (802.11) device 'wlan0'.
Oct 28 14:55:22 gentoo-linux64 NetworkManager: <info>  Deactivating device wlan0.
Oct 28 14:55:24 gentoo-linux64 NetworkManager: <debug> [1225202124.933238] GentooReadConfig(): Enabling DHCP for device eth0.
Oct 28 14:55:24 gentoo-linux64 NetworkManager: <debug> [1225202124.933302] GentooReadConfig(): Found hostname.
Oct 28 14:55:24 gentoo-linux64 NetworkManager: <info>  eth0: Device is fully-supported using driver '(null)'.
Oct 28 14:55:24 gentoo-linux64 NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start
Oct 28 14:55:24 gentoo-linux64 NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing.
Oct 28 14:55:24 gentoo-linux64 NetworkManager: <info>  Now managing wired Ethernet (802.3) device 'eth0'.
Oct 28 14:55:24 gentoo-linux64 NetworkManager: <info>  Deactivating device eth0.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Will activate wired connection 'eth0' because it now has a link.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  SWITCH: no current connection, found better connection 'eth0'.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Will activate connection 'eth0'.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Device eth0 activation scheduled...
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) started...
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) successful.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Oct 28 14:55:34 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Oct 28 14:55:35 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Beginning DHCP transaction.
Oct 28 14:55:35 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Oct 28 14:55:35 gentoo-linux64 NetworkManager: <info>  DHCP daemon state is now 12 (successfully started) for interface eth0
Oct 28 14:55:59 gentoo-linux64 NetworkManager: <info>  Updating allowed wireless network lists.
Oct 28 14:55:59 gentoo-linux64 NetworkManager: <info>  Updating VPN Connections...
Oct 28 14:56:00 gentoo-linux64 NetworkManager: <info>  Old device 'eth0' activating, won't change.
Oct 28 14:56:00 gentoo-linux64 NetworkManager: <info>  Old device 'eth0' activating, won't change.
Oct 28 14:56:03 gentoo-linux64 NetworkManager: <info>  Old device 'eth0' activating, won't change.
Oct 28 14:56:20 gentoo-linux64 NetworkManager: <info>  Device 'eth0' DHCP transaction took too long (>45s), stopping it.
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Timeout) started...
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  No DHCP reply received.  Automatically obtaining IP via Zeroconf.
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Timeout) scheduled...
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  DHCP daemon state is now 14 (normal exit) for interface eth0
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  DHCP daemon state is now 11 (unknown) for interface eth0
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  DHCP daemon state is now 14 (normal exit) for interface eth0
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  autoip: Sending probe #0 for IP address 169.254.69.108.
Oct 28 14:56:21 gentoo-linux64 NetworkManager: <info>  autoip: Waiting for reply...
Oct 28 14:56:23 gentoo-linux64 NetworkManager: <info>  autoip: Sending probe #1 for IP address 169.254.69.108.
Oct 28 14:56:23 gentoo-linux64 NetworkManager: <info>  autoip: Waiting for reply...
Oct 28 14:56:25 gentoo-linux64 NetworkManager: <info>  autoip: Sending probe #2 for IP address 169.254.69.108.
Oct 28 14:56:25 gentoo-linux64 NetworkManager: <info>  autoip: Waiting for reply...
Oct 28 14:56:28 gentoo-linux64 NetworkManager: <info>  autoip: Sending announce #0 for IP address 169.254.69.108.
Oct 28 14:56:28 gentoo-linux64 NetworkManager: <info>  autoip: Waiting for reply...
Oct 28 14:56:31 gentoo-linux64 NetworkManager: <info>  autoip: Sending announce #1 for IP address 169.254.69.108.
Oct 28 14:56:31 gentoo-linux64 NetworkManager: <info>  autoip: Waiting for reply...
Oct 28 14:56:33 gentoo-linux64 NetworkManager: <info>  Old device 'eth0' activating, won't change.
Oct 28 14:56:34 gentoo-linux64 NetworkManager: <info>  autoip: Sending announce #2 for IP address 169.254.69.108.
Oct 28 14:56:34 gentoo-linux64 NetworkManager: <info>  autoip: Waiting for reply...
Oct 28 14:56:37 gentoo-linux64 NetworkManager: <info>  autoip: Got some data to check for reply packet.
Oct 28 14:56:37 gentoo-linux64 NetworkManager: <WARN>  get_autoip(): autoip: (eth0) recv arp type=2048, op=0,
Oct 28 14:56:37 gentoo-linux64 NetworkManager: <WARN>  get_autoip():  source = 0.1.239.255 7F:11:EE:61:C0:A8,
Oct 28 14:56:37 gentoo-linux64 NetworkManager: <WARN>  get_autoip():  target = 1.4.188.38 FF:FA:07:6C:07:6C
Oct 28 14:56:37 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
Oct 28 14:56:37 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Timeout) complete.
Oct 28 14:56:37 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Oct 28 14:56:38 gentoo-linux64 NetworkManager: <WARN>  nm_system_set_hostname(): nm_system_set_hostname(): gethostbyaddr failed, h_errno = 2
Oct 28 14:56:38 gentoo-linux64 NetworkManager: <info>  Activation (eth0) successful, device activated.
Oct 28 14:56:38 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Finish handler scheduled.
Oct 28 14:56:38 gentoo-linux64 NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.

i have to restart networkmanager one or more time to get the ip.

I've tried to downgrade dhcp to version 3.0.6 or 3.0.3 like said in gentoo forums but nothing changed.

This problem happend with all dhcp server i've tried (my home, my university ecc...)

Reproducible: Always

Steps to Reproduce:
1.start networkmanager
2.plug-in the cable 
3.sometimes (rarely) the ip is get as expected but commonly it fails

Actual Results:  
networkmanager falls back to zeroconf using a randm ip 169.xxx.xxx.xxx

Expected Results:  
the normal result is getting the right ip from dhcp server
Comment 1 Enrico Tagliavini 2008-10-28 15:28:40 UTC
I've forgotten a thing. When it fails before 

Oct 28 14:56:20 gentoo-linux64 NetworkManager: <info>  Device 'eth0' DHCP transaction took too long (>45s), stopping it.

dhclient get the ip as expected but networkmanager don't notify that and still wait an ip. After 45 second it gives up and fallback to zeroconf
Comment 2 Jeroen Roovers (RETIRED) gentoo-dev 2008-10-28 18:05:55 UTC
Please post your `emerge --info' too.
Comment 3 Enrico Tagliavini 2008-10-28 18:10:45 UTC
here it is :D

Portage 2.1.4.5 (default/linux/amd64/2008.0, gcc-4.1.2, glibc-2.6.1-r0, 2.6.27-gentoo-r1 x86_64)
=================================================================
System uname: 2.6.27-gentoo-r1 x86_64 Intel(R) Core(TM)2 Duo CPU P8400 @ 2.26GHz
Timestamp of tree: Sun, 26 Oct 2008 13:45:01 +0000
ccache version 2.4 [enabled]
app-shells/bash:     3.2_p33
dev-java/java-config: 1.3.7, 2.1.6
dev-lang/python:     2.5.2-r7
dev-util/ccache:     2.4-r7
dev-util/cmake:      2.4.6-r1
sys-apps/baselayout: 1.12.11.1
sys-apps/sandbox:    1.2.18.1-r2
sys-devel/autoconf:  2.13, 2.61-r2
sys-devel/automake:  1.5, 1.7.9-r1, 1.8.5-r3, 1.9.6-r2, 1.10.1-r1
sys-devel/binutils:  2.18-r3
sys-devel/gcc-config: 1.4.0-r4
sys-devel/libtool:   1.5.26
virtual/os-headers:  2.6.23-r3
ACCEPT_KEYWORDS="amd64"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-march=nocona -O2 -pipe"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc /usr/kde/3.5/env /usr/kde/3.5/share/config /usr/kde/3.5/shutdown /usr/share/config"
CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/env.d/java/ /etc/fonts/fonts.conf /etc/gconf /etc/revdep-rebuild /etc/splash /etc/terminfo /etc/texmf/web2c /etc/udev/rules.d"
CXXFLAGS="-march=nocona -O2 -pipe"
DISTDIR="/usr/portage/distfiles"
FEATURES="ccache distlocks fixpackages metadata-transfer parallel-fetch sandbox sfperms strict unmerge-orphans userfetch"
GENTOO_MIRRORS=" ftp://mirror.ing.unibo.it/gentoo/  ftp://mirror.switch.ch/mirror/gentoo/ ftp://ftp.solnet.ch/mirror/Gentoo  ftp://ftp.unina.it/pub/linux/distributions/gentoo "
LDFLAGS="-Wl,-O1"
LINGUAS="it"
MAKEOPTS="-j3"
PKGDIR="/usr/portage/packages"
PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages"
PORTAGE_TMPDIR="/var/tmp"
PORTDIR="/usr/portage"
PORTDIR_OVERLAY="/usr/portage/local/layman/desktop-effects /usr/portage/local/layman/science /usr/local/portage"
SYNC="rsync://rsync.europe.gentoo.org/gentoo-portage"
USE="X acl acpi alsa amd64 arts avahi bash-completion berkdb bluetooth branding bzip2 cdr cli cracklib crypt cups custom-optimization dbus dri dvd dvdr dvdread ffmpeg firefox fortran gdbm gif gnutls gpm hal iconv ipv6 isdnlog java jpeg kde mad midi mmx mp3 mpeg mudflap multilib ncurses networkmanager nls nptl nptlonly nsplugin ogg opengl openmp pam pch pcre perl pic png pppd pvr python qt3 qt4 readline reflection samba sdl session smp spl sse sse2 sse3 ssl ssse3 startup-notification sysfs tcpd threads truetype unicode usb v4l v4l2 vorbis xcomposite xine xinerama xorg xulrunner xv xvmc zlib" ALSA_CARDS="hda-intel" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mmap_emul mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" ELIBC="glibc" INPUT_DEVICES="keyboard mouse synaptics" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LINGUAS="it" USERLAND="GNU" VIDEO_CARDS="fglrx radeon radeonhd"
Unset:  CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, FFLAGS, INSTALL_MASK, LANG, LC_ALL, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
Comment 4 Enrico Tagliavini 2008-10-29 00:40:29 UTC
After some additional test seems that this bug is very similar to http://bugs.gentoo.org/show_bug.cgi?id=244629. I have dhcpcd-4.0.2 installed, but networkmanager don't use it couse it use dhclient (as far as i know). Howerver i've tried to start net.eth0 with dhcpcd (stopped networkmanager first of course) and after unplugged and plugged the cable a couple of time dhcpcd timed out!! But if i start dhcpcd alone without starting dhcpcd it works as expected. I've unplugged and plugged the cable 100 times but never time out!!
net.eth0 load following modules:
modules: apipa arping tuntap bridge ccwgroup macchanger macnet rename ifplugd iwconfig essidnet iptunnel iproute2 autoipd system dhcpcd ip6to4
is it possible that some modules makes a mess? I'm trying to disable some of them but with no luck
Comment 5 Steev Klimaszewski (RETIRED) gentoo-dev 2008-10-29 12:44:31 UTC
Additional information needed - since NetworkManager is apparently not getting the driver information anymore "driver (null)" - could you please tell me what kind of card you have, what driver you are using (madwifi-ng vs. ath5k in kernel vs ath5k via patch as an example)?  What about wireless?  Does wireless work fine, and its just wired that you have issues with?  
Comment 6 Enrico Tagliavini 2008-10-29 13:09:05 UTC
(In reply to comment #5)
> Additional information needed - since NetworkManager is apparently not getting
> the driver information anymore "driver (null)" - could you please tell me what
> kind of card you have, what driver you are using (madwifi-ng vs. ath5k in
> kernel vs ath5k via patch as an example)?  What about wireless?  Does wireless
> work fine, and its just wired that you have issues with?  
> 

this is the output of lspci:
Ethernet controller: Silicon Integrated Systems [SiS] 191 Gigabit Ethernet Adapter (rev 02)
and i use sis190 compiled as module (it is raccomended in kernel help). I have 2.6.27-gentoo-r1 and 2.6.26-gentoo-r1 and the issue appear with both.

My wireless card is Atheros Communications, Inc. AR5007EG 802.11 b/g and i use in kernel ath5k in 2.6.27. In 2.6.26 i must use the svn madwifi-hal.
Wireless seem to work well, even if sometimes i have some performance issue (low signal) couse the driver is not complete yet (it misses the hw_txpower PhyFunctions) but dhcp work as espected with this card.

In short it is only a wired problem. 

I don't think that "driver (null)" is accountable: i've tried networkmanager-0.7 from rbu overlay and it report the correct diver (sis190) but the issue persists. Additionaly this morning i can't connect to the wired network of my university even without networkmanager (never happened before!!!)
Comment 7 Steev Klimaszewski (RETIRED) gentoo-dev 2008-10-29 13:31:08 UTC
(In reply to comment #6)
> I don't think that "driver (null)" is accountable: i've tried
> networkmanager-0.7 from rbu overlay and it report the correct diver (sis190)
> but the issue persists. Additionaly this morning i can't connect to the wired
> network of my university even without networkmanager (never happened before!!!)
> 

I didn't mean that the driver (null) was the cause - I meant that since its reporting null I didn't know what kind of wired card you had :) - I actually have one of those wired cards myself.  Does it work if you set the module to use dhclient instead of dhcpcd? I think it is something like (forgive me, I am at work currently and don't have access to my home network right now for some reason) modules=( "dhclient" ) or modules=( "dhcp" ) (I don't remember which one to tell it - I think I had actually just done modules=( "!dhcpcd" ) on my machine with dhcpcd on it.  The only other thing that I could think of  - I have 2 of those machines, one here at work, and one at home - here at work, it worked just fine, HOWEVER at home - i *had* to set the mtu to 1492 as opposed to the default of 1500 - does that help you at all?
Comment 8 Enrico Tagliavini 2008-10-29 14:36:17 UTC
(In reply to comment #7)
> (In reply to comment #6)
> > I don't think that "driver (null)" is accountable: i've tried
> > networkmanager-0.7 from rbu overlay and it report the correct diver (sis190)
> > but the issue persists. Additionaly this morning i can't connect to the wired
> > network of my university even without networkmanager (never happened before!!!)
> > 
> 
> I didn't mean that the driver (null) was the cause - I meant that since its
> reporting null I didn't know what kind of wired card you had :) - I actually
> have one of those wired cards myself.  Does it work if you set the module to
> use dhclient instead of dhcpcd? I think it is something like (forgive me, I am
> at work currently and don't have access to my home network right now for some
> reason) modules=( "dhclient" ) or modules=( "dhcp" ) (I don't remember which
> one to tell it - I think I had actually just done modules=( "!dhcpcd" ) on my
> machine with dhcpcd on it.  The only other thing that I could think of  - I
> have 2 of those machines, one here at work, and one at home - here at work, it
> worked just fine, HOWEVER at home - i *had* to set the mtu to 1492 as opposed
> to the default of 1500 - does that help you at all?

Here is the situation after setting ifconfig_eth0="mtu 1492" in conf.d/net
using Networkmanager with modules_eth0=( "dhclient"  ) or modules_eth0=( "dhcpcd" ) nothing changed. If i unplug and the plugin the cable 2 or 3 times i got timeout in dhcp request

but if i DON'T use networkmanager and setting ifconfig_eth0="mtu 1492" with modules_eth0=( "dhclient"  ) or modules_eth0=( "dhcpcd" ) it _seems_ that the situation is better. with dhclient i have to unplug and plugin the cable several times to get a timeout, or if i'm lucky never got timeout. with dhcpcd it is even better, just 1 timeout gotten in a lot of try.
So yes this helped me, even if i can't use nm, may be now i can use net.eth0 with a decent result, thank you very much. I hope that now i can connect to the wired network of my university, but i'm at home now so i can't say it now.

Just a circumstantiation: when i get a timeout i have to restart the network services (nm or net.eth0) couse even if i retry a lot of time i'll get always timeout.
Comment 9 Enrico Tagliavini 2008-10-30 16:07:01 UTC
Unlucky... change mtu is useless :°( i have the same result with both 1500 and 1492.
BTW i've make a mistake: ifconfig_eth0="mtu 1492" don't change mtu at boot (i saw it today after rebooting my notebook)
Comment 10 Enrico Tagliavini 2008-10-31 15:46:51 UTC
I have maked same comparison test with another notebook (same model as mine) and the issue is not present, so i think it seems an hardware fault. I have contacted asus (my notebook is an asus f5sl-ap247e) and now i'm waiting their answer.

I'm sorry for the loss of time but, it is a very strange issue, and i haven't thinked it was an hardware fault (also because it is very strange as an hardware fault)

Thank you very much for the help, continue to make gentoo always better, 'cause it is the best GNU/Linux distro ever :D

Bye
Comment 11 Enrico Tagliavini 2008-11-12 13:57:49 UTC
Asus has changed my mainboard, but the issue still persist. A this point i think there is something that is breaking my hardware. Is it possibile? Maybe the kernel driver? 
Comment 12 Enrico Tagliavini 2008-11-20 14:30:59 UTC
There is a difference between gentoo-2.6.27 and gentoo-2.6.26. With 2.6.27 i can't get the ip (via dhcp) at my university _never_, but with 2.6.26 it "just work".

Another strange thing is this: if i boot with 2.6.26 i get the ip and i'm connected. I reboot with 2.6.27 and it doesn't work. After that if i reboot with 2.6.26 it doesn't work!!!! I must wait sometime (minute hours?? i can't say it) with the pc totally turned off, and at rebbot with 2.6.26 it works. This is very strange. I've checked the differenze in the .config file, but i can't see nothing wrong. I can attach the 2 config file if these can be helpfull

BTW 2.6.26 is not perfect, i still have some performace issue with big file transfert (i have it also in windows --just for try, i don't use it :P--, but only with this pc, my brother's pc --identical to mine-- does not has this performance issue), but it works better.