libvirt: test_attach_volume_shelved_or_offload_server times out waiting for device detach (which fails)

This isn't a very common failure:

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Failed%20to%20detach%20volume%5C%22%20AND%20message%3A%5C%22libvirtError%3A%20End%20of%20file%20while%20reading%20data%3A%20Input%2Foutput%20error%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22&from=7d

2 hits in 7 days, check and gate.

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

(From an IRC interaction with Dan Berrangé [danpb] and Matthew Booth
[mdbooth].)

Dan has done some log analysis. Specifically from the below log message
(from libvirt debug logs), he could deduce some clues about root cause:

   [...]
   2017-03-16 01:01:33.096+0000: 26064: debug : virNetlinkStartup:138 : Running global netlink initialization
   [...]

[danpb]: "The above is showing libvirtd has been restarted, so
presumably it crashed, causing Nova to see the EOF. We should probably
make sure OpenStack CI does *not* restart things, as it just hides the
obvious failure!"

And after looking at the error from 'syslog':

    [...]
    Mar 16 01:01:32 ubuntu-xenial-infracloud-vanilla-7903827 libvirtd[17211]: *** Error in `/usr/sbin/libvirtd': malloc(): memory corruption: 0x0000562d21527f50 ***
    [...]

[danpb]: "So it's a bug in libvirt in Ubuntu. Which is probably fixed
sometime after 1.3.1."

NOTE (kashyap): There is an existing bug for the above memory corruption
here:

    https://bugs.launchpad.net/nova/+bug/1643911/ -- 'libvirt randomly
    crashes on xenial nodes with "*** Error in `/usr/sbin/libvirtd':
    malloc(): memory corruption:"'

After some code inspection, Dan pointed out two potential commits from
libvirt that are likely candidates to have fixed the issue:

(1) One possible candidate in 1.3.2 would be:

    'qemu: Process monitor EOF in a job' --
    https://libvirt.org/git/?p=libvirt.git;a=commit;h=8c9ff99

(2) This might be relevant, too, but less likely:

    ;qemu: Avoid calling qemuProcessStop without a job' --
    https://libvirt.org/git/?p=libvirt.git;a=commit;h=81f50cb

He notes further: "the first [libvirt] commit hash noted above (8c9ff99)
is something you'd want to encourage Ubuntu maintainers to add as I
don't see it in their patches right now."

Hi Kashyap,
I appreciate your check with Dan.

I agree that 8c9ff99 is a reasonable fix in general.
The backporting of this series from Jiri can be done two ways.
A) On one hand I could either try to pick 8c9ff996 which implies at least 4d0c535a to work reasonably.
B) Or OTOH I could try to leverage the full series of Jiri - both changes recommended by Dan, but since that means more dependencies it is essentially all of the series = 17c4312c..81f50cb92

A) is less invasive, while B) is certainly more complete but might hide some of its dependencies.
I prepared both in PPAs and will drive some basic tests on them now.
Once they pass tests I would come back here recommend one or both of them to be tried in your context.

In preparation I wanted to ask to what extend you could test from a ppa in your environment?

Ok, basic verifications were all good, I faced no issues on automated tests on all sort of libvirt interactions as well as migrations from/to/in-between xenial. I also have not seen any arch difference.

This means I would have two ppa's for you to try:
- Backport of the minimal recommended fix: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/2620
- Backport of the full series of related fixes: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/2619

Is there a reasonable way to expose that in your infrastructure - although I'm afraid "2 hits in 7 days" make this hard to feel 100% sure that "0 hits in 7 days" is a safe validation. But you know your environment best - is there a way to test these to gain some confidence - in this being a fix as well as not causing another regression?

Reviewed: https://review.openstack.org/446601
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=33d0b029f1927a455b6b00f41b4d83ed19a694ff
Submitter: Jenkins
Branch: master

commit 33d0b029f1927a455b6b00f41b4d83ed19a694ff
Author: Matt Riedemann <email address hidden>
Date: Thu Mar 16 11:35:04 2017 -0400

    libvirt: add debug logging in detach_device_with_retry

    When we hit failures in this method it can be hard to
    sort out from a traceback what actually happened, and
    if we failed from the intial detach or if we failed
    during the retry loop.

    This patch adds some simple debug logging statements
    to help give context to what's going on when we need
    to debug a failure in this operation.

    Change-Id: I392192f139ced077664e54469eead0b0df9ebf4a
    Related-Bug: #1673483

(9:56:32 AM) mriedem: clarkb: sorry if you guys already talked about this, but in https://bugs.launchpad.net/nova/+bug/1673483 there are comments from ubuntu devs that backports have been made to some packages and are available for testing,
(9:56:34 AM) openstack: Launchpad bug 1673483 in libvirt (Ubuntu) "libvirt: test_attach_volume_shelved_or_offload_server times out waiting for device detach (which fails)" [Medium,Triaged]
(9:56:45 AM) mriedem: clarkb: it's not clear to me if we have a way to hook testing packages in our CI?
(9:56:48 AM) clarkb: mriedem: yes but that bug isn't a problem
(9:56:57 AM) clarkb: mriedem: we have 3 other libvirt bugs that are actually major issues
(9:57:12 AM) clarkb: mriedem: and I mentioned it would be simple to modify devstack to use a ppa or just wget and dpkg -i
(9:57:47 AM) mriedem: ok, and we don't have fixes identified to backport for 1.3.3 in xenial LTS for testing yet
(9:58:06 AM) jamespage: clarkb: can I get context please on those three bugs
(9:58:16 AM) jamespage: refs would be ok for now
jamespage jamespd
(9:58:30 AM) jamespage: guessing one is bug 1643911
(9:58:30 AM) mriedem: jamespage: https://bugs.launchpad.net/nova/+bug/1643911/
(9:58:31 AM) openstack: bug 1643911 in OpenStack Compute (nova) "libvirt randomly crashes on xenial nodes with "*** Error in `/usr/sbin/libvirtd': malloc(): memory corruption:"" [Medium,Confirmed] https://launchpad.net/bugs/1643911
(9:58:47 AM) clarkb: jamespage: its the three elastic recheck links I gave you above
(9:58:52 AM) clarkb: jamespage: they have links to launchpad
(9:58:56 AM) jamespage: clarkb: ta

(9:46:30 AM) clarkb: jamespage: fwiw we also have http://status.openstack.org/elastic-recheck/index.html#1643911 http://status.openstack.org/elastic-recheck/index.html#1638982 http://status.openstack.org/elastic-recheck/index.html#1646779 which are our top failures according to elastic-recheck

I updated the other potentially related bug to encourage considering ways to test the PPAs mentioned in comment #5

The scope of "seems potentially related" are these bugs:
- bug 1646779
- bug 1643911
- bug 1638982
- bug 1673483 (= this one)

Related fix proposed to branch: stable/ocata
Review: https://review.openstack.org/472308

Related fix proposed to branch: stable/newton
Review: https://review.openstack.org/472344

Reviewed: https://review.openstack.org/472308
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=527834dea884d0663c1cf5f075c850e6f4a4eeaa
Submitter: Jenkins
Branch: stable/ocata

commit 527834dea884d0663c1cf5f075c850e6f4a4eeaa
Author: Matt Riedemann <email address hidden>
Date: Thu Mar 16 11:35:04 2017 -0400

    libvirt: add debug logging in detach_device_with_retry

    When we hit failures in this method it can be hard to
    sort out from a traceback what actually happened, and
    if we failed from the intial detach or if we failed
    during the retry loop.

    This patch adds some simple debug logging statements
    to help give context to what's going on when we need
    to debug a failure in this operation.

    Change-Id: I392192f139ced077664e54469eead0b0df9ebf4a
    Related-Bug: #1673483
    (cherry picked from commit 33d0b029f1927a455b6b00f41b4d83ed19a694ff)

Reviewed: https://review.openstack.org/472344
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=58e7f8c3253d6f22a60ed567d95bdd4de64da5f1
Submitter: Jenkins
Branch: stable/newton

commit 58e7f8c3253d6f22a60ed567d95bdd4de64da5f1
Author: Matt Riedemann <email address hidden>
Date: Thu Mar 16 11:35:04 2017 -0400

    libvirt: add debug logging in detach_device_with_retry

    When we hit failures in this method it can be hard to
    sort out from a traceback what actually happened, and
    if we failed from the intial detach or if we failed
    during the retry loop.

    This patch adds some simple debug logging statements
    to help give context to what's going on when we need
    to debug a failure in this operation.

    Change-Id: I392192f139ced077664e54469eead0b0df9ebf4a
    Related-Bug: #1673483
    (cherry picked from commit 33d0b029f1927a455b6b00f41b4d83ed19a694ff)
    (cherry picked from commit 0e21bbde99b765f97100c832d3a81df1fee5b23b)