Packer: The second file builder in a template causes Packer to freeze

[quater]

This problem was introduced with Packer v1.3.0 since it is working with v1.2.5!

I encounter this issue when I use the File provisioner along with the LXD builder. I have not tested it in combination with other builders and I therefore don't know whether it is a generic problem.

The log output is attached but it is only of limited help since Packer freezes all together and no further logs are written.

• Packer version from packer version:

Packer v1.3.0

• Host platform:

Distributor ID: Ubuntu
Description:    Ubuntu 18.04.1 LTS
Release:    18.04
Codename:   bionic

• Debug log output from PACKER_LOG=1 packer build template.json:
  https://gist.github.com/quater/79f36f7f36d8906f1da6c6b86d0bd154

• The _simplest example template and scripts_ needed to reproduce the bug.
  https://gist.github.com/quater/31d3afd3e81a8d62e3202b45043e87bc

[repl-mathieu-fenniak]

I can confirm that I have run into the same issue when attempting to upgrade from Packer 1.2.5 to 1.3.0. Just came here looking for a bug report. 👍 Thanks for documenting it @quater.

[SwampDragons]

@repl-mathieu-fenniak is your issue also specific to the LXD builder?

[SwampDragons]

I'm able to reproduce with aws and docker; this is not an LXD-specific bug.

[SwampDragons]

The fix is in PR #6698; Here are some builds of that branch:

linux:
packer.zip

osx:
packer.zip

windows:
packer.zip

[SwampDragons]

This issue is closed by #6698 but I suspect a lot of traffic is going to come to this issue in the next week or two so I'm going to leave it open to make it easier for users to find.

[queeno]

I confirm I had the same issue - working in 1.2.5 and broken 1.3.0. I also came here looking for a bug report.

Since this bug significantly affects the packer functionality and I expect many people will spend their time investigating, would it be possible either to release 1.3.1 quickly or remove 1.3.0? Thanks!

[djsly]

Same here spent half a day debugging...

we are using packer light from docker hub and ended up getting 1.3.0 magically overnight.

[dstarmanhr]

Yep, build with fix works on aws builder. A lot of people will hit this bug, an early 1.3.1 or pulling 1.3.0 would be a good solution as @queeno suggested...

[SwampDragons]

Yeah we're definitely going to do an early 1.3.1. Going to wait through the end of this week to make sure that there are no other critical regressions we haven't heard about next and do 1.3.1 next week.

[johnpekcan]

I'm still experiencing this with v 1.3.1

==> openstack: Connected to WinRM!
2018/09/18 05:22:27 packer: 2018/09/18 05:22:27 Running the provision hook
2018/09/18 05:22:27 [INFO] (telemetry) Starting provisioner file
==> openstack: Uploading scripts/foo/bar1.ps1 => c:\temp\Register-Machine.ps1
2018/09/18 05:22:27 packer: 2018/09/18 05:22:27 Uploading file to 'c:\temp\Register-Machine.ps1'
2018/09/18 05:22:27 [INFO] 3271 bytes written for 'uploadData'
2018/09/18 05:22:27 packer: 2018/09/18 05:22:27 [INFO] 3271 bytes written for 'uploadData'
1 items:  3.19 KiB / 3.19 KiB [===================================================================================================================================================================================================]
2018/09/18 05:22:31 packer: #< CLIXML
1 items:  3.19 KiB / 3.19 KiB [===================================================================================================================================================================================================$
2018/09/18 05:22:35 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><$S><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
1 items:  3.19 KiB / 3.19 KiB [================================================================================================================================================================================================] 7$
2018/09/18 05:22:35 [INFO] (telemetry) ending file
2018/09/18 05:22:35 [INFO] (telemetry) Starting provisioner file
==> openstack: Uploading scripts/foo/bar2.txt => c:\temp\bar2.txt
^C2018/09/18 05:29:54 Closing stdin because interrupt received.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 Stopping build: openstack
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 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><$S><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/09/18 05:29:54 Received interrupt signa$ (count: 1). Ignoring.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Received interrupt signal (count: 1). Ignoring.
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Cancelling the step runner...
2018/09/18 05:29:54 packer: 2018/09/18 05:29:54 Cancelling provisioning due to interrupt...
2018/09/18 05:29:54 Provisioner.Cancel err: unexpected EOF
2018/09/18 05:29:54 [INFO] (telemetry) ending file
2018/09/18 05:29:54 /usr/bin/packer: plugin process exited
==> openstack: Terminating the source server: aaf0e00c-cb4b-4614-b5b2-d02d1a45fd0c ...
2018/09/18 05:29:55 packer: 2018/09/18 05:29:55 Waiting for state to become: [DELETED]
2018/09/18 05:29:55 packer: 2018/09/18 05:29:55 Waiting for state to become: [DELETED] currently ACTIVE (0%!)(MISSING)
2018/09/18 05:29:57 packer: 2018/09/18 05:29:57 Waiting for state to become: [DELETED] currently ACTIVE (0%!)(MISSING)
2018/09/18 05:30:00 packer: 2018/09/18 05:30:00 Waiting for state to become: [DELETED] currently ACTIVE (0%!)(MISSING)
2018/09/18 05:30:02 packer: 2018/09/18 05:30:02 [INFO] 404 on ServerStateRefresh, returning DELETED
==> openstack: Deleting temporary keypair: packer_5ba08acd-cdcf-681c-0f64-2a4a89324ff5 ...
Build 'openstack' finished.
Cleanly cancelled builds after being interrupted.

[jpekcan@testbox packer]$ packer --version
1.3.1

Builder type: openstack

EDIT:
can confirm, if I combine my steps and upload the entire dir:

    "provisioners": [
        {
            "type": "file",
            "source": "scripts/foo/",
            "destination": "c:\\temp\\"
        },

I can continue building.

[azr]

Hello @johnpekcan, thanks for reporting, do you have a config file to reproduce ?

It worked fine for me with 3 file provisioners on GCP; I expect behaviour to be the same but I might be wrong.

Edit: Trying to have a repro on openstack in the meantime.

[johnpekcan]

Here is a very stripped down example I can reproduce with.

{
    "variables": {
        "username": "Administrator",
        "password": ""
    },
    "builders": [
        {
            "type": "openstack",
            "image_name": "windows-server-2016-gui-test",
            "source_image_name": "windows-server-2016-gui-latest",
            "domain_name": "development",
            "networks": "fe33ceae-4c5d-4233-88fa-0bcdd9b0a8ba",
            "flavor": "m4.xlarge",
            "communicator": "winrm",
            "winrm_username": "{{user `username`}}",
            "winrm_password": "{{user `password`}}",
            "winrm_port": "5985",
            "winrm_timeout": "12h",
            "user_data_file": "scripts/user_data.tpl"
        }
    ],
    "provisioners": [
        {
            "type": "file",
            "source": "scripts/octopus/Register-Machine.ps1",
            "destination": "c:\\temp\\Register-Machine.ps1"
        },
        {
            "type": "file",
            "source": "scripts/octopus/OctopusCert.txt",
            "destination": "c:\\temp\\OctopusCert.txt"
        },
        {
            "type": "powershell",
            "script": "scripts/_boxstarter.ps1"
        },
        {
            "type": "powershell",
            "environment_vars": [
                "WINRMPASS={{user `password`}}"
            ],
            "elevated_execute_command": "powershell -executionpolicy bypass \"& { if (Test-Path variable:global:ProgressPreference){$ProgressPreference='SilentlyContinue'}; . {{.Vars}}; &'Install-BoxstarterPackage -PackageName {{.Path}}'; exit $LastExitCode }\"",
            "scripts": [
                "scripts/06_octopus.ps1"
            ]
        }
    ]
}

    openstack: WinRM connected.
2018/09/18 21:24:59 packer: 2018/09/18 21:24:59 [INFO] command 'powershell.exe -EncodedCommand aQBmACAAKABUAGUAcwB0AC0AUABhAHQAaAAgAHYAYQByAGkAYQBiAGwAZQA6AGcAbABvAGIAYQBsADoAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAKQB7ACQAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAPQAnAFMAaQBsAGUAbgB0AGwAeQBDAG8AbgB0AGkAbgB1AGUAJwB9ADsAIABlAGMAaABvACAAIgBXAGkAbgBSAE0AIABjAG8AbgBuAGUAYwB0AGUAZAAuACIA' exited with code: 0
    openstack: #< CLIXML
    openstack: <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>
==> openstack: Connected to WinRM!
2018/09/18 21:24:59 packer: 2018/09/18 21:24:59 Connected to machine
2018/09/18 21:24:59 packer: 2018/09/18 21:24:59 Running the provision hook
2018/09/18 21:24:59 [INFO] (telemetry) Starting provisioner file
==> openstack: Uploading scripts/octopus/Register-Machine.ps1 => c:\temp\Register-Machine.ps1
2018/09/18 21:24:59 packer: 2018/09/18 21:24:59 Uploading file to 'c:\temp\Register-Machine.ps1'
2018/09/18 21:24:59 packer: 2018/09/18 21:24:59 [INFO] 3161 bytes written for 'uploadData'
2018/09/18 21:24:59 [INFO] 3161 bytes written for 'uploadData'
1 items:  3.09 KiB / 3.09 KiB [==============================================================================================================================================================================================================================================================================================]
2018/09/18 21:25:04 packer: #< CLIXML
1 items:  3.09 KiB / 3.09 KiB [==============================================================================================================================================================================================================================================================================================]
2018/09/18 21:25: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
2018/09/18 21:25:08 [INFO] (telemetry) ending file
2018/09/18 21:25:08 [INFO] (telemetry) Starting provisioner file
1 items:  3.09 KiB / 3.09 KiB [===========================================================================================================================================================================================================================================================================================] 8s
==> openstack: Uploading scripts/octopus/OctopusCert.txt => c:\temp\OctopusCert.txt
^C2018/09/18 21:34:24 Stopping build: openstack
2018/09/18 21:34:24 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/09/18 21:34:24 Received interrupt signal (count: 1). Ignoring.
2018/09/18 21:34:24 packer: 2018/09/18 21:34:24 Received interrupt signal (count: 1). Ignoring.
2018/09/18 21:34:24 packer: 2018/09/18 21:34:24 Received interrupt signal (count: 1). Ignoring.
2018/09/18 21:34:24 packer: 2018/09/18 21:34:24 Received interrupt signal (count: 1). Ignoring.
2018/09/18 21:34:24 packer: 2018/09/18 21:34:24 Received interrupt signal (count: 1). Ignoring.
2018/09/18 21:34:24 Closing stdin because interrupt received.
2018/09/18 21:34:24 packer: 2018/09/18 21:34:24 Cancelling the step runner...
2018/09/18 21:34:24 packer: 2018/09/18 21:34:24 Cancelling provisioning due to interrupt...
2018/09/18 21:34:24 Provisioner.Cancel err: unexpected EOF
2018/09/18 21:34:24 [INFO] (telemetry) ending file
==> openstack: Terminating the source server: 032d46b2-02e7-440e-a5cf-c62af96a9216 ...
2018/09/18 21:34:24 /usr/bin/packer: plugin process exited
2018/09/18 21:34:25 packer: 2018/09/18 21:34:25 Waiting for state to become: [DELETED]
2018/09/18 21:34:25 packer: 2018/09/18 21:34:25 Waiting for state to become: [DELETED] currently ACTIVE (0%!)(MISSING)
2018/09/18 21:34:27 packer: 2018/09/18 21:34:27 [INFO] 404 on ServerStateRefresh, returning DELETED
==> openstack: Deleting temporary keypair: packer_5ba16c11-c53b-6396-2e33-82187c7e17c2 ...
Build 'openstack' finished.
Cleanly cancelled builds after being interrupted.
2018/09/18 21:34:27 Build cancelled: openstack
2018/09/18 21:34:27 [INFO] (telemetry) ending openstack
2018/09/18 21:34:27 Builds completed. Waiting on interrupt barrier...
2018/09/18 21:34:27 [INFO] (telemetry) Finalizing.
2018/09/18 21:34:27 waiting for all plugin processes to complete...
2018/09/18 21:34:27 /usr/bin/packer: plugin process exited
2018/09/18 21:34:27 /usr/bin/packer: plugin process exited
2018/09/18 21:34:27 /usr/bin/packer: plugin process exited
2018/09/18 21:34:27 /usr/bin/packer: plugin process exited

[johnpekcan]

where use_data.tpl is the recommended winrm setup found in:
https://www.packer.io/intro/getting-started/build-image.html

[SwampDragons]

@azr is this related to #6788 and #6759?

[azr]

Yes, totally could be related; #6788 will fix a race condition that might cause a crash in case two threads start/end a progress bar at the same time.

Here's a build of master @johnpekcan, could you please tell us if that fixes it for you ??
packer_linux_amd64.zip

packer_darwin_amd64.zip

---

I'm currently adding more progress bar unit tests to see if I can trigger it, and to avoid future regression.

Race conditions are always a bit random and have the unwritten rule that they will never happen to author ( well in my experience ) .
I ran an bunch of aws-ebs-windows-2016/2012 builds that uploaded multiple files consecutively and haven't had any deadlock. ( before and after #6788)

My initial thought was that since the progress bar code is shared by all builders then everything should be the same, but with race conditions tiny timing differences will change everything; and it is very likely that timing will be different between builders and I have no means to test with openstack.

---

Edit: Yup found a bunch more !

[SwampDragons]

I believe this was closed by #6851; since we've had no more activity on this issue I'm going to close. Hopefully all of these race conditions will be gone in the v1.3.3 release this week.

[hashibot[bot]]

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.