paleozogt / MSVCDocker

MSVC via Wine in Docker
121 stars 20 forks source link

makefile/vagrantfile doesn't check for dependencies #2

Closed fzwoch closed 5 years ago

fzwoch commented 5 years ago

At least that's what I think I can read out of the log, but probably you understand it better. I guess the Windows Vagrant is build with 5.x Guest Additions and won't work with Virtualbox 6 ultimately causing the networking part to be non-operational and failing the build.

$ make msvc15
./vagranttools/setupbasebox.sh

--2019-03-29 11:47:09--  https://az792536.vo.msecnd.net/vms/VMBuild_20180425/Vagrant/MSEdge/MSEdge.Win10.Vagrant.zip
Resolving az792536.vo.msecnd.net (az792536.vo.msecnd.net)... 152.199.19.161, 2606:2800:133:206e:1315:22a5:2006:24fd
Connecting to az792536.vo.msecnd.net (az792536.vo.msecnd.net)|152.199.19.161|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 4575246379 (4.3G) [application/octet-stream]
Saving to: ‘build/MSEdge.Win10.Vagrant.zip’

build/MSEdge.Win10.Vagrant.zip            100%[=====================================================================================>]   4.26G  5.92MB/s    in 27m 24s 

2019-03-29 12:14:34 (2.65 MB/s) - ‘build/MSEdge.Win10.Vagrant.zip’ saved [4575246379/4575246379]

Archive:  build/MSEdge.Win10.Vagrant.zip
 extracting: build/MSEdge - Win10.box  
==> box: Box file was not detected as metadata. Adding it directly...
==> box: Adding box 'Microsoft/EdgeOnWindows10' (v0) for provider: 
    box: Unpacking necessary files from: file:///home/fzwoch/code/MSVCDocker/build/MSEdge%20-%20Win10.box
==> box: Successfully added box 'Microsoft/EdgeOnWindows10' (v0) for 'virtualbox'!
Microsoft/EdgeOnWindows10 (virtualbox, 0)
FIRSTBOOT=1 vagrant up win-msvc15
Bringing machine 'win-msvc15' up with 'virtualbox' provider...
==> win-msvc15: Preparing master VM for linked clones...
    win-msvc15: This is a one time operation. Once the master VM is prepared,
    win-msvc15: it will be used as a base for linked clones, making the creation
    win-msvc15: of new VMs take milliseconds on a modern system.
==> win-msvc15: Importing base box 'Microsoft/EdgeOnWindows10'...
==> win-msvc15: Cloning VM...
==> win-msvc15: Matching MAC address for NAT networking...
==> win-msvc15: Setting the name of the VM: win-msvc15
Vagrant is currently configured to create VirtualBox synced folders with
the `SharedFoldersEnableSymlinksCreate` option enabled. If the Vagrant
guest is not trusted, you may want to disable this option. For more
information on this option, please refer to the VirtualBox manual:

  https://www.virtualbox.org/manual/ch04.html#sharedfolders

This option can be disabled globally with an environment variable:

  VAGRANT_DISABLE_VBOXSYMLINKCREATE=1

or on a per folder basis within the Vagrantfile:

  config.vm.synced_folder '/host/path', '/guest/path', SharedFoldersEnableSymlinksCreate: false
==> win-msvc15: Clearing any previously set network interfaces...
==> win-msvc15: Preparing network interfaces based on configuration...
    win-msvc15: Adapter 1: nat
==> win-msvc15: Forwarding ports...
    win-msvc15: 22 (guest) => 2222 (host) (adapter 1)
==> win-msvc15: Running 'pre-boot' VM customizations...
==> win-msvc15: Booting VM...
==> win-msvc15: Waiting for machine to boot. This may take a few minutes...
    win-msvc15: SSH address: 127.0.0.1:2222
    win-msvc15: SSH username: IEUser
    win-msvc15: SSH auth method: password
==> win-msvc15: Machine booted and ready!
==> win-msvc15: Checking for guest additions in VM...
    win-msvc15: The guest additions on this VM do not match the installed version of
    win-msvc15: VirtualBox! In most cases this is fine, but in rare cases it can
    win-msvc15: prevent things such as shared folders from working properly. If you see
    win-msvc15: shared folder errors, please make sure the guest additions within the
    win-msvc15: virtual machine match the version of VirtualBox you have installed on
    win-msvc15: your host and reload your VM.
    win-msvc15: 
    win-msvc15: Guest Additions Version: 5.2.8
    win-msvc15: VirtualBox Version: 6.0
==> win-msvc15: Mounting shared folders...
    win-msvc15: /vagrant => /home/fzwoch/code/MSVCDocker/build
==> win-msvc15: Running provisioner: ssh...
powershell "Set-NetConnectionProfile -InterfaceAlias Ethernet -NetworkCategory Private"
==> win-msvc15: Running provisioner: ssh...
powershell "NetSh Advfirewall set allprofiles state off" 
==> win-msvc15: Running provisioner: ssh...
cmd /c "reg add HKEY_LOCAL_MACHINE\Software\Microsoft\Windows\CurrentVersion\Policies\System /v EnableLUA /d 0 /t REG_DWORD /f /reg:64"
==> win-msvc15: Running provisioner: ssh...
echo 'cmd /k C:\Windows\System32\winrm.cmd quickconfig --force -quiet' > '/cygdrive/c/Users/IEUser/AppData/Roaming/Microsoft/Windows/Start Menu/Programs/Startup/winrm_config.bat'
==> win-msvc15: Running provisioner: ssh...
shutdown -t 0 -s -f
vagrant halt win-msvc15
==> win-msvc15: Attempting graceful shutdown of VM...
    win-msvc15: Guest communication could not be established! This is usually because
    win-msvc15: SSH is not running, the authentication information was changed,
    win-msvc15: or some other networking issue. Vagrant will force halt, if
    win-msvc15: capable.
==> win-msvc15: Forcing shutdown of VM...
vagrant up --provision win-msvc15
Bringing machine 'win-msvc15' up with 'virtualbox' provider...
There are errors in the configuration of this machine. Please fix
the following errors and try again:

vm:
* The 'reload' provisioner could not be found.

make: *** [Makefile:24: buildsnapshot15] Error 1
paleozogt commented 5 years ago

I think the problem may be this error:

vm:
* The 'reload' provisioner could not be found.

which you can resolve by installing the Vagrant Reload Plugin.

fzwoch commented 5 years ago

Oh yeah, you are right. I read about it, but forgot about it too. It was working much further this time but didn't succeed either. But most likely not related to Virtualbox.

At some point I noticed this red marked block:

    win-msvc15: Download of vs_BuildTools.exe (1013.11 KB) completed.
    win-msvc15: Hashes match.
    win-msvc15: Installing visualcpp-build-tools...
    win-msvc15: visualcpp-build-tools has been installed.
    win-msvc15:  The install of visualcpp-build-tools was successful.
    win-msvc15:   Software installed as 'EXE', install location is likely default.
    win-msvc15: Chocolatey installed 4/4 packages. 
    win-msvc15:  See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).
    win-msvc15: waiting for installer to finish
    win-msvc15: Test-Path : Cannot bind argument to parameter 'Path' because it is null.
    win-msvc15: At C:\tmp\vagrant-shell.ps1:80 char:24
    win-msvc15: +     while (!(Test-Path $vcvarsbat)) {
    win-msvc15: +                        ~~~~~~~~~~
    win-msvc15:     + CategoryInfo          : InvalidData: (:) [Test-Path], ParameterBindingValidationException
    win-msvc15:     + FullyQualifiedErrorId : ParameterArgumentValidationErrorNullNotAllowed,Microsoft.PowerShell.Commands.TestPathCom 
    win-msvc15:    mand
    win-msvc15: Chocolatey v0.10.13

And while it just kept going it failed here:

    win-msvc15: Mode                LastWriteTime         Length Name                                                                  
    win-msvc15: ----                -------------         ------ ----                                                                  
    win-msvc15: d-----        3/29/2019  11:50 AM                SNAPSHOT-02                                                           
    win-msvc15: exporting \\vboxsvr\vagrant\msvc15\snapshots\SNAPSHOT-02\vcvars32.txt
    win-msvc15: **********************************************************************
    win-msvc15: ** Visual Studio 2017 Developer Command Prompt v15.0
    win-msvc15: ** Copyright (c) 2017 Microsoft Corporation
    win-msvc15: **********************************************************************
    win-msvc15: [vcvarsall.bat] Environment initialized for: 'x86'
    win-msvc15: exporting \\vboxsvr\vagrant\msvc15\snapshots\SNAPSHOT-02\vcvars64.txt
    win-msvc15: **********************************************************************
    win-msvc15: ** Visual Studio 2017 Developer Command Prompt v15.0
    win-msvc15: ** Copyright (c) 2017 Microsoft Corporation
    win-msvc15: **********************************************************************
    win-msvc15: [vcvarsall.bat] Environment initialized for: 'x64'
    win-msvc15: Refreshing environment variables from the registry for powershell.exe. Please wait...
    win-msvc15: Finished
==> win-msvc15: Running provisioner: reload...
==> win-msvc15: Attempting graceful shutdown of VM...
==> win-msvc15: Clearing any previously set forwarded ports...
==> win-msvc15: Clearing any previously set network interfaces...
==> win-msvc15: Preparing network interfaces based on configuration...
    win-msvc15: Adapter 1: nat
==> win-msvc15: Forwarding ports...
    win-msvc15: 5985 (guest) => 55985 (host) (adapter 1)
    win-msvc15: 5986 (guest) => 55986 (host) (adapter 1)
    win-msvc15: 22 (guest) => 2222 (host) (adapter 1)
==> win-msvc15: Running 'pre-boot' VM customizations...
==> win-msvc15: Booting VM...
==> win-msvc15: Waiting for machine to boot. This may take a few minutes...
    win-msvc15: WinRM address: 127.0.0.1:55985
    win-msvc15: WinRM username: IEUser
    win-msvc15: WinRM execution_time_limit: PT2H
    win-msvc15: WinRM transport: negotiate
An error occurred executing a remote WinRM command.

Shell: Cmd
Command: hostname
Message: HTTPClient::KeepAliveDisconnected: 
make: *** [Makefile:24: buildsnapshot15] Error 1
paleozogt commented 5 years ago

This is good info. I'll try to see if I can reproduce it. What's your host OS and version? And your exact VirtualBox version?

fzwoch commented 5 years ago

This was done with Debian Sid amd64. Virtualbox should be (6.0.4-dfsg-7). I would have to look at the machine when I have access to it again to verify, but I had it updated to all available updates..

Vagrant I have installed via the official .deb from vagrantup.com. The plugin would not install if I tried to use the Debian Vagrant package. (some dependency version conflicts)

Everything else should be stock Debian Sid provided software versions.

paleozogt commented 5 years ago

Just for reference, I've got these versions:

➜  ~ VBoxManage --version
6.0.4r128413
➜  ~ vagrant --version
Vagrant 2.2.4
➜  ~ vagrant plugin list
vagrant-reload (0.0.1, global)
paleozogt commented 5 years ago

I've fixed that first problem, tho sadly it doesn't seem related to the real issue, which is that vagrant can't connect to the VM after it installs MSVC and reboots.

I've pushed a branch, issue2, that has much more verbose debug logging for vagrant. If you can attach that log to your reply, that would be great.

Before you run make msvc15 again, make sure that you don't have any lingering VMs from the previous runs:

vagrant destroy
vagrant global-status --prune
VBoxManage list vms
fzwoch commented 5 years ago
$ VBoxManage --version
6.0.4_Debianr128164
$ vagrant --version
Vagrant 2.2.4
$ vagrant plugin list
vagrant-reload (0.0.1, global)
$ docker --version 
Docker version 18.09.1, build 4c52b90

I removed everything as advised. I manually deleted the Edge VirtualBox image too.

 INFO warden: Calling OUT action: #<Proc:0x00007f16e0b91920@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Provision:0x0000000002ff6e58>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000002ff6e80>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000002ff6f48>
 INFO warden: Calling OUT action: #<VagrantPlugins::ProviderVirtualBox::Action::ClearForwardedPorts:0x0000000002ff6fc0>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000002ff6fe8>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000002ff70d8>
 INFO warden: Calling OUT action: #<VagrantPlugins::ProviderVirtualBox::Action::SetName:0x0000000003095be8>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003095c10>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003095d00>
 INFO warden: Calling OUT action: #<VagrantPlugins::ProviderVirtualBox::Action::CleanMachineFolder:0x0000000003095d28>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003095d50>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003095e18>
 INFO warden: Calling OUT action: #<VagrantPlugins::ProviderVirtualBox::Action::CheckAccessible:0x0000000003095e40>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003095e68>
 INFO warden: Calling OUT action: #<Proc:0x000000000344ec08@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x0000000002e6c8a8>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000002e6c8d0>
 INFO warden: Calling OUT action: #<Proc:0x0000000002df61d0@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x000000000313f558>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x000000000313f580>
 INFO warden: Calling OUT action: #<Proc:0x00000000030b02b8@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x0000000003511c08>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003511c30>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003511ca8>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BoxCheckOutdated:0x0000000003591e80>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003591ea8>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003591f48>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::ConfigValidate:0x0000000003591f70>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003591f98>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003592010>
 INFO warden: Calling OUT action: #<VagrantPlugins::ProviderVirtualBox::Action::CheckVirtualbox:0x0000000003498c40>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003498c68>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003498ce0>
 INFO warden: Calling OUT action: #<Proc:0x0000000002bec6c8@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Proc:0x0000000002a91378@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x0000000003498d30>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003498d58>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003498e20>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::ConfigValidate:0x0000000003498e48>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003498e70>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003498ee8>
 INFO warden: Calling OUT action: #<Proc:0x0000000002f2f420@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Proc:0x0000000002e84020@/opt/vagrant/embedded/gems/2.2.4/gems/vagrant-2.2.4/lib/vagrant/action/warden.rb:120 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x0000000003498f38>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x0000000003498f60>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::AfterTriggerAction:0x0000000003499000>
 INFO warden: Calling OUT action: #<VagrantPlugins::ProviderVirtualBox::Action::CheckVirtualbox:0x00000000033ad920>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::BeforeTriggerAction:0x00000000033ad948>
 INFO interface: Machine: action ["up", "end", {:target=>:"win-msvc15"}]
 INFO environment: Released process lock: machine-action-69a75303f28a2598d45f4faeaca0f639
DEBUG environment: Attempting to acquire process-lock: dotlock
 INFO environment: Acquired process lock: dotlock
 INFO environment: Released process lock: dotlock
 INFO environment: Running hook: environment_unload
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: environment_unload #<Vagrant::Action::Builder:0x00007f16e3f4ab18>
vagrant halt win-msvc15
==> win-msvc15: Attempting graceful shutdown of VM...
docker build -f Dockerfile -t msvc:15 --build-arg WINE_VER=4.0 --build-arg MSVC=15 .
ERRO[0000] failed to dial gRPC: cannot connect to the Docker daemon. Is 'docker daemon' running on this host?: dial unix /var/run/docker.sock: connect: permission denied 
Got permission denied while trying to connect to the Docker daemon socket at unix:///var/run/docker.sock: Post http://%2Fvar%2Frun%2Fdocker.sock/v1.39/build?buildargs=%7B%22MSVC%22%3A%2215%22%2C%22WINE_VER%22%3A%224.0%22%7D&cachefrom=%5B%5D&cgroupparent=&cpuperiod=0&cpuquota=0&cpusetcpus=&cpusetmems=&cpushares=0&dockerfile=Dockerfile&labels=%7B%7D&memory=0&memswap=0&networkmode=default&rm=1&session=kxg5styucb6fih6kzqen1emgx&shmsize=0&t=msvc%3A15&target=&ulimits=null&version=1: dial unix /var/run/docker.sock: connect: permission denied
make: *** [Makefile:24: buildimage15] Error 1

I will try re-running with sudo..

fzwoch commented 5 years ago

Here is a (shortened) log file when running from a sudo -s shell:

log.txt

I think this one quit much earlier than the last one. Maybe hinting at the original issue?

After the error I peeked at the still running VirtualBox image:

screenshot

paleozogt commented 5 years ago

You've exposed some assumptions in the Makefile that make it less robust to errors than I'd like. :)

For one, the Makefile assumes that Docker has been setup to run without sudo. I hadn't even put that in the readme.

Another problem in the makefile is that its assuming that it's always running "from scratch" without any pre-existing VM images. So if something goes wrong and it aborts, re-running it will then fail.

I'm going to make the script more robust to these sorts of things. In the meantime, setup Docker without sudo, clear out the VMs again, and try building again.

Third time's the charm?

paleozogt commented 5 years ago

I've pushed some error-checking changes to a new branch, issue2_2. It has some fail-fast checks so that it can error out before spending time building the VM, such as

I also updated the instructions and added a clean target, so now we can run make clean when something goes wrong.

Finally, I added a way to insert arguments to Vagrant, so debug logging can easily be turned on by appending VAGRANTARGS=--debug to make (e.g., make msvc15 VAGRANTARGS=--debug).

fzwoch commented 5 years ago

Hey, that worked now!

A few things I noticed. After make clean and re-running I was still prompted about something still existed:

Archive:  build/MSEdge.Win10.Vagrant.zip
replace build/MSEdge - Win10.box? [y]es, [n]o, [A]ll, [N]one, [r]ename:

Near the end I saw this one:

Step 51/59 : RUN find $WINEPREFIX -name Include -execdir mv Include include \; ||     find $WINEPREFIX -name Lib -execdir mv Lib lib \; ||     find $WINEPREFIX -name \*.Lib -execdir rename 'y/A-Z/a-z/' {} \;
 ---> Running in 8df1def64be6
find: '/opt/win/drive_c/Program Files (x86)/Windows Kits/10/Extension SDKs/WindowsMobile/10.0.17763.0/Include': No such file or directory
find: '/opt/win/drive_c/Program Files (x86)/Windows Kits/10/Include': No such file or directory
find: '/opt/win/drive_c/Program Files (x86)/Windows Kits/10/Lib': No such file or directory
Removing intermediate container 8df1def64be6
 ---> b4e8d058a63b
Step 52/59 : ADD dockertools/msc_ver.cpp msc_ver.cpp

But it succeeded just fine:

------------------------------------------------------
Running /usr/bin/wineserver -w. This will hang until all wine processes in prefix=/opt/win terminate
------------------------------------------------------
Removing intermediate container 5b0bd43e6985
 ---> b18d0b760063
Step 59/59 : RUN wineboot -r
 ---> Running in fff06338d3bf
Removing intermediate container fff06338d3bf
 ---> 6df669c833f2
Successfully built 6df669c833f2
Successfully tagged msvc:15

Next I need to play around with it to see how well it works.

Many thanks for helping me get through this and creating this thing in the first place - I belong to the group of people mentioned in the Readme:

Lots of folks have tried to do this over the years [1], but the setup is involved and fiddly.

paleozogt commented 5 years ago

No problem-- thanks for testing it out and giving feedback.

The rest of those messages are expected. Glad it worked for you!

Feel free to file more tickets as you run into problems or new use-cases. Since I've only got my own use-cases to work from, I'm sure there are some I haven't thought of.