Unable to deploy postgresql-k8s charm from charmhub

Bug #1928182 reported by Tom Haddon
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Canonical Juju
Fix Released
High
Simon Richardson
Snap Store Server
Invalid
Undecided
Unassigned

Bug Description

I'm trying to deploy the postgresql-k8s charm from charmhub. I was able to do this a few minutes ago, but have now had three failures in a row. The error is:

$ juju deploy --debug postgresql-k8s postgresql
10:01:34 INFO juju.cmd supercommand.go:56 running juju [2.9.0 0 ac860f7db4296273ea2cf213115ec2c229d57a07 gc go1.14.15]
10:01:34 DEBUG juju.cmd supercommand.go:57 args: []string{"/snap/juju/16132/bin/juju", "deploy", "--debug", "postgresql-k8s", "postgresql"}
10:01:34 INFO juju.juju api.go:78 connecting to API addresses: [localhost:36437 10.152.183.222:17070]
10:01:34 DEBUG juju.api apiclient.go:1132 successfully dialed "wss://localhost:33201/api"
10:01:34 INFO juju.api apiclient.go:1034 cannot resolve "localhost": operation was canceled
10:01:34 INFO juju.api apiclient.go:664 connection established to "wss://localhost:33201/api"
10:01:34 INFO juju.juju api.go:328 API endpoints changed from [localhost:36437 10.152.183.222:17070] to [localhost:33201 10.152.183.222:17070]
10:01:34 INFO juju.juju api.go:78 connecting to API addresses: [localhost:33201 10.152.183.222:17070]
10:01:34 DEBUG juju.api apiclient.go:1132 successfully dialed "wss://localhost:40939/model/5bcf83c1-0c1f-436e-8ccc-b16bd35fbba8/api"
10:01:34 INFO juju.api apiclient.go:1034 cannot resolve "localhost": operation was canceled
10:01:34 INFO juju.api apiclient.go:664 connection established to "wss://localhost:40939/model/5bcf83c1-0c1f-436e-8ccc-b16bd35fbba8/api"
10:01:34 INFO juju.juju api.go:328 API endpoints changed from [localhost:33201 10.152.183.222:17070] to [localhost:40939 10.152.183.222:17070]
10:01:34 INFO juju.juju api.go:78 connecting to API addresses: [localhost:40939 10.152.183.222:17070]
10:01:34 DEBUG juju.api apiclient.go:1132 successfully dialed "wss://localhost:33215/api"
10:01:34 INFO juju.api apiclient.go:1034 cannot resolve "localhost": operation was canceled
10:01:34 INFO juju.api apiclient.go:664 connection established to "wss://localhost:33215/api"
10:01:34 INFO juju.juju api.go:328 API endpoints changed from [localhost:40939 10.152.183.222:17070] to [localhost:33215 10.152.183.222:17070]
10:01:34 DEBUG juju.cmd.juju.application.deployer deployer.go:396 cannot interpret as local charm: file does not exist
10:01:34 DEBUG juju.cmd.juju.application.deployer deployer.go:203 cannot interpret as a redeployment of a local charm from the controller
10:01:36 DEBUG juju.cmd.juju.application.store charmadapter.go:122 cannot interpret as charmstore bundle: focal (series) != "bundle"
10:01:36 INFO cmd charm.go:435 Preparing to deploy "postgresql-k8s" from the charm-hub
10:01:38 INFO juju.cmd.juju.application.deployer series_selector.go:83 with the configured model default series "focal"
10:01:49 DEBUG juju.api monitor.go:35 RPC connection died
ERROR storing charm "postgresql-k8s": cannot retrieve "https://api.charmhub.io/api/v1/charms/download/y2vuZHGLElMmdfcL4q1zJayL9utaheIa_2.charm": unable to locate archive
10:01:49 DEBUG cmd supercommand.go:537 error stack:
cannot retrieve "https://api.charmhub.io/api/v1/charms/download/y2vuZHGLElMmdfcL4q1zJayL9utaheIa_2.charm": unable to locate archive
/build/snapcraft-juju-35d6cf/parts/juju/src/rpc/client.go:178:
/build/snapcraft-juju-35d6cf/parts/juju/src/api/apiclient.go:1231:
/build/snapcraft-juju-35d6cf/parts/juju/src/api/charms/client.go:155:
/build/snapcraft-juju-35d6cf/parts/juju/src/cmd/juju/application/store/store.go:44:
/build/snapcraft-juju-35d6cf/parts/juju/src/cmd/juju/application/deployer/charm.go:510: storing charm "postgresql-k8s"

Tags: charmhub
Revision history for this message
John A Meinel (jameinel) wrote :

https://api.charmhub.io/api/v1/charms/download/y2vuZHGLElMmdfcL4q1zJayL9utaheIa_2.charm

makes me think that Juju is correctly querying the store, but for whatever reason accessing the actual charm is failing.

Revision history for this message
Daniel Manrique (roadmr) wrote :

The binaries' hash from the API response:

 curl -XPOST -s https://api.charmhub.io/v2/charms/refresh -H 'Content-type: application/json' -d '{"context": [], "actions": [{"name": "postgresql-k8s", "base": {"architecture": "amd64", "name": "ubuntu", "channel": "16.04"}, "revision": 2, "action": "install", "instance-key": "a-test"}]}' | jq '.results[0].charm.download."hash-sha-256"'
"ab8499d6b81ee74f84105468d1ad19007a56035970d83e8f252e602fe08c296c"

now let's download the charm:

$ curl -LO $(curl -XPOST -s https://api.charmhub.io/v2/charms/refresh -H 'Content-type: application/json' -d '{"context": [], "actions": [{"name": "postgresql-k8s", "base": {"architecture": "amd64", "name": "ubuntu", "channel": "16.04"}, "revision": 2, "action": "install", "instance-key": "a-test"}]}' | jq -r '.results[0].charm.download."url"')
  % Total % Received % Xferd Average Speed Time Time Time Current
                                 Dload Upload Total Spent Left Speed
100 549 100 549 0 0 1127 0 --:--:-- --:--:-- --:--:-- 1127
100 15.0M 100 15.0M 0 0 3095k 0 0:00:04 0:00:04 --:--:-- 3639k

and checksum it, ensure it matches what the API told us to expect:

$ sha256sum y2vuZHGLElMmdfcL4q1zJayL9utaheIa_2.charm
ab8499d6b81ee74f84105468d1ad19007a56035970d83e8f252e602fe08c296c y2vuZHGLElMmdfcL4q1zJayL9utaheIa_2.charm

Not sure why Juju is unable to download the archive. Is it doing something significantly different than what curl would do? did something change with postgresql-k8s in the 17 hours since the bug was filed?

Changed in snapstore-server:
status: New → Incomplete
Daniel Manrique (roadmr)
tags: added: charmhub
Revision history for this message
John A Meinel (jameinel) wrote : Re: [Bug 1928182] Re: Unable to deploy postgresql-k8s charm from charmhub

Note that by whatever mechanism it appears to be working again:
$ juju deploy postgresql-k8s
Located charm "postgresql-k8s" in charm-hub, revision 3
Deploying "postgresql-k8s" from charm-hub charm "postgresql-k8s", revision
3 in channel stable

On Thu, May 13, 2021 at 7:50 AM Daniel Manrique <email address hidden>
wrote:

> ** Tags added: charmhub
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1928182
>
> Title:
> Unable to deploy postgresql-k8s charm from charmhub
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1928182/+subscriptions
>

Revision history for this message
John A Meinel (jameinel) wrote :

From everything I can tell this was a temporary outage (as you can again deploy from postgresql-k8s). However, it is something we should be aware of in case it comes back and we have the opportunity to reproduce.

Changed in juju:
status: New → Incomplete
Revision history for this message
Daniel Manrique (roadmr) wrote :

The download problem happened at 2021-05-12 10:01:49, charmhub didn't have any outage at that time.

COuld we perhaps get more information about under which circumstances Juju would say "unable to locate archive"?

ERROR storing charm "postgresql-k8s": cannot retrieve "https://api.charmhub.io/api/v1/charms/download/y2vuZHGLElMmdfcL4q1zJayL9utaheIa_2.charm": unable to locate archive

I'd like to know what HTTP response code / payload was received by Juju to result in this message, so we can track down why charmhub responded with that.

Revision history for this message
John A Meinel (jameinel) wrote :

That particular error is coming from here:
https://github.com/juju/juju/blob/19d6a75eea61f5021a9fa0ee8e37fe7f6e3c9d53/charmhub/download.go#L201

Given what it is downloading from, I believe it is coming from:
https://github.com/juju/juju/blob/19d6a75eea61f5021a9fa0ee8e37fe7f6e3c9d53/charmhub/download.go#L101

Essentially we got the charm URL from Charmhub, but when we went to download it, we got a status code that wasn't 200 OK, and wasn't 404 Not Found.
(I feel like we should at least be logging more information if not including it in the error)

Revision history for this message
Tom Haddon (mthaddon) wrote :

I know this was a temporary outage, I mentioned that when filing the bug. I don't understand why this has been marked incomplete on both the snap-store and juju projects though. Are we saying we don't have appropriate logging in place to diagnose this issue? If so, can we fix that?

Revision history for this message
Daniel Manrique (roadmr) wrote :

"Could we perhaps get more information about under which circumstances Juju would say "unable to locate archive"?" sounds like a valid reason to set the bug as incomplete.

"cannot be verified, the reporter needs to give more info".

I didn't change the bug status because Launchpad didn't send me a notification when John replied. I'll do so now, and use your timestamps to track down the return code from the store.

Changed in snapstore-server:
status: Incomplete → Confirmed
Revision history for this message
Simon Richardson (simonrichardson) wrote :

@jameinel: I'll open a PR to add more logging.

Revision history for this message
Daniel Manrique (roadmr) wrote :

I checked logging on our side - I couldn't find a Sentry report matching the error's timestamp, which suggests either this was a problem at the haproxy level (Sentry only logs application units), or it was a non-loggable error (403 is an example, I'm not saying it was the case here, but the circumstances under which most 4xx errors are returned to clients are normal enough that we don't log them).

Unfortunately, due to the amount of traffic the store gets, we only have 15 days' retention of haproxy logs, meaning that the possible haproxy error that happened on the 12th of May has now rotated into /dev/null :(

I'll check other logs we might have to try to learn more.

Revision history for this message
Simon Richardson (simonrichardson) wrote :

The PR[1] to include logging went out with juju-2.9.4

I'm leaving this open until retries when requesting charmhub API are implemented.

 - 1. https://github.com/juju/juju/pull/13018

Changed in juju:
assignee: nobody → Simon Richardson (simonrichardson)
milestone: none → 2.9.7
status: Incomplete → In Progress
importance: Undecided → High
Revision history for this message
Simon Richardson (simonrichardson) wrote :

PR to retry all requests (including downloads) based on the status code sent from the server: https://github.com/juju/juju/pull/13106

Changed in juju:
status: In Progress → Fix Committed
Changed in juju:
status: Fix Committed → Fix Released
William Grant (wgrant)
no longer affects: ubuntu
Changed in snapstore-server:
status: Confirmed → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.