Software encryption at fscrypt causing the filesystem access unresponsive

Software encryption at fscrypt causing the filesystem access unresponsive

[Yuvaraj Ranganathan]

Hello developers,

We are trying to validate a Software file based encryption with standard key by disabling Inline encryption and we are observing  the adb session is hung.
We are not able to access the same filesystem at that moment. 

Please note, we don't see any issues on validating the standard key with Inline encryption HW.

Test:
adb push/pull of 1MB file with a sleep of 1s between each push & pull on the encrypted filesystem for 10 iterations and device going to hung at 7th iterations.

Dump:
[ 1694.844307] INFO: task systemd-journal:575 blocked for more than 120 seconds.
[ 1694.852455]       Tainted: G        W  O       6.6.33-debug #1
[ 1694.859301] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1694.868128] task:systemd-journal state:D stack:0     pid:575   ppid:1      flags:0x00000801
[ 1694.868147] Call trace:
[ 1694.868153]  __switch_to+0xf0/0x16c
[ 1694.868175]  __schedule+0x334/0x980
[ 1694.868184]  schedule+0x5c/0xf8
[ 1694.868194]  wait_transaction_locked+0x7c/0xcc
[ 1694.868208]  add_transaction_credits+0x130/0x338
[ 1694.868218]  start_this_handle+0xf0/0x52c
[ 1694.868227]  jbd2__journal_start+0x110/0x24c
[ 1694.868237]  __ext4_journal_start_sb+0x114/0x1c4
[ 1694.868250]  ext4_dirty_inode+0x38/0x88
[ 1694.868261]  __mark_inode_dirty+0x58/0x41c
[ 1694.868274]  generic_update_time+0x4c/0x60
[ 1694.868285]  touch_atime+0x1bc/0x21c
[ 1694.868294]  ovl_update_time+0x50/0x94 [overlay]
[ 1694.868351]  touch_atime+0x178/0x21c
[ 1694.868362]  ovl_file_accessed.part.0+0x50/0x7c [overlay]
[ 1694.868396]  ovl_read_iter+0x180/0x274 [overlay]
[ 1694.868423]  vfs_read+0x200/0x2a0
[ 1694.868429]  ksys_pread64+0x78/0xbc
[ 1694.868434]  __arm64_sys_pread64+0x20/0x2c
[ 1694.868439]  invoke_syscall+0x48/0x118
[ 1694.868453]  el0_svc_common.constprop.0+0xc8/0xe8
[ 1694.868459]  do_el0_svc+0x20/0x2c
[ 1694.868465]  el0_svc+0x40/0x120
[ 1694.868473]  el0t_64_sync_handler+0x13c/0x158
[ 1694.868479]  el0t_64_sync+0x1a0/0x1a4
[ 1694.868487] INFO: task journal-offline:2276 blocked for more than 120 seconds.
[ 1694.876656]       Tainted: G        W  O       6.6.33-debug #1
[ 1694.884212] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1694.893185] task:journal-offline state:D stack:0     pid:2276  ppid:1      flags:0x00000a00
[ 1694.893190] Call trace:
[ 1694.893191]  __switch_to+0xf0/0x16c
[ 1694.893195]  __schedule+0x334/0x980
[ 1694.893197]  schedule+0x5c/0xf8
[ 1694.893199]  wait_transaction_locked+0x7c/0xcc
[ 1694.893202]  add_transaction_credits+0x130/0x338
[ 1694.893204]  start_this_handle+0xf0/0x52c
[ 1694.893206]  jbd2__journal_start+0x110/0x24c
[ 1694.893208]  __ext4_journal_start_sb+0x114/0x1c4
[ 1694.893211]  ext4_dirty_inode+0x38/0x88
[ 1694.893213]  __mark_inode_dirty+0x58/0x41c
[ 1694.893215]  generic_update_time+0x4c/0x60
[ 1694.893217]  file_update_time+0xa0/0xa4
[ 1694.893219]  ext4_page_mkwrite+0x84/0x554
[ 1694.893221]  do_page_mkwrite+0x58/0xdc
[ 1694.893225]  do_wp_page+0x14c/0xe08
[ 1694.893227]  __handle_mm_fault+0x5c8/0xce8
[ 1694.893230]  handle_mm_fault+0x68/0x2a0
[ 1694.893232]  do_page_fault+0x228/0x514
[ 1694.893235]  do_mem_abort+0x44/0x94
[ 1694.893238]  el0_da+0x30/0xb4
[ 1694.893240]  el0t_64_sync_handler+0xe4/0x158
[ 1694.893243]  el0t_64_sync+0x1a0/0x1a4
[ 1694.893245] INFO: task journal-offline:2277 blocked for more than 120 seconds.
[ 1694.901766]       Tainted: G        W  O       6.6.33-debug #1
[ 1694.908540] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1694.917324] task:journal-offline state:D stack:0     pid:2277  ppid:1      flags:0x00000a00
[ 1694.917328] Call trace:
[ 1694.917329]  __switch_to+0xf0/0x16c
[ 1694.917333]  __schedule+0x334/0x980
[ 1694.917335]  schedule+0x5c/0xf8
[ 1694.917337]  jbd2_log_wait_commit+0xb4/0x14c
[ 1694.917341]  jbd2_complete_transaction+0x90/0xd0
[ 1694.917343]  ext4_fc_commit+0x400/0x754
[ 1694.917345]  ext4_sync_file+0x1d8/0x3c8
[ 1694.917348]  vfs_fsync_range+0x34/0x80
[ 1694.917351]  ovl_fsync+0x10c/0x124 [overlay]
[ 1694.917363]  vfs_fsync_range+0x34/0x80
[ 1694.917365]  do_fsync+0x3c/0x84
[ 1694.917367]  __arm64_sys_fsync+0x18/0x28
[ 1694.917370]  invoke_syscall+0x48/0x118
[ 1694.917372]  el0_svc_common.constprop.0+0xc8/0xe8
[ 1694.917375]  do_el0_svc+0x20/0x2c
[ 1694.917378]  el0_svc+0x40/0x120
[ 1694.917380]  el0t_64_sync_handler+0x13c/0x158
[ 1694.917382]  el0t_64_sync+0x1a0/0x1a4
[ 1694.917396] INFO: task jbd2/sda6-8:787 blocked for more than 120 seconds.
[ 1694.925099]       Tainted: G        W  O       6.6.33-debug #1
[ 1694.931810] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1694.940558] task:jbd2/sda6-8     state:D stack:0     pid:787   ppid:2      flags:0x00000208
[ 1694.940561] Call trace:
[ 1694.940562]  __switch_to+0xf0/0x16c
[ 1694.940564]  __schedule+0x334/0x980
[ 1694.940566]  schedule+0x5c/0xf8
[ 1694.940567]  jbd2_journal_wait_updates+0x68/0xdc
[ 1694.940569]  jbd2_journal_commit_transaction+0x184/0x1b4c
[ 1694.940572]  kjournald2+0xbc/0x260
[ 1694.940573]  kthread+0x118/0x11c
[ 1694.940576]  ret_from_fork+0x10/0x20
[ 1694.940583] INFO: task systemd-timesyn:859 blocked for more than 120 seconds.
[ 1694.948628]       Tainted: G        W  O       6.6.33-debug #1
[ 1694.955332] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1694.964088] task:systemd-timesyn state:D stack:0     pid:859   ppid:1      flags:0x00000a00
[ 1694.964090] Call trace:
[ 1694.964091]  __switch_to+0xf0/0x16c
[ 1694.964093]  __schedule+0x334/0x980
[ 1694.964094]  schedule+0x5c/0xf8
[ 1694.964096]  wait_transaction_locked+0x7c/0xcc
[ 1694.964098]  add_transaction_credits+0x130/0x338
[ 1694.964100]  start_this_handle+0xf0/0x52c
[ 1694.964102]  jbd2__journal_start+0x110/0x24c
[ 1694.964104]  __ext4_journal_start_sb+0x114/0x1c4
[ 1694.964106]  ext4_dirty_inode+0x38/0x88
[ 1694.964108]  __mark_inode_dirty+0x58/0x41c
[ 1694.964110]  ext4_setattr+0x48c/0xa64
[ 1694.964112]  notify_change+0x1a8/0x3f8
[ 1694.964114]  ovl_setattr+0x114/0x1f0 [overlay]
[ 1694.964121]  notify_change+0x1a8/0x3f8
[ 1694.964122]  vfs_utimes+0x12c/0x228
[ 1694.964125]  do_utimes+0x94/0x178
[ 1694.964127]  __arm64_sys_utimensat+0x78/0xd0
[ 1694.964130]  invoke_syscall+0x48/0x118
[ 1694.964132]  el0_svc_common.constprop.0+0xc8/0xe8
[ 1694.964135]  do_el0_svc+0x20/0x2c
[ 1694.964137]  el0_svc+0x40/0x120
[ 1694.964139]  el0t_64_sync_handler+0x13c/0x158
[ 1694.964141]  el0t_64_sync+0x1a0/0x1a4
[ 1694.964179] INFO: task rs:main Q:Reg:2005 blocked for more than 120 seconds.
[ 1694.972145]       Tainted: G        W  O       6.6.33-debug #1
[ 1694.978856] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1694.987612] task:rs:main Q:Reg   state:D stack:0     pid:2005  ppid:1      flags:0x00000200
[ 1694.987614] Call trace:
[ 1694.987614]  __switch_to+0xf0/0x16c
[ 1694.987617]  __schedule+0x334/0x980
[ 1694.987618]  schedule+0x5c/0xf8
[ 1694.987620]  wait_transaction_locked+0x7c/0xcc
[ 1694.987622]  add_transaction_credits+0x130/0x338
[ 1694.987624]  start_this_handle+0xf0/0x52c
[ 1694.987626]  jbd2__journal_start+0x110/0x24c
[ 1694.987628]  __ext4_journal_start_sb+0x114/0x1c4
[ 1694.987630]  ext4_dirty_inode+0x38/0x88
[ 1694.987632]  __mark_inode_dirty+0x58/0x41c
[ 1694.987634]  generic_update_time+0x4c/0x60
[ 1694.987635]  file_modified+0xcc/0xd0
[ 1694.987637]  ext4_buffered_write_iter+0x58/0x10c
[ 1694.987640]  ext4_file_write_iter+0x54/0x69c
[ 1694.987642]  do_iter_readv_writev+0xbc/0x14c
[ 1694.987645]  do_iter_write+0x94/0x214
[ 1694.987646]  vfs_iter_write+0x1c/0x30
[ 1694.987648]  ovl_write_iter+0x278/0x300 [overlay]
[ 1694.987654]  vfs_write+0x230/0x2f0
[ 1694.987655]  ksys_write+0x6c/0xfc
[ 1694.987656]  __arm64_sys_write+0x1c/0x28
[ 1694.987658]  invoke_syscall+0x48/0x118
[ 1694.987660]  el0_svc_common.constprop.0+0xc8/0xe8
[ 1694.987663]  do_el0_svc+0x20/0x2c
[ 1694.987665]  el0_svc+0x40/0x120
[ 1694.987667]  el0t_64_sync_handler+0x13c/0x158
[ 1694.987670]  el0t_64_sync+0x1a0/0x1a4
[ 1694.987674] INFO: task kworker/u16:3:2154 blocked for more than 120 seconds.
[ 1694.995628]       Tainted: G        W  O       6.6.33-debug #1
[ 1695.002335] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1695.011094] task:kworker/u16:3   state:D stack:0     pid:2154  ppid:2      flags:0x00000208
[ 1695.011097] Workqueue: writeback wb_workfn (flush-8:0)
[ 1695.011101] Call trace:
[ 1695.011102]  __switch_to+0xf0/0x16c
[ 1695.011104]  __schedule+0x334/0x980
[ 1695.011105]  schedule+0x5c/0xf8
[ 1695.011107]  schedule_timeout+0x19c/0x1c0
[ 1695.011110]  wait_for_completion+0x78/0x188
[ 1695.011111]  fscrypt_crypt_block+0x218/0x25c
[ 1695.011114]  fscrypt_encrypt_pagecache_blocks+0x104/0x1b4
[ 1695.011117]  ext4_bio_write_folio+0x534/0x7a8
[ 1695.011119]  mpage_submit_folio+0x70/0x98
[ 1695.011120]  mpage_map_and_submit_buffers+0x158/0x2c8
[ 1695.011122]  ext4_do_writepages+0x788/0xbfc
[ 1695.011124]  ext4_writepages+0x7c/0xfc
[ 1695.011126]  do_writepages+0x8c/0x1c0
[ 1695.011128]  __writeback_single_inode+0x44/0x4a4
[ 1695.011130]  writeback_sb_inodes+0x214/0x498
[ 1695.011132]  __writeback_inodes_wb+0x50/0x108
[ 1695.011134]  wb_writeback+0x2d8/0x3bc
[ 1695.011136]  wb_workfn+0x278/0x5c8
[ 1695.011138]  process_one_work+0x170/0x3b8
[ 1695.011139]  worker_thread+0x2c8/0x3d8
[ 1695.011141]  kthread+0x118/0x11c
[ 1695.011143]  ret_from_fork+0x10/0x20
[ 1695.011146] INFO: task sync:2271 blocked for more than 121 seconds.
[ 1695.018313]       Tainted: G        W  O       6.6.33-debug #1
[ 1695.025025] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1695.033779] task:sync            state:D stack:0     pid:2271  ppid:1086   flags:0x00000208
[ 1695.033781] Call trace:
[ 1695.033782]  __switch_to+0xf0/0x16c
[ 1695.033784]  __schedule+0x334/0x980
[ 1695.033786]  schedule+0x5c/0xf8
[ 1695.033787]  wb_wait_for_completion+0x9c/0xc8
[ 1695.033789]  sync_inodes_sb+0xb8/0x268
[ 1695.033791]  sync_inodes_one_sb+0x1c/0x28
[ 1695.033794]  iterate_supers+0xa0/0x124
[ 1695.033796]  ksys_sync+0x4c/0xb8
[ 1695.033798]  __arm64_sys_sync+0x10/0x20
[ 1695.033800]  invoke_syscall+0x48/0x118
[ 1695.033803]  el0_svc_common.constprop.0+0xc8/0xe8
[ 1695.033805]  do_el0_svc+0x20/0x2c
[ 1695.033808]  el0_svc+0x40/0x120
[ 1695.033810]  el0t_64_sync_handler+0x13c/0x158
[ 1695.033812]  el0t_64_sync+0x1a0/0x1a4

Thanks,
Yuvaraj, Senior Engineer,
Qualcomm Incorporated.

Re: Software encryption at fscrypt causing the filesystem access unresponsive

[Theodore Ts'o]

On Wed, Jul 24, 2024 at 02:21:26PM +0000, Yuvaraj Ranganathan wrote:
> Hello developers,
> 
> We are trying to validate a Software file based encryption with
> standard key by disabling Inline encryption and we are observing the
> adb session is hung.  We are not able to access the same filesystem
> at that moment.

The stack trace seems to indicate that the fast_commit feature is
enabled.  That's a relatively new feature; can you replicate the hang
without fast_commit being enabled?

						- Ted

RE: Software encryption at fscrypt causing the filesystem access unresponsive

[Yuvaraj Ranganathan (QUIC)]

Hello Ted,

I don't see fast_commit feature is enabled for this filesystem.

Here are the filesystem features enabled for that disk partition,

Filesystem features: 
has_journal ext_attr resize_inode dir_index stable_inodes filetype needs_recovery extent 64bit flex_bg encrypt sparse_super large_file huge_file dir_nlink extra_isize metadata_csum

Thanks,
Yuvaraj.

-----Original Message-----
From: Theodore Ts'o <tytso@mit.edu> 
Sent: Wednesday, July 24, 2024 9:52 PM
To: Yuvaraj Ranganathan <yrangana@qti.qualcomm.com>
Cc: linux-fscrypt@vger.kernel.org; linux-fsdevel@vger.kernel.org; linux-kernel@vger.kernel.org
Subject: Re: Software encryption at fscrypt causing the filesystem access unresponsive

WARNING: This email originated from outside of Qualcomm. Please be wary of any links or attachments, and do not enable macros.

On Wed, Jul 24, 2024 at 02:21:26PM +0000, Yuvaraj Ranganathan wrote:
> Hello developers,
>
> We are trying to validate a Software file based encryption with 
> standard key by disabling Inline encryption and we are observing the 
> adb session is hung.  We are not able to access the same filesystem at 
> that moment.

The stack trace seems to indicate that the fast_commit feature is enabled.  That's a relatively new feature; can you replicate the hang without fast_commit being enabled?

                                                - Ted

Re: Software encryption at fscrypt causing the filesystem access unresponsive

[Eric Biggers]

On Wed, Jul 24, 2024 at 02:21:26PM +0000, Yuvaraj Ranganathan wrote:
> [ 1694.987674] INFO: task kworker/u16:3:2154 blocked for more than 120 seconds.
> [ 1694.995628]       Tainted: G        W  O       6.6.33-debug #1
> [ 1695.002335] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 1695.011094] task:kworker/u16:3   state:D stack:0     pid:2154  ppid:2      flags:0x00000208
> [ 1695.011097] Workqueue: writeback wb_workfn (flush-8:0)
> [ 1695.011101] Call trace:
> [ 1695.011102]  __switch_to+0xf0/0x16c
> [ 1695.011104]  __schedule+0x334/0x980
> [ 1695.011105]  schedule+0x5c/0xf8
> [ 1695.011107]  schedule_timeout+0x19c/0x1c0
> [ 1695.011110]  wait_for_completion+0x78/0x188
> [ 1695.011111]  fscrypt_crypt_block+0x218/0x25c
> [ 1695.011114]  fscrypt_encrypt_pagecache_blocks+0x104/0x1b4
> [ 1695.011117]  ext4_bio_write_folio+0x534/0x7a8
> [ 1695.011119]  mpage_submit_folio+0x70/0x98
> [ 1695.011120]  mpage_map_and_submit_buffers+0x158/0x2c8
> [ 1695.011122]  ext4_do_writepages+0x788/0xbfc
> [ 1695.011124]  ext4_writepages+0x7c/0xfc

I think this is the important part.  It's showing that the call into the crypto
API to actually encrypt the data is hanging.

What I suspect is that you are *not* actually using software encryption, but
rather a buggy driver for an off-CPU crypto accelerator.  This would happen if
your driver registers itself with the crypto API with a higher priority than the
software algorithm you intended to use.

To check what driver is being used, you can either check for a kernel log
message that looks like 'fscrypt: AES-256-XTS using implementation
"xts-aes-ce"', or check /proc/crypto for which xts(aes) algorithm has the
highest priority.

Which driver are you using, and is it upstream?

- Eric