haproxy causing continuous service restart on status-update

[Gábor Mészáros]

Designate keeps restarting all services, since haproxy.cfg is being regenerated every 5 minutes.

[Alex Kavanagh (ajkavanagh)]

Info: Reading through the logs, the key parts are:

update-status hook:
Invoking reactive handler: reactive/designate_handlers.py:66:setup_amqp_req
Invoking reactive handler: reactive/designate_handlers.py:122:configure_designate_full
... then does apt update
... x 2 (i.e. does apt update twice)
2017-06-19 13:01:26 WARNING juju-log Not adding haproxy listen stanza for designate-api_int port is already in use
2017-06-19 13:01:26 WARNING juju-log Not adding haproxy listen stanza for designate-api_public port is already in use
2017-06-19 13:01:26 INFO juju-log Writing file /etc/haproxy/haproxy.cfg root:root 444 ← this is when it is re-written (ha proxy)

and then:
2017-06-19 13:01:26 INFO update-status * Stopping haproxy haproxy
2017-06-19 13:01:26 INFO update-status ...done.
2017-06-19 13:01:26 INFO update-status designate-mdns stop/waiting
2017-06-19 13:01:31 INFO update-status designate-zone-manager stop/waiting
2017-06-19 13:01:31 INFO update-status designate-agent stop/waiting
2017-06-19 13:01:36 INFO update-status designate-pool-manager stop/waiting
2017-06-19 13:01:36 INFO update-status designate-central stop/waiting
2017-06-19 13:01:36 INFO update-status designate-sink stop/waiting
2017-06-19 13:01:36 INFO update-status designate-api stop/waiting
2017-06-19 13:01:36 INFO update-status * Starting haproxy haproxy
2017-06-19 13:01:36 INFO update-status [WARNING] 169/130136 (36667) : config : proxy 'stats' has no 'bind' directive. Please declare it as a backend if this was intended.
2017-06-19 13:01:36 INFO update-status ...done.
2017-06-19 13:01:37 INFO update-status designate-mdns start/running, process 36684
2017-06-19 13:01:37 INFO update-status designate-zone-manager start/running, process 36701
2017-06-19 13:01:37 INFO update-status designate-agent start/running, process 36718
2017-06-19 13:01:37 INFO update-status designate-pool-manager start/running, process 36735
2017-06-19 13:01:37 INFO update-status designate-central start/running, process 36752
2017-06-19 13:01:37 INFO update-status designate-sink start/running, process 36769
2017-06-19 13:01:37 INFO update-status designate-api start/running, process 36786
... then writes a whole bunch of config files
... and then invokes a bunch of handlers:
2017-06-19 13:01:42 INFO juju-log Invoking reactive handler: reactive/designate_handlers.py:84:setup_endpoint
2017-06-19 13:01:43 INFO juju-log Invoking reactive handler: reactive/designate_handlers.py:74:setup_database
2017-06-19 13:01:44 INFO juju-log Invoking reactive handler: reactive/designate_handlers.py:143:cluster_connected
2017-06-19 13:01:44 INFO juju-log Invoking reactive handler: reactive/designate_handlers.py:47:set_dns_config_available
2017-06-19 13:01:44 INFO juju-log Invoking reactive handler: reactive/designate_handlers.py:116:update_peers

... and then it's over.

Conclusions:

1. It's doing WAY too much in the update status hook (apt get update, re-writing lots of files, etc.).
2. It looks like the write to /etc/haproxy/haproxy.cfg is causing the problem which is probably in charms.openstack.

More investigation to follow.

[Alex Kavanagh (ajkavanagh)]

The charms.openstack review (https://review.openstack.org/#/c/484835/) should provide a fix for this as it was the ordering of the (unchanging) hosts in the haproxy.cfg file that was causing the restarts.

[Tytus Kurek (tkurek)]

Is it really fixed? Attached is the log file from newly installed designate from openstack-charmers-next repository. Please take a look on the following part:

root@juju-64cbea-22-lxd-26:~# cat /var/log/juju/unit-designate-55.log | grep update-status | grep "start/running" | grep designate-api
2017-09-25 11:10:34 DEBUG update-status designate-api start/running, process 45695
2017-09-25 11:15:28 DEBUG update-status designate-api start/running, process 6005
2017-09-25 11:25:35 DEBUG update-status designate-api start/running, process 14542
2017-09-25 11:30:52 DEBUG update-status designate-api start/running, process 18462
2017-09-25 11:36:49 DEBUG update-status designate-api start/running, process 21473
2017-09-25 11:42:39 DEBUG update-status designate-api start/running, process 25512
2017-09-25 11:48:16 DEBUG update-status designate-api start/running, process 29599
2017-09-25 11:52:42 DEBUG update-status designate-api start/running, process 32658
2017-09-25 11:57:26 DEBUG update-status designate-api start/running, process 36359
2017-09-25 12:02:14 DEBUG update-status designate-api start/running, process 40265
2017-09-25 12:07:39 DEBUG update-status designate-api start/running, process 43252
2017-09-25 12:12:22 DEBUG update-status designate-api start/running, process 46965
2017-09-25 12:16:55 DEBUG update-status designate-api start/running, process 1802
2017-09-25 12:21:22 DEBUG update-status designate-api start/running, process 4987
2017-09-25 12:25:33 DEBUG update-status designate-api start/running, process 8877
2017-09-25 12:31:01 DEBUG update-status designate-api start/running, process 13100
2017-09-25 12:38:57 DEBUG update-status designate-api start/running, process 26117
2017-09-25 12:44:38 DEBUG update-status designate-api start/running, process 30086
2017-09-25 12:49:49 DEBUG update-status designate-api start/running, process 33895
2017-09-25 12:54:12 DEBUG update-status designate-api start/running, process 36828

[Tytus Kurek (tkurek)]

Shall this be re-opened or a new bug report shall be created?

root@juju-a2afdd-20-lxd-34:~# grep "wsgi starting up" /var/log/designate/designate-api.log | tail -10
2017-10-18 09:12:41.582 3975 INFO eventlet.wsgi [-] (3975) wsgi starting up on http://127.0.0.1:8981
2017-10-18 09:17:42.066 7424 INFO eventlet.wsgi [-] (7424) wsgi starting up on http://127.0.0.1:8981
2017-10-18 09:22:41.630 9750 INFO eventlet.wsgi [-] (9750) wsgi starting up on http://127.0.0.1:8981
2017-10-18 09:27:41.942 13269 INFO eventlet.wsgi [-] (13269) wsgi starting up on http://127.0.0.1:8981
2017-10-18 09:32:41.075 16462 INFO eventlet.wsgi [-] (16462) wsgi starting up on http://127.0.0.1:8981
2017-10-18 09:37:43.353 19204 INFO eventlet.wsgi [-] (19204) wsgi starting up on http://127.0.0.1:8981
2017-10-18 09:42:42.973 22598 INFO eventlet.wsgi [-] (22598) wsgi starting up on http://127.0.0.1:8981
2017-10-18 09:47:42.233 25909 INFO eventlet.wsgi [-] (25909) wsgi starting up on http://127.0.0.1:8981
2017-10-18 10:02:42.302 34631 INFO eventlet.wsgi [-] (34631) wsgi starting up on http://127.0.0.1:8981
2017-10-18 10:07:42.180 37110 INFO eventlet.wsgi [-] (37110) wsgi starting up on http://127.0.0.1:8981

[Dmitrii Shcherbakov (dmitriis)]

Not sure which time format is it (seems to be US)

charm show cs:~openstack-charmers-next/designate --all | grep Upload
  UploadTime: 2017-10-05T19:12:47.666Z

The latest commit to stable/17.08 is 16 days ago
https://git.io/vd7WC

If you have the new version maybe you should reopen. Full logs could be useful for others though.

[Tytus Kurek (tkurek)]

Dmitrii,

I'm using the following version:

cs:~openstack-charmers-next/designate-51

Attached are full logs. Actually, I cannot re-open.

[James Page (james-page)]

Actually this is a different bug - the original bug was about haproxy being restarted; this is about designate-api.

[James Page (james-page)]

raised bug 1729020 based on comments in #6 and #7

[Jakub Rohovsky (jakub.rohovsky)]

After installing upgrading to OpenStack Designate Charm 17.11, following is still present:

root@juju-baab69-29-lxd-8:~# grep "Stopping haproxy" /var/log/juju/unit-designate-hacluster-63.log | tail -6
2017-12-11 15:43:48 DEBUG ha-relation-changed * Stopping haproxy haproxy
2017-12-11 15:54:59 DEBUG ha-relation-changed * Stopping haproxy haproxy
2017-12-11 16:00:20 DEBUG ha-relation-changed * Stopping haproxy haproxy
2017-12-11 16:11:36 DEBUG ha-relation-changed * Stopping haproxy haproxy
2017-12-11 16:15:47 DEBUG ha-relation-changed * Stopping haproxy haproxy
2017-12-11 16:25:38 DEBUG ha-relation-changed * Stopping haproxy haproxy

root@juju-baab69-29-lxd-8:~# grep -c "Stopping haproxy" /var/log/juju/unit-designate-hacluster-63.log
2518

[Tytus Kurek (tkurek)]

I've raised bug 1737776 based on comment in #10