libvirt hangs after utah workload is aborted

Seems a deadlock on a futex

strace: Process 6518 attached
     0.000000 futex(0x3ff8c017840, FUTEX_WAIT_PRIVATE, 2, NULL
 <detached ...>

All threads are blocked lock related
  Id Target Id Frame
* 1 Thread 0x3ff9a75d130 (LWP 6518) "libvirtd" 0x000003ff9a011158 in __lll_lock_wait (futex=futex@entry=0x3ff8c017840, private=<optimized out>) at lowlevellock.c:46
  2 Thread 0x3ff956ff910 (LWP 6519) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e134) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  3 Thread 0x3ff94efe910 (LWP 6520) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e130) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  4 Thread 0x3ff946fd910 (LWP 6521) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e130) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  5 Thread 0x3ff8befc910 (LWP 6522) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e130) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  6 Thread 0x3ff93efc910 (LWP 6523) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e134) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  7 Thread 0x3ff936fb910 (LWP 6524) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e1d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  8 Thread 0x3ff92efa910 (LWP 6525) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e1d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  9 Thread 0x3ff926f9910 (LWP 6526) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e1d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  10 Thread 0x3ff91ef8910 (LWP 6527) "libvirtd" 0x000003ff9a011158 in __lll_lock_wait (futex=futex@entry=0x3ff74013180, private=<optimized out>) at lowlevellock.c:46
  11 Thread 0x3ff916f7910 (LWP 6528) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa4659e1d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  12 Thread 0x3ff8ad7f910 (LWP 6529) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa465eb550) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  13 Thread 0x3ff8a57e910 (LWP 6530) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa465eb550) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  14 Thread 0x3ff89d7d910 (LWP 6531) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa465eb550) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  15 Thread 0x3ff8957c910 (LWP 6532) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x2aa465eb550) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  16 Thread 0x3ff88d7b910 (LWP 6533) "libvirtd" 0x000003ff9a00d936 in futex_wait_cancelab...

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=futex@entry=0x3ff8c017840, private=<optimized out>) at lowlevellock.c:46
#1 0x000003ff9a00a1f8 in __GI___pthread_mutex_lock (mutex=0x3ff8c017840) at ../nptl/pthread_mutex_lock.c:78
#2 0x000003ff9a2ff1be in virMutexLock (m=<optimized out>) at ../../../src/util/virthread.c:89
#3 0x000003ff9a38c41c in virChrdevFDStreamCloseCb (st=<optimized out>, opaque=0x3ff74010310) at ../../../src/conf/virchrdev.c:254
#4 0x000003ff9a2a226a in virFDStreamCloseInt (st=0x3ff7403f7d0, streamAbort=<optimized out>) at ../../../src/util/virfdstream.c:737
#5 0x000003ff9a3de7ca in virStreamAbort (stream=0x3ff7403f7d0) at ../../../src/libvirt-stream.c:1244
#6 0x000002aa24ad0726 in daemonStreamHandleAbort (client=client@entry=0x2aa465d8f60, stream=stream@entry=0x3ff74016c40, msg=0x2aa465aa430) at ../../../daemon/stream.c:632
#7 0x000002aa24ad166c in daemonStreamHandleWrite (stream=0x3ff74016c40, client=0x2aa465d8f60) at ../../../daemon/stream.c:745
#8 daemonStreamEvent (st=<optimized out>, events=<optimized out>, opaque=0x2aa465d8f60) at ../../../daemon/stream.c:144
#9 0x000003ff9a2a2696 in virFDStreamEvent (watch=<optimized out>, fd=<optimized out>, events=14, opaque=0x3ff7403f7d0) at ../../../src/util/virfdstream.c:327
#10 0x000003ff9a2a1c50 in virEventPollDispatchHandles (fds=<optimized out>, nfds=<optimized out>) at ../../../src/util/vireventpoll.c:508
#11 virEventPollRunOnce () at ../../../src/util/vireventpoll.c:657
#12 0x000003ff9a2a0142 in virEventRunDefaultImpl () at ../../../src/util/virevent.c:327
#13 0x000003ff9a429cd6 in virNetDaemonRun (dmn=0x2aa4659dd30) at ../../../src/rpc/virnetdaemon.c:838
#14 0x000002aa24aa0400 in main (argc=<optimized out>, argv=<optimized out>) at ../../../daemon/libvirtd.c:1510

#10

(gdb) bt
#0 0x000003ff9a011158 in __lll_lock_wait (futex=futex@entry=0x3ff74013180, private=<optimized out>) at lowlevellock.c:46
#1 0x000003ff9a00a1f8 in __GI___pthread_mutex_lock (mutex=0x3ff74013180) at ../nptl/pthread_mutex_lock.c:78
#2 0x000003ff9a2ff1be in virMutexLock (m=<optimized out>) at ../../../src/util/virthread.c:89
#3 0x000003ff9a2dc230 in virObjectLock (anyobj=anyobj@entry=0x3ff74013170) at ../../../src/util/virobject.c:435
#4 0x000003ff9a2a4908 in virFDStreamSetInternalCloseCb (st=<optimized out>, cb=cb@entry=0x0, opaque=opaque@entry=0x0, fcb=fcb@entry=0x0) at ../../../src/util/virfdstream.c:1428
#5 0x000003ff9a38c3ee in virChrdevFreeClearCallbacks (payload=<optimized out>, name=<optimized out>, data=<optimized out>) at ../../../src/conf/virchrdev.c:301
#6 0x000003ff9a2aef5e in virHashForEach (table=0x3ff8c02be10, iter=iter@entry=0x3ff9a38c3d0 <virChrdevFreeClearCallbacks>, data=data@entry=0x0) at ../../../src/util/virhash.c:584
#7 0x000003ff9a38c490 in virChrdevFree (devs=<optimized out>) at ../../../src/conf/virchrdev.c:316
#8 0x000003ff8af0187a in qemuDomainObjPrivateFree (data=<optimized out>) at ../../../src/qemu/qemu_domain.c:1847
#9 0x000003ff9a33cc6c in virDomainObjDispose (obj=0x3ff8c001ec0) at ../../../src/conf/domain_conf.c:3078
#10...

#1 is triggered via (it seems a guest goes away - qemu died and then cleanup runs after a write failed)
 daemonStreamHandleWrite (failing to write)
 -> daemonStreamHandleAbort (closing things and cleaning up)
    -> ... virChrdevFDStreamCloseCb
        virMutexLock(&priv->devs->lock);
        # priv = Domain's device information structure
        # client stream is client=0x2aa465d8f60
        # 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
  remoteDispatchDomainUndefine
  ... -> virChrdevFree
     ... -> virFDStreamSetInternalCloseCb
        -> virObjectLock(virFDStreamDataPtr fdst)
          -> virMutexLock(&obj->lock);
  #closing all streams of a guest (requiring the same locks)

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

Thanks Christian for looking into it. The next time it happens I'll try to gather some more context and follow up.

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.

@Paride
Could you make the test system use:
https://launchpad.net/~ubuntu-cloud-archive/+archive/ubuntu/stein-staging

And report if you can still hang it with that?

Sure, I'll try and report back.

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.

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.

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://bazaar.launchpad.net/~utah/utah/dev/view/head:/utah/provisioning/vm.py#L437

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://bazaar.launchpad.net/~utah/utah/dev/view/head:/utah/provisioning/vm.py#L445

Thanks, even using that on the very same machine doesn't reproduce.
I pinged you to talk about early/late abort in your cases.

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.

FYI info on all threads

  Id Target Id Frame
* 1 Thread 0x7f0d087c8640 (LWP 26958) "libvirtd" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  2 Thread 0x7f0cfbdfb700 (LWP 26959) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d1104) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  3 Thread 0x7f0cfb5fa700 (LWP 26960) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d1104) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  4 Thread 0x7f0cfadf9700 (LWP 26961) "libvirtd" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  5 Thread 0x7f0cfa5f8700 (LWP 26962) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d1104) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  6 Thread 0x7f0cf1df7700 (LWP 26963) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d1104) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  7 Thread 0x7f0cf9df7700 (LWP 26964) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d11a4) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  8 Thread 0x7f0cf95f6700 (LWP 26965) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d11a4) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  9 Thread 0x7f0cf8df5700 (LWP 26966) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d11a4) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  10 Thread 0x7f0cf3fff700 (LWP 26967) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d11a0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  11 Thread 0x7f0cf37fe700 (LWP 26968) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65d11a0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  12 Thread 0x7f0ccb924700 (LWP 26969) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65f9520) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  13 Thread 0x7f0ccb123700 (LWP 26970) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65f9520) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  14 Thread 0x7f0cca922700 (LWP 26971) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65f9520) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  15 Thread 0x7f0cca121700 (LWP 26972) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55f2f65f9520) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  16 Thread 0x7f0cc9920700 (LWP 26973) "libvirtd" 0x00007f0d0757e9f3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0...

Submitted upstream to get more eyeballs onto the problem
=> https://www.redhat.com/archives/libvir-list/2019-April/msg00080.html

Thanks to Michal I got the suggested d63c82df8b11b583dec8e72dfb216d8c14783876 as a fix.
This might need 4deed5f3c71f94acce387b68afbfc92911bf0a75 to backport.
Related is also a5445a3706b0bcbb6ec3f4f0f9e03b853ccf911b which also sounds close to the topic.
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://launchpad.net/~paelzer/+archive/ubuntu/bug-1822096-libvirtd-deadlock

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 d63c82df8b11b583dec8e72dfb216d8c14783876.

(gdb) info threads
  Id Target Id Frame
* 1 Thread 0x7f394aea5b40 (LWP 11330) "libvirtd" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
  2 Thread 0x7f394a9ea700 (LWP 11331) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc7534) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  3 Thread 0x7f394a1e9700 (LWP 11332) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc7530) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  4 Thread 0x7f39499e8700 (LWP 11333) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc7530) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  5 Thread 0x7f39491e7700 (LWP 11334) "libvirtd" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
  6 Thread 0x7f3943fff700 (LWP 11335) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc7530) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  7 Thread 0x7f39489e6700 (LWP 11336) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc75d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  8 Thread 0x7f39437fe700 (LWP 11337) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc75d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  9 Thread 0x7f3942ffd700 (LWP 11338) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc75d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  10 Thread 0x7f39427fc700 (LWP 11339) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc75d4) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  11 Thread 0x7f3941ffb700 (LWP 11340) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bc75d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  12 Thread 0x7f3912627700 (LWP 11341) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bfc440) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  13 Thread 0x7f3911e26700 (LWP 11342) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bfc440) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  14 Thread 0x7f3911625700 (LWP 11343) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x556951bfc440) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  15 Thread 0x7f3903fff700 (LWP 11344) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55...

I pinged upstream that this seems to be a different issue.

Interesting actually the new stack trace shows daemonStreamHandleWrite twice.
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 daemonStreamHandleAbort.
Let me add that to my upstream mail ...

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/unix/sysv/linux/x86_64/lowlevellock.S:103
103 ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: No such file or directory.
(gdb) bt
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
#1 0x00007f976f5eb945 in __GI___pthread_mutex_lock (mutex=0x7f975401efc0) at ../nptl/pthread_mutex_lock.c:80
#2 0x00007f976f762095 in virMutexLock (m=<optimized out>) at ../../../src/util/virthread.c:89
#3 0x00007f976f73a3db in virObjectLock (anyobj=anyobj@entry=0x7f975401efb0) at ../../../src/util/virobject.c:429
#4 0x00007f976f70481f in virFDStreamSetInternalCloseCb (st=<optimized out>, cb=cb@entry=0x0, opaque=opaque@entry=0x0, fcb=fcb@entry=0x0) at ../../../src/util/virfdstream.c:1439
#5 0x00007f976f7f3f9f in virChrdevFreeClearCallbacks (payload=<optimized out>, name=<optimized out>, data=<optimized out>) at ../../../src/conf/virchrdev.c:299
#6 0x00007f976f70ef20 in virHashForEach (data=<optimized out>, iter=<optimized out>, table=<optimized out>) at ../../../src/util/virhash.c:575
#7 virHashForEach (table=0x7f9744002d40, iter=iter@entry=0x7f976f7f3f90 <virChrdevFreeClearCallbacks>, data=data@entry=0x0) at ../../../src/util/virhash.c:563
#8 0x00007f976f7f4011 in virChrdevFree (devs=<optimized out>) at ../../../src/conf/virchrdev.c:314
#9 0x00007f9760705fdc in qemuDomainObjPrivateFree (data=<optimized out>) at ../../../src/qemu/qemu_domain.c:1994
#10 0x00007f976f7a3d7b in virDomainObjDispose (obj=0x7f9744003e40) at ../../../src/conf/domain_conf.c:3204
#11 0x00007f976f73a1eb in virObjectUnref (anyobj=<optimized out>) at ../../../src/util/virobject.c:350
#12 0x00007f976f78e869 in virDomainObjEndAPI (vm=vm@entry=0x7f9769ea6818) at ../../../src/conf/domain_conf.c:3322
#13 0x00007f9760791795 in qemuDomainUndefineFlags (dom=<optimized out>, flags=<optimized out>) at ../../../src/qemu/qemu_driver.c:7866
#14 0x00007f976f9098b3 in virDomainUndefine (domain=domain@entry=0x7f974c003190) at ../../../src/libvirt-domain.c:6256
#15 0x0000557f2cd4631f in remoteDispatchDomainUndefine (server=0x557f2e98a3b0, msg=0x557f2e9f6510, args=0x7f974c003160, rerr=0x7f9769ea69a0, client=<optimized out>) at ../../../src/remote/remote_daemon_dispatch_stubs.h:12624
#16 remoteDispatchDomainUndefineHelper (server=0x557f2e98a3b0, client=<optimized out>, msg=0x557f2e9f6510, rerr=0x7f9769ea69a0, args=0x7f974c003160, ret=0x7f974c002f90) at ../../../src/remote/remote_daemon_dispatch_stubs.h:12600
#17 0x00007f976f82e574 in virNetServerProgramDispatchCall (msg=0x557f2e9f6510, client=0x557f2e9aedd0, server=0x557f2e98a3b0, prog=0x557f2e9ba970) at ../../../src/rpc/virnetserverprogram.c:435
#18 virNetServerProgramDispatch (prog=0x557f2e9ba970, server=server@entry=0x557f2e98a3b0, client=0x557f2e9aedd0, msg=0x557f2e9f6510) at ../../../src/rpc/virnetserverprogram.c:302
#19 0x00007f976f834928 in virNetServerProcessMsg (msg=<optimized out>, prog=<optimized out>, client=<optimized out>, srv=0x557f2e98a3b0) at ../../../src/rpc/virnetserver.c:142
#20 virNetServerHandleJo...

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/unix/sysv/linux/x86_64/lowlevellock.S:103
  2 Thread 0x7f1eab434700 (LWP 13688) "libvirtd" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x557ce654a534) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
[...]

I see only one process directly in the lowlevellock.S

(gdb) bt
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
#1 0x00007f1eaf378945 in __GI___pthread_mutex_lock (mutex=0x7f1e8c0016d0) at ../nptl/pthread_mutex_lock.c:80
#2 0x00007f1eaf4ef095 in virMutexLock (m=<optimized out>) at ../../../src/util/virthread.c:89
#3 0x00007f1eaf580fbc in virChrdevFDStreamCloseCb (st=st@entry=0x7f1e9c0128f0, opaque=opaque@entry=0x7f1e9c031090) at ../../../src/conf/virchrdev.c:252
#4 0x00007f1eaf48f180 in virFDStreamCloseInt (st=0x7f1e9c0128f0, streamAbort=<optimized out>) at ../../../src/util/virfdstream.c:742
#5 0x00007f1eaf6bbec9 in virStreamAbort (stream=0x7f1e9c0128f0) at ../../../src/libvirt-stream.c:1244
#6 0x0000557ce5bd83aa in daemonStreamHandleAbort (client=client@entry=0x557ce65cc650, stream=stream@entry=0x7f1e9c0315b0, msg=msg@entry=0x557ce65d1e20) at ../../../src/remote/remote_daemon_stream.c:636
#7 0x0000557ce5bd8ee3 in daemonStreamHandleWrite (stream=0x7f1e9c0315b0, client=0x557ce65cc650) at ../../../src/remote/remote_daemon_stream.c:749
[...]

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(&priv->devs->lock);
in virChrdevFDStreamCloseCb

(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
  virHashRemoveEntry(priv->devs->hash, priv->path);
This will access 0x25
  nextptr = table->table + virHashComputeKey(table, name);

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...

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->devs->lock, the assumption is that this is already held by the path undefine takes

Analyzing the backtraces I found crossover locking triggering the deadlock:
I'll call the stack of undefine "U" and the stack of daemonStreamHandleAbort "A":
1A: already has FDST locked in virFDStreamCloseInt
2A: calls virChrdevFDStreamCloseCb which blocks on locks priv->devs->lock
3U: virFDStreamSetInternalCloseCb blocks on locking FDST
4U: virChrdevFree -> ... -> virFDStreamSetInternalCloseCb
5U: virChrdevFree does virMutexLock(&devs->lock);

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 :-/

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 virChrdevFDStreamCloseCbFree which frees priv->path and priv, but does not access dev. So it might be save to do not hold this while calling.

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.

I had the simple suggestion of instead using this:
--- a/src/conf/virchrdev.c
+++ b/src/conf/virchrdev.c
@@ -310,8 +310,8 @@ void virChrdevFree(virChrdevsPtr devs)
     if (!devs || !devs->hash)
         return;

- virMutexLock(&devs->lock);
     virHashForEach(devs->hash, virChrdevFreeClearCallbacks, NULL);
+ virMutexLock(&devs->lock);
     virHashFree(devs->hash);
     virMutexUnlock(&devs->lock);
     virMutexDestroy(&devs->lock);

But then this breaks as well:
 src/util/virfdstream.c
 if (fdst->icbFreeOpaque)
 (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/virfdstream.c
+++ b/src/util/virfdstream.c
@@ -1435,6 +1435,8 @@ int virFDStreamSetInternalCloseCb(virStr
                                   virFDStreamInternalCloseCbFreeOpaque fcb)
 {
     virFDStreamDataPtr fdst = st->privateData;
+ if (!fdst)
+ return -1;

     virObjectLock(fdst);

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.

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 ...

#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00007f6adcbd2535 in __GI_abort () at abort.c:79
#2 0x00007f6adcc397b6 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7f6adcd5f952 "%s\n") at ../sysdeps/posix/libc_fatal.c:181
#3 0x00007f6adcc4060a in malloc_printerr (str=str@entry=0x7f6adcd61638 "double free or corruption (fasttop)") at malloc.c:5352
#4 0x00007f6adcc425a4 in _int_free (av=0x7f6ab0000020, p=0x7f6ab0022690, have_lock=<optimized out>) at malloc.c:4274
#5 0x00007f6adce923cb in virFree (ptrptr=ptrptr@entry=0x7f6ad765b6f0) at ../../../src/util/viralloc.c:581
#6 0x00007f6adcfabdc9 in virChrdevFDStreamCloseCbFree (opaque=<optimized out>) at ../../../src/conf/virchrdev.c:238
#7 0x00007f6adcebc839 in virFDStreamSetInternalCloseCb (st=<optimized out>, cb=cb@entry=0x0, opaque=opaque@entry=0x0, fcb=fcb@entry=0x0) at ../../../src/util/virfdstream.c:1444
#8 0x00007f6adcfabfaf in virChrdevFreeClearCallbacks (payload=<optimized out>, name=<optimized out>, data=<optimized out>) at ../../../src/conf/virchrdev.c:299
#9 0x00007f6adcec6f30 in virHashForEach (data=<optimized out>, iter=<optimized out>, table=<optimized out>) at ../../../src/util/virhash.c:575

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).