Deployment of Keystone cluster often fails due to haproxy service not listening on ports that it should

[Frode Nordahl]

$ juju status --format=tabular
keystone/0 active idle 1.25.8 188 5000/tcp 10.5.14.180 Unit is ready
keystone/1 blocked idle 1.25.8 189 5000/tcp 10.5.14.181 Services not running that should be: haproxy; Ports which should be open, but are not: 5000, 35357
keystone/2 blocked idle 1.25.8 190 5000/tcp 10.5.14.182 Services not running that should be: haproxy; Ports which should be open, but are not: 5000, 35357

Log excerpt from working node /var/log/juju/unit-keystone-0.log:
2016-12-08 10:33:49 INFO juju-log shared-db:332: Wrote template /etc/haproxy/haproxy.cfg.
2016-12-08 10:33:54 INFO shared-db-relation-changed haproxy is running.
2016-12-08 10:36:32 INFO juju-log Registered config file: /etc/haproxy/haproxy.cfg

Log excerpt from non-working node /var/log/juju/unit-keystone-1.log:
2016-12-08 10:34:02 INFO juju-log Wrote template /etc/haproxy/haproxy.cfg.
2016-12-08 10:34:02 INFO leader-settings-changed haproxy not running.

On both nodes there are various log messages with this error:
error: no relation id specified

This might be related to haproxy steps (install, leader-settings-changed, config-changed, start, update-status)

[Frode Nordahl (fnordahl)]

No log evidence as of why haproxy does not start.

[Frode Nordahl (fnordahl)]

In simple one-shot trial run we have the following stats for observation:
trusty-icehouse Observed
trusty-kilo Observed
trusty-liberty Not observed
trusty-mitaka Not observed
xenial-mitaka Not observed
xenial-newton Not observed

[Frode Nordahl (fnordahl)]

Second run of trials show same observations.

dpkg used for trusty-icehouse: haproxy 1.4.24-2ubuntu0.4 amd64
dpkg used for trusty-kilo: haproxy 1.4.24-2ubuntu0.4 amd64
dpkg used for trusty-liberty: haproxy 1.5.14-1ubuntu0.15.10.1~cloud0 amd64

I have a working theory that the root cause for this issue comes from the haproxy package in trusty. For Ubuntu OpenStack versions >= trusty-liberty we include haproxy in the Ubuntu Cloud Archive.

[Frode Nordahl (fnordahl)]

https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline/openstack/charm-keystone/416689/2/1861/test_charm_amulet_smoke_3205/amulet-smoke.txt

[Frode Nordahl (fnordahl)]

https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline/openstack/charm-keystone/416689/2/1863/test_charm_amulet_smoke_3207/amulet-smoke.txt

[Frode Nordahl (fnordahl)]

https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline_amulet_full/openstack/charm-keystone/416689/2/557/test_charm_amulet_full_2091/amulet-test.txt

[James Page (james-page)]

Frode - looks like you might have a smoking gun with the older haproxy version.

[James Page (james-page)]

Hmm although one of those latest test failures is xenial mitaka - where it looks like the haproxy.cfg was updated, but haproxy was not actually restarted.

[James Page (james-page)]

Message is:

message: 'Ports which should be open, but are not: 5000, 35357'

haproxy is running, but not listening on either port.

[Alex Kavanagh (ajkavanagh)]

I've seen this and then it clears on the next update-status hook. Maybe the
internal status update code is not being executed for the relevant hook?

On 5 Jan 2017 10:31 am, "James Page" <email address hidden> wrote:

> Message is:
>
> message: 'Ports which should be open, but are not: 5000, 35357'
>
> haproxy is running, but not listening on either port.
>
> --
> You received this bug notification because you are a member of OpenStack
> Charmers, which is subscribed to keystone in Juju Charms Collection.
> https://bugs.launchpad.net/bugs/1648396
>
> Title:
> Deployment of Keystone cluster often fails due to haproxy service not
> being started
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/charms/+source/keystone/+bug/
> 1648396/+subscriptions
>

[Frode Nordahl (fnordahl)]

I indeed have a sample of haproxy not being restarted even though the configuration is changed:

$ ps axu | grep haproxy
root 19997 0.0 0.0 4228 652 ? Ss 13:49 0:00 /usr/sbin/haproxy-systemd-wrapper -f /etc/haproxy/haproxy.cfg -p /run/haproxy.pid
haproxy 20001 0.0 0.3 37692 5000 ? S 13:49 0:00 /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /run/haproxy.pid -Ds
haproxy 20003 0.0 0.0 37692 936 ? Ss 13:49 0:00 /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /run/haproxy.pid -Ds

$ ls -l /etc/haproxy/haproxy.cfg
-rw-r--r-- 1 root root 1224 Jan 11 13:59 haproxy.cfg

As you say, after some time it solves itself, but not always.

[Ryan Beisner (1chb1n)]

Keystone full amulet tests are failing on Trusty-Mitaka, where one of the 3 keystone units has no haproxy service running and is not listening on 5000.

keystone/7 blocked idle 1.25.10 18 5000/tcp 172.17.106.63 Ports which should be open, but are not: 5000, 35357

[Ryan Beisner (1chb1n)]

Here is an example of this caught in CI:

https://openstack-ci-reports.ubuntu.com/artifacts/test_charm_pipeline/openstack/charm-keystone/433892/2/2442/index.html

[Frode Nordahl (fnordahl)]

2017-02-27 15:05:00 INFO cluster-relation-changed Adding user juju_keystone to group juju_keystone
2017-02-27 15:05:00 INFO cluster-relation-changed # 10.5.26.147 SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.8
2017-02-27 15:05:00 INFO cluster-relation-changed # 10.5.26.147 SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.8
2017-02-27 15:05:02 INFO cluster-relation-changed * Stopping haproxy haproxy
2017-02-27 15:05:02 INFO cluster-relation-changed ...done.
2017-02-27 15:05:02 INFO cluster-relation-changed * Starting haproxy haproxy
2017-02-27 15:05:02 INFO cluster-relation-changed Available polling systems :
2017-02-27 15:05:02 INFO cluster-relation-changed sepoll : pref=400, test result OK
2017-02-27 15:05:02 INFO cluster-relation-changed epoll : pref=300, test result OK
2017-02-27 15:05:02 INFO cluster-relation-changed poll : pref=200, test result OK
2017-02-27 15:05:02 INFO cluster-relation-changed select : pref=150, test result FAILED
2017-02-27 15:05:02 INFO cluster-relation-changed Total: 4 (3 usable), will use sepoll.
2017-02-27 15:05:02 INFO cluster-relation-changed [ALERT] 057/150502 (14281) : Starting frontend tcp-in_admin-port: cannot bind socket
2017-02-27 15:05:02 INFO cluster-relation-changed [ALERT] 057/150502 (14281) : Starting frontend tcp-in_public-port: cannot bind socket
2017-02-27 15:05:02 INFO cluster-relation-changed Using sepoll() as the polling mechanism.
2017-02-27 15:05:02 INFO cluster-relation-changed ...fail!

[Frode Nordahl (fnordahl)]

There is a few issues with haproxy logging adding to the complexity of finding the root cause of this bug.

1) The rsyslog daemon is not restarted after configuration is injected in /etc/rsyslog.d by the the haproxy package. This leads to /var/lib/haproxy/dev/log socket not being created.

2) The charm-helpers haproxy.cfg template configures haproxy to log to 127.0.0.1 UDP/514, but rsyslog is by default not configured to receive on UDP/514

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/438617

[Frode Nordahl (fnordahl)]

For the record, updates for findings in comment #17:
1) Proposed fix for rsyslog here:
  https://bugs.launchpad.net/ubuntu/+source/rsyslog/+bug/1668639
2) Proposed fix for charm-helpers here:
  https://code.launchpad.net/~fnordahl/charm-helpers/haproxy-logging/+merge/318476

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/438617
Committed: https://git.openstack.org/cgit/openstack/charm-keystone/commit/?id=01816c846616ceb73717aff48e53da98cb661ce0
Submitter: Jenkins
Branch: master

commit 01816c846616ceb73717aff48e53da98cb661ce0
Author: Frode Nordahl <email address hidden>
Date: Mon Feb 27 17:33:04 2017 +0100

    Make sure haproxy runs post-install

    Unconfigured keystone service listening on ports destined for haproxy
    race with start of haproxy service.

    Change-Id: I9f601344e72bd67738429f82151f9683f5ecf8e4
    Closes-Bug: #1648396