diff mbox series

ceph: fix lock inversion when flushing the mdlog for filesystem sync

Message ID 20220418174540.151546-1-jlayton@kernel.org (mailing list archive)
State New, archived
Headers show
Series ceph: fix lock inversion when flushing the mdlog for filesystem sync | expand

Commit Message

Jeff Layton April 18, 2022, 5:45 p.m. UTC
======================================================
    WARNING: possible circular locking dependency detected
    5.18.0-rc2+ #237 Tainted: G            E
    ------------------------------------------------------
    fsstress/8647 is trying to acquire lock:
    ffff88810d910090 (&s->s_mutex){+.+.}-{3:3}, at: send_flush_mdlog+0x4c/0x150 [ceph]

                                but task is already holding lock:
    ffff888100ed4070 (&mdsc->mutex){+.+.}-{3:3}, at: ceph_mdsc_sync+0x14b/0x670 [ceph]

                                which lock already depends on the new lock.

                                the existing dependency chain (in reverse order) is:

                                -> #1 (&mdsc->mutex){+.+.}-{3:3}:
           __mutex_lock+0x110/0xc40
           mds_dispatch+0x1376/0x2480 [ceph]
           ceph_con_process_message+0xd9/0x240 [libceph]
           process_message+0x1b/0x1f0 [libceph]
           ceph_con_v2_try_read+0x1ac7/0x2b70 [libceph]
           ceph_con_workfn+0x56a/0x910 [libceph]
           process_one_work+0x4e8/0x970
           worker_thread+0x2c6/0x650
           kthread+0x16c/0x1a0
           ret_from_fork+0x22/0x30

                                -> #0 (&s->s_mutex){+.+.}-{3:3}:
           __lock_acquire+0x1990/0x2ca0
           lock_acquire+0x15d/0x3e0
           __mutex_lock+0x110/0xc40
           send_flush_mdlog+0x4c/0x150 [ceph]
           ceph_mdsc_sync+0x2a7/0x670 [ceph]
           ceph_sync_fs+0x50/0xd0 [ceph]
           iterate_supers+0xbd/0x140
           ksys_sync+0x96/0xf0
           __do_sys_sync+0xa/0x10
           do_syscall_64+0x3b/0x90
           entry_SYSCALL_64_after_hwframe+0x44/0xae

                                other info that might help us debug this:
     Possible unsafe locking scenario:
           CPU0                    CPU1
           ----                    ----
      lock(&mdsc->mutex);
                                   lock(&s->s_mutex);
                                   lock(&mdsc->mutex);
      lock(&s->s_mutex);

                                 *** DEADLOCK ***
    2 locks held by fsstress/8647:
     #0: ffff888100ed00e0 (&type->s_umount_key#68){++++}-{3:3}, at: iterate_supers+0x93/0x140
     #1: ffff888100ed4070 (&mdsc->mutex){+.+.}-{3:3}, at: ceph_mdsc_sync+0x14b/0x670 [ceph]

                                stack backtrace:
    CPU: 9 PID: 8647 Comm: fsstress Tainted: G            E     5.18.0-rc2+ #237
    Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.15.0-1.fc35 04/01/2014
    Call Trace:
     <TASK>
     dump_stack_lvl+0x56/0x6f
     check_noncircular+0x1b8/0x1e0
     ? print_circular_bug+0x110/0x110
     ? __lock_acquire+0x830/0x2ca0
     ? lockdep_lock+0x9f/0x140
     ? add_chain_block+0x1dc/0x280
     __lock_acquire+0x1990/0x2ca0
     ? lockdep_hardirqs_on_prepare+0x220/0x220
     lock_acquire+0x15d/0x3e0
     ? send_flush_mdlog+0x4c/0x150 [ceph]
     ? lock_release+0x410/0x410
     ? lock_acquire+0x16d/0x3e0
     ? lock_release+0x410/0x410
     __mutex_lock+0x110/0xc40
     ? send_flush_mdlog+0x4c/0x150 [ceph]
     ? preempt_count_sub+0x14/0xc0
     ? send_flush_mdlog+0x4c/0x150 [ceph]
     ? mutex_lock_io_nested+0xbc0/0xbc0
     ? mutex_lock_io_nested+0xbc0/0xbc0
     ? ceph_mdsc_sync+0x13a/0x670 [ceph]
     ? lock_downgrade+0x380/0x380
     ? send_flush_mdlog+0x4c/0x150 [ceph]
     send_flush_mdlog+0x4c/0x150 [ceph]
     ceph_mdsc_sync+0x2a7/0x670 [ceph]
     ? ceph_mdsc_pre_umount+0x280/0x280 [ceph]
     ? ceph_osdc_sync+0xdd/0x180 [libceph]
     ? vfs_fsync_range+0x100/0x100
     ceph_sync_fs+0x50/0xd0 [ceph]
     iterate_supers+0xbd/0x140
     ksys_sync+0x96/0xf0
     ? vfs_fsync+0xe0/0xe0
     ? lockdep_hardirqs_on_prepare+0x128/0x220
     ? syscall_enter_from_user_mode+0x21/0x70
     __do_sys_sync+0xa/0x10
     do_syscall_64+0x3b/0x90
     entry_SYSCALL_64_after_hwframe+0x44/0xae
    RIP: 0033:0x7f90ca30829b
    Code: c3 66 0f 1f 44 00 00 48 8b 15 89 1b 0f 00 f7 d8 64 89 02 b8 ff ff ff ff eb b8 0f 1f 44 00 00 f3 0f 1e fa b8 a2 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 5d 1b 0f 00 f7 d8 64 >
    RSP: 002b:00007ffd202a72b8 EFLAGS: 00000202 ORIG_RAX: 00000000000000a2
    RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f90ca30829b
    RDX: 0000000000000000 RSI: 000000007c9a84db RDI: 000000000000029e
    RBP: 028f5c28f5c28f5c R08: 000000000000007d R09: 00007ffd202a6ca7
    R10: 0000000000000000 R11: 0000000000000202 R12: 000000000000029e
    R13: 8f5c28f5c28f5c29 R14: 00000000004033c0 R15: 00007f90ca5676c0
     </TASK>
Apr 18 12:23:38 client1 kernel: libceph: mon0 (2)192.168.1.81:3300 session lost, hunting for new mon

Fixes: 7d8f9923957f77 (ceph: flush the mdlog for filesystem sync)
Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/ceph/mds_client.c | 14 ++++++++++----
 1 file changed, 10 insertions(+), 4 deletions(-)

I found this while testing today. Xiubo, feel free to fold this into
7d8f9923957f77, so we avoid the regression.

Comments

Xiubo Li April 19, 2022, 12:49 a.m. UTC | #1
On 4/19/22 1:45 AM, Jeff Layton wrote:
>      ======================================================
>      WARNING: possible circular locking dependency detected
>      5.18.0-rc2+ #237 Tainted: G            E
>      ------------------------------------------------------
>      fsstress/8647 is trying to acquire lock:
>      ffff88810d910090 (&s->s_mutex){+.+.}-{3:3}, at: send_flush_mdlog+0x4c/0x150 [ceph]
>
>                                  but task is already holding lock:
>      ffff888100ed4070 (&mdsc->mutex){+.+.}-{3:3}, at: ceph_mdsc_sync+0x14b/0x670 [ceph]
>
>                                  which lock already depends on the new lock.
>
>                                  the existing dependency chain (in reverse order) is:
>
>                                  -> #1 (&mdsc->mutex){+.+.}-{3:3}:
>             __mutex_lock+0x110/0xc40
>             mds_dispatch+0x1376/0x2480 [ceph]
>             ceph_con_process_message+0xd9/0x240 [libceph]
>             process_message+0x1b/0x1f0 [libceph]
>             ceph_con_v2_try_read+0x1ac7/0x2b70 [libceph]
>             ceph_con_workfn+0x56a/0x910 [libceph]
>             process_one_work+0x4e8/0x970
>             worker_thread+0x2c6/0x650
>             kthread+0x16c/0x1a0
>             ret_from_fork+0x22/0x30
>
>                                  -> #0 (&s->s_mutex){+.+.}-{3:3}:
>             __lock_acquire+0x1990/0x2ca0
>             lock_acquire+0x15d/0x3e0
>             __mutex_lock+0x110/0xc40
>             send_flush_mdlog+0x4c/0x150 [ceph]
>             ceph_mdsc_sync+0x2a7/0x670 [ceph]
>             ceph_sync_fs+0x50/0xd0 [ceph]
>             iterate_supers+0xbd/0x140
>             ksys_sync+0x96/0xf0
>             __do_sys_sync+0xa/0x10
>             do_syscall_64+0x3b/0x90
>             entry_SYSCALL_64_after_hwframe+0x44/0xae
>
>                                  other info that might help us debug this:
>       Possible unsafe locking scenario:
>             CPU0                    CPU1
>             ----                    ----
>        lock(&mdsc->mutex);
>                                     lock(&s->s_mutex);
>                                     lock(&mdsc->mutex);
>        lock(&s->s_mutex);
>
>                                   *** DEADLOCK ***
>      2 locks held by fsstress/8647:
>       #0: ffff888100ed00e0 (&type->s_umount_key#68){++++}-{3:3}, at: iterate_supers+0x93/0x140
>       #1: ffff888100ed4070 (&mdsc->mutex){+.+.}-{3:3}, at: ceph_mdsc_sync+0x14b/0x670 [ceph]
>
>                                  stack backtrace:
>      CPU: 9 PID: 8647 Comm: fsstress Tainted: G            E     5.18.0-rc2+ #237
>      Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.15.0-1.fc35 04/01/2014
>      Call Trace:
>       <TASK>
>       dump_stack_lvl+0x56/0x6f
>       check_noncircular+0x1b8/0x1e0
>       ? print_circular_bug+0x110/0x110
>       ? __lock_acquire+0x830/0x2ca0
>       ? lockdep_lock+0x9f/0x140
>       ? add_chain_block+0x1dc/0x280
>       __lock_acquire+0x1990/0x2ca0
>       ? lockdep_hardirqs_on_prepare+0x220/0x220
>       lock_acquire+0x15d/0x3e0
>       ? send_flush_mdlog+0x4c/0x150 [ceph]
>       ? lock_release+0x410/0x410
>       ? lock_acquire+0x16d/0x3e0
>       ? lock_release+0x410/0x410
>       __mutex_lock+0x110/0xc40
>       ? send_flush_mdlog+0x4c/0x150 [ceph]
>       ? preempt_count_sub+0x14/0xc0
>       ? send_flush_mdlog+0x4c/0x150 [ceph]
>       ? mutex_lock_io_nested+0xbc0/0xbc0
>       ? mutex_lock_io_nested+0xbc0/0xbc0
>       ? ceph_mdsc_sync+0x13a/0x670 [ceph]
>       ? lock_downgrade+0x380/0x380
>       ? send_flush_mdlog+0x4c/0x150 [ceph]
>       send_flush_mdlog+0x4c/0x150 [ceph]
>       ceph_mdsc_sync+0x2a7/0x670 [ceph]
>       ? ceph_mdsc_pre_umount+0x280/0x280 [ceph]
>       ? ceph_osdc_sync+0xdd/0x180 [libceph]
>       ? vfs_fsync_range+0x100/0x100
>       ceph_sync_fs+0x50/0xd0 [ceph]
>       iterate_supers+0xbd/0x140
>       ksys_sync+0x96/0xf0
>       ? vfs_fsync+0xe0/0xe0
>       ? lockdep_hardirqs_on_prepare+0x128/0x220
>       ? syscall_enter_from_user_mode+0x21/0x70
>       __do_sys_sync+0xa/0x10
>       do_syscall_64+0x3b/0x90
>       entry_SYSCALL_64_after_hwframe+0x44/0xae
>      RIP: 0033:0x7f90ca30829b
>      Code: c3 66 0f 1f 44 00 00 48 8b 15 89 1b 0f 00 f7 d8 64 89 02 b8 ff ff ff ff eb b8 0f 1f 44 00 00 f3 0f 1e fa b8 a2 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 5d 1b 0f 00 f7 d8 64 >
>      RSP: 002b:00007ffd202a72b8 EFLAGS: 00000202 ORIG_RAX: 00000000000000a2
>      RAX: ffffffffffffffda RBX: 00000000000001f4 RCX: 00007f90ca30829b
>      RDX: 0000000000000000 RSI: 000000007c9a84db RDI: 000000000000029e
>      RBP: 028f5c28f5c28f5c R08: 000000000000007d R09: 00007ffd202a6ca7
>      R10: 0000000000000000 R11: 0000000000000202 R12: 000000000000029e
>      R13: 8f5c28f5c28f5c29 R14: 00000000004033c0 R15: 00007f90ca5676c0
>       </TASK>
> Apr 18 12:23:38 client1 kernel: libceph: mon0 (2)192.168.1.81:3300 session lost, hunting for new mon
>
> Fixes: 7d8f9923957f77 (ceph: flush the mdlog for filesystem sync)
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>   fs/ceph/mds_client.c | 14 ++++++++++----
>   1 file changed, 10 insertions(+), 4 deletions(-)
>
> I found this while testing today. Xiubo, feel free to fold this into
> 7d8f9923957f77, so we avoid the regression.
>
> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
> index 94bd4dd956fd..ff38d0eac5c9 100644
> --- a/fs/ceph/mds_client.c
> +++ b/fs/ceph/mds_client.c
> @@ -5099,7 +5099,7 @@ static void flush_mdlog_and_wait_mdsc_unsafe_requests(struct ceph_mds_client *md
>   						 u64 want_tid)
>   {
>   	struct ceph_mds_request *req = NULL, *nextreq;
> -	struct ceph_mds_session *last_session = NULL, *s;
> +	struct ceph_mds_session *last_session = NULL;
>   	struct rb_node *n;
>   
>   	mutex_lock(&mdsc->mutex);
> @@ -5115,23 +5115,29 @@ static void flush_mdlog_and_wait_mdsc_unsafe_requests(struct ceph_mds_client *md
>   			nextreq = NULL;
>   		if (req->r_op != CEPH_MDS_OP_SETFILELOCK &&
>   		    (req->r_op & CEPH_MDS_OP_WRITE)) {
> +			struct ceph_mds_session *s;
> +
>   			/* write op */
>   			ceph_mdsc_get_request(req);
>   			if (nextreq)
>   				ceph_mdsc_get_request(nextreq);
>   
> -			s = req->r_session;
> +			s = ceph_get_mds_session(req->r_session);

This will cause NULL pointer dereference bug, because in 
ceph_get_mds_session() it won't check whether the session parameter is 
NULL or not, it should be:

			s = req->r_session;
  			if (!s) {
  				req = nextreq;
  				continue;
  			}
+			s = ceph_get_mds_session(s);

+			mutex_unlock(&mdsc->mutex);

Thanks Jeff, I will post the V4.


>   			if (!s) {
>   				req = nextreq;
>   				continue;
>   			}
> +			mutex_unlock(&mdsc->mutex);
> +
>   			/* send flush mdlog request to MDS */
>   			if (last_session != s) {
>   				send_flush_mdlog(s);
>   				ceph_put_mds_session(last_session);
> -				last_session = ceph_get_mds_session(s);
> +				last_session = s;
> +			} else {
> +				ceph_put_mds_session(s);
>   			}
> -			mutex_unlock(&mdsc->mutex);
> +
>   			dout("%s wait on %llu (want %llu)\n", __func__,
>   			     req->r_tid, want_tid);
>   			wait_for_completion(&req->r_safe_completion);
diff mbox series

Patch

diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
index 94bd4dd956fd..ff38d0eac5c9 100644
--- a/fs/ceph/mds_client.c
+++ b/fs/ceph/mds_client.c
@@ -5099,7 +5099,7 @@  static void flush_mdlog_and_wait_mdsc_unsafe_requests(struct ceph_mds_client *md
 						 u64 want_tid)
 {
 	struct ceph_mds_request *req = NULL, *nextreq;
-	struct ceph_mds_session *last_session = NULL, *s;
+	struct ceph_mds_session *last_session = NULL;
 	struct rb_node *n;
 
 	mutex_lock(&mdsc->mutex);
@@ -5115,23 +5115,29 @@  static void flush_mdlog_and_wait_mdsc_unsafe_requests(struct ceph_mds_client *md
 			nextreq = NULL;
 		if (req->r_op != CEPH_MDS_OP_SETFILELOCK &&
 		    (req->r_op & CEPH_MDS_OP_WRITE)) {
+			struct ceph_mds_session *s;
+
 			/* write op */
 			ceph_mdsc_get_request(req);
 			if (nextreq)
 				ceph_mdsc_get_request(nextreq);
 
-			s = req->r_session;
+			s = ceph_get_mds_session(req->r_session);
 			if (!s) {
 				req = nextreq;
 				continue;
 			}
+			mutex_unlock(&mdsc->mutex);
+
 			/* send flush mdlog request to MDS */
 			if (last_session != s) {
 				send_flush_mdlog(s);
 				ceph_put_mds_session(last_session);
-				last_session = ceph_get_mds_session(s);
+				last_session = s;
+			} else {
+				ceph_put_mds_session(s);
 			}
-			mutex_unlock(&mdsc->mutex);
+
 			dout("%s wait on %llu (want %llu)\n", __func__,
 			     req->r_tid, want_tid);
 			wait_for_completion(&req->r_safe_completion);