Re: UBIFS file-system corruption (missing inode) after power-cut on 4.14.96

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 

On Thu, Mar 21, 2019 at 11:02 AM Lars Persson <lists@xxxxxxx> wrote:
>
> Hi
>
> We have recently encountered multiple cases of corrupted UBIFS volumes that
> were triggered by a power-cut during startup. It may be a regression in the
> 4.14 stable branch.
>
> The symptom is seen when accessing a file in the corrupted FS:
>   UBIFS error (ubi0:20 pid 513): ubifs_iget: failed to read inode 348, error -2
>   UBIFS error (ubi0:20 pid 513): ubifs_lookup: dead directory entry
> 'tampering.conf', error -2
>   UBIFS warning (ubi0:20 pid 513): ubifs_ro_mode.part.0: switched to
> read-only mode, error -2
>   [<80506a51>] (dump_stack) from [<80297e2f>] (ubifs_lookup+0x29b/0x300)
>   [<80297e2f>] (ubifs_lookup) from [<80226169>] (lookup_slow+0x69/0xe4)
>
> We enabled chk_fs and reproduced it:
>   UBIFS error (ubi0:20 pid 120): read_add_inode: inode 352 not found in index
>   UBIFS error (ubi0:20 pid 120): check_leaf: error -2 while processing
> entry node and trying to find inode node 352
>   UBIFS (ubi0:20): dump of node at LEB 29:94656
>         magic          0x6101831
>         crc            0xda5d6bee
>         node_type      2 (direntry node)
>         group_type     1 (in node group)
>         sqnum          4079
>         len            70
>         key            (66, direntry, 0x4974b0f)
>         inum           352
>         type           0
>         nlen           13
>         name           emotiond.conf
>   UBIFS error (ubi0:20 pid 120): dbg_walk_index: leaf checking
> function returned error -2, for leaf at LEB 29:94656
>   UBIFS (ubi0:20): dump of znode at LEB 37:57680
>   znode be0bf000, LEB 37:57680 len 128 parent be0af800 iip 1 level 0
> child_cnt 5 flags 0
>   zbranches:
>         0: LNC   (null) LEB 32:53248 len 81 key (66, direntry, 0x363e97f)
>         1: LNC   (null) LEB 29:94208 len 63 key (66, direntry, 0x3f88c71)
>         2: LNC   (null) LEB 12:92160 len 74 key (66, direntry, 0x477308e)
>         3: LNC   (null) LEB 29:94656 len 70 key (66, direntry, 0x4974b0f)
>         4: LNC be084600 LEB 814:49152 len 63 key (66, direntry, 0x49bb6f7)
>   UBIFS error (ubi0:20 pid 120): dbg_check_filesystem: file-system
> check failed with error -2
>
> The setup of our system is:
> An overlayfs stack for /etc with:
> - The lower file-system is a read-only squashfs on ubi
> - The upper file-system is an ubifs
>
> The ubi partition resides on an SLC NAND from Toshiba (TH58NVG2S3HBAI4).
>
> The missing inode is always triggered on those two particular files
> emotiond.conf and tampering.conf that share the same write pattern at startup:
>
>  cp file file.tmp
>  echo some data > file.tmp
>  mv file.tmp file
>  fsync file
>
> Do not ask me about the logic of this script :> It overwrites the result of cp
> and does not implement a proper atomic move.. Anyway the end result must not be
> a file-system that is corrupt and mounts as RO.
>

Further debug information with dbg_rcvry, dbg_mnt, dbg_jnl and
dbg_jnlk prints enabled.
Let me know if additional information is needed.

The recovery code is dropping the inode, claiming it is orphaned.


UBIFS DBG rcvry (pid 103): checking index head at 37:92160
UBIFS DBG rcvry (pid 103): checking LPT head at 7:18432
UBIFS DBG mnt (pid 103): start replaying the journal
UBIFS DBG mnt (pid 103): replay log LEB 3:0
UBIFS DBG mnt (pid 103): commit start sqnum 7367
UBIFS DBG mnt (pid 103): add replay bud LEB 831:110592, head 1
UBIFS DBG mnt (pid 103): add replay bud LEB 823:49152, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 828:124928, head 1
UBIFS DBG mnt (pid 103): add replay bud LEB 822:0, head 1
UBIFS DBG mnt (pid 103): add replay bud LEB 821:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 820:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 819:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 818:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 817:0, head 1
UBIFS DBG mnt (pid 103): add replay bud LEB 816:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 815:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 814:0, head 1
UBIFS DBG mnt (pid 103): add replay bud LEB 813:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 812:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 811:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 810:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 809:0, head 2
UBIFS DBG mnt (pid 103): add replay bud LEB 808:0, head 1
UBIFS DBG mnt (pid 103): replay log LEB 4:0
UBIFS DBG mnt (pid 103): replay bud LEB 831, head 1, offs 110592, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 831 replied: dirty 12608, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 823, head 2, offs 49152, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 823 replied: dirty 20376, free 2048
UBIFS DBG mnt (pid 103): replay bud LEB 828, head 1, offs 124928, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 828 replied: dirty 1488, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 822, head 1, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 822 replied: dirty 93248, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 821, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 821 replied: dirty 608, free 2048
UBIFS DBG mnt (pid 103): replay bud LEB 820, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 820 replied: dirty 608, free 2048
UBIFS DBG mnt (pid 103): replay bud LEB 819, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 819 replied: dirty 10736, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 818, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 818 replied: dirty 27608, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 817, head 1, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 817 replied: dirty 90896, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 816, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 816 replied: dirty 20456, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 815, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 815 replied: dirty 8352, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 814, head 1, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 814 replied: dirty 87888, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 813, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 813 replied: dirty 1864, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 812, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 812 replied: dirty 632, free 2048
UBIFS DBG mnt (pid 103): replay bud LEB 811, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 811 replied: dirty 800, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 810, head 2, offs 0, is_last 0
UBIFS DBG mnt (pid 103): bud LEB 810 replied: dirty 24776, free 0
UBIFS DBG mnt (pid 103): replay bud LEB 809, head 2, offs 0, is_last 1
UBIFS DBG rcvry (pid 103): 809:0, jhead 2, grouped 1
UBIFS DBG rcvry (pid 103): found corruption (-1) at 809:26624
UBIFS DBG rcvry (pid 103): cleaning corruption at 809:26624
UBIFS DBG rcvry (pid 103): fixing LEB 809 start 0 endpt 26624
UBIFS DBG mnt (pid 103): bud LEB 809 replied: dirty 9592, free 100352
UBIFS DBG mnt (pid 103): replay bud LEB 808, head 1, offs 0, is_last 1
UBIFS DBG rcvry (pid 103): 808:0, jhead 1, grouped 1
UBIFS DBG rcvry (pid 103): found corruption (-1) at 808:53248
UBIFS DBG rcvry (pid 103): cleaning corruption at 808:53248
UBIFS DBG rcvry (pid 103): fixing LEB 808 start 0 endpt 53248
UBIFS DBG mnt (pid 103): bud LEB 808 replied: dirty 19608, free 73728
UBIFS DBG mnt (pid 103): bud LEB 822 was GC'd (126976 free, 30920 dirty)
UBIFS DBG mnt (pid 103): LEB 822 lp: 126976 free 30920 dirty replay: 0
free 93248 dirty
UBIFS DBG mnt (pid 103): bud LEB 818 was GC'd (126976 free, 336 dirty)
UBIFS DBG mnt (pid 103): LEB 818 lp: 126976 free 336 dirty replay: 0
free 27608 dirty
UBIFS DBG mnt (pid 103): bud LEB 817 was GC'd (126976 free, 30344 dirty)
UBIFS DBG mnt (pid 103): LEB 817 lp: 126976 free 30344 dirty replay: 0
free 90896 dirty
UBIFS DBG mnt (pid 103): bud LEB 815 was GC'd (126976 free, 760 dirty)
UBIFS DBG mnt (pid 103): LEB 815 lp: 126976 free 760 dirty replay: 0
free 8352 dirty
UBIFS DBG mnt (pid 103): bud LEB 814 was GC'd (126976 free, 31152 dirty)
UBIFS DBG mnt (pid 103): LEB 814 lp: 126976 free 31152 dirty replay: 0
free 87888 dirty
UBIFS DBG mnt (pid 103): bud LEB 811 was GC'd (126976 free, 400 dirty)
UBIFS DBG mnt (pid 103): LEB 811 lp: 126976 free 400 dirty replay: 0
free 800 dirty
UBIFS DBG mnt (pid 103): bud LEB 810 was GC'd (126976 free, 4336 dirty)
UBIFS DBG mnt (pid 103): LEB 810 lp: 126976 free 4336 dirty replay: 0
free 24776 dirty
UBIFS DBG mnt (pid 103): bud LEB 808 was GC'd (126976 free, 5000 dirty)
UBIFS DBG mnt (pid 103): LEB 808 lp: 126976 free 5000 dirty replay:
73728 free 19608 dirty
UBIFS DBG mnt (pid 103): finished, log head LEB 3:34816, max_sqnum
9265, highest_inum 721
UBIFS DBG rcvry (pid 103): LEB 9
UBIFS DBG rcvry (pid 103): deleting orphaned inode 218
UBIFS DBG mnt (pid 103): ino 218, new 0, tot 1
UBIFS DBG rcvry (pid 103): last orph node for commit 15 at 9:0
UBIFS DBG rcvry (pid 103): deleting orphaned inode 237
UBIFS DBG mnt (pid 103): ino 237, new 0, tot 2
UBIFS DBG rcvry (pid 103): last orph node for commit 17 at 9:2048
UBIFS DBG rcvry (pid 103): deleting orphaned inode 247
UBIFS DBG mnt (pid 103): ino 247, new 0, tot 3
UBIFS DBG rcvry (pid 103): last orph node for commit 19 at 9:4096
UBIFS DBG rcvry (pid 103): deleting orphaned inode 250
UBIFS DBG mnt (pid 103): ino 250, new 0, tot 4
UBIFS DBG rcvry (pid 103): last orph node for commit 21 at 9:6144
UBIFS DBG rcvry (pid 103): deleting orphaned inode 253
UBIFS DBG mnt (pid 103): ino 253, new 0, tot 5
UBIFS DBG rcvry (pid 103): last orph node for commit 23 at 9:8192
UBIFS DBG rcvry (pid 103): deleting orphaned inode 256
UBIFS DBG mnt (pid 103): ino 256, new 0, tot 6
UBIFS DBG rcvry (pid 103): last orph node for commit 25 at 9:10240
UBIFS DBG rcvry (pid 103): deleting orphaned inode 259
UBIFS DBG mnt (pid 103): ino 259, new 0, tot 7
UBIFS DBG rcvry (pid 103): last orph node for commit 27 at 9:12288
UBIFS DBG rcvry (pid 103): deleting orphaned inode 262
UBIFS DBG mnt (pid 103): ino 262, new 0, tot 8
UBIFS DBG rcvry (pid 103): last orph node for commit 29 at 9:14336
UBIFS DBG rcvry (pid 103): deleting orphaned inode 265
UBIFS DBG mnt (pid 103): ino 265, new 0, tot 9
UBIFS DBG rcvry (pid 103): last orph node for commit 31 at 9:16384
UBIFS DBG rcvry (pid 103): deleting orphaned inode 268
UBIFS DBG mnt (pid 103): ino 268, new 0, tot 10
UBIFS DBG rcvry (pid 103): last orph node for commit 33 at 9:18432
UBIFS DBG rcvry (pid 103): deleting orphaned inode 272
UBIFS DBG mnt (pid 103): ino 272, new 0, tot 11
UBIFS DBG rcvry (pid 103): last orph node for commit 35 at 9:20480
UBIFS DBG rcvry (pid 103): deleting orphaned inode 275
UBIFS DBG mnt (pid 103): ino 275, new 0, tot 12
UBIFS DBG rcvry (pid 103): last orph node for commit 37 at 9:22528
UBIFS DBG rcvry (pid 103): deleting orphaned inode 278
UBIFS DBG mnt (pid 103): ino 278, new 0, tot 13
UBIFS DBG rcvry (pid 103): last orph node for commit 39 at 9:24576
UBIFS DBG rcvry (pid 103): deleting orphaned inode 281
UBIFS DBG mnt (pid 103): ino 281, new 0, tot 14
UBIFS DBG rcvry (pid 103): last orph node for commit 41 at 9:26624
UBIFS DBG rcvry (pid 103): deleting orphaned inode 284
UBIFS DBG mnt (pid 103): ino 284, new 0, tot 15
UBIFS DBG rcvry (pid 103): last orph node for commit 43 at 9:28672
UBIFS DBG rcvry (pid 103): deleting orphaned inode 287
UBIFS DBG mnt (pid 103): ino 287, new 0, tot 16
UBIFS DBG rcvry (pid 103): last orph node for commit 45 at 9:30720
UBIFS DBG rcvry (pid 103): deleting orphaned inode 290
UBIFS DBG mnt (pid 103): ino 290, new 0, tot 17
UBIFS DBG rcvry (pid 103): last orph node for commit 47 at 9:32768
UBIFS DBG rcvry (pid 103): deleting orphaned inode 293
UBIFS DBG mnt (pid 103): ino 293, new 0, tot 18
UBIFS DBG rcvry (pid 103): last orph node for commit 49 at 9:34816
UBIFS DBG rcvry (pid 103): deleting orphaned inode 296
UBIFS DBG mnt (pid 103): ino 296, new 0, tot 19
UBIFS DBG rcvry (pid 103): last orph node for commit 51 at 9:36864
UBIFS DBG rcvry (pid 103): deleting orphaned inode 299
UBIFS DBG mnt (pid 103): ino 299, new 0, tot 20
UBIFS DBG rcvry (pid 103): last orph node for commit 53 at 9:38912
UBIFS DBG rcvry (pid 103): deleting orphaned inode 302
UBIFS DBG mnt (pid 103): ino 302, new 0, tot 21
UBIFS DBG rcvry (pid 103): last orph node for commit 55 at 9:40960
UBIFS DBG rcvry (pid 103): deleting orphaned inode 305
UBIFS DBG mnt (pid 103): ino 305, new 0, tot 22
UBIFS DBG rcvry (pid 103): last orph node for commit 57 at 9:43008
UBIFS DBG rcvry (pid 103): deleting orphaned inode 308
UBIFS DBG mnt (pid 103): ino 308, new 0, tot 23
UBIFS DBG rcvry (pid 103): last orph node for commit 59 at 9:45056
UBIFS DBG rcvry (pid 103): deleting orphaned inode 311
UBIFS DBG mnt (pid 103): ino 311, new 0, tot 24
UBIFS DBG rcvry (pid 103): last orph node for commit 61 at 9:47104
UBIFS DBG rcvry (pid 103): deleting orphaned inode 314
UBIFS DBG mnt (pid 103): ino 314, new 0, tot 25
UBIFS DBG rcvry (pid 103): last orph node for commit 63 at 9:49152
UBIFS DBG rcvry (pid 103): deleting orphaned inode 317
UBIFS DBG mnt (pid 103): ino 317, new 0, tot 26
UBIFS DBG rcvry (pid 103): last orph node for commit 65 at 9:51200
UBIFS DBG rcvry (pid 103): deleting orphaned inode 320
UBIFS DBG mnt (pid 103): ino 320, new 0, tot 27
UBIFS DBG rcvry (pid 103): last orph node for commit 68 at 9:53248
UBIFS DBG rcvry (pid 103): deleting orphaned inode 349
UBIFS DBG mnt (pid 103): ino 349, new 0, tot 28
UBIFS DBG rcvry (pid 103): last orph node for commit 72 at 9:55296
UBIFS DBG rcvry (pid 103): deleting orphaned inode 466
UBIFS DBG mnt (pid 103): ino 466, new 0, tot 29
UBIFS DBG rcvry (pid 103): last orph node for commit 127 at 9:57344
UBIFS DBG rcvry (pid 103): LEB 10
UBIFS DBG rcvry (pid 103): GC head LEB -1, offs -1
UBIFS DBG rcvry (pid 103): found empty LEB 807, run commit
UBIFS error (ubi0:20 pid 103): read_add_inode: inode 349 not found in index
UBIFS error (ubi0:20 pid 103): check_leaf: error -2 while processing
entry node and trying to find inode node 349
 magic          0x6101831
 crc            0xba9856a7
 node_type      2 (direntry node)
 group_type     1 (in node group)
 sqnum          4115
 len            70
 key            (66, direntry, 0x4974b0f)
 inum           349
 type           0
 nlen           13
 name           emotiond.conf
UBIFS error (ubi0:20 pid 103): dbg_walk_index: leaf checking function
returned error -2, for leaf at LEB 29:90112
znode be091400, LEB 37:92496 len 128 parent be089600 iip 1 level 0
child_cnt 5 flags 0
zbranches:
 0: LNC   (null) LEB 32:24576 len 81 key (66, direntry, 0x363e97f)
 1: LNC   (null) LEB 29:100352 len 63 key (66, direntry, 0x3f88c71)
 2: LNC   (null) LEB 12:94208 len 74 key (66, direntry, 0x477308e)
 3: LNC   (null) LEB 29:90112 len 70 key (66, direntry, 0x4974b0f)
 4: LNC be0590c0 LEB 814:73728 len 63 key (66, direntry, 0x49bb6f7)
UBIFS error (ubi0:20 pid 103): dbg_check_filesystem: file-system check
failed with error -2

______________________________________________________
Linux MTD discussion mailing list
http://lists.infradead.org/mailman/listinfo/linux-mtd/
[Index of Archives]     [LARTC]     [Bugtraq]     [Yosemite Forum]     [Photo]

  Powered by Linux