v9.1.0.0p1-Beta scp behaviour change breaks packer #2018

rgl · 2022-12-17T23:23:26Z

Prerequisites

Write a descriptive title.
Make sure you are able to repro it on the latest version
Search the existing issues.

Steps to reproduce

use packer to provision a windows machine that has Win32-OpenSSH v9.1.0.0p1-Beta installed.
configure the packer template to use scp, e.g.:

  communicator             = "ssh"
  ssh_username             = "vagrant"
  ssh_password             = "vagrant"
  ssh_timeout              = "4h"
  ssh_file_transfer_method = "scp" # NB scp is the default.

run packer to provision the windows machine

FWIW, we can workaround this in our packer template with ssh_file_transfer_method = "sftp", but that does not seem to be the correct way of handling this.

Expected behavior

Expected scp to work in packer.

Actual behavior

The packer output shows:

==> qemu.windows-2022-amd64: Waiting for SSH to become available...
==> qemu.windows-2022-amd64: Connected to SSH!
==> qemu.windows-2022-amd64: Provisioning with Powershell...
==> qemu.windows-2022-amd64: Provisioning with powershell script: disable-windows-updates.ps1
==> qemu.windows-2022-amd64: Error processing command: Error uploading ps script containing env vars: Process exited with status 1
==> qemu.windows-2022-amd64: Step "StepProvision" failed, aborting...
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "StepConnect"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepWaitGuestAddress"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepTypeBootCommand"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepConfigureQMP"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepRun"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepPrepareEfivars"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepConfigureVNC"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepPortForward"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "StepHTTPServer"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepHTTPIPDiscover"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepResizeDisk"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepCopyDisk"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepCreateDisk"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "StepCreateCD"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "StepCreateFloppy"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepCreatevTPM"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "stepPrepareOutputDir"
==> qemu.windows-2022-amd64: aborted: skipping cleanup of step "StepDownload"
Build 'qemu.windows-2022-amd64' errored after 10 minutes 59 seconds: Error processing command: Error uploading ps script containing env vars: Process exited with status 1

The packer logs show:

2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] Opening new ssh session
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] Starting remote scp process:  scp -vt c:/Windows/Temp
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] Started SCP session, beginning transfers...
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] Copying input data into temporary file so we can read the length
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] scp: Uploading packer-ps-env-vars-639e4af1-37d0-609c-2d47-6651b5f3cd0f.ps1: perms=C0644 size=0
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] SCP session complete, closing stdin pipe.
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] Waiting for SSH session to complete.
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] scp stderr (length 118): Sink: C0644 0 packer-ps-env-vars-639e4af1-37d0-609c-2d47-6651b5f3cd0f.ps1
2022/12/17 23:04:29 packer-builder-qemu plugin: scp.exe: debug1: fd 0 clearing O_NONBLOCK
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] non-zero exit status: 1, Process exited with status 1
2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] scp output: �scp: c:/Windows/Temp/packer-ps-env-vars-639e4af1-37d0-609c-2d47-6651b5f3cd0f.ps1: add_mark_of_web failed
2022/12/17 23:04:29 packer-builder-qemu plugin: 
2022/12/17 23:04:29 packer-provisioner-powershell plugin: Retryable error: Error uploading ps script containing env vars: Process exited with status 1
2022/12/17 23:04:31 packer-provisioner-powershell plugin: [INFO] 0 bytes written for 'uploadData'
2022/12/17 23:04:31 [INFO] 0 bytes written for 'uploadData'

I think this is due to extraneous output now being returned by sshd:

scp output: �scp: c:/Windows/Temp/packer-ps-env-vars-639e4af1-37d0-609c-2d47-6651b5f3cd0f.ps1: add_mark_of_web failed

This seems related to:

Is there a way to disable the add_mark_of_web feature?

Error details

No response

Environment data

v9.1.0.0p1-Beta

Version

v9.1.0.0p1-Beta

Visuals

No response

The text was updated successfully, but these errors were encountered:

tgauth · 2022-12-19T19:05:49Z

There is no way to disable the mark of the web, but it is intended to be a best effort attempt, so note_err only prints add_mark_of_web failed in verbose mode (-v). And even with the logging via note_err, the file transfer should still proceed. Will further investigate the SCP logging for mark of the web, so verbose mode does not limit SCP working in Packer, but have two initial questions:

2022/12/17 23:04:29 packer-builder-qemu plugin: [DEBUG] Starting remote scp process: scp -vt c:/Windows/Temp

Since Packer seems to be using verbose mode - is this set automatically by Packer, or is there a way to override?

FWIW, we can workaround this in our packer template with ssh_file_transfer_method = "sftp", but that does not seem to be the correct way of handling this.

Are there any messages in the SFTP logs regarding add_mark_of_web? Curious if it's failing silently, as intended, or due to the differences in implementation between SCP and SFTP. For example, in the case of a file being pushed from the client to the server, SCP is always expected to be unable to add the mark of the web, but that's not the case for SFTP.

rgl · 2022-12-19T20:20:48Z

I'm not sure what is setting the ssh/scp verbose mode, so I've created a simple go program at https://github.com/rgl/use-packer-scp that uses the internal packer scp client to reproduce the problem, and it also behaves like in packer, so we can now easily reproduce the problem.

This is what it returns, which is the same as my initial message:

2022/12/19 20:12:34 [DEBUG] Copying input data into temporary file so we can read the length
2022/12/19 20:12:34 [DEBUG] scp: Uploading packer-test.txt: perms=C0644 size=5
2022/12/19 20:12:34 [DEBUG] SCP session complete, closing stdin pipe.
2022/12/19 20:12:34 [DEBUG] Waiting for SSH session to complete.
2022/12/19 20:12:34 [DEBUG] scp stderr (length 74): Sink: C0644 5 packer-test.txt
scp.exe: debug1: fd 0 clearing O_NONBLOCK
2022/12/19 20:12:34 [DEBUG] non-zero exit status: 1, Process exited with status 1
2022/12/19 20:12:34 [DEBUG] scp output: �scp: C:/packer-test.txt: add_mark_of_web failed

2022/12/19 20:12:39 failed to upload file: Process exited with status 1

Please note that the file is successfully uploaded to the remote machine, but there is something checked by the packer ssh/scp communicator that breaks its expectation.

lbajolet-hashicorp · 2023-01-06T15:19:35Z

Hi, Packer dev here.

We've had a report from another user hitting this same problem, they opened an issue in the Amazon plugin for Packer: hashicorp/packer-plugin-amazon#305

From what I gather here, the logs aren't the problem, we don't rely on this to determine if the transfer was successful or not, but on the return code of the command, if non-zero, we assume there's been an error, and fail the step.

Packer invokes scp with the -vt options, hence why you can see the log in the output (when you set PACKER_LOG for more verbosity in your own shell).
You can see where the code is set here: https://github.com/hashicorp/packer-plugin-sdk/blob/main/sdk-internals/communicator/ssh/communicator.go#L673

The file upload code itself being here: https://github.com/hashicorp/packer-plugin-sdk/blob/main/sdk-internals/communicator/ssh/communicator.go#L880

Now looking at the code, this does not seem to be a case of failure, is it? Is there a reason why this implementation of scp returns a non-zero code if the transfer succeeds?
Also pardon my ignorance as I've just today learnt about MOTW, if the attribute is not set, I assume Windows will reject the execution of the script we upload, is that right? Any way we can fix this? I fear this might become a problem for all our users that build Windows images with Packer.

tgauth · 2023-01-06T15:51:36Z

TLDR; the open PR will address these concerns, as MOTW will no longer affect the SCP exit code status in verbose mode (-v).

Now looking at the code, this does not seem to be a case of failure, is it? Is there a reason why this implementation of scp returns a non-zero code if the transfer succeeds?

Initially, it was a matter of being able to print the debug message, which was only to be done in verbose mode. Since it is currently being printed using note_err, it changes the exit code status. However, if SCP is run normally (without -v), the exit code status is normal. The open PR will remedy the inconsistent exit code behavior between verbose mode and regular mode.

Also pardon my ignorance as I've just today learnt about MOTW, if the attribute is not set, I assume Windows will reject the execution of the script we upload, is that right? Any way we can fix this? I fear this might become a problem for all our users that build Windows images with Packer.

If I understand the question correctly - no, Windows should not prevent a script from being executed if MOTW is not present. MOTW is intended to be a defense-in-depth security feature, which is why we make a best effort attempt to include it, but if we cannot, then the file transfer still proceeds. Windows will look for the MOTW, but it will not make any assumptions about the file, if it is not there. Also, in the case that the MOTW is there, and Windows blocks the file, simply run the Unblock-File cmdlet in PowerShell.

lbajolet-hashicorp · 2023-01-06T16:26:20Z

Perfect, thanks for the speedy response, much appreciated!

Regarding the PR, do you think this will get backported and released in an upcoming release? In the meantime it seems the sftp workaround works so I don't think this is a major concern.
We'll add some documentation in our docs so users know this can be a problem and what to do when it happens.

tgauth · 2023-01-09T20:04:15Z

We don't typically backport bug fixes for beta releases, but yes this will be fixed in the next release - and thanks!

rgl · 2023-03-05T18:55:42Z

This is now working with https://github.com/PowerShell/Win32-OpenSSH/releases/tag/v9.2.0.0p1-Beta

Thank you!

I'm closing this issue since its now fixed.

tgauth added Issue-Bug Area-SCP Known-workaround Investigate labels Dec 19, 2022

tgauth self-assigned this Dec 19, 2022

tgauth mentioned this issue Dec 19, 2022

limit scp mark of the web attempt to pull case and change logging to … PowerShell/openssh-portable#652

Merged

rgl closed this as completed Mar 5, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

v9.1.0.0p1-Beta scp behaviour change breaks packer #2018

v9.1.0.0p1-Beta scp behaviour change breaks packer #2018

rgl commented Dec 17, 2022 •

edited

Loading

tgauth commented Dec 19, 2022 •

edited

Loading

rgl commented Dec 19, 2022 •

edited

Loading

lbajolet-hashicorp commented Jan 6, 2023

tgauth commented Jan 6, 2023 •

edited

Loading

lbajolet-hashicorp commented Jan 6, 2023

tgauth commented Jan 9, 2023

rgl commented Mar 5, 2023

v9.1.0.0p1-Beta scp behaviour change breaks packer #2018

v9.1.0.0p1-Beta scp behaviour change breaks packer #2018

Comments

rgl commented Dec 17, 2022 • edited Loading

Prerequisites

Steps to reproduce

Expected behavior

Actual behavior

Error details

Environment data

Version

Visuals

tgauth commented Dec 19, 2022 • edited Loading

rgl commented Dec 19, 2022 • edited Loading

lbajolet-hashicorp commented Jan 6, 2023

tgauth commented Jan 6, 2023 • edited Loading

lbajolet-hashicorp commented Jan 6, 2023

tgauth commented Jan 9, 2023

rgl commented Mar 5, 2023

rgl commented Dec 17, 2022 •

edited

Loading

tgauth commented Dec 19, 2022 •

edited

Loading

rgl commented Dec 19, 2022 •

edited

Loading

tgauth commented Jan 6, 2023 •

edited

Loading