Grenade Failure - MessagingTimeout on floating IP remove

[Davanum Srinivas (DIMS)]

Logstash query:
message:"<class 'oslo_messaging.exceptions.MessagingTimeout'> (HTTP 500)"

Grenade failure:
2016-02-12 10:31:02.846 | + openstack ip floating remove 172.24.5.2 cinder_server1
2016-02-12 10:32:05.422 | Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
2016-02-12 10:32:05.422 | <class 'oslo_messaging.exceptions.MessagingTimeout'> (HTTP 500) (Request-ID: req-b1f17c4c-b814-4a21-9209-13db7915370f)
2016-02-12 10:32:05.443 | + exit_trap

Example from: http://logs.openstack.org/12/278012/3/check/gate-grenade-dsvm/ac87c30/logs/grenade.sh.txt.gz

[Davanum Srinivas (DIMS) (dims-v)]

Initial triage on openstack-oslo - http://eavesdrop.openstack.org/irclogs/%23openstack-oslo/%23openstack-oslo.2016-02-12.log.html#t2016-02-12T13:54:17

[Matt Riedemann (mriedem)]

The failure in n-api is here:

http://logs.openstack.org/12/278012/3/check/gate-grenade-dsvm/ac87c30/logs/new/screen-n-api.txt.gz?level=TRACE#_2016-02-12_10_32_05_378

That timeout is at 10:32:05. Around the same time in the n-net logs we have this:

http://logs.openstack.org/12/278012/3/check/gate-grenade-dsvm/ac87c30/logs/new/screen-n-net.txt.gz#_2016-02-12_10_31_05_380

2016-02-12 10:31:05.380 DEBUG oslo_concurrency.lockutils [req-b1f17c4c-b814-4a21-9209-13db7915370f cinder_grenade cinder_grenade] Lock "172.24.5.2" acquired by "nova.network.floating_ips.do_disassociate" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-02-12 10:32:06.595 22979 DEBUG oslo.messaging._drivers.impl_rabbit [-] Received recoverable error from kombu: on_error /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/impl_rabbit.py:654
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit Traceback (most recent call last):
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/kombu/connection.py", line 436, in _ensured
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit return fun(*args, **kwargs)
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/kombu/connection.py", line 508, in __call__
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit return fun(*args, channel=channels[0], **kwargs), channels[0]
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/impl_rabbit.py", line 704, in execute_method
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit method()
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/impl_rabbit.py", line 1050, in _publish
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit producer.publish(msg, expiration=timeout)
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/kombu/messaging.py", line 172, in publish
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit routing_key, mandatory, immediate, exchange, declare)
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/kombu/messaging.py", line 188, in _publish
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit mandatory=mandatory, immediate=immediate,
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/amqp/channel.py", line 2132, in basic_publish_confirm
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit self.wait([(60, 80), (60, 120)])
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/local/lib/python2.7/dist-packages/amqp/abstract_channel.py", line 67, in wait
2016-02-12 10:32:06.595 22979 ERROR oslo.messaging._d...

[Matt Riedemann (mriedem)]

Also, FWIW, it looks like this started happening around 2/4:

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22cinder_grenade%5C%22%20AND%20message%3A%5C%22_disassociate_floating_ip%5C%22%20AND%20message%3A%5C%22MessagingTimeout%5C%22%20AND%20tags%3A%5C%22screen-n-api.txt%5C%22&from=30d

[Matt Riedemann (mriedem)]

oslo.messaging 4.1.0 was released on 2/4 so we suspect there was a regression in that:

https://github.com/openstack/oslo.messaging/compare/4.0.0...4.1.0

[Davanum Srinivas (DIMS) (dims-v)]

1 hit in last 7 days. Please reopen if this repeats again.

[Dan Smith (danms)]

This looks to me like the same deal, everything fails at the end of the run with rabbit timeouts:

http://logs.openstack.org/15/290715/2/check/gate-grenade-dsvm/056bc19/logs/grenade.sh.txt.gz#_2016-03-09_19_21_22_820

http://logs.openstack.org/15/290715/2/check/gate-grenade-dsvm/056bc19/logs/new/screen-n-api.txt.gz?level=TRACE#_2016-03-09_19_21_22_814

http://logs.openstack.org/15/290715/2/check/gate-grenade-dsvm/056bc19/logs/new/screen-n-cpu.txt.gz?level=TRACE#_2016-03-09_19_20_41_431

http://logs.openstack.org/15/290715/2/check/gate-grenade-dsvm/056bc19/logs/new/screen-n-cpu.txt.gz?level=TRACE#_2016-03-09_19_20_41_431

[Davanum Srinivas (DIMS) (dims-v)]

Looks like 5 hits starting 7th. all on build_node devstack-trusty-osic-cloud1-XYZ

[Davanum Srinivas (DIMS) (dims-v)]

In each of the 5 hits i see - "Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 104.46 sec"

http://logs.openstack.org/30/285530/7/check/gate-grenade-dsvm/4575575/logs/new/screen-n-net.txt.gz?#_2016-03-08_18_36_23_074
http://logs.openstack.org/54/268054/6/check/gate-grenade-dsvm-ceilometer/a253d5f/logs/new/screen-n-net.txt.gz?#_2016-03-08_08_01_31_912
http://logs.openstack.org/14/288814/2/check/gate-grenade-dsvm/c80d3b0/logs/new/screen-n-net.txt.gz?#_2016-03-08_00_57_02_802
http://logs.openstack.org/76/286976/4/gate/gate-grenade-dsvm/101e2a3/logs/new/screen-n-net.txt.gz?#_2016-03-07_22_42_49_151
http://logs.openstack.org/19/225119/5/check/gate-grenade-dsvm/31baa7b/logs/new/screen-n-net.txt.gz?#_2016-03-07_11_08_44_475

It almost seems like something is locking things up?

[Markus Zoeller (markus_z) (mzoeller)]

Adding "gate-failure" tag as this issue got noted in the gate.

[Sean Dague (sdague)]

This is not a nova issue, this is an oslo.messaging failure. The Nova API is just the first thing to get called.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/292313

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/292181
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=b6a8d51e6cdbe69b38a0c51401e7ffd07d67a9ba
Submitter: Jenkins
Branch: master

commit b6a8d51e6cdbe69b38a0c51401e7ffd07d67a9ba
Author: Davanum Srinivas <email address hidden>
Date: Sun Mar 13 20:41:01 2016 -0400

    Bump rabbit_transient_queues_ttl to 30 mins

    In I83a8d09dc0cdae24c12d7043ec810529a9ce57ab, we
    made reply and fanout queues expire instead of auto-delete
    and set the rabbit_transient_queues_ttl to 10 mins.

    In grenade, we seem to see the queues expiring just around
    the time the new side is coming up which causes havoc. There
    is no reason the rabbit_transient_queues_ttl should not be
    higher. So let's bump up the expiry to 30 mins.

    Closes-Bug: #1545002
    Change-Id: I70a29b762198129fe0a3e904d9f2a7d4242b322c

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/292313
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=f8cad0e76d1d7ed0c60b0a7c2cd6c157382f0e9a
Submitter: Jenkins
Branch: stable/mitaka

commit f8cad0e76d1d7ed0c60b0a7c2cd6c157382f0e9a
Author: Davanum Srinivas <email address hidden>
Date: Sun Mar 13 20:41:01 2016 -0400

    Bump rabbit_transient_queues_ttl to 30 mins

    In I83a8d09dc0cdae24c12d7043ec810529a9ce57ab, we
    made reply and fanout queues expire instead of auto-delete
    and set the rabbit_transient_queues_ttl to 10 mins.

    In grenade, we seem to see the queues expiring just around
    the time the new side is coming up which causes havoc. There
    is no reason the rabbit_transient_queues_ttl should not be
    higher. So let's bump up the expiry to 30 mins.

    Closes-Bug: #1545002
    Change-Id: I70a29b762198129fe0a3e904d9f2a7d4242b322c

[Davanum Srinivas (DIMS) (dims-v)]

This issue was fixed in the openstack/oslo.messaging 4.5.1 release.

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/oslo.messaging 5.0.0 release.