search

packer-community / packer-windows-plugins

A suite of Packer plugins for provisioning Windows machines
112 stars 20 forks source link

Powershell provisioner not executing scripts correctly #26

Closed mefellows closed 9 years ago

mefellows commented 9 years ago

The powershell provisioner is not behaving in the latest release, all scripts finish with '0 bytes written for' notice. It appears to be unrelated to the restart-windows provisioner as tested by not using it in a packer run.

Example output:

2015/02/11 13:55:07 ui: ==> devbox-vbox: Provisioning with Powershell...
2015/02/11 13:55:07 ui: ==> devbox-vbox: Provisioning with shell script: ./scripts/openssh.ps1
2015/02/11 13:55:07 packer-provisioner-powershell: 2015/02/11 13:55:07 Opening ./scripts/openssh.ps1 for reading
2015/02/11 13:55:07 packer-provisioner-powershell: 2015/02/11 13:55:07 [INFO] 4265 bytes written for 'uploadData'
2015/02/11 13:55:07 [INFO] 4265 bytes written for 'uploadData'
2015/02/11 13:55:15 packer-builder-virtualbox-windows-ovf: 2015/02/11 13:55:15 starting remote command: powershell.exe -EncodedCommand ewB7AC4AUABhAHQAaAB9AH0A
2015/02/11 13:55:16 packer-builder-virtualbox-windows-ovf: 2015/02/11 13:55:16 [INFO] RPC endpoint: Communicator ended with: 0
2015/02/11 13:55:16 [INFO] 0 bytes written for 'stderr'
2015/02/11 13:55:16 [INFO] 0 bytes written for 'stdout'
2015/02/11 13:55:16 [INFO] RPC client: Communicator ended with: 0
2015/02/11 13:55:16 [INFO] RPC endpoint: Communicator ended with: 0
2015/02/11 13:55:16 packer-provisioner-powershell: 2015/02/11 13:55:16 [INFO] RPC client: Communicator ended with: 0
2015/02/11 13:55:16 packer-provisioner-powershell: 2015/02/11 13:55:16 [INFO] 0 bytes written for 'stderr'
2015/02/11 13:55:16 packer-provisioner-powershell: 2015/02/11 13:55:16 [INFO] 0 bytes written for 'stdout'
2015/02/11 13:55:16 ui: ==> devbox-vbox: Provisioning with shell script: ./scripts/provision.ps1
2015/02/11 13:55:16 packer-provisioner-powershell: 2015/02/11 13:55:16 Opening ./scripts/provision.ps1 for reading
2015/02/11 13:55:16 [INFO] 1208 bytes written for 'uploadData'
2015/02/11 13:55:16 packer-provisioner-powershell: 2015/02/11 13:55:16 [INFO] 1208 bytes written for 'uploadData'
2015/02/11 13:55:24 packer-builder-virtualbox-windows-ovf: 2015/02/11 13:55:24 starting remote command: powershell.exe -EncodedCommand ewB7AC4AUABhAHQAaAB9AH0A
2015/02/11 13:55:25 packer-builder-virtualbox-windows-ovf: 2015/02/11 13:55:25 [INFO] RPC endpoint: Communicator ended with: 0
2015/02/11 13:55:25 [INFO] 0 bytes written for 'stderr'
2015/02/11 13:55:25 [INFO] 0 bytes written for 'stdout'
2015/02/11 13:55:25 [INFO] RPC client: Communicator ended with: 0
2015/02/11 13:55:25 [INFO] RPC endpoint: Communicator ended with: 0
2015/02/11 13:55:25 packer-provisioner-powershell: 2015/02/11 13:55:25 [INFO] RPC client: Communicator ended with: 0
2015/02/11 13:55:25 packer-provisioner-powershell: 2015/02/11 13:55:25 [INFO] 0 bytes written for 'stderr'
2015/02/11 13:55:25 packer-provisioner-powershell: 2015/02/11 13:55:25 [INFO] 0 bytes written for 'stdout'
2015/02/11 13:55:25 ui: ==> devbox-vbox: Provisioning with windows-shell...
2015/02/11 13:55:25 ui: ==> devbox-vbox: Provisioning with shell script: ./scripts/rsync.bat
2015/02/11 13:55:25 packer-provisioner-windows-shell: 2015/02/11 13:55:25 Opening ./scripts/rsync.bat for reading
2015/02/11 13:55:25 [INFO] 886 bytes written for 'uploadData'
2015/02/11 13:55:25 packer-provisioner-windows-shell: 2015/02/11 13:55:25 [INFO] 886 bytes written for 'uploadData'
2015/02/11 13:55:32 packer-builder-virtualbox-windows-ovf: 2015/02/11 13:55:32 starting remote command: set "PACKER_BUILDER_TYPE=virtualbox-windows-ovf" && set "PACKER_BUILD_NAME=devbox-vbox" && "c:/Windows/Temp/script.bat"
2015/02/11 13:55:33 ui:     devbox-vbox:
2015/02/11 13:55:33 ui:     devbox-vbox: C:\Users\vagrant>rem install rsync
2015/02/11 13:55:33 ui:     devbox-vbox:
mefellows commented 9 years ago

Tracked the issue to d875f4b5f2f999cebdd55bf496f844580227465e. Looks like c.timeout is never properly initialised. Updated and corresponding test case to follow.

mefellows commented 9 years ago

Issue closed and update released.

dylanmei commented 9 years ago

(Put my comment in the wrong place)

There's a "connect" timeout that we get from the configuration. This is used from New when we make our first request. Individual commands should not timeout, or should run a long time (such as when processing Windows updates).

Correct me if I'm wrong, but I if you "persist" the timeout from New and use it in subsequent commands, what you are saying is the builder's start_timeout should be applied to all commands.

mefellows commented 9 years ago

You are correct, actually.

With some of my testing I had assumed it was actually the same thing applied at the command level - if the operation did not start within that time then it was considered a timeout.

As per line 1048 of http://www.dmtf.org/sites/default/files/standards/documents/DSP0226_1.0.0.pdf it actually is the operation time, BUT, measured from the time the request started to the time a response is generated (not until it is actually finished).

So, an operation could take 24 hours but if the timeout was set to 5m and a response was generated straight away (e.g. with a Write-Host "Starting long process"), it would never fail.

I suggest perhaps creating a separate configuration parameter operation_timeout that is used for this purpose and defaults to the previous value of time.Minute * 120.

dylanmei commented 9 years ago

I think in the ssh provisioner it would just run indefinitely. That's pretty much what I was going for with 120m. Can we get this effect without adding an operation_timeout?

mefellows commented 9 years ago

Fair enough. I guess until there is a need we should keep it simple. I'll revert the commit.

dylanmei commented 9 years ago 
R6.1-4: If the wsman:OperationTimeout element is omitted, the service may interpret this omission as an instruction to block indefinitely until a response is available, or it may impose a default timeout.

Hate how that's so open to interpretation! 120m is such a magical value. But getting kicked out of a big Windows update is a bummer. Won't be surprised to see us revisit this.

mefellows commented 9 years ago

sigh. Better to have some control I agree.

mefellows commented 9 years ago

So, yeah, we need to revisit (see #44). Thoughts? Currently, we have a few options:

  1. Increase the arbitrary timeout to some larger number that WinRM accepts
  2. Parameterize the value
  3. Come up with a new approach

Having had a bit of a think, I'm currently in favour with the former, as parameterising this will be a bit of a pain in the butt and exposes some low level things which arguably should be hidden from the end user.

dylanmei commented 9 years ago

Until the day the ssh communicator imposes a timeout, the intent is to run forever and never timeout. I am not excited about adding a windows-/winrm-only configuration here. For my money, in this space, 24h pretty close to forever.