libvirt hangs after utah workload is aborted
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
libvirt (Ubuntu) |
New
|
Undecided
|
Unassigned |
Bug Description
Reported by Paride on s390x (s1lp4) sometimes libvirt becomes unresponsive when he aborted the UTAH automation.
This bug shall collect log/analysis data until we can debug and fix it.
Christian Ehrhardt (paelzer) wrote : | #1 |
Christian Ehrhardt (paelzer) wrote : | #2 |
All threads are blocked lock related
Id Target Id Frame
* 1 Thread 0x3ff9a75d130 (LWP 6518) "libvirtd" 0x000003ff9a011158 in __lll_lock_wait (futex=
2 Thread 0x3ff956ff910 (LWP 6519) "libvirtd" 0x000003ff9a00d936 in futex_wait_
3 Thread 0x3ff94efe910 (LWP 6520) "libvirtd" 0x000003ff9a00d936 in futex_wait_
4 Thread 0x3ff946fd910 (LWP 6521) "libvirtd" 0x000003ff9a00d936 in futex_wait_
5 Thread 0x3ff8befc910 (LWP 6522) "libvirtd" 0x000003ff9a00d936 in futex_wait_
6 Thread 0x3ff93efc910 (LWP 6523) "libvirtd" 0x000003ff9a00d936 in futex_wait_
7 Thread 0x3ff936fb910 (LWP 6524) "libvirtd" 0x000003ff9a00d936 in futex_wait_
8 Thread 0x3ff92efa910 (LWP 6525) "libvirtd" 0x000003ff9a00d936 in futex_wait_
9 Thread 0x3ff926f9910 (LWP 6526) "libvirtd" 0x000003ff9a00d936 in futex_wait_
10 Thread 0x3ff91ef8910 (LWP 6527) "libvirtd" 0x000003ff9a011158 in __lll_lock_wait (futex=
11 Thread 0x3ff916f7910 (LWP 6528) "libvirtd" 0x000003ff9a00d936 in futex_wait_
12 Thread 0x3ff8ad7f910 (LWP 6529) "libvirtd" 0x000003ff9a00d936 in futex_wait_
13 Thread 0x3ff8a57e910 (LWP 6530) "libvirtd" 0x000003ff9a00d936 in futex_wait_
14 Thread 0x3ff89d7d910 (LWP 6531) "libvirtd" 0x000003ff9a00d936 in futex_wait_
15 Thread 0x3ff8957c910 (LWP 6532) "libvirtd" 0x000003ff9a00d936 in futex_wait_
16 Thread 0x3ff88d7b910 (LWP 6533) "libvirtd" 0x000003ff9a00d936 in futex_wait_
Christian Ehrhardt (paelzer) wrote : | #3 |
Maybe we can learn from the backtrace which lock and why:
The two main threads are #1 and #10, here their backtraces
(gdb) bt
#0 0x000003ff9a011158 in __lll_lock_wait (futex=
#1 0x000003ff9a00a1f8 in __GI___
#2 0x000003ff9a2ff1be in virMutexLock (m=<optimized out>) at ../../.
#3 0x000003ff9a38c41c in virChrdevFDStre
#4 0x000003ff9a2a226a in virFDStreamCloseInt (st=0x3ff7403f7d0, streamAbort=
#5 0x000003ff9a3de7ca in virStreamAbort (stream=
#6 0x000002aa24ad0726 in daemonStreamHan
#7 0x000002aa24ad166c in daemonStreamHan
#8 daemonStreamEvent (st=<optimized out>, events=<optimized out>, opaque=
#9 0x000003ff9a2a2696 in virFDStreamEvent (watch=<optimized out>, fd=<optimized out>, events=14, opaque=
#10 0x000003ff9a2a1c50 in virEventPollDis
#11 virEventPollRunOnce () at ../../.
#12 0x000003ff9a2a0142 in virEventRunDefa
#13 0x000003ff9a429cd6 in virNetDaemonRun (dmn=0x2aa4659dd30) at ../../.
#14 0x000002aa24aa0400 in main (argc=<optimized out>, argv=<optimized out>) at ../../.
#10
(gdb) bt
#0 0x000003ff9a011158 in __lll_lock_wait (futex=
#1 0x000003ff9a00a1f8 in __GI___
#2 0x000003ff9a2ff1be in virMutexLock (m=<optimized out>) at ../../.
#3 0x000003ff9a2dc230 in virObjectLock (anyobj=
#4 0x000003ff9a2a4908 in virFDStreamSetI
#5 0x000003ff9a38c3ee in virChrdevFreeCl
#6 0x000003ff9a2aef5e in virHashForEach (table=
#7 0x000003ff9a38c490 in virChrdevFree (devs=<optimized out>) at ../../.
#8 0x000003ff8af0187a in qemuDomainObjPr
#9 0x000003ff9a33cc6c in virDomainObjDispose (obj=0x3ff8c001ec0) at ../../.
#10...
Christian Ehrhardt (paelzer) wrote : | #4 |
#1 is triggered via (it seems a guest goes away - qemu died and then cleanup runs after a write failed)
daemonStreamHa
-> daemonStreamHan
-> ... virChrdevFDStre
# priv = Domain's device information structure
# client stream is client=
# there would be code that is meant to avoid issues "Unable to close" if lock held
# but the log doesn't show this
#10 seems triggered via an "undefine" call
remoteDispatc
... -> virChrdevFree
... -> virFDStreamSetI
-> virObjectLock(
-> virMutexLock(
#closing all streams of a guest (requiring the same locks)
Christian Ehrhardt (paelzer) wrote : | #5 |
- test script (not triggering it yet) Edit (2.6 KiB, text/x-python)
Based on UTAH code and on the assumptions made due to the debugging I created a test script that tries to trigger the cleanup being concurrent to the undefine calls.
I aran 600 loops - so far nothing triggered, so we miss some aspect of the original issue.
Maybe the reason/way qemu dies is different?
Maybe we need a case where libvirt writes to qemu on some of those streams?
Not sure yet, for now I enable a debugging log of libvirt on s1lp4 to maybe get better insight this happens next time.
@paride - please ping me when it happens next time so we can check the logs
@paride - if anything comes to your mind how this guest abort could be different let me know
Paride Legovini (paride) wrote : | #6 |
Thanks Christian for looking into it. The next time it happens I'll try to gather some more context and follow up.
Christian Ehrhardt (paelzer) wrote : | #7 |
A debug log did not show a clear path further, but the idea came up that it might be related to either redirecting or attaching a console.
I updated the test script for that - but had no luck to trigger it.
Christian Ehrhardt (paelzer) wrote : | #8 |
- second version trying to have consoles attached still not triggering it Edit (3.1 KiB, text/x-python)
Christian Ehrhardt (paelzer) wrote : | #9 |
@Paride
Could you make the test system use:
https:/
And report if you can still hang it with that?
Paride Legovini (paride) wrote : | #10 |
Sure, I'll try and report back.
Paride Legovini (paride) wrote : | #11 |
I've been able to reproduce the hang with libvirt-* installed from the stein-staging PPA. Once again it seems that having an open console to the VM when UTAH is interrupted is a relevant factor to reproduce the problem.
I'll now try to take everything from the PPA and try again.
Paride Legovini (paride) wrote : | #12 |
It is reproducible even with all the packages grabbed from the stein PPA.
Another thing I observe is that if UTAH is killed very early in the installation process (e.g. during the network configuration stage) it doesn't hang. Killing it later in the process, when block devices are already involved, does cause the hang.
Christian Ehrhardt (paelzer) wrote : | #13 |
As just discussed, please add a few debug prints in utah so we can be sure if we are at [1] or somewhere else when you hit CTRL+C.
Please also check which code is run on CTRL+C (some cleanup maybe)?
In addition share the guest XML that is used so my erpro can become more similar.
[1]: https:/
Paride Legovini (paride) wrote : | #14 |
- utah-118-bionic-server-s390x.xml Edit (1.9 KiB, application/xml)
After adding some debugging messages to vm.py I can confirm the hang happens exactly when vm.undefine() is called at vm.py:445 [1]. But there's more: adding a debugging printout right before vm.undefine() prevents the hang from happening, confirming the idea you had since the beginning that the underlying problem is a race condition.
I am now trying to reproduce the issue without starting the VM with UTAH.
Attached to this message is the XML file defining the typical VM which is running when libvirtd hangs.
[1] https:/
Christian Ehrhardt (paelzer) wrote : | #15 |
- v3 of the test, very similar to Utah Edit (3.1 KiB, text/x-python)
Thanks, even using that on the very same machine doesn't reproduce.
I pinged you to talk about early/late abort in your cases.
Christian Ehrhardt (paelzer) wrote : | #16 |
- script to trigger the test on x86 Edit (2.8 KiB, text/x-python)
Finally I seem to have found the way to make an example.
By using automated SIGINT I usually have it triggered in the first few runs, but since it is a race it might differ per platform.
After the s390x was simplified enough the only difference to x86 where removing type=sclp and the architecture attribute.
Attaching the new script (v4)
With that I hope that more people can reproduce and help to understand it as right now I fail to spot the exact path this becomes a deadlock.
Christian Ehrhardt (paelzer) wrote : | #17 |
FYI info on all threads
Id Target Id Frame
* 1 Thread 0x7f0d087c8640 (LWP 26958) "libvirtd" __lll_lock_wait () at ../sysdeps/
2 Thread 0x7f0cfbdfb700 (LWP 26959) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
3 Thread 0x7f0cfb5fa700 (LWP 26960) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
4 Thread 0x7f0cfadf9700 (LWP 26961) "libvirtd" __lll_lock_wait () at ../sysdeps/
5 Thread 0x7f0cfa5f8700 (LWP 26962) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
6 Thread 0x7f0cf1df7700 (LWP 26963) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
7 Thread 0x7f0cf9df7700 (LWP 26964) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
8 Thread 0x7f0cf95f6700 (LWP 26965) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
9 Thread 0x7f0cf8df5700 (LWP 26966) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
10 Thread 0x7f0cf3fff700 (LWP 26967) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
11 Thread 0x7f0cf37fe700 (LWP 26968) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
12 Thread 0x7f0ccb924700 (LWP 26969) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
13 Thread 0x7f0ccb123700 (LWP 26970) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
14 Thread 0x7f0cca922700 (LWP 26971) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
15 Thread 0x7f0cca121700 (LWP 26972) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
16 Thread 0x7f0cc9920700 (LWP 26973) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_
Christian Ehrhardt (paelzer) wrote : | #18 |
Submitted upstream to get more eyeballs onto the problem
=> https:/
Christian Ehrhardt (paelzer) wrote : | #19 |
Thanks to Michal I got the suggested d63c82df8b11b58
This might need 4deed5f3c71f94a
Related is also a5445a3706b0bcb
Essentially it is a 9 patch series and we can later check if/which subset we only need.
Test builds should pop up later in https:/
Christian Ehrhardt (paelzer) wrote : | #20 |
First I made sure this really reproduces on libvirt 5.0 on x86 (we only had that combination on s390x before).
It did after a while (26 iterations this time).
With that I installed the fix from the PPA and ran the loop again.
Unfortunately with the fixes applied it still hit the issue (7th try).
So this (alone) isn't the fix :-/
The stacks still look more or less the same (this is on libvirt 5.0 + the 9 patch series around d63c82df8b11b58
(gdb) info threads
Id Target Id Frame
* 1 Thread 0x7f394aea5b40 (LWP 11330) "libvirtd" __lll_lock_wait () at ../sysdeps/
2 Thread 0x7f394a9ea700 (LWP 11331) "libvirtd" futex_wait_
3 Thread 0x7f394a1e9700 (LWP 11332) "libvirtd" futex_wait_
4 Thread 0x7f39499e8700 (LWP 11333) "libvirtd" futex_wait_
5 Thread 0x7f39491e7700 (LWP 11334) "libvirtd" __lll_lock_wait () at ../sysdeps/
6 Thread 0x7f3943fff700 (LWP 11335) "libvirtd" futex_wait_
7 Thread 0x7f39489e6700 (LWP 11336) "libvirtd" futex_wait_
8 Thread 0x7f39437fe700 (LWP 11337) "libvirtd" futex_wait_
9 Thread 0x7f3942ffd700 (LWP 11338) "libvirtd" futex_wait_
10 Thread 0x7f39427fc700 (LWP 11339) "libvirtd" futex_wait_
11 Thread 0x7f3941ffb700 (LWP 11340) "libvirtd" futex_wait_
12 Thread 0x7f3912627700 (LWP 11341) "libvirtd" futex_wait_
13 Thread 0x7f3911e26700 (LWP 11342) "libvirtd" futex_wait_
14 Thread 0x7f3911625700 (LWP 11343) "libvirtd" futex_wait_
15 Thread 0x7f3903fff700 (LWP 11344) "libvirtd" futex_wait_
Christian Ehrhardt (paelzer) wrote : | #21 |
I pinged upstream that this seems to be a different issue.
Christian Ehrhardt (paelzer) wrote : | #22 |
Interesting actually the new stack trace shows daemonStreamHan
So it no more is the undefine call in this new code scenario.
Let me re-run this if that is always the case ...
Hmm, yeah it now always shows 2 times the stacks from daemonStreamHan
Let me add that to my upstream mail ...
Christian Ehrhardt (paelzer) wrote : | #23 |
Silly me, the second thread obviously is on thread and not frame 5 :-)
All as it was before:
(gdb) thread 5
[Switching to thread 5 (Thread 0x7f9769ea7700 (LWP 13402))]
#0 __lll_lock_wait () at ../sysdeps/
103 ../sysdeps/
(gdb) bt
#0 __lll_lock_wait () at ../sysdeps/
#1 0x00007f976f5eb945 in __GI___
#2 0x00007f976f762095 in virMutexLock (m=<optimized out>) at ../../.
#3 0x00007f976f73a3db in virObjectLock (anyobj=
#4 0x00007f976f70481f in virFDStreamSetI
#5 0x00007f976f7f3f9f in virChrdevFreeCl
#6 0x00007f976f70ef20 in virHashForEach (data=<optimized out>, iter=<optimized out>, table=<optimized out>) at ../../.
#7 virHashForEach (table=
#8 0x00007f976f7f4011 in virChrdevFree (devs=<optimized out>) at ../../.
#9 0x00007f9760705fdc in qemuDomainObjPr
#10 0x00007f976f7a3d7b in virDomainObjDispose (obj=0x7f974400
#11 0x00007f976f73a1eb in virObjectUnref (anyobj=<optimized out>) at ../../.
#12 0x00007f976f78e869 in virDomainObjEndAPI (vm=vm@
#13 0x00007f9760791795 in qemuDomainUndef
#14 0x00007f976f9098b3 in virDomainUndefine (domain=
#15 0x0000557f2cd4631f in remoteDispatchD
#16 remoteDispatchD
#17 0x00007f976f82e574 in virNetServerPro
#18 virNetServerPro
#19 0x00007f976f834928 in virNetServerPro
#20 virNetServerHan
Christian Ehrhardt (paelzer) wrote : | #24 |
There was another suggestion [1] but with it applied the case still hangs (after 12 and 1 iteration(s), so not much later than usual).
But the threads looked slightly different this time:
Id Target Id Frame
* 1 Thread 0x7f1eab8efb40 (LWP 13686) "libvirtd" __lll_lock_wait () at ../sysdeps/
2 Thread 0x7f1eab434700 (LWP 13688) "libvirtd" futex_wait_
[...]
I see only one process directly in the lowlevellock.S
(gdb) bt
#0 __lll_lock_wait () at ../sysdeps/
#1 0x00007f1eaf378945 in __GI___
#2 0x00007f1eaf4ef095 in virMutexLock (m=<optimized out>) at ../../.
#3 0x00007f1eaf580fbc in virChrdevFDStre
#4 0x00007f1eaf48f180 in virFDStreamCloseInt (st=0x7f1e9c0128f0, streamAbort=
#5 0x00007f1eaf6bbec9 in virStreamAbort (stream=
#6 0x0000557ce5bd83aa in daemonStreamHan
#7 0x0000557ce5bd8ee3 in daemonStreamHan
[...]
On a retry this was the same again, so the suggeste dpatch did change something. But not enough yet.
I need to find which lock that actually is and if possible who holds it at the moment.
The lock is on
virMutexLock(
in virChrdevFDStre
(gdb) p priv->devs->lock
$1 = {lock = pthread_mutex_t = {Type = Normal, Status = Not acquired, Robust = Yes, Shared = No, Protocol = Priority protect, Priority ceiling = 0}}
(gdb) p &priv->devs->lock
$2 = (virMutex *) 0x7f4554020b20
Interesting that it lists Status as "Not aquired"
I wanted to check which path that would be, but the value for the hash seems wrong:
p priv->devs->hash
$6 = (virHashTablePtr) 0x25
Code would usually access hash and 0x25 is not a valid address.
The code after the lock would have failed in
virHashRemove
This will access 0x25
nextptr = table->table + virHashComputeK
So we are seeing a not fully cleaned up structure here.
Most likely if not being a lock issue it would be a crash instead.
OTOH that might be due to our unlocking with the most recent patch [1], allowing it the struct to go partially away. I dropped the patch and debugged again if it would be more useful to check in there for the actual lock and path.
I was back at my two backtraces fighting for the lock.
The lock now was in a "better" state.
(gdb) p priv->devs->lock
$9 = {lock = pthread_mutex_t = {Type = Normal, Status = Acquired, possibly with waiters, Owner ID = 23102, Robust = No, Shared = No...
Christian Ehrhardt (paelzer) wrote : | #25 |
The locks we have seen are not the same (not both blocking on the same lock).
One is on the FDST (virObjLock)
And the other is on devs->lock of the virChrdevs
priv->devs->lock == fdst->icbOpaque
Analyzing the backtraces I found crossover locking triggering the deadlock:
I'll call the stack of undefine "U" and the stack of daemonStreamHan
1A: already has FDST locked in virFDStreamCloseInt
2A: calls virChrdevFDStre
3U: virFDStreamSetI
4U: virChrdevFree -> ... -> virFDStreamSetI
5U: virChrdevFree does virMutexLock(
So it seems that:
- 5U (holds) and 2A (blocks) collide on devs->lock
- 1A (holds) and 3U (blocks) collide on virObjectLock(fdst)
Seems like a classic entangled deadlock :-/
Christian Ehrhardt (paelzer) wrote : | #26 |
Michal might have already had that understanding, but for me it was worth to track that down.
The problem with the patch so far is that it allows priv->devs to go away and that is what is causing the issues with the patch applied (also as seen in comment #24 only one thread is left locking on the bad struct, but no two thread deadlock scenario anymore.
Considering the above it seems that FDST can not be dropped without the risk of loosing priv->devs content. I think we need a clear ordering of FDST>>devs and in this stack that could be done by modifying virChrdevFree.
The lower layers should lock priv->devs as needed (and it seems they do already).
But virChrdevFree should not do the callbacks with devs->lock held.
Only later for free/destroy.
The only one registered atm as callback to clean is virChrdevFDStre
There might be other issues with this e.g. if my assumption that the lock is ok to not be held for the callback is wrong, but for now that is worth a try.
Christian Ehrhardt (paelzer) wrote : | #27 |
I had the simple suggestion of instead using this:
--- a/src/conf/
+++ b/src/conf/
@@ -310,8 +310,8 @@ void virChrdevFree(
if (!devs || !devs->hash)
return;
- virMutexLock(
virHashFor
+ virMutexLock(
virHashFre
virMutexUn
virMutexDe
But then this breaks as well:
src/util/
if (fdst->
(Segfaults as fdst became 0 which was formerly indirectly blocked by the devs->lock being held.
Actually if there is no FDST anymore after the lock is acquired we can just do an early exit.
--- a/src/util/
+++ b/src/util/
@@ -1435,6 +1435,8 @@ int virFDStreamSetI
{
virFDStrea
+ if (!fdst)
+ return -1;
virObjectL
Lets try to add a check to that, I don't think this is the right solution yet, but maybe with all that insight added later on others on upstream can help again to straighten the fix.
Christian Ehrhardt (paelzer) wrote : | #28 |
Hrm with the latter is still crashes later on with a double free.
I wonder if we'd want a much higher lock that any of such paths would have to take.
Maybe a virObjectLock on the stream or so?
I'd leave that open for discussion as I'd be just doing trial and error which doesn't seem right.
I hope to find some more time the next days to look deeper into this ...
Christian Ehrhardt (paelzer) wrote : | #29 |
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/
#1 0x00007f6adcbd2535 in __GI_abort () at abort.c:79
#2 0x00007f6adcc397b6 in __libc_message (action=
#3 0x00007f6adcc4060a in malloc_printerr (str=str@
#4 0x00007f6adcc425a4 in _int_free (av=0x7f6ab0000020, p=0x7f6ab0022690, have_lock=
#5 0x00007f6adce923cb in virFree (ptrptr=
#6 0x00007f6adcfabdc9 in virChrdevFDStre
#7 0x00007f6adcebc839 in virFDStreamSetI
#8 0x00007f6adcfabfaf in virChrdevFreeCl
#9 0x00007f6adcec6f30 in virHashForEach (data=<optimized out>, iter=<optimized out>, table=<optimized out>) at ../../.
Christian Ehrhardt (paelzer) wrote : | #30 |
I reported my findings upstream again, as I'm currently torn between trying a new debug session and implementing an upper lock level at streams (at least for all cleanup paths).
Seems a deadlock on a futex
strace: Process 6518 attached 7840, FUTEX_WAIT_PRIVATE, 2, NULL
0.000000 futex(0x3ff8c01
<detached ...>