Re: [dm-devel] [PATCH] multipathd: avoid crash in uevent_cleanup()

[Martin Wilck <mwilck@suse.com>]

On Tue, 2021-03-02 at 20:44 +0800, lixiaokeng wrote:
> 
> > Note that unlike all other threads, TUR threads are _detached_
> > threads.
> > multipathd tries to cancel them, but it has no way to verify that
> > they
> > actually stopped. It may be just a normal observation that you
> > can't
> > see the messages when a TUR thread terminates, in particular if the
> > program is exiting and might have already closed the stderr file
> > descriptor.
> > 
> > 
> > If you look at the crashed processes with gdb, the thread IDs
> > should
> > give you some clue which stack belongs to which thread. The TUR
> > threads
> > will have higher thread IDs than the others because they are
> > started
> > later.
> > 
> 
> 
> ??
> 
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/usr/lib64/libthread_db.so.1".
> Core was generated by `/sbin/multipathd -d -s'.
> Program terminated with signal SIGSEGV, Segmentation fault.
> #0  0x00007f3f669e071d in ?? ()
> [Current thread is 1 (Thread 0x7f3f65873700 (LWP 1645593))]
> (gdb) i thread
>   Id   Target Id                           Frame
> * 1    Thread 0x7f3f65873700 (LWP 1645593) 0x00007f3f669e071d in ??
> ()
>   2    Thread 0x7f3f6611a000 (LWP 1645066) 0x00007f3f669fede7 in
> munmap () at ../sysdeps/unix/syscall-template.S:78
>   3    Thread 0x7f3f6609d700 (LWP 1645095) syscall () at
> ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
> (gdb) bt
> #0  0x00007f3f669e071d in ?? ()
> #1  0x0000000000000000 in ?? ()
> (gdb) thread 2
> [Switching to thread 2 (Thread 0x7f3f6611a000 (LWP 1645066))]
> #0  0x00007f3f669fede7 in munmap () at ../sysdeps/unix/syscall-
> template.S:78
> 78      T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
> (gdb) bt
> #0  0x00007f3f669fede7 in munmap () at ../sysdeps/unix/syscall-
> template.S:78
> #1  0x00007f3f669fb77d in _dl_unmap_segments
> (l=l@entry=0x557cb432ba10) at ./dl-unmap-segments.h:32
> ...
> #10 0x00007f3f669b44ed in cleanup_prio () at prio.c:66 
> //cleanup_checkers() is finished.
> #11 0x0000557cb26db794 in child (param=<optimized out>) at
> main.c:2932
> #12 0x0000557cb26d44d3 in main (argc=<optimized out>,
> argv=0x7ffc98d47948) at main.c:3150
> 
> 
> UNWIND
> 
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/usr/lib64/libthread_db.so.1".
> Core was generated by `/sbin/multipathd -d -s'.
> Program terminated with signal SIGSEGV, Segmentation fault.
> #0  x86_64_fallback_frame_state (fs=0x7fa9b2f576d0,
> context=0x7fa9b2f57980) at ./md-unwind-support.h:58
> 58        if (*(unsigned char *)(pc+0) == 0x48
> [Current thread is 1 (Thread 0x7fa9b2f58700 (LWP 1285074))]
> (gdb) i thread
>   Id   Target Id                                     Frame
> * 1    Thread 0x7fa9b2f58700 (LWP 1285074) (Exiting)
> x86_64_fallback_frame_state (fs=0x7fa9b2f576d0,
> context=0x7fa9b2f57980) at ./md-unwind-support.h:58
>   2    Thread 0x7fa9b383e000 (LWP 1284366)          
> 0x00007fa9b403e127 in __close (fd=5) at
> ../sysdeps/unix/sysv/linux/close.c:27
>   3    Thread 0x7fa9b37c1700 (LWP 1284374)           syscall () at
> ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
>   4    Thread 0x7fa9b2f73700 (LWP 1285077)          
> 0x00007fa9b3e06507 in ioctl () at ../sysdeps/unix/syscall-
> template.S:78
>   5    Thread 0x7fa9b2f61700 (LWP 1285076)          
> 0x00007fa9b3e06507 in ioctl () at ../sysdeps/unix/syscall-
> template.S:78
>   6    Thread 0x7fa9b2f4f700 (LWP 1285079)          
> 0x00007fa9b3e06507 in ioctl () at ../sysdeps/unix/syscall-
> template.S:78
>   7    Thread 0x7fa9b2fa9700 (LWP 1285080)          
> 0x00007fa9b3e06507 in ioctl () at ../sysdeps/unix/syscall-
> template.S:78
> (gdb) thread 2
> [Switching to thread 2 (Thread 0x7fa9b383e000 (LWP 1284366))]
> #0  0x00007fa9b403e127 in __close (fd=5) at
> ../sysdeps/unix/sysv/linux/close.c:27
> 27        return SYSCALL_CANCEL (close, fd);
> (gdb) bt
> #0  0x00007fa9b403e127 in __close (fd=5) at
> ../sysdeps/unix/sysv/linux/close.c:27
> #1  0x00005606f030f95b in cleanup_dmevent_waiter () at dmevents.c:111
> #2  0x00005606f03087a2 in child (param=<optimized out>) at
> main.c:2934
> #3  0x00005606f03014d3 in main (argc=<optimized out>,
> argv=0x7ffdb782ab38) at main.c:3150
> 
> 
> The LWP of ?? and UNWIND is much larger than thread 2(main).
> 
> I add print_func like:
> 
> @@ -228,6 +228,10 @@ static void copy_msg_to_tcc(void *ct_p, const
> char *msg)
>         pthread_mutex_unlock(&ct->lock);
>  }
> 
> +static void lxk10 (void)
> +{
> +       condlog(2, "lxk exit tur_thread");
> +}
>  static void *tur_thread(void *ctx)
>  {
>         struct tur_checker_context *ct = ctx;
> @@ -235,6 +239,8 @@ static void *tur_thread(void *ctx)
>         char devt[32];
> 
>         /* This thread can be canceled, so setup clean up */
> +       condlog(2, "lxk start tur_thread");
> +       pthread_cleanup_push(lxk10, NULL);
>         tur_thread_cleanup_push(ct);
> 
> When there are four devices, core log:
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: exit
> (signal)
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sda:
> unusable path
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdf:
> unusable path
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sde:
> unusable path
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdd:
> unusable path
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdc:
> unusable path
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdb:
> unusable path
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk start
> tur_thread
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> tur_thread
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk start
> tur_thread
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk start
> tur_thread
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> tur_thread
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk start
> tur_thread
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> tur_thread
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]:
> 360014057a1353ec1bdd4dfcad19db6db: remove multipath map
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdg: orphan
> path, map flushed
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: BUG:
> orphaning path sdg that holds hwe of
> 360014057a1353ec1bdd4dfcad19db6db
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: tur checker
> refcount 4
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]:
> 36001405faf8a6c2920840ed8ba73b9ee: remove multipath map
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdj: orphan
> path, map flushed
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: BUG:
> orphaning path sdj that holds hwe of
> 36001405faf8a6c2920840ed8ba73b9ee
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: tur checker
> refcount 3
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]:
> 36001405044c0f50ba3c4e5b9b57e4de4: remove multipath map
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdi: orphan
> path, map flushed
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: BUG:
> orphaning path sdi that holds hwe of
> 36001405044c0f50ba3c4e5b9b57e4de4
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: tur checker
> refcount 2
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]:
> 36001405e0cbb950907b4a51af1a002ed: remove multipath map
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: sdh: orphan
> path, map flushed
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: BUG:
> orphaning path sdh that holds hwe of
> 36001405e0cbb950907b4a51af1a002ed
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: tur checker
> refcount 1
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> ueventloop
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> uxlsnrloop
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> uevqloop
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> wait_dmevents
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk exit
> checkerloop
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: directio
> checker refcount 6
> Mar 02 11:40:35 localhost.localdomain multipathd[85474]: lxk free tur
> checker  //checker_put


So we do not see "unloading tur checker". Like you said, that suggests
that the crash occurs between libcheck_free() and the thread exiting.
I suggest you put a message in tur.c:libcheck_free (), AFTER the call
to cleanup_context(), printing the values of "running" and "holders".

Anyway:

	holders = uatomic_sub_return(&ct->holders, 1);
	if (!holders)
		cleanup_context(ct);

Whatever mistakes we have made, only one actor can have seen 
holders == 0, and have called cleanup_context().

The stacks you have shown indicate that the instruction pointers were
broken. That would suggest something similar as dicussed in the ML
thread leading to 38ffd89 ("libmultipath: prevent DSO unloading with
astray checker threads"). Your logs show "tur checker refcount 1", so
the next call to checker_put would have unloaded the DSO. 

Please try commenting out the dlclose() call in free_checker_class(),
and see if it makes a difference.

Martin



--
dm-devel mailing list
dm-devel@redhat.com
https://listman.redhat.com/mailman/listinfo/dm-devel