Spurious + Repeated "Timed out waiting for RPC response" with oslo.messaging 1.5.0

[Kiall Mac Innes]

On an idle Designate+DevStack install, with oslo.messaging 1.5.0, we see these log entries on all consumer services every second or so:

2014-12-04 15:37:38.497 DEBUG oslo.messaging._drivers.impl_rabbit [-] Timed out waiting for RPC response: timed out from (pid=12693) _raise_timeout_if_deadline_is_reached /usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py:676

These log entries seem to cause no harm, as everything is still functional, but will continue logging every second or so forever.

[Graham Hayes (grahamhayes)]

Confirmed this is new in olso.messaging 1.5.0, downgraded to 1.4.1 and the messages no longer appear

[Graham Hayes (grahamhayes)]

also, occurs in oslo.messaging 1.5.1 (in Designate anyway)

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/139980

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/139981

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit 023b7f44e2ccd77a7e9ee9ee78431a4646c88f13
Author: Mehdi Abaakouk <email address hidden>
Date: Mon Dec 8 10:56:52 2014 +0100

    rabbit: more precise iterconsume timeout

    The iterconsume always set the timeout of kombu to 1 second
    even the requested timeout more precise or < 1 second.

    This change fixes that.

    Related bug: #1400268
    Related bug: #1399257

    Change-Id: I157dab80cdb4afcf9a5f26fa900f96f0696db502

[OpenStack Infra (hudson-openstack)]

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

commit 43a9dc1de58df6559be02dc9f9ae3f5eeb12cb7a
Author: Mehdi Abaakouk <email address hidden>
Date: Mon Dec 8 10:28:12 2014 +0100

    qpid: honor iterconsume timeout

    The qpid driver must always honor the timeout passed the iterconsume
    method, this change fixes that.

    Related bug: #1400268
    Related bug: #1399257

    Change-Id: I8f267fc8b5a7abc852f0caf84d1e7c2c342ba951

[OpenStack Infra (hudson-openstack)]

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

commit 15aa5cbda810ef3f757e9e54280fd8216dc9ef7d
Author: Mehdi Abaakouk <email address hidden>
Date: Mon Dec 8 10:52:45 2014 +0100

    The executor doesn't need to set the timeout

    It's up to the driver to set a suitable timeout for polling the broker,
    this one can be different that the one requested by the driver
    caller as long as the caller timeout is respected.

    This change also adds a new driver listener API, to be able
    to stop it cleanly, specially in case of timeout=None.

    Closes bug: #1400268
    Closes bug: #1399257
    Change-Id: I674c0def1efb420c293897d49683593a0b10e291

[Graham Hayes (grahamhayes)]

Fixed in Designate with commit http://git.openstack.org/cgit/openstack/designate/commit/?id=1f046a25135efac9e070858d20a56eae84edf9ec

Changed oslo.messaging's default log level
Moved the default log level for oslo.messaging to WARN,
reducing the amount of cluter in the logs

Change-Id: Icde2f6f52d6b72162805424434ebbd458c0af10b
Notes

Notes (review):
    Verified+2: Jenkins
    Code-Review+2: Kiall Mac Innes <email address hidden>
    Code-Review+2: Vinod Mangalpally <email address hidden>
    Workflow+1: Vinod Mangalpally <email address hidden>
    Submitted-by: Jenkins
    Submitted-at: Mon, 15 Dec 2014 21:59:15 +0000
    Reviewed-on: https://review.openstack.org/141889
    Project: openstack/designate
    Branch: refs/heads/master

[Kiall Mac Innes (kiall)]

The fix is oslo.messaging 1.5.1, hiding the logs doesn't fix the underlying issue for people who want debug level etc...

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/juno
Review: https://review.openstack.org/143805

[aeva black (tenbrae)]

This does not appear to be addressed by oslo.messaging=1.5.1 and so I have pushed a similar work-around (change the default log level for oslo.messaging) to Ironic.

[aeva black (tenbrae)]

Not sure why it didn't post automatically --

Review: https://review.openstack.org/145361

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/145361
Committed: https://git.openstack.org/cgit/openstack/ironic/commit/?id=7ec094c2c26da3fec809e1fab07426ec631570fa
Submitter: Jenkins
Branch: master

commit 7ec094c2c26da3fec809e1fab07426ec631570fa
Author: Devananda van der Veen <email address hidden>
Date: Tue Jan 6 14:13:54 2015 -0800

    Hide oslo.messaging DEBUG logs by default

    This change moves the default log level for oslo.messaging
    from DEBUG to INFO.

    This hides the once-per-second debug log lines which started in
    oslo.messaging 1.5.0.

    Change-Id: Ia310a5430dcb0a38f8653bbdf5caac82b6990414
    Closes-bug: #1399257

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/146965
Committed: https://git.openstack.org/cgit/openstack/sahara/commit/?id=09a652b655a12fe9cb90903fc81e2e54bd004cd7
Submitter: Jenkins
Branch: master

commit 09a652b655a12fe9cb90903fc81e2e54bd004cd7
Author: Andrew Lazarev <email address hidden>
Date: Tue Jan 13 11:42:20 2015 -0800

    Hide oslo.messaging DEBUG logs by default

    This change moves the default log level for oslo.messaging
    from DEBUG to INFO.

    This hides the once-per-second debug log lines which started in
    oslo.messaging 1.5.0.

    Change-Id: Ic55c27d80d634b794e3dda418fb1ae0decee6974
    Closes-bug: #1399257

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/173717

[OpenStack Infra (hudson-openstack)]

Change abandoned by Mehdi Abaakouk (sileht) (<email address hidden>) on branch: stable/juno
Review: https://review.openstack.org/143805
Reason: https://review.openstack.org/#/c/161119/

and

https://review.openstack.org/#/c/161120/

have replaced this changes.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/173717
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=b58180210145e1c804ec496576d6bb2caabc68ef
Submitter: Jenkins
Branch: stable/icehouse

commit b58180210145e1c804ec496576d6bb2caabc68ef
Author: Mehdi Abaakouk <email address hidden>
Date: Mon Dec 8 10:56:52 2014 +0100

    rabbit: more precise iterconsume timeout

    The iterconsume always set the timeout of kombu to 1 second
    even the requested timeout more precise or < 1 second.

    This change fixes that.

    Related bug: #1400268
    Related bug: #1399257
    Related-bug: #1338732

    (cherry picked from commit 023b7f44e2ccd77a7e9ee9ee78431a4646c88f13)

    Conflicts:
     oslo/messaging/_drivers/amqpdriver.py
     oslo/messaging/_drivers/impl_rabbit.py

    Change-Id: I157dab80cdb4afcf9a5f26fa900f96f0696db502