Win 11 Slow Command Start While on VPN

Suspected Bug
1

What is the problem you are having with rclone?

While on VPN any rclone command you run takes upwards of 30 seconds to start. Once it starts it runs normally. I searched the forum and found this post which seems like the same issue although he doesn't mentions if he is using a VPN: Slow startup on Windows

The only reason I think this could be considered a bug is that I was not using rclone for any cloud related operations but for local filesystem to local filesystem copies/moves. Even just running rclone version takes the same long time (42s) to start.

Once I disconnect from the VPN commands start within 2s.

Also some VPNs cause the issue and some don't. I use ShrewVPN to connect to my office. This causes the command start delay, but If I use Sophos VPN to connect to a jobsite that doesn't cause any delays.

Run the command 'rclone version' and share the full output of the command.

rclone v1.65.0

  • os/version: Microsoft Windows 11 Pro 22H2 (64 bit)
  • os/kernel: 10.0.22621.2715 (x86_64)
  • os/type: windows
  • os/arch: amd64
  • go/version: go1.21.4
  • go/linking: static
  • go/tags: cmount

Which cloud storage system are you using? (eg Google Drive)

Local Filesystem

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone version

The rclone config contents with secrets removed.

# I used an empty config file since I'm doing local filesystem operations

A log from the command with the -vv flag

rclone version -vv
2023/12/07 05:39:50 DEBUG : rclone: Version "v1.65.0" starting with parameters ["rclone" "version" "-vv"]
rclone v1.65.0
- os/version: Microsoft Windows 11 Pro 22H2 (64 bit)
- os/kernel: 10.0.22621.2715 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.21.4
- go/linking: static
- go/tags: cmount
2023/12/07 05:39:50 DEBUG : rclone: Version "v1.65.0" finishing with parameters ["rclone" "version" "-vv"]
2

run a command that copies a single file. make sure to add -vv to the command.
post the full output.

2013-07-01 I am pleased to announce the Shrew Soft VPN Client 2.2.2 Release
last update was over 10 years ago?

fwiw, on windows, i use rclone/veeam/etc... over openvpn, mullvad, tailscale, viscosity, wireguard.
never had such a problem.

3

run a command that copies a single file. make sure to add -vv to the command.
post the full output.

Here you go:

C:\Users\tonyl>rclone copy "C:\Users\tonyl\Test 1" "C:\Users\tonyl\Test 2" -vv
2023/12/07 09:20:07 DEBUG : rclone: Version "v1.65.0" starting with parameters ["rclone" "copy" "C:\\Users\\tonyl\\Test 1" "C:\\Users\\tonyl\\Test 2" "-vv"]
2023/12/07 09:20:07 DEBUG : Creating backend with remote "C:\\Users\\tonyl\\Test 1"
2023/12/07 09:20:07 DEBUG : Using config file from "C:\\Users\\tonyl\\.config\\rclone\\rclone.conf"
2023/12/07 09:20:07 DEBUG : fs cache: renaming cache item "C:\\Users\\tonyl\\Test 1" to be canonical "//?/C:/Users/tonyl/Test 1"
2023/12/07 09:20:07 DEBUG : Creating backend with remote "C:\\Users\\tonyl\\Test 2"
2023/12/07 09:20:07 DEBUG : fs cache: renaming cache item "C:\\Users\\tonyl\\Test 2" to be canonical "//?/C:/Users/tonyl/Test 2"
2023/12/07 09:20:07 DEBUG : file 1.txt: Need to transfer - File not found at Destination
2023/12/07 09:20:07 DEBUG : Local file system at //?/C:/Users/tonyl/Test 2: Waiting for checks to finish
2023/12/07 09:20:07 DEBUG : Local file system at //?/C:/Users/tonyl/Test 2: Waiting for transfers to finish
2023/12/07 09:20:07 DEBUG : file 1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2023/12/07 09:20:07 DEBUG : file 1.txt.kezoxas4.partial: renamed to: file 1.txt
2023/12/07 09:20:07 INFO  : file 1.txt: Copied (new)
2023/12/07 09:20:07 INFO  :
Transferred:              0 B / 0 B, -, 0 B/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:        42.6s

2023/12/07 09:20:07 DEBUG : 5 go routines active

2013-07-01 I am pleased to announce the Shrew Soft VPN Client 2.2.2 Release
last update was over 10 years ago?
fwiw, on windows, i use rclone/veeam/etc... over openvpn, mullvad, tailscale, viscosity, wireguard.
never had such a problem.

Yep it's super old but it's what I have to use to connect to my office. I have no control over that.

4

ok, how about this

echo %time% && rclone copy "C:\Users\tonyl\Test 1" "C:\Users\tonyl\Test 2" -vv

what testing have you done to confirm that?

5

Here's the output:

C:\Users\tonyl>echo %time% && rclone copy "C:\Users\tonyl\Test 1" "C:\Users\tonyl\Test 2" -vv
 9:32:13.46
2023/12/07 09:32:56 DEBUG : rclone: Version "v1.65.0" starting with parameters ["rclone" "copy" "C:\\Users\\tonyl\\Test 1" "C:\\Users\\tonyl\\Test 2" "-vv"]
2023/12/07 09:32:56 DEBUG : Creating backend with remote "C:\\Users\\tonyl\\Test 1"
2023/12/07 09:32:56 DEBUG : Using config file from "C:\\Users\\tonyl\\.config\\rclone\\rclone.conf"
2023/12/07 09:32:56 DEBUG : fs cache: renaming cache item "C:\\Users\\tonyl\\Test 1" to be canonical "//?/C:/Users/tonyl/Test 1"
2023/12/07 09:32:56 DEBUG : Creating backend with remote "C:\\Users\\tonyl\\Test 2"
2023/12/07 09:32:56 DEBUG : fs cache: renaming cache item "C:\\Users\\tonyl\\Test 2" to be canonical "//?/C:/Users/tonyl/Test 2"
2023/12/07 09:32:56 DEBUG : file 1.txt: Need to transfer - File not found at Destination
2023/12/07 09:32:56 DEBUG : Local file system at //?/C:/Users/tonyl/Test 2: Waiting for checks to finish
2023/12/07 09:32:56 DEBUG : Local file system at //?/C:/Users/tonyl/Test 2: Waiting for transfers to finish
2023/12/07 09:32:56 DEBUG : file 1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2023/12/07 09:32:56 DEBUG : file 1.txt.lodocek6.partial: renamed to: file 1.txt
2023/12/07 09:32:56 INFO  : file 1.txt: Copied (new)
2023/12/07 09:32:56 INFO  :
Transferred:              0 B / 0 B, -, 0 B/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:        42.6s

2023/12/07 09:32:56 DEBUG : 5 go routines active

I haven't done any testing regarding it being the same issue or not but it just seemed very similar with the 30s delay. The post died out with no solution anyways.

6

ok, that confirms the initial delay.

what about
echo %time% && rclone version -vv

7 
C:\Users\tonyl>echo %time% && rclone version -vv
 9:57:03.23
2023/12/07 09:57:46 DEBUG : rclone: Version "v1.65.0" starting with parameters ["rclone" "version" "-vv"]
rclone v1.65.0
- os/version: Microsoft Windows 11 Pro 22H2 (64 bit)
- os/kernel: 10.0.22621.2715 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.21.4
- go/linking: static
- go/tags: cmount
2023/12/07 09:57:46 DEBUG : rclone: Version "v1.65.0" finishing with parameters ["rclone" "version" "-vv"]
8

so far, not seeing this as a rclone bug/issue.
the delay occurs before rclone starts.

rclone version does not access the network, does not do dns lookups

fwiw, need to do basic troubleshooting on your machine; what is causing that delay before rclone starts.
can use procmon, same as the OP in that other topic.

perhaps contact tech support for shrewvpn?

9

As it is not something one can replicate easily if you want to get to the bottom of this issue you have to capture more debug info yourself.

  1. Download and install Process Monitor - Sysinternals | Microsoft Learn

  2. Run Procmon64.exe

  3. Open cmd window and run rclone version

  4. In procmon click at filter (1), add "Process name contains rclone" (2) and click Add (3)

Screenshot 2023-12-07 at 15.32.24
Screenshot 2023-12-07 at 15.32.241780×1096 179 KB

Scroll results and find out which rclone.exe operation is responsible for the initial delay. There is a lot of details to go through - rclone version I tried generated 16k+ operations. But looking at Time of Day column should easily point you into problematic sequence (given massive delay you experience).

It should hopefully give us some clue what is the culprit.

10

Thanks @kapitainsky I wasn't sure how to debug further than the logs. This is pretty cool. I'm not sure what the proper way to share the results of the test, so I'm adding a screenshot. It pretty clear where the delay is happening. Take a look:

image
image1422×280 52 KB

for some reason it is starting a network connection to what I think it's the domain server at my office (not 100% on this).

Let me know if there is a better way to share the whole capture.

11

Well done!

Now we need some Windows guru to shed some light on what is happening here. I am afraid my Win knowledge is not enough to interpret it.

But at least we have clear info captured.

Interestingly thread you mentioned Slow startup on Windows have similar operation causing delay:

11:36:34.2920494 AM rclone.exe 1956 TCP Disconnect RL-BU01-AWS.rockliffe.local:59191 -> a2a:808:::epmap SUCCESS Length: 0, seqnum: 0, connid: 0
11:37:41.2927932 AM rclone.exe 1956 Thread Exit SUCCESS Thread ID: 2120, User Time: 0.0000000, Kernel Time: 0.0000000

network call to epmap port (it is 135 (RPC) I believe)

12

i should have been more clear, then simply writing can use procmon, same as the OP in that other topic.

for that procmon output, what command did you run,
i would test using the simplest command that can reproduce the issue - rclone version

from the menu, File/Save, leave defaults but pick a path to save the file.
then you can upload the file somewhere, so we can take a look.

13

@asdffdsa This was the capture for:

rclone version

I will upload the whole capture and link it.

14

Here's a link to the full capture:

15

i still think this is not a rclone issue, as can find examples of it happening to chrome, excel, etc
looks to be a misconfiguration of windows laptop connecting to windows domain controller over internet, perhaps for DNS or DHCP.
now, should run the same rclone version test using Sophos VPN and compare the results.

for each TCP Reconnect, the next delay is doubled.

|10:53:11.2833603 AM|rclone.exe|10560|TCP Reconnect|DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap|SUCCESS|Length: 0, seqnum: 0, connid: 0|
|10:53:13.2869157 AM|rclone.exe|10560|TCP Reconnect|DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap|SUCCESS|Length: 0, seqnum: 0, connid: 0|
|10:53:17.2941160 AM|rclone.exe|10560|TCP Reconnect|DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap|SUCCESS|Length: 0, seqnum: 0, connid: 0|
|10:53:25.3022568 AM|rclone.exe|10560|TCP Reconnect|DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap|SUCCESS|Length: 0, seqnum: 0, connid: 0|

then here, everything is fast.

10:53:31.5042370 AM	rclone.exe	10560	TCP Send	DA-TONY.DigitalAutomation.local:52541 -> DAFILE04:epmap	SUCCESS	Length: 160, startime: 7401852, endtime: 7401860, seqnum: 0, connid: 0
10:53:31.5042703 AM	rclone.exe	10560	TCP Receive	DA-TONY.DigitalAutomation.local:52541 -> DAFILE04:epmap	SUCCESS	Length: 108, seqnum: 0, connid: 0
10:53:31.5745602 AM	rclone.exe	10560	TCP Send	DA-TONY.DigitalAutomation.local:52541 -> DAFILE04:epmap	SUCCESS	Length: 168, startime: 7401860, endtime: 7401867, seqnum: 0, connid: 0
10:53:31.5745929 AM	rclone.exe	10560	TCP Receive	DA-TONY.DigitalAutomation.local:52541 -> DAFILE04:epmap	SUCCESS	Length: 172, seqnum: 0, connid: 0

then here, slow again on the reconnect, but the delay is constant two seconds

10:53:32.5890678 AM	rclone.exe	10560	TCP Reconnect	DA-TONY.DigitalAutomation.local:52543 -> 192.168.56.1:49667	SUCCESS	Length: 0, seqnum: 0, connid: 0
10:53:34.5925484 AM	rclone.exe	10560	TCP Reconnect	DA-TONY.DigitalAutomation.local:52543 -> 192.168.56.1:49667	SUCCESS	Length: 0, seqnum: 0, connid: 0
10:53:38.6048488 AM	rclone.exe	10560	TCP Reconnect	DA-TONY.DigitalAutomation.local:52543 -> 192.168.56.1:49667	SUCCESS	Length: 0, seqnum: 0, connid: 0

when the shrewvpn connects, does it set the default route to the office?
as a test, i would exclude rclone.exe from flowing over the shrewvpn and test what happens.

16

Here's a link to the output for rclone version while connected with SophosVPN:

Interestingly I don't see any TCP operations in this capture. I ran it a couple of time to make sure.

I'm not super strong on networking but I think the main difference might be that the ShrewVPN is not a split connection while the SophosVPN is a split connection.

I'll try to figure out how to do this, but don't you think it's strange that rclone version is attempting TCP connections? And weirder still that it doesn't do it on Sophos. I can't test because I work remotely but I wonder if the TCP connections would happen if I was local in the domain.

18

i took another look at the procmon file you posted.

10:53:11.2833603 AM	rclone.exe	10560	TCP Reconnect	DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap	SUCCESS	Length: 0, seqnum: 0, connid: 0
10:53:13.2869157 AM	rclone.exe	10560	TCP Reconnect	DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap	SUCCESS	Length: 0, seqnum: 0, connid: 0
10:53:17.2941160 AM	rclone.exe	10560	TCP Reconnect	DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap	SUCCESS	Length: 0, seqnum: 0, connid: 0
10:53:25.3022568 AM	rclone.exe	10560	TCP Reconnect	DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap	SUCCESS	Length: 0, seqnum: 0, connid: 0
10:53:31.3168261 AM	rclone.exe	10560	TCP Disconnect	DA-TONY.DigitalAutomation.local:52518 -> 192.168.56.1:epmap	SUCCESS	Length: 0, seqnum: 0, connid: 0
10:53:31.4266432 AM	rclone.exe	10560	TCP Connect	DA-TONY.DigitalAutomation.local:52541 -> DAFILE04:epmap	SUCCESS	Length: 0, mss: 1340, sackopt: 1, tsopt: 0, wsopt: 1, rcvwin: 65660, rcvwinscale: 8, sndwinscale: 8, seqnum: 0, connid: 0

notice,
very slow and repeats, when doing an epmap to ipaddress 192.168.56.1.
not slow and no repeats, when doing an epmap to hostname DAFILE04

what is 192.168.56.1?
the internet router on the domain controller side or what?
is there software that should be listening and repsonding to epmap requests?

what is DAFILE04? the domain controller or what?

maybe, as a possible workaround, to prevent that possible epmap lookup.

on DAFILE04, let's say the ipaddress is 192.168.56.111
on the laptop, in the hosts file, c:\Windows\System32\drivers\etc\hosts
i would hardcode an entry like so
192.168.56.111 DAFILE04

19

So 192.168.56.1 was a VirtualBox network adapter. It looks like they had to run a VM for a test on the server and installing VirtualBox ended up killing the dns resolution on the domain server.

After they uninstalled VirtualBox the dns lookup still happens but there's no delay to it.

I did try robocopy as a test to see if copying files with it would trigger a dns lookup while on VPN but it did not. Just wanted to see if it was file operations that were triggering the query.

The dns lookup also doesn't happen with rclone if I am not connected to the domain.

1 Like
20

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.