lvchange -a causing RPC timeouts between c-api and c-vol on inap hosts in CI

[Lee Yarwood]

https://zuul.opendev.org/t/openstack/build/15d948dfe4184df38bcea92d42378ee0/log/zuul-info/inventory.yaml

  hosts:
    compute1:
      ansible_connection: ssh
      ansible_host: 198.72.124.190
      ansible_port: 22
      ansible_python_interpreter: auto
      ansible_user: zuul
      nodepool:
        az: nova
        cloud: inap
        host_id: 3c9c8f46f2a6c8e8daa2acdcef7613a60c986460cc415e7e7aca5f7a
        interface_ip: 198.72.124.190
        label: ubuntu-bionic
        private_ipv4: 198.72.124.190
        provider: inap-mtl01
        public_ipv4: 198.72.124.190
        public_ipv6: ''
        region: mtl01
    controller:
      ansible_connection: ssh
      ansible_host: 198.72.124.210
      ansible_port: 22
      ansible_python_interpreter: auto
      ansible_user: zuul
      nodepool:
        az: nova
        cloud: inap
        host_id: 3c9c8f46f2a6c8e8daa2acdcef7613a60c986460cc415e7e7aca5f7a
        interface_ip: 198.72.124.210
        label: ubuntu-bionic
        private_ipv4: 198.72.124.210
        provider: inap-mtl01
        public_ipv4: 198.72.124.210
        public_ipv6: ''
        region: mtl01

https://zuul.opendev.org/t/openstack/build/15d948dfe4184df38bcea92d42378ee0/log/controller/logs/screen-c-vol.txt#1463

Apr 15 15:31:28.343392 ubuntu-bionic-inap-mtl01-0015954199 cinder-volume[26482]: DEBUG oslo_concurrency.processutils [req-f0848f9c-e74d-4014-8a3d-b869976fc965 req-2075521f-1981-48c8-b307-d9d8f961e9d6 tempest-UpdateMultiattachVolumeNegativeTest-1535704675 None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K stack-volumes-lvmdriver-1/volume-76ef6bca-3a03-4b38-9cee-f5a68a68e315 {{(pid=26774) execute /usr/local/lib/python3.6/dist-packages/oslo_concurrency/processutils.py:372}}
Apr 15 15:31:28.356005 ubuntu-bionic-inap-mtl01-0015954199 sudo[13082]: stack : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/local/bin/cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K stack-volumes-lvmdriver-1/volume-76ef6bca-3a03-4b38-9cee-f5a68a68e315
[..]
Apr 15 15:32:50.100520 ubuntu-bionic-inap-mtl01-0015954199 cinder-volume[26482]: DEBUG oslo_concurrency.processutils [req-f0848f9c-e74d-4014-8a3d-b869976fc965 req-2075521f-1981-48c8-b307-d9d8f961e9d6 tempest-UpdateMultiattachVolumeNegativeTest-1535704675 None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K stack-volumes-lvmdriver-1/volume-76ef6bca-3a03-4b38-9cee-f5a68a68e315" returned: 0 in 81.758s {{(pid=26774) execute /usr/local/lib/python3.6/dist-packages/oslo_concurrency/processutils.py:409}}

This has the knock on effect of causing c-api to timeout, delete the attachment that c-vol is still trying to update and return a 500 error back to n-cpu.

[Lee Yarwood (lyarwood)]

FWIW this might be a duplicate of https://bugs.launchpad.net/cinder/+bug/1814916 but I'm not seeing the premature timeout Matt reported in that bug, the timeout is valid in this case.

[Lee Yarwood (lyarwood)]

http://paste.openstack.org/show/792214/ - Full logs.

[Lee Yarwood (lyarwood)]

Another example below, I'll try to work out a recheck query for this now.

https://zuul.opendev.org/t/openstack/build/56eea988a7684222a750bf5623134d0e/log/controller/logs/screen-n-cpu.txt

54045 Dec 22 22:05:49.380188 fedora-32-vexxhost-ca-ymq-1-0022317164 nova-compute[99839]: ERROR nova.volume.cinder [None req-6fbe3107-470a-4158-83a9-2d56ed6f4e11 tempest-AttachVolumeMultiAttachTest-2040614977 tempest-AttachVolumeMultiAttachTest-2040614977] Update attachment failed for attachment 4f396696-0740-47a5-870c-0776285f861a. Error: Internal Server Error (HTTP 500) Code: 500: cinderclient.exceptions.ClientException: Internal Server Error (HTTP 500)

https://zuul.opendev.org/t/openstack/build/56eea988a7684222a750bf5623134d0e/log/controller/logs/screen-c-api.txt

23124 Dec 22 22:04:48.586155 fedora-32-vexxhost-ca-ymq-1-0022317164 <email address hidden>[100676]: DEBUG cinder.coordination [req-6fbe3107-470a-4158-83a9-2d56ed6f4e11 req-d62dbd0b-5973-45b7-911e-6c1ba606cdce tempest-AttachVolumeMultiAttachTest-2040614977 tempest-AttachVo lumeMultiAttachTest-2040614977] Lock "b'cinder-attachment_update-87862c54-bdb9-49f6-a04c-fa8ed7e791b8-fedora-32-vexxhost-ca-ymq-1-0022317164'" acquired by "attachment_update" :: waited 0.123s {{(pid=100676) _synchronized /opt/stack/cinder/cinder/coordination.py:146}}
[..]
24165 Dec 22 22:05:49.389223 fedora-32-vexxhost-ca-ymq-1-0022317164 <email address hidden>[100676]: ERROR cinder.api.v3.attachments oslo_messaging.exceptions.MessagingTimeout: Timed out waiting for a reply to message ID 32395480a3264e83a8367e882b2678d2

https://zuul.opendev.org/t/openstack/build/56eea988a7684222a750bf5623134d0e/log/controller/logs/screen-c-vol.txt

5905 Dec 22 22:04:48.642754 fedora-32-vexxhost-ca-ymq-1-0022317164 cinder-volume[101743]: DEBUG oslo_concurrency.processutils [req-6fbe3107-470a-4158-83a9-2d56ed6f4e11 req-d62dbd0b-5973-45b7-911e-6c1ba606cdce tempest-AttachVolumeMultiAttachTest-2040614977 None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K stack-volumes-lvmdriver-1/volume-87862c54-bdb9-49f6-a04c-fa8ed7e791b8 {{(pid=101743) execute /usr/local/lib/python3.8/site-packages/oslo_concurrency/processutils.py:384}}
[..]
Dec 22 22:05:56.037822 fedora-32-vexxhost-ca-ymq-1-0022317164 cinder-volume[101743]: DEBUG oslo_concurrency.processutils [req-6fbe3107-470a-4158-83a9-2d56ed6f4e11 req-d62dbd0b-5973-45b7-911e-6c1ba606cdce tempest-AttachVolumeMultiAttachTest-2040614977 None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K stack-volumes-lvmdriver-1/volume-87862c54-bdb9-49f6-a04c-fa8ed7e791b8" returned: 0 in 67.396s {{(pid=101743) execute /usr/local/lib/python3.8/site-packages/oslo_concurrency/processutils.py:422}}

[Lee Yarwood (lyarwood)]

https://review.opendev.org/c/openstack/devstack/+/768323 to workaround this for now.