Vagrant: Vagrant hangs on all commands (Windows 7)

[mliebelt]

I face currently the strange situation that (without any change that I have done), a VirtualBox image I use since years is now slow in startup. This image runs all the time on my host machine (Windows 7), and normally I don't reboot the computer too often, so I cannot say when it stopped working fast.

There are some details below, my impression is, that there is some timeout (30 seconds) active, and the log shows all the time lines like that:

DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 32000
DEBUG subprocess: Exit status: 0
INFO subprocess: Starting process: ["C:/Program Files/Oracle/VirtualBox/VBoxManage.exe", "showvminfo", "9c33633d-d8d0-422d-87b3-0ba5667053ed", "--machinereadable"]
INFO subprocess: Command not in installer, restoring original environment...

When I reinstall Vagrant, the first run is fast, all following are slow again. The output in the log is similar, but the timing is different.

Vagrant version

1.7.4 (had the same problems with 1.8.4 and 1.8.5)

Host operating system

Windows 7

Guest operating system

ubuntu/trusty64

Vagrantfile

VAGRANTFILE_API_VERSION = "2"
Vagrant.configure(VAGRANTFILE_API_VERSION) do |config|
   config.vm.box_check_update = false
   config.vm.boot_timeout = 900
   config.vm.box = "ubuntu/trusty64"
  config.vm.network :forwarded_port, guest: 4009, host: 5009
  config.vm.network :forwarded_port, guest: 4008, host: 5008
  ...
  config.proxy.http     = "http://<our-proxy>:8080"
  config.proxy.https    = "http://<our-proxy>:8080"
  config.proxy.no_proxy = "localhost,127.0.0.1"
  config.vm.synced_folder "../data", "/vagrant_data"
end

Debug output

https://gist.github.com/mliebelt/18ce5e109ef9cd2f4494dbac178efb69

This contains 2 consecutive runs, the first one after a fresh install (first deinstalled, then reinstalled, restarted the computer). The second run was done immediate after the first one.

Expected behavior

The runtime behavior of Vagrant should be all the time similar.

Actual behavior

Currently I face the problem that Vagrant hangs a lot for all commands (even vagrant status needs some minutes). The only workaround I have found is to do a reinstall of Vagrant. The first run afterwards is then fast again, but only the first.

I have further tried different things, here is a summary:

• Same behavior for combination Vagrant 1.7.5 and VB 5.024, Vagrant 1.8.4 and VB 5.0.26, Vagrant 1.8.5 and VB 5.1.4
• It has nothing to do if I have a network connection or not.
• I can disable the VB network connectors as well, no difference.
• The first run of Vagrant after a reinstall is fast, all following are slow.
• There is no difference if I restart the machine in between.
• When running the commands with the flag --debug, I see vagrant hanging all the time when the log shows: INFO subprocess: Command not in installer, restoring original environment...
• I had to add a bigger timeout (see line config.vm.boot_timeout = 900) so that the commands could finish. Before that vagrant aborted.

Steps to reproduce

I cannot say how others can reproduce it. For me the following steps are sufficient all the time:

1. Reinstall vagrant
2. Run vagrant up on an existing (or new) box
3. This runs with normal speed (~ 30 seconds for the startup).
   4- Run vagrant ssh to login.
4. This now runs slow with ~ 5-10 minutes for the login.
5. Stop the VirtualBox image with the VirtualBox UI (vagrant halt needs too much time).
6. Run vagrant up again.
7. Startup time is now ~ 40 minutes

References

Are there any other GitHub issues (open or closed) that should be linked here?
For example:

• #6812: Tried the tip of @tlartaud, but did not help me.
• #6242: Found that, will try to go back to version 1.7.2 to see if the timeout problem then goes away as well.

[mliebelt]

Today, I had the usual Microsoft patch day, and after restarting my computer, the problem was gone. vagrant up is now again at ~30 seconds, vagrant ssh returns immediately. I cannot explain that, if that is for interest, I could add the patches installed today (only the names).

• Oktober 2016 – monatliches Sicherheitsqualitätsrollup für Windows 7 für x64-basierte Systeme (KB3185330)
• Reliability Rollup for Microsoft .NET Framework 4.5.2, 4.6 and 4.6.1 on Windows 7 and Server 2008 R2 for x64 (KB3179930)
• Update für Windows 7 für x64-Systeme (KB2952664)
• Windows-Tool zum Entfernen bösartiger Software x64 - Oktober 2016 (KB890830)
• Update für Windows 7 für x64-basierte Systeme (KB3182203)
• Sicherheitsupdate für Microsoft Word 2010 (KB3118312) 32-Bit-Edition
• October, 2016 Security and Quality Rollup for .NET Framework 3.5.1 on Windows 7 SP1 and Windows Server 2008 R2 SP1 for x64 (KB3188740)
• Sicherheitsupdate für Microsoft Silverlight (KB3193713)
• Update für Windows 7 für x64-basierte Systeme (KB3181988)
• Update für Windows 7 für x64-basierte Systeme (KB3184143)

I will close that ticket now.

[mliebelt]

Problem ist there again, so I gave it another try:

• Installed latest Ruby version.
• Ensured that it is in the path.
• Started the following command with the the output then:
  date +%s%N;ruby --version;date +%s%N

1479637816796089000 ruby 2.3.1p112 (2016-04-26 revision 54768) [i386-mingw32] 1479637847225131600

The difference in Nanosecond is: 30429042

So my interpretation is: starting the Ruby interpreter needs > 30 seconds each time. So if I could measure the performance inside the Ruby interpreter, there could be a chance to find the reason for that behavior.

[mliebelt]

Today was again Microsoft patch day, and the problem was gone (again). So there seem to be some deep things go wrong in Windows 7, which are fixed by Microsoft again and again. I will close that ticket forever ... :-(

[chrisroberts]

Do you see the same issues if you run Vagrant via the windows installer package?

[mliebelt]

I don't understand your question. I have used the Windows Installer package of Vagrant to install Vagrant locally, so it is now in the path:

    $ which vagrant
    /c/apps/vagrant/bin/vagrant

How do I run Vagrant through the Windows Installer Package?

[chrisroberts]

I thought you were running Vagrant through a custom Ruby install but it was simply because I misread this comment: https://github.com/mitchellh/vagrant/issues/7823#issuecomment-261770969

I am very curious about this behavior, and the transient nature of it. You note that when it hangs you generally see this line:

INFO subprocess: Command not in installer, restoring original environment...

If you see the behavior again, would you please make note of what subprocess is being run and update here. It should help to at least start identifying what is the underlying cause of the issue You should see this directly above in the log:

INFO subprocess: Starting process: ...

I'm going to leave this open for now and will close it again if I am unable to reproduce the behavior _and_ you do not experience it again. Thanks!

[chrisroberts]

I have been unable to reproduce this issue. I'm going to close this issue now, however, I'm not closing it because I see it as a non-issue. Merely that I can't get a proper reproduction to debug it. If this behavior surfaces again, and you can provide more information, please reopen this issue, or create a new one. I would like to determine the root cause of the issue, but without being able to reproduce it that's not really possible. Thanks!

[mliebelt]

Sorry that I needed so long. Here are some news, but they won't help you (but me):

• I found the following issue which described a similar behavior as I have seen: https://github.com/Maximus5/ConEmu/issues/692
• I checked then the following:
  
  
  
  • Started directly Git Bash (not ConEmu, then inside Git Bash).
  
  
  • Went there to directory for vagrant, and started vagrant up as usual.
  
  
  • I got the old performance again, fast as before.
  
  
• I then dig a little deeper, and saw that our virus scan software gave me a warning about using ConEmu processes.

I cannot stop the virus scan (a business computer, I have not sufficient rights to do that). but I only face the slow behavior in the following constellation: ConEmu, Git Bash inside, then Vagrant.

I am not sure if anyone could reproduce it. Here are the versions of the software used:

• ConEmu:. installation from Nov 2015, unclear which version (did not find the information).
• Git Bash: git version 2.10.1.windows.1
• Vagrant: 1.8.5

[pscheit]

i got this with the following

 INFO subprocess: Starting process: ["C:\\Windows\\System32\\WindowsPowerShell\\v1.0\\/powershell.EXE", "-NoLogo", "-NoProfile", "-NonInteractive", "-ExecutionPolicy", "Bypass", "-Command", "(new-object System.
Security.Principal.WindowsPrincipal([System.Security.Principal.WindowsIdentity]::GetCurrent())).IsInRole([System.Security.Principal.WindowsBuiltInRole]::Administrator)"]
 INFO subprocess: Command not in installer, restoring original environment...

(for example)

vagrant: 1.9.6
virtualbox: 5.1.26
Windows 7 Professional 64bit

[theotherp]

@pscheit See https://github.com/mitchellh/vagrant/issues/8777#issuecomment-317845567

[sz332]

I had the same problem, but killing the powershell process allowed vagrant to continue...

[c-gregory]

I had the same problem at @pscheit . I tried killing the powershell process as @sz332 suggested and it worked.

[nintendnerd]

Killing the powershell process (had to do it twice) also worked for me

[sz332]

The problem is still available in 1.9.7.

[sz332]

The problem is still not fixed in 1.9.8.

[sz332]

DEBUG provisioner: Provisioner defined:
DEBUG provisioner: Provisioner defined:
DEBUG loader: Configuration loaded successfully, finalizing and returning
DEBUG push: finalizing
DEBUG command: Getting target VMs for command. Arguments:
DEBUG command: -- names: ["default"]
DEBUG command: -- options: {:provider=>nil}
DEBUG command: Finding machine that match name: default
INFO loader: Set "29740260_machine_default" = []
INFO loader: Loading configuration in order: [:home, :root, "29740260_machine_d
efault"]
DEBUG loader: Loading from: home (cache)
DEBUG loader: Loading from: root (cache)
DEBUG loader: Configuration loaded successfully, finalizing and returning
DEBUG push: finalizing
INFO subprocess: Starting process: ["C:\Windows\System32\WindowsPowerShell\
v1.0\/powershell.EXE", "-NoLogo", "-NoProfile", "-NonInteractive", "-ExecutionP
olicy", "Bypass", "-Command", "$PSVersionTable.PSVersion.Major"]
INFO subprocess: Command not in installer, restoring original environment...
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stdout: 2

... waiting

[sz332]

@c-gregory @nintendnerd guys, I think i have a fix for the issue. The problem looks like that the powershell version we had installed was old. Please, try the following. Start a powershell, and enter the following command:

$PSVersionTable.PSVersion

If this is like 2.0 then try to install a newer version

https://docs.microsoft.com/en-us/powershell/scripting/setup/installing-windows-powershell?view=powershell-5.1

I installed WMF 5.1, which required a windows restart, with the latest vagrant (1.9.8)

Entering the same powershell command:

Major Minor Build Revision

---

5 1 14409 1005

Now, when starting vagrant up --debug it worked perfectly.

[raofq]

@sz332 Hi, I installed WMF 5.1, but the version of PS it still 2.0 after windows restart.

C:WindowsSystem32WindowsPowerShellv1.0powershell.exe

Windows 7 SP1Windows Server 2008 R2 SP1 | WMF 3.0 | WMF 4.0 | WMF 5.0 | WMF 5.1

[sz332]

@raofq uh, we have Win 7 64 bit SP1, and it seems to work.

There are some prerequirements as I read:

https://docs.microsoft.com/en-us/powershell/wmf/5.1/install-configure

Also found this one, perhaps it will help:

https://arlanblogs.alvarnet.com/installing-powershell-5-1wmf-5-1/

[raofq]

@sz332 Yes, .NET Framework not install.

[sz332]

@raofq did this solve your problem?

[carbontwelve]

I had this issue, updating powershell to 4 from 3 on my windows 7 box fixed it.

[advocaite]

i have this issue too ever since i restarted my pc first thing virtual box would not even run then finally it starts working but now vagrant just hangs stupid program they need to fix this

[hashibot[bot]]

I'm going to lock this issue because it has been closed for _30 days_ ⏳. This helps our maintainers find and focus on the active issues.

If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.