NATnetwork port forwarding not completely operational after starting VMs -> fixed in 5.2

[Reiner Brodbeck]

NATnetwork Settings see attached file VirtualBox_extract.xml

Scenario: A group of four VMs in saved state. So VBoxNetNAT.exe is not running for that related NATnetwork. Now I select the group and press the start button to start all four VMs. When the VMs are running, randomly some of the connections defined by port forwarding are working, some not. Now editing the NATnetwork (File->Preferences->Network, select the proper network, press Edit button), pressing OK in Edit window, then in preferences window seems to restart the NATnetwork. After that all is working fine.

Attached files: VBox_nnn.log according to the last part of the VM's IP address NatAMHS.log NATnetwork definition as an extract of VirtualBox.xml

[Reiner Brodbeck]

I forgot to mention in the error description: This may be related to ticket #16695, although the behaviour observed is somehow different.

[Valery Ushakov]

Does this only happen when you start the VMs?

When some of those port-forwarding rules don't work, do you have the corresponding listening socket on the host (netstat -an -p tcp)?

If there are listening sockets, can you capture the traffic on the target VM (filtering with relevant "tcp port ...") to see whether the forwarding connection is attempted or not.

[Reiner Brodbeck]

Replying to vushakov:

Does this only happen when you start the VMs?

Yes, this is only after starting VMs. Once port forwardings are working after "editing" NATnetwork settings, it is okay as long as VBoxNAT.exe keeps running.

When some of those port-forwarding rules don't work, do you have the corresponding listening socket on the host (netstat -an -p tcp)?

Listening sockets on the host are only present for port forwardings that work.

If there are listening sockets, can you capture the traffic on the target VM (filtering with relevant "tcp port ...") to see whether the forwarding connection is attempted or not.

While not working Wireshark does not capture the packets on the target VM.

[Valery Ushakov]

Please, can you try with a recent Windows test build with extra logging enabled.

To enable the extra logs, you need to set these two environment variables:

VBOXNET_NatAMHS_RELEASE_LOG="+nat_service.l2 -nat_service.restrict"
VBOXNET_NatAMHS_RELEASE_LOG_FLAGS="thread timeprog"

(The NatAMHS portion of the variable names is the name of your natnet. In case you want to test with a different natnet - use underscores for any characters in the natnet name that are not suitable for an identifier; e.g. for a network test-0 use VBOXNET_test_0_RELEASE_LOG).

It's probably easiest to set them globally via Window GUI. E.g. Control Panel -> System -> Advanced system settings -> Advanced -> Environment Variables.

The logs are in the release log file. On Windows in your case it's %USERPROFILE%/.VirtualBox/NatAMHS.log

If the environment vars are set correctly you should see

LogRel2 enabled

near the beginning of that log to provide you immediate feedback.

With extra logging set up, please restore your VMs and try connecting through the port-forwarding. Then do the magic Edit that fixes it for you and try port-forwarding again. Attach the log from that.

Thanks in advance.

[Reiner Brodbeck]

I downloaded and installed VirtualBox-5.1.27-117823-Win.exe and Oracle_VM_VirtualBox_Extension_Pack-5.1.27-117558.vbox-extpack.

Now VMs don't start at all. Error message is:

Failed to open a session for the virtual machine AMHS-Tester.

The device helper structure version has changed.

If you have upgraded VirtualBox recently, please make sure you have terminated all VMs and upgraded any extension packs. If this error persists, try re-installing VirtualBox. (VERR_PDM_DEVHLPR3_VERSION_MISMATCH).

Result Code: E_FAIL (0x80004005) Component: ConsoleWrap Interface: IConsole {872da645-4a9b-1727-bee2-5585105b9eed}

[Valery Ushakov]

Ah, you probably need newer extension pack as well. I've uploaded the matching one.

[Reiner Brodbeck]

Debugging enabled

[Reiner Brodbeck]

I have added the new NatAMHS.log

After VMs have been up, last entry was at 00:00:25.878115. After that port forwardings AFTN and SSH did work, the other port forwardings did not.

After openening edit mask for NatAMHS (window title "NAT network details), last logging entry was at 00:02:11.092345.

After closing "NAT newtork details" and preferences window with OK, last entry was at 00:03:07.401368. Now all port forwardings did work.

Finally I brought back VMs to saved state, last entry at 00:04:12.843025

[Valery Ushakov]

This is puzzling. Please, can you retry it with r117849?

[Reiner Brodbeck]

Next try, build 117849

[Reiner Brodbeck]

I added NatAMHS.log with results of r117849. Time stamps are

00:00:28.758067 after VMs are up. This time all port forwardings working with exception of MTA-1. (I already mentioned, this is random)

00:01:04.336770 after opening window "NAT network details"

00:01:38.589526 after closing windows with OK

00:02:18.866730 after bringing VMs to saved state

[Valery Ushakov]

Please, can you re-run the test with

VBOXNET_NatAMHS_RELEASE_LOG="+nat_service.l2.l3 -nat_service.restrict"

(i.e. l3 added to the log spec).

Thanks for your patience.

[Reiner Brodbeck]

I added the new NatAMHS.log. The usual time stamps are:

00:01:16.401294

00:01:59.747429

00:02:31.920704

00:03:22.265692

This time only SSH port forwarding was working after start of VMs.

[Reiner Brodbeck]

I had a closer look on the NatAMHS.log. Some more information concerning the IP addresses:

192.168.10.104:8500 is an outgoing connection from the VM with NatNetwork address 192.168.111.120

192.168.10.66 is the host from where I try to connect via port forwarding. For this test I use a script that tries to connect every 5 seconds to all of these ports, using the nc utility.

[Valery Ushakov]

Very strange. From rtfs I think all possible error legs between "Loading IPv4 port-forwarding rule..." and "fwtcp_add" should have logging, yet when the rules are first loaded only some of them actually reach that "fwtcp_add". Let me add some logs to the normal path as well.

[Valery Ushakov]

Please, can you download and try r117883. TIA.

PS: You don't have to make any connections to the forwarded ports.

[Reiner Brodbeck]

New NatAMHS.log added. Time stamps are:

00:01:11.061447

00:02:21.151882

00:02:44.128612

00:03:23.798688

Operational after VM startup were AFTN, MTA-1, SSH, not operational MTA-2 and MTA-3.

[Valery Ushakov]

Thanks! That was very helpful. The fix unfortunately turned out to be non-trivial, so it will not make it into the forthcoming 5.1 dot-dot release, only in the next 5.2 beta.