pktcdvd ->open_mutex lockdep splat

pktcdvd ->open_mutex lockdep splat

[Brian Foster]

Hi all,

I noticed the splat below on one of my test VMs when running latest
upstream with lockdep enabled. I'm not really sure why this occurs
because I'm not actually using this device for anything I'm aware of. I
suppose it's possible this has a busted userspace or kvm config, as this
is just one of a handful of scratch VMs I have around for development
purposes. I'm happy to try and dig further into it or just expunge it if
this is of little interest.

FWIW, the splat itself reproduces back before ->open_mutex was created
from bd_mutex by commit a8698707a183 ("block: move bd_mutex to struct
gendisk"). I went as far back as v5.10 and still observed it.

Brian

--- 8< ---

[   11.667694] block (null): writer mapped to sr0

[   11.677407] ============================================
[   11.680650] WARNING: possible recursive locking detected
[   11.683581] 6.8.0+ #346 Tainted: G            E     
[   11.686246] --------------------------------------------
[   11.689075] systemd-udevd/1438 is trying to acquire lock:
[   11.690607] ffff8bb78f553cc8 (&disk->open_mutex){+.+.}-{3:3}, at: bdev_open+0x60/0x3e0
[   11.692504] 
               but task is already holding lock:
[   11.693921] ffff8bb786b39cc8 (&disk->open_mutex){+.+.}-{3:3}, at: bdev_open+0x239/0x3e0
[   11.695806] 
               other info that might help us debug this:
[   11.697362]  Possible unsafe locking scenario:

[   11.698779]        CPU0
[   11.699397]        ----
[   11.699994]   lock(&disk->open_mutex);
[   11.700923]   lock(&disk->open_mutex);
[   11.701849] 
                *** DEADLOCK ***

[   11.703273]  May be due to missing lock nesting notation

[   11.704878] 3 locks held by systemd-udevd/1438:
[   11.705967]  #0: ffff8bb786b39cc8 (&disk->open_mutex){+.+.}-{3:3}, at: bdev_open+0x239/0x3e0
[   11.707966]  #1: ffffffffc085c768 (pktcdvd_mutex){+.+.}-{3:3}, at: pkt_open+0x2b/0x630 [pktcdvd]
[   11.710080]  #2: ffffffffc085d868 (&ctl_mutex#2){+.+.}-{3:3}, at: pkt_open+0x39/0x630 [pktcdvd]
[   11.712164] 
               stack backtrace:
[   11.713200] CPU: 3 PID: 1438 Comm: systemd-udevd Tainted: G            E      6.8.0+ #346
[   11.715122] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-1.fc38 04/01/2014
[   11.717123] Call Trace:
[   11.717741]  <TASK>
[   11.718271]  dump_stack_lvl+0x79/0xb0
[   11.719194]  __lock_acquire+0x1228/0x2170
[   11.720172]  lock_acquire+0xbb/0x2c0
[   11.721030]  ? bdev_open+0x60/0x3e0
[   11.721869]  __mutex_lock+0x77/0xd40
[   11.722724]  ? bdev_open+0x60/0x3e0
[   11.723558]  ? find_held_lock+0x2b/0x80
[   11.724470]  ? bdev_open+0x56/0x3e0
[   11.725324]  ? bdev_open+0x60/0x3e0
[   11.726173]  ? bdev_open+0x60/0x3e0
[   11.727031]  bdev_open+0x60/0x3e0
[   11.727844]  bdev_file_open_by_dev+0xbf/0x120
[   11.728909]  pkt_open+0x10e/0x630 [pktcdvd]
[   11.729944]  ? bdev_open+0x22f/0x3e0
[   11.730815]  ? lock_release+0xb8/0x270
[   11.731729]  ? bdev_open+0x239/0x3e0
[   11.732605]  blkdev_get_whole+0x25/0x90
[   11.733544]  bdev_open+0x29f/0x3e0
[   11.734380]  ? iput.part.0+0x34/0x260
[   11.735277]  ? __pfx_blkdev_open+0x10/0x10
[   11.736282]  blkdev_open+0x8b/0xc0
[   11.737090]  do_dentry_open+0x172/0x580
[   11.738002]  path_openat+0x3a9/0xa30
[   11.738864]  do_filp_open+0xa1/0x130
[   11.739731]  ? _raw_spin_unlock+0x23/0x40
[   11.740700]  do_sys_openat2+0x82/0xb0
[   11.741596]  __x64_sys_openat+0x49/0x80
[   11.742529]  do_syscall_64+0x7c/0x190
[   11.743406]  entry_SYSCALL_64_after_hwframe+0x6c/0x74
[   11.744599] RIP: 0033:0x7f30e4afd70b
[   11.745450] Code: 25 00 00 41 00 3d 00 00 41 00 74 4b 64 8b 04 25 18 00 00 00 85 c0 75 67 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 91 00 00 00 48 8b 54 24 28 64 48 2b 14 25
[   11.749817] RSP: 002b:00007ffdafd13250 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[   11.751633] RAX: ffffffffffffffda RBX: 0000000000006000 RCX: 00007f30e4afd70b
[   11.753306] RDX: 0000000000080900 RSI: 00007ffdafd132d0 RDI: 00000000ffffff9c
[   11.754966] RBP: 00007ffdafd132d0 R08: 0000000000000000 R09: 00007ffdafd13160
[   11.756624] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000080900
[   11.758311] R13: 0000000000080900 R14: 0000000000000006 R15: 00007ffdafd13470
[   11.760041]  </TASK>

Re: pktcdvd ->open_mutex lockdep splat

[Brian Foster]

On Fri, Mar 22, 2024 at 12:40:21PM -0400, Brian Foster wrote:
> Hi all,
> 
> I noticed the splat below on one of my test VMs when running latest
> upstream with lockdep enabled. I'm not really sure why this occurs
> because I'm not actually using this device for anything I'm aware of. I
> suppose it's possible this has a busted userspace or kvm config, as this
> is just one of a handful of scratch VMs I have around for development
> purposes. I'm happy to try and dig further into it or just expunge it if
> this is of little interest.
> 

Ok, I guess the reason I was only seeing this in one particular VM is
that for whatever reason, something happens to invoke pktsetup during
boot on that guest. If I boot up a separate VM/distro and run 'pktsetup
0 /dev/sr0,' I see the same splat..

Brian

> FWIW, the splat itself reproduces back before ->open_mutex was created
> from bd_mutex by commit a8698707a183 ("block: move bd_mutex to struct
> gendisk"). I went as far back as v5.10 and still observed it.
> 
> Brian
> 
> --- 8< ---
> 
> [   11.667694] block (null): writer mapped to sr0
> 
> [   11.677407] ============================================
> [   11.680650] WARNING: possible recursive locking detected
> [   11.683581] 6.8.0+ #346 Tainted: G            E     
> [   11.686246] --------------------------------------------
> [   11.689075] systemd-udevd/1438 is trying to acquire lock:
> [   11.690607] ffff8bb78f553cc8 (&disk->open_mutex){+.+.}-{3:3}, at: bdev_open+0x60/0x3e0
> [   11.692504] 
>                but task is already holding lock:
> [   11.693921] ffff8bb786b39cc8 (&disk->open_mutex){+.+.}-{3:3}, at: bdev_open+0x239/0x3e0
> [   11.695806] 
>                other info that might help us debug this:
> [   11.697362]  Possible unsafe locking scenario:
> 
> [   11.698779]        CPU0
> [   11.699397]        ----
> [   11.699994]   lock(&disk->open_mutex);
> [   11.700923]   lock(&disk->open_mutex);
> [   11.701849] 
>                 *** DEADLOCK ***
> 
> [   11.703273]  May be due to missing lock nesting notation
> 
> [   11.704878] 3 locks held by systemd-udevd/1438:
> [   11.705967]  #0: ffff8bb786b39cc8 (&disk->open_mutex){+.+.}-{3:3}, at: bdev_open+0x239/0x3e0
> [   11.707966]  #1: ffffffffc085c768 (pktcdvd_mutex){+.+.}-{3:3}, at: pkt_open+0x2b/0x630 [pktcdvd]
> [   11.710080]  #2: ffffffffc085d868 (&ctl_mutex#2){+.+.}-{3:3}, at: pkt_open+0x39/0x630 [pktcdvd]
> [   11.712164] 
>                stack backtrace:
> [   11.713200] CPU: 3 PID: 1438 Comm: systemd-udevd Tainted: G            E      6.8.0+ #346
> [   11.715122] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-1.fc38 04/01/2014
> [   11.717123] Call Trace:
> [   11.717741]  <TASK>
> [   11.718271]  dump_stack_lvl+0x79/0xb0
> [   11.719194]  __lock_acquire+0x1228/0x2170
> [   11.720172]  lock_acquire+0xbb/0x2c0
> [   11.721030]  ? bdev_open+0x60/0x3e0
> [   11.721869]  __mutex_lock+0x77/0xd40
> [   11.722724]  ? bdev_open+0x60/0x3e0
> [   11.723558]  ? find_held_lock+0x2b/0x80
> [   11.724470]  ? bdev_open+0x56/0x3e0
> [   11.725324]  ? bdev_open+0x60/0x3e0
> [   11.726173]  ? bdev_open+0x60/0x3e0
> [   11.727031]  bdev_open+0x60/0x3e0
> [   11.727844]  bdev_file_open_by_dev+0xbf/0x120
> [   11.728909]  pkt_open+0x10e/0x630 [pktcdvd]
> [   11.729944]  ? bdev_open+0x22f/0x3e0
> [   11.730815]  ? lock_release+0xb8/0x270
> [   11.731729]  ? bdev_open+0x239/0x3e0
> [   11.732605]  blkdev_get_whole+0x25/0x90
> [   11.733544]  bdev_open+0x29f/0x3e0
> [   11.734380]  ? iput.part.0+0x34/0x260
> [   11.735277]  ? __pfx_blkdev_open+0x10/0x10
> [   11.736282]  blkdev_open+0x8b/0xc0
> [   11.737090]  do_dentry_open+0x172/0x580
> [   11.738002]  path_openat+0x3a9/0xa30
> [   11.738864]  do_filp_open+0xa1/0x130
> [   11.739731]  ? _raw_spin_unlock+0x23/0x40
> [   11.740700]  do_sys_openat2+0x82/0xb0
> [   11.741596]  __x64_sys_openat+0x49/0x80
> [   11.742529]  do_syscall_64+0x7c/0x190
> [   11.743406]  entry_SYSCALL_64_after_hwframe+0x6c/0x74
> [   11.744599] RIP: 0033:0x7f30e4afd70b
> [   11.745450] Code: 25 00 00 41 00 3d 00 00 41 00 74 4b 64 8b 04 25 18 00 00 00 85 c0 75 67 44 89 e2 48 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 91 00 00 00 48 8b 54 24 28 64 48 2b 14 25
> [   11.749817] RSP: 002b:00007ffdafd13250 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> [   11.751633] RAX: ffffffffffffffda RBX: 0000000000006000 RCX: 00007f30e4afd70b
> [   11.753306] RDX: 0000000000080900 RSI: 00007ffdafd132d0 RDI: 00000000ffffff9c
> [   11.754966] RBP: 00007ffdafd132d0 R08: 0000000000000000 R09: 00007ffdafd13160
> [   11.756624] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000080900
> [   11.758311] R13: 0000000000080900 R14: 0000000000000006 R15: 00007ffdafd13470
> [   11.760041]  </TASK>
> 
> 

Re: pktcdvd ->open_mutex lockdep splat

[Christoph Hellwig]

On Fri, Mar 22, 2024 at 01:09:51PM -0400, Brian Foster wrote:
> Ok, I guess the reason I was only seeing this in one particular VM is
> that for whatever reason, something happens to invoke pktsetup during
> boot on that guest. If I boot up a separate VM/distro and run 'pktsetup
> 0 /dev/sr0,' I see the same splat..

pktcdvd is completely unmaintained and in horrible shape unfortunately,
and no one is interested in caring for it.

I can only recommend to not build it into any kernel you can care about.

Re: pktcdvd ->open_mutex lockdep splat

[Brian Foster]

On Sun, Mar 24, 2024 at 04:39:53PM -0700, Christoph Hellwig wrote:
> On Fri, Mar 22, 2024 at 01:09:51PM -0400, Brian Foster wrote:
> > Ok, I guess the reason I was only seeing this in one particular VM is
> > that for whatever reason, something happens to invoke pktsetup during
> > boot on that guest. If I boot up a separate VM/distro and run 'pktsetup
> > 0 /dev/sr0,' I see the same splat..
> 
> pktcdvd is completely unmaintained and in horrible shape unfortunately,
> and no one is interested in caring for it.
> 
> I can only recommend to not build it into any kernel you can care about.
> 

Heh, Ok thanks. I was poking around the code a bit just to try and
figure if there was some easy/incremental improvement to be made here,
but if so, I'm not familiar enough with the code to see it. I was
particularly wondering why the multi-open occurs across the setup and
pktcdvd device open and if that can be avoided. It looks like the main
difference is the nonblock flag. From digging down into cdrom_open(),
that is what controls whether or not the drive is opened for data or
control purposes (i.e., so dictates whether media is read or not), and
so that seems to explain why a blocking open would be deferred to
pktcdvd device open.

Anyways, it does seem like the warning itself is benign because the
pktcdvd and backing device will be separate disks.

Brian