Delayed network reconnect and resolv.conf getting 127.0.0.1

[yaaang]

I'm running Ubuntu 12.04 in VirtualBox 4.2.18 r88780 (with the latest Extension Pack installed on host and re-installed/updated on guest) on a MacBook running Mac OS X 10.8.5. The VM is configured to use NAT (since I need to access servers running in the guest from the host). The guest Ubuntu just runs Ubuntu Desktop, so the network stack is managed by NetworkManager.

The symptoms: after resuming my Macbook, my SSH connection to the VM is unresponsive. Switching to the VirtualBox display window, I can see from NetworkManager that the network is disconnected and that /etc/resolv.conf lists zero nameservers. Then the network is re-establishing for about 15-30 seconds. After becoming re-established, the guest can reach Internet IPs, but DNS resolution is broken since /etc/resolv.conf now has 127.0.0.1 as the only nameserver.

I don't believe this has always happened - I started noticing it happening a couple months back.

My questions:

1. What's going on with the disconnection and reconnection delay? Slightly annoying to have to wait for SSH to come back.
2. What's going on with the nameserver and how do I fix it? My workaround is to manually change 127.0.0.1 to e.g. 8.8.8.8 in /etc/resolv.conf.

Here are some details from the guest:

Code: Select all

$ uname -a
Linux yang-vbox-ubuntu 3.5.0-41-generic #64~precise1-Ubuntu SMP Thu Sep 12 16:50:04 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 12.04.3 LTS
Release:        12.04
Codename:       precise

$ ip addr
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 16436 qdisc noqueue state UNKNOWN
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000
    link/ether 08:00:27:69:20:88 brd ff:ff:ff:ff:ff:ff
    inet 10.0.2.15/24 brd 10.0.2.255 scope global eth0
    inet6 fe80::a00:27ff:fe69:2088/64 scope link
       valid_lft forever preferred_lft forever

$ ip link
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 16436 qdisc noqueue state UNKNOWN
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000
    link/ether 08:00:27:69:20:88 brd ff:ff:ff:ff:ff:ff

$ cat /etc/resolv.conf
# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
nameserver 127.0.0.1

$ less /var/log/syslog
...
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): carrier now ON (device state 20)
Oct 22 16:52:25 yang-vbox-ubuntu kernel: [474262.748760] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
Oct 22 16:52:25 yang-vbox-ubuntu kernel: [474262.749423] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Auto-activating connection 'Wired connection 1'.
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) starting connection 'Wired connection 1'
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): device state change: prepare -> config (reason 'none') [40 50 0]
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful.
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): device state change: config -> ip-config (reason 'none') [50 70 0]
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> dhclient started with pid 1967
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Beginning IP6 addrconf.
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: Internet Systems Consortium DHCP Client 4.1-ESV-R4
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: Copyright 2004-2011 Internet Systems Consortium.
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: All rights reserved.
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: For info, please visit https://www.isc.org/software/dhcp/
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: 
Oct 22 16:52:25 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): DHCPv4 state changed nbi -> preinit
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: Listening on LPF/eth0/08:00:27:69:20:88
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: Sending on   LPF/eth0/08:00:27:69:20:88
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: Sending on   Socket/fallback
Oct 22 16:52:25 yang-vbox-ubuntu dhclient: DHCPREQUEST of 10.0.2.15 on eth0 to 255.255.255.255 port 67
Oct 22 16:52:27 yang-vbox-ubuntu avahi-daemon[533]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::a00:27ff:fe69:2088.
Oct 22 16:52:27 yang-vbox-ubuntu avahi-daemon[533]: New relevant interface eth0.IPv6 for mDNS.
Oct 22 16:52:27 yang-vbox-ubuntu avahi-daemon[533]: Registering new address record for fe80::a00:27ff:fe69:2088 on eth0.*.
Oct 22 16:52:28 yang-vbox-ubuntu dhclient: DHCPREQUEST of 10.0.2.15 on eth0 to 255.255.255.255 port 67
Oct 22 16:52:33 yang-vbox-ubuntu dhclient: DHCPREQUEST of 10.0.2.15 on eth0 to 255.255.255.255 port 67
Oct 22 16:52:40 yang-vbox-ubuntu dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 3
Oct 22 16:52:40 yang-vbox-ubuntu dhclient: DHCPREQUEST of 10.0.2.15 on eth0 to 255.255.255.255 port 67
Oct 22 16:52:40 yang-vbox-ubuntu dhclient: DHCPOFFER of 10.0.2.15 from 10.0.2.2
Oct 22 16:52:40 yang-vbox-ubuntu dhclient: DHCPACK of 10.0.2.15 from 10.0.2.2
Oct 22 16:52:40 yang-vbox-ubuntu dhclient: bound to 10.0.2.15 -- renewal in 36515 seconds.
Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): DHCPv4 state changed preinit -> bound
Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info>   address 10.0.2.15
Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info>   prefix 24 (255.255.255.0)
Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info>   gateway 10.0.2.2
Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info>   nameserver '10.0.2.3'
Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Commit) started...
Oct 22 16:52:40 yang-vbox-ubuntu avahi-daemon[533]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.0.2.15.
Oct 22 16:52:40 yang-vbox-ubuntu avahi-daemon[533]: New relevant interface eth0.IPv4 for mDNS.
Oct 22 16:52:40 yang-vbox-ubuntu avahi-daemon[533]: Registering new address record for 10.0.2.15 on eth0.IPv4.
Oct 22 16:52:41 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): writing resolv.conf to /sbin/resolvconf
Oct 22 16:52:41 yang-vbox-ubuntu dnsmasq[939]: setting upstream servers from DBus
Oct 22 16:52:41 yang-vbox-ubuntu dnsmasq[939]: using nameserver 10.0.2.3#53
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) successful, device activated.
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Commit) complete.
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> (eth0): IP6 addrconf timed out or failed.
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 4 of 5 (IPv6 Configure Timeout) started...
Oct 22 16:52:52 yang-vbox-ubuntu NetworkManager[753]: <info> Activation (eth0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
Oct 22 16:52:52 yang-vbox-ubuntu dbus[500]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Oct 22 16:52:52 yang-vbox-ubuntu dbus[500]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 22 16:53:42 yang-vbox-ubuntu ntpdate[2048]: Can't find host ntp.ubuntu.com: Name or service not known (-2)
Oct 22 16:53:42 yang-vbox-ubuntu ntpdate[2048]: no servers can be used, exiting

Here is the state on the host (it does not have any nameserver of 127.0.0.1).

Code: Select all

$ ifconfig
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> mtu 16384
	options=3<RXCSUM,TXCSUM>
	inet6 fe80::1%lo0 prefixlen 64 scopeid 0x1
	inet 127.0.0.1 netmask 0xff000000
	inet6 ::1 prefixlen 128
gif0: flags=8010<POINTOPOINT,MULTICAST> mtu 1280
stf0: flags=0<> mtu 1280
en0: flags=8863<UP,BROADCAST,SMART,RUNNING,SIMPLEX,MULTICAST> mtu 1500
	ether 20:c9:d0:89:f1:ab
	inet6 fe80::22c9:d0ff:fe89:f1ab%en0 prefixlen 64 scopeid 0x4
	inet 10.66.224.133 netmask 0xffffff00 broadcast 10.66.224.255
	media: autoselect
	status: active
p2p0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 2304
	ether 02:c9:d0:89:f1:ab
	media: autoselect
	status: inactive

$ cat /etc/resolv.conf
#
# Mac OS X Notice
#
# This file is not used by the host name and address resolution
# or the DNS query routing mechanisms used by most processes on
# this Mac OS X system.
#
# This file is automatically generated.
#
nameserver 8.8.8.8
nameserver 156.154.70.1

There have been a string of related issues in the past, but they seem to be fixed and I don't see any directly reflecting my circumstance.

https://www.virtualbox.org/ticket/421
https://www.virtualbox.org/ticket/1470
https://www.virtualbox.org/ticket/3847
https://www.virtualbox.org/ticket/10864

Any help would be greatly appreciated. Thanks in advance.

[vushakov]

Ubuntu uses dnsmasq as caching resolver so "nameserver 127.0.0.1" is intended.

In slighly older versions of 12.04 the address of the real resolver (that dnsmasq talks to) can be found in /var/run/nm-dns-dnsmasq.conf In newever versions that file is still around but it just tells you

Code: Select all

# DNSMasq configuration is now done via DBUS.
# See /var/log/syslog for the nameservers used.
# You can use files in /etc/NetworkManager/dnsmasq.d
# to configure dnsmasq.

so check syslog for lines matching 'NetworkManager.*nameserver'

[yaaang]

Thanks @vushakov, very interesting. However, my n-dns-dnsmasq.conf does just contain that comment *and* I found no mention of NetworkManager.* in my syslog (which I had pasted in my original post).

However the log does say some things from dnsmasq, specifically:

Code: Select all

Oct 22 16:52:41 yang-vbox-ubuntu dnsmasq[939]: setting upstream servers from DBus
Oct 22 16:52:41 yang-vbox-ubuntu dnsmasq[939]: using nameserver 10.0.2.3#53

When I manually try to query 10.0.2.3 from the guest, I see:

Code: Select all

$ dig @10.0.2.3 google.com
;; Warning: query response not set

; <<>> DiG 9.8.1-P1 <<>> @10.0.2.3 google.com
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 62506
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; WARNING: recursion requested but not available

;; QUESTION SECTION:
;google.com.                    IN      A

;; Query time: 6 msec
;; SERVER: 10.0.2.3#53(10.0.2.3)
;; WHEN: Wed Oct 23 11:42:50 2013
;; MSG SIZE  rcvd: 28

Is the problem in the VBox DNS server refusing recursion? Still don't know what's going on here.

[vushakov]

... *and* I found no mention of NetworkManager.* in my syslog (which I had pasted in my original post).

Heh, I didn't notice it, hasn't scrolled down far enough. The line actually *was* there, sorry.

Code: Select all

Oct 22 16:52:40 yang-vbox-ubuntu NetworkManager[753]: <info>   nameserver '10.0.2.3'

Is the problem in the VBox DNS server refusing recursion? Still don't know what's going on here.

10.0.2.3 - so you use DNS proxy or host resolver. They are described in the manual here: http://www.virtualbox.org/manual/ch09.html#nat-adv-dns

Unfortunately, I can't seem to find a way to query from the command line which one is used, short of looking at the VM's *.vbox XML file, at the Network/Adapter/NAT/DNS element. You should see something like:

Code: Select all

<DNS pass-domain="true" use-proxy="true" use-host-resolver="false"/>

[yaaang]

That seems to have fixed the problem—thank you!

My file had:

Code: Select all

...
          <NAT>
            <DNS pass-domain="true" use-proxy="false" use-host-resolver="false"/>
            <Alias logging="false" proxy-only="false" use-same-ports="false"/>
            <Forwarding name="Rule 1" proto="1" hostport="8000" guestport="80"/>
            <Forwarding name="Rule 2" proto="1" hostport="1122" guestport="22"/>
          </NAT>
...

Note: I've never changed any settings on this VM other than choosing NAT and configuring some port forwarding. I don't know why VirtualBox is causing my guest to rely on this being turned on.

Also, when I first boot the machine (rather than coming back from a suspend), DNS is working fine.

Anyway I set use-proxy to true (done via the command-line in the doc you linked to), and now things seem to be working consistently. Thanks again. Very bizarre that this is happening at all.

[vushakov]

I think that when there are problems reading host's nameservers from resolv.conf VBox will automatically swtich to "host resolver" mode. You can probably get more information from the VM log (look for "NAT").

[yaaang]

Alas, I spoke too soon! It's still not working. I'm not sure how I was convinced it was working earlier, but DNS resolutions still are definitely not working, and use-proxy is true for the VM (it has been stopped and started).

Perhaps the reason why I thought it was working earlier was because I tried suspending/resuming while on the same network (and hence host DNS settings) as the one the VM originally started/booted in—perhaps things continue to work in that situation. I'm not sure (would need to experiment a lot more—usually when I suspend/resume, I'm taking the laptop somewhere else with a different Wi-Fi network). Might VirtualBox not be able to handle this situation where the DNS settings are changing? Any more clues on how to debug this?

[vushakov]

It looks like there are problems getting the list of nameservers from the host. Please, can you disable DNS proxy and check in the VM log what NAT has to say about it. And what does /etc/resolv.conf contain at that time.

[yaaang]

Well if I reset use-proxy back to false then it'll just be the same log output and resolv.conf as what I pasted originally. resolv.conf is always just set to 127.0.0.1, which makes sense according to what you said about dnsmasq....

[vushakov]

I mean virtualbox log in VirtualBox VMs/$name/Logs/VBox.log

[yaaang]

I just reopened my computer to find this reoccurring. Here's my nearly-complete latest VBox.log (hitting char limit, pasted complete log to http://pastebin.com/089m96cE):

Code: Select all

...
00:00:16.212772 Audio: set_record_source ars=0 als=0 (not implemented)
00:00:16.663942 Guest Additions capability report: (0x4) seamless: no, hostWindowMapping: no, graphics: yes
00:00:16.752974 Guest Additions capability report: (0x4) seamless: no, hostWindowMapping: no, graphics: yes
00:00:16.753272 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
00:00:16.753295 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000111185000 w=952 h=720 bpp=32 cbLine=0xEE0, flags=0x1
00:00:16.836915 Guest Additions capability report: (0x4) seamless: no, hostWindowMapping: no, graphics: yes
00:00:16.837006 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
00:00:16.858121 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000111185000 w=952 h=720 bpp=32 cbLine=0xEE0, flags=0x1
00:00:17.337444 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff88007794a810), OR(0x0), NOT(0xffffffff), flags(0x0)
00:00:17.671577 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
00:00:17.788885 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff880077f46210), OR(0x0), NOT(0xffffffff), flags(0x0)
00:00:18.571920 EHCI: USB Operational
00:00:21.033840 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff880057a12610), OR(0x0), NOT(0xffffffff), flags(0x0)
00:00:21.110620 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff880057a12c10), OR(0x0), NOT(0xffffffff), flags(0x0)
00:00:21.411232 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff880057a12810), OR(0x0), NOT(0xffffffff), flags(0x0)
00:00:21.484093 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff8800523b5410), OR(0x0), NOT(0xffffffff), flags(0x0)
00:00:21.558559 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff88005206ce10), OR(0x0), NOT(0xffffffff), flags(0x0)
00:00:23.939852 EHCI: USB Suspended
00:00:47.657990 Guest Log: VBoxGuest: VBoxGuestCommonGuestCapsAcquire: pSession(0xffff880058846610), OR(0x0), NOT(0xffffffff), flags(0x0)
00:11:41.687956 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
00:11:41.689826 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
00:11:41.689913 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
00:11:41.689957 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x3
00:11:41.689965 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
00:11:41.691350 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
00:11:41.691398 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x3
00:11:41.691406 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
00:11:41.691427 Display::handleDisplayResize(): Warning: resize postponed.
00:11:41.700621 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
05:21:52.813487 NAT: old socket rcv size: 207KB
05:21:52.813883 NAT: old socket snd size: 79KB
06:05:09.601773 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
06:05:09.607196 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
06:05:09.608108 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000111185000 w=952 h=720 bpp=32 cbLine=0xEE0, flags=0x1
06:05:09.608694 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
06:05:09.608730 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
06:15:42.323580 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
06:15:42.323691 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
06:15:42.323763 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
06:15:42.323833 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x3
06:15:42.323843 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
06:15:42.323972 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
06:15:42.324015 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x3
06:15:42.324022 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
06:15:42.324027 Display::handleDisplayResize(): Warning: resize postponed.
06:15:42.331970 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
07:00:46.387457 Pausing VM execution, reason "host suspend"
07:00:46.390992 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
07:00:46.398206 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0781) created successfully
07:00:46.429408 PDMR3Suspend: 36 712 904 ns run time
07:00:46.429428 Changing the VM state from 'SUSPENDING' to 'SUSPENDED'.
07:04:18.351916 Resuming VM execution, reason "host resume"
07:04:18.385163 Changing the VM state from 'SUSPENDED' to 'RESUMING'.
07:04:18.431381 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0723) created successfully
07:04:18.462235 Changing the VM state from 'RESUMING' to 'RUNNING'.
07:04:19.744846 NAT: link up
07:04:19.760789 NAT: link up
07:04:26.215115 NAT: DNS#0: 8.8.8.8
07:04:26.215708 NAT: DNS#1: 8.8.4.4
07:04:26.215714 NAT: DNS#2: 192.168.10.1
07:04:26.215746 NAT: DHCP offered IP address 10.0.2.15
07:17:27.263038 Pausing VM execution, reason "host suspend"
07:17:27.268270 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
07:17:27.276174 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0781) created successfully
07:17:27.378441 PDMR3Suspend: 110 146 708 ns run time
07:17:27.378457 Changing the VM state from 'SUSPENDING' to 'SUSPENDED'.
07:18:05.169900 Resuming VM execution, reason "host resume"
07:18:05.170699 Changing the VM state from 'SUSPENDED' to 'RESUMING'.
07:18:05.170881 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0723) created successfully
07:18:05.203508 Changing the VM state from 'RESUMING' to 'RUNNING'.
07:18:05.285567 NAT: link up
07:18:11.787798 NAT: DHCP offered IP address 10.0.2.15
07:18:22.200223 NAT: link up
07:18:22.263053 NAT: link up
07:18:29.850967 NAT: DHCP offered IP address 10.0.2.15
07:18:33.836114 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
07:18:33.836269 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
07:18:33.836340 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000111185000 w=952 h=720 bpp=32 cbLine=0xEE0, flags=0x1
07:18:33.836513 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
07:18:33.836620 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1

[vushakov]

And what does /etc/resolv.conf contain at that time? From the VM log I guess (unfortunately the failure is not logged), that NAT was unable to get the list of nameservers from the host on last resume, switched to host resolver mode and NAT's DHCP offered you 10.0.2.3 as resolver again; but I'm almost certain the problem stems from /etc/resolv.conf. May be there's something in it that NAT doesn't like, may be there's a race condition between host updating its /etc/resolv.conf on resume and NAT's rereading it.

[yaaang]

It's happening right now and /etc/resolv.conf contains (currently in a building owned by AOL):

Code: Select all

# Mac OS X Notice
#
# This file is not used by the host name and address resolution
# or the DNS query routing mechanisms used by most processes on
# this Mac OS X system.
#
# This file is automatically generated.
#
domain office.aol.com
nameserver 8.8.8.8
nameserver 156.154.70.1

New content in VBox.log:

Code: Select all

...
07:18:33.836620 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
07:21:47.749549 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
07:21:47.751208 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0781) created successfully
07:21:47.813088 PDMR3Suspend: 63 518 908 ns run time
07:21:47.813125 Changing the VM state from 'SUSPENDING' to 'SUSPENDED'.
07:21:47.816653 ************************* CFGM dump *************************
07:21:47.817318 [/Devices/piix3ide/0/] (level 0)
07:21:47.817893   PCIBusNo      <integer> = 0x0000000000000000 (0)
07:21:47.817897   PCIDeviceNo   <integer> = 0x0000000000000001 (1)
07:21:47.817898   PCIFunctionNo <integer> = 0x0000000000000001 (1)
07:21:47.817900   Trusted       <integer> = 0x0000000000000001 (1)
07:21:47.818246 
07:21:47.818248 [/Devices/piix3ide/0/Config/] (level 1) (restricted root)
07:21:47.818252   Type <string>  = "PIIX4" (cb=6)
07:21:47.818254 
07:21:47.818254 [/Devices/piix3ide/0/Config/SecondaryMaster/] (level 2)
07:21:47.818258   NonRotationalMedium <integer> = 0x0000000000000000 (0)
07:21:47.818260 
07:21:47.818260 [/Devices/piix3ide/0/LUN#2/] (level 1)
07:21:47.818263   Driver <string>  = "Block" (cb=6)
07:21:47.818264 
07:21:47.818265 [/Devices/piix3ide/0/LUN#2/AttachedDriver/] (level 2)
07:21:47.818267   Driver <string>  = "VD" (cb=3)
07:21:47.818269 
07:21:47.818269 [/Devices/piix3ide/0/LUN#2/AttachedDriver/Config/] (level 3) (restricted root)
07:21:47.818272   Format   <string>  = "RAW" (cb=4)
07:21:47.818273   Path     <string>  = "/Applications/VirtualBox.app/Contents/MacOS/VBoxGuestAdditions.iso" (cb=67)
07:21:47.818275   ReadOnly <integer> = 0x0000000000000001 (1)
07:21:47.818276   Type     <string>  = "DVD" (cb=4)
07:21:47.818278 
07:21:47.818279 [/Devices/piix3ide/0/LUN#2/Config/] (level 2) (restricted root)
07:21:47.818282   Mountable <integer> = 0x0000000000000001 (1)
07:21:47.818284   Type      <string>  = "DVD" (cb=4)
07:21:47.818285 
07:21:47.818285 [/Devices/piix3ide/0/LUN#999/] (level 1)
07:21:47.818288   Driver <string>  = "MainStatus" (cb=11)
07:21:47.818290 
07:21:47.818291 [/Devices/piix3ide/0/LUN#999/Config/] (level 2) (restricted root)
07:21:47.818293   DeviceInstance        <string>  = "piix3ide/0" (cb=11)
07:21:47.818294   First                 <integer> = 0x0000000000000000 (0)
07:21:47.818296   Last                  <integer> = 0x0000000000000003 (3)
07:21:47.818298   pConsole              <integer> = 0x000000010383a600 (4 353 926 656)
07:21:47.818301   papLeds               <integer> = 0x000000010383a8f0 (4 353 927 408)
07:21:47.818303   pmapMediumAttachments <integer> = 0x000000010383abf8 (4 353 928 184)
07:21:47.818305 
07:21:47.818307 ********************* End of CFGM dump **********************
07:21:47.818314 Changing the VM state from 'SUSPENDED' to 'RESUMING'.
07:21:47.822730 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0723) created successfully
07:21:47.824399 Changing the VM state from 'RESUMING' to 'RUNNING'.
07:21:47.826394 ERROR [COM]: aRC=NS_ERROR_FAILURE (0x80004005) aIID={db7ab4ca-2a3f-4183-9243-c1208da92392} aComponent={Console} aText={Could not mount the media/drive '/Users/yang/cache/software/ubuntu-12.04.2-desktop-amd64.iso' (VERR_PDM_MEDIA_LOCKED)}, preserve=false
07:32:24.038980 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
07:32:24.039073 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
07:32:24.039146 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
07:32:24.039193 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x3
07:32:24.039204 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
07:32:24.039356 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
07:32:24.039431 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x3
07:32:24.039440 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
07:32:24.039446 Display::handleDisplayResize(): Warning: resize postponed.
07:32:24.059654 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=952 h=720 bpp=0 cbLine=0x0, flags=0x3
08:13:08.458407 Pausing VM execution, reason "host suspend"
08:13:08.471358 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
08:13:08.471953 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0781) created successfully
08:13:08.503712 PDMR3Suspend: 32 327 169 ns run time
08:13:08.504050 Changing the VM state from 'SUSPENDING' to 'SUSPENDED'.
08:13:47.204322 Resuming VM execution, reason "host resume"
08:13:47.207585 Changing the VM state from 'SUSPENDED' to 'RESUMING'.
08:13:47.207918 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0723) created successfully
08:13:47.213002 Changing the VM state from 'RESUMING' to 'RUNNING'.
08:13:47.215333 NAT: link up
08:13:53.647530 NAT: DHCP offered IP address 10.0.2.15
08:13:55.567725 NAT: link up
08:13:55.589805 NAT: link up
09:05:53.026130 Pausing VM execution, reason "host suspend"
09:05:53.028423 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
09:05:53.030786 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0781) created successfully
09:05:53.082389 PDMR3Suspend: 53 947 775 ns run time
09:05:53.082410 Changing the VM state from 'SUSPENDING' to 'SUSPENDED'.
09:06:31.356050 Resuming VM execution, reason "host resume"
09:06:31.361892 Changing the VM state from 'SUSPENDED' to 'RESUMING'.
09:06:31.362089 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0723) created successfully
09:06:31.367536 Changing the VM state from 'RESUMING' to 'RUNNING'.
09:06:33.864065 NAT: link up
09:06:33.884398 NAT: link up
09:06:40.691039 NAT: DHCP offered IP address 10.0.2.15
09:12:52.743877 Pausing VM execution, reason "host suspend"
09:12:52.749555 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
09:12:52.755512 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0781) created successfully
09:12:52.797837 PDMR3Suspend: 48 258 013 ns run time
09:12:52.797856 Changing the VM state from 'SUSPENDING' to 'SUSPENDED'.
09:13:31.026195 Resuming VM execution, reason "host resume"
09:13:31.027867 Changing the VM state from 'SUSPENDED' to 'RESUMING'.
09:13:31.028042 AIOMgr: Endpoint for file '/Users/yang/VirtualBox VMs/Ubuntu 12.04 64-bit/Ubuntu 12.04 64-bit.vdi' (flags 000c0723) created successfully
09:13:31.956735 Changing the VM state from 'RESUMING' to 'RUNNING'.
09:13:33.074949 NAT: link up
09:13:33.091942 NAT: link up
09:13:38.724910 NAT: DHCP offered IP address 10.0.2.15
09:18:06.600954 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
09:18:06.601051 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1
09:18:06.601108 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000111185000 w=952 h=720 bpp=32 cbLine=0xEE0, flags=0x1
09:18:06.601229 Guest Additions capability report: (0x5) seamless: yes, hostWindowMapping: no, graphics: yes
09:18:06.601278 VBVA_INFO_SCREEN: [0] @0,0 952x720, line 0xee0, BPP 32, flags 0x1

[vushakov]

One more experiment that might help confirm my hypothesis is to suspend and resume the VM after it gets into this state after laptop is resumed. If after resuming the VM you get correct nameservers, then you are most likely seeing a race for /etc/resolv.conf. Otherwise, I'm out of ideas.

[yaaang]

I tried saving the VM state and resuming it, but DNS still doesn't work. I guess I'll try filing a bug. Thanks a lot for taking the time!