UBI/UBIFS corruptions during random power-cuts

Bhuvan,

Am 30.01.2017 um 14:31 schrieb Bhuvanchandra DV:
> On 01/30/2017 01:27 PM, Richard Weinberger wrote:
> 
>> Bhuvan,
>>
>> Am 30.01.2017 um 06:48 schrieb Bhuvanchandra DV:
>>> [    9.823378] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 126
>>> [   10.190926] UBIFS assert failed in pack_bits at 242 (pid 120)
>>> [   10.197294] CPU: 0 PID: 120 Comm: mount Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #13
>>> [   10.205952] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>>> [   10.212515] Backtrace:
>>> [   10.215142] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>>> [   10.222899]  r7:00000000 r6:600c0013 r5:00000000 r4:c0e29058
>>> [   10.228716] [<c010c704>] (show_stack) from [<c03fcf18>] (dump_stack+0xb4/0xe8)
>>> [   10.236150] [<c03fce64>] (dump_stack) from [<c037b2dc>] (pack_bits+0x1f4/0x200)
>>> [   10.243649]  r10:0000b800 r9:ffffffee r8:c32bdd50 r7:c32bdd54 r6:00000001 r5:c831c860
>>> [   10.251651]  r4:0000000e r3:00000000
>>> [   10.255352] [<c037b0e8>] (pack_bits) from [<c037bf90>] (ubifs_pack_pnode+0x84/0x104)
>>> [   10.263289]  r9:c831c853 r8:c831c851 r7:c32299e0 r6:c30dc000 r5:c32bdd54 r4:c32299c8
>>> [   10.271233] [<c037bf0c>] (ubifs_pack_pnode) from [<c0385d50>] (ubifs_lpt_end_commit+0x27c/0x6fc)
>>> [   10.280214]  r9:00000001 r8:c8311000 r7:00000011 r6:0000b862 r5:c3229980 r4:c30dc000
>>> [   10.288148] [<c0385ad4>] (ubifs_lpt_end_commit) from [<c0373658>] (do_commit+0x244/0x80c)
>>> [   10.296515]  r10:00000020 r9:00000020 r8:c3195dd4 r7:00000003 r6:c30dc2f0 r5:c30dc000
>>> [   10.304514]  r4:00000000
>>> [   10.307163] [<c0373414>] (do_commit) from [<c0373e70>] (ubifs_run_commit+0x9c/0xf0)
>>> [   10.315001]  r8:00000000 r7:c30dcb48 r6:c30dc3e4 r5:c30dc42c r4:c30dc000
>>> [   10.321856] [<c0373dd4>] (ubifs_run_commit) from [<c03823dc>] (ubifs_rcvry_gc_commit+0x7c/0x1d8)
>>> [   10.330830]  r7:c30dcb48 r6:c3195c00 r5:c30dcb8c r4:c30dc000
>>> [   10.336659] [<c0382360>] (ubifs_rcvry_gc_commit) from [<c0364700>] (ubifs_remount_fs+0x514/0x79c)
>>> [   10.345731]  r7:c30dcb48 r6:c32a3c00 r5:c30dcb8c r4:c30dc000
>>> [   10.351548] [<c03641ec>] (ubifs_remount_fs) from [<c0225188>] (do_remount_sb+0x6c/0x1d8)
>>> [   10.359825]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:c318a000
>>> [   10.367783] [<c022511c>] (do_remount_sb) from [<c0248f4c>] (do_mount+0x698/0xc84)
>>> [   10.375452]  r8:c3108b10 r7:c02498e8 r6:c318a000 r5:00000000 r4:c318a044
>>> [   10.382306] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>>> [   10.389416]  r10:00000000 r9:c32bc000 r8:c0ed0020 r7:01696860 r6:00000000 r5:c3214b40
>>> [   10.397418]  r4:c3214e80
>>> [   10.400075] [<c024986c>] (SyS_mount) from [<c0107e60>] (ret_fast_syscall+0x0/0x1c)
>>> [   10.407832]  r8:c0108004 r7:00000015 r6:00000000 r5:00000000 r4:00000000
>>> [   10.518251] systemd[1]: Started Journal Service.
>> This is what I was looking for! :)
>> Let's see whether I can find the root cause with that issue, otherwise I'll create
>> a debug patch for you.
> 
> Sure! Thank you.

Hmm, i suspect that the dirty variable turns negative. Can you please reproduce
with the attached debug patch? Maybe it gives us more hints what is going on.

Thanks,
//richard

On 01/31/2017 02:18 AM, Richard Weinberger wrote:

> Bhuvan,
>
> Am 30.01.2017 um 14:31 schrieb Bhuvanchandra DV:
>> On 01/30/2017 01:27 PM, Richard Weinberger wrote:
>>
>>> Bhuvan,
>>>
>>> Am 30.01.2017 um 06:48 schrieb Bhuvanchandra DV:
>>>> [    9.823378] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 126
>>>> [   10.190926] UBIFS assert failed in pack_bits at 242 (pid 120)
>>>> [   10.197294] CPU: 0 PID: 120 Comm: mount Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #13
>>>> [   10.205952] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>>>> [   10.212515] Backtrace:
>>>> [   10.215142] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>>>> [   10.222899]  r7:00000000 r6:600c0013 r5:00000000 r4:c0e29058
>>>> [   10.228716] [<c010c704>] (show_stack) from [<c03fcf18>] (dump_stack+0xb4/0xe8)
>>>> [   10.236150] [<c03fce64>] (dump_stack) from [<c037b2dc>] (pack_bits+0x1f4/0x200)
>>>> [   10.243649]  r10:0000b800 r9:ffffffee r8:c32bdd50 r7:c32bdd54 r6:00000001 r5:c831c860
>>>> [   10.251651]  r4:0000000e r3:00000000
>>>> [   10.255352] [<c037b0e8>] (pack_bits) from [<c037bf90>] (ubifs_pack_pnode+0x84/0x104)
>>>> [   10.263289]  r9:c831c853 r8:c831c851 r7:c32299e0 r6:c30dc000 r5:c32bdd54 r4:c32299c8
>>>> [   10.271233] [<c037bf0c>] (ubifs_pack_pnode) from [<c0385d50>] (ubifs_lpt_end_commit+0x27c/0x6fc)
>>>> [   10.280214]  r9:00000001 r8:c8311000 r7:00000011 r6:0000b862 r5:c3229980 r4:c30dc000
>>>> [   10.288148] [<c0385ad4>] (ubifs_lpt_end_commit) from [<c0373658>] (do_commit+0x244/0x80c)
>>>> [   10.296515]  r10:00000020 r9:00000020 r8:c3195dd4 r7:00000003 r6:c30dc2f0 r5:c30dc000
>>>> [   10.304514]  r4:00000000
>>>> [   10.307163] [<c0373414>] (do_commit) from [<c0373e70>] (ubifs_run_commit+0x9c/0xf0)
>>>> [   10.315001]  r8:00000000 r7:c30dcb48 r6:c30dc3e4 r5:c30dc42c r4:c30dc000
>>>> [   10.321856] [<c0373dd4>] (ubifs_run_commit) from [<c03823dc>] (ubifs_rcvry_gc_commit+0x7c/0x1d8)
>>>> [   10.330830]  r7:c30dcb48 r6:c3195c00 r5:c30dcb8c r4:c30dc000
>>>> [   10.336659] [<c0382360>] (ubifs_rcvry_gc_commit) from [<c0364700>] (ubifs_remount_fs+0x514/0x79c)
>>>> [   10.345731]  r7:c30dcb48 r6:c32a3c00 r5:c30dcb8c r4:c30dc000
>>>> [   10.351548] [<c03641ec>] (ubifs_remount_fs) from [<c0225188>] (do_remount_sb+0x6c/0x1d8)
>>>> [   10.359825]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:c318a000
>>>> [   10.367783] [<c022511c>] (do_remount_sb) from [<c0248f4c>] (do_mount+0x698/0xc84)
>>>> [   10.375452]  r8:c3108b10 r7:c02498e8 r6:c318a000 r5:00000000 r4:c318a044
>>>> [   10.382306] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>>>> [   10.389416]  r10:00000000 r9:c32bc000 r8:c0ed0020 r7:01696860 r6:00000000 r5:c3214b40
>>>> [   10.397418]  r4:c3214e80
>>>> [   10.400075] [<c024986c>] (SyS_mount) from [<c0107e60>] (ret_fast_syscall+0x0/0x1c)
>>>> [   10.407832]  r8:c0108004 r7:00000015 r6:00000000 r5:00000000 r4:00000000
>>>> [   10.518251] systemd[1]: Started Journal Service.
>>> This is what I was looking for! :)
>>> Let's see whether I can find the root cause with that issue, otherwise I'll create
>>> a debug patch for you.
>> Sure! Thank you.
> Hmm, i suspect that the dirty variable turns negative. Can you please reproduce
> with the attached debug patch? Maybe it gives us more hints what is going on.

Here is the log:

[    4.313136] UBIFS (ubi0:2): recovery needed
[    4.646472] ------------[ cut here ]------------
[    4.651575] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
[    4.660406] Modules linked in:
[    4.663904] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #14
[    4.672721] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    4.679290] Backtrace:
[    4.681907] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[    4.689665]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
[    4.695480] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[    4.702896] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
[    4.710006]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
[    4.718008]  r4:00000000 r3:00000000
[    4.721702] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
[    4.729454]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:0001b948 r5:c32326c8 r4:c31dcb40
[    4.737386] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
[    4.746745] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
[    4.755468]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
[    4.763468]  r4:00000000
[    4.766138] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
[    4.773427]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
[    4.781424]  r4:c3108b00
[    4.784090] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
[    4.791747]  r6:00008001 r5:c31dc340 r4:c3108b00
[    4.796509] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
[    4.804263]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
[    4.812197] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
[    4.819307]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
[    4.827301]  r4:c31dc300
[    4.829955] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
[    4.837970]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
[    4.844820] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
[    4.853453]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
[    4.861452]  r4:c0d60888
[    4.864099] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
[    4.873155]  r6:c0d73d5c r5:c0e78000 r4:00000008
[    4.877912] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
[    4.886369]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
[    4.894361]  r4:00000000
[    4.897019] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
[    4.904767]  r5:c0979c20 r4:00000000
[    4.908858] ---[ end trace 0f8d6b2bab39eeac ]---
[    4.913831] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 909 lp free: 126976 lp dirty: 112968 b free: 0 b8
[    4.927181] ------------[ cut here ]------------
[    4.932194] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
[    4.941005] Modules linked in:
[    4.944485] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
[    4.954530] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    4.961097] Backtrace:
[    4.963702] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[    4.971456]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
[    4.977272] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[    4.984684] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
[    4.991798]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
[    4.999800]  r4:00000000 r3:00000000
[    5.003497] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
[    5.011254]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:000143e8 r5:c32326b0 r4:c31dcbc0
[    5.019192] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
[    5.028553] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
[    5.037277]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
[    5.045277]  r4:00000000
[    5.047938] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
[    5.055224]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
[    5.063224]  r4:c3108b00
[    5.065886] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
[    5.073547]  r6:00008001 r5:c31dc340 r4:c3108b00
[    5.078309] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
[    5.086063]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
[    5.093999] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
[    5.101107]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
[    5.109103]  r4:c31dc300
[    5.111754] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
[    5.119770]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
[    5.126622] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
[    5.135252]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
[    5.143250]  r4:c0d60888
[    5.145899] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
[    5.154954]  r6:c0d73d5c r5:c0e78000 r4:00000008
[    5.159709] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
[    5.168160]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
[    5.176151]  r4:00000000
[    5.178811] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
[    5.186556]  r5:c0979c20 r4:00000000
[    5.190810] ---[ end trace 0f8d6b2bab39eead ]---
[    5.195803] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 908 lp free: 126976 lp dirty: 82920 b free: 0 b 0
[    5.209152] ------------[ cut here ]------------
[    5.214149] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
[    5.223250] Modules linked in:
[    5.226486] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
[    5.236506] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    5.243069] Backtrace:
[    5.245682] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[    5.253439]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
[    5.259249] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[    5.266668] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
[    5.273780]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
[    5.281783]  r4:00000000 r3:00000000
[    5.285478] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
[    5.293237]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:00015cf8 r5:c3232698 r4:c31dcc40
[    5.301176] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
[    5.310536] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
[    5.319259]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
[    5.327259]  r4:00000000
[    5.329923] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
[    5.337215]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
[    5.345216]  r4:c3108b00
[    5.347878] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
[    5.355537]  r6:00008001 r5:c31dc340 r4:c3108b00
[    5.360297] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
[    5.368056]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
[    5.375990] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
[    5.383099]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
[    5.391092]  r4:c31dc300
[    5.393743] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
[    5.401759]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
[    5.408613] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
[    5.417244]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
[    5.425243]  r4:c0d60888
[    5.427891] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
[    5.436947]  r6:c0d73d5c r5:c0e78000 r4:00000008
[    5.441701] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
[    5.450159]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
[    5.458151]  r4:00000000
[    5.460809] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
[    5.468549]  r5:c0979c20 r4:00000000
[    5.472625] ---[ end trace 0f8d6b2bab39eeae ]---
[    5.477444] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 907 lp free: 126976 lp dirty: 89336 b free: 0 b 6
[    5.490551] ------------[ cut here ]------------
[    5.495644] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
[    5.504653] Modules linked in:
[    5.507883] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
[    5.517898] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    5.524463] Backtrace:
[    5.527067] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[    5.534825]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
[    5.540637] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[    5.548053] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
[    5.555162]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
[    5.563165]  r4:00000000 r3:00000000
[    5.566862] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
[    5.574612]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:00005df0 r5:c3232ae0 r4:c31dccc0
[    5.582549] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
[    5.591910] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
[    5.600636]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
[    5.608635]  r4:00000000
[    5.611297] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
[    5.618582]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
[    5.626581]  r4:c3108b00
[    5.629245] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
[    5.636906]  r6:00008001 r5:c31dc340 r4:c3108b00
[    5.641664] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
[    5.649419]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
[    5.657355] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
[    5.664465]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
[    5.672459]  r4:c31dc300
[    5.675111] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
[    5.683127]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
[    5.689978] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
[    5.698609]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
[    5.706600]  r4:c0d60888
[    5.709248] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
[    5.718302]  r6:c0d73d5c r5:c0e78000 r4:00000008
[    5.723057] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
[    5.731508]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
[    5.739500]  r4:00000000
[    5.742149] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
[    5.749888]  r5:c0979c20 r4:00000000
[    5.753960] ---[ end trace 0f8d6b2bab39eeaf ]---
[    5.758775] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 906 lp free: 126976 lp dirty: 24048 b free: 0 b 8
[    5.819011] UBIFS (ubi0:2): recovery deferred
[    5.825155] UBIFS (ubi0:2): UBIFS: mounted UBI device 0, volume 2, name "rootfs", R/O mode
[    5.834016] UBIFS (ubi0:2): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
[    5.844368] UBIFS (ubi0:2): FS size: 114532352 bytes (109 MiB, 902 LEBs), journal size 9023488 bytes (8 MiB, 72 LE)
[    5.855418] UBIFS (ubi0:2): reserved for root: 0 bytes (0 KiB)
[    5.861580] UBIFS (ubi0:2): media format: w4/r0 (latest is w5/r0), UUID 297830B7-F714-4754-B0DA-617A5595067D, small
[    5.876654] VFS: Mounted root (ubifs filesystem) readonly on device 0:12.

--
Bhuvan

>
> Thanks,
> //richard

Bhuvan,

Am 31.01.2017 um 08:06 schrieb Bhuvanchandra DV:
>>>> Am 30.01.2017 um 06:48 schrieb Bhuvanchandra DV:
>>>>> [    9.823378] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 126
>>>>> [   10.190926] UBIFS assert failed in pack_bits at 242 (pid 120)
>>>>> [   10.197294] CPU: 0 PID: 120 Comm: mount Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #13
>>>>> [   10.205952] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>>>>> [   10.212515] Backtrace:
>>>>> [   10.215142] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>>>>> [   10.222899]  r7:00000000 r6:600c0013 r5:00000000 r4:c0e29058
>>>>> [   10.228716] [<c010c704>] (show_stack) from [<c03fcf18>] (dump_stack+0xb4/0xe8)
>>>>> [   10.236150] [<c03fce64>] (dump_stack) from [<c037b2dc>] (pack_bits+0x1f4/0x200)
>>>>> [   10.243649]  r10:0000b800 r9:ffffffee r8:c32bdd50 r7:c32bdd54 r6:00000001 r5:c831c860
>>>>> [   10.251651]  r4:0000000e r3:00000000
>>>>> [   10.255352] [<c037b0e8>] (pack_bits) from [<c037bf90>] (ubifs_pack_pnode+0x84/0x104)
>>>>> [   10.263289]  r9:c831c853 r8:c831c851 r7:c32299e0 r6:c30dc000 r5:c32bdd54 r4:c32299c8
>>>>> [   10.271233] [<c037bf0c>] (ubifs_pack_pnode) from [<c0385d50>] (ubifs_lpt_end_commit+0x27c/0x6fc)
>>>>> [   10.280214]  r9:00000001 r8:c8311000 r7:00000011 r6:0000b862 r5:c3229980 r4:c30dc000
>>>>> [   10.288148] [<c0385ad4>] (ubifs_lpt_end_commit) from [<c0373658>] (do_commit+0x244/0x80c)
>>>>> [   10.296515]  r10:00000020 r9:00000020 r8:c3195dd4 r7:00000003 r6:c30dc2f0 r5:c30dc000
>>>>> [   10.304514]  r4:00000000
>>>>> [   10.307163] [<c0373414>] (do_commit) from [<c0373e70>] (ubifs_run_commit+0x9c/0xf0)
>>>>> [   10.315001]  r8:00000000 r7:c30dcb48 r6:c30dc3e4 r5:c30dc42c r4:c30dc000
>>>>> [   10.321856] [<c0373dd4>] (ubifs_run_commit) from [<c03823dc>] (ubifs_rcvry_gc_commit+0x7c/0x1d8)
>>>>> [   10.330830]  r7:c30dcb48 r6:c3195c00 r5:c30dcb8c r4:c30dc000
>>>>> [   10.336659] [<c0382360>] (ubifs_rcvry_gc_commit) from [<c0364700>] (ubifs_remount_fs+0x514/0x79c)
>>>>> [   10.345731]  r7:c30dcb48 r6:c32a3c00 r5:c30dcb8c r4:c30dc000
>>>>> [   10.351548] [<c03641ec>] (ubifs_remount_fs) from [<c0225188>] (do_remount_sb+0x6c/0x1d8)
>>>>> [   10.359825]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:c318a000
>>>>> [   10.367783] [<c022511c>] (do_remount_sb) from [<c0248f4c>] (do_mount+0x698/0xc84)
>>>>> [   10.375452]  r8:c3108b10 r7:c02498e8 r6:c318a000 r5:00000000 r4:c318a044
>>>>> [   10.382306] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>>>>> [   10.389416]  r10:00000000 r9:c32bc000 r8:c0ed0020 r7:01696860 r6:00000000 r5:c3214b40
>>>>> [   10.397418]  r4:c3214e80
>>>>> [   10.400075] [<c024986c>] (SyS_mount) from [<c0107e60>] (ret_fast_syscall+0x0/0x1c)
>>>>> [   10.407832]  r8:c0108004 r7:00000015 r6:00000000 r5:00000000 r4:00000000
>>>>> [   10.518251] systemd[1]: Started Journal Service.
>>>> This is what I was looking for! :)
>>>> Let's see whether I can find the root cause with that issue, otherwise I'll create
>>>> a debug patch for you.
>>> Sure! Thank you.
>> Hmm, i suspect that the dirty variable turns negative. Can you please reproduce
>> with the attached debug patch? Maybe it gives us more hints what is going on.
> 
> Here is the log:
> 
> [    4.313136] UBIFS (ubi0:2): recovery needed
> [    4.646472] ------------[ cut here ]------------
> [    4.651575] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
> [    4.660406] Modules linked in:
> [    4.663904] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #14
> [    4.672721] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
> [    4.679290] Backtrace:
> [    4.681907] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
> [    4.689665]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
> [    4.695480] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
> [    4.702896] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
> [    4.710006]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
> [    4.718008]  r4:00000000 r3:00000000
> [    4.721702] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
> [    4.729454]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:0001b948 r5:c32326c8 r4:c31dcb40
> [    4.737386] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
> [    4.746745] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
> [    4.755468]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
> [    4.763468]  r4:00000000
> [    4.766138] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
> [    4.773427]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
> [    4.781424]  r4:c3108b00
> [    4.784090] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
> [    4.791747]  r6:00008001 r5:c31dc340 r4:c3108b00
> [    4.796509] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
> [    4.804263]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
> [    4.812197] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
> [    4.819307]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
> [    4.827301]  r4:c31dc300
> [    4.829955] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
> [    4.837970]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
> [    4.844820] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
> [    4.853453]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
> [    4.861452]  r4:c0d60888
> [    4.864099] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
> [    4.873155]  r6:c0d73d5c r5:c0e78000 r4:00000008
> [    4.877912] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
> [    4.886369]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
> [    4.894361]  r4:00000000
> [    4.897019] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
> [    4.904767]  r5:c0979c20 r4:00000000
> [    4.908858] ---[ end trace 0f8d6b2bab39eeac ]---
> [    4.913831] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 909 lp free: 126976 lp dirty: 112968 b free: 0 b8
> [    4.927181] ------------[ cut here ]------------
> [    4.932194] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
> [    4.941005] Modules linked in:
> [    4.944485] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
> [    4.954530] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
> [    4.961097] Backtrace:
> [    4.963702] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
> [    4.971456]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
> [    4.977272] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
> [    4.984684] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
> [    4.991798]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
> [    4.999800]  r4:00000000 r3:00000000
> [    5.003497] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
> [    5.011254]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:000143e8 r5:c32326b0 r4:c31dcbc0
> [    5.019192] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
> [    5.028553] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
> [    5.037277]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
> [    5.045277]  r4:00000000
> [    5.047938] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
> [    5.055224]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
> [    5.063224]  r4:c3108b00
> [    5.065886] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
> [    5.073547]  r6:00008001 r5:c31dc340 r4:c3108b00
> [    5.078309] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
> [    5.086063]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
> [    5.093999] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
> [    5.101107]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
> [    5.109103]  r4:c31dc300
> [    5.111754] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
> [    5.119770]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
> [    5.126622] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
> [    5.135252]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
> [    5.143250]  r4:c0d60888
> [    5.145899] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
> [    5.154954]  r6:c0d73d5c r5:c0e78000 r4:00000008
> [    5.159709] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
> [    5.168160]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
> [    5.176151]  r4:00000000
> [    5.178811] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
> [    5.186556]  r5:c0979c20 r4:00000000
> [    5.190810] ---[ end trace 0f8d6b2bab39eead ]---
> [    5.195803] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 908 lp free: 126976 lp dirty: 82920 b free: 0 b 0
> [    5.209152] ------------[ cut here ]------------
> [    5.214149] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
> [    5.223250] Modules linked in:
> [    5.226486] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
> [    5.236506] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
> [    5.243069] Backtrace:
> [    5.245682] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
> [    5.253439]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
> [    5.259249] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
> [    5.266668] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
> [    5.273780]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
> [    5.281783]  r4:00000000 r3:00000000
> [    5.285478] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
> [    5.293237]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:00015cf8 r5:c3232698 r4:c31dcc40
> [    5.301176] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
> [    5.310536] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
> [    5.319259]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
> [    5.327259]  r4:00000000
> [    5.329923] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
> [    5.337215]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
> [    5.345216]  r4:c3108b00
> [    5.347878] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
> [    5.355537]  r6:00008001 r5:c31dc340 r4:c3108b00
> [    5.360297] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
> [    5.368056]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
> [    5.375990] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
> [    5.383099]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
> [    5.391092]  r4:c31dc300
> [    5.393743] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
> [    5.401759]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
> [    5.408613] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
> [    5.417244]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
> [    5.425243]  r4:c0d60888
> [    5.427891] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
> [    5.436947]  r6:c0d73d5c r5:c0e78000 r4:00000008
> [    5.441701] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
> [    5.450159]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
> [    5.458151]  r4:00000000
> [    5.460809] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
> [    5.468549]  r5:c0979c20 r4:00000000
> [    5.472625] ---[ end trace 0f8d6b2bab39eeae ]---
> [    5.477444] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 907 lp free: 126976 lp dirty: 89336 b free: 0 b 6
> [    5.490551] ------------[ cut here ]------------
> [    5.495644] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
> [    5.504653] Modules linked in:
> [    5.507883] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
> [    5.517898] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
> [    5.524463] Backtrace:
> [    5.527067] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
> [    5.534825]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
> [    5.540637] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
> [    5.548053] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
> [    5.555162]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
> [    5.563165]  r4:00000000 r3:00000000
> [    5.566862] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
> [    5.574612]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:00005df0 r5:c3232ae0 r4:c31dccc0
> [    5.582549] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
> [    5.591910] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
> [    5.600636]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
> [    5.608635]  r4:00000000
> [    5.611297] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
> [    5.618582]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
> [    5.626581]  r4:c3108b00
> [    5.629245] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
> [    5.636906]  r6:00008001 r5:c31dc340 r4:c3108b00
> [    5.641664] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
> [    5.649419]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
> [    5.657355] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
> [    5.664465]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
> [    5.672459]  r4:c31dc300
> [    5.675111] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
> [    5.683127]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
> [    5.689978] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
> [    5.698609]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
> [    5.706600]  r4:c0d60888
> [    5.709248] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
> [    5.718302]  r6:c0d73d5c r5:c0e78000 r4:00000008
> [    5.723057] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
> [    5.731508]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
> [    5.739500]  r4:00000000
> [    5.742149] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
> [    5.749888]  r5:c0979c20 r4:00000000
> [    5.753960] ---[ end trace 0f8d6b2bab39eeaf ]---
> [    5.758775] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 906 lp free: 126976 lp dirty: 24048 b free: 0 b 8
> [    5.819011] UBIFS (ubi0:2): recovery deferred
> [    5.825155] UBIFS (ubi0:2): UBIFS: mounted UBI device 0, volume 2, name "rootfs", R/O mode
> [    5.834016] UBIFS (ubi0:2): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
> [    5.844368] UBIFS (ubi0:2): FS size: 114532352 bytes (109 MiB, 902 LEBs), journal size 9023488 bytes (8 MiB, 72 LE)
> [    5.855418] UBIFS (ubi0:2): reserved for root: 0 bytes (0 KiB)
> [    5.861580] UBIFS (ubi0:2): media format: w4/r0 (latest is w5/r0), UUID 297830B7-F714-4754-B0DA-617A5595067D, small
> [    5.876654] VFS: Mounted root (ubifs filesystem) readonly on device 0:12.
> 

Is this really the last triggered warning right before the power-cut where UBIFS renders unmountable?
I miss the failing ubifs_assert().

Thanks,
//richard

On 01/31/2017 02:01 PM, Richard Weinberger wrote:

> Bhuvan,
>
> Am 31.01.2017 um 08:06 schrieb Bhuvanchandra DV:
>>>>> Am 30.01.2017 um 06:48 schrieb Bhuvanchandra DV:
>>>>>> [    9.823378] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 126
>>>>>> [   10.190926] UBIFS assert failed in pack_bits at 242 (pid 120)
>>>>>> [   10.197294] CPU: 0 PID: 120 Comm: mount Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #13
>>>>>> [   10.205952] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>>>>>> [   10.212515] Backtrace:
>>>>>> [   10.215142] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>>>>>> [   10.222899]  r7:00000000 r6:600c0013 r5:00000000 r4:c0e29058
>>>>>> [   10.228716] [<c010c704>] (show_stack) from [<c03fcf18>] (dump_stack+0xb4/0xe8)
>>>>>> [   10.236150] [<c03fce64>] (dump_stack) from [<c037b2dc>] (pack_bits+0x1f4/0x200)
>>>>>> [   10.243649]  r10:0000b800 r9:ffffffee r8:c32bdd50 r7:c32bdd54 r6:00000001 r5:c831c860
>>>>>> [   10.251651]  r4:0000000e r3:00000000
>>>>>> [   10.255352] [<c037b0e8>] (pack_bits) from [<c037bf90>] (ubifs_pack_pnode+0x84/0x104)
>>>>>> [   10.263289]  r9:c831c853 r8:c831c851 r7:c32299e0 r6:c30dc000 r5:c32bdd54 r4:c32299c8
>>>>>> [   10.271233] [<c037bf0c>] (ubifs_pack_pnode) from [<c0385d50>] (ubifs_lpt_end_commit+0x27c/0x6fc)
>>>>>> [   10.280214]  r9:00000001 r8:c8311000 r7:00000011 r6:0000b862 r5:c3229980 r4:c30dc000
>>>>>> [   10.288148] [<c0385ad4>] (ubifs_lpt_end_commit) from [<c0373658>] (do_commit+0x244/0x80c)
>>>>>> [   10.296515]  r10:00000020 r9:00000020 r8:c3195dd4 r7:00000003 r6:c30dc2f0 r5:c30dc000
>>>>>> [   10.304514]  r4:00000000
>>>>>> [   10.307163] [<c0373414>] (do_commit) from [<c0373e70>] (ubifs_run_commit+0x9c/0xf0)
>>>>>> [   10.315001]  r8:00000000 r7:c30dcb48 r6:c30dc3e4 r5:c30dc42c r4:c30dc000
>>>>>> [   10.321856] [<c0373dd4>] (ubifs_run_commit) from [<c03823dc>] (ubifs_rcvry_gc_commit+0x7c/0x1d8)
>>>>>> [   10.330830]  r7:c30dcb48 r6:c3195c00 r5:c30dcb8c r4:c30dc000
>>>>>> [   10.336659] [<c0382360>] (ubifs_rcvry_gc_commit) from [<c0364700>] (ubifs_remount_fs+0x514/0x79c)
>>>>>> [   10.345731]  r7:c30dcb48 r6:c32a3c00 r5:c30dcb8c r4:c30dc000
>>>>>> [   10.351548] [<c03641ec>] (ubifs_remount_fs) from [<c0225188>] (do_remount_sb+0x6c/0x1d8)
>>>>>> [   10.359825]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:c318a000
>>>>>> [   10.367783] [<c022511c>] (do_remount_sb) from [<c0248f4c>] (do_mount+0x698/0xc84)
>>>>>> [   10.375452]  r8:c3108b10 r7:c02498e8 r6:c318a000 r5:00000000 r4:c318a044
>>>>>> [   10.382306] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>>>>>> [   10.389416]  r10:00000000 r9:c32bc000 r8:c0ed0020 r7:01696860 r6:00000000 r5:c3214b40
>>>>>> [   10.397418]  r4:c3214e80
>>>>>> [   10.400075] [<c024986c>] (SyS_mount) from [<c0107e60>] (ret_fast_syscall+0x0/0x1c)
>>>>>> [   10.407832]  r8:c0108004 r7:00000015 r6:00000000 r5:00000000 r4:00000000
>>>>>> [   10.518251] systemd[1]: Started Journal Service.
>>>>> This is what I was looking for! :)
>>>>> Let's see whether I can find the root cause with that issue, otherwise I'll create
>>>>> a debug patch for you.
>>>> Sure! Thank you.
>>> Hmm, i suspect that the dirty variable turns negative. Can you please reproduce
>>> with the attached debug patch? Maybe it gives us more hints what is going on.
>> Here is the log:
>>
>> [    4.313136] UBIFS (ubi0:2): recovery needed
>> [    4.646472] ------------[ cut here ]------------
>> [    4.651575] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
>> [    4.660406] Modules linked in:
>> [    4.663904] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #14
>> [    4.672721] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>> [    4.679290] Backtrace:
>> [    4.681907] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>> [    4.689665]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
>> [    4.695480] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
>> [    4.702896] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
>> [    4.710006]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
>> [    4.718008]  r4:00000000 r3:00000000
>> [    4.721702] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
>> [    4.729454]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:0001b948 r5:c32326c8 r4:c31dcb40
>> [    4.737386] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
>> [    4.746745] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
>> [    4.755468]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
>> [    4.763468]  r4:00000000
>> [    4.766138] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
>> [    4.773427]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
>> [    4.781424]  r4:c3108b00
>> [    4.784090] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
>> [    4.791747]  r6:00008001 r5:c31dc340 r4:c3108b00
>> [    4.796509] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
>> [    4.804263]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
>> [    4.812197] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>> [    4.819307]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
>> [    4.827301]  r4:c31dc300
>> [    4.829955] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
>> [    4.837970]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
>> [    4.844820] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
>> [    4.853453]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
>> [    4.861452]  r4:c0d60888
>> [    4.864099] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
>> [    4.873155]  r6:c0d73d5c r5:c0e78000 r4:00000008
>> [    4.877912] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
>> [    4.886369]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
>> [    4.894361]  r4:00000000
>> [    4.897019] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
>> [    4.904767]  r5:c0979c20 r4:00000000
>> [    4.908858] ---[ end trace 0f8d6b2bab39eeac ]---
>> [    4.913831] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 909 lp free: 126976 lp dirty: 112968 b free: 0 b8
>> [    4.927181] ------------[ cut here ]------------
>> [    4.932194] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
>> [    4.941005] Modules linked in:
>> [    4.944485] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
>> [    4.954530] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>> [    4.961097] Backtrace:
>> [    4.963702] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>> [    4.971456]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
>> [    4.977272] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
>> [    4.984684] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
>> [    4.991798]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
>> [    4.999800]  r4:00000000 r3:00000000
>> [    5.003497] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
>> [    5.011254]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:000143e8 r5:c32326b0 r4:c31dcbc0
>> [    5.019192] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
>> [    5.028553] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
>> [    5.037277]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
>> [    5.045277]  r4:00000000
>> [    5.047938] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
>> [    5.055224]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
>> [    5.063224]  r4:c3108b00
>> [    5.065886] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
>> [    5.073547]  r6:00008001 r5:c31dc340 r4:c3108b00
>> [    5.078309] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
>> [    5.086063]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
>> [    5.093999] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>> [    5.101107]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
>> [    5.109103]  r4:c31dc300
>> [    5.111754] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
>> [    5.119770]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
>> [    5.126622] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
>> [    5.135252]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
>> [    5.143250]  r4:c0d60888
>> [    5.145899] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
>> [    5.154954]  r6:c0d73d5c r5:c0e78000 r4:00000008
>> [    5.159709] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
>> [    5.168160]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
>> [    5.176151]  r4:00000000
>> [    5.178811] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
>> [    5.186556]  r5:c0979c20 r4:00000000
>> [    5.190810] ---[ end trace 0f8d6b2bab39eead ]---
>> [    5.195803] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 908 lp free: 126976 lp dirty: 82920 b free: 0 b 0
>> [    5.209152] ------------[ cut here ]------------
>> [    5.214149] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
>> [    5.223250] Modules linked in:
>> [    5.226486] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
>> [    5.236506] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>> [    5.243069] Backtrace:
>> [    5.245682] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>> [    5.253439]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
>> [    5.259249] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
>> [    5.266668] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
>> [    5.273780]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
>> [    5.281783]  r4:00000000 r3:00000000
>> [    5.285478] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
>> [    5.293237]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:00015cf8 r5:c3232698 r4:c31dcc40
>> [    5.301176] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
>> [    5.310536] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
>> [    5.319259]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
>> [    5.327259]  r4:00000000
>> [    5.329923] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
>> [    5.337215]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
>> [    5.345216]  r4:c3108b00
>> [    5.347878] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
>> [    5.355537]  r6:00008001 r5:c31dc340 r4:c3108b00
>> [    5.360297] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
>> [    5.368056]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
>> [    5.375990] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>> [    5.383099]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
>> [    5.391092]  r4:c31dc300
>> [    5.393743] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
>> [    5.401759]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
>> [    5.408613] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
>> [    5.417244]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
>> [    5.425243]  r4:c0d60888
>> [    5.427891] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
>> [    5.436947]  r6:c0d73d5c r5:c0e78000 r4:00000008
>> [    5.441701] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
>> [    5.450159]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
>> [    5.458151]  r4:00000000
>> [    5.460809] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
>> [    5.468549]  r5:c0979c20 r4:00000000
>> [    5.472625] ---[ end trace 0f8d6b2bab39eeae ]---
>> [    5.477444] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 907 lp free: 126976 lp dirty: 89336 b free: 0 b 6
>> [    5.490551] ------------[ cut here ]------------
>> [    5.495644] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
>> [    5.504653] Modules linked in:
>> [    5.507883] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
>> [    5.517898] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>> [    5.524463] Backtrace:
>> [    5.527067] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>> [    5.534825]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
>> [    5.540637] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
>> [    5.548053] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
>> [    5.555162]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
>> [    5.563165]  r4:00000000 r3:00000000
>> [    5.566862] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
>> [    5.574612]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:00005df0 r5:c3232ae0 r4:c31dccc0
>> [    5.582549] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
>> [    5.591910] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
>> [    5.600636]  r10:c30dc008 r9:c31dc3c0 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
>> [    5.608635]  r4:00000000
>> [    5.611297] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
>> [    5.618582]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31dc340
>> [    5.626581]  r4:c3108b00
>> [    5.629245] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
>> [    5.636906]  r6:00008001 r5:c31dc340 r4:c3108b00
>> [    5.641664] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
>> [    5.649419]  r9:00000060 r8:c31dc300 r7:c02498e8 r6:c31dc340 r5:00000000 r4:c0e2515c
>> [    5.657355] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>> [    5.664465]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31dc340
>> [    5.672459]  r4:c31dc300
>> [    5.675111] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
>> [    5.683127]  r8:c0d60878 r7:c7d3cd80 r6:c31ec000 r5:c31ec000 r4:00008001
>> [    5.689978] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
>> [    5.698609]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
>> [    5.706600]  r4:c0d60888
>> [    5.709248] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
>> [    5.718302]  r6:c0d73d5c r5:c0e78000 r4:00000008
>> [    5.723057] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
>> [    5.731508]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
>> [    5.739500]  r4:00000000
>> [    5.742149] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
>> [    5.749888]  r5:c0979c20 r4:00000000
>> [    5.753960] ---[ end trace 0f8d6b2bab39eeaf ]---
>> [    5.758775] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 906 lp free: 126976 lp dirty: 24048 b free: 0 b 8
>> [    5.819011] UBIFS (ubi0:2): recovery deferred
>> [    5.825155] UBIFS (ubi0:2): UBIFS: mounted UBI device 0, volume 2, name "rootfs", R/O mode
>> [    5.834016] UBIFS (ubi0:2): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
>> [    5.844368] UBIFS (ubi0:2): FS size: 114532352 bytes (109 MiB, 902 LEBs), journal size 9023488 bytes (8 MiB, 72 LE)
>> [    5.855418] UBIFS (ubi0:2): reserved for root: 0 bytes (0 KiB)
>> [    5.861580] UBIFS (ubi0:2): media format: w4/r0 (latest is w5/r0), UUID 297830B7-F714-4754-B0DA-617A5595067D, small
>> [    5.876654] VFS: Mounted root (ubifs filesystem) readonly on device 0:12.
>>
> Is this really the last triggered warning right before the power-cut where UBIFS renders unmountable?
> I miss the failing ubifs_assert().

No this not the one before corruption, observed this on every power cut thought this is what you are expecting.
Let me continue the power-cut tests until the ubifs getting corrupted for the expected ubids_assert logs.

--
Bhuvan

>
> Thanks,
> //richard

Bhuvan,

Am 31.01.2017 um 09:31 schrieb Bhuvanchandra DV:
>> Is this really the last triggered warning right before the power-cut where UBIFS renders unmountable?
>> I miss the failing ubifs_assert().
> 
> No this not the one before corruption, observed this on every power cut thought this is what you are expecting.
> Let me continue the power-cut tests until the ubifs getting corrupted for the expected ubids_assert logs.

Thanks! sorry for not being clear at first place.

Thanks,
//richard

On 01/31/2017 02:18 AM, Richard Weinberger wrote:

> Bhuvan,
>
> Am 30.01.2017 um 14:31 schrieb Bhuvanchandra DV:
>> On 01/30/2017 01:27 PM, Richard Weinberger wrote:
>>
>>> Bhuvan,
>>>
>>> Am 30.01.2017 um 06:48 schrieb Bhuvanchandra DV:
>>>> [    9.823378] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 126
>>>> [   10.190926] UBIFS assert failed in pack_bits at 242 (pid 120)
>>>> [   10.197294] CPU: 0 PID: 120 Comm: mount Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #13
>>>> [   10.205952] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>>>> [   10.212515] Backtrace:
>>>> [   10.215142] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>>>> [   10.222899]  r7:00000000 r6:600c0013 r5:00000000 r4:c0e29058
>>>> [   10.228716] [<c010c704>] (show_stack) from [<c03fcf18>] (dump_stack+0xb4/0xe8)
>>>> [   10.236150] [<c03fce64>] (dump_stack) from [<c037b2dc>] (pack_bits+0x1f4/0x200)
>>>> [   10.243649]  r10:0000b800 r9:ffffffee r8:c32bdd50 r7:c32bdd54 r6:00000001 r5:c831c860
>>>> [   10.251651]  r4:0000000e r3:00000000
>>>> [   10.255352] [<c037b0e8>] (pack_bits) from [<c037bf90>] (ubifs_pack_pnode+0x84/0x104)
>>>> [   10.263289]  r9:c831c853 r8:c831c851 r7:c32299e0 r6:c30dc000 r5:c32bdd54 r4:c32299c8
>>>> [   10.271233] [<c037bf0c>] (ubifs_pack_pnode) from [<c0385d50>] (ubifs_lpt_end_commit+0x27c/0x6fc)
>>>> [   10.280214]  r9:00000001 r8:c8311000 r7:00000011 r6:0000b862 r5:c3229980 r4:c30dc000
>>>> [   10.288148] [<c0385ad4>] (ubifs_lpt_end_commit) from [<c0373658>] (do_commit+0x244/0x80c)
>>>> [   10.296515]  r10:00000020 r9:00000020 r8:c3195dd4 r7:00000003 r6:c30dc2f0 r5:c30dc000
>>>> [   10.304514]  r4:00000000
>>>> [   10.307163] [<c0373414>] (do_commit) from [<c0373e70>] (ubifs_run_commit+0x9c/0xf0)
>>>> [   10.315001]  r8:00000000 r7:c30dcb48 r6:c30dc3e4 r5:c30dc42c r4:c30dc000
>>>> [   10.321856] [<c0373dd4>] (ubifs_run_commit) from [<c03823dc>] (ubifs_rcvry_gc_commit+0x7c/0x1d8)
>>>> [   10.330830]  r7:c30dcb48 r6:c3195c00 r5:c30dcb8c r4:c30dc000
>>>> [   10.336659] [<c0382360>] (ubifs_rcvry_gc_commit) from [<c0364700>] (ubifs_remount_fs+0x514/0x79c)
>>>> [   10.345731]  r7:c30dcb48 r6:c32a3c00 r5:c30dcb8c r4:c30dc000
>>>> [   10.351548] [<c03641ec>] (ubifs_remount_fs) from [<c0225188>] (do_remount_sb+0x6c/0x1d8)
>>>> [   10.359825]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:c318a000
>>>> [   10.367783] [<c022511c>] (do_remount_sb) from [<c0248f4c>] (do_mount+0x698/0xc84)
>>>> [   10.375452]  r8:c3108b10 r7:c02498e8 r6:c318a000 r5:00000000 r4:c318a044
>>>> [   10.382306] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>>>> [   10.389416]  r10:00000000 r9:c32bc000 r8:c0ed0020 r7:01696860 r6:00000000 r5:c3214b40
>>>> [   10.397418]  r4:c3214e80
>>>> [   10.400075] [<c024986c>] (SyS_mount) from [<c0107e60>] (ret_fast_syscall+0x0/0x1c)
>>>> [   10.407832]  r8:c0108004 r7:00000015 r6:00000000 r5:00000000 r4:00000000
>>>> [   10.518251] systemd[1]: Started Journal Service.
>>> This is what I was looking for! :)
>>> Let's see whether I can find the root cause with that issue, otherwise I'll create
>>> a debug patch for you.
>> Sure! Thank you.
> Hmm, i suspect that the dirty variable turns negative. Can you please reproduce
> with the attached debug patch? Maybe it gives us more hints what is going on.

Here is the log with debug patch:

[    3.244581] ubi0: attached by fastmap
[    3.248432] ubi0: fastmap pool size: 50
[    3.252617] ubi0: fastmap WL pool size: 25
[    3.296085] ubi0: attached mtd3 (name "ubi", size 126 MiB)
[    3.302006] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    3.309050] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    3.316151] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[    3.323429] ubi0: good PEBs: 1000, bad PEBs: 8, corrupted PEBs: 0
[    3.329677] ubi0: user volume: 3, internal volumes: 1, max. volumes count: 128
[    3.337233] ubi0: max/mean erase counter: 276/31, WL threshold: 4096, image sequence number: 0
[    3.346200] ubi0: available PEBs: 0, total reserved PEBs: 1000, PEBs reserved for bad PEB handling: 12
[    3.356545] ubi0: background thread "ubi_bgt0d" started, PID 93
[    3.369408] rtc-ds1307 0-0068: hctosys: unable to read the hardware clock
[    3.379847] ALSA device list:
[    3.383366]   No soundcards found.
[    3.486183] UBIFS (ubi0:2): recovery needed
[    3.806677] ------------[ cut here ]------------
[    3.811542] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
[    3.820907] Modules linked in:
[    3.824313] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #14
[    3.833124] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    3.839689] Backtrace:
[    3.842309] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[    3.850066]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
[    3.855877] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[    3.863297] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
[    3.870405]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
[    3.878408]  r4:00000000 r3:00000000
[    3.882105] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
[    3.889865]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:ffffff58 r5:c322c498 r4:c320e180
[    3.897801] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
[    3.907163] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
[    3.915891]  r10:c30dc008 r9:c31d7c80 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
[    3.923885]  r4:00000000
[    3.926555] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
[    3.933842]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31d7c40
[    3.941841]  r4:c3108b00
[    3.944505] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
[    3.952164]  r6:00008001 r5:c31d7c40 r4:c3108b00
[    3.956926] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
[    3.964681]  r9:00000060 r8:c31d7280 r7:c02498e8 r6:c31d7c40 r5:00000000 r4:c0e2515c
[    3.972616] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
[    3.979725]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31d7c40
[    3.987721]  r4:c31d7280
[    3.990370] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
[    3.998384]  r8:c0d60878 r7:c7d3cac0 r6:c31d6000 r5:c31d6000 r4:00008001
[    4.005239] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
[    4.013870]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
[    4.021868]  r4:c0d60888
[    4.024515] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
[    4.033572]  r6:c0d73d5c r5:c0e78000 r4:00000008
[    4.038327] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
[    4.046777]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
[    4.054770]  r4:00000000
[    4.057426] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
[    4.065165]  r5:c0979c20 r4:00000000
[    4.069239] ---[ end trace 0340b4f2891a36dc ]---
[    4.074236] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 819 lp free: 0 lp dirty: 126808 b free: 22528 b dirty: 96 dirty: -168
[    4.086957] UBIFS assert failed in ubifs_change_lp at 559 (pid 1)
[    4.093407] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
[    4.103447] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[    4.110012] Backtrace:
[    4.112614] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[    4.120372]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
[    4.126182] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[    4.133616] [<c03fcec4>] (dump_stack) from [<c03808b4>] (ubifs_change_lp+0x69c/0x6f8)
[    4.141637]  r10:00005800 r9:c30dc990 r8:ffffffb8 r7:c30dcc0c r6:ffffff58 r5:c322c498
[    4.149634]  r4:c30dc000 r3:00000000
[    4.153334] [<c0380218>] (ubifs_change_lp) from [<c03713c0>] (ubifs_replay_journal+0xb14/0x14bc)
[    4.162316]  r10:c30dc000 r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:ffffff58 r5:c322c498
[    4.170310]  r4:c320e180
[    4.172977] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
[    4.181706]  r10:c30dc008 r9:c31d7c80 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
[    4.189698]  r4:00000000
[    4.192360] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
[    4.199647]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31d7c40
[    4.207645]  r4:c3108b00
[    4.210309] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
[    4.217967]  r6:00008001 r5:c31d7c40 r4:c3108b00
[    4.222728] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
[    4.230485]  r9:00000060 r8:c31d7280 r7:c02498e8 r6:c31d7c40 r5:00000000 r4:c0e2515c
[    4.238418] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
[    4.245529]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31d7c40
[    4.253523]  r4:c31d7280
[    4.256172] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
[    4.264183]  r8:c0d60878 r7:c7d3cac0 r6:c31d6000 r5:c31d6000 r4:00008001
[    4.271033] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
[    4.279666]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
[    4.287665]  r4:c0d60888
[    4.290309] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
[    4.299367]  r6:c0d73d5c r5:c0e78000 r4:00000008
[    4.304123] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
[    4.312572]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
[    4.320565]  r4:00000000
[    4.323222] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
[    4.330960]  r5:c0979c20 r4:00000000
[    4.338528] UBIFS (ubi0:2): recovery deferred
[    4.345120] UBIFS (ubi0:2): UBIFS: mounted UBI device 0, volume 2, name "rootfs", R/O mode
[    4.353998] UBIFS (ubi0:2): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
[    4.364349] UBIFS (ubi0:2): FS size: 114532352 bytes (109 MiB, 902 LEBs), journal size 9023488 bytes (8 MiB, 72 LEBs)
[    4.375390] UBIFS (ubi0:2): reserved for root: 0 bytes (0 KiB)
[    4.381392] UBIFS (ubi0:2): media format: w4/r0 (latest is w5/r0), UUID 297830B7-F714-4754-B0DA-617A5595067D, small LPT model
[    4.396743] VFS: Mounted root (ubifs filesystem) readonly on device 0:12.
...
[    9.672243] UBIFS (ubi0:2): completing deferred recovery
[   10.228267] UBIFS (ubi0:2): background thread "ubifs_bgt0_2" started, PID 126
[   10.276128] UBIFS assert failed in pack_bits at 242 (pid 120)
[   10.282568] CPU: 0 PID: 120 Comm: mount Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
[   10.292446] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[   10.299010] Backtrace:
[   10.301638] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[   10.309394]  r7:00000000 r6:600f0113 r5:00000000 r4:c0e29058
[   10.315206] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[   10.322634] [<c03fcec4>] (dump_stack) from [<c037b33c>] (pack_bits+0x1f4/0x200)
[   10.330138]  r10:00017000 r9:fffffff7 r8:c32cdd50 r7:c32cdd54 r6:00000002 r5:c83280da
[   10.338135]  r4:0000000e r3:00000000
[   10.341835] [<c037b148>] (pack_bits) from [<c037bff0>] (ubifs_pack_pnode+0x84/0x104)
[   10.349767]  r9:c83280d8 r8:c83280d6 r7:c322c4e0 r6:c30dc000 r5:c32cdd54 r4:c322c480
[   10.357719] [<c037bf6c>] (ubifs_pack_pnode) from [<c0385db0>] (ubifs_lpt_end_commit+0x27c/0x6fc)
[   10.366698]  r9:00000001 r8:c8311000 r7:00000011 r6:000170e7 r5:c322c480 r4:c30dc000
[   10.374633] [<c0385b34>] (ubifs_lpt_end_commit) from [<c03736b8>] (do_commit+0x244/0x80c)
[   10.383002]  r10:00000020 r9:00000020 r8:c3195dd4 r7:00000003 r6:c30dc2f0 r5:c30dc000
[   10.391000]  r4:00000000
[   10.393646] [<c0373474>] (do_commit) from [<c0373ed0>] (ubifs_run_commit+0x9c/0xf0)
[   10.401484]  r8:00000000 r7:c30dcb48 r6:c30dc3e4 r5:c30dc42c r4:c30dc000
[   10.408335] [<c0373e34>] (ubifs_run_commit) from [<c038243c>] (ubifs_rcvry_gc_commit+0x7c/0x1d8)
[   10.417305]  r7:c30dcb48 r6:c3195c00 r5:c30dcb8c r4:c30dc000
[   10.423128] [<c03823c0>] (ubifs_rcvry_gc_commit) from [<c0364700>] (ubifs_remount_fs+0x514/0x79c)
[   10.432199]  r7:c30dcb48 r6:c32a0c00 r5:c30dcb8c r4:c30dc000
[   10.438015] [<c03641ec>] (ubifs_remount_fs) from [<c0225188>] (do_remount_sb+0x6c/0x1d8)
[   10.446293]  r9:00000020 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:c318a000
[   10.454251] [<c022511c>] (do_remount_sb) from [<c0248f4c>] (do_mount+0x698/0xc84)
[   10.461922]  r8:c3108b10 r7:c02498e8 r6:c318a000 r5:00000000 r4:c318a044
[   10.468776] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
[   10.475884]  r10:00000000 r9:c32cc000 r8:c0ed0020 r7:0078f860 r6:00000000 r5:c3216bc0
[   10.483886]  r4:c3216e40
[   10.486539] [<c024986c>] (SyS_mount) from [<c0107e60>] (ret_fast_syscall+0x0/0x1c)
[   10.494290]  r8:c0108004 r7:00000015 r6:00000000 r5:00000000 r4:00000000
...
[   10.692568] UBIFS (ubi0:2): deferred recovery completed
[   11.757358] systemd-journald[115]: Received request to flush runtime journal from PID 1
[   11.826036] UBIFS assert failed in ubifs_change_lp at 559 (pid 115)
[   11.833005] CPU: 0 PID: 115 Comm: systemd-journal Tainted: G        W       4.10.0-rc4-00016-g60124f748422-dirty #14
[   11.843768] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
[   11.850336] Backtrace:
[   11.852954] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
[   11.860716]  r7:00000000 r6:600f0013 r5:00000000 r4:c0e29058
[   11.866526] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
[   11.873973] [<c03fcec4>] (dump_stack) from [<c03808b4>] (ubifs_change_lp+0x69c/0x6f8)
[   11.881998]  r10:000055b0 r9:c30dc990 r8:ffffffb8 r7:00000333 r6:c30dcc0c r5:c322c498
[   11.890002]  r4:c30dc000 r3:00000000
[   11.893701] [<c0380218>] (ubifs_change_lp) from [<c0380ae0>] (ubifs_update_one_lp+0x84/0x150)
[   11.902421]  r10:00000333 r9:c337c000 r8:000055b0 r7:00000333 r6:c30dcc0c r5:c30dc000
[   11.910414]  r4:00000000
[   11.913091] [<c0380a5c>] (ubifs_update_one_lp) from [<c0364058>] (bud_wbuf_callback+0x20/0x28)
[   11.921902]  r8:0000024c r7:c3195e18 r6:00000250 r5:c30dc000 r4:c3195db0
[   11.928768] [<c0364038>] (bud_wbuf_callback) from [<c036935c>] (ubifs_wbuf_write_nolock+0x234/0x770)
[   11.938117] [<c0369128>] (ubifs_wbuf_write_nolock) from [<c035b6dc>] (ubifs_jnl_write_data+0x1a4/0x300)
[   11.947714]  r10:00000333 r9:c3195c00 r8:c337c000 r7:c3295d08 r6:0000024c r5:c30dc000
[   11.955711]  r4:00000000
[   11.958363] [<c035b538>] (ubifs_jnl_write_data) from [<c035db28>] (do_writepage+0x80/0x1a8)
[   11.966911]  r10:0000f66e r9:c17ef000 r8:20000000 r7:c35de590 r6:00001000 r5:c30dc000
[   11.974909]  r4:c7d08de0
[   11.977559] [<c035daa8>] (do_writepage) from [<c035f50c>] (ubifs_writepage+0x174/0x240)
[   11.985757]  r10:c35de804 r9:00000000 r8:00000000 r7:c7d08de0 r6:800f0013 r5:00000200
[   11.993760]  r4:c35de590
[   11.996411] [<c035f398>] (ubifs_writepage) from [<c01df1b8>] (__writepage+0x1c/0x48)
[   12.004343]  r10:c3295e88 r9:00000000 r8:ffffffff r7:c35de6c4 r6:c7d08de0 r5:c35de6c4
[   12.012339]  r4:00000000
[   12.014986] [<c01df19c>] (__writepage) from [<c01df8e8>] (write_cache_pages+0x16c/0x3d0)
[   12.023260]  r5:c3295de0 r4:00000000
[   12.026957] [<c01df77c>] (write_cache_pages) from [<c01dfb94>] (generic_writepages+0x48/0x64)
[   12.035670]  r10:00000000 r9:7fffffff r8:ffffffff r7:00000000 r6:c35de6c4 r5:c3295e88
[   12.043670]  r4:c35de6c4
[   12.046319] [<c01dfb4c>] (generic_writepages) from [<c01e1c24>] (do_writepages+0x3c/0x40)
[   12.054677]  r5:7fffffff r4:ffffffff
[   12.058392] [<c01e1be8>] (do_writepages) from [<c01d4e38>] (__filemap_fdatawrite_range+0x7c/0xa4)
[   12.067470] [<c01d4dbc>] (__filemap_fdatawrite_range) from [<c01d4fb4>] (filemap_write_and_wait_range+0x3c/0x88)
[   12.077844]  r6:00000000 r5:c35de6c4 r4:c3377280
[   12.082602] [<c01d4f78>] (filemap_write_and_wait_range) from [<c035e290>] (ubifs_fsync+0x48/0xbc)
[   12.091679]  r9:7fffffff r8:ffffffff r7:00000000 r6:c30dc000 r5:c35de590 r4:c3377280
[   12.099644] [<c035e248>] (ubifs_fsync) from [<c025470c>] (vfs_fsync_range+0x60/0xb4)
[   12.107574]  r9:c3294000 r8:c35de590 r7:00000000 r6:00000000 r5:00000000 r4:c3377280
[   12.115506] [<c02546ac>] (vfs_fsync_range) from [<c02547d8>] (do_fsync+0x44/0x6c)
[   12.123175]  r9:c3294000 r8:c0108004 r7:00000076 r6:00000000 r5:c3377280 r4:c3377280
[   12.131106] [<c0254794>] (do_fsync) from [<c0254a94>] (SyS_fsync+0x14/0x18)
[   12.138203]  r6:00000006 r5:00000001 r4:81036430
[   12.142961] [<c0254a80>] (SyS_fsync) from [<c0107e60>] (ret_fast_syscall+0x0/0x1c)

--
Bhuvan

>
> Thanks,
> //richard

Bhuvan,

Am 06.02.2017 um 07:10 schrieb Bhuvanchandra DV:
> Here is the log with debug patch:
> 
> [    3.244581] ubi0: attached by fastmap
> [    3.248432] ubi0: fastmap pool size: 50
> [    3.252617] ubi0: fastmap WL pool size: 25
> [    3.296085] ubi0: attached mtd3 (name "ubi", size 126 MiB)
> [    3.302006] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
> [    3.309050] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
> [    3.316151] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
> [    3.323429] ubi0: good PEBs: 1000, bad PEBs: 8, corrupted PEBs: 0
> [    3.329677] ubi0: user volume: 3, internal volumes: 1, max. volumes count: 128
> [    3.337233] ubi0: max/mean erase counter: 276/31, WL threshold: 4096, image sequence number: 0
> [    3.346200] ubi0: available PEBs: 0, total reserved PEBs: 1000, PEBs reserved for bad PEB handling: 12
> [    3.356545] ubi0: background thread "ubi_bgt0d" started, PID 93
> [    3.369408] rtc-ds1307 0-0068: hctosys: unable to read the hardware clock
> [    3.379847] ALSA device list:
> [    3.383366]   No soundcards found.
> [    3.486183] UBIFS (ubi0:2): recovery needed
> [    3.806677] ------------[ cut here ]------------
> [    3.811542] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
> [    3.820907] Modules linked in:
> [    3.824313] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #14
> [    3.833124] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
> [    3.839689] Backtrace:
> [    3.842309] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
> [    3.850066]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
> [    3.855877] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
> [    3.863297] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
> [    3.870405]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
> [    3.878408]  r4:00000000 r3:00000000
> [    3.882105] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
> [    3.889865]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:ffffff58 r5:c322c498 r4:c320e180
> [    3.897801] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
> [    3.907163] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
> [    3.915891]  r10:c30dc008 r9:c31d7c80 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
> [    3.923885]  r4:00000000
> [    3.926555] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
> [    3.933842]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31d7c40
> [    3.941841]  r4:c3108b00
> [    3.944505] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
> [    3.952164]  r6:00008001 r5:c31d7c40 r4:c3108b00
> [    3.956926] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
> [    3.964681]  r9:00000060 r8:c31d7280 r7:c02498e8 r6:c31d7c40 r5:00000000 r4:c0e2515c
> [    3.972616] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
> [    3.979725]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31d7c40
> [    3.987721]  r4:c31d7280
> [    3.990370] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
> [    3.998384]  r8:c0d60878 r7:c7d3cac0 r6:c31d6000 r5:c31d6000 r4:00008001
> [    4.005239] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
> [    4.013870]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
> [    4.021868]  r4:c0d60888
> [    4.024515] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
> [    4.033572]  r6:c0d73d5c r5:c0e78000 r4:00000008
> [    4.038327] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
> [    4.046777]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
> [    4.054770]  r4:00000000
> [    4.057426] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
> [    4.065165]  r5:c0979c20 r4:00000000
> [    4.069239] ---[ end trace 0340b4f2891a36dc ]---
> [    4.074236] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 819 lp free: 0 lp dirty: 126808 b free: 22528 b dirty: 96 dirty: -168

Hmm, so it really underflows. ;-\

Just in case, you can trigger this also with a fresh filesystem?
Or did you always keep the same one?

Thanks,
//richard

Richard,

On 02/09/2017 03:40 AM, Richard Weinberger wrote:

> Bhuvan,
>
> Am 06.02.2017 um 07:10 schrieb Bhuvanchandra DV:
>> Here is the log with debug patch:
>>
>> [    3.244581] ubi0: attached by fastmap
>> [    3.248432] ubi0: fastmap pool size: 50
>> [    3.252617] ubi0: fastmap WL pool size: 25
>> [    3.296085] ubi0: attached mtd3 (name "ubi", size 126 MiB)
>> [    3.302006] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
>> [    3.309050] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
>> [    3.316151] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
>> [    3.323429] ubi0: good PEBs: 1000, bad PEBs: 8, corrupted PEBs: 0
>> [    3.329677] ubi0: user volume: 3, internal volumes: 1, max. volumes count: 128
>> [    3.337233] ubi0: max/mean erase counter: 276/31, WL threshold: 4096, image sequence number: 0
>> [    3.346200] ubi0: available PEBs: 0, total reserved PEBs: 1000, PEBs reserved for bad PEB handling: 12
>> [    3.356545] ubi0: background thread "ubi_bgt0d" started, PID 93
>> [    3.369408] rtc-ds1307 0-0068: hctosys: unable to read the hardware clock
>> [    3.379847] ALSA device list:
>> [    3.383366]   No soundcards found.
>> [    3.486183] UBIFS (ubi0:2): recovery needed
>> [    3.806677] ------------[ cut here ]------------
>> [    3.811542] WARNING: CPU: 0 PID: 1 at fs/ubifs/replay.c:143 ubifs_replay_journal+0x1434/0x14bc
>> [    3.820907] Modules linked in:
>> [    3.824313] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.10.0-rc4-00016-g60124f748422-dirty #14
>> [    3.833124] Hardware name: Freescale Vybrid VF5xx/VF6xx (Device Tree)
>> [    3.839689] Backtrace:
>> [    3.842309] [<c010c474>] (dump_backtrace) from [<c010c71c>] (show_stack+0x18/0x1c)
>> [    3.850066]  r7:00000000 r6:60000013 r5:00000000 r4:c0e29058
>> [    3.855877] [<c010c704>] (show_stack) from [<c03fcf78>] (dump_stack+0xb4/0xe8)
>> [    3.863297] [<c03fcec4>] (dump_stack) from [<c0125f64>] (__warn+0xd8/0x104)
>> [    3.870405]  r10:c30dc000 r9:c0371ce0 r8:c0c1e4a0 r7:0000008f r6:00000009 r5:00000000
>> [    3.878408]  r4:00000000 r3:00000000
>> [    3.882105] [<c0125e8c>] (__warn) from [<c0126044>] (warn_slowpath_null+0x28/0x30)
>> [    3.889865]  r9:00000000 r8:c30dcd2c r7:c30dcc0c r6:ffffff58 r5:c322c498 r4:c320e180
>> [    3.897801] [<c012601c>] (warn_slowpath_null) from [<c0371ce0>] (ubifs_replay_journal+0x1434/0x14bc)
>> [    3.907163] [<c03708ac>] (ubifs_replay_journal) from [<c03662ac>] (ubifs_mount+0x13d8/0x17d8)
>> [    3.915891]  r10:c30dc008 r9:c31d7c80 r8:c30dcb48 r7:00000000 r6:c30dc000 r5:c318a000
>> [    3.923885]  r4:00000000
>> [    3.926555] [<c0364ed4>] (ubifs_mount) from [<c022558c>] (mount_fs+0x1c/0xb0)
>> [    3.933842]  r10:00008001 r9:00000000 r8:c0248a04 r7:c0e2515c r6:c0e2515c r5:c31d7c40
>> [    3.941841]  r4:c3108b00
>> [    3.944505] [<c0225570>] (mount_fs) from [<c0244bd4>] (vfs_kern_mount+0x5c/0x134)
>> [    3.952164]  r6:00008001 r5:c31d7c40 r4:c3108b00
>> [    3.956926] [<c0244b78>] (vfs_kern_mount) from [<c0248a04>] (do_mount+0x150/0xc84)
>> [    3.964681]  r9:00000060 r8:c31d7280 r7:c02498e8 r6:c31d7c40 r5:00000000 r4:c0e2515c
>> [    3.972616] [<c02488b4>] (do_mount) from [<c02498e8>] (SyS_mount+0x7c/0xa4)
>> [    3.979725]  r10:c0d00604 r9:c0d60888 r8:00008001 r7:c0bf5644 r6:00000000 r5:c31d7c40
>> [    3.987721]  r4:c31d7280
>> [    3.990370] [<c024986c>] (SyS_mount) from [<c0d0121c>] (mount_block_root+0x10c/0x274)
>> [    3.998384]  r8:c0d60878 r7:c7d3cac0 r6:c31d6000 r5:c31d6000 r4:00008001
>> [    4.005239] [<c0d01110>] (mount_block_root) from [<c0d01644>] (prepare_namespace+0x98/0x1d0)
>> [    4.013870]  r10:c0d00604 r9:c0d60858 r8:c0d60854 r7:c0e78000 r6:c0d60878 r5:c0d60878
>> [    4.021868]  r4:c0d60888
>> [    4.024515] [<c0d015ac>] (prepare_namespace) from [<c0d00ec0>] (kernel_init_freeable+0x1ac/0x1f8)
>> [    4.033572]  r6:c0d73d5c r5:c0e78000 r4:00000008
>> [    4.038327] [<c0d00d14>] (kernel_init_freeable) from [<c0979c30>] (kernel_init+0x10/0x120)
>> [    4.046777]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0979c20
>> [    4.054770]  r4:00000000
>> [    4.057426] [<c0979c20>] (kernel_init) from [<c0107ef0>] (ret_from_fork+0x14/0x24)
>> [    4.065165]  r5:c0979c20 r4:00000000
>> [    4.069239] ---[ end trace 0340b4f2891a36dc ]---
>> [    4.074236] UBIFS error (ubi0:2 pid 1): ubifs_replay_journal: LEB 819 lp free: 0 lp dirty: 126808 b free: 22528 b dirty: 96 dirty: -168
> Hmm, so it really underflows. ;-\
>
> Just in case, you can trigger this also with a fresh filesystem?
> Or did you always keep the same one?

Yes, I triggered it with fresh filesystem.

--
Bhuvan

>
> Thanks,
> //richard

Bhuvan,

Am 09.02.2017 um 05:59 schrieb Bhuvanchandra DV:
>> Just in case, you can trigger this also with a fresh filesystem?
>> Or did you always keep the same one?
> 
> Yes, I triggered it with fresh filesystem.

Okay. Not good.

How do you trigger this? What workload is running while the power-cut
happens?
Did you try also kernel 4.9?
Does it also only happen then xattrs are used?

Thanks,
//richard

On 02/10/2017 06:31 PM, Richard Weinberger wrote:

> Bhuvan,
>
> Am 09.02.2017 um 05:59 schrieb Bhuvanchandra DV:
>>> Just in case, you can trigger this also with a fresh filesystem?
>>> Or did you always keep the same one?
>> Yes, I triggered it with fresh filesystem.
> Okay. Not good.
>
> How do you trigger this? What workload is running while the power-cut
> happens?

The issue is triggered when doing a continous external power-cut for every
25sec since power ON. After a week or two observed this issue. There is no
additional work load on CPU during the test, it just boots to a lxde desktop.

> Did you try also kernel 4.9?

I did ran similar testes on our downstream kernel 4.4 and 4.9 kernel few weeks
back, observed similar issues.

> Does it also only happen then xattrs are used?

Didn't check that. How exactly to check whether xattr is used ?

--
Bhuvan

>
> Thanks,
> //richard

Bhuvan,

Am 13.02.2017 um 04:34 schrieb Bhuvanchandra DV:
> On 02/10/2017 06:31 PM, Richard Weinberger wrote:
> 
>> Bhuvan,
>>
>> Am 09.02.2017 um 05:59 schrieb Bhuvanchandra DV:
>>>> Just in case, you can trigger this also with a fresh filesystem?
>>>> Or did you always keep the same one?
>>> Yes, I triggered it with fresh filesystem.
>> Okay. Not good.
>>
>> How do you trigger this? What workload is running while the power-cut
>> happens?
> 
> The issue is triggered when doing a continous external power-cut for every
> 25sec since power ON. After a week or two observed this issue. There is no
> additional work load on CPU during the test, it just boots to a lxde desktop.

So, the power-cut happens while the system is idle? Hmm.

>> Did you try also kernel 4.9?
> 
> I did ran similar testes on our downstream kernel 4.4 and 4.9 kernel few weeks
> back, observed similar issues.

Okay, so I didn't break it lately. Puh... ;)

>> Does it also only happen then xattrs are used?
> 
> Didn't check that. How exactly to check whether xattr is used ?

i.e. is a LSM such das SELinux being used?

Thanks,
//richard

On 02/13/2017 01:27 PM, Richard Weinberger wrote:

> Bhuvan,
>
> Am 13.02.2017 um 04:34 schrieb Bhuvanchandra DV:
>> On 02/10/2017 06:31 PM, Richard Weinberger wrote:
>>
>>> Bhuvan,
>>>
>>> Am 09.02.2017 um 05:59 schrieb Bhuvanchandra DV:
>>>>> Just in case, you can trigger this also with a fresh filesystem?
>>>>> Or did you always keep the same one?
>>>> Yes, I triggered it with fresh filesystem.
>>> Okay. Not good.
>>>
>>> How do you trigger this? What workload is running while the power-cut
>>> happens?
>> The issue is triggered when doing a continous external power-cut for every
>> 25sec since power ON. After a week or two observed this issue. There is no
>> additional work load on CPU during the test, it just boots to a lxde desktop.
> So, the power-cut happens while the system is idle? Hmm.

May be not, sometimes power-cut might happen during boot. Sometimes I observed
journalctl logging just before power-cut.

>
>>> Did you try also kernel 4.9?
>> I did ran similar testes on our downstream kernel 4.4 and 4.9 kernel few weeks
>> back, observed similar issues.
> Okay, so I didn't break it lately. Puh... ;)

:)

>
>>> Does it also only happen then xattrs are used?
>> Didn't check that. How exactly to check whether xattr is used ?
> i.e. is a LSM such das SELinux being used?

No, not used so far.

--
Bhuvan

>
> Thanks,
> //richard

On 02/13/2017 05:15 PM, Bhuvanchandra DV wrote:
> On 02/13/2017 01:27 PM, Richard Weinberger wrote:
>
>> Bhuvan,
>>
>> Am 13.02.2017 um 04:34 schrieb Bhuvanchandra DV:
>>> On 02/10/2017 06:31 PM, Richard Weinberger wrote:
>>>
>>>> Bhuvan,
>>>>
>>>> Am 09.02.2017 um 05:59 schrieb Bhuvanchandra DV:
>>>>>> Just in case, you can trigger this also with a fresh filesystem?
>>>>>> Or did you always keep the same one?
>>>>> Yes, I triggered it with fresh filesystem.
>>>> Okay. Not good.
>>>>
>>>> How do you trigger this? What workload is running while the power-cut
>>>> happens?
>>> The issue is triggered when doing a continous external power-cut for 
>>> every
>>> 25sec since power ON. After a week or two observed this issue. There 
>>> is no
>>> additional work load on CPU during the test, it just boots to a lxde 
>>> desktop.
>> So, the power-cut happens while the system is idle? Hmm.
>
> May be not, sometimes power-cut might happen during boot. Sometimes I 
> observed
> journalctl logging just before power-cut.
>
>>
>>>> Did you try also kernel 4.9?
>>> I did ran similar testes on our downstream kernel 4.4 and 4.9 kernel 
>>> few weeks
>>> back, observed similar issues.
>> Okay, so I didn't break it lately. Puh... ;)
>
> :)
>
>>
>>>> Does it also only happen then xattrs are used?
>>> Didn't check that. How exactly to check whether xattr is used ?
>> i.e. is a LSM such das SELinux being used?
>
> No, not used so far.

I was wrong, systemd version which we use lately is enabled with access control lists(ACL).
...
[    3.324846] systemd[1]: systemd 230 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKI)
...

Will do the test with a systemd without ACL support.

--
Bhuvan


>
> -- 
> Bhuvan
>
>>
>> Thanks,
>> //richard
>

Am 15.02.2017 um 08:22 schrieb Bhuvanchandra DV:
> I was wrong, systemd version which we use lately is enabled with access control lists(ACL).
> ...
> [    3.324846] systemd[1]: systemd 230 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKI)
> ...
> 
> Will do the test with a systemd without ACL support.

Well, do files have xattrs?
See getfattr.
I'm trying to understand why your system makes so different.

Thanks,
//richard

On 02/15/2017 02:42 PM, Richard Weinberger wrote:

> Am 15.02.2017 um 08:22 schrieb Bhuvanchandra DV:
>> I was wrong, systemd version which we use lately is enabled with access control lists(ACL).
>> ...
>> [    3.324846] systemd[1]: systemd 230 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKI)
>> ...
>>
>> Will do the test with a systemd without ACL support.
> Well, do files have xattrs?
> See getfattr.
> I'm trying to understand why your system makes so different.

systemd's journald uses ACL, the journald's logs files seems to have extended attributes.

root@colibri-vf:~# getfattr -R /var/log/journal/3e283b492ea046a29683c0801ceaba91
getfattr: Removing leading '/' from absolute path names
# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec00621f43-a0f5cd8e864efc36.journal~
user.crtime_usec

# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec25f38147-3ede62d61071df3c.journal~
user.crtime_usec

# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0820e4037f504446ad35bb362be7b809-0000000000000001-l
user.crtime_usec

# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system.journal
user.crtime_usec

# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@37549ee306da42479500fb717cb2dada-0000000000000001-l
user.crtime_usec

# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ecafe0f654-e0c2574255c05aed.journal~
user.crtime_usec

# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec78bce8a1-02b48f08c5d6a410.journal~
user.crtime_usec

# file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0005488c6421da38-c4690dc0bb71068f.journal~
user.crtime_usec

--
Bhuvan

>
> Thanks,
> //richard

Am 15.02.2017 um 16:06 schrieb Bhuvanchandra DV:
> On 02/15/2017 02:42 PM, Richard Weinberger wrote:
> 
>> Am 15.02.2017 um 08:22 schrieb Bhuvanchandra DV:
>>> I was wrong, systemd version which we use lately is enabled with access control lists(ACL).
>>> ...
>>> [    3.324846] systemd[1]: systemd 230 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP
>>> +BLKI)
>>> ...
>>>
>>> Will do the test with a systemd without ACL support.
>> Well, do files have xattrs?
>> See getfattr.
>> I'm trying to understand why your system makes so different.
> 
> systemd's journald uses ACL, the journald's logs files seems to have extended attributes.
> 
> root@colibri-vf:~# getfattr -R /var/log/journal/3e283b492ea046a29683c0801ceaba91
> getfattr: Removing leading '/' from absolute path names
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec00621f43-a0f5cd8e864efc36.journal~
> user.crtime_usec
> 
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec25f38147-3ede62d61071df3c.journal~
> user.crtime_usec
> 
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0820e4037f504446ad35bb362be7b809-0000000000000001-l
> user.crtime_usec
> 
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system.journal
> user.crtime_usec
> 
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@37549ee306da42479500fb717cb2dada-0000000000000001-l
> user.crtime_usec
> 
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ecafe0f654-e0c2574255c05aed.journal~
> user.crtime_usec
> 
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec78bce8a1-02b48f08c5d6a410.journal~
> user.crtime_usec
> 
> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0005488c6421da38-c4690dc0bb71068f.journal~
> user.crtime_usec

Hmm, not sure whether systemd journal triggers such a bug in UBIFS.
Anyway, can you provide me a UBIFS image after a failure?
A dd from the UBI volume (i.e. /dev/ubiX_Y) will do it.

Maybe it can give me some hint.

Thanks,
//richard

On 02/15/2017 08:44 PM, Richard Weinberger wrote:

> Am 15.02.2017 um 16:06 schrieb Bhuvanchandra DV:
>> On 02/15/2017 02:42 PM, Richard Weinberger wrote:
>>
>>> Am 15.02.2017 um 08:22 schrieb Bhuvanchandra DV:
>>>> I was wrong, systemd version which we use lately is enabled with access control lists(ACL).
>>>> ...
>>>> [    3.324846] systemd[1]: systemd 230 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP
>>>> +BLKI)
>>>> ...
>>>>
>>>> Will do the test with a systemd without ACL support.
>>> Well, do files have xattrs?
>>> See getfattr.
>>> I'm trying to understand why your system makes so different.
>> systemd's journald uses ACL, the journald's logs files seems to have extended attributes.
>>
>> root@colibri-vf:~# getfattr -R /var/log/journal/3e283b492ea046a29683c0801ceaba91
>> getfattr: Removing leading '/' from absolute path names
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec00621f43-a0f5cd8e864efc36.journal~
>> user.crtime_usec
>>
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec25f38147-3ede62d61071df3c.journal~
>> user.crtime_usec
>>
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0820e4037f504446ad35bb362be7b809-0000000000000001-l
>> user.crtime_usec
>>
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system.journal
>> user.crtime_usec
>>
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@37549ee306da42479500fb717cb2dada-0000000000000001-l
>> user.crtime_usec
>>
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ecafe0f654-e0c2574255c05aed.journal~
>> user.crtime_usec
>>
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec78bce8a1-02b48f08c5d6a410.journal~
>> user.crtime_usec
>>
>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0005488c6421da38-c4690dc0bb71068f.journal~
>> user.crtime_usec
> Hmm, not sure whether systemd journal triggers such a bug in UBIFS.
> Anyway, can you provide me a UBIFS image after a failure?
> A dd from the UBI volume (i.e. /dev/ubiX_Y) will do it.
>
> Maybe it can give me some hint.

Here[1] is the raw image of the corrupted UBI volume.


[1] https://share.toradex.com/xbczmjz0b2pntfv

--
Bhuvan

>
> Thanks,
> //richard

Hello Richard,

On 02/16/2017 09:46 AM, Bhuvanchandra DV wrote:

> On 02/15/2017 08:44 PM, Richard Weinberger wrote:
>
>> Am 15.02.2017 um 16:06 schrieb Bhuvanchandra DV:
>>> On 02/15/2017 02:42 PM, Richard Weinberger wrote:
>>>
>>>> Am 15.02.2017 um 08:22 schrieb Bhuvanchandra DV:
>>>>> I was wrong, systemd version which we use lately is enabled with 
>>>>> access control lists(ACL).
>>>>> ...
>>>>> [    3.324846] systemd[1]: systemd 230 running in system mode. 
>>>>> (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP 
>>>>> -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP
>>>>> +BLKI)
>>>>> ...
>>>>>
>>>>> Will do the test with a systemd without ACL support.
>>>> Well, do files have xattrs?
>>>> See getfattr.
>>>> I'm trying to understand why your system makes so different.
>>> systemd's journald uses ACL, the journald's logs files seems to have 
>>> extended attributes.
>>>
>>> root@colibri-vf:~# getfattr -R 
>>> /var/log/journal/3e283b492ea046a29683c0801ceaba91
>>> getfattr: Removing leading '/' from absolute path names
>>> # file: 
>>> var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec00621f43-a0f5cd8e864efc36.journal~
>>> user.crtime_usec
>>>
>>> # file: 
>>> var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec25f38147-3ede62d61071df3c.journal~
>>> user.crtime_usec
>>>
>>> # file: 
>>> var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0820e4037f504446ad35bb362be7b809-0000000000000001-l
>>> user.crtime_usec
>>>
>>> # file: var/log/journal/3e283b492ea046a29683c0801ceaba91/system.journal
>>> user.crtime_usec
>>>
>>> # file: 
>>> var/log/journal/3e283b492ea046a29683c0801ceaba91/system@37549ee306da42479500fb717cb2dada-0000000000000001-l
>>> user.crtime_usec
>>>
>>> # file: 
>>> var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ecafe0f654-e0c2574255c05aed.journal~
>>> user.crtime_usec
>>>
>>> # file: 
>>> var/log/journal/3e283b492ea046a29683c0801ceaba91/system@000547ec78bce8a1-02b48f08c5d6a410.journal~
>>> user.crtime_usec
>>>
>>> # file: 
>>> var/log/journal/3e283b492ea046a29683c0801ceaba91/system@0005488c6421da38-c4690dc0bb71068f.journal~
>>> user.crtime_usec
>> Hmm, not sure whether systemd journal triggers such a bug in UBIFS.
>> Anyway, can you provide me a UBIFS image after a failure?
>> A dd from the UBI volume (i.e. /dev/ubiX_Y) will do it.
>>
>> Maybe it can give me some hint.
>
> Here[1] is the raw image of the corrupted UBI volume.
>
>
> [1] https://share.toradex.com/xbczmjz0b2pntfv

The UBI/UBIFs corruption issue is still there even, with/without xattar,
we disabled systemd ACL support and ran the power-cut tests.
Tests are done on our down stream kernel and mainline kernel.

Here are the logs:

Kernel v4.4.59 without ACL:
https://pastebin.com/8MUrzqsL

Mainline kernel 4.11.0-rc4 without ACL:
https://pastebin.com/g0qJN7rJ

--
Bhuvan

>
> -- 
> Bhuvan
>
>>
>> Thanks,
>> //richard
>