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

Bug #1399257 reported by Kiall Mac Innes
26
This bug affects 5 people
Affects Status Importance Assigned to Milestone
Designate
High
Graham Hayes
Ironic
Fix Released
Low
Chris Krelle
Sahara
Fix Released
Low
Andrew Lazarev
oslo.messaging
High
Mehdi Abaakouk

Bug Description

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.

Kiall Mac Innes (kiall)
summary: - "Timed out waiting for RPC response" with oslo.messaging 1.5.0
+ Spurious + Repeated "Timed out waiting for RPC response" with
+ oslo.messaging 1.5.0
description: updated
Revision history for this message
Graham Hayes (grahamhayes) wrote :

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

Revision history for this message
Graham Hayes (grahamhayes) wrote :

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

Changed in oslo.messaging:
status: New → Confirmed
importance: Undecided → High
Mehdi Abaakouk (sileht)
Changed in oslo.messaging:
assignee: nobody → Mehdi Abaakouk (sileht)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to oslo.messaging (master)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

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

Changed in oslo.messaging:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to oslo.messaging (master)

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

Mehdi Abaakouk (sileht)
Changed in oslo.messaging:
milestone: none → next-kilo
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to oslo.messaging (master)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

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

Changed in oslo.messaging:
status: In Progress → Fix Committed
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to oslo.messaging (master)

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

aeva black (tenbrae)
Changed in ironic:
status: New → Triaged
importance: Undecided → Low
Revision history for this message
Graham Hayes (grahamhayes) wrote :

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

Changed in designate:
status: Triaged → Fix Committed
assignee: nobody → Graham Hayes (grahamhayes)
milestone: none → kilo-1
Revision history for this message
Kiall Mac Innes (kiall) wrote :

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

Changed in designate:
status: Fix Committed → Triaged
Kiall Mac Innes (kiall)
Changed in designate:
milestone: kilo-1 → kilo-2
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to oslo.messaging (stable/juno)

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

Revision history for this message
aeva black (tenbrae) wrote :

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.

Changed in ironic:
assignee: nobody → Devananda van der Veen (devananda)
milestone: none → kilo-2
Revision history for this message
aeva black (tenbrae) wrote :

Not sure why it didn't post automatically --

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

Changed in ironic:
assignee: Devananda van der Veen (devananda) → Chris Krelle (nobodycam)
status: Triaged → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to ironic (master)

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

Changed in ironic:
status: In Progress → Fix Committed
Changed in sahara:
status: New → Confirmed
assignee: nobody → Andrew Lazarev (alazarev)
importance: Undecided → Low
milestone: none → kilo-2
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to sahara (master)

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

Changed in sahara:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to sahara (master)

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

Changed in sahara:
status: In Progress → Fix Committed
Changed in oslo.messaging:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in sahara:
status: Fix Committed → Fix Released
Kiall Mac Innes (kiall)
Changed in designate:
status: Triaged → Fix Committed
Thierry Carrez (ttx)
Changed in designate:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in ironic:
status: Fix Committed → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to oslo.messaging (stable/icehouse)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on oslo.messaging (stable/juno)

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.

Thierry Carrez (ttx)
Changed in sahara:
milestone: kilo-2 → 2015.1.0
Thierry Carrez (ttx)
Changed in ironic:
milestone: kilo-2 → 2015.1.0
Thierry Carrez (ttx)
Changed in designate:
milestone: kilo-2 → 2015.1.0
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to oslo.messaging (stable/icehouse)

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

tags: added: in-stable-icehouse
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers