Packer: Snapshot tagging timeout too short for encrypted volumes

Created on 28 Jun 2018  ·  17Comments  ·  Source: hashicorp/packer

Packer: v1.2.4
Host: Amazon Linux v1 (latest)

About 75% of the time I do a build, I get the below error. Rerunning the build eventually works. I get the error for multiple different applications but they all have similar packer configurations. I believe there is a race condition with the tagging of encrypted snapshots.

Of course, as soon as I turn on verbose packer logging, I get 2 builds to work in a row. I will provide verbose logs ASAP.

Log:

==> amazon-chroot: Unmounting the root device...
==> amazon-chroot: Detaching EBS volume...
==> amazon-chroot: Creating snapshot...
    amazon-chroot: Snapshot ID: snap-xxxxxxxxxxxxxxxxx
==> amazon-chroot: Registering the AMI...
==> amazon-chroot: AMI: ami-zzzzzzzz
==> amazon-chroot: Waiting for AMI to become ready...
==> amazon-chroot: Creating Encrypted AMI Copy
==> amazon-chroot: Copying AMI: us-east-1(ami-zzzzzzzz)
==> amazon-chroot: Encrypting with KMS Key ID: 99999999-9999-9999-9999-999999999999
==> amazon-chroot: Waiting for AMI copy to become ready...
==> amazon-chroot: Deregistering unencrypted AMI
==> amazon-chroot: Deleting unencrypted snapshots
    amazon-chroot: Deleting Snapshot ID: snap-xxxxxxxxxxxxxxxxx
==> amazon-chroot: Adding tags to AMI (ami-yyyyyyyy)...
==> amazon-chroot: Creating AMI tags
==> amazon-chroot: Creating snapshot tags
    amazon-chroot: Adding tag: "Name": "app-1530157884"
==> amazon-chroot: Error adding tags to Resources ([]*string{(*string)(0xc4204699c0)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
==> amazon-chroot:  status code: 400, request id: 88888888-8888-8888-8888-888888888888
==> amazon-chroot: Deregistering the AMI because cancellation or error...
==> amazon-chroot: Removing snapshot since we cancelled or halted...
==> amazon-chroot: Error: InvalidSnapshot.NotFound: The snapshot 'snap-xxxxxxxxxxxxxxxxx' does not exist.
==> amazon-chroot:  status code: 400, request id: 77777777-7777-7777-7777-777777777777
==> amazon-chroot: Deleting the created EBS volume...
Build 'amazon-chroot' errored: Error adding tags to Resources ([]*string{(*string)(0xc4204699c0)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
    status code: 400, request id: 88888888-8888-8888-8888-888888888888

==> Some builds didn't complete successfully and had errors:
--> amazon-chroot: Error adding tags to Resources ([]*string{(*string)(0xc4204699c0)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
    status code: 400, request id: 88888888-8888-8888-8888-888888888888

==> Builds finished but no artifacts were created.

Packer Config:

{
  "builders": [
    {
      "type": "amazon-chroot",
      "region": "us-east-1",
      "ami_name": "app-{{timestamp}}",
      "snapshot_tags": {
        "Name": "app-{{timestamp}}"
      },
      "source_ami": "ami-afd15ed0",
      "root_volume_size": 8,
      "ena_support": true,
      "encrypt_boot": true,
      "kms_key_id": "99999999-9999-9999-9999-999999999999"
    }
  ],
  "provisioners": [
    {
      "type": "shell",
      "script": "prepare.sh"
    },
    {
      "type": "file",
      "source": "yyyyyyyy",
      "destination": "zzzzzzzzz"
    },
    {
      "type": "shell",
      "script": "prebuild.sh"
    },
    {
      "type": "shell",
      "execute_command": "chmod +x {{ .Path }}; {{ .Vars }} sudo -u user {{ .Path }}",
      "script": "build.sh"
    }
  ],
  "post-processors": [
    {
      "type": "manifest",
      "output": "manifest.json",
      "strip_path": true
    },
    {
      "type": "shell-local",
      "script": "deploy.sh"
    }
  ]
}
bug buildeamazon
Source
picture fenichelar
👍2

Most helpful comment

Just tested and this will be fixed by #6332

picture mwhooker on 28 Jun 2018
🎉2

All 17 comments

Probably same issue as

https://github.com/hashicorp/packer/issues/6369

FrancescoFerro picture FrancescoFerro on 28 Jun 2018

+1

martoc picture martoc on 28 Jun 2018

@FrancescoFerro I suspect so! However, I have never had a snapshot not get tagged when the build exited successfully.

fenichelar picture fenichelar on 28 Jun 2018

Looks like we retry creating tags for only 2 min 30 seconds. I'm guessing that the encrypted snapshots take longer than that, and so we get the above error. Thanks for the report!

mwhooker picture mwhooker on 28 Jun 2018

Yeah, am able to reproduce by letting it only retry once. here are debug logs

2018/06/28 13:58:44 ui:     amazon-ebs: Adding tag: "Name": "app-1530219012"
    amazon-ebs: Adding tag: "Name": "app-1530219012"
2018/06/28 13:58:44 ui error: ==> amazon-ebs: Error adding tags to Resources ([]*string{(*string)(0xc420552440)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
==> amazon-ebs:     status code: 400, request id: f7256544-55bd-4fc6-9e1e-39dfc0b2ef4e
2018/06/28 13:58:44 ui: ==> amazon-ebs: Deregistering the AMI because cancellation or error...
==> amazon-ebs: Error adding tags to Resources ([]*string{(*string)(0xc420552440)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
==> amazon-ebs:     status code: 400, request id: f7256544-55bd-4fc6-9e1e-39dfc0b2ef4e
==> amazon-ebs: Deregistering the AMI because cancellation or error...
2018/06/28 13:58:45 ui: ==> amazon-ebs: Deregistering the AMI because cancellation or error...
==> amazon-ebs: Deregistering the AMI because cancellation or error...
2018/06/28 13:58:45 ui error: ==> amazon-ebs: Error deregistering AMI, may still be around: InvalidAMIID.Unavailable: The image ID 'ami-e2a0f89d' is no longer available
==> amazon-ebs:     status code: 400, request id: ea534a61-e2de-4894-a0c5-2076ef1647f0
==> amazon-ebs: Error deregistering AMI, may still be around: InvalidAMIID.Unavailable: The image ID 'ami-e2a0f89d' is no longer available
2018/06/28 13:58:45 ui: ==> amazon-ebs: Terminating the source AWS instance...
==> amazon-ebs:     status code: 400, request id: ea534a61-e2de-4894-a0c5-2076ef1647f0
==> amazon-ebs: Terminating the source AWS instance...
2018/06/28 13:58:46 packer: 2018/06/28 13:58:46 Waiting for state to become: terminated
2018/06/28 13:58:46 packer: 2018/06/28 13:58:46 Using 2s as polling delay (change with AWS_POLL_DELAY_SECONDS)
2018/06/28 13:58:46 packer: 2018/06/28 13:58:46 Allowing 300s to complete (change with AWS_TIMEOUT_SECONDS)
2018/06/28 13:58:52 ui: ==> amazon-ebs: Cleaning up any extra volumes...
==> amazon-ebs: Cleaning up any extra volumes...
2018/06/28 13:58:52 ui: ==> amazon-ebs: No volumes to clean up, skipping
==> amazon-ebs: No volumes to clean up, skipping
2018/06/28 13:58:52 ui: ==> amazon-ebs: Deleting temporary security group...
==> amazon-ebs: Deleting temporary security group...
==> amazon-ebs: Deleting temporary keypair...
2018/06/28 13:58:53 ui: ==> amazon-ebs: Deleting temporary keypair...
2018/06/28 13:58:53 [INFO] (telemetry) ending amazon-ebs
2018/06/28 13:58:53 ui error: Build 'amazon-ebs' errored: Error adding tags to Resources ([]*string{(*string)(0xc420552440)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
    status code: 400, request id: f7256544-55bd-4fc6-9e1e-39dfc0b2ef4e
2018/06/28 13:58:53 Builds completed. Waiting on interrupt barrier...
2018/06/28 13:58:53 machine readable: error-count []string{"1"}
2018/06/28 13:58:53 ui error:
==> Some builds didn't complete successfully and had errors:
2018/06/28 13:58:53 machine readable: amazon-ebs,error []string{"Error adding tags to Resources ([]*string{(*string)(0xc420552440)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid\n\tstatus code: 400, request id: f7256544-55bd-4fc6-9e1e-39dfc0b2ef4e"}
2018/06/28 13:58:53 ui error: --> amazon-ebs: Error adding tags to Resources ([]*string{(*string)(0xc420552440)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
    status code: 400, request id: f7256544-55bd-4fc6-9e1e-39dfc0b2ef4e
2018/06/28 13:58:53 ui:
==> Builds finished but no artifacts were created.
2018/06/28 13:58:53 [INFO] (telemetry) Finalizing.
Build 'amazon-ebs' errored: Error adding tags to Resources ([]*string{(*string)(0xc420552440)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
    status code: 400, request id: f7256544-55bd-4fc6-9e1e-39dfc0b2ef4e

==> Some builds didn't complete successfully and had errors:
--> amazon-ebs: Error adding tags to Resources ([]*string{(*string)(0xc420552440)}): InvalidParameterValue: Value ( null ) for parameter resourceId is invalid. Null/empty value for resourceId is invalid
    status code: 400, request id: f7256544-55bd-4fc6-9e1e-39dfc0b2ef4e

==> Builds finished but no artifacts were created.
2018/06/28 13:58:53 waiting for all plugin processes to complete...
2018/06/28 13:58:53 /Users/mwhooker/go/bin/packer: plugin process exited

I think if we find the right place to call https://docs.aws.amazon.com/sdk-for-go/api/service/ec2/#EC2.WaitUntilSnapshotCompleted we might have a solution for this. Otherwise we can bump the retry timeout

mwhooker picture mwhooker on 28 Jun 2018
👍1

Just tested and this will be fixed by #6332

mwhooker picture mwhooker on 28 Jun 2018
🎉2

In the mean time, am I correct in thinking that I can use AWS_TIMEOUT_SECONDS=600 packer build packer.json to increase the wait time?

fenichelar picture fenichelar on 28 Jun 2018

Also, is it 2 min 30 seconds of wait or 5 minutes (300 seconds).

fenichelar picture fenichelar on 28 Jun 2018

In the mean time, am I correct in thinking that I can use AWS_TIMEOUT_SECONDS=600 packer build packer.json to increase the wait time?

unfortunately no, this is a regrettable instance where we hardcoded the retry period

mwhooker picture mwhooker on 28 Jun 2018

:( well hopefully #6332 will be accepted soon and a new packer version release!

fenichelar picture fenichelar on 28 Jun 2018

@mwhooker This has become very problematic from a productivity stand point and is increasing the amount of money I have to spend on 🍺 for each new release. Is there anything I can do in the meantime?

fenichelar picture fenichelar on 2 Jul 2018

@fenichelar I usually recommend people build packer themselves with the patch applied if they need something before a release. I'm happy to make a build for you if you let me know your os and architecture. lmk!

mwhooker picture mwhooker on 2 Jul 2018

@mwhooker Thank you for the offer! Unless I run into a lot of problems, I'd love to build it myself. I ran the following:

mkdir -p $GOPATH/src/github.com/hashicorp && cd $_
git clone https://github.com/hashicorp/packer.git
cd packer
go get
make dev

and I get:

make: govendor: Command not found
make: *** [deps] Error 127

Is there something I am missing? I'm a Go virgin, sorry if this is a dumb question.

fenichelar picture fenichelar on 2 Jul 2018

@fenichelar I think you are just missing to add $GOPATH/bin to your PATH and everything should be fine.

rickard-von-essen picture rickard-von-essen on 2 Jul 2018

@rickard-von-essen you are correct!

fenichelar picture fenichelar on 2 Jul 2018

I had only added /usr/lib/golang/bin.

fenichelar picture fenichelar on 2 Jul 2018

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.

hashibot[bot] picture hashibot[bot] on 31 Mar 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

mwhooker picture mwhooker  ·  3Comments
jesse-c picture jesse-c  ·  3Comments
sourav82 picture sourav82  ·  3Comments
mvermaes picture mvermaes  ·  3Comments
paulcdejean picture paulcdejean  ·  3Comments