Packer: Packer cannot copy scripts to VMs `/tmp` folder

[Wasapl]

Packer cannot scp script to /tmp folder during provision phase.
Packer print in stdout:

==> hyperv-iso: Provisioning with shell script: scripts/basicconfig.sh

But packer fails to copy basicconfig.sh into VM.
Next line shows up in log file: "scp output: NUL scp: Broken pipe." Then packer tries to scp again and again until timeout. After timeout it cleans up and prints error:

 hyperv-iso: Retryable error: Error uploading script: Process exited with status 1

Here is list of files in VM's /tmp directory:

vagrant@ubuntu:/tmp$ ls -ltra
total 28
drwxr-xr-x 22 root     root     4096 Apr 22 21:28 ..
drwxrwxrwt  2 root     root     4096 Apr 22 21:31 .X11-unix
drwxrwxrwt  2 root     root     4096 Apr 22 21:31 .XIM-unix
drwxrwxrwt  2 root     root     4096 Apr 22 21:31 .Test-unix
drwxrwxrwt  2 root     root     4096 Apr 22 21:31 .ICE-unix
drwxrwxrwt  2 root     root     4096 Apr 22 21:31 .font-unix
-rw-rw-r--  1 vagrant vagrant    0 Apr 22 21:31 script_2399.sh
drwxrwxrwt  7 root     root     4096 Apr 22 21:34 .
vagrant@ubuntu:/tmp$

/tmp is writtable, with sufficient amount of free memory.
If I run command scp basicconfig.sh vagrant@<IP>:/tmp manually in other shell it works like a charm.

• Packer version 1.2.2, reproducible with both builders hyperv-iso and hyperv-vmcx.
• Host platform Windows Server 2016
• Debug log https://gist.github.com/Wasapl/9e871d22f88b9bd5380ab65daa6e995d
• The _simplest example template and scripts_ needed to reproduce the bug: https://gist.github.com/Wasapl/d413b4506e497c68da66843b9ab131bc contents of provisioned scripts are irrelevant.

[krisztianloki]

This is a regression from 1.2.1
It seems to have something to do with windows-unix line ending conversion; setting the binary option to True fixes the upload problem in 1.2.2.

[Wasapl]

Thanks, @krisztianloki ! Downgraded to 1.2.1 and now it works.

[SwampDragons]

@krisztianloki Thanks for the workaround -- do you have any more details on the specifics of the issue or ideas on how we can fix it for 1.2.3?

[krisztianloki]

I think that it has nothing to do with any specific builder; it happened to me with the virtualbox-ovf builder.
Here is the relevant part from the debug log:
>
2018/04/23 10:55:45 [INFO] (telemetry) Starting provisioner shell
2018/04/23 10:55:45 ui: ==> virtualbox-ovf: Provisioning with shell script: scripts/create_rootdisk
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 Opening scripts/create_rootdisk for reading
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [DEBUG] Opening new ssh session
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [DEBUG] starting remote command: test -d "/tmp/script_9991.sh"
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [INFO] 5903 bytes written for 'uploadData'
2018/04/23 10:55:45 [INFO] 5903 bytes written for 'uploadData'
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [ERROR] Remote command exited with '1': test -d "/tmp/script_9991.sh"
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [DEBUG] Opening new ssh session
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [DEBUG] Starting remote scp process: scp -vt /tmp
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [DEBUG] Started SCP session, beginning transfers...
2018/04/23 10:55:45 packer.exe: 2018/04/23 10:55:45 [DEBUG] scp: Uploading script_9991.sh: perms=C0666 size=6112
2018/04/23 10:55:46 packer.exe: 2018/04/23 10:55:46 [DEBUG] SCP session complete, closing stdin pipe.
2018/04/23 10:55:46 packer.exe: 2018/04/23 10:55:46 [DEBUG] Waiting for SSH session to complete.
2018/04/23 10:55:46 packer.exe: 2018/04/23 10:55:46 [DEBUG] non-zero exit status: 1
2018/04/23 10:55:46 packer.exe: 2018/04/23 10:55:46 [DEBUG] scp output: ☺scp: Broken pipe
2018/04/23 10:55:46 packer.exe: 2018/04/23 10:55:46 Retryable error: Error uploading script: Process exited with status 1
>
The real size of the file is 6112 bytes with windows line-ending, packer converts it to linux format and the result is a 5903 byte long file. But this information gets lost somewhere and scp thinks it has to upload the original size. The difference between 6112 and 5903 is exactly the number of lines in the file.

I have no idea how to fix it, I am not familiar with Go... I was looking at the code trying to figure out something but got lost...

[breisig]

I just tried with packer 1.2.3 and I am still getting the same issue with virtualbox-ovf builder

[Wasapl]

I tried to reproduce this with packer 1.2.3 with hyperv-vmcx builder and it worked fine:

2018/04/26 07:43:52 ui: ==> hyperv-vmcx: Provisioning with shell script: scripts/basicconfig.sh
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 Opening scripts/basicconfig.sh for reading
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] Opening new ssh session
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [INFO] 4313 bytes written for 'uploadData'
2018/04/26 07:43:52 [INFO] 4313 bytes written for 'uploadData'
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] Starting remote scp process:  scp -vt /tmp
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] Started SCP session, beginning transfers...
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] scp: Uploading script_7190.sh: perms=C0666 size=4312
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] SCP session complete, closing stdin pipe.
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] Waiting for SSH session to complete.
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] scp stderr (length 32): Sink: C0666 4312 script_7190.sh
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] Opening new ssh session
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] starting remote command: chmod 0755 /tmp/script_7190.sh
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [INFO] RPC endpoint: Communicator ended with: 0
2018/04/26 07:43:52 [INFO] RPC client: Communicator ended with: 0
2018/04/26 07:43:52 [INFO] RPC endpoint: Communicator ended with: 0
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [INFO] RPC client: Communicator ended with: 0
2018/04/26 07:43:52 packer.exe: 2018/04/26 07:43:52 [DEBUG] Opening new ssh session

I believe issue fixed for hyperv-vmcx.

[SwampDragons]

@breisig can I have debug logs from your failed build? And a repro case, if you've got a simple one?

[andrewsav-datacom]

@SwampDragons where you able to reproduce this one? I'm also affected, and I can try and put a repro together if you still have not got one.

[breisig]

@SwampDragons Here's the log output using virtualbox-ovf on packer 1.2.3 : https://pastebin.com/siFdFTwA

[SwampDragons]

@andrewsav-datacom I'd love a repro, thanks

[andrewsav-datacom]

@SwampDragons ubuntu-1604.zip Here is the repo for VirtualBox/VmWare , the logs are inside.

[SwampDragons]

and @andrewsav-datacom you're also on a windows host machine?

[AndrewSav]

@SwampDragons yes!

[breisig]

Based on the logs, it looks like it's happening with packer running on windows.

[SwampDragons]

okay; I am able to repro with @andrewsav-datacom 's case, but I'm not able to fix the issue by adding the "binary" flag as @krisztianloki suggested. Downgrading to Packer 1.2.1 did solve it though, so I am confident this is the same bug. I'm going to start combing through the commit history and building/testing on commits I think could be related.

[SwampDragons]

andddd the culprit is: c5e0710a9a1c9d99a8241bc10ec21f3766e3719c

I'll start looking at fixes tomorrow.

[SwampDragons]

@andrewsav-datacom I have a patch that seems to resolve the issue with your use case: https://github.com/hashicorp/packer/pull/6239. A windows-build of said patch is attached.
packer.zip . Can you and @breisig test with this patch and let me know if it resolves your issues? I wonder if something in the act of stating the file is causing weirdness with the endings. I'm still going to dig in a bit further but would like confirmation that I'm on the right track.

[breisig]

@SwampDragons Thanks, I'll test it out right away.

[breisig]

@SwampDragons Perfect! Your patched build is working for me.

[SwampDragons]

Glad to hear it! I'll make sure this is fixed in one capacity or another in the next release.

[hegyre]

Hello @SwampDragons ,

Had the exact same issue with Packer 1.2.2 and 1.2.3, and your dev build fixed the issue for me as well ;)

[hegyre]

An extra note:
As @krisztianloki said, It had to do with EOL convertion.
I've just converted myself my .sh script from Windows EOL to Unix EOL (With Notepad++, I'm on Windows)
Then tested with Packer 1.2.3, and it works fine

[SwampDragons]

yeah, I saw that... I'm just really confused about how stating the file could have messed with the EOL stuff. I'll dig into it later. For now I'm glad you have a workaround.

[krisztianloki]

I think the EOL conversion happens as part of the uploading. And if the conversion is not an identity conversion, then the size of the file will change. I assume that stat() happens before the conversion; that is why the upload fails with size mismatch.

[SwampDragons]

You're right; it's not the stat, it's the upload code. I've merged the fix, so I'm going to close this issue. The fix will be part of the next release.

[lmayorga1980]

Same issue here using git bash on Windows.

[staticfrost]

When does the patch make it in to the next release?

[AndrewSav]

@staticfrost, most likely it is _already_ in the next release. All we need to do is to wait for that release to come out.

Many companies do not announce the firm release dates, and do releases when they are ready. Having said that, you can give a feel for their usual cadence here: https://github.com/hashicorp/packer/releases

Also the label on this issue says upcoming-05-2018-ish which I read as that it's likely to be before the end of June.

[SwampDragons]

That's correct. We'll be releasing 1.3.0 either at the end of this week or the beginning of next.

[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.