yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1831697] [NEW] 'amqp.exceptions.ConnectionForced: Too many heartbeats missed' in nova api log

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Sam Wan <sam.wan@xxxxxxx>
Date: Wed, 05 Jun 2019 06:25:57 -0000
Reply-to: Bug 1831697 <1831697@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

Got error message related to rabbitmq in nova api log
======
Jun 03 17:08:12.865089 UnityiSCSISlave devstack@n-api.service[30882]: [pid: 30884|app: 0|req: 24/46] 10.228.225.234 () {60 vars in 1304 bytes} [Mon Jun  3 17:08:12 2019] POST /compute/v2.1/servers/7770c3ae-c56e-462c-80da-ea7b1eb43f9b/os-volume_attachments => generated 194 bytes in 340 msecs (HTTP/1.1 200) 9 headers in 357 bytes (2 switches on core 0)
Jun 03 17:10:12.989956 UnityiSCSISlave devstack@n-api.service[30882]: INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 104] Connection reset by peer
Jun 03 17:10:12.990695 UnityiSCSISlave devstack@n-api.service[30882]: Mon Jun  3 17:10:12 2019 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /compute/v2.1/servers/b19aaaad-d18f-4288-8f49-259c70a52685/os-volume_attachments (ip 10.228.225.234) !!!
Jun 03 17:10:12.997481 UnityiSCSISlave devstack@n-api.service[30882]: WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: amqp.exceptions.ConnectionForced: Too many heartbeats missed
Jun 03 17:10:13.002452 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG nova.api.openstack.wsgi [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Action: 'create', calling method: <bound method VolumeAttachmentController.create of <nova.api.openstack.compute.volumes.VolumeAttachmentController object at 0x7fe10f2e8048>>, body: {"volumeAttachment": {"volumeId": "0d6e3395-e4b1-41f4-8d0b-cab421296ca7"}} {{(pid=30883) _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:520}}
Jun 03 17:10:13.003914 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG nova.compute.api [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] [instance: b19aaaad-d18f-4288-8f49-259c70a52685] Fetching instance by UUID {{(pid=30883) get /opt/stack/new/nova/nova/compute/api.py:2563}}
Jun 03 17:10:13.010807 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.000s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:327}}
Jun 03 17:10:13.019659 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" released by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:339}}
Jun 03 17:10:13.019659 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.000s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:327}}
Jun 03 17:10:13.019659 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" released by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:339}}
Jun 03 17:10:13.377583 UnityiSCSISlave devstack@n-api.service[30882]: INFO nova.api.openstack.requestlog [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] 10.228.225.234 "POST /compute/v2.1/servers/b19aaaad-d18f-4288-8f49-259c70a52685/os-volume_attachments" status: 200 len: 194 microversion: 2.60 time: 0.388941
Jun 03 17:10:13.377583 UnityiSCSISlave devstack@n-api.service[30882]: [pid: 30883|app: 0|req: 23/47] 10.228.225.234 () {62 vars in 1345 bytes} [Mon Jun  3 17:10:12 2019] POST /compute/v2.1/servers/b19aaaad-d18f-4288-8f49-259c70a52685/os-volume_attachments => generated 194 bytes in 390 msecs (HTTP/1.1 200) 9 headers in 359 bytes (1 switches on core 0)
Jun 03 17:12:17.122134 UnityiSCSISlave devstack@n-api.service[30882]: ERROR oslo.messaging._drivers.impl_rabbit [-] [2bf667ab-913d-41d7-8675-bccdfdfe522c] AMQP server on 10.228.225.234:5672 is unreachable: <RecoverableConnectionError: unknown error>. Trying again in 1 seconds.: amqp.exceptions.RecoverableConnectionError: <RecoverableConnectionError: unknown error>
Jun 03 17:12:17.126554 UnityiSCSISlave devstack@n-api.service[30882]: INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Server unexpectedly closed connection
Jun 03 17:12:17.126688 UnityiSCSISlave devstack@n-api.service[30882]: Mon Jun  3 17:12:17 2019 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /compute/v2.1/servers/7770c3ae-c56e-462c-80da-ea7b1eb43f9b/os-volume_attachments/cf24983a-ed4b-4eda-8da5-bcec65cc973d (ip 10.228.225.234) !!!
Jun 03 17:12:17.134529 UnityiSCSISlave devstack@n-api.service[30882]: INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Server unexpectedly closed connection
Jun 03 17:12:17.134582 UnityiSCSISlave devstack@n-api.service[30882]: Mon Jun  3 17:12:17 2019 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /compute/v2.1/servers/7770c3ae-c56e-462c-80da-ea7b1eb43f9b/os-volume_attachments/cf24983a-ed4b-4eda-8da5-bcec65cc973d (ip 10.228.225.234) !!!
======

detailed information:
http://publiclogs.emc.com/95/613695/6/check/DellEMC_Unity_iSCSI/b497650/DellEMC_Unity_iSCSI/328/logs/screen-n-api.txt.gz

** Affects: nova
     Importance: Undecided
         Status: New


** Tags: nova-api

** Tags added: nova-api

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1831697

Title:
  'amqp.exceptions.ConnectionForced: Too many heartbeats missed' in nova
  api log

Status in OpenStack Compute (nova):
  New

Bug description:
  Got error message related to rabbitmq in nova api log
  ======
  Jun 03 17:08:12.865089 UnityiSCSISlave devstack@n-api.service[30882]: [pid: 30884|app: 0|req: 24/46] 10.228.225.234 () {60 vars in 1304 bytes} [Mon Jun  3 17:08:12 2019] POST /compute/v2.1/servers/7770c3ae-c56e-462c-80da-ea7b1eb43f9b/os-volume_attachments => generated 194 bytes in 340 msecs (HTTP/1.1 200) 9 headers in 357 bytes (2 switches on core 0)
  Jun 03 17:10:12.989956 UnityiSCSISlave devstack@n-api.service[30882]: INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 104] Connection reset by peer
  Jun 03 17:10:12.990695 UnityiSCSISlave devstack@n-api.service[30882]: Mon Jun  3 17:10:12 2019 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /compute/v2.1/servers/b19aaaad-d18f-4288-8f49-259c70a52685/os-volume_attachments (ip 10.228.225.234) !!!
  Jun 03 17:10:12.997481 UnityiSCSISlave devstack@n-api.service[30882]: WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: amqp.exceptions.ConnectionForced: Too many heartbeats missed
  Jun 03 17:10:13.002452 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG nova.api.openstack.wsgi [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Action: 'create', calling method: <bound method VolumeAttachmentController.create of <nova.api.openstack.compute.volumes.VolumeAttachmentController object at 0x7fe10f2e8048>>, body: {"volumeAttachment": {"volumeId": "0d6e3395-e4b1-41f4-8d0b-cab421296ca7"}} {{(pid=30883) _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:520}}
  Jun 03 17:10:13.003914 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG nova.compute.api [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] [instance: b19aaaad-d18f-4288-8f49-259c70a52685] Fetching instance by UUID {{(pid=30883) get /opt/stack/new/nova/nova/compute/api.py:2563}}
  Jun 03 17:10:13.010807 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.000s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:327}}
  Jun 03 17:10:13.019659 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" released by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:339}}
  Jun 03 17:10:13.019659 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.000s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:327}}
  Jun 03 17:10:13.019659 UnityiSCSISlave devstack@n-api.service[30882]: DEBUG oslo_concurrency.lockutils [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] Lock "ec47ef5d-3126-4ae6-870a-9bbb032f4475" released by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=30883) inner /usr/local/lib/python3.6/dist-packages/oslo_concurrency/lockutils.py:339}}
  Jun 03 17:10:13.377583 UnityiSCSISlave devstack@n-api.service[30882]: INFO nova.api.openstack.requestlog [None req-23cd59d1-7ec5-422e-aaac-f1f43485c144 tempest-TestMultiAttachVolumeSwap-1395968741 tempest-TestMultiAttachVolumeSwap-1395968741] 10.228.225.234 "POST /compute/v2.1/servers/b19aaaad-d18f-4288-8f49-259c70a52685/os-volume_attachments" status: 200 len: 194 microversion: 2.60 time: 0.388941
  Jun 03 17:10:13.377583 UnityiSCSISlave devstack@n-api.service[30882]: [pid: 30883|app: 0|req: 23/47] 10.228.225.234 () {62 vars in 1345 bytes} [Mon Jun  3 17:10:12 2019] POST /compute/v2.1/servers/b19aaaad-d18f-4288-8f49-259c70a52685/os-volume_attachments => generated 194 bytes in 390 msecs (HTTP/1.1 200) 9 headers in 359 bytes (1 switches on core 0)
  Jun 03 17:12:17.122134 UnityiSCSISlave devstack@n-api.service[30882]: ERROR oslo.messaging._drivers.impl_rabbit [-] [2bf667ab-913d-41d7-8675-bccdfdfe522c] AMQP server on 10.228.225.234:5672 is unreachable: <RecoverableConnectionError: unknown error>. Trying again in 1 seconds.: amqp.exceptions.RecoverableConnectionError: <RecoverableConnectionError: unknown error>
  Jun 03 17:12:17.126554 UnityiSCSISlave devstack@n-api.service[30882]: INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Server unexpectedly closed connection
  Jun 03 17:12:17.126688 UnityiSCSISlave devstack@n-api.service[30882]: Mon Jun  3 17:12:17 2019 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /compute/v2.1/servers/7770c3ae-c56e-462c-80da-ea7b1eb43f9b/os-volume_attachments/cf24983a-ed4b-4eda-8da5-bcec65cc973d (ip 10.228.225.234) !!!
  Jun 03 17:12:17.134529 UnityiSCSISlave devstack@n-api.service[30882]: INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Server unexpectedly closed connection
  Jun 03 17:12:17.134582 UnityiSCSISlave devstack@n-api.service[30882]: Mon Jun  3 17:12:17 2019 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /compute/v2.1/servers/7770c3ae-c56e-462c-80da-ea7b1eb43f9b/os-volume_attachments/cf24983a-ed4b-4eda-8da5-bcec65cc973d (ip 10.228.225.234) !!!
  ======

  detailed information:
  http://publiclogs.emc.com/95/613695/6/check/DellEMC_Unity_iSCSI/b497650/DellEMC_Unity_iSCSI/328/logs/screen-n-api.txt.gz

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1831697/+subscriptions
Follow ups

[Bug 1831697] Re: 'amqp.exceptions.ConnectionForced: Too many heartbeats missed' in nova api log
From: Sam Wan, 2019-06-17