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.