charm with storage gets stuck initialising on aws

The ubuntu deploy continues.. it's been running over 30 min now, currently at "agent installing". https://paste.ubuntu.com/p/NSrM75tz83/

I got an update-status hook error on a postgresql unit, seems caused by API connection issues? https://paste.ubuntu.com/p/vfz2pZHwjH/

The ubuntu deploy completed successfully and went to a "ready" state. So perhaps if I keep retrying deploys, they may eventually succeed.

"unit-postgresql-5" cannot open api: unable to connect to API: dial
tcp 10.25.2.109:17070: i/o timeout

Typically when we see i/o timeout that is when we fail to contact Mongo. Do
you have logs from the controller?
The actual log lines do look like we are just failing to contact the
controller at all, the dial attempts are not being actively rejected but
just not going through.

Given "controller: prodstack-is" I'm guessing something was going on there?

On Fri, Dec 21, 2018 at 9:30 PM Casey Marshall <email address hidden>
wrote:

> The ubuntu deploy completed successfully and went to a "ready" state. So
> perhaps if I keep retrying deploys, they may eventually succeed.
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1809478
>
> Title:
> Juju model on 2.4.7 controller is unresponsive, agents are getting
> lost and stuck
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1809478/+subscriptions
>

I'm able to deploy other charms just fine, only kafka seems to be getting stuck. It's not even getting to the install hook, so I don't think it's anything to do with the charm. I forced the log level on one of the stuck units to DEBUG (by editing agent.conf) and it looks like the resolver is stuck waiting for storage, see log snippet below.

My deployment is using mojo, which uses juju-deployer. In my deployer bundle, I specify the storage volume up front. I imagine that (though I am not familiar with the internals of juju-deployer) the storage is being added immediately after the deploy API call or command is executed.

I commented out the storage declaration in the bundle for now, and instead, I'm running a script to attach storage after the charm is successfully deployed. That seems to workaround this issue.

2019-01-07 18:25:51 DEBUG juju.worker.logger logger.go:70 reconfiguring logging from "<root>=WARNING;juju=DEBUG" to "juju=DEBUG"
2019-01-07 18:25:51 DEBUG juju.worker.leadership tracker.go:130 kafka/6 making initial claim for kafka leadership
2019-01-07 18:25:51 DEBUG juju.worker.dependency engine.go:545 "metric-spool" manifold worker started
2019-01-07 18:25:51 DEBUG juju.worker.dependency engine.go:545 "logging-config-updater" manifold worker started
2019-01-07 18:25:51 DEBUG juju.worker.dependency engine.go:545 "metric-sender" manifold worker started
2019-01-07 18:25:51 DEBUG juju.worker.dependency engine.go:545 "hook-retry-strategy" manifold worker started
2019-01-07 18:25:51 DEBUG juju.worker.logger logger.go:58 overriding logging config with override from agent.conf "juju=DEBUG"
2019-01-07 18:25:51 DEBUG juju.worker.dependency engine.go:545 "uniter" manifold worker started
2019-01-07 18:25:51 DEBUG juju.worker.proxyupdater proxyupdater.go:168 applying in-process legacy proxy settings proxy.Settings{Http:"", Https:"", Ftp:"", NoProxy:"10.25.2.109,10.25.2.110,10.25.2.111", AutoNoProxy
:""}
2019-01-07 18:25:51 DEBUG juju.worker.proxyupdater proxyupdater.go:188 saving new legacy proxy settings proxy.Settings{Http:"", Https:"", Ftp:"", NoProxy:"10.25.2.109,10.25.2.110,10.25.2.111", AutoNoProxy:""}
2019-01-07 18:25:51 DEBUG juju.worker.proxyupdater proxyupdater.go:252 new apt proxy settings proxy.Settings{Http:"", Https:"", Ftp:"", NoProxy:"", AutoNoProxy:""}
2019-01-07 18:25:51 DEBUG juju.worker.meterstatus connected.go:88 got meter status change signal from watcher
2019-01-07 18:25:51 DEBUG juju.network network.go:507 no lxc bridge addresses to filter for machine
2019-01-07 18:25:51 DEBUG juju.network network.go:543 cannot get "lxdbr0" addresses: route ip+net: no such network interface (ignoring)
2019-01-07 18:25:51 DEBUG juju.network network.go:543 cannot get "virbr0" addresses: route ip+net: no such network interface (ignoring)
2019-01-07 18:25:51 DEBUG juju.network network.go:492 including address local-cloud:10.25.2.111 for machine
2019-01-07 18:25:51 DEBUG juju.network network.go:492 including address local-machine:127.0.0.1 for machine
2019-01-07 18:25:51 DEBUG juju.network network.go:492 including address local-machine:::1 for machine
2019-01-07 18:25:51 DEBUG juju.network network.go:561 addresses after filtering: [local-clou...

The charm hook execution will block until all requested storage is attached. For block storage, this means that the machine agent on the worker node has to poll block devices using lsblk and report back what it sees to Juju - the storage provisioner will attempt to match the /dev/foo block device name with the storage request and thus mark the storage as attached. Juju pauses charm hook execution until this happens.

There was a bug on AWS recently where the block device WWN could not be used to match the storage request: https://bugs.launchpad.net/juju/+bug/1778033. This was fixed in 2.4.7. Perhaps there's a similar issue here. You can turn on TRACE debugging for "juju.apiserver.storagecommon" to see the matching attempts to pair the block device info with the storage request to see why it might be failing.

So it looks like AWS is broken - Juju runs the udevadm command for each of the block devices it finds using lsblk. The udevadm command prints various attributes of the device which Juju needs to know, including WWN, device link etc. When I ssh'ed into an AWS instance running a deployed postgresq with storage, the /dev/xvdf device showed up when the EBS volume was create, but the udevadm output was virtually empty. Without this info, Juju cannot complete the storage setup. There's no issue when I tested on GCE - the udevadm output was fully populated.

I have no idea what's changed on AWS to break udevadm and with it Juju storage.

Note - the above was with 2.5 but there's no difference between 2.4.7 and 2.5 in this area.

Maybe it's related to the newish NVMe EBS instances?

So turns out that AWS xen pv block devices do not have identifying hardware info from udev that we can use to match the volume request from Juju, so we need to fall back to matching on device name. It's not ideal but all we can do for now.

https://github.com/juju/juju/pull/9620

Machine log, unit log and output of juju storage --format yaml

Reproduced my issue again on openstack, see attached logs/storage info. Issue is actually "quota exceeded" but I didn't figure this out until looking at the yaml format of `juju storage`. Nothing in the logs to indicate this was the underlying cause.