Received-SPF: pass (google.com: domain of linux-ext4-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Subject: Re: [powerpc][5.13.0-next-20210701] Kernel crash while running
 ltp(chdir01) tests
To:     Guoqing Jiang <guoqing.jiang@linux.dev>,
        Sachin Sant <sachinp@linux.vnet.ibm.com>,
        <linux-ext4@vger.kernel.org>, <linux-fsdevel@vger.kernel.org>
CC:     <linuxppc-dev@lists.ozlabs.org>, <jack@suse.cz>,
        Theodore Ts'o <tytso@mit.edu>
References: <26ACA75D-E13D-405B-9BFC-691B5FB64243@linux.vnet.ibm.com>
 <bf1c5b38-92f1-65db-e210-a97a199718ba@linux.dev>
From:   Zhang Yi <yi.zhang@huawei.com>
Message-ID: <4cc87ab3-aaa6-ed87-b690-5e5b99de8380@huawei.com>
Date:   Fri, 2 Jul 2021 21:23:01 +0800
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:78.0) Gecko/20100101
 Thunderbird/78.3.1
MIME-Version: 1.0
In-Reply-To: <bf1c5b38-92f1-65db-e210-a97a199718ba@linux.dev>
Content-Type: text/plain; charset="utf-8"
Content-Language: en-US
Content-Transfer-Encoding: 8bit
Precedence: bulk

On 2021/7/2 17:38, Guoqing Jiang wrote:
> 
> 
> On 7/2/21 4:51 PM, Sachin Sant wrote:
>> While running LTP tests (chdir01) against 5.13.0-next20210701 booted on a Power server,
>> following crash is encountered.
>>
>> [ 3051.182992] ext2 filesystem being mounted at /var/tmp/avocado_oau90dri/ltp-W0cFB5HtCy/lKhal5/mntpoint supports timestamps until 2038 (0x7fffffff)
>> [ 3051.621341] EXT4-fs (loop0): mounting ext3 file system using the ext4 subsystem
>> [ 3051.624645] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.
>> [ 3051.624682] ext3 filesystem being mounted at /var/tmp/avocado_oau90dri/ltp-W0cFB5HtCy/lKhal5/mntpoint supports timestamps until 2038 (0x7fffffff)
>> [ 3051.629026] Kernel attempted to read user page (13fda70000) - exploit attempt? (uid: 0)
>> [ 3051.629074] BUG: Unable to handle kernel data access on read at 0x13fda70000
>> [ 3051.629103] Faulting instruction address: 0xc0000000006fa5cc
>> [ 3051.629118] Oops: Kernel access of bad area, sig: 11 [#1]
>> [ 3051.629130] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=2048 NUMA pSeries
>> [ 3051.629148] Modules linked in: vfat fat btrfs blake2b_generic xor zstd_compress raid6_pq xfs loop sctp ip6_udp_tunnel udp_tunnel libcrc32c rpadlpar_io rpaphp dm_mod bonding rfkill sunrpc pseries_rng xts vmx_crypto uio_pdrv_genirq uio sch_fq_codel ip_tables ext4 mbcache jbd2 sd_mod t10_pi sg ibmvscsi ibmveth scsi_transport_srp fuse [last unloaded: test_cpuidle_latency]
>> [ 3051.629270] CPU: 10 PID: 274044 Comm: chdir01 Tainted: G        W  OE     5.13.0-next-20210701 #1
>> [ 3051.629289] NIP:  c0000000006fa5cc LR: c008000006949bc4 CTR: c0000000006fa5a0
>> [ 3051.629300] REGS: c000000f74de3660 TRAP: 0300   Tainted: G        W  OE      (5.13.0-next-20210701)
>> [ 3051.629314] MSR:  800000000280b033 <SF,VEC,VSX,EE,FP,ME,IR,DR,RI,LE>  CR: 24000288  XER: 20040000
>> [ 3051.629342] CFAR: c008000006957564 DAR: 00000013fda70000 DSISR: 40000000 IRQMASK: 0
>> [ 3051.629342] GPR00: c008000006949bc4 c000000f74de3900 c0000000029bc800 c000000f88f0ab80
>> [ 3051.629342] GPR04: ffffffffffffffff 0000000000000020 0000000024000282 0000000000000000
>> [ 3051.629342] GPR08: c00000110628c828 0000000000000000 00000013fda70000 c008000006957550
>> [ 3051.629342] GPR12: c0000000006fa5a0 c0000013ffffbe80 0000000000000000 0000000000000000
>> [ 3051.629342] GPR16: 0000000000000000 0000000000000000 00000000100555f8 0000000010050d40
>> [ 3051.629342] GPR20: 0000000000000000 0000000010026188 0000000010026160 c000000f88f0ac08
>> [ 3051.629342] GPR24: 0000000000000000 c000000f88f0a920 0000000000000000 0000000000000002
>> [ 3051.629342] GPR28: c000000f88f0ac50 c000000f88f0a800 c000000fc5577d00 c000000f88f0ab80
>> [ 3051.629468] NIP [c0000000006fa5cc] percpu_counter_add_batch+0x2c/0xf0
>> [ 3051.629493] LR [c008000006949bc4] __jbd2_journal_remove_checkpoint+0x9c/0x280 [jbd2]
>> [ 3051.629526] Call Trace:
>> [ 3051.629532] [c000000f74de3900] [c000000f88f0a84c] 0xc000000f88f0a84c (unreliable)
>> [ 3051.629547] [c000000f74de3940] [c008000006949bc4] __jbd2_journal_remove_checkpoint+0x9c/0x280 [jbd2]
>> [ 3051.629577] [c000000f74de3980] [c008000006949eb4] jbd2_log_do_checkpoint+0x10c/0x630 [jbd2]
>> [ 3051.629605] [c000000f74de3a40] [c0080000069547dc] jbd2_journal_destroy+0x1b4/0x4e0 [jbd2]
>> [ 3051.629636] [c000000f74de3ad0] [c00800000735d72c] ext4_put_super+0xb4/0x560 [ext4]
>> [ 3051.629703] [c000000f74de3b60] [c000000000484d64] generic_shutdown_super+0xc4/0x1d0
>> [ 3051.629720] [c000000f74de3bd0] [c000000000484f48] kill_block_super+0x38/0x90
>> [ 3051.629736] [c000000f74de3c00] [c000000000485120] deactivate_locked_super+0x80/0x100
>> [ 3051.629752] [c000000f74de3c30] [c0000000004bec1c] cleanup_mnt+0x10c/0x1d0
>> [ 3051.629767] [c000000f74de3c80] [c000000000188b08] task_work_run+0xf8/0x170
>> [ 3051.629783] [c000000f74de3cd0] [c000000000021a24] do_notify_resume+0x434/0x480
>> [ 3051.629800] [c000000f74de3d80] [c000000000032910] interrupt_exit_user_prepare_main+0x1a0/0x260
>> [ 3051.629816] [c000000f74de3de0] [c000000000032d08] syscall_exit_prepare+0x68/0x150
>> [ 3051.629830] [c000000f74de3e10] [c00000000000c770] system_call_common+0x100/0x258
>> [ 3051.629846] --- interrupt: c00 at 0x7fffa2b92ffc
>> [ 3051.629855] NIP:  00007fffa2b92ffc LR: 00007fffa2b92fcc CTR: 0000000000000000
>> [ 3051.629867] REGS: c000000f74de3e80 TRAP: 0c00   Tainted: G        W  OE      (5.13.0-next-20210701)
>> [ 3051.629880] MSR:  800000000280f033 <SF,VEC,VSX,EE,PR,FP,ME,IR,DR,RI,LE>  CR: 24000474  XER: 00000000
>> [ 3051.629908] IRQMASK: 0
>> [ 3051.629908] GPR00: 0000000000000034 00007fffc0242e20 00007fffa2c77100 0000000000000000
>> [ 3051.629908] GPR04: 0000000000000000 0000000000000078 0000000000000000 0000000000000020
>> [ 3051.629908] GPR08: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
>> [ 3051.629908] GPR12: 0000000000000000 00007fffa2d1a310 0000000000000000 0000000000000000
>> [ 3051.629908] GPR16: 0000000000000000 0000000000000000 00000000100555f8 0000000010050d40
>> [ 3051.629908] GPR20: 0000000000000000 0000000010026188 0000000010026160 00000000100288f0
>> [ 3051.629908] GPR24: 00007fffa2d13320 00000000000186a0 0000000010025dd8 0000000010055688
>> [ 3051.629908] GPR28: 0000000010024bb8 0000000000000001 0000000000000001 0000000000000000
>> [ 3051.630022] NIP [00007fffa2b92ffc] 0x7fffa2b92ffc
>> [ 3051.630032] LR [00007fffa2b92fcc] 0x7fffa2b92fcc
>> [ 3051.630041] --- interrupt: c00
>> [ 3051.630048] Instruction dump:
>> [ 3051.630057] 60000000 3c4c022c 38422260 7c0802a6 fbe1fff8 fba1ffe8 7c7f1b78 fbc1fff0
>> [ 3051.630078] f8010010 f821ffc1 e94d0030 e9230020 <7fca4aaa> 7fbe2214 7fa9fe76 7d2aea78
>> [ 3051.630102] ---[ end trace 83afe3a19212c333 ]---
>> [ 3051.633656]
>> [ 3052.633681] Kernel panic - not syncing: Fatal exception
>>
>> 5.13.0-next-20210630 was good. Bisect points to following patch:
>>
>> commit 4ba3fcdde7e3
>>           jbd2,ext4: add a shrinker to release checkpointed buffers
>>
>> Reverting this patch allows the test to run successfully.
> 
> I guess the problem is j_jh_shrink_count was destroyed in ext4_put_super _>  jbd2_journal_unregister_shrinker
> which is before the path ext4_put_super -> jbd2_journal_destroy -> jbd2_log_do_checkpoint to call
> percpu_counter_dec(&journal->j_jh_shrink_count).
> 
> And since jbd2_journal_unregister_shrinker is already called inside jbd2_journal_destroy, does it make sense
> to do this?
> 
> --- a/fs/ext4/super.c
> +++ b/fs/ext4/super.c
> @@ -1176,7 +1176,6 @@ static void ext4_put_super(struct super_block  *sb)
>         ext4_unregister_sysfs(sb);
> 
>         if (sbi->s_journal) {
> -               jbd2_journal_unregister_shrinker(sbi->s_journal);
>                 aborted = is_journal_aborted(sbi->s_journal);
>                 err = jbd2_journal_destroy(sbi->s_journal);
>                 sbi->s_journal = NULL;
> 

Hi Guoqing,

Thanks for your analyze. This problem cannot reproduce on x86_64 but 100% reproduce on arm64,
it depends on the percpu counter code on different architecture.

Indeed, as you said, the real problem is invoke percpu_counter_dec(&journal->j_jh_shrink_count)
after it was destroyed during umount, and I'm afraid that it may also affect ocfs2
because it doesn't initialize the percpu counter before doing add/sub in
__jbd2_journal_[insert|remove]_checkpoint().

I think the quick fix could be:

diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
index 152880c298ca..48c7e5d17b38 100644
--- a/fs/jbd2/journal.c
+++ b/fs/jbd2/journal.c
@@ -1352,17 +1352,23 @@ static journal_t *journal_init_common(struct block_device *bdev,
        if (!journal->j_wbuf)
                goto err_cleanup;

+       err = percpu_counter_init(&journal->j_jh_shrink_count, 0, GFP_KERNEL);
+       if (err)
+               goto err_cleanup;
+
        bh = getblk_unmovable(journal->j_dev, start, journal->j_blocksize);
        if (!bh) {
                pr_err("%s: Cannot get buffer for journal superblock\n",
                        __func__);
-               goto err_cleanup;
+               goto err_cleanup_cnt;
        }
        journal->j_sb_buffer = bh;
        journal->j_superblock = (journal_superblock_t *)bh->b_data;

        return journal;

+err_cleanup_cnt:
+       percpu_counter_destroy(&journal->j_jh_shrink_count);
 err_cleanup:
        kfree(journal->j_wbuf);
        jbd2_journal_destroy_revoke(journal);
@@ -2101,26 +2107,13 @@ static unsigned long jbd2_journal_shrink_count(struct shrinker *shrink,
  */
 int jbd2_journal_register_shrinker(journal_t *journal)
 {
-       int err;
-
        journal->j_shrink_transaction = NULL;
-
-       err = percpu_counter_init(&journal->j_jh_shrink_count, 0, GFP_KERNEL);
-       if (err)
-               return err;
-
        journal->j_shrinker.scan_objects = jbd2_journal_shrink_scan;
        journal->j_shrinker.count_objects = jbd2_journal_shrink_count;
        journal->j_shrinker.seeks = DEFAULT_SEEKS;
        journal->j_shrinker.batch = journal->j_max_transaction_buffers;

-       err = register_shrinker(&journal->j_shrinker);
-       if (err) {
-               percpu_counter_destroy(&journal->j_jh_shrink_count);
-               return err;
-       }
-
-       return 0;
+       return register_shrinker(&journal->j_shrinker);
 }
 EXPORT_SYMBOL(jbd2_journal_register_shrinker);

@@ -2132,7 +2125,6 @@ EXPORT_SYMBOL(jbd2_journal_register_shrinker);
  */
 void jbd2_journal_unregister_shrinker(journal_t *journal)
 {
-       percpu_counter_destroy(&journal->j_jh_shrink_count);
        unregister_shrinker(&journal->j_shrinker);
 }
 EXPORT_SYMBOL(jbd2_journal_unregister_shrinker);
@@ -2209,8 +2201,6 @@ int jbd2_journal_destroy(journal_t *journal)
                brelse(journal->j_sb_buffer);
        }

-       jbd2_journal_unregister_shrinker(journal);
-
        if (journal->j_proc_entry)
                jbd2_stats_proc_exit(journal);
        iput(journal->j_inode);
@@ -2220,6 +2210,7 @@ int jbd2_journal_destroy(journal_t *journal)
                crypto_free_shash(journal->j_chksum_driver);
        kfree(journal->j_fc_wbuf);
        kfree(journal->j_wbuf);
+       percpu_counter_destroy(&journal->j_jh_shrink_count);
        kfree(journal);

        return err;

Thanks,
Yi.