NAT Network goes inop after a few hours

[L.Shaner]

I am on macOS Sierra, 10.12.1 (lastest as of a while) on a MacBook Pro (17-inch, Late 2011) w/ 16 GB of RAM 2.5 GHz Intel Core i7 and an 6 Gb/s SSD as the internal HDD (containing all guests).
I am running VirtualBox Version 5.1.10 r112026 (Qt5.6.2).
As of VirtualBox 5.1.8 and also in 5.1.10, I have experienced my NAT Networked guests losing all network connectivity after a time of 1 to 3 hours, depending on number of guests running and how much network activity they are generating.
The only solution I have found is to shutdown all the guests and quit the VirtualBox manager so that no VirtualBox processes are running, then start up the guests again.
This is obviously very disruptive.

Another symptom of the problem is that the numerous port-forwarders on the NAT Network fail to connect through to the guest even upon initial startup of the guests.
To get the port forwarding to work I have to go edit the NAT Network portforwarding rules and just change a port or IP and re-save the same info.
Sometimes I have to use that workaround a couple of times before the port forwarding starts to work, but even after doing the workaround my guests still lose network connectivity after a while as describe above.

Other info:

Code: Select all

$ VBoxManage showvminfo "OL7u2-Docker-Tomcat-Jenkins"
Name:            OL7u2-Docker-Tomcat-Jenkins
Groups:          /
Guest OS:        Oracle (64-bit)
UUID:            6d9f9557-53c7-46f6-9589-f36d27b432ee
Config file:     /Local/VirtualBox/Machines/OL7u2-Docker-Tomcat-Jenkins/OL7u2-Docker-Tomcat-Jenkins.vbox
Snapshot folder: /Local/VirtualBox/Machines/OL7u2-Docker-Tomcat-Jenkins/Snapshots
Log folder:      /Local/VirtualBox/Machines/OL7u2-Docker-Tomcat-Jenkins/Logs
Hardware UUID:   6d9f9557-53c7-46f6-9589-f36d27b432ee
Memory size:     3072MB
Page Fusion:     off
VRAM size:       16MB
CPU exec cap:    100%
HPET:            off
Chipset:         piix3
Firmware:        BIOS
Number of CPUs:  1
PAE:             on
Long Mode:       on
Triple Fault Reset: off
APIC:            on
X2APIC:          on
CPUID Portability Level: 0
CPUID overrides: None
Boot menu mode:  message and menu
Boot Device (1): Floppy
Boot Device (2): DVD
Boot Device (3): HardDisk
Boot Device (4): Not Assigned
ACPI:            on
IOAPIC:          on
BIOS APIC mode:  APIC
Time offset:     0ms
RTC:             UTC
Hardw. virt.ext: on
Nested Paging:   on
Large Pages:     on
VT-x VPID:       on
VT-x unr. exec.: on
Paravirt. Provider: Default
Effective Paravirt. Provider: KVM
State:           running (since 2016-11-29T15:33:46.416000000)
Monitor count:   1
3D Acceleration: off
2D Video Acceleration: off
Teleporter Enabled: off
Teleporter Port: 0
Teleporter Address: 
Teleporter Password: 
Tracing Enabled: off
Allow Tracing to Access VM: off
Tracing Configuration: 
Autostart Enabled: off
Autostart Delay: 0
Default Frontend: 
Storage Controller Name (0):            IDE
Storage Controller Type (0):            PIIX4
Storage Controller Instance Number (0): 0
Storage Controller Max Port Count (0):  2
Storage Controller Port Count (0):      2
Storage Controller Bootable (0):        on
Storage Controller Name (1):            SATA
Storage Controller Type (1):            IntelAhci
Storage Controller Instance Number (1): 0
Storage Controller Max Port Count (1):  30
Storage Controller Port Count (1):      3
Storage Controller Bootable (1):        on
IDE (1, 0): Empty
SATA (0, 0): /Local/VirtualBox/Machines/OL7u2-Docker-Tomcat-Jenkins/Snapshots/{075a12d5-572b-438d-9e28-07e4e42f6fa9}.vmdk (UUID: 075a12d5-572b-438d-9e28-07e4e42f6fa9)
SATA (1, 0): /Local/VirtualBox/Machines/OL7u2-Docker-Tomcat-Jenkins/Snapshots/{f7174714-235b-4f60-9e83-0c941b26ad77}.vmdk (UUID: f7174714-235b-4f60-9e83-0c941b26ad77)
SATA (2, 0): /Local/VirtualBox/Machines/OL7u2-Docker-Tomcat-Jenkins/Snapshots/{4035586a-bff0-4b5c-a44b-0504a8b328c3}.vmdk (UUID: 4035586a-bff0-4b5c-a44b-0504a8b328c3)
NIC 1:           MAC: 080027943995, Attachment: NAT Network 'OMCLocalNet', Cable connected: on, Trace: off (file: none), Type: 82540EM, Reported speed: 0 Mbps, Boot priority: 0, Promisc Policy: allow-all, Bandwidth group: none
NIC 2:           disabled
NIC 3:           disabled
NIC 4:           disabled
NIC 5:           disabled
NIC 6:           disabled
NIC 7:           disabled
NIC 8:           disabled
Pointing Device: PS/2 Mouse
Keyboard Device: PS/2 Keyboard
UART 1:          disabled
UART 2:          disabled
UART 3:          disabled
UART 4:          disabled
LPT 1:           disabled
LPT 2:           disabled
Audio:           enabled (Driver: CoreAudio, Controller: AC97, Codec: AD1980)
Clipboard Mode:  disabled
Drag and drop Mode: disabled
Session name:    GUI/Qt
Video mode:      800x600x32 at 0,0 enabled
VRDE:            disabled
USB:             enabled
EHCI:            enabled
XHCI:            disabled

USB Device Filters:

<none>

Available remote USB devices:

<none>

Currently Attached USB Devices:

<none>

Bandwidth groups:  <none>

Shared folders:  <none>

VRDE Connection:    not active
Clients so far:     0

Video capturing:    not active
Capture screens:    0
Capture file:       /Local/VirtualBox/Machines/OL7u2-Docker-Tomcat-Jenkins/OL7u2-Docker-Tomcat-Jenkins.webm
Capture dimensions: 1024x768
Capture rate:       512 kbps
Capture FPS:        25

Guest:

Configured memory balloon size:      0 MB
OS type:                             Linux26_64
Additions run level:                 2
Additions version:                   5.1.10 r112026


Guest Facilities:

Facility "VirtualBox Base Driver": active/running (last update: 2016/11/29 15:33:56 UTC)
Facility "VirtualBox System Service": active/running (last update: 2016/11/29 15:34:02 UTC)
Facility "Seamless Mode": active/running (last update: 2016/11/29 15:33:56 UTC)
Facility "Graphics Mode": active/running (last update: 2016/11/29 15:33:56 UTC)

Snapshots:

   Name: Clean before installing Docker Engine (UUID: ac3629db-6eea-43fa-99c0-20bf98e44283)
      Name: jenkins040 (UUID: 9ed43899-9edf-415a-b8a8-427aba6d606e) *
      Description:
With Jenkins installed and /u01/docker/{host_name}/{catalina_base_directory}/usr/local/tomcat directory structure in place

[socratis]

Can you please try and see if this happens without the use of Docker? Docker is a program that relies on VirtualBox but modifies its configuration files in unknown ways to us. It is not supported on these VirtualBox user forums, they have their own support channels. If you are having this problem with a standalone version of VirtualBox, then we can continue this discussion.


PS. Good thinking for using the <code> tag. However, I don't know where you copied your "other info" from, but a) it's very difficult to read and b) it contained characters that could not be displayed. It needs some formatting "massage" to make it easier to read/parse. For example:

Code: Select all

General
Name:           OL7u2-Docker-Tomcat-Jenkins
OS Type:        Oracle (64-bit)

System
Base Memory:    3072
Processor(s):   1
Execution Cap:  100
Boot Order:     Floppy, Optical, Hard Disk
VT-x/AMD-V:     Enabled
...

[L.Shaner]

Hi, Socratis. I have multiple guests, including Windows 10 and several Oracle Linux 7u2, without Docker and all the guests are affected when the NAT Network goes south. The guest with the Docker Engine is just the one that I was working with at the time that I reported the issue.

[L.Shaner]

Hi, Socrates, about the "other info" it was a copy paste from VirtualBoxGuest -> Machine -> Session information.
So would it be an RFE to have that information formatted in a way that doesn't contain special characters?

[socratis]

In that case, please run one or more stand-alone guests (preferably just one), observe the problem and once you do, shut down the VM completely, right-click on the VM in the VirtualBox Manager, show log, save it (just the VBox.log), zip it and attach it to your response.

[socratis]

the "other info" it was a copy paste from VirtualBoxGuest -> Machine -> Session information.

Really? Is that what happens? Damn... I usually run "VBoxManage showvminfo <VMName>" from the command line, nice and clean. I'll have to take a look at the "Session information" dialog and possibly tell the devs about it.

Update: Yikes! That's one ugly copy/paste! I'll take a look at the bug tracker and see what I come up with.

[L.Shaner]

Update: Yikes! That's one ugly copy/paste! I'll take a look at the bug tracker and see what I come up with.

Thanks. I re-edited my original post and substituted the "showvminfo" output instead.

I'll upload the VBox.log (zip) from a guest not running Docker, but I need to leave the Docker guest also running, because it's my day job.

[socratis]

but I need to leave the Docker guest also running, because it's my day job.

I was hoping to having that avoided to take any parameters out of the equation, but you can't win them all...

Thank you for updating the info. As I said, I'll look in the bugtracker and if not there, I'll try to file a bug report. The thing is I'm not sure if they have control over the copy/paste process, since this seems to be a part of the Qt forms.

[L.Shaner]

Interesting...

Below is a snippet of the logs from shortly after the (non-Docker) guest was started up to the point that the networking went south, and until I shut it down.
Not much activity in the logs. Also attached are the full logs.

I haven't watched the logs carefully before upon normal startup so I am not sure if those Software reset, Hardware reset, USB Reset, USB Suspended, ATA Rest, AC97 Reset are all "normal" shortly after the guest is started?

My Mac is disallowed from sleeping, when plugged into power, but the display was asleep when I checked in on it.
I had a script running on the host to SSH into the guest from time to time and send a Growl-style notification as soon as the SSH logins stopped working.
The script was aimed at alerting me at the moment when the guest NAT Networking went south, but the problem apparently happened while I was away at dinner. :S

The thing is the notification from the SSH test script popped as soon as I touched the keyboard, to wake the display.
So now I wonder if my Mac was actually sleeping and not just the display...perhaps some new macOS Sierra quirk? Hmm...
Hmm... Could the display going to sleep be having an adverse effect on the guest?
I would expect the guest to keep running even if the host display is asleep... :-/

FWIW:
$ sudo systemsetup -getcomputersleep
Computer Sleep: Never

Log Snippet:

Code: Select all

00:00:10.676331 PIT: mode=2 count=0x4a9 (1193) - 1000.15 Hz (ch=0)
00:00:10.874743 PIT: mode=0 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:10.987004 OHCI: Software reset
00:00:11.312119 EHCI: Hardware reset
00:00:11.312331 EHCI: USB Operational
00:00:11.318995 OHCI: USB Reset
00:00:11.369696 OHCI: Software reset
00:00:11.369753 OHCI: USB Operational
00:00:11.418933 EHCI: USB Suspended
00:00:11.494576 OHCI: USB Suspended
00:00:11.737680 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=0 CmdIf0=0x00 (-1 usec ago) CmdIf1=0x00 (-1 usec ago)
00:00:11.737753 PIIX3 ATA: Ctl#0: finished processing RESET
00:00:11.739982 PIIX3 ATA: Ctl#1: RESET, DevSel=0 AIOIf=0 CmdIf0=0xa0 (-1 usec ago) CmdIf1=0x00 (-1 usec ago)
00:00:11.740037 PIIX3 ATA: Ctl#1: finished processing RESET
00:00:12.202649 AHCI#0: Reset the HBA
00:00:12.210242 AHCI#0: Port 0 reset
00:00:12.521602 AHCI#0: Port 1 reset
00:00:13.117133 AIOMgr: Host limits number of active IO requests to 16. Expect a performance impact.
00:00:15.329275 AC97: Reset
00:00:15.329737 AC97: Reset
00:00:25.827305 Display::handleDisplayResize: uScreenId=0 pvVRAM=0000000113b1f000 w=1024 h=768 bpp=32 cbLine=0x1000 flags=0x1
00:00:25.827370 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=1024x768, Sending to async-handler
00:00:25.827457 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=1024x768
00:00:25.827468 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=1024x768
00:00:25.827495 GUI: UIFrameBufferPrivate::performResize: Size=1024x768, Directly using source bitmap content
02:14:37.957882 GUI: UIDesktopWidgetWatchdog::sltHandleHostScreenWorkAreaResized: Screen 0 work area is formally resized to: 34x23 x 1886x1177
02:16:34.571034 GUI: UIDesktopWidgetWatchdog::sltHandleHostScreenWorkAreaResized: Screen 0 work area is formally resized to: 35x23 x 1885x1177
02:59:53.915898 GUI: UIDesktopWidgetWatchdog::sltHandleHostScreenWorkAreaResized: Screen 0 work area is formally resized to: 34x23 x 1886x1177
08:54:31.891786 Display::handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x1
08:54:31.893069 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=720x400, Sending to async-handler
08:54:31.893200 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=720x400
08:54:31.893213 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=720x400
08:54:31.893234 GUI: UIFrameBufferPrivate::performResize: Size=720x400, Directly using source bitmap content
08:54:35.215852 OHCI: Software reset
08:54:35.227807 ACPI: Entering S5 power state (power down)
08:54:35.227827 Changing the VM state from 'RUNNING' to 'POWERING_OFF'
08:54:35.227849 ****************** Guest state at power off for VCpu 0 ******************

[L.Shaner]

Having now started the guest again, I checked... These types of "reset" messages are a "normal" occurrence upon guest startup in my environment.
But are they expected in general, i.e. is this normal behavior for these devices to go through a reset cycle at guest startup?

Code: Select all

00:00:10.553940 PIT: mode=2 count=0x4a9 (1193) - 1000.15 Hz (ch=0)
00:00:10.796250 PIT: mode=0 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:10.910695 OHCI: Software reset
00:00:11.239939 EHCI: Hardware reset
00:00:11.240106 EHCI: USB Operational
00:00:11.246165 OHCI: USB Reset
00:00:11.297441 OHCI: Software reset
00:00:11.297496 OHCI: USB Operational
00:00:11.346080 EHCI: USB Suspended
00:00:11.414356 OHCI: USB Suspended
00:00:12.057346 AHCI#0: Reset the HBA
00:00:12.064512 AHCI#0: Port 0 reset
00:00:12.068818 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=0 CmdIf0=0x00 (-1 usec ago) CmdIf1=0x00 (-1 usec ago)
00:00:12.068893 PIIX3 ATA: Ctl#0: finished processing RESET
00:00:12.071828 PIIX3 ATA: Ctl#1: RESET, DevSel=0 AIOIf=0 CmdIf0=0xa0 (-1 usec ago) CmdIf1=0x00 (-1 usec ago)
00:00:12.071902 PIIX3 ATA: Ctl#1: finished processing RESET
00:00:12.371652 AHCI#0: Port 1 reset
00:00:12.999453 AIOMgr: Host limits number of active IO requests to 16. Expect a performance impact.
00:00:15.064334 AC97: Reset
00:00:15.064748 AC97: Reset
00:00:26.852689 Display::handleDisplayResize: uScreenId=0 pvVRAM=0000000118d2b000 w=1024 h=768 bpp=32 cbLine=0x1000 flags=0x1
00:00:26.852742 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=1024x768, Sending to async-handler
00:00:26.852810 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=1024x768
00:00:26.852817 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=1024x768
00:00:26.852832 GUI: UIFrameBufferPrivate::performResize: Size=1024x768, Directly using source bitmap content

[L.Shaner]

Hmm... From what I can tell the following messages correspond to when my display went to sleep:
So the guest is aware of the display going to sleep... I wonder if it is unexpectedly affecting guest operations?

Code: Select all

02:14:37.957882 GUI: UIDesktopWidgetWatchdog::sltHandleHostScreenWorkAreaResized: Screen 0 work area is formally resized to: 34x23 x 1886x1177
02:16:34.571034 GUI: UIDesktopWidgetWatchdog::sltHandleHostScreenWorkAreaResized: Screen 0 work area is formally resized to: 35x23 x 1885x1177
02:59:53.915898 GUI: UIDesktopWidgetWatchdog::sltHandleHostScreenWorkAreaResized: Screen 0 work area is formally resized to: 34x23 x 1886x1177

Then the first message seen after waking the display is:

Code: Select all

08:54:31.891786 Display::handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x1
08:54:31.893069 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=720x400, Sending to async-handler
08:54:31.893200 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=720x400
08:54:31.893213 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=720x400
08:54:31.893234 GUI: UIFrameBufferPrivate::performResize: Size=720x400, Directly using source bitmap content
08:54:35.215852 OHCI: Software reset

Seems as if the display sleeping and waking is at least correlated to the networking dropping off... Correlation, but what about causation?

[L.Shaner]

Another datapoint. My SSH test script had reported the time the networking had stopped, at about 7:45 p.m., but it was much later when I re-woke the display and heard the notification. My present thinking is that notifications queue while the display is sleeping, but never-the-less, the network had dropped off a long time before I re-woke the display.

Here are the last date stamps from the my SSH test script:

Code: Select all

Tue Nov 29 19:44:54 EST 2016
Tue Nov 29 19:44:59 EST 2016
ssh_exchange_identification: read: Connection reset by peer

And here is the script itself if anyone is interested... This relies on SSH authorized_keys in the guest OS so that passwordless login is allowed via ssh from host to guest (and with port forwarding enabled in the NAT Network from 2240 in my case to 22 in the guest).

Code: Select all

#!/bin/bash
ssh -p 2240 ocloud@10.0.2.2 date
RC=$?
if [ $RC -ne 0 ] ; then
	osascript -e 'display notification time string of (current date) with title "VBox Guest is Down!"'
	exit
fi
sleep 5
exec $0

[socratis]

Couple of things:

1. Yes, the reset messages are normal, as you already figured out.
2. There's nothing in the VBox.log showing a network glitch.
3. Try "/Users/<username>/Library/VirtualBox/VBoxNATNetwork.log" and "/Users/<username>/Library/VirtualBox/VBoxSVC.log" for a session that fails. Let's see what they have to say.
4. I'll try to repeat your setup and leave it overnight so we can compare notes. I don't have an Oracle-64bit guest, but I don't think it should matter. If it does, then we're veering off in different waters.
5. Thank you for posting the script, I was about to ask you if you could possibly post it.

[socratis]

Wait a minute... I took a second look at your logs, in the part where I (foolishly) skipped the first time (note to self: never rely on snippets of a log posted in the answer, it can be really misleading).

You do not have a NATNetwork in your guest! You only have one network card with "Internal Network"!

Care to explain what's going on? And since you're at it, right-click on the VM in the VirtualBox Manager, show in Finder, zip the .vbox file and post it.

[L.Shaner]

As a test, I disabled the display sleep and let the guest run over night.
The networking was fine all the way through to 7:33 a.m. this morning, which is many more hours than usual! =D

As before, the logs through the period when the networking stopped pertain only to screen resolution changes.
Full logs attached. I'll look into the other suggestions after this post.

Meanwhile...
The following messages are from just after the guest was booted and they reflect the change from the text console to the GNOME login:

Code: Select all

00:00:26.513893 Display::handleDisplayResize: uScreenId=0 pvVRAM=000000011097a000 w=1024 h=768 bpp=32 cbLine=0x1000 flags=0x1
00:00:26.513944 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=1024x768, Sending to async-handler
00:00:26.514005 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=1024x768
00:00:26.514016 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=1024x768
00:00:26.514032 GUI: UIFrameBufferPrivate::performResize: Size=1024x768, Directly using source bitmap content

Then this morning, I checked in on the guest about an hour after the SSH test had logged that the networking had gone off line.
There is no message about the screen 0 changing size, so that much was definitely due to the screen sleeping in the prior cases.
However, there is also no message about networking issues in the log either.
The next message after the above is the screen resolution change from shutting down the guest:

Code: Select all

09:34:23.315509 Display::handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x1
09:34:23.316006 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=720x400, Sending to async-handler
09:34:23.316121 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=720x400
09:34:23.316135 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=720x400
09:34:23.317533 GUI: UIFrameBufferPrivate::performResize: Size=720x400, Directly using source bitmap content
09:34:26.486421 OHCI: Software reset
09:34:26.502294 ACPI: Entering S5 power state (power down)
09:34:26.502327 Changing the VM state from 'RUNNING' to 'POWERING_OFF'