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

First provisioner is sometimes 'skipped' on Windows #7039

Closed nebffa closed 5 years ago

nebffa commented 5 years ago

I have found that for some reason, certain provisioners on Windows silently fail with an exit code of 0 when they are the first provisioner. For example, in this case, the Chef provisioner 'installs' Chef - but it's not actually installed. I've verified this by logging on to the server and seeing that there's no C:\opscode directory. Sadly, the debug Packer log doesn't really show much.

Adding in a sleep that comes first, like:

    {
      "inline": "Start-Sleep 10",
      "type": "powershell"
    },

makes everything work.

2018/11/26 15:57:51 [INFO] Packer version: 1.3.1
2018/11/26 15:57:51 Packer Target OS/Arch: darwin amd64
2018/11/26 15:57:51 Built with Go Version: go1.11
2018/11/26 15:57:51 [DEBUG] Discovered plugin: windows-update = /usr/local/bin/packer-provisioner-windows-update
2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 [DEBUG] Discovered plugin: amazon-ami-management = /Users/ben/.packer.d/plugins/packer-post-processor-amazon-ami-management
2018/11/26 15:57:51 Using internal plugin for amazon-chroot
2018/11/26 15:57:51 Using internal plugin for amazon-ebsvolume
2018/11/26 15:57:51 Using internal plugin for lxc
2018/11/26 15:57:51 Using internal plugin for openstack
2018/11/26 15:57:51 Using internal plugin for profitbricks
2018/11/26 15:57:51 Using internal plugin for alicloud-ecs
2018/11/26 15:57:51 Using internal plugin for amazon-ebssurrogate
2018/11/26 15:57:51 Using internal plugin for digitalocean
2018/11/26 15:57:51 Using internal plugin for hyperv-vmcx
2018/11/26 15:57:51 Using internal plugin for cloudstack
2018/11/26 15:57:51 Using internal plugin for oracle-classic
2018/11/26 15:57:51 Using internal plugin for scaleway
2018/11/26 15:57:51 Using internal plugin for azure-arm
2018/11/26 15:57:51 Using internal plugin for oneandone
2018/11/26 15:57:51 Using internal plugin for parallels-iso
2018/11/26 15:57:51 Using internal plugin for parallels-pvm
2018/11/26 15:57:51 Using internal plugin for virtualbox-ovf
2018/11/26 15:57:51 Using internal plugin for vmware-iso
2018/11/26 15:57:51 Using internal plugin for amazon-instance
2018/11/26 15:57:51 Using internal plugin for docker
2018/11/26 15:57:51 Using internal plugin for null
2018/11/26 15:57:51 Using internal plugin for oracle-oci
2018/11/26 15:57:51 Using internal plugin for file
2018/11/26 15:57:51 Using internal plugin for googlecompute
2018/11/26 15:57:51 Using internal plugin for hyperv-iso
2018/11/26 15:57:51 Using internal plugin for lxd
2018/11/26 15:57:51 Using internal plugin for ncloud
2018/11/26 15:57:51 Using internal plugin for amazon-ebs
2018/11/26 15:57:51 Using internal plugin for triton
2018/11/26 15:57:51 Using internal plugin for vmware-vmx
2018/11/26 15:57:51 Using internal plugin for qemu
2018/11/26 15:57:51 Using internal plugin for virtualbox-iso
2018/11/26 15:57:51 Using internal plugin for windows-restart
2018/11/26 15:57:51 Using internal plugin for windows-shell
2018/11/26 15:57:51 Using internal plugin for ansible
2018/11/26 15:57:51 Using internal plugin for chef-client
2018/11/26 15:57:51 Using internal plugin for powershell
2018/11/26 15:57:51 Using internal plugin for salt-masterless
2018/11/26 15:57:51 Using internal plugin for file
2018/11/26 15:57:51 Using internal plugin for shell
2018/11/26 15:57:51 Using internal plugin for ansible-local
2018/11/26 15:57:51 Using internal plugin for chef-solo
2018/11/26 15:57:51 Using internal plugin for converge
2018/11/26 15:57:51 Using internal plugin for puppet-masterless
2018/11/26 15:57:51 Using internal plugin for puppet-server
2018/11/26 15:57:51 Using internal plugin for shell-local
2018/11/26 15:57:51 Using internal plugin for amazon-import
2018/11/26 15:57:51 Using internal plugin for googlecompute-export
2018/11/26 15:57:51 Using internal plugin for manifest
2018/11/26 15:57:51 Using internal plugin for vagrant
2018/11/26 15:57:51 Using internal plugin for googlecompute-import
2018/11/26 15:57:51 Using internal plugin for docker-import
2018/11/26 15:57:51 Using internal plugin for docker-push
2018/11/26 15:57:51 Using internal plugin for docker-save
2018/11/26 15:57:51 Using internal plugin for docker-tag
2018/11/26 15:57:51 Using internal plugin for checksum
2018/11/26 15:57:51 Using internal plugin for vagrant-cloud
2018/11/26 15:57:51 Using internal plugin for vsphere
2018/11/26 15:57:51 Using internal plugin for vsphere-template
2018/11/26 15:57:51 Using internal plugin for alicloud-import
2018/11/26 15:57:51 Using internal plugin for artifice
2018/11/26 15:57:51 Using internal plugin for compress
2018/11/26 15:57:51 Using internal plugin for shell-local
2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 Attempting to open config file: /Users/ben/.packerconfig
2018/11/26 15:57:51 [WARN] Config file doesn't exist: /Users/ben/.packerconfig
2018/11/26 15:57:51 Packer config: &{DisableCheckpoint:false DisableCheckpointSignature:false PluginMinPort:10000 PluginMaxPort:25000 Builders:map[cloudstack:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-cloudstack oneandone:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-oneandone amazon-instance:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-amazon-instance amazon-chroot:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-amazon-chroot alicloud-ecs:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-alicloud-ecs digitalocean:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-digitalocean triton:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-triton openstack:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-openstack scaleway:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-scaleway file:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-file ncloud:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-ncloud lxc:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-lxc oracle-classic:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-oracle-classic azure-arm:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-azure-arm vmware-iso:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-vmware-iso null:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-null googlecompute:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-googlecompute hyperv-iso:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-hyperv-iso hyperv-vmcx:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-hyperv-vmcx parallels-iso:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-parallels-iso parallels-pvm:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-parallels-pvm oracle-oci:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-oracle-oci vmware-vmx:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-vmware-vmx docker:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-docker amazon-ebs:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-amazon-ebs virtualbox-iso:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-virtualbox-iso amazon-ebsvolume:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-amazon-ebsvolume profitbricks:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-profitbricks qemu:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-qemu amazon-ebssurrogate:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-amazon-ebssurrogate virtualbox-ovf:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-virtualbox-ovf lxd:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-builder-lxd] PostProcessors:map[checksum:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-checksum alicloud-import:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-alicloud-import vagrant:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-vagrant docker-save:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-docker-save compress:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-compress shell-local:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-shell-local manifest:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-manifest googlecompute-import:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-googlecompute-import docker-import:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-docker-import docker-tag:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-docker-tag artifice:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-artifice amazon-ami-management:/Users/ben/.packer.d/plugins/packer-post-processor-amazon-ami-management amazon-import:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-amazon-import googlecompute-export:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-googlecompute-export docker-push:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-docker-push vagrant-cloud:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-vagrant-cloud vsphere:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-vsphere vsphere-template:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-post-processor-vsphere-template] Provisioners:map[ansible:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-ansible salt-masterless:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-salt-masterless puppet-masterless:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-puppet-masterless windows-update:/usr/local/bin/packer-provisioner-windows-update windows-shell:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-windows-shell file:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-file ansible-local:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-ansible-local converge:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-converge powershell:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-powershell shell-local:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-shell-local windows-restart:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-windows-restart chef-client:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-chef-client shell:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-shell chef-solo:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-chef-solo puppet-server:/usr/local/bin/packer-PACKERSPACE-plugin-PACKERSPACE-packer-provisioner-puppet-server]}
2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 Setting cache directory: /Users/ben/work/*********/infrastructure/packer-windows-base/packer_cache
2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 Loading builder: amazon-ebs
2018/11/26 15:57:51 Plugin could not be found. Checking same directory as executable.
2018/11/26 15:57:51 Current exe path: /usr/local/bin/packer
2018/11/26 15:57:51 Creating plugin client for path: /usr/local/bin/packer
2018/11/26 15:57:51 Starting plugin: /usr/local/bin/packer []string{"/usr/local/bin/packer", "plugin", "packer-builder-amazon-ebs"}
2018/11/26 15:57:51 Waiting for RPC address for: /usr/local/bin/packer
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [INFO] Packer version: 1.3.1
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Packer Target OS/Arch: darwin amd64
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Built with Go Version: go1.11
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Attempting to open config file: /Users/ben/.packerconfig
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [WARN] Config file doesn't exist: /Users/ben/.packerconfig
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Packer config: &{DisableCheckpoint:false DisableCheckpointSignature:false PluginMinPort:10000 PluginMaxPort:25000 Builders:map[] PostProcessors:map[] Provisioners:map[]}
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Setting cache directory: /Users/ben/work/*********/infrastructure/packer-windows-base/packer_cache
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 args: []string{"packer-builder-amazon-ebs"}
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin minimum port: 10000
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin maximum port: 25000
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin address: unix /var/folders/kv/rxy7p81s21j_227mm0k00m_80000gn/T/packer-plugin122624348
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Waiting for connection...
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Serving a plugin connection...
2018/11/26 15:57:51 Loading provisioner: chef-solo
2018/11/26 15:57:51 Plugin could not be found. Checking same directory as executable.
2018/11/26 15:57:51 Current exe path: /usr/local/bin/packer
2018/11/26 15:57:51 Creating plugin client for path: /usr/local/bin/packer
2018/11/26 15:57:51 Starting plugin: /usr/local/bin/packer []string{"/usr/local/bin/packer", "plugin", "packer-provisioner-chef-solo"}
2018/11/26 15:57:51 Waiting for RPC address for: /usr/local/bin/packer
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [INFO] Packer version: 1.3.1
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Packer Target OS/Arch: darwin amd64
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Built with Go Version: go1.11
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Attempting to open config file: /Users/ben/.packerconfig
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [WARN] Config file doesn't exist: /Users/ben/.packerconfig
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Packer config: &{DisableCheckpoint:false DisableCheckpointSignature:false PluginMinPort:10000 PluginMaxPort:25000 Builders:map[] PostProcessors:map[] Provisioners:map[]}
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Setting cache directory: /Users/ben/work/*********/infrastructure/packer-windows-base/packer_cache
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 args: []string{"packer-provisioner-chef-solo"}
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin minimum port: 10000
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin maximum port: 25000
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin address: unix /var/folders/kv/rxy7p81s21j_227mm0k00m_80000gn/T/packer-plugin230623488
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Waiting for connection...
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Serving a plugin connection...
2018/11/26 15:57:51 Loading provisioner: powershell
2018/11/26 15:57:51 Plugin could not be found. Checking same directory as executable.
2018/11/26 15:57:51 Current exe path: /usr/local/bin/packer
2018/11/26 15:57:51 Creating plugin client for path: /usr/local/bin/packer
2018/11/26 15:57:51 Starting plugin: /usr/local/bin/packer []string{"/usr/local/bin/packer", "plugin", "packer-provisioner-powershell"}
2018/11/26 15:57:51 Waiting for RPC address for: /usr/local/bin/packer
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [INFO] Packer version: 1.3.1
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Packer Target OS/Arch: darwin amd64
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Built with Go Version: go1.11
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Attempting to open config file: /Users/ben/.packerconfig
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [WARN] Config file doesn't exist: /Users/ben/.packerconfig
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Packer config: &{DisableCheckpoint:false DisableCheckpointSignature:false PluginMinPort:10000 PluginMaxPort:25000 Builders:map[] PostProcessors:map[] Provisioners:map[]}
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Detected home directory from env var: /Users/ben
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Setting cache directory: /Users/ben/work/*********/infrastructure/packer-windows-base/packer_cache
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 args: []string{"packer-provisioner-powershell"}
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin minimum port: 10000
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin maximum port: 25000
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Plugin address: unix /var/folders/kv/rxy7p81s21j_227mm0k00m_80000gn/T/packer-plugin207053684
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Waiting for connection...
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Serving a plugin connection...
2018/11/26 15:57:51 Build debug mode: false
2018/11/26 15:57:51 Force build: false
2018/11/26 15:57:51 On error: abort
2018/11/26 15:57:51 Preparing build: amazon-ebs
amazon-ebs output will be in this color.

2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 {{amazon-ebs amazon-ebs false false abort map[subnet_id:subnet-a5bd3fc2 source_ami:Windows_Server-2016-English-Full-Base-????.??.?? security_group_id:sg-d7e9d2ae ssh_private_key_file:/Users/ben/.ssh/*********/shared_services/packer.pem] []} {  false   ap-southeast-2  false false  <nil>} {********* Windows Base 1543208271   [121797399020] [] [] [] false map[Amazon_AMI_Management_Identifier:*********_windows_base_ami] false false false false false  map[] map[] [] []} {{[]} {[]}} {false  0 false false false packer-instance-profile stop t2.medium map[]  [sg-d7e9d2ae]  {map[0xc0003d6d60:0xc0003d6d80 0xc0003d6da0:0xc0003d6dc0 0xc0003d6de0:0xc0003d6e00 0xc0003d6e20:0xc0003d6e40] [0xc0003d6ec0] true}   map[] subnet-a5bd3fc2  0.0.0.0/0  ./user_data.txt  20m0s {winrm  0   [] [] packer  false /Users/ben/.ssh/*********/shared_services/packer.pem   false 0s false false 0  0 false      0   0s 0s Administrator   5986 5m0s true true false <nil>}} map[] {<nil> map[clean_ami_name:0x1945920] map[source_ami:Windows_Server-2016-English-Full-Base-????.??.?? security_group_id:sg-d7e9d2ae ssh_private_key_file:/Users/ben/.ssh/*********/shared_services/packer.pem subnet_id:subnet-a5bd3fc2] [] false amazon-ebs amazon-ebs /Users/ben/work/*********/infrastructure/packer-windows-base/*********-windows-base.json}}
2018/11/26 15:57:51 Waiting on builds to complete...
2018/11/26 15:57:51 Starting build run: amazon-ebs
2018/11/26 15:57:51 Running builder: amazon-ebs
2018/11/26 15:57:51 [INFO] (telemetry) Starting builder amazon-ebs
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 Found region ap-southeast-2
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [INFO] AWS Auth provider used: "EnvConfigCredentials"
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [INFO] Finding AZ and VpcId for the given subnet 'subnet-a5bd3fc2'
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [INFO] AvailabilityZone found: 'ap-southeast-2a'
2018/11/26 15:57:51 packer: 2018/11/26 15:57:51 [INFO] VpcId found: 'vpc-89e01bee'
==> amazon-ebs: Prevalidating AMI Name: ********* Windows Base 1543208271
2018/11/26 15:57:52 packer: 2018/11/26 15:57:52 Using AMI Filters {
2018/11/26 15:57:52 packer:   Filters: [
2018/11/26 15:57:52 packer:     {
2018/11/26 15:57:52 packer:       Name: "virtualization-type",
2018/11/26 15:57:52 packer:       Values: ["hvm"]
2018/11/26 15:57:52 packer:     },
2018/11/26 15:57:52 packer:     {
2018/11/26 15:57:52 packer:       Name: "architecture",
2018/11/26 15:57:52 packer:       Values: ["x86_64"]
2018/11/26 15:57:52 packer:     },
2018/11/26 15:57:52 packer:     {
2018/11/26 15:57:52 packer:       Name: "name",
2018/11/26 15:57:52 packer:       Values: ["Windows_Server-2016-English-Full-Base-????.??.??"]
2018/11/26 15:57:52 packer:     },
2018/11/26 15:57:52 packer:     {
2018/11/26 15:57:52 packer:       Name: "root-device-type",
2018/11/26 15:57:52 packer:       Values: ["ebs"]
2018/11/26 15:57:52 packer:     }
2018/11/26 15:57:52 packer:   ],
2018/11/26 15:57:52 packer:   Owners: ["amazon"]
2018/11/26 15:57:52 packer: }
    amazon-ebs: Found Image ID: ami-03b3182648d0d0bfb
==> amazon-ebs: Using existing SSH private key
2018/11/26 15:57:53 packer: 2018/11/26 15:57:53 Using specified security groups: [sg-d7e9d2ae]
2018/11/26 15:57:53 packer: 2018/11/26 15:57:53 [DEBUG] base64 encoding user data...
==> amazon-ebs: Launching a source AWS instance...
==> amazon-ebs: Adding tags to source instance
    amazon-ebs: Adding tag: "Name": "Packer Builder"
    amazon-ebs: Instance ID: i-085cb8b49b60f6003
==> amazon-ebs: Waiting for instance (i-085cb8b49b60f6003) to become ready...
==> amazon-ebs: Waiting for auto-generated password for instance...
    amazon-ebs: but it usually takes around 5. Please wait.
    amazon-ebs: It is normal for this process to take up to 15 minutes,
    amazon-ebs: but it usually takes around 5. Please wait.
2018/11/26 15:58:29 packer: 2018/11/26 15:58:29 [DEBUG] Password is blank, will retry...
2018/11/26 15:58:35 packer: 2018/11/26 15:58:35 [DEBUG] Password is blank, will retry...
2018/11/26 15:58:40 packer: 2018/11/26 15:58:40 [DEBUG] Password is blank, will retry...
2018/11/26 15:58:45 packer: 2018/11/26 15:58:45 [DEBUG] Password is blank, will retry...
2018/11/26 15:58:50 packer: 2018/11/26 15:58:50 [DEBUG] Password is blank, will retry...
2018/11/26 15:58:55 packer: 2018/11/26 15:58:55 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:00 packer: 2018/11/26 15:59:00 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:05 packer: 2018/11/26 15:59:05 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:10 packer: 2018/11/26 15:59:10 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:15 packer: 2018/11/26 15:59:15 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:20 packer: 2018/11/26 15:59:20 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:25 packer: 2018/11/26 15:59:25 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:31 packer: 2018/11/26 15:59:31 [DEBUG] Password is blank, will retry...
2018/11/26 15:59:36 packer: 2018/11/26 15:59:36 [DEBUG] Password is blank, will retry...
    amazon-ebs: Password retrieved!
    amazon-ebs:
    amazon-ebs: Password retrieved!
==> amazon-ebs: Using winrm communicator to connect: 10.2.2.42
2018/11/26 15:59:41 packer: 2018/11/26 15:59:41 Waiting for WinRM, up to timeout: 5m0s
==> amazon-ebs: Waiting for WinRM to become available...
2018/11/26 15:59:46 packer: 2018/11/26 15:59:46 [INFO] Attempting WinRM connection...
2018/11/26 15:59:46 packer: 2018/11/26 15:59:46 [DEBUG] connecting to remote shell using WinRM
2018/11/26 15:59:52 packer: 2018/11/26 15:59:52 Checking that WinRM is connected with: 'powershell.exe -EncodedCommand aQBmACAAKABUAGUAcwB0AC0AUABhAHQAaAAgAHYAYQByAGkAYQBiAGwAZQA6AGcAbABvAGIAYQBsADoAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAKQB7ACQAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAPQAnAFMAaQBsAGUAbgB0AGwAeQBDAG8AbgB0AGkAbgB1AGUAJwB9ADsAIABlAGMAaABvACAAIgBXAGkAbgBSAE0AIABjAG8AbgBuAGUAYwB0AGUAZAAuACIA'
2018/11/26 15:59:52 packer: 2018/11/26 15:59:52 [INFO] starting remote command: powershell.exe -EncodedCommand aQBmACAAKABUAGUAcwB0AC0AUABhAHQAaAAgAHYAYQByAGkAYQBiAGwAZQA6AGcAbABvAGIAYQBsADoAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAKQB7ACQAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAPQAnAFMAaQBsAGUAbgB0AGwAeQBDAG8AbgB0AGkAbgB1AGUAJwB9ADsAIABlAGMAaABvACAAIgBXAGkAbgBSAE0AIABjAG8AbgBuAGUAYwB0AGUAZAAuACIA
2018/11/26 15:59:52 packer: 2018/11/26 15:59:52 [INFO] command 'powershell.exe -EncodedCommand aQBmACAAKABUAGUAcwB0AC0AUABhAHQAaAAgAHYAYQByAGkAYQBiAGwAZQA6AGcAbABvAGIAYQBsADoAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAKQB7ACQAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAPQAnAFMAaQBsAGUAbgB0AGwAeQBDAG8AbgB0AGkAbgB1AGUAJwB9ADsAIABlAGMAaABvACAAIgBXAGkAbgBSAE0AIABjAG8AbgBuAGUAYwB0AGUAZAAuACIA' exited with code: 0
    amazon-ebs: WinRM connected.
    amazon-ebs: #< CLIXML
2018/11/26 15:59:52 packer: 2018/11/26 15:59:52 Connected to machine
    amazon-ebs: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj><Obj S="progress" RefId="1"><TNRef RefId="0" /><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj></Objs>
==> amazon-ebs: Connected to WinRM!
2018/11/26 15:59:52 packer: 2018/11/26 15:59:52 Running the provision hook
2018/11/26 15:59:52 [INFO] (telemetry) Starting provisioner chef-solo
==> amazon-ebs: Provisioning with chef-solo
    amazon-ebs: Installing Chef...
2018/11/26 15:59:52 packer: 2018/11/26 15:59:52 [INFO] starting remote command: powershell.exe -Command ". { iwr -useb https://omnitruck.chef.io/install.ps1 } | iex; Install-Project"
    amazon-ebs:
    amazon-ebs: ModuleType Version    Name                                ExportedCommands
    amazon-ebs: ---------- -------    ----                                ----------------
    amazon-ebs: Script     0.0        Omnitruck                           {Get-ProjectMetadata, Install-Project, install}
2018/11/26 15:59:57 packer: 2018/11/26 15:59:57 [INFO] command 'powershell.exe -Command ". { iwr -useb https://omnitruck.chef.io/install.ps1 } | iex; Install-Project"' exited with code: 0
2018/11/26 15:59:57 packer: 2018/11/26 15:59:57 [INFO] RPC endpoint: Communicator ended with: 0
2018/11/26 15:59:57 [INFO] 365 bytes written for 'stdout'
2018/11/26 15:59:57 [INFO] 0 bytes written for 'stderr'
2018/11/26 15:59:57 [INFO] RPC client: Communicator ended with: 0
2018/11/26 15:59:57 [INFO] RPC endpoint: Communicator ended with: 0
2018/11/26 15:59:57 packer: 2018/11/26 15:59:57 [INFO] 365 bytes written for 'stdout'
2018/11/26 15:59:57 packer: 2018/11/26 15:59:57 [INFO] 0 bytes written for 'stderr'
2018/11/26 15:59:57 packer: 2018/11/26 15:59:57 [INFO] RPC client: Communicator ended with: 0
    amazon-ebs: Creating directory: C:/chef/*********
2018/11/26 16:00:00 packer: 2018/11/26 16:00:00 [INFO] starting remote command: powershell.exe -Command "New-Item -ItemType directory -Force -ErrorAction SilentlyContinue -Path C:/chef/*********"
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] command 'powershell.exe -Command "New-Item -ItemType directory -Force -ErrorAction SilentlyContinue -Path C:/chef/*********"' exited with code: 0
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] RPC endpoint: Communicator ended with: 0
2018/11/26 16:00:02 [INFO] 399 bytes written for 'stdout'
    amazon-ebs:
2018/11/26 16:00:02 [INFO] 0 bytes written for 'stderr'
2018/11/26 16:00:02 [INFO] RPC client: Communicator ended with: 0
2018/11/26 16:00:02 [INFO] RPC endpoint: Communicator ended with: 0
    amazon-ebs:
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] 399 bytes written for 'stdout'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] 0 bytes written for 'stderr'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] RPC client: Communicator ended with: 0
    amazon-ebs:     Directory: C:\chef
    amazon-ebs:
    amazon-ebs:
    amazon-ebs: Mode                LastWriteTime         Length Name
    amazon-ebs: ----                -------------         ------ ----
    amazon-ebs: d-----       11/26/2018   5:00 AM                *********
    amazon-ebs:
    amazon-ebs:
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] starting remote command: echo 'skipping chmod 0777 C:/chef/*********'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] command 'echo 'skipping chmod 0777 C:/chef/*********'' exited with code: 0
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] RPC endpoint: Communicator ended with: 0
2018/11/26 16:00:02 [INFO] 0 bytes written for 'stderr'
2018/11/26 16:00:02 [INFO] 42 bytes written for 'stdout'
2018/11/26 16:00:02 [INFO] RPC client: Communicator ended with: 0
2018/11/26 16:00:02 [INFO] RPC endpoint: Communicator ended with: 0
    amazon-ebs: 'skipping chmod 0777 C:/chef/*********'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] 42 bytes written for 'stdout'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] 0 bytes written for 'stderr'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] RPC client: Communicator ended with: 0
    amazon-ebs: Creating configuration file 'solo.rb'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 [INFO] 55 bytes written for 'uploadData'
2018/11/26 16:00:02 [INFO] 55 bytes written for 'uploadData'
2018/11/26 16:00:02 packer: 2018/11/26 16:00:02 Uploading file to 'C:/chef/*********/solo.rb'
2018/11/26 16:00:03 packer: #< CLIXML
2018/11/26 16:00:04 packer: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj></Objs>#< CLIXML
    amazon-ebs: Creating JSON attribute file
2018/11/26 16:00:04 packer: 2018/11/26 16:00:04 [INFO] 70 bytes written for 'uploadData'
2018/11/26 16:00:04 [INFO] 70 bytes written for 'uploadData'
2018/11/26 16:00:04 packer: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj></Objs>2018/11/26 16:00:04 Uploading file to 'C:/chef/*********/node.json'
2018/11/26 16:00:06 packer: #< CLIXML
2018/11/26 16:00:08 packer: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj></Objs>#< CLIXML
    amazon-ebs: Executing Chef: c:/opscode/chef/bin/chef-solo.bat --no-color -c C:/chef/*********/solo.rb -j C:/chef/*********/node.json
2018/11/26 16:00:08 packer: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj></Objs>2018/11/26 16:00:08 [INFO] starting remote command: c:/opscode/chef/bin/chef-solo.bat --no-color -c C:/chef/*********/solo.rb -j C:/chef/*********/node.json
2018/11/26 16:00:08 packer: 2018/11/26 16:00:08 [INFO] command 'c:/opscode/chef/bin/chef-solo.bat --no-color -c C:/chef/*********/solo.rb -j C:/chef/*********/node.json' exited with code: 1
2018/11/26 16:00:08 packer: 2018/11/26 16:00:08 [INFO] RPC endpoint: Communicator ended with: 1
2018/11/26 16:00:08 [INFO] 0 bytes written for 'stdout'
2018/11/26 16:00:08 [INFO] 44 bytes written for 'stderr'
2018/11/26 16:00:08 [INFO] RPC client: Communicator ended with: 1
2018/11/26 16:00:08 [INFO] RPC endpoint: Communicator ended with: 1
2018/11/26 16:00:08 packer: 2018/11/26 16:00:08 [INFO] 0 bytes written for 'stdout'
2018/11/26 16:00:08 packer: 2018/11/26 16:00:08 [INFO] 44 bytes written for 'stderr'
    amazon-ebs: The system cannot find the path specified.
2018/11/26 16:00:08 packer: 2018/11/26 16:00:08 [INFO] RPC client: Communicator ended with: 1
2018/11/26 16:00:08 [INFO] (telemetry) ending chef-solo
2018/11/26 16:00:08 ui error: ==> amazon-ebs: Error executing Chef: Non-zero exit status: 1
==> amazon-ebs: Error executing Chef: Non-zero exit status: 1
2018/11/26 16:00:08 ui error: ==> amazon-ebs: Step "StepProvision" failed, aborting...
==> amazon-ebs: Step "StepProvision" failed, aborting...
2018/11/26 16:00:08 /usr/local/bin/packer: plugin process exited
2018/11/26 16:00:08 [INFO] (telemetry) ending amazon-ebs
2018/11/26 16:00:08 ui error: Build 'amazon-ebs' errored: unexpected EOF
2018/11/26 16:00:08 Builds completed. Waiting on interrupt barrier...
2018/11/26 16:00:08 machine readable: error-count []string{"1"}
Build 'amazon-ebs' errored: unexpected EOF

2018/11/26 16:00:08 ui error:
==> Some builds didn't complete successfully and had errors:
2018/11/26 16:00:08 machine readable: amazon-ebs,error []string{"unexpected EOF"}
2018/11/26 16:00:08 ui error: --> amazon-ebs: unexpected EOF
==> Some builds didn't complete successfully and had errors:
==> Builds finished but no artifacts were created.
--> amazon-ebs: unexpected EOF
2018/11/26 16:00:08 [INFO] (telemetry) Finalizing.

==> Builds finished but no artifacts were created.
2018/11/26 16:00:10 waiting for all plugin processes to complete...
2018/11/26 16:00:10 /usr/local/bin/packer: plugin process exited
SwampDragons commented 5 years ago

Does this happen only with the Powershell provisioner or with others as well?

SwampDragons commented 5 years ago

And what happens if you use the option valid_exit_codes?

nebffa commented 5 years ago

I think it might be an issue with the winrm communicator rather than the PowerShell provisioner. The reason I say this is because while I've made this issue about the Chef provisioner, I've noticed this happening before with the PowerShell provisioner. The thing that both of those had in common was the winrm communicator (and Windows, of course). Both times, an exit code of 0 would be returned early despite the provisioning steps not doing what was claimed.

On Tue, 27 Nov 2018 at 08:55, Megan Marsh notifications@github.com wrote:

And what happens if you use the option valid_exit_codes https://www.packer.io/docs/provisioners/powershell.html#valid_exit_codes ?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/hashicorp/packer/issues/7039#issuecomment-441813610, or mute the thread https://github.com/notifications/unsubscribe-auth/AEQWSCfoQELbKSUNkrg9-n9I3DI-dKBnks5uzGNggaJpZM4YyXe6 .

--

Ben Lucato

Phone: +61 400 159 632 | Email: ben.lucato@gmail.com

SwampDragons commented 5 years ago

Okay, thanks. You're right; there's a good chance that this is because winrm is trying to run the provisioner before the windows vm is fully up after it boots, which would explain why it happens on the first provisioner and not subsequent ones.

SwampDragons commented 5 years ago

I'm attaching an osx build of packer with the patch linked in #7052 applied; can you let me know if this solves your issue?

packer.zip

nebffa commented 5 years ago

Hey Megan,

Unfortunately I don't have the time to go back and work on this issue - I'd love to help you debug it but at this point I've been moved on to other tasks and the workaround with a sleep is 'good enough' for now. Sorry :(

On Thu, 29 Nov 2018 at 11:15, Megan Marsh notifications@github.com wrote:

I'm attaching an osx build of packer with the patch linked in #7052 https://github.com/hashicorp/packer/pull/7052 applied; can you let me know if this solves your issue?

packer.zip https://github.com/hashicorp/packer/files/2627053/packer.zip

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/hashicorp/packer/issues/7039#issuecomment-442656076, or mute the thread https://github.com/notifications/unsubscribe-auth/AEQWSLEaUo2KnG3aj-OqryqqPHrBBT52ks5uzycPgaJpZM4YyXe6 .

--

Ben Lucato

Phone: +61 400 159 632 | Email: ben.lucato@gmail.com

SwampDragons commented 5 years ago

That's fine, but given that the sleep is a viable workaround I'm probably going to just have to set this issue aside and work on things that don't have workarounds then. Thanks for reporting.

ghost commented 4 years ago

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.