search

hashicorp / packer

Packer is a tool for creating identical machine images for multiple platforms from a single source configuration.
http://www.packer.io
Other
15.13k stars 3.33k forks source link

Intermittent failures with Hyper-V and PowerShell #10270

Open yaakov-h opened 4 years ago

yaakov-h commented 4 years ago

Overview of the Issue

I use the hyperv-iso builder and powershell provisioner, and lately I have noticed two different intermittent failures:

One is that PowerShell scripts fail to execute as though they are missing. Perhaps they were not transferred correctly to the guest VM:

==> DAT-BUILD-SERVER-grbo01ivhtj: Machine successfully restarted, moving on
==> DAT-BUILD-SERVER-grbo01ivhtj: Provisioning with Powershell...
==> DAT-BUILD-SERVER-grbo01ivhtj: Provisioning with powershell script: ../install-scripts/install-biztalk.ps1
    DAT-BUILD-SERVER-grbo01ivhtj: Windows PowerShell
    DAT-BUILD-SERVER-grbo01ivhtj: Copyright (C) 2016 Microsoft Corporation. All rights reserved.
    DAT-BUILD-SERVER-grbo01ivhtj:
==> DAT-BUILD-SERVER-grbo01ivhtj: The argument 'C:/Windows/Temp/packer-elevated-shell-5fb33157-d2af-d8f2-5aaa-b1758686c2ef.ps1' to the -File parameter does not exist. Provide the path to an existing '.ps1' file as an argument to the -File parameter.
==> DAT-BUILD-SERVER-grbo01ivhtj: Provisioning step had errors: Running the cleanup provisioner, if present...
==> DAT-BUILD-SERVER-grbo01ivhtj: Disconnecting from vmconnect...
==> DAT-BUILD-SERVER-grbo01ivhtj: Cleanup floppy drive...
==> DAT-BUILD-SERVER-grbo01ivhtj: Clean up os dvd drive...
==> DAT-BUILD-SERVER-grbo01ivhtj: Unregistering and deleting virtual machine...
==> DAT-BUILD-SERVER-grbo01ivhtj: Deleting output directory...
==> DAT-BUILD-SERVER-grbo01ivhtj: Deleting build directory...
Build 'DAT-BUILD-SERVER-grbo01ivhtj' errored: Script exited with non-zero exit status: 4294770688.Allowed exit codes are: [0]

The second is that the PACKER_HTTP_ADDR environment variable does not appear to be always set correctly:

==> DAT-BUILD-SERVER-4vydwo3xvla: Provisioning with powershell script: ../install-scripts/install-dotnet-sdk.ps1
    DAT-BUILD-SERVER-4vydwo3xvla: Invoke-WebRequest : Cannot bind parameter 'Uri'. Cannot convert value
    DAT-BUILD-SERVER-4vydwo3xvla: "http:///dotnet/dotnet-sdk-3.1.404-win-x64.exe" to type "System.Uri". Error:
    DAT-BUILD-SERVER-4vydwo3xvla: "Invalid URI: The hostname could not be parsed."
    DAT-BUILD-SERVER-4vydwo3xvla: At C:\Windows\Temp\script-5fb304d2-912a-b106-4d01-71d0a204df52.ps1:7 char:24
    DAT-BUILD-SERVER-4vydwo3xvla: + ... equest -Uri http://${env:PACKER_HTTP_ADDR}/dotnet/dotnet-sdk-3.1.404- ...
    DAT-BUILD-SERVER-4vydwo3xvla: +                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    DAT-BUILD-SERVER-4vydwo3xvla:     + CategoryInfo          : InvalidArgument: (:) [Invoke-WebRequest], Parent
    DAT-BUILD-SERVER-4vydwo3xvla:    ContainsErrorRecordException
    DAT-BUILD-SERVER-4vydwo3xvla:     + FullyQualifiedErrorId : CannotConvertArgumentNoMessage,Microsoft.PowerSh
    DAT-BUILD-SERVER-4vydwo3xvla:    ell.Commands.InvokeWebRequestCommand
    DAT-BUILD-SERVER-4vydwo3xvla:
==> DAT-BUILD-SERVER-4vydwo3xvla: Provisioning step had errors: Running the cleanup provisioner, if present...

Note that the URL we are requesting here starts with http://${env:PACKER_HTTP_ADDR}/dotnet/ but PowerShell is attempting to download from http:///dotnet/, i.e. the environment variable from http_directory has evaluated to an empty string or null.

Reproduction Steps

No clear reproduction because it is intermittent.

Packer version

Packer v.1.6.0

Simplified Packer Buildfile

``` { "variables": { "admin_username": "{{env `admin_username`}}", "admin_password": "{{env `admin_password`}}", "installers_path": "C:\\blah\\Installers\\installers", "vm_suffix": "{{env `vm_suffix`}}", "iso_path": "http://blah/", "iso_name": "en_windows_server_2012_r2_bs_20180504_02.iso" }, "builders": [ { "type": "hyperv-iso", "guest_additions_mode": "disable", "iso_url": "{{user `iso_path`}}/{{user `iso_name`}}", "iso_checksum": "sha1:f2da749f765e17ce288b50f5016b4195b66c741e", "cpus": 8, "memory": "16384", "disk_size": "300000", "generation": 1, "enable_secure_boot": false, "communicator": "winrm", "winrm_username": "{{user `admin_username`}}", "winrm_password": "{{user `admin_password`}}", "winrm_use_ssl": "false", "winrm_timeout": "12h", "floppy_files": [ "Autounattend.xml" ], "shutdown_command": "shutdown /s /t 10 /f /d P:0:0 /c \"Packer shutting down VM\"", "http_directory": "{{user `installers_path`}}", "name": "DAT-BUILD-SERVER-{{user `vm_suffix`}}", "vm_name": "DAT-BUILD-SERVER-{{user `vm_suffix`}}", "switch_name": "packer-hyperv-iso", "output_directory": "..\\..\\bin\\build-server-vm" } ], "provisioners": [ { "type": "powershell", "elevated_user": "{{user `admin_username`}}", "elevated_password": "{{user `admin_password`}}", "valid_exit_codes": [ 0, 2147781575 ], "scripts": [ "../install-scripts/optimization-settings.ps1", "../install-scripts/install-net-framework-35.ps1", "../install-scripts/install-visual-studio-2008.ps1", "../install-scripts/install-visual-studio-2019.ps1" ] }, { "type": "windows-restart" }, { "type": "powershell", "elevated_user": "{{user `admin_username`}}", "elevated_password": "{{user `admin_password`}}", "scripts": [ "../install-scripts/install-biztalk.ps1" ] }, { "type": "windows-restart" }, { // etc. } ] } ```

Operating system and Environment details

Host: Windows Server 2016 Version 1607 (OS Build 14393.3986) 64-bit Dell PowerEdge FC630 with 44 CPU cores and 1024GB of RAM Running as a child process of a Windows Service in Session 0 Logged on as an Active Directory domain user with local Administrator privileges

Guest: Windows Server 2012 R2 64-bit

yaakov-h commented 4 years ago

I managed to capture verbose output from another occurrence where the environment variable was missing. Notice that this time it struck a different script, but the problem remains the same:

``` [#4]: ==> DAT-BUILD-SERVER-ifknfbweeg1: Provisioning with powershell script: ../install-scripts/install-cw1-appmgr.ps1 [#4]: 2020/11/17 16:02:46 packer.exe plugin: Opening ../install-scripts/install-cw1-appmgr.ps1 for reading [#4]: 2020/11/17 16:02:46 packer.exe plugin: Env var [REDACTED] converted to [REDACTED] after escaping chars special to PS [#4]: 2020/11/17 16:02:46 packer.exe plugin: Uploading env vars to c:/Windows/Temp/packer-ps-env-vars-5fb346d6-ae61-af2b-6855-72f40985e6a0.ps1 [#4]: 2020/11/17 16:02:46 packer.exe plugin: [INFO] 479 bytes written for 'uploadData' [#4]: 2020/11/17 16:02:46 [INFO] 479 bytes written for 'uploadData' [#4]: 2020/11/17 16:02:46 packer.exe plugin: Uploading file to 'c:/Windows/Temp/packer-ps-env-vars-5fb346d6-ae61-af2b-6855-72f40985e6a0.ps1' [#4]: 2020/11/17 16:02:49 packer.exe plugin: #< CLIXML [#4]: 2020/11/17 16:02:51 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 1Preparing modules for first use.0-1-1Completed-1 #< CLIXML [#4]: 2020/11/17 16:02:51 packer.exe plugin: Building elevated command wrapper for: powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb346d6-ae61-af2b-6855-72f40985e6a0.ps1; &'c:/Windows/Temp/script-5fb346d6-9c98-2536-0059-8b035d77c047.ps1'; exit $LastExitCode }" [#4]: 2020/11/17 16:02:51 packer.exe plugin: Command [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb346d6-ae61-af2b-6855-72f40985e6a0.ps1; &'c:/Windows/Temp/script-5fb346d6-9c98-2536-0059-8b035d77c047.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5fb3597b-96b8-871a-63cb-b6340897e063.out 2>&1] converted to [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb346d6-ae61-af2b-6855-72f40985e6a0.ps1; &'c:/Windows/Temp/script-5fb346d6-9c98-2536-0059-8b035d77c047.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5fb3597b-96b8-871a-63cb-b6340897e063.out 2>&1] for use in XML string [#4]: 2020/11/17 16:02:51 packer.exe plugin: Uploading elevated shell wrapper for command [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb346d6-ae61-af2b-6855-72f40985e6a0.ps1; &'c:/Windows/Temp/script-5fb346d6-9c98-2536-0059-8b035d77c047.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5fb3597b-96b8-871a-63cb-b6340897e063.out 2>&1] to [C:/Windows/Temp/packer-elevated-shell-5fb3597b-12b7-41ce-df86-9e95ad8c7c38.ps1] [#4]: 2020/11/17 16:02:51 packer.exe plugin: [INFO] 3513 bytes written for 'uploadData' [#4]: 2020/11/17 16:02:51 [INFO] 3513 bytes written for 'uploadData' [#4]: 2020/11/17 16:02:51 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 Uploading file to 'C:/Windows/Temp/packer-elevated-shell-5fb3597b-12b7-41ce-df86-9e95ad8c7c38.ps1' [#4]: 2020/11/17 16:02:54 packer.exe plugin: #< CLIXML [#4]: 2020/11/17 16:02:56 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML [#4]: 2020/11/17 16:02:56 packer.exe plugin: [INFO] 370 bytes written for 'uploadData' [#4]: 2020/11/17 16:02:56 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 Uploading file to 'c:/Windows/Temp/script-5fb346d6-9c98-2536-0059-8b035d77c047.ps1' [#4]: 2020/11/17 16:02:56 [INFO] 370 bytes written for 'uploadData' [#4]: 2020/11/17 16:02:59 packer.exe plugin: #< CLIXML [#4]: 2020/11/17 16:03:01 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML [#4]: 2020/11/17 16:03:01 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 [INFO] starting remote command: powershell -executionpolicy bypass -file "C:/Windows/Temp/packer-elevated-shell-5fb3597b-12b7-41ce-df86-9e95ad8c7c38.ps1" [#4]: 2020/11/17 16:03:07 packer.exe plugin: [INFO] command 'powershell -executionpolicy bypass -file "C:/Windows/Temp/packer-elevated-shell-5fb3597b-12b7-41ce-df86-9e95ad8c7c38.ps1"' exited with code: 1 [#4]: 2020/11/17 16:03:07 packer.exe plugin: [INFO] RPC endpoint: Communicator ended with: 1 [#4]: 2020/11/17 16:03:07 [INFO] 688 bytes written for 'stdout' [#4]: 2020/11/17 16:03:07 [INFO] 0 bytes written for 'stderr' [#4]: 2020/11/17 16:03:07 [INFO] RPC client: Communicator ended with: 1 [#4]: 2020/11/17 16:03:07 [INFO] RPC endpoint: Communicator ended with: 1 [#4]: 2020/11/17 16:03:07 packer.exe plugin: [INFO] 0 bytes written for 'stderr' [#4]: 2020/11/17 16:03:07 packer.exe plugin: [INFO] 688 bytes written for 'stdout' [#4]: 2020/11/17 16:03:07 packer.exe plugin: [INFO] RPC client: Communicator ended with: 1 [#4]: DAT-BUILD-SERVER-ifknfbweeg1: Invoke-WebRequest : Cannot bind parameter 'Uri'. Cannot convert value [#4]: DAT-BUILD-SERVER-ifknfbweeg1: "http:///cw1-appmgr/CargoWiseOneAppManagerSetup-2.0.13.msi" to type [#4]: DAT-BUILD-SERVER-ifknfbweeg1: "System.Uri". Error: "Invalid URI: The hostname could not be parsed." [#4]: DAT-BUILD-SERVER-ifknfbweeg1: At C:\Windows\Temp\script-5fb346d6-9c98-2536-0059-8b035d77c047.ps1:6 char:24 [#4]: DAT-BUILD-SERVER-ifknfbweeg1: + ... equest -Uri http://${env:PACKER_HTTP_ADDR}/cw1-appmgr/CargoWiseOneApp ... [#4]: DAT-BUILD-SERVER-ifknfbweeg1: + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ [#4]: DAT-BUILD-SERVER-ifknfbweeg1: + CategoryInfo : InvalidArgument: (:) [Invoke-WebRequest], Parent [#4]: DAT-BUILD-SERVER-ifknfbweeg1: ContainsErrorRecordException [#4]: DAT-BUILD-SERVER-ifknfbweeg1: + FullyQualifiedErrorId : CannotConvertArgumentNoMessage,Microsoft.PowerSh [#4]: DAT-BUILD-SERVER-ifknfbweeg1: ell.Commands.InvokeWebRequestCommand [#4]: DAT-BUILD-SERVER-ifknfbweeg1: [#4]: 2020/11/17 16:03:07 packer.exe plugin: c:/Windows/Temp/script-5fb346d6-9c98-2536-0059-8b035d77c047.ps1 returned with exit code 1 [#4]: 2020/11/17 16:03:07 [INFO] (telemetry) ending powershell [#4]: ==> DAT-BUILD-SERVER-ifknfbweeg1: Provisioning step had errors: Running the cleanup provisioner, if present... ```
yaakov-h commented 4 years ago

And some more verbose output from another occurrence where the script file was not found:

``` ==> DAT-BUILD-SERVER-bpss15vhraj: Provisioning with powershell script: ../install-scripts/install-biztalk.ps1 2020/11/17 19:39:31 packer.exe plugin: Opening ../install-scripts/install-biztalk.ps1 for reading 2020/11/17 19:39:31 packer.exe plugin: Uploading env vars to c:/Windows/Temp/packer-ps-env-vars-5fb379f5-2ec0-149e-f699-63c50dce862b.ps1 2020/11/17 19:39:31 packer.exe plugin: [INFO] 358 bytes written for 'uploadData' 2020/11/17 19:39:31 [INFO] 358 bytes written for 'uploadData' 2020/11/17 19:39:31 packer.exe plugin: Uploading file to 'c:/Windows/Temp/packer-ps-env-vars-5fb379f5-2ec0-149e-f699-63c50dce862b.ps1' 2020/11/17 19:39:34 packer.exe plugin: #< CLIXML 2020/11/17 19:39:36 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML 2020/11/17 19:39:36 packer.exe plugin: Building elevated command wrapper for: powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb379f5-2ec0-149e-f699-63c50dce862b.ps1; &'c:/Windows/Temp/script-5fb379f5-8683-1f8b-2026-683535abe6a1.ps1'; exit $LastExitCode }" 2020/11/17 19:39:36 packer.exe plugin: Command [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb379f5-2ec0-149e-f699-63c50dce862b.ps1; &'c:/Windows/Temp/script-5fb379f5-8683-1f8b-2026-683535abe6a1.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5fb38c48-194e-ef6c-2d5b-ff080b1faf23.out 2>&1] converted to [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb379f5-2ec0-149e-f699-63c50dce862b.ps1; &'c:/Windows/Temp/script-5fb379f5-8683-1f8b-2026-683535abe6a1.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5fb38c48-194e-ef6c-2d5b-ff080b1faf23.out 2>&1] for use in XML string 2020/11/17 19:39:36 packer.exe plugin: Uploading elevated shell wrapper for command [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5fb379f5-2ec0-149e-f699-63c50dce862b.ps1; &'c:/Windows/Temp/script-5fb379f5-8683-1f8b-2026-683535abe6a1.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5fb38c48-194e-ef6c-2d5b-ff080b1faf23.out 2>&1] to [C:/Windows/Temp/packer-elevated-shell-5fb38c48-e684-99bd-b07f-a8502a478b49.ps1] 2020/11/17 19:39:36 packer.exe plugin: [INFO] 3513 bytes written for 'uploadData' 2020/11/17 19:39:36 [INFO] 3513 bytes written for 'uploadData' 2020/11/17 19:39:36 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 Uploading file to 'C:/Windows/Temp/packer-elevated-shell-5fb38c48-e684-99bd-b07f-a8502a478b49.ps1' 2020/11/17 19:40:00 packer.exe plugin: #< CLIXML 2020/11/17 19:40:00 packer.exe plugin: [INFO] 971 bytes written for 'uploadData' 2020/11/17 19:40:00 [INFO] 971 bytes written for 'uploadData' 2020/11/17 19:40:00 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 Uploading file to 'c:/Windows/Temp/script-5fb379f5-8683-1f8b-2026-683535abe6a1.ps1' 2020/11/17 19:40:03 packer.exe plugin: #< CLIXML 2020/11/17 19:40:05 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML 2020/11/17 19:40:05 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 [INFO] starting remote command: powershell -executionpolicy bypass -file "C:/Windows/Temp/packer-elevated-shell-5fb38c48-e684-99bd-b07f-a8502a478b49.ps1" DAT-BUILD-SERVER-bpss15vhraj: Windows PowerShell DAT-BUILD-SERVER-bpss15vhraj: Copyright (C) 2016 Microsoft Corporation. All rights reserved. DAT-BUILD-SERVER-bpss15vhraj: ==> DAT-BUILD-SERVER-bpss15vhraj: The argument 'C:/Windows/Temp/packer-elevated-shell-5fb38c48-e684-99bd-b07f-a8502a478b49.ps1' to the -File parameter does not exist. Provide the path to an existing '.ps1' file as an argument to the -File parameter. 2020/11/17 19:40:07 packer.exe plugin: [INFO] command 'powershell -executionpolicy bypass -file "C:/Windows/Temp/packer-elevated-shell-5fb38c48-e684-99bd-b07f-a8502a478b49.ps1"' exited with code: 4294770688 2020/11/17 19:40:07 packer.exe plugin: [INFO] RPC endpoint: Communicator ended with: 4294770688 2020/11/17 19:40:07 [INFO] 87 bytes written for 'stdout' 2020/11/17 19:40:07 [INFO] 217 bytes written for 'stderr' 2020/11/17 19:40:07 [INFO] RPC client: Communicator ended with: 4294770688 2020/11/17 19:40:07 [INFO] RPC endpoint: Communicator ended with: 4294770688 2020/11/17 19:40:07 packer.exe plugin: [INFO] 217 bytes written for 'stderr' 2020/11/17 19:40:07 packer.exe plugin: [INFO] 87 bytes written for 'stdout' 2020/11/17 19:40:07 packer.exe plugin: [INFO] RPC client: Communicator ended with: 4294770688 2020/11/17 19:40:07 packer.exe plugin: c:/Windows/Temp/script-5fb379f5-8683-1f8b-2026-683535abe6a1.ps1 returned with exit code 4294770688 2020/11/17 19:40:07 [INFO] (telemetry) ending powershell ```
yaakov-h commented 4 years ago

This looks like it might be related to recent changes in Windows.

After uninstalling KB4578969 and KB4580346 I managed to get a successful packer build run.