Bug 473785

Summary: NetworkManager generates useless /etc/resolv.conf
Product: [Fedora] Fedora Reporter: Joachim Backes <joachim.backes>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: medium    
Version: 10CC: arxs, dcbw, wtogami, yrtimid, ywb_bsd
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-10-15 04:06:57 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Joachim Backes 2008-11-30 15:50:01 UTC
Description of problem:
NetworkManager generates a useless /etc/resolv.conf without a nameserver entry:
--------------- snip -------------------
# Generated by NetworkManager
domain Speedport_W_700V
search Speedport_W_700V


# 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

----------------- snip ------------------

Version-Release number of selected component (if applicable):
NetworkManager-0.7.0-0.12.svn4326.fc10.i386

How reproducible:
each time

Steps to Reproduce:
1./etc/init.d/NetworkManager start
2.
3.
  
Actual results:
see above

Expected results:
nameserver entry in /etc/resolv.conf: 
nameserver 192.168.179.1

Additional info:
Output of NetworkManager --no-daemon
-------------------- snip --------------------
NetworkManager: <info>  starting...
-- Error received: File exists
-- Original message: type=0x14 length=56 flags=<REQUEST,ACK,ATOMIC> sequence-nr=1228059533 pid=4198936
NetworkManager: <WARN>  nm_generic_enable_loopback(): error -17 returned from rtnl_addr_add():
Sucess

NetworkManager: nm_device_ethernet_new: assertion `driver != NULL' failed
NetworkManager: nm_device_ethernet_new: assertion `driver != NULL' failed
NetworkManager: <info>  eth0: driver is 'forcedeth'.
NetworkManager: <info>  Found new Ethernet device 'eth0'.
NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_0c_76_c0_40_36
NetworkManager: <info>  Trying to start the supplicant...
NetworkManager: <info>  (eth0): carrier now ON (device state 1)
NetworkManager: <info>  (eth0): device state change: 1 -> 2
NetworkManager: <info>  (eth0): preparing device.
NetworkManager: <info>  (eth0): deactivating device (reason: 2).
-- Error received: Numerical result out of range
-- Original message: type=0x19 length=56 flags=<REQUEST,ACK> sequence-nr=1228059544 pid=4198936
NetworkManager: <WARN>  check_one_route(): (eth0) error -34 returned from rtnl_route_del(): Sucess

NetworkManager: <info>  (eth0): device state change: 2 -> 3
NetworkManager: <info>  Activation (eth0) starting connection 'System eth0'
NetworkManager: <info>  (eth0): device state change: 3 -> 4
NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (eth0): device state change: 4 -> 5
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) successful.
NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info>  (eth0): device state change: 5 -> 7
NetworkManager: <info>  Activation (eth0) Beginning DHCP transaction.
Internet Systems Consortium DHCP Client 4.0.0
Copyright 2004-2007 Internet Systems Consortium.
All rights reserved.
For info, please visit http://www.isc.org/sw/dhcp/

NetworkManager: <info>  dhclient started with pid 4635
NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Listening on LPF/eth0/00:0c:76:c0:40:36
Sending on   LPF/eth0/00:0c:76:c0:40:36
Sending on   Socket/fallback
NetworkManager: <info>  DHCP: device eth0 state changed (null) -> preinit
DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 4
DHCPOFFER from 192.168.179.1
DHCPREQUEST on eth0 to 255.255.255.255 port 67
DHCPACK from 192.168.179.1
NetworkManager: <info>  DHCP: device eth0 state changed preinit -> bound
NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Get) scheduled...
NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Get) started...
NetworkManager: <info>    address 192.168.179.107
NetworkManager: <info>    prefix 24 (255.255.255.0)
NetworkManager: <info>    gateway 192.168.179.1
NetworkManager: <info>    nameserver '192.168.179.1'
NetworkManager: <info>    domain name 'Speedport_W_700V'
NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Get) complete.
NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
bound to 192.168.179.107 -- renewal in 138326 seconds.nameserver '192.168.179.1'
Stopping nscd: [  OK  ]
Starting nscd: [  OK  ]
NetworkManager: <info>  (eth0): device state change: 7 -> 8
Stopping nscd: [  OK  ]
Starting nscd: [  OK  ]
NetworkManager: <info>  Policy set 'System eth0' (eth0) as default for routing and DNS.
NetworkManager: <info>  Activation (eth0) successful, device activated.
NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
---------------------- snip ---------------------------

Comment 1 yrtimiD 2008-12-11 20:30:52 UTC
I confirm this bug. Have same behavior.
versions:
NetworkManager-0.7.0-0.12.svn4326.fc10.i386
dhcp-4.0.0-33.fc10.i386
dhclient-4.0.0-33.fc10.i386

output of /var/log/messages after "service NetworkManager start":
Dec 11 22:23:18 localhost NetworkManager: <info>  starting...                                                                
Dec 11 22:23:18 localhost NetworkManager: <WARN>  nm_generic_enable_loopback(): error -17 returned from rtnl_addr_add():#012Sucess#012                                                                                                                    
Dec 11 22:23:18 localhost NetworkManager: <info>  eth1: driver is '8139too'.                                                 
Dec 11 22:23:18 localhost NetworkManager: <info>  Found new Ethernet device 'eth1'.                                          
Dec 11 22:23:18 localhost NetworkManager: <info>  (eth1): exported as /org/freedesktop/Hal/devices/net_00_00_21_f3_2a_b7     
Dec 11 22:23:18 localhost NetworkManager: <info>  eth0: driver is '8139too'.                                                 
Dec 11 22:23:18 localhost NetworkManager: <info>  Found new Ethernet device 'eth0'.                                          
Dec 11 22:23:18 localhost NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_00_21_f3_2a_b4     
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): device state change: 1 -> 2                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): bringing up device.                                                
Dec 11 22:23:22 localhost kernel: eth1: link up, 100Mbps, full-duplex, lpa 0xC5E1                                            
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): preparing device.                                                  
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): deactivating device (reason: 2).                                   
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): carrier now ON (device state 2)                                    
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): device state change: 2 -> 3                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) starting connection 'System eth1'                        
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): device state change: 3 -> 4                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled...               
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): device state change: 1 -> 2                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): bringing up device.                                                
Dec 11 22:23:22 localhost kernel: eth0: link up, 100Mbps, full-duplex, lpa 0x45E1                                            
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): preparing device.                                                  
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): deactivating device (reason: 2).                                   
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): carrier now ON (device state 2)                                    
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): device state change: 2 -> 3                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) started...                 
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) scheduled...             
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) complete.                  
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) starting connection 'System eth0'                        
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): device state change: 3 -> 4                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...               
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) starting...              
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): device state change: 4 -> 5                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) successful.              
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 3 of 5 (IP Configure Start) scheduled.             
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) complete.                
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) started...                 
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...             
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) complete.                  
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 3 of 5 (IP Configure Start) started...             
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth1): device state change: 5 -> 7                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 4 of 5 (IP Configure Get) scheduled...             
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 3 of 5 (IP Configure Start) complete.              
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) starting...              
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): device state change: 4 -> 5                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) successful.              
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.             
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) complete.                
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 4 of 5 (IP Configure Get) started...               
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5 (IP Configure Commit) scheduled...          
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 4 of 5 (IP Configure Get) complete.                
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) started...             
Dec 11 22:23:22 localhost NetworkManager: <info>  (eth0): device state change: 5 -> 7                                        
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Beginning DHCP transaction.                              
Dec 11 22:23:22 localhost dhclient: Internet Systems Consortium DHCP Client 4.0.0                                            
Dec 11 22:23:22 localhost NetworkManager: <info>  dhclient started with pid 12296                                            
Dec 11 22:23:22 localhost dhclient: Copyright 2004-2007 Internet Systems Consortium.                                         
Dec 11 22:23:22 localhost dhclient: All rights reserved.                                                                     
Dec 11 22:23:22 localhost dhclient: For info, please visit http://www.isc.org/sw/dhcp/                                       
Dec 11 22:23:22 localhost dhclient:                                                                                          
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.              
Dec 11 22:23:22 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5 (IP Configure Commit) started...            
Dec 11 22:23:22 localhost dhclient: Listening on LPF/eth0/00:00:21:f3:2a:b4                                                  
Dec 11 22:23:22 localhost dhclient: Sending on   LPF/eth0/00:00:21:f3:2a:b4                                                  
Dec 11 22:23:22 localhost dhclient: Sending on   Socket/fallback                                                             
Dec 11 22:23:23 localhost NetworkManager: <info>  (eth1): device state change: 7 -> 8                                        
Dec 11 22:23:23 localhost NetworkManager: <info>  Policy set 'System eth1' (eth1) as default for routing and DNS.            
Dec 11 22:23:23 localhost NetworkManager: <info>  Activation (eth1) successful, device activated.                            
Dec 11 22:23:23 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5 (IP Configure Commit) complete.             
Dec 11 22:23:23 localhost NetworkManager: <info>  DHCP: device eth0 state changed (null) -> preinit                          
Dec 11 22:23:24 localhost dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7                               
Dec 11 22:23:24 localhost dhclient: DHCPOFFER from 10.163.128.1
Dec 11 22:23:24 localhost dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Dec 11 22:23:24 localhost dhclient: DHCPACK from 10.163.128.1
Dec 11 22:23:24 localhost dhclient: bound to 84.XXX.XXX.190 -- renewal in 34583 seconds.
Dec 11 22:23:24 localhost NetworkManager: <info>  DHCP: device eth0 state changed preinit -> bound
Dec 11 22:23:24 localhost NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Get) scheduled...
Dec 11 22:23:24 localhost NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Get) started...
Dec 11 22:23:24 localhost NetworkManager: <info>    address 84.XXX.XXX.190
Dec 11 22:23:24 localhost NetworkManager: <info>    prefix 22 (255.255.252.0)
Dec 11 22:23:24 localhost NetworkManager: <info>    gateway 84.XXX.XXX.1
Dec 11 22:23:24 localhost NetworkManager: <info>    hostname 'yserver'
Dec 11 22:23:24 localhost NetworkManager: <info>    nameserver '192.117.235.235'
Dec 11 22:23:24 localhost NetworkManager: <info>    nameserver '62.219.186.7'
Dec 11 22:23:24 localhost NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
Dec 11 22:23:24 localhost NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP Configure Get) complete.
Dec 11 22:23:24 localhost NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Dec 11 22:23:25 localhost NetworkManager: <info>  Policy set 'System eth1' (eth1) as default for routing and DNS.
Dec 11 22:23:25 localhost NetworkManager: <info>  (eth0): device state change: 7 -> 8
Dec 11 22:23:25 localhost NetworkManager: <info>  Activation (eth0) successful, device activated.
Dec 11 22:23:25 localhost NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.


resolv.conf after "start" finished:
# 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

Comment 2 Lou 2009-01-11 08:12:58 UTC
I also have problem with NetworkManager to create a usable /etc/resolv.conf when /etc/sysconf/readonly-root is modified with TEMPORARY_STATE="yes". The problem seems to be NetworkManager attempt to create a temporary file called /etc/resolv.conf.tmp first then copies it back to the bind-mounted /etc/resolv.conf which is causing a device busy kind of error. I haven't looked into the source code of NetworkManager but I have similar problems with /etc/mtab under fuse/zfs-fuse which is also trying to mv /etc/mtab.tmp to /etc/mtab which is also bind-mounted to the /var/lib/stateless/writable/etc/mtab. When I unmount zfs filesystems, it will emit error messages telling me unable to rename /etc/mtab.tmp to /etc/mtab because the device is busy. I think change the mv to cat with a redirection to the bind-mounted file will solve these problems.

Comment 3 Joachim Backes 2009-01-11 08:24:02 UTC
The problem in my box seems to be another one:

cat /etc/sysconfig/readonly-root
----------------------------- snip ----------------------
# Set to 'yes' to mount the system filesystems read-only.
READONLY=no
# Set to 'yes' to mount various temporary state as either tmpfs
# or on the block device labelled RW_LABEL. Implied by READONLY
TEMPORARY_STATE=no
# Place to put a tmpfs for temporary scratch writable space
RW_MOUNT=/var/lib/stateless/writable
# Label on local filesystem which can be used for temporary scratch space
RW_LABEL=stateless-rw
# Options to use for temporary mount
RW_OPTIONS=
# Label for partition with persistent data
STATE_LABEL=stateless-state
# Where to mount to the persistent data
STATE_MOUNT=/var/lib/stateless/state
# Options to use for peristent mount
STATE_OPTIONS=
---------------------- snap ------------------------------

Comment 4 Lou 2009-01-11 21:53:22 UTC
Then, do I need to file another bug report?

Comment 5 Dan Williams 2009-02-13 12:46:09 UTC
(In reply to comment #3)
> The problem in my box seems to be another one:
> 
> cat /etc/sysconfig/readonly-root
> ----------------------------- snip ----------------------
> # Set to 'yes' to mount the system filesystems read-only.
> READONLY=no
> # Set to 'yes' to mount various temporary state as either tmpfs
> # or on the block device labelled RW_LABEL. Implied by READONLY
> TEMPORARY_STATE=no
> # Place to put a tmpfs for temporary scratch writable space
> RW_MOUNT=/var/lib/stateless/writable
> # Label on local filesystem which can be used for temporary scratch space
> RW_LABEL=stateless-rw
> # Options to use for temporary mount
> RW_OPTIONS=
> # Label for partition with persistent data
> STATE_LABEL=stateless-state
> # Where to mount to the persistent data
> STATE_MOUNT=/var/lib/stateless/state
> # Options to use for peristent mount
> STATE_OPTIONS=
> ---------------------- snap ------------------------------

Is /etc/ mounted as a tmpfs or something like that?

Comment 6 Niels Haase 2009-04-10 20:34:54 UTC
Reporter, could you please reply to the previous question? If you won't reply in one month, I will have to close this bug as INSUFFICIENT_DATA. Thank you.

-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 7 Joachim Backes 2009-04-11 06:00:42 UTC
1. No, /etc/ is not mounted as tmpfs or something other.
2. Since some NetworkManager versions, my /etc/resolv.conf is OK (I reported this already to another thread).

Comment 8 Dan Williams 2009-10-15 04:06:57 UTC
Ok, thanks for the report.  Please let us know if this happens again!