Fix potential dead lock for tty_write_message() if CONFIG_PRINT_QUOTA_WARNING is enabled

I observed the below lockdep warning info at syslog on 3.5-rc4, it could be simply reproduced by creating files more than the soft limits of inode quota on ext4 if CONFIG_PRINT_QUOTA_WARNING is enabled.

jeff@pibroch:~$ uname -a
Linux pibroch 3.5.0-rc4-dirty #220 SMP Fri Jun 29 11:30:20 CST 2012 i686 GNU/Linux
jeff@pibroch:~$ quota -u jeff
Disk quotas for user jeff (uid 1000):
Filesystem  blocks   quota   limit   grace   files   quota   limit   grace
/dev/sda8       0       0       0               1     100    6000 

So creating 110 a files could got quota warns.

$ for((i=0;i<110;i++));do touch "/ext4_mount_path/testme.".$i;done

[  213.324324] =====================================================
[  213.324337] [ INFO: possible circular locking dependency detected ]
[  213.324353] 3.5.0-rc4 #201 Not tainted
[  213.324364] -------------------------------------------------------
[  213.324376] touch/2237 is trying to acquire lock:
[  213.324413]  (&tty->atomic_write_lock){+.+...}, at: [<c14dcc02>] tty_write_message+0x40/0x103
[  213.324426] [  213.324426] but task is already holding lock:
[  213.324469]  (jbd2_handle){+.+...}, at: [<f8202060>] start_this_handle+0xa19/0xa8a [jbd2]
[  213.324482] [  213.324482] which lock already depends on the new lock.
[  213.324482] [  213.324497] [  213.324497] the existing dependency chain (in reverse order) is:
[  213.324525] [  213.324525] -> #2 (jbd2_handle){+.+...}:
[  213.324546]        [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.324576]        [<f82020a4>] start_this_handle+0xa5d/0xa8a [jbd2]
[  213.324608]        [<f820247a>] jbd2__journal_start+0x11b/0x187 [jbd2]
[  213.324638]        [<f8202506>] jbd2_journal_start+0x20/0x30 [jbd2]
[  213.324701]        [<f8a8028c>] ext4_journal_start_sb+0x280/0x296 [ext4]
[  213.324753]        [<f8a5a9bd>] ext4_dirty_inode+0x27/0x84 [ext4]
[  213.324767]        [<c127e24e>] __mark_inode_dirty+0x52/0x2e7
[  213.324781]        [<c12675fe>] update_time+0x10f/0x126
[  213.324794]        [<c1267c07>] touch_atime+0x235/0x25e
[  213.324841]        [<f8a49fac>] ext4_file_mmap+0x5c/0x7d [ext4]
[  213.324856]        [<c1201bf9>] mmap_region+0x449/0x7c4
[  213.324870]        [<c1202435>] do_mmap_pgoff+0x4c1/0x4db
[  213.324884]        [<c11e7bb4>] vm_mmap_pgoff+0x98/0xc7
[  213.324899]        [<c11ffa5e>] sys_mmap_pgoff+0x16a/0x1bf
[  213.324912]        [<c18a5224>] syscall_call+0x7/0xb

[  213.324929] [  213.324929] -> #1 (&mm->mmap_sem){++++++}:
[  213.324943]        [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.324956]        [<c11f3bcb>] might_fault+0xbf/0xf8
[  213.324970]        [<c13e1cd3>] _copy_from_user+0x40/0x8a
[  213.324982]        [<c14da3cf>] copy_from_user+0x16/0x26
[  213.324994]        [<c14dc80b>] tty_write+0x282/0x3c7
[  213.325006]        [<c14dca34>] redirected_tty_write+0xe4/0xfd
[  213.325020]        [<c123f955>] vfs_write+0xf5/0x1a3
[  213.325033]        [<c123fcb8>] sys_write+0x6c/0xa9
[  213.325045]        [<c18b169f>] sysenter_do_call+0x12/0x38

[  213.325062] [  213.325062] -> #0 (&tty->atomic_write_lock){+.+...}:
[  213.325078]        [<c1100e70>] __lock_acquire+0x15bb/0x1b98
[  213.325091]        [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.325105]        [<c189fb16>] __mutex_lock_common+0x52/0x7cd
[  213.325118]        [<c18a0439>] mutex_lock_nested+0x5c/0x70
[  213.325130]        [<c14dcc02>] tty_write_message+0x40/0x103
[  213.325144]        [<c12bf9fd>] flush_warnings+0x17c/0x313
[  213.325157]        [<c12c47c4>] dquot_alloc_inode+0x1e4/0x1fc
[  213.325207]        [<f8a4db1e>] ext4_new_inode+0x11f5/0x1576 [ext4]
[  213.325262]        [<f8a6166d>] ext4_create+0x160/0x230 [ext4]
[  213.325276]        [<c1253dc2>] vfs_create+0xc4/0x106
[  213.325297]        [<c1254ee2>] do_last+0x437/0xdcc
[  213.325310]        [<c125762a>] path_openat+0x10e/0x5a7
[  213.325323]        [<c1257c57>] do_filp_open+0x39/0xc2
[  213.325335]        [<c123e362>] do_sys_open+0xb5/0x1bb
[  213.325347]        [<c123e4a1>] sys_open+0x39/0x5b
[  213.325360]        [<c18a5224>] syscall_call+0x7/0xb
[  213.325368] [  213.325368] other info that might help us debug this:
[  213.325368] [  213.325391] Chain exists of:
[  213.325391]   &tty->atomic_write_lock --> &mm->mmap_sem --> jbd2_handle
[  213.325391] [  213.325401]  Possible unsafe locking scenario:
[  213.325401] [  213.325410]        CPU0                    CPU1
[  213.325417]        ----                    ----
[  213.325558]   lock(jbd2_handle);
[  213.325571]                                lock(&mm->mmap_sem);
[  213.325583]                                lock(jbd2_handle);
[  213.325595]   lock(&tty->atomic_write_lock);
[  213.325602] [  213.325602]  *** DEADLOCK ***
[  213.325602] [  213.325613] 2 locks held by touch/2237:
[  213.325639]  #0:  (&type->i_mutex_dir_key#3){+.+.+.}, at: [<c1254da1>] do_last+0x2f6/0xdcc
[  213.325673]  #1:  (jbd2_handle){+.+...}, at: [<f8202060>] start_this_handle+0xa19/0xa8a [jbd2]
[  213.325682] [  213.325682] stack backtrace:
[  213.325693] Pid: 2237, comm: touch Not tainted 3.5.0-rc4 #201
[  213.325702] Call Trace:
[  213.325717]  [<c10faac9>] print_circular_bug+0x3fa/0x412
[  213.325732]  [<c1100e70>] __lock_acquire+0x15bb/0x1b98
[  213.325747]  [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.325761]  [<c14dcc02>] ? tty_write_message+0x40/0x103
[  213.325776]  [<c189fb16>] __mutex_lock_common+0x52/0x7cd
[  213.325789]  [<c14dcc02>] ? tty_write_message+0x40/0x103
[  213.325804]  [<c18a525d>] ? restore_all+0xf/0xf
[  213.325819]  [<c10b396c>] ? need_resched+0x22/0x3a
[  213.325833]  [<c18a0439>] mutex_lock_nested+0x5c/0x70
[  213.325847]  [<c14dcc02>] ? tty_write_message+0x40/0x103
[  213.325860]  [<c14dcc02>] tty_write_message+0x40/0x103
[  213.325874]  [<c12bf9fd>] flush_warnings+0x17c/0x313
[  213.325888]  [<c12c47c4>] dquot_alloc_inode+0x1e4/0x1fc
[  213.325941]  [<f8a4db1e>] ext4_new_inode+0x11f5/0x1576 [ext4]
[  213.326000]  [<f8a6166d>] ext4_create+0x160/0x230 [ext4]
[  213.326018]  [<c1253dc2>] vfs_create+0xc4/0x106
[  213.326033]  [<c1254ee2>] do_last+0x437/0xdcc
[  213.326048]  [<c125762a>] path_openat+0x10e/0x5a7
[  213.326063]  [<c1257c57>] do_filp_open+0x39/0xc2
[  213.326077]  [<c1101cdc>] ? lock_release+0x4b3/0x4c8
[  213.326090]  [<c18a5116>] ? _raw_spin_unlock+0x4c/0x5d
[  213.326104]  [<c126c821>] ? alloc_fd+0x2fe/0x317
[  213.326118]  [<c123e362>] do_sys_open+0xb5/0x1bb
[  213.326132]  [<c123e4a1>] sys_open+0x39/0x5b
[  213.326145]  [<c18a5224>] syscall_call+0x7/0xb

looks this issue is caused by the tty_write_message()->....->tty_write() because it will call copy_from_user() which will produce page faults and kick off ext4 inode dirty process on another CPU if possible.
According to my understood, if the current process was be preempted when its time quantum expires, the need_resched field of the current process is set, so the scheduler is invoked and the current process will be re-scheduled to run and call next tty_write_message() at dquot.c->print_warning(), and it need to acquire atomic_write_lock again, however, this lock has already been hold by another process, so the race situation is occurred.

I know such kind of issue should be better to fix at quota module, I have also tried to fix it there but no luck. :( For now, I could only work out a stupid patch set to let lockdep happy by making both tty_write_lock and BTM lock sleepable.

Thanks,
-Jeff

Hello,

Quoted 10 lines · Jeff Liu

I observed the below lockdep warning info at syslog on 3.5-rc4, it could be simply reproduced by creating files more than the soft limits of inode quota on ext4 if CONFIG_PRINT_QUOTA_WARNING is enabled.

jeff@pibroch:~$ uname -a
Linux pibroch 3.5.0-rc4-dirty #220 SMP Fri Jun 29 11:30:20 CST 2012 i686 GNU/Linux
jeff@pibroch:~$ quota -u jeff
Disk quotas for user jeff (uid 1000):
Filesystem  blocks   quota   limit   grace   files   quota   limit   grace
/dev/sda8       0       0       0               1     100    6000 

Quoted 2 lines

So creating 110 a files could got quota warns.

$ for((i=0;i<110;i++));do touch "/ext4_mount_path/testme.".$i;done

Yeah, situations like the one reported below can possibly cause problems
(e.g. when you have application with redirected output to /mnt/out and the application writes to /mnt/b which exceeds quota - you try to write message to /mnt/out in the middle of writing to /mnt/b). These problems are rather hard to overcome and that's why CONFIG_PRINT_QUOTA_WARNING is marked as obsolete and CONFIG_QUOTA_NETLINK_INTERFACE should be used instead.

Honza

Quoted 117 lines

[  213.324324] =====================================================
[  213.324337] [ INFO: possible circular locking dependency detected ]
[  213.324353] 3.5.0-rc4 #201 Not tainted
[  213.324364] -------------------------------------------------------
[  213.324376] touch/2237 is trying to acquire lock:
[  213.324413]  (&tty->atomic_write_lock){+.+...}, at: [<c14dcc02>] tty_write_message+0x40/0x103
[  213.324426] [  213.324426] but task is already holding lock:
[  213.324469]  (jbd2_handle){+.+...}, at: [<f8202060>] start_this_handle+0xa19/0xa8a [jbd2]
[  213.324482] [  213.324482] which lock already depends on the new lock.
[  213.324482] [  213.324497] [  213.324497] the existing dependency chain (in reverse order) is:
[  213.324525] [  213.324525] -> #2 (jbd2_handle){+.+...}:
[  213.324546]        [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.324576]        [<f82020a4>] start_this_handle+0xa5d/0xa8a [jbd2]
[  213.324608]        [<f820247a>] jbd2__journal_start+0x11b/0x187 [jbd2]
[  213.324638]        [<f8202506>] jbd2_journal_start+0x20/0x30 [jbd2]
[  213.324701]        [<f8a8028c>] ext4_journal_start_sb+0x280/0x296 [ext4]
[  213.324753]        [<f8a5a9bd>] ext4_dirty_inode+0x27/0x84 [ext4]
[  213.324767]        [<c127e24e>] __mark_inode_dirty+0x52/0x2e7
[  213.324781]        [<c12675fe>] update_time+0x10f/0x126
[  213.324794]        [<c1267c07>] touch_atime+0x235/0x25e
[  213.324841]        [<f8a49fac>] ext4_file_mmap+0x5c/0x7d [ext4]
[  213.324856]        [<c1201bf9>] mmap_region+0x449/0x7c4
[  213.324870]        [<c1202435>] do_mmap_pgoff+0x4c1/0x4db
[  213.324884]        [<c11e7bb4>] vm_mmap_pgoff+0x98/0xc7
[  213.324899]        [<c11ffa5e>] sys_mmap_pgoff+0x16a/0x1bf
[  213.324912]        [<c18a5224>] syscall_call+0x7/0xb

[  213.324929] [  213.324929] -> #1 (&mm->mmap_sem){++++++}:
[  213.324943]        [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.324956]        [<c11f3bcb>] might_fault+0xbf/0xf8
[  213.324970]        [<c13e1cd3>] _copy_from_user+0x40/0x8a
[  213.324982]        [<c14da3cf>] copy_from_user+0x16/0x26
[  213.324994]        [<c14dc80b>] tty_write+0x282/0x3c7
[  213.325006]        [<c14dca34>] redirected_tty_write+0xe4/0xfd
[  213.325020]        [<c123f955>] vfs_write+0xf5/0x1a3
[  213.325033]        [<c123fcb8>] sys_write+0x6c/0xa9
[  213.325045]        [<c18b169f>] sysenter_do_call+0x12/0x38

[  213.325062] [  213.325062] -> #0 (&tty->atomic_write_lock){+.+...}:
[  213.325078]        [<c1100e70>] __lock_acquire+0x15bb/0x1b98
[  213.325091]        [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.325105]        [<c189fb16>] __mutex_lock_common+0x52/0x7cd
[  213.325118]        [<c18a0439>] mutex_lock_nested+0x5c/0x70
[  213.325130]        [<c14dcc02>] tty_write_message+0x40/0x103
[  213.325144]        [<c12bf9fd>] flush_warnings+0x17c/0x313
[  213.325157]        [<c12c47c4>] dquot_alloc_inode+0x1e4/0x1fc
[  213.325207]        [<f8a4db1e>] ext4_new_inode+0x11f5/0x1576 [ext4]
[  213.325262]        [<f8a6166d>] ext4_create+0x160/0x230 [ext4]
[  213.325276]        [<c1253dc2>] vfs_create+0xc4/0x106
[  213.325297]        [<c1254ee2>] do_last+0x437/0xdcc
[  213.325310]        [<c125762a>] path_openat+0x10e/0x5a7
[  213.325323]        [<c1257c57>] do_filp_open+0x39/0xc2
[  213.325335]        [<c123e362>] do_sys_open+0xb5/0x1bb
[  213.325347]        [<c123e4a1>] sys_open+0x39/0x5b
[  213.325360]        [<c18a5224>] syscall_call+0x7/0xb
[  213.325368] [  213.325368] other info that might help us debug this:
[  213.325368] [  213.325391] Chain exists of:
[  213.325391]   &tty->atomic_write_lock --> &mm->mmap_sem --> jbd2_handle
[  213.325391] [  213.325401]  Possible unsafe locking scenario:
[  213.325401] [  213.325410]        CPU0                    CPU1
[  213.325417]        ----                    ----
[  213.325558]   lock(jbd2_handle);
[  213.325571]                                lock(&mm->mmap_sem);
[  213.325583]                                lock(jbd2_handle);
[  213.325595]   lock(&tty->atomic_write_lock);
[  213.325602] [  213.325602]  *** DEADLOCK ***
[  213.325602] [  213.325613] 2 locks held by touch/2237:
[  213.325639]  #0:  (&type->i_mutex_dir_key#3){+.+.+.}, at: [<c1254da1>] do_last+0x2f6/0xdcc
[  213.325673]  #1:  (jbd2_handle){+.+...}, at: [<f8202060>] start_this_handle+0xa19/0xa8a [jbd2]
[  213.325682] [  213.325682] stack backtrace:
[  213.325693] Pid: 2237, comm: touch Not tainted 3.5.0-rc4 #201
[  213.325702] Call Trace:
[  213.325717]  [<c10faac9>] print_circular_bug+0x3fa/0x412
[  213.325732]  [<c1100e70>] __lock_acquire+0x15bb/0x1b98
[  213.325747]  [<c1101e89>] lock_acquire+0x198/0x1d3
[  213.325761]  [<c14dcc02>] ? tty_write_message+0x40/0x103
[  213.325776]  [<c189fb16>] __mutex_lock_common+0x52/0x7cd
[  213.325789]  [<c14dcc02>] ? tty_write_message+0x40/0x103
[  213.325804]  [<c18a525d>] ? restore_all+0xf/0xf
[  213.325819]  [<c10b396c>] ? need_resched+0x22/0x3a
[  213.325833]  [<c18a0439>] mutex_lock_nested+0x5c/0x70
[  213.325847]  [<c14dcc02>] ? tty_write_message+0x40/0x103
[  213.325860]  [<c14dcc02>] tty_write_message+0x40/0x103
[  213.325874]  [<c12bf9fd>] flush_warnings+0x17c/0x313
[  213.325888]  [<c12c47c4>] dquot_alloc_inode+0x1e4/0x1fc
[  213.325941]  [<f8a4db1e>] ext4_new_inode+0x11f5/0x1576 [ext4]
[  213.326000]  [<f8a6166d>] ext4_create+0x160/0x230 [ext4]
[  213.326018]  [<c1253dc2>] vfs_create+0xc4/0x106
[  213.326033]  [<c1254ee2>] do_last+0x437/0xdcc
[  213.326048]  [<c125762a>] path_openat+0x10e/0x5a7
[  213.326063]  [<c1257c57>] do_filp_open+0x39/0xc2
[  213.326077]  [<c1101cdc>] ? lock_release+0x4b3/0x4c8
[  213.326090]  [<c18a5116>] ? _raw_spin_unlock+0x4c/0x5d
[  213.326104]  [<c126c821>] ? alloc_fd+0x2fe/0x317
[  213.326118]  [<c123e362>] do_sys_open+0xb5/0x1bb
[  213.326132]  [<c123e4a1>] sys_open+0x39/0x5b
[  213.326145]  [<c18a5224>] syscall_call+0x7/0xb

looks this issue is caused by the tty_write_message()->....->tty_write() because it will call copy_from_user() which will produce page faults and kick off ext4 inode dirty process on another CPU if possible.
According to my understood, if the current process was be preempted when its time quantum expires, the need_resched field of the current process is set, so the scheduler is invoked and the current process will be re-scheduled to run and call next tty_write_message() at dquot.c->print_warning(), and it need to acquire atomic_write_lock again, however, this lock has already been hold by another process, so the race situation is occurred.

I know such kind of issue should be better to fix at quota module, I have also tried to fix it there but no luck. :( For now, I could only work out a stupid patch set to let lockdep happy by making both tty_write_lock and BTM lock sleepable.

Thanks,
-Jeff