incredibly slow network access from Windows 7 host to guest NAT network services

[jandd2kminus23]

I observe really slow network connectivity from a Windows 7 Enterprise host to several Linux guests with NAT networking.

I forward a local port (i.e. 2222) to a guest port (ie. 22) and get very slow (multiple seconds) initial ssh connections and after an established connection it is still incredibly slow. Typed characters are echoed back to the terminal only after several seconds.

If I directly use the guest system via its console or graphical desktop it is fast and responsive. Neither the guest nor the host are under load.

I already discussed this issue in IRC yesterday. Here is a transcript of the IRC session:

11:55 < jandd> I have a strange latency problem with ssh to a NAT forwarded ssh guest (VirtualBox 4.3.18 on Windows 7 host with CentOS 6.5 guest). Not only connecting is slow (looked at all the DNS advice already) but typing too (multiple seconds until a typed character appears in the terminal window). Typing in the guest console is fast and neither the host nor the guest are under load. Logs in the guest contain no information. I also tried a Debian guest and observed the same behaviour. I first observed this with the Boot2Docker VM a while ago but obviously this is a more general issue. Do you have any ideas where to look?
11:59 <@klaus-vb> DNS problems can't explain such extreme latency, so trying to poke around those areas won't help
12:00 <@klaus-vb> it's probably a regression due to the recent NAT code changes, backfiring on windows host
12:01 <@klaus-vb> jandd: just to make sure we'll look in the right place: this is with NAT, not with NAT Network, right?
12:02 <@klaus-vb> jandd: do you have an older data point which worked? was 4.3.16 also affected?
12:10 < jandd> yes this is a NAT issue
12:10 < jandd> I have no older data points
12:11 < jandd> the tests with Boot2Docker where in Juli with the VirtualBox version that was the current release at that time
12:11 <@klaus-vb> it's quite likely that this is a recent regression...
12:12 < jandd> 4.3.12 or 4.3.14 where current in July
12:12 < jandd> I can do another test with some older version, any suggestions which one to try?
12:13 <@klaus-vb> 4.3.16 and maybe 4.3.14...
12:13 < jandd> ok, I'll test these and come back afterwards
12:14 <@klaus-vb> thanks!
12:18 <@klaus-vb> I'll be afk for a bit, but back later. will read whatever you write...
12:55 < jandd> 4.3.16 is slow too ... continuing with 4.3.14
12:58 < jandd> 4.3.14 ... same :-(
13:09 <@klaus-vb> back... hmm. doesn't sound good. 4.3.12 would be quite a bit older.
13:11 < jandd> same with 4.2.26
13:12 <@klaus-vb> that's almost proof that something very bad is happening on your system, related to hardening of the VBox for Windows code
13:13 <@klaus-vb> 4.2.26 is quite recent actually, from July.
13:14 <@klaus-vb> would be great if you could try 4.3.12 or 4.2.24 - those predate the hardening effort.
13:15 < jandd> ok, I'll try 4.3.12
13:16 < jandd> the Windows version is Windows 7 Enterprise Version 5.1 (Build 7601: Service Pack 1) with all the latest patches applied if this matters
13:20 <@fmehnert> A VBoxStartup.log file from 4.3.18 could also help.
13:21 <@klaus-vb> would be of course by now overwritten by the older packages...
13:21 < jandd> ok, I'll do the test with 4.3.12 and will install 4.3.18 afterwards to provide the logs
13:33 < jandd> 4.3.12 is slow too
13:33 < jandd> I'll do another test with 4.3.18 and provide the logs afterwards. I just saved the VBox.log from the 4.3.12 test
13:35 < jandd> ... another Windows reboot :-/
13:44 < jandd> https://www.dropbox.com/sh/uru57dbky4sc18m/AACst6LMfbXQBWAqHNzGSdv1a/VirtualBox-Slowness?dl=0 ... there are the logs
13:52 <@fmehnert> Let me check the log. Well, if 4.3.12 is affected as well, it cannot be the Windows hardening which we introduce with 4.3.14
13:58 <@fmehnert> I cannot spot any problem in the VBoxStartup.log. wintab32.dll couldn't be opened but that's probably not a problem.
13:58 <@fmehnert> I guess only a wireshark trace could help here.
13:59 < jandd> ok, I'll try that
14:32 < jandd> fmehnert: I used rawcap to get a dump because Wireshark does not support captures on Loopback on Windows
14:32 < jandd> the dump is in the same dropbox folder as the logs
14:34 < jandd> I used 2222 as forwarded port and "tcp.port == 22" in the Wireshark filter input field finds my ssh session
14:34 <@fmehnert> jandd: Hmm, in that folder I can only see the three older log files...
14:40 < jandd> fmehnert: sorry ... put it in the virtualbox logs folder instead of Dropbox ... should be there now
14:40 < jandd> dumpfile.pcap
14:42 <@fmehnert> Have it, thanks. Analyzing will take some time. I don't have time to look myself but I have created an internal issue for that problem and added your files there.
14:46 < jandd> ok, thanks
17:39 <@klaus-vb> jandd: I think this needs to become an official bug ticket... it's not a quick issue which can be resolved over IRC. http://www.215389.xyz/wiki/Bugtracker

I attach the logfiles and package capture from yesterday to this ticket.

[jandd2kminus23]

gzipped VBoxStartup.log from 4.3.18 session

[jandd2kminus23]

packet capture from Loopback interface containing an ssh session to a Debian GNU/Linux guest on 4.3.18

[Valery Ushakov]

I assume that delays in the captured port-forwarded connection are not caused by human input.

What attracts attention in this packet trace is that it contains quite a bit of packets like:

2222→55984 [ACK] Seq=3464 Ack=2888 Win=64640 Len=0 SLE=2840 SRE=2888

that look, if I interpret them correctly, like RFC2883 DSACK: i.e. receiver says: "I've got data up to 2888 and btw, why have you sent me a segment 2840..2888 for the second time?" Except that I don't see those duplicate segments in the trace (there's only one retransmission - frame 341). I don't think this is normal.

BTW, relative order of packets with the same timestamp cannot be trusted it seems, as e.g. the three-way handshake for this ssh connection has SYN in frame 94 - after the SYN/ACK in frame 93. So it may be that D-SACK packets actually precede the duplicate ACKs with the same timestamp.

There are several frames that has time delta of about 3 seconds to the previous frame, e.g. 130, 157, etc, that are all sent by the ssh client. This looks suspiciously like a retransmit timer, though again, I don't see any indication of duplicate packets or packet loss in the trace.

I cannot reproduce the problem locally. I also don't see SACK in a port-forwarded SSH session that I capture on my machine.

All this makes me suspect that some host problem may be at play here.

[jandd2kminus23]

Today I did another try and observed that there is a huge speed difference when using ssh from cygwin instead of ssh from mingw/git. I attach two additional package captures, one from mingw-ssh and one from cygwin-ssh doing the same steps:

• connect to localhost port 2222
• login
• ps ax
• exit

in cygwin the sequence worked almost instantly while in mingw-ssh it was as slow as observed last week.

[jandd2kminus23]

I just tried other (non VirtualBox) ssh servers with the same mingw ssh binary and they are as slow as my attempts to connect to the NATed VirtualBox guest. This seems to indicate that this is not a VirtualBox issue at all.

[jandd2kminus23]

I just filed ​https://sourceforge.net/p/mingw/bugs/2240/

[Valery Ushakov]

Thank you for quick follow-up. Closing as not a bug.