Issue with checksums and 1.1.0

[hernandesbsousa]

Hi there, I was using 1.0.2 without any problems, now, with 1.1.0 I'm getting the following error:

➜  empregoligado  vagrant up
Bringing machine 'devbox' up with 'virtualbox' provider...
==> devbox: Box 'my/devbox' could not be found. Attempting to find and install...
    devbox: Box Provider: virtualbox
    devbox: Box Version: >= 0
==> devbox: Loading metadata for box 's3://mys3bucket/devbox.json'
    devbox: URL: s3://mys3bucket/devbox.json
==> devbox: Adding box 'my/devbox' (v0.0.4) for provider: virtualbox
    devbox: Downloading: https://s3.amazonaws.com/mys3bucket/devbox/versions/0.0.4/devbox.box
    devbox: Calculating and comparing box checksum...
The checksum of the downloaded box did not match the expected
value. Please verify that you have the proper URL setup and that
you're downloading the proper file.

Expected: 28747f3bc3a530b7596ec99aa11548f5f5476c65
Received: f7ebebd8b1d883ced852fffb9693890b6c92f537

Any idea what might be causing this? Downgrading to 1.0.3 solves it. Also, the message is instant (no download actually occurs) and the Received checksum always changes.

[benesch]

Oh no! 1.1.0 introduced some major refactoring of the internals: the AWS SDK was upgraded to v2 and we now try an unauthenticated download before an authenticated download. My first guess is that we're downloading a 403 error page, not realizing it's a 403 error, and telling Vagrant that the error page is a box. This explains the near-instant download, and, if IIRC, the error page includes the date, which would explain the changing checksum.

Which version of Vagrant are you running? Could you also post the results of VAGRANT_LOG=debug vagrant up with the buggy plugin?

Thanks!

[hernandesbsousa]

I'm running 1.7.2 on OSX, but I had reports of the same issue on 1.5.4 on OSX and 1.6.5 on Ubuntu.

There's quite a lot of output when running in debug mode :smile_cat: is there any specific part you're interested in?

[benesch]

Most important are the lines that start with "s3auth:" and the surrounding context from Vagrant about the box download. (Feel free to strip them of private details as you did before.) Thank you much!

[benesch]

Bump! Would love to be able to dig in.

[hernandesbsousa]

Hi there, sorry, forgot to follow up.

 INFO downloader: s3auth: Discovered S3 URL: s3://mybucket/devbox.json
DEBUG downloader: s3auth: Bucket: "mybucket"
DEBUG downloader: s3auth: Key: "devbox.json"
 INFO downloader: s3auth: Generating signed URL for HEAD
INFO subprocess: Starting process: ["/opt/vagrant/bin/../embedded/bin/curl", "-I", "-q", "--fail", "--location", "--max-redirs", "10", "--user-agent", "Vagrant/1.7.2", "--continue-at", "-", "-H", "Accept: application/json", "https://mybucket.s3-sa-east-
1.amazonaws.com/devbox.json?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=CREDENTIALOMMITTED%2F20150715%2Fsa-east-1%2Fs3%2Faws4_request&X-Amz-Date=20150715T132026Z&X-Amz-Expires=600&X-Amz-SignedHeaders=host&X-Amz-Signature=3fa8df04176cfe2776bf5d85ebba272ba0816be10d3
8b3930c2d030503b4579e"]
INFO subprocess: Command in the installer. Specifying DYLD_LIBRARY_PATH...
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stderr:   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                Dload  Upload   Total   Spent    Left  Speed
^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
DEBUG subprocess: stderr: ^M  0  1228    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
DEBUG subprocess: stdout: HTTP/1.1 200 OK
...

 INFO downloader: s3auth: Discovered S3 URL: https://mybucket.s3-sa-east-1.amazonaws.com/devbox.json?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=CREDENTIALOMMITTED%2F20150715%2Fsa-east-1%2Fs3%2Faws4_request&X-Amz-Date=20150715T132026Z&X-Amz-Expires=600&X-Amz-SignedHeaders=host&X-Amz-Signature=3fa8df04176cfe2776bf5d85ebba272ba0816be10d38b3930c2d030503b4579e
DEBUG downloader: s3auth: Bucket: "mybucket"
DEBUG downloader: s3auth: Key: "devbox.json"
 INFO downloader: s3auth: Generating signed URL for GET
INFO subprocess: Starting process: ["/opt/vagrant/bin/../embedded/bin/curl", "-q", "--fail", "--location", "--max-redirs", "10", "--user-agent", "Vagrant/1.7.2", "--continue-at", "-", "-H", "Accept: application/json", "--output", "/Users/Hernandes/.vagrant.d/tmp/boxc6a96
8a3f585daff4eaa95b5f23df246d49fff83", "https://mybucket.s3-sa-east-1.amazonaws.com/devbox.json?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=CREDENTIALOMMITTED%2F20150715%2Fsa-east-1%2Fs3%2Faws4_request&X-Amz-Date=20150715T132027Z&X-Amz-Expires=600
&X-Amz-SignedHeaders=host&X-Amz-Signature=eb10a35aa4c50deca0edc346332badd1f9951fcd1ad823c252265be52bf7c929"]
 INFO subprocess: Command in the installer. Specifying DYLD_LIBRARY_PATH...
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stderr:   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Lef
DEBUG subprocess: stderr: t  Speed
^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
DEBUG subprocess: stderr: ^M100  1228  100  1228    0     0   9598      0 --:--:-- --:--:-- --:--:--  9746
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 32000
DEBUG subprocess: Exit status: 0
 INFO environment: Running hook: authenticate_box_url
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 3 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x000001028f1698>
 INFO warden: Calling IN action: #<VagrantPlugins::LoginCommand::AddAuthentication:0x000001028f9ca8>
 INFO warden: Calling OUT action: #<VagrantPlugins::LoginCommand::AddAuthentication:0x000001028f9ca8>
 INFO interface: output: Adding box 'mycompany/devbox' (v0.0.4) for provider: virtualbox
 INFO interface: output: ==> devbox: Adding box 'mycompany/devbox' (v0.0.4) for provider: virtualbox
==> devbox: Adding box 'mycompany/devbox' (v0.0.4) for provider: virtualbox
 INFO box_add: Downloading box: https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box => /Users/Hernandes/.vagrant.d/tmp/boxe80ced809e00a38e5c63e48d4d9a662cddafec60
 INFO interface: detail: Downloading: https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box
 INFO interface: detail:     devbox: Downloading: https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box
    devbox: Downloading: https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box
 INFO downloader: Downloader starting download:
 INFO downloader:   -- Source: https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box
 INFO downloader:   -- Destination: /Users/Hernandes/.vagrant.d/tmp/boxe80ced809e00a38e5c63e48d4d9a662cddafec60
 INFO subprocess: Starting process: ["/opt/vagrant/bin/../embedded/bin/curl", "-q", "--fail", "--location", "--max-redirs", "10", "--user-agent", "Vagrant/1.7.2", "--continue-at", "-", "--output", "/Users/Hernandes/.vagrant.d/tmp/boxe80ced809e00a38e5c63e48d4d9a662cddafec6
0", "https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box"]
 INFO subprocess: Command in the installer. Specifying DYLD_LIBRARY_PATH...
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stderr:   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
DEBUG subprocess: stderr: ^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
 INFO interface: info: ^M
^M INFO interface: detail: Progress: 0% (Rate: 0/s, Estimated time remaining: --:--:--)
 INFO interface: detail:     devbox: Progress: 0% (Rate: 0/s, Estimated time remaining: --:--:--)
    devbox: Progress: 0% (Rate: 0/s, Estimated time remaining: --:--:--)DEBUG subprocess: stderr: ^M100   467    0   467    0     0    521      0 --:--:-- --:--:-- --:--:--   522
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 31999
DEBUG subprocess: Exit status: 0
 INFO interface: info: ^M
^M INFO interface: detail: Calculating and comparing box checksum...
 INFO interface: detail:     devbox: Calculating and comparing box checksum...
    devbox: Calculating and comparing box checksum...
 INFO box_add: Validating checksum with Digest::SHA1
 INFO box_add: Expected checksum: 28747f3bc3a530b7596ec99aa11548f5f5476c65
DEBUG box_add: Deleting temporary box: /Users/Hernandes/.vagrant.d/tmp/boxe80ced809e00a38e5c63e48d4d9a662cddafec60
ERROR warden: Error occurred: The checksum of the downloaded box did not match the expected
value. Please verify that you have the proper URL setup and that
you're downloading the proper file.

Expected: 28747f3bc3a530b7596ec99aa11548f5f5476c65
Received: a062126b94632eea9c238b42e4e7579c5e922902
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: The checksum of the downloaded box did not match the expected
value. Please verify that you have the proper URL setup and that
you're downloading the proper file.

Is this enough context? If you need more let me know.

Thanks

[benesch]

Thanks! One last request. Can you verify that, on a version of Vagrant without vagrant-s3auth installed,

$ vagrant box add devbox https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box

prints out something like

An error occurred while downloading the remote file. The error
message, if any, is reproduced below. Please fix this error and try
again.

The requested URL returned error: 403 Forbidden

The key bit is the "403 Forbidden"; if Vagrant doesn't raise an exception with that message, S3Auth doesn't bother with an authenticated download. So if your Vagrant does indeed fail to print "403 Forbidden", try a curl -v BOX_URL and see what response code you're getting.

[hernandesbsousa]

I was getting a 301 as the bucket was not in the us standard region with the following url https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box, then tried a different format (this might be another issue, as I was using the s3://bucket/ format, which should not require region description if I got it correctly)

With https://mybucket.s3-sa-east-1.amazonaws.com/devbox.json I get the same checksum issue and the curl -v returns 403

[hernandesbsousa]

Hi there, let me know if you need any help on this.

[benesch]

So the problem is here:

 INFO subprocess: Starting process: ["/opt/vagrant/bin/../embedded/bin/curl", "-q", "--fail", "--location", "--max-redirs", "10", "--user-agent", "Vagrant/1.7.2", "--continue-at", "-", "--output", "/Users/Hernandes/.vagrant.d/tmp/boxe80ced809e00a38e5c63e48d4d9a662cddafec6
0", "https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box"]
 INFO subprocess: Command in the installer. Specifying DYLD_LIBRARY_PATH...
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stderr:   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
DEBUG subprocess: stderr: ^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
 INFO interface: info: ^M
^M INFO interface: detail: Progress: 0% (Rate: 0/s, Estimated time remaining: --:--:--)
 INFO interface: detail:     devbox: Progress: 0% (Rate: 0/s, Estimated time remaining: --:--:--)
    devbox: Progress: 0% (Rate: 0/s, Estimated time remaining: --:--:--)DEBUG subprocess: stderr: ^M100   467    0   467    0     0    521      0 --:--:-- --:--:-- --:--:--   522
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 31999
DEBUG subprocess: Exit status: 0

curl shouldn't be returning an exit status of zero if the box download is failing. I just can't understand why. If you're up for it, there's one last thing you could try. Launch a VAGRANT_LOG=debug vagrant up and grab the curl command from the actual download of the .box. It'll be the very last one. In the example above, it's:

["/opt/vagrant/bin/../embedded/bin/curl", "-q", "--fail", "--location", "--max-redirs", "10", "--user-agent", "Vagrant/1.7.2", "--continue-at", "-", "--output", "/Users/Hernandes/.vagrant.d/tmp/boxe80ced809e00a38e5c63e48d4d9a662cddafec60", "https://s3.amazonaws.com/mybucket/devbox/versions/0.0.4/devbox.box"]

If you strip the commas and square braces, you'll be able to run that command directly and see if the curl options Vagrant's setting are somehow resulting in a false success.

Sorry! I wish I had more insight for you.

[benesch]

I just had a thought! Is it possibly related to your IAM config? I.e., are you following the recommended IAM config?

[benesch]

Bump!

[benesch]

Closing due to inactivity. Reopen if you find some bandwidth to help me debug!

[ericgoedtel]

I have a user on a team that is seeing a similar problem and I ran the prescribed test. This team uses a Vagrantfile that specifies a box URL that points to a manifest as follows:

config.vm.box     = 'foo/bar'
config.vm.box_url = 'https://s3.amazonaws.com/my-box/manifest.json'

This manifest has an entry similar to the following:

  "name": "foo/bar",
  "description": "Provides a box for developing against foo.",
  "versions": [
    {
      "version": "1.0.0",
      "providers": [
        {
          "name": "virtualbox",
          "url": "s3://my-box/app-201705220933.box",
          "checksum_type": "sha1",
          "checksum": "1234567890abcdef1234567890abcdef12345678"
        }
      ]
    }
}

I observed that the URL being accessed by curl had no authentication at all. No S3 signature appended--just the raw URL that you can see in the box manifest above. So in my case--the issue is that the S3 signature is not being added to the URL and the URL is completely unauthenticated. This is resulting in S3 returning an http 404

Let me know if you'd like me to open a separate issue--but I think that the OP and I are on the same level.

[benesch]

The 404 is expected, actually. vagrant-s3auth lets Vagrant try to download the box normally first, and only attempts to add S3 authentication parameters if the normal download fails. I suspect this is the same bug as before: for some reason, curl is exiting without a failure code even though the HTTP response is ostensibly a 404.

As I mentioned before, would you be able to share your IAM config?

[ericgoedtel]

I have redacted the bucket names except for part of the bucket that indicates where my box and manifest lives.

The policy is very straightforward. All S3 actions against a selection of buckets.