Deploy sometimes fails behind a proxy

[Andreas Hasenack]

2.0-beta15-xenial-amd64

I can't seem to deploy apps or bundles with juju 2b15 behind a proxy, but bootstrap works.

Here I have switched to the controller model already:

andreas@nsn7:~/bundles/mybundles$ juju-2.0 status
MODEL CONTROLLER CLOUD/REGION VERSION
controller vmwarestack-controller vmwarestack-maas2 2.0-beta15

APP VERSION STATUS EXPOSED ORIGIN CHARM REV OS

UNIT WORKLOAD AGENT MACHINE PUBLIC-ADDRESS PORTS MESSAGE

MACHINE STATE DNS INS-ID SERIES AZ
0 started 10.245.200.46 4y3h8n xenial default

andreas@nsn7:~/bundles/mybundles$ juju-2.0 show-cloud local:vmwarestack-maas2
defined: local
type: maas
auth-types: [oauth1]
endpoint: http://10.245.200.25/MAAS/
config:
  default-series: xenial
  http-proxy: http://squid.internal:3128/
  https-proxy: http://squid.internal:3128/
  no-proxy: localhost,127.0.0.1,10.245.200.25,169.254.169.254

andreas@nsn7:~/bundles/mybundles$ juju-2.0 deploy ./juju2-xenial-trunk-landscape-dense-maas.yaml --debug
2016-08-18 17:24:58 INFO juju.cmd supercommand.go:63 running juju [2.0-beta15 gc go1.6.2]
2016-08-18 17:24:58 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-18 17:24:58 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:00 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:00 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-18 17:25:00 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-18 17:25:00 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:01 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:01 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-18 17:25:02 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-18 17:25:02 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:04 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:04 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-18 17:25:04 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-18 17:25:04 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:05 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:05 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-18 17:25:05 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-18 17:25:05 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:07 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:07 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-18 17:25:07 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-18 17:25:07 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:08 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/c3a28a54-0a20-412b-865b-c70eda654478/api"
2016-08-18 17:25:08 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-18 17:25:08 DEBUG httpbakery client.go:244 client do GET https://api.jujucharms.com/charmstore/v5/trusty/haproxy/meta/any?include=id&include=supported-series&include=published {
2016-08-18 17:25:09 DEBUG httpbakery client.go:246 } -> error <nil>

... stalls for a while ...

2016-08-18 17:29:24 DEBUG juju.api apiclient.go:588 health ping failed: connection is shut down
2016-08-18 17:29:24 DEBUG juju.api apiclient.go:588 health ping failed: connection is shut down
2016-08-18 17:29:24 ERROR cmd supercommand.go:458 cannot deploy bundle: cannot add charm "cs:trusty/haproxy": cannot retrieve charm "cs:trusty/haproxy-19": cannot get archive: Get https://api.jujucharms.com/charmstore/v5/trusty/haproxy-19/archive?channel=stable: dial tcp 162.213.33.122:443: getsockopt: connection timed out
2016-08-18 17:29:24 DEBUG cmd supercommand.go:459 (error details: [{github.com/juju/juju/cmd/juju/application/deploy.go:429: } {github.com/juju/juju/cmd/juju/application/bundle.go:192: cannot deploy bundle} {github.com/juju/juju/cmd/juju/application/bundle.go:320: cannot add charm "cs:trusty/haproxy"} {github.com/juju/juju/cmd/juju/application/store.go:127: } {github.com/juju/juju/api/client.go:372: } {github.com/juju/juju/api/apiclient.go:647: } {github.com/juju/retry/retry.go:187: } {github.com/juju/juju/rpc/client.go:149: } {cannot retrieve charm "cs:trusty/haproxy-19": cannot get archive: Get https://api.jujucharms.com/charmstore/v5/trusty/haproxy-19/archive?channel=stable: dial tcp 162.213.33.122:443: getsockopt: connection timed out}])

In the meantime, on the bootstrap node:
tcp 0 1 10.245.200.46:35534 162.213.33.121:443 SYN_SENT 6275/jujud
tcp 0 1 10.245.200.46:35536 162.213.33.121:443 SYN_SENT 6275/jujud

root@node-1:~# cat /home/ubuntu/.juju-proxy
export http_proxy=http://squid.internal:3128/
export HTTP_PROXY=http://squid.internal:3128/
export https_proxy=http://squid.internal:3128/
export HTTPS_PROXY=http://squid.internal:3128/
export no_proxy=10.245.200.25,10.245.200.46,127.0.0.1,169.254.169.254,::1,localhost
export NO_PROXY=10.245.200.25,10.245.200.46,127.0.0.1,169.254.169.254,::1,localhost

[Andreas Hasenack (ahasenack)]

This doesn't happen consistently, I don't know why.

[Richard Harding (rharding)]

Andreas, does it happen consistently from once bootstrapped or is it a complete intermittent issue?

e.g. if I bootstrap and get this failure I'll continue to get this failure, however the next bootstrap might not have it

or is it more

any time I run juju deploy behind a proxy it may or may not work

[Andreas Hasenack (ahasenack)]

It's more "it may or may not work after bootstrap". If it works, it never fails again.

Another data point: a case where it was NOT working after bootstrap, repeatedly, started working after I rebooted the controller. But I tried this just once.

It kind of felt like there is a race with a set of processes starting before the proxy configuration was set.

[Andreas Hasenack (ahasenack)]

I haven't had a case, other than the reboot one I talked about in my previous comment, where it would start working after a while, on its own.

[Richard Harding (rharding)]

Thanks Andreas, that's helpful, especially that restarting the controller seemed to have flipped it to working on an occasion.

[Andreas Hasenack (ahasenack)]

I got another case where deploys were not working right after a bootstrap behind proxy. This bootstrap was done with debugging enabled and I'm attaching logs.

More interestingly, though, is that right after I restarted the jujud-machine-0 service, the deploys started working. I'm also attaching logs about that.

[Andreas Hasenack (ahasenack)]

debug bootstrap followed by failed deploy (console)

[Andreas Hasenack (ahasenack)]

machine 0 logs and files that cover the bootstrap plus two "ubuntu" deploy attempts.

[Andreas Hasenack (ahasenack)]

At around Fri Aug 19 13:19:53 UTC 2016 I restarted the jujud-machine-0 agent:

root@node-1:/# service jujud-machine-0 restart
root@node-1:/# date
Fri Aug 19 13:19:53 UTC 2016

Then the deploy worked:
andreas@nsn7:~$ juju-2.0 deploy ubuntu --debug
2016-08-19 13:19:54 INFO juju.cmd supercommand.go:63 running juju [2.0-beta15 gc go1.6.2]
2016-08-19 13:19:54 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-19 13:19:54 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:19:56 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:19:56 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-19 13:19:56 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-19 13:19:56 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:19:57 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:19:57 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-19 13:19:58 DEBUG httpbakery client.go:244 client do GET https://api.jujucharms.com/charmstore/v5/xenial/ubuntu/meta/any?include=id&include=supported-series&include=published {
2016-08-19 13:19:59 DEBUG httpbakery client.go:246 } -> error <nil>
2016-08-19 13:20:00 INFO cmd cmd.go:129 Added charm "cs:ubuntu-0" to the model.
2016-08-19 13:20:00 INFO cmd cmd.go:129 Deploying charm "cs:ubuntu-0" with the user specified series "xenial".
2016-08-19 13:20:00 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-19 13:20:00 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:20:01 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:20:01 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-19 13:20:02 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-19 13:20:02 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:20:03 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:20:03 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-19 13:20:03 INFO juju.juju api.go:74 connecting to API addresses: [10.245.200.46:17070]
2016-08-19 13:20:03 INFO juju.api apiclient.go:537 dialing "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:20:04 INFO juju.api apiclient.go:313 connection established to "wss://10.245.200.46:17070/model/234c8604-e751-457d-8573-dd310d47ebea/api"
2016-08-19 13:20:05 DEBUG juju.juju api.go:248 API hostnames unchanged - not resolving
2016-08-19 13:20:05 DEBUG juju.api apiclient.go:588 health ping failed: co...

[Nate Finch (natefinch)]

Please retry with beta 18 when it comes out. I've done a dozen or more deploys and it always succeeds, but I can repro the failure immediately with beta 17.

[Andreas Hasenack (ahasenack)]

Hit this again with 2.1b3, see bug #1654591