Bug 1270179 - Wired network takes nearly 60 seconds to regain name resolution after resume (no nameserver in /etc/resolv.conf despite DHCPACK
Summary: Wired network takes nearly 60 seconds to regain name resolution after resume ...
Keywords:
Status: CLOSED DUPLICATE of bug 1270025
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 22
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Lubomir Rintel
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-10-09 08:28 UTC by Kieran Clancy
Modified: 2015-10-09 14:06 UTC (History)
3 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2015-10-09 14:06:25 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Kieran Clancy 2015-10-09 08:28:04 UTC
Description of problem:
After resume and suspend, my wired network comes back up within a few seconds (as it always has), but DNS now takes about 1 minute to start working again. This basically means I have to wait a minute before I do anything on the network. It only started doing this recently.

Version-Release number of selected component (if applicable):
NetworkManager-1.0.6-6.fc22.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Suspend
2. Resume
3. Try to access internet within 10 seconds

Actual results:
No name resolution. /etc/resolv.conf contains:
# Generated by NetworkManager
# No nameservers found; try putting DNS servers into your
# ifcfg files in /etc/sysconfig/network-scripts like so:
#
# DNS1=xxx.xxx.xxx.xxx
# DNS2=xxx.xxx.xxx.xxx
# DOMAIN=lab.foo.com bar.foo.com

Expected results:
Network resumes, /etc/resolv.conf is updated as soon as DHCPACK received.

Additional info:
Here's the timeline and relevant log messages:

0. Immediately before suspending, the network is brought down and /etc/resolv.conf is replaced with the "No nameservers found" lines above

1. After resuming, within a few seconds the network is brought up, and DHCPREQUEST and DHCPACK messages are sent/received:
Oct  9 18:20:35 kbook NetworkManager[1064]: <info>  wake requested (sleeping: yes  enabled: yes)
Oct  9 18:20:35 kbook NetworkManager[1064]: <info>  waking up...
Oct  9 18:20:35 kbook NetworkManager[1064]: <info>  (p3p1): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Oct  9 18:20:35 kbook kernel: IPv6: ADDRCONF(NETDEV_UP): p3p1: link is not ready
Oct  9 18:20:35 kbook kernel: r8169 0000:02:00.0 p3p1: link down
Oct  9 18:20:35 kbook kernel: IPv6: ADDRCONF(NETDEV_UP): p3p1: link is not ready
Oct  9 18:20:35 kbook NetworkManager[1064]: <info>  (wlp1s0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Oct  9 18:20:35 kbook kernel: IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
Oct  9 18:20:35 kbook NetworkManager[1064]: <info>  NetworkManager state is now CONNECTED_LOCAL
Oct  9 18:20:35 kbook NetworkManager[1064]: <info>  connectivity: check for uri 'http://fedoraproject.org/static/hotspot.txt' failed with 'Error resolving 'fedoraproject.org': No address associated with hostname'
Oct  9 18:20:38 kbook kernel: r8169 0000:02:00.0 p3p1: link up
Oct  9 18:20:38 kbook kernel: IPv6: ADDRCONF(NETDEV_CHANGE): p3p1: link becomes ready
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): link connected
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  Auto-activating connection 'enp2s0'.
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): Activation: starting connection 'enp2s0' (75881dc3-36ee-494f-8bf0-97a0d68ae439)
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  NetworkManager state is now CONNECTING
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): device state change: prepare -> config (reason 'none') [40 50 0]
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): device state change: config -> ip-config (reason 'none') [50 70 0]
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  Activation (p3p1) Beginning DHCPv4 transaction (timeout in 45 seconds)
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  dhclient started with pid 3200
Oct  9 18:20:38 kbook dhclient[3200]: DHCPREQUEST on p3p1 to 255.255.255.255 port 67 (xid=0xc3c76156)
Oct  9 18:20:38 kbook dhclient[3200]: DHCPACK from 192.168.0.1 (xid=0xc3c76156)
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    address 192.168.0.8
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    plen 16 (255.255.0.0)
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    gateway 192.168.0.1
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    server identifier 192.168.0.1
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    lease time 43200
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    hostname 'kbook-fixed'
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    nameserver '192.168.0.1'
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>    domain search 'example.com.'
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): DHCPv4 state changed unknown -> bound
Oct  9 18:20:38 kbook avahi-daemon[860]: Joining mDNS multicast group on interface p3p1.IPv4 with address 192.168.0.8.
Oct  9 18:20:38 kbook avahi-daemon[860]: New relevant interface p3p1.IPv4 for mDNS.
Oct  9 18:20:38 kbook avahi-daemon[860]: Registering new address record for 192.168.0.8 on p3p1.IPv4.
Oct  9 18:20:38 kbook NetworkManager[1064]: <info>  (p3p1): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Oct  9 18:20:38 kbook dhclient[3200]: bound to 192.168.0.8 -- renewal in 17020 seconds.
Oct  9 18:20:40 kbook avahi-daemon[860]: Registering new address record for fe80::1a67:b0ff:fe3f:c07 on p3p1.*.

^ Upon receiving that DHCPACK, NetworkManager should immediately be updating /etc/resolv.conf, but it doesn't

2. Nearly one minute later:

Oct  9 18:21:33 kbook nm-dispatcher: Dispatching action 'pre-up' for p3p1
Oct  9 18:21:33 kbook NetworkManager[1064]: <info>  (p3p1): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Oct  9 18:21:33 kbook NetworkManager[1064]: <info>  (p3p1): device state change: secondaries -> activated (reason 'none') [90 100 0]
Oct  9 18:21:33 kbook NetworkManager[1064]: <info>  NetworkManager state is now CONNECTED_LOCAL
Oct  9 18:21:33 kbook NetworkManager[1064]: <info>  NetworkManager state is now CONNECTED_SITE
Oct  9 18:21:33 kbook NetworkManager[1064]: <info>  Policy set 'enp2s0' (p3p1) as default for IPv4 routing and DNS.
Oct  9 18:21:33 kbook NetworkManager[1064]: <info>  (p3p1): Activation: successful, device activated.
Oct  9 18:21:33 kbook nm-dispatcher: Dispatching action 'up' for p3p1
Oct  9 18:21:35 kbook NetworkManager[1064]: <info>  NetworkManager state is now CONNECTED_GLOBAL

There is nothing of interest in /var/log/messages during this 50+ seconds of silence. How can I debug this?

Comment 1 Dan Williams 2015-10-09 14:06:25 UTC
This could be related to sending ARP notifications (which NM now does) and certainly seems like a bug.  Debugging instructions are in the bug that I've duped this one to.  Could you attach your log output there?  Thanks!

*** This bug has been marked as a duplicate of bug 1270025 ***


Note You need to log in before you can comment on or make changes to this bug.