UBIFS failure & stable page writes

[Prins Anton (ST-CO/ENG1.1)]

Will add the CFLAG -DDEBUG and debug further!
(I hope at this kernel-recovery stage there are not debug messages of multiple partitions because there are more UBIFS partitions.)

Doing this I saw some suspicious messages like:
UBIFS DBG rcvry: deleting orphaned inode 0
...
UBIFS DBG rcvry: deleting orphaned inode 1
...

Am I correct the recovery thinks the inode 1 is a orphan inode, so it disappears?

Below the complete log of recovery-till failure:
UBIFS: recovery needed
UBIFS DBG rcvry: checking index head at 1203:69632
UBIFS DBG rcvry: checking LPT head at 8:262144
UBIFS DBG lp: space_bits 16
UBIFS DBG lp: lpt_lnum_bits 2
UBIFS DBG lp: lpt_offs_bits 19
UBIFS DBG lp: lpt_spc_bits 19
UBIFS DBG lp: pcnt_bits 9
UBIFS DBG lp: lnum_bits 11
UBIFS DBG lp: pnode_sz 19
UBIFS DBG lp: nnode_sz 13
UBIFS DBG lp: ltab_sz 12
UBIFS DBG lp: lsave_sz 355
UBIFS DBG lp: lsave_cnt 256
UBIFS DBG lp: lpt_hght 5
UBIFS DBG lp: big_lpt 0
UBIFS DBG lp: LPT root is at 8:258202
UBIFS DBG lp: LPT head is at 8:262144
UBIFS DBG lp: LPT ltab is at 8:258048
UBIFS DBG io: LEB 1:245760, master node, length 512 (aligned 4096)
UBIFS DBG io: LEB 2:245760, master node, length 512 (aligned 4096)
UBIFS DBG lp: LEB 8 add 13 to 261048
UBIFS DBG lp: LEB 8 add 12 to 261061
UBIFS DBG lp: LEB 8 add 13 to 261073
UBIFS DBG lp: LEB 8 add 13 to 261086
UBIFS DBG lp: LEB 8 add 13 to 261099
UBIFS DBG lp: LEB 8 add 13 to 261112
UBIFS DBG lp: LEB 8 add 19 to 261125
UBIFS DBG lp: LEB 1203, free 446464, dirty 63576, flags 34
UBIFS DBG lp: LEB 1203, free -2147483647, dirty -2147483647, flags 50
UBIFS DBG lp: LEB 1203, free 446464, dirty 63576, flags 34
UBIFS DBG mnt: start replaying the journal
UBIFS DBG mnt: replay log LEB 4:0
UBIFS DBG scan: scan LEB 4:0
UBIFS DBG scan: look at LEB 4:0 (516096 bytes left)
UBIFS DBG scan: scanning commit start node
UBIFS DBG scan: look at LEB 4:32 (516064 bytes left)
UBIFS DBG scan: scanning reference node
UBIFS DBG scan: look at LEB 4:96 (516000 bytes left)
UBIFS DBG scan: scanning reference node
UBIFS DBG scan: look at LEB 4:160 (515936 bytes left)
UBIFS DBG scan: scanning padding node
UBIFS DBG scan: 3908 bytes padded, offset now 4096
UBIFS DBG scan: look at LEB 4:4096 (512000 bytes left)
UBIFS DBG scan: hit empty space
UBIFS DBG scan: stop scanning LEB 4 at offset 4096
UBIFS DBG mnt: commit start sqnum 8295884
UBIFS DBG mnt: add replay bud LEB 168:319488, head 1
UBIFS DBG log: LEB 168:319488, jhead 1 (base), bud_bytes 196608
UBIFS DBG mnt: add replay bud LEB 1202:307200, head 2
UBIFS DBG log: LEB 1202:307200, jhead 2 (data), bud_bytes 405504
UBIFS DBG mnt: replay log LEB 5:0
UBIFS DBG scan: scan LEB 5:0
UBIFS DBG scan: look at LEB 5:0 (516096 bytes left)
UBIFS DBG scan: hit empty space
UBIFS DBG scan: stop scanning LEB 5 at offset 0
UBIFS DBG mnt: replay bud LEB 168, head 1, offs 319488, is_last 1
UBIFS DBG rcvry: 168:319488, jhead 1, grouped 1
UBIFS DBG scan: scan LEB 168:319488
UBIFS DBG scan: look at LEB 168:319488 (196608 bytes left)
UBIFS DBG scan: hit empty space
UBIFS DBG rcvry: found corruption (-1) at 168:319488
UBIFS DBG rcvry: cleaning corruption at 168:319488
UBIFS DBG scan: stop scanning LEB 168 at offset 319488
UBIFS DBG rcvry: fixing LEB 168 start 319488 endpt 319488
UBIFS DBG mnt: bud LEB 168 replied: dirty 0, free 196608
UBIFS DBG mnt: replay bud LEB 1202, head 2, offs 307200, is_last 1
UBIFS DBG rcvry: 1202:307200, jhead 2, grouped 1
UBIFS DBG scan: scan LEB 1202:307200
UBIFS DBG scan: look at LEB 1202:307200 (208896 bytes left)
UBIFS DBG scan: hit empty space
UBIFS DBG rcvry: found corruption (-1) at 1202:307200
UBIFS DBG rcvry: cleaning corruption at 1202:307200
UBIFS DBG scan: stop scanning LEB 1202 at offset 307200
UBIFS DBG rcvry: fixing LEB 1202 start 307200 endpt 307200
UBIFS DBG mnt: bud LEB 1202 replied: dirty 0, free 208896
UBIFS DBG lp: LEB 8 add 13 to 261144
UBIFS DBG lp: LEB 8 add 13 to 261157
UBIFS DBG lp: LEB 8 add 13 to 261170
UBIFS DBG lp: LEB 8 add 13 to 261183
UBIFS DBG lp: LEB 8 add 19 to 261196
UBIFS DBG lp: LEB 168, free 196608, dirty 319008, flags 1
UBIFS DBG lp: LEB 168, free 196608, dirty 319008, flags 17
UBIFS DBG lp: LEB 168, free 196608, dirty 319008, flags 1
UBIFS DBG io: LEB 168:319488, jhead 1 (base)
UBIFS DBG lp: LEB 1202, free 208896, dirty 287016, flags 1
UBIFS DBG lp: LEB 1202, free 208896, dirty 287016, flags 17
UBIFS DBG lp: LEB 1202, free 208896, dirty 287016, flags 1
UBIFS DBG io: LEB 1202:307200, jhead 2 (data)
UBIFS DBG mnt: finished, log head LEB 4:4096, max_sqnum 8295889, highest_inum 1127865
UBIFS DBG rcvry: LEB 9
UBIFS DBG scan: scan LEB 9:0
UBIFS DBG scan: look at LEB 9:0 (516096 bytes left)
UBIFS DBG scan: scanning orphan node
UBIFS DBG scan: look at LEB 9:40 (516056 bytes left)
UBIFS DBG scan: scanning padding node
UBIFS DBG scan: 4028 bytes padded, offset now 4096
UBIFS DBG scan: look at LEB 9:4096 (512000 bytes left)
UBIFS DBG scan: scanning orphan node
UBIFS DBG scan: look at LEB 9:4136 (511960 bytes left)
UBIFS DBG scan: scanning padding node
UBIFS DBG scan: 4028 bytes padded, offset now 8192
UBIFS DBG scan: look at LEB 9:8192 (507904 bytes left)
UBIFS DBG scan: scanning orphan node
UBIFS DBG scan: look at LEB 9:8232 (507864 bytes left)
UBIFS DBG scan: scanning padding node
UBIFS DBG scan: 4028 bytes padded, offset now 12288
UBIFS DBG scan: look at LEB 9:12288 (503808 bytes left)
UBIFS DBG scan: scanning orphan node
UBIFS DBG scan: look at LEB 9:12328 (503768 bytes left)
UBIFS DBG scan: scanning padding node
UBIFS DBG scan: 4028 bytes padded, offset now 16384
UBIFS DBG scan: look at LEB 9:16384 (499712 bytes left)
UBIFS DBG scan: scanning orphan node
UBIFS DBG scan: look at LEB 9:16424 (499672 bytes left)
UBIFS DBG scan: scanning padding node
UBIFS DBG scan: 4028 bytes padded, offset now 20480
UBIFS DBG scan: look at LEB 9:20480 (495616 bytes left)
UBIFS DBG scan: scanning orphan node
UBIFS DBG scan: look at LEB 9:20520 (495576 bytes left)
UBIFS DBG scan: scanning padding node
UBIFS DBG scan: 4028 bytes padded, offset now 24576
UBIFS DBG scan: look at LEB 9:24576 (491520 bytes left)
UBIFS DBG scan: hit empty space
UBIFS DBG scan: stop scanning LEB 9 at offset 24576
UBIFS DBG rcvry: deleting orphaned inode 821482
UBIFS DBG tnc: ino 821482
UBIFS DBG tnc: (lowest) (821482, xentry, 0x000000)
UBIFS DBG tnc: search key (821482, xentry, 0x000000)
UBIFS DBG io: LEB 1203:66968, indexing node, length 68
UBIFS DBG tnc: LEB 1203:66968, level 6, 2 branch
UBIFS DBG io: LEB 1203:66800, indexing node, length 168
UBIFS DBG tnc: LEB 1203:66800, level 5, 7 branch
UBIFS DBG io: LEB 1203:66648, indexing node, length 148
UBIFS DBG tnc: LEB 1203:66648, level 4, 6 branch
UBIFS DBG io: LEB 1203:66520, indexing node, length 128
UBIFS DBG tnc: LEB 1203:66520, level 3, 5 branch
UBIFS DBG io: LEB 1203:66352, indexing node, length 168
UBIFS DBG tnc: LEB 1203:66352, level 2, 7 branch
UBIFS DBG io: LEB 890:301496, indexing node, length 68
UBIFS DBG tnc: LEB 890:301496, level 1, 2 branch
UBIFS DBG io: LEB 890:301352, indexing node, length 68
UBIFS DBG tnc: LEB 890:301352, level 0, 2 branch
UBIFS DBG io: LEB 890:282872, indexing node, length 148
UBIFS DBG tnc: LEB 890:282872, level 2, 6 branch
UBIFS DBG io: LEB 890:282800, indexing node, length 68
UBIFS DBG tnc: LEB 890:282800, level 1, 2 branch
UBIFS DBG io: LEB 890:282728, indexing node, length 68
UBIFS DBG tnc: LEB 890:282728, level 0, 2 branch
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG tnc: search key (821482, inode)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG mnt: ino 821482, new 0, tot 1
UBIFS DBG rcvry: last orph node for commit 1376 at 9:0
UBIFS DBG rcvry: deleting orphaned inode 977567
UBIFS DBG tnc: ino 977567
UBIFS DBG tnc: (lowest) (977567, xentry, 0x000000)
UBIFS DBG tnc: search key (977567, xentry, 0x000000)
UBIFS DBG io: LEB 1203:66240, indexing node, length 108
UBIFS DBG tnc: LEB 1203:66240, level 1, 4 branch
UBIFS DBG io: LEB 1203:65720, indexing node, length 48
UBIFS DBG tnc: LEB 1203:65720, level 0, 1 branch
UBIFS DBG io: LEB 890:318744, indexing node, length 128
UBIFS DBG tnc: LEB 890:318744, level 1, 5 branch
UBIFS DBG io: LEB 890:310560, indexing node, length 48
UBIFS DBG tnc: LEB 890:310560, level 0, 1 branch
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG tnc: search key (977567, inode)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG mnt: ino 977567, new 0, tot 2
UBIFS DBG rcvry: last orph node for commit 1395 at 9:4096
UBIFS DBG rcvry: deleting orphaned inode 985932
UBIFS DBG tnc: ino 985932
UBIFS DBG tnc: (lowest) (985932, xentry, 0x000000)
UBIFS DBG tnc: search key (985932, xentry, 0x000000)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG tnc: search key (985932, inode)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG mnt: ino 985932, new 0, tot 3
UBIFS DBG rcvry: last orph node for commit 1396 at 9:8192
UBIFS DBG rcvry: deleting orphaned inode 0
UBIFS DBG tnc: ino 0
UBIFS DBG tnc: (lowest) (0, xentry, 0x000000)
UBIFS DBG tnc: search key (0, xentry, 0x000000)
UBIFS DBG io: LEB 1203:64440, indexing node, length 108
UBIFS DBG tnc: LEB 1203:64440, level 5, 4 branch
UBIFS DBG io: LEB 1203:63672, indexing node, length 108
UBIFS DBG tnc: LEB 1203:63672, level 4, 4 branch
UBIFS DBG io: LEB 1203:62360, indexing node, length 128
UBIFS DBG tnc: LEB 1203:62360, level 3, 5 branch
UBIFS DBG io: LEB 1203:61880, indexing node, length 128
UBIFS DBG tnc: LEB 1203:61880, level 2, 5 branch
UBIFS DBG io: LEB 1203:61512, indexing node, length 88
UBIFS DBG tnc: LEB 1203:61512, level 1, 3 branch
UBIFS DBG io: LEB 1203:61440, indexing node, length 68
UBIFS DBG tnc: LEB 1203:61440, level 0, 2 branch
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG tnc: search key (0, inode)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG mnt: ino 0, new 0, tot 4
UBIFS DBG rcvry: last orph node for commit 1398 at 9:12288
UBIFS DBG rcvry: deleting orphaned inode 1
UBIFS DBG tnc: ino 1
UBIFS DBG tnc: (lowest) (1, xentry, 0x000000)
UBIFS DBG tnc: search key (1, xentry, 0x000000)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG tnc: search key (1, inode)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG mnt: ino 1, new 0, tot 5
UBIFS DBG rcvry: last orph node for commit 1405 at 9:16384
UBIFS DBG rcvry: deleting orphaned inode 1120394
UBIFS DBG tnc: ino 1120394
UBIFS DBG tnc: (lowest) (1120394, xentry, 0x000000)
UBIFS DBG tnc: search key (1120394, xentry, 0x000000)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG tnc: search key (1120394, inode)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS DBG mnt: ino 1120394, new 0, tot 6
UBIFS DBG rcvry: last orph node for commit 1412 at 9:20480
UBIFS DBG rcvry: GC head LEB -1, offs -1
UBIFS DBG find: found LEB 166, free 516096, dirty 0, flags 0x4
UBIFS DBG lp: LEB 166, free 516096, dirty 0, flags 52
UBIFS DBG lp: LEB 166, free 516096, dirty 0, flags 4
UBIFS DBG lp: LEB 166, free 516096, dirty 0, flags 48
UBIFS DBG lp: LEB 166, free -2147483647, dirty -2147483647, flags 16
UBIFS DBG io: jhead 1 (base)
UBIFS DBG io: synchronize
UBIFS DBG io: LEB 26:0, 808 bytes, jhead 1 (base)
UBIFS DBG lp: LEB 26, free 515288, dirty 392, flags 16
UBIFS DBG lp: LEB 26, free 512000, dirty 3680, flags 16
UBIFS DBG lp: LEB 26, free 515288, dirty 392, flags 16
UBIFS DBG lp: LEB 166, free 516096, dirty 0, flags 48
UBIFS DBG rcvry: found empty LEB 166, run commit
UBIFS DBG cmt: start
UBIFS DBG log: add ref to LEB 168:319488 for jhead 1 (base)
UBIFS DBG log: add ref to LEB 1202:307200 for jhead 2 (data)
UBIFS DBG log: writing commit start at LEB 5:0, len 4096
UBIFS DBG log: preserve 168:319488, jhead 1 (base), bud bytes 0, cmt_bud_bytes 0
UBIFS DBG log: preserve 1202:307200, jhead 2 (data), bud bytes 0, cmt_bud_bytes 0
UBIFS DBG cmt: no znodes to commit
UBIFS DBG find: found 0 dirty index LEBs
UBIFS DBG cmt: number of index LEBs 31
UBIFS DBG cmt: size of index 702944
UBIFS DBG lp:
UBIFS DBG cmt: committing 11 cnodes
UBIFS DBG lp: committing 11 cnodes
UBIFS DBG lp: LEB 8 free 253952 dirty 261215 to 249856 +3929
UBIFS DBG cmt: 0 orphans to commit
UBIFS DBG lp:
UBIFS DBG lp: LPT root is at 8:262298
UBIFS DBG lp: LPT head is at 8:266240
UBIFS DBG lp: LPT ltab is at 8:262144
UBIFS DBG gen: deleting orphan ino 1120394
UBIFS DBG gen: deleting orphan ino 1
UBIFS DBG gen: deleting orphan ino 0
UBIFS DBG gen: deleting orphan ino 985932
UBIFS DBG gen: deleting orphan ino 977567
UBIFS DBG gen: deleting orphan ino 821482
UBIFS DBG log: old tail was LEB 4:0, new tail is LEB 5:0
UBIFS DBG io: LEB 1:249856, master node, length 512 (aligned 4096)
UBIFS DBG io: LEB 2:249856, master node, length 512 (aligned 4096)
UBIFS DBG log: unmap log LEB 4
UBIFS DBG cmt: commit end
UBIFS: recovery completed
UBIFS: mounted UBI device 1, volume 1, name "datafs"
UBIFS: file system size:   640475136 bytes (625464 KiB, 610 MiB, 1241 LEBs)
UBIFS: journal size:       10452992 bytes (10208 KiB, 9 MiB, 21 LEBs)
UBIFS: media format:       w4/r0 (latest is w4/r0)
UBIFS: default compressor: lzo
UBIFS: reserved for root:  0 bytes (0 KiB)
UBIFS DBG (pid 1): mount_ubifs: compiled on:         May 28 2013 at 11:15:36
UBIFS DBG (pid 1): mount_ubifs: min. I/O unit size:  4096 bytes
UBIFS DBG (pid 1): mount_ubifs: max. write size:     4096 bytes
UBIFS DBG (pid 1): mount_ubifs: LEB size:            516096 bytes (504 KiB)
UBIFS DBG (pid 1): mount_ubifs: data journal heads:  1
UBIFS DBG (pid 1): mount_ubifs: UUID:                1D1AD726-53AB-4623-8D86-B7773B5EFA83
UBIFS DBG (pid 1): mount_ubifs: big_lpt              0
UBIFS DBG (pid 1): mount_ubifs: log LEBs:            4 (3 - 6)
UBIFS DBG (pid 1): mount_ubifs: LPT area LEBs:       2 (7 - 8)
UBIFS DBG (pid 1): mount_ubifs: orphan area LEBs:    1 (9 - 9)
UBIFS DBG (pid 1): mount_ubifs: main area LEBs:      1241 (10 - 1250)
UBIFS DBG (pid 1): mount_ubifs: index LEBs:          31
UBIFS DBG (pid 1): mount_ubifs: total index bytes:   702944 (686 KiB, 0 MiB)
UBIFS DBG (pid 1): mount_ubifs: key hash type:       0
UBIFS DBG (pid 1): mount_ubifs: tree fanout:         8
UBIFS DBG (pid 1): mount_ubifs: reserved GC LEB:     166
UBIFS DBG (pid 1): mount_ubifs: first main LEB:      10
UBIFS DBG (pid 1): mount_ubifs: max. znode size      240
UBIFS DBG (pid 1): mount_ubifs: max. index node size 192
UBIFS DBG (pid 1): mount_ubifs: node sizes:          data 48, inode 160, dentry 56
UBIFS DBG (pid 1): mount_ubifs: node sizes:          trun 56, sb 4096, master 512
UBIFS DBG (pid 1): mount_ubifs: node sizes:          ref 64, cmt. start 32, orph 32
UBIFS DBG (pid 1): mount_ubifs: max. node sizes:     data 4144, inode 4256 dentry 312, idx 188
UBIFS DBG (pid 1): mount_ubifs: dead watermark:      4096
UBIFS DBG (pid 1): mount_ubifs: dark watermark:      8192
UBIFS DBG (pid 1): mount_ubifs: LEB overhead:        2240
UBIFS DBG (pid 1): mount_ubifs: max. dark space:     10166272 (9928 KiB, 9 MiB)
UBIFS DBG (pid 1): mount_ubifs: maximum bud bytes:   8388608 (8192 KiB, 8 MiB)
UBIFS DBG (pid 1): mount_ubifs: BG commit bud bytes: 6815744 (6656 KiB, 6 MiB)
UBIFS DBG (pid 1): mount_ubifs: current bud bytes    405504 (396 KiB, 0 MiB)
UBIFS DBG (pid 1): mount_ubifs: max. seq. number:    8295894
UBIFS DBG (pid 1): mount_ubifs: commit number:       1442
UBIFS DBG gen: inode 1
UBIFS DBG tnc: search key (1, inode)
UBIFS DBG tnc: found 0, lvl 0, n -1
UBIFS error (pid 1): ubifs_iget: failed to read inode 1, error -2
UBIFS DBG gen: inode 1, mode 0x8000
UBIFS DBG gen: un-mounting UBI device 1, volume 1