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.04k stars 3.32k forks source link

Powershell provisioner times out during Windows 10 Enterprise build #10444

Open gys-msci opened 3 years ago

gys-msci commented 3 years ago

Overview of the Issue

I am using Azure Devops to try building a Windows 10 Enterprise (Azure Marketplace Image SKU: 20h1-ent) image in Azure to be uploaded to a Shared Image Gallery. During the Packer build process I noticed that powershell provisioners time out, while for example windows-shell and windows-restart remain functional. However the powershell provisioners worked fine for Windows 10 Enterprise Multi-Session (Marketplace SKU: 20h1-evd). What might be different between these SKUs that enable or prevent powershell Packer provisioner usage? Can we enable powershell provisioner to work with the plain Windows 10 Enterprise image?

Reproduction Steps

The problem persisted each time I tried running the pipeline, the same was the outcome when I tried different SKUs, like 20h1-ent-g2, 20h1-entn, 20h1-entn-g2.

Packer version

Tried it with versions 1.4.5 and 1.6.5.

Simplified Packer Buildfile

"builders": [{
    "type": "azure-arm",

    "os_type": "Windows",
    "image_publisher": "MicrosoftWindowsDesktop",
    "image_offer": "Windows-10",
    "image_sku": "20h1-ent",

    "communicator": "winrm",
    "winrm_use_ssl": "true",
    "winrm_insecure": "true",
    "winrm_timeout": "20m",
}],
"provisioners": [
{
   "type": "windows-shell",
   "inline": [
     "netsh advfirewall set allprofiles state off"
   ]
},
{
  "type": "powershell",
  "elevated_user": "packer",
  "elevated_password": "{{.WinRMPassword}}",
  "inline": [
      "New-Item -Path C:\\Install -ItemType Directory -Force",
      "New-Item -Path C:\\Install\\Logs -ItemType Directory -Force",
      "New-Item -Path C:\\Install\\AzCLI -ItemType Directory -Force",
      "cd C:\\Install \\AzCLI",
      "(New-Object System.Net.WebClient).DownloadFile(\"https://aka.ms/installazurecliwindows\", \"C:\\Install \\AzCLI\\AzCLI.msi\")",
      "Start-Process msiexec.exe -Wait -ArgumentList '/i AzCLI.msi /qn /l*v C:\\Install\\Logs\\AzCLI_Install.log'"
  ]
},

Operating system and Environment details

The build took place on an Azure Devops agent (windows-2019) that uses WinRM to remotely connect to a temporary Azure VM.

Log Fragments and crash.log files

1609923473,,ui,say,==> azure-arm: Waiting for WinRM to become available... 1609923481,,ui,message, azure-arm: WinRM connected. 1609923481,,ui,error,==> azure-arm: #< CLIXML 1609923481,,ui,error,==> azure-arm: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 1Preparing modules for first use.0-1-1Completed-1 1609923481,,ui,say,==> azure-arm: Connected to WinRM! 1609923481,,ui,say,==> azure-arm: Provisioning with windows-shell... 1609923481,,ui,say,==> azure-arm: Provisioning with shell script: C:\Users\VSSADM~1\AppData\Local\Temp\windows-shell-provisioner242678815 1609923483,,ui,message, azure-arm: 1609923483,,ui,message, azure-arm: C:\Users\packer>netsh advfirewall set allprofiles state off 1609923484,,ui,message, azure-arm: Ok. 1609923484,,ui,message, azure-arm: 1609923484,,ui,say,==> azure-arm: Provisioning with Powershell... 1609923484,,ui,say,==> azure-arm: Provisioning with powershell script: C:\Users\VSSADM~1\AppData\Local\Temp\powershell-provisioner554706963

nywilken commented 3 years ago

Hi there thanks for reaching out. Could you provide the full packer debug logs PACKER_LOG=1 so that may better see what is happening during the build.

With that said, have you tired removing some of the inline commands in the Powershell provisoiner to see which command may be causing the timeout?

That fact that the provisioner works for one sku but fails for others seems to imply it is a Windows issue upon script execution. Not sure without logging. There is a debug mode option you could enable to see if one of the commands are failing somehow - see https://www.packer.io/docs/provisioners/powershell#debug_mode

gys-msci commented 3 years ago

Thank you for the response and the suggestions, nywilken!

I enabled PACKER_LOG=1 in the Packer build as well as debug_mode in the powershell provisioner ("debug_mode": "2"), simplified the inline command (hostname) and got the following:

2021-01-08T10:06:08.3572422Z 2021/01/08 10:06:08 packer.exe plugin: Connected to machine 2021-01-08T10:06:08.3574499Z 2021/01/08 10:06:08 1610100368,,ui,say,==> azure-arm: Connected to WinRM! 2021-01-08T10:06:08.3574879Z 1610100368,,ui,say,==> azure-arm: Connected to WinRM! 2021-01-08T10:06:08.3576641Z 2021/01/08 10:06:08 packer.exe plugin: Running the provision hook 2021-01-08T10:06:08.3577439Z 2021/01/08 10:06:08 [INFO] (telemetry) Starting provisioner windows-shell 2021-01-08T10:06:08.3587793Z 2021/01/08 10:06:08 1610100368,,ui,say,==> azure-arm: Provisioning with windows-shell... 2021-01-08T10:06:08.3588261Z 1610100368,,ui,say,==> azure-arm: Provisioning with windows-shell... 2021-01-08T10:06:08.3596337Z 2021/01/08 10:06:08 packer.exe plugin: Found command: netsh advfirewall set allprofiles state off 2021-01-08T10:06:08.3606379Z 2021/01/08 10:06:08 1610100368,,ui,say,==> azure-arm: Provisioning with shell script: C:\Users\VSSADM1\AppData\Local\Temp\windows-shell-provisioner691624915 2021-01-08T10:06:08.3607080Z 1610100368,,ui,say,==> azure-arm: Provisioning with shell script: C:\Users\VSSADM1\AppData\Local\Temp\windows-shell-provisioner691624915 2021-01-08T10:06:08.3608747Z 2021/01/08 10:06:08 packer.exe plugin: Opening C:\Users\VSSADM1\AppData\Local\Temp\windows-shell-provisioner691624915 for reading 2021-01-08T10:06:08.3615254Z 2021/01/08 10:06:08 packer.exe plugin: [INFO] 44 bytes written for 'uploadData' 2021-01-08T10:06:08.3616736Z 2021/01/08 10:06:08 [INFO] 44 bytes written for 'uploadData' 2021-01-08T10:06:08.3617820Z 2021/01/08 10:06:08 packer.exe plugin: Uploading file to 'c:/Windows/Temp/script.bat' 2021-01-08T10:06:09.5488939Z 2021/01/08 10:06:09 packer.exe plugin: #< CLIXML 2021-01-08T10:06:10.2963930Z 2021/01/08 10:06:10 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML 2021-01-08T10:06:10.4917762Z 2021/01/08 10:06:10 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 [INFO] starting remote command: set "PACKER_BUILDER_TYPE=azure-arm" && set "PACKER_BUILD_NAME=azure-arm" && "c:/Windows/Temp/script.bat" 2021-01-08T10:06:11.0486099Z 2021/01/08 10:06:11 1610100371,,ui,message, azure-arm: 2021-01-08T10:06:11.0486651Z 1610100371,,ui,message, azure-arm: 2021-01-08T10:06:11.0491447Z 2021/01/08 10:06:11 1610100371,,ui,message, azure-arm: C:\Users\packer>netsh advfirewall set allprofiles state off 2021-01-08T10:06:11.0513839Z 1610100371,,ui,message, azure-arm: C:\Users\packer>netsh advfirewall set allprofiles state off 2021-01-08T10:06:11.2357372Z 2021/01/08 10:06:11 packer.exe plugin: [INFO] command 'set "PACKER_BUILDER_TYPE=azure-arm" && set "PACKER_BUILD_NAME=azure-arm" && "c:/Windows/Temp/script.bat"' exited with code: 0 2021-01-08T10:06:11.2360563Z 2021/01/08 10:06:11 packer.exe plugin: [INFO] RPC endpoint: Communicator ended with: 0 2021-01-08T10:06:11.2361367Z 2021/01/08 10:06:11 [INFO] 71 bytes written for 'stdout' 2021-01-08T10:06:11.2362210Z 2021/01/08 10:06:11 [INFO] 0 bytes written for 'stderr' 2021-01-08T10:06:11.2365004Z 2021/01/08 10:06:11 [INFO] RPC client: Communicator ended with: 0 2021-01-08T10:06:11.2365620Z 2021/01/08 10:06:11 [INFO] RPC endpoint: Communicator ended with: 0 2021-01-08T10:06:11.2369585Z 2021/01/08 10:06:11 1610100371,,ui,message, azure-arm: Ok. 2021-01-08T10:06:11.2369937Z 1610100371,,ui,message, azure-arm: Ok. 2021-01-08T10:06:11.2370328Z 2021/01/08 10:06:11 packer.exe plugin: [INFO] 71 bytes written for 'stdout' 2021-01-08T10:06:11.2370736Z 2021/01/08 10:06:11 packer.exe plugin: [INFO] 0 bytes written for 'stderr' 2021-01-08T10:06:11.2371151Z 2021/01/08 10:06:11 packer.exe plugin: [INFO] RPC client: Communicator ended with: 0 2021-01-08T10:06:11.2375699Z 2021/01/08 10:06:11 1610100371,,ui,message, azure-arm: 2021-01-08T10:06:11.2382240Z 2021/01/08 10:06:11 [INFO] (telemetry) ending windows-shell 2021-01-08T10:06:11.2383138Z 2021/01/08 10:06:11 [INFO] (telemetry) Starting provisioner powershell 2021-01-08T10:06:11.2393085Z 2021/01/08 10:06:11 1610100371,,ui,say,==> azure-arm: Provisioning with Powershell... 2021-01-08T10:06:11.2393469Z 1610100371,,ui,message, azure-arm: 2021-01-08T10:06:11.2400432Z 2021/01/08 10:06:11 packer.exe plugin: Found command: hostname 2021-01-08T10:06:11.2403394Z 1610100371,,ui,say,==> azure-arm: Provisioning with Powershell... 2021-01-08T10:06:11.2405388Z 2021/01/08 10:06:11 1610100371,,ui,say,==> azure-arm: Provisioning with powershell script: C:\Users\VSSADM1\AppData\Local\Temp\powershell-provisioner774643687 2021-01-08T10:06:11.2406053Z 1610100371,,ui,say,==> azure-arm: Provisioning with powershell script: C:\Users\VSSADM1\AppData\Local\Temp\powershell-provisioner774643687 2021-01-08T10:06:11.2407538Z 2021/01/08 10:06:11 packer.exe plugin: Opening C:\Users\VSSADM1\AppData\Local\Temp\powershell-provisioner774643687 for reading 2021-01-08T10:06:11.2408878Z 2021/01/08 10:06:11 packer.exe plugin: Uploading env vars to c:/Windows/Temp/packer-ps-env-vars-5ff82d57-337a-e32f-458f-29ef4359ac0e.ps1 2021-01-08T10:06:11.2412996Z 2021/01/08 10:06:11 packer.exe plugin: [INFO] 74 bytes written for 'uploadData' 2021-01-08T10:06:11.2415967Z 2021/01/08 10:06:11 [INFO] 74 bytes written for 'uploadData' 2021-01-08T10:06:11.2416894Z 2021/01/08 10:06:11 packer.exe plugin: Uploading file to 'c:/Windows/Temp/packer-ps-env-vars-5ff82d57-337a-e32f-458f-29ef4359ac0e.ps1' 2021-01-08T10:06:12.4711108Z 2021/01/08 10:06:12 packer.exe plugin: #< CLIXML 2021-01-08T10:06:13.1747199Z 2021/01/08 10:06:13 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML 2021-01-08T10:06:13.2198149Z 2021/01/08 10:06:13 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'};Set-PsDebug -Trace 2;. c:/Windows/Temp/packer-ps-env-vars-5ff82d57-337a-e32f-458f-29ef4359ac0e.ps1; &'c:/Windows/Temp/script-5ff82d57-447a-9c90-40d0-240cda2136d7.ps1'; exit $LastExitCode }" 2021-01-08T10:06:13.2204653Z 2021/01/08 10:06:13 packer.exe plugin: Command [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};Set-PsDebug -Trace 2;. c:/Windows/Temp/packer-ps-env-vars-5ff82d57-337a-e32f-458f-29ef4359ac0e.ps1; &'c:/Windows/Temp/script-5ff82d57-447a-9c90-40d0-240cda2136d7.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5ff82e95-a809-81e5-3a30-3d46ac28aa78.out 2>&1] converted to [powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};Set-PsDebug -Trace 2;. c:/Windows/Temp/packer-ps-env-vars-5ff82d57-337a-e32f-458f-29ef4359ac0e.ps1; &'c:/Windows/Temp/script-5ff82d57-447a-9c90-40d0-240cda2136d7.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5ff82e95-a809-81e5-3a30-3d46ac28aa78.out 2>&1] for use in XML string 2021-01-08T10:06:13.2210370Z 2021/01/08 10:06:13 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'};Set-PsDebug -Trace 2;. c:/Windows/Temp/packer-ps-env-vars-5ff82d57-337a-e32f-458f-29ef4359ac0e.ps1; &'c:/Windows/Temp/script-5ff82d57-447a-9c90-40d0-240cda2136d7.ps1'; exit $LastExitCode }" > %SYSTEMROOT%/Temp/packer-5ff82e95-a809-81e5-3a30-3d46ac28aa78.out 2>&1] to [C:/Windows/Temp/packer-elevated-shell-5ff82e95-91a3-1454-ec22-d07c92d3a9b8.ps1] 2021-01-08T10:06:13.2213251Z 2021/01/08 10:06:13 packer.exe plugin: [INFO] 3543 bytes written for 'uploadData' 2021-01-08T10:06:13.2214006Z 2021/01/08 10:06:13 [INFO] 3543 bytes written for 'uploadData' 2021-01-08T10:06:13.2215923Z 2021/01/08 10:06:13 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-5ff82e95-91a3-1454-ec22-d07c92d3a9b8.ps1' 2021-01-08T10:06:14.4085164Z 2021/01/08 10:06:14 packer.exe plugin: #< CLIXML 2021-01-08T10:06:15.0959094Z 2021/01/08 10:06:15 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML 2021-01-08T10:06:15.1787328Z 2021/01/08 10:06:15 packer.exe plugin: [INFO] 9 bytes written for 'uploadData' 2021-01-08T10:06:15.1788862Z 2021/01/08 10:06:15 [INFO] 9 bytes written for 'uploadData' 2021-01-08T10:06:15.1791086Z 2021/01/08 10:06:15 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 Uploading file to 'c:/Windows/Temp/script-5ff82d57-447a-9c90-40d0-240cda2136d7.ps1' 2021-01-08T10:06:16.2260351Z 2021/01/08 10:06:16 packer.exe plugin: #< CLIXML 2021-01-08T10:06:16.8862275Z 2021/01/08 10:06:16 packer.exe plugin: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 #< CLIXML 2021-01-08T10:06:17.0410392Z 2021/01/08 10:06:17 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-5ff82e95-91a3-1454-ec22-d07c92d3a9b8.ps1" 2021-01-08T10:19:35.7748143Z ##[error]The operation was canceled. 2021-01-08T10:19:35.7771968Z ##[section]Finishing: Call Packer

I hoped for an error message but there was none.

simonlock commented 2 years ago

The same error exists using 20h1-evd-o365pp but works with Windows Server 2019. If Azure Image Builder uses Packer then there must be an issue there too.

efxvbr1 commented 2 years ago

we also face a similar issue while executing a PowerShell script file to unzip a zip file through the PowerShell provisioners. The packer completes without unzipping the file completely and starts creating the image , we are using windows 2019