Some issues with the AT91 dataflash driver...

(not Cc'ing linux-arm-kernel since I'm not subscribed)

I'm seeing something similar on AVR32/ATNGW100 as well. On 2.6.22-rc3 I get this:

root@uclibc ~]# mount -tjffs2 mtd3 /mnt
JFFS2 write-buffering enabled buffer (1056) erasesize (8448)
[root@uclibc ~]#JFFS2 error: (134) read_more: can not read -928 bytes from 0x00000420, error code: -22.
JFFS2 error: (134) jffs2_do_read_inode_internal: cannot read nodes for ino 2, returned error is -22
Returned error for crccheck of ino #2. Expect badness...
JFFS2 error: (134) read_more: can not read -928 bytes from 0x00019020, error code: -22.

Unable to handle kernel NULL pointer dereference at virtual address 000000ec
ptbr = 91d67800 pgd = 103d9c66 pte = 00000000
Oops: Kernel access of bad area, sig: 11 [#1]
FRAME_POINTER chip: 0x01f:0x1e82 rev 0
Modules linked in:
PC is at jffs2_free_tmp_dnode_info_list+0xa/0x54
LR is at jffs2_free_tmp_dnode_info+0xe/0x14
pc : [<9009807a>]    lr : [<900970ca>]    Not tainted
sp : 91e73e1c  r12: 901b22fc  r11: 9021a940

r10: 000000e7 r9 : 91e4a9a0 r8 : 00000000
r7 : 91e73e1c r6 : 000000e7 r5 : 91e73e84 r4 : 00000000 r3 : 91dd4000 r2 : ffffffea r1 : 91e1cec4 r0 : 00018e4c
Flags: qvnzc
Mode bits: hrje....g
CPU Mode: Supervisor
Process: jffs2_gcd_mtd3 [134] (task: 90279540 thread: 91e72000)

Stack: (0x91e73e1c to 0x91e74000)

3e00: 9009901e
3e20: 91e73e54 fffffc60 00019020 00000000 00000000 91e73e84 91d3b200 91d3b400 3e40: 00000420 000001ef 91e1ce58 00000000 00000420 9009906c 91e73ea8 91e73e84 3e60: 91e73ecc 00000000 91e1d1f8 91d3b200 9009dccc 91d3b400 00000000 91d3b200 3e80: 00000000 91e4a100 00000000 0000009a 00000000 00000000 00000000 00000000 3ea0: 9009dccc 91d3b400 90099838 91e73f10 91d3b200 fffffff4 00000000 91e1d1f8 3ec0: 91d3b400 9009dccc 91d3b400 1985e002 00000055 ce5f02cc 00000015 00000001 3ee0: 0000a1ff 00000003 90015ff2 91e73f0c 00400025 91e1d1e0 00000000 901530e4 3f00: 91e73f20 90015b2e 90279540 00000000 9009cea0 91e73f48 91d3b42c 91e1d1f8 3f20: 00000000 00000001 91d3b400 9009dccc 91d3b400 91e73f44 91e72000 91d3b400 3f40: 00000000 9001a51a 9009dd82 91e73fec 91e72000 91d3b400 00000000 00000000 3f60: 90019f2c 9009dccc 91d3b400 0079cfdb 0079cfdc 0079cfdd 0079cfde 0079cfdf 3f80: 0079cfe0 0079cfe1 0079cfe2 0079cfe3 0079cfe4 0079cfe5 0079cfe6 0079cfe7 3fa0: 0079cfe8 90010166 91e01a34 901b5b08 90279000 91dd4800 00400000 90012d6c 3fc0: 90012d6c 91e74000 00000000 00000000 00000000 00000000 00000000 00000000 3fe0: 00000000 00000000 00000000 90019f2c 00000000 00000000 00000000 00000000

Call trace:
 [<9009901e>] jffs2_get_inode_nodes+0xc9c/0xcc6
 [<9009906c>] jffs2_do_read_inode_internal+0x24/0x7b8
 [<90099838>] jffs2_do_crccheck_inode+0x38/0x6c
 [<9009cea0>] jffs2_garbage_collect_pass+0x134/0x4d4
 [<9009dd82>] jffs2_garbage_collect_thread+0xb6/0xd8
 [<90019f2c>] do_exit+0x0/0x51c

When I revert back to 32f15dc5e6 (which is when the ATNGW100 board support got merged), I get tons of CRC errors but no crash. That might be related to the bug fixed by a1e3cf418f however; I'll see if I can verify that.

Ah, I've somehow managed to set CONFIG_SLOB=y. That explains it...

I'm sure I've seen this message several times too.

Looks to me like something more fundamental got broken. I'm using mtd_dataflash with the atmel_spi driver. I take it you're using at91_dataflash with the legacy AT91 SPI driver, right?

Now that I've got the CRC errors sorted out, I'll try bisecting it.

Haavard

Correct I'm using at91_dataflash and legacy SPI on 2.6.22rc1+maxim patches. Better say trying to use :-)

BR, Ivan

Done. git-bisect blames this commit:

10731f83009e2556f98ffa5c7c2cbffe66dacfb3 is first bad commit commit 10731f83009e2556f98ffa5c7c2cbffe66dacfb3

Author: Artem Bityutskiy <[email protected]>
Date:   Wed Apr 4 13:59:11 2007 +0300

[JFFS2] fix buffer sise calculations in jffs2_get_inode_nodes()

In read inode we have an optimization which prevents one min. I/O unit (e.g. NAND page) to be read more then once.

Namely, at the beginning we do not know which node type we read, so we read so we assume we read the directory entry, because it has the smallest node header. When we read it, we read up to the next min. I/O unit, just because if later we'll need to read more, we already have this data.

If it turns out to be that the node is not directory entry, and we need more data, and we did not read it because it sits in the next min. I/O unit, we read the whole next (or several next) min. I/O unit(s). And if it happens to be that we read a data node, and we've read part of its data, we calculate partial CRC. So if later we need to check data CRC, we'll only read the rest of the data from further min. I/O units and continue CRC checking.

This code was a bit messy and buggy. The bug was that it assumed relatively large min. I/O unit, so that the largest node header could overlap only one min. I/O unit boundary.

This parch clean-ups the code a bit and fixes this bug. The patch was not tested on flash with small min. I/O unit, like NOR-ECC, nut it was tested on NAND with 512 bytes NAND page, so it at least does not break NAND. It was also tested with mtdram so it should not break NOR.

I don't have a clue what's wrong with it, but I'll of course help you debugging if you tell me what to do.

Haavard

Hi,

whats mtd->writesize of the flash? Do you have the debugging output log?

Best regards,
Artem Bityutskiy (Битюцкий Артём)

Hi Artem,

According to the source of at91_dataflash.c :
device->writesize = pagesize;

page size for AT45DB642 is 1056

BR,
Ivan

MTD_DEBUG=3 enabled:

at91_dataflash: AT45DB642 detected [spi0] (8650752 bytes) Creating 5 MTD partitions on "AT45DB642.spi0":
0x00031800-0x00139800 : "kernel"
mtd: Giving out device 0 to kernel 0x00139800-0x003cd800 : "initrd"
mtd: Giving out device 1 to initrd 0x003cd800-0x00582c00 : "data1"
mtd: Giving out device 2 to data1 0x00582c00-0x00738000 : "data2"
mtd: Giving out device 3 to data2 0x00738000-0x00840000 : "Dataflash"
mtd: Giving out device 4 to Dataflash

cat /proc/mtd
dev: size erasesize name
mtd0: 00108000 00000420 "kernel"
mtd1: 00294000 00000420 "initrd"
mtd2: 001b5400 00000420 "data1"
mtd3: 001b5400 00000420 "data2"
mtd4: 00108000 00000420 "Dataflash"

mount -t jffs2 /dev/mtdblock/4 /mnt/dataflash/
JFFS2 write-buffering enabled buffer (1056) erasesize (8448)
Empty flash at 0x000f825c ends at 0x000f8460
/ # JFFS2 error: (686) read_more: short read at 0x0f4aa0: 79200 instead of -928.
JFFS2 error: (686) jffs2_do_read_inode_internal: cannot read nodes for ino 4, returned error is -5 Returned error for crccheck of ino #4. Expect badness...
JFFS2 error: (686) read_more: short read at 0x0f94e0: 60192 instead of -928.
JFFS2 error: (686) jffs2_do_read_inode_internal: cannot read nodes for ino 4294967295, returned error is -5 Returned error for crccheck of ino #4294967295. Expect badness...
Checked all inodes but still 0x12db0 bytes of unchecked space?
No space for garbage collection. Aborting GC thread

Unable to handle kernel paging request at virtual address ffffffff
pgd = c0018000
[ffffffff] *pgd=20002031, *pte=00000000, *ppte=00000000
Internal error: Oops: 813 [#1]
Modules linked in:
CPU: 0
PC is at free_block+0x90/0x178
LR is at 0xc026eee0
pc : [<c006fa30>]    lr : [<c026eee0>]    Not tainted

sp : c040fefc ip : c071f000 fp : c040ff2c
r10: 00000018 r9 : 00000000 r8 : 00000000
r7 : c0671960 r6 : c0410000 r5 : 00000018 r4 : c0410010 r3 : ffffffff r2 : ffffffff r1 : c071f01c r0 : c071f3e0
Flags: nzcv IRQs off FIQs on Mode SVC_32 Segment kernel
Control: C000717F
Table: 20018000 DAC: 00000017
Process events/0 (pid: 5, stack limit = 0xc040e258)

Stack: (0xc040fefc to 0xc0410000)

fee0: c071f01c
ff00: c0410010 c0410010 00000018 c0410000 c0671960 c01f68c4 00000000 00000000
ff20: c040ff4c c040ff30 c006fbc0 c006f9b0 c026eee0 c0671960 00000000 c01f68b8
ff40: c040ff7c c040ff50 c0071420 c006fb28 00000000 c040ff60 c067ada0 c00713c4
ff60: c040ffac c04012c0 00000000 00000000 c040ff94 c040ff80 c0043cd0 c00713d4
ff80: c067ada8 c067ada0 c040ffdc c040ff98 c0043e7c c0043c28 00000000 c04012c0
ffa0: c0047cb4 c040ffb8 c040ffb8 00000000 c04012c0 c0047cb4 c040ffb8 c040ffb8
ffc0: fffffffc c0043d60 00000000 00000000 c040fff4 c040ffe0 c00477e4 c0043d70
ffe0: 00000000 00000000 00000000 c040fff8 c00366a0 c00477a0 33cc33cc 33cc33cc

Backtrace: 
[<c006f9a0>] (free_block+0x0/0x178) from [<c006fbc0>] (drain_array+0xa8/0xd8)
[<c006fb18>] (drain_array+0x0/0xd8) from [<c0071420>] (cache_reap+0x5c/0x10c)
 r7:c01f68b8 r6:00000000 r5:c0671960 r4:c026eee0
[<c00713c4>] (cache_reap+0x0/0x10c) from [<c0043cd0>] (run_workqueue+0xb8/0x148)
[<c0043c18>] (run_workqueue+0x0/0x148) from [<c0043e7c>] (worker_thread+0x11c/0x130)
 r5:c067ada0 r4:c067ada8
[<c0043d60>] (worker_thread+0x0/0x130) from [<c00477e4>] (kthread+0x54/0x7c)
 r7:00000000 r6:00000000 r5:c0043d60 r4:fffffffc
[<c0047790>] (kthread+0x0/0x7c) from [<c00366a0>] (do_exit+0x0/0x74c)
 r5:00000000 r4:00000000
Code: e59c3000 e59c2004 e28c101c e50b1030 (e5823000) 

Here is log under 2.6.20:
at91_dataflash: AT45DB642 detected [spi0] (8650752 bytes) Creating 5 MTD partitions on "AT45DB642.spi0":
0x00738000-0x00840000 : "Dataflash" 0x00031800-0x00139800 : "kernel" 0x00139800-0x003cd800 : "initrd" 0x003cd800-0x00582c00 : "data1" 0x00582c00-0x00738000 : "data2"

cat /proc/mtd
dev: size erasesize name
mtd0: 00108000 00000420 "Dataflash"
mtd1: 00108000 00000420 "kernel"
mtd2: 00294000 00000420 "initrd"
mtd3: 001b5400 00000420 "data1"
mtd4: 001b5400 00000420 "data2"

mount -t jffs2 /dev/mtdblock/0 /mnt/dataflash/ JFFS2 write-buffering enabled buffer (1056) erasesize (8448) Empty flash at 0x000f825c ends at 0x000f8460

here flash contents under /mnt/dataflash gets listed.

Best regards,
Ivan

Sorry for long delay. I is not quite what I asked, but anyway, may you pleas apply the below patch, reproduce the problem and send me the result.

Please, do this faster if you can because I will need to disappear for about 2 weeks in a day. I will try to figure out what is going wrong, thanks.

index 4884d5e..c629c54 100644
@@ -761,7 +761,7 @@ static inline int read_dnode(struct jffs2_sb_info *c, struct jffs2_raw_node_ref
 			len = min_t(uint32_t, rdlen - sizeof(*rd), csize);
 			tn->partial_crc = crc32(0, buf, len);
 
-			dbg_readinode("Calculates CRC (%#08x) for %d bytes, csize %d\n", tn->partial_crc, len, csize);
+printk("Calculates CRC (%#08x) for %d bytes, csize %d\n", tn->partial_crc, len, csize);
 
 			/* If we actually calculated the whole data CRC
 			 * and it is wrong, drop the node. */

@@ -780,7 +780,7 @@ static inline int read_dnode(struct jffs2_sb_info *c, struct jffs2_raw_node_ref
 			 */
 			struct jffs2_eraseblock *jeb;
 
-			dbg_readinode("the node has no data.\n");
+printk("the node has no data.\n");
 			jeb = &c->blocks[ref->flash_offset / c->sector_size];
 			len = ref_totlen(c, jeb, ref);
 

@@ -919,7 +919,7 @@ static int read_more(struct jffs2_sb_info *c, struct jffs2_raw_node_ref *ref,
 	/* We need to read more data */
 	offs = ref_offset(ref) + *rdlen;
 
-	dbg_readinode("read more %d bytes\n", to_read);
+printk("read more %d bytes, needed_len %d\n", to_read, needed_len);
 
 	err = jffs2_flash_read(c, offs, to_read, &retlen, buf + *rdlen);
 	if (err) {

@@ -1004,7 +1004,7 @@ static int jffs2_get_inode_nodes(struct jffs2_sb_info *c, struct jffs2_inode_inf
 			len = end - ref_offset(ref);
 		}
 
-		dbg_readinode("read %d bytes at %#08x(%d).\n", len, ref_offset(ref), ref_flags(ref));
+printk("read %d bytes at %#08x(%d), wbuf sz %d\n", len, ref_offset(ref), ref_flags(ref), c->wbuf_pagesize);
 
 		/* FIXME: point() */
 		err = jffs2_flash_read(c, ref_offset(ref), len, &retlen, buf);

Best regards,
Artem Bityutskiy (Битюцкий Артём)

Here you go. I cut out a few bits that looked uninteresting as the whole log ended up at almost 150K. I can send you the whole log in private if you want it.

This is on an ATNGW100 board (AT32AP7000 AVR32 CPU) with AT45DB642D dataflash using the mtd_dataflash and atmel_spi drivers. I believe Ivan is using an AT91RM9200 ARM CPU with AT45DB642 dataflash using the at91_dataflash and at91_spi drivers.

The symptoms aren't always the same, but the "can not read -928 bytes" message always seems to appear before things start to go bad.

I have to go offline now, but I'll be back in about 11 hours.

Haavard

[root@uclibc ~]# mount -tjffs2 mtd3 /mnt
JFFS2 write-buffering enabled buffer (1056) erasesize (8448) read 480 bytes at 0x000240(2), wbuf sz 1056
read 592 bytes at 0x0001d0(2), wbuf sz 1056
read 708 bytes at 0x00015c(2), wbuf sz 1056
read 820 bytes at 0x0000ec(2), wbuf sz 1056
read 932 bytes at 0x00007c(2), wbuf sz 1056
read 1056 bytes at 0x000000(2), wbuf sz 1056
read 1004 bytes at 0x000034(0), wbuf sz 1056
read more -928 bytes, needed_len 68
JFFS2 error: (132) read_more: can not read -928 bytes from 0x00000420, error code: -22. JFFS2 error: (132) jffs2_do_read_inode_internal:
cannot read nodes for ino 2, returned error is -22 Returned error for crccheck of ino #2. Expect badness... read 172 bytes at 0x38bb74(2), wbuf sz 1056 read 308 bytes at 0x38baec(2), wbuf sz 1056 read 444 bytes at 0x38ba64(2), wbuf sz 1056
read 576 bytes at 0x38b9e0(2), wbuf sz 1056
read 712 bytes at 0x38b958(2), wbuf sz 1056

(...)

Calculates CRC (0x799298d3) for 56 bytes, csize 56
read 960 bytes at 0x019080(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0x53b0cfec) for 56 bytes, csize 56
read 468 bytes at 0x018e4c(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0x5a9364f2) for 495 bytes, csize 495
read 1056 bytes at 0x018c00(0), wbuf sz 1056
read more -928 bytes, needed_len 68
JFFS2 error: (132) read_more: can not read -928 bytes from 0x00019020, error code: -22. JFFS2 error: (132) jffs2_do_read_inode_internal:
cannot read nodes for ino 22, returned error is -22 Returned error for crccheck of ino #22. Expect badness... read 900 bytes at 0x0194dc(0), wbuf sz 1056 read more 128 bytes, needed_len 68
Calculates CRC (0x28639b3d) for 17 bytes, csize 17
read 768 bytes at 0x019560(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0x28639b3d) for 17 bytes, csize 17
read 632 bytes at 0x0195e8(0), wbuf sz 1056
read more 128 bytes, needed_len 68

(...)

Calculates CRC (0x2d452039) for 444 bytes, csize 609
read 1056 bytes at 0x021000(0), wbuf sz 1056
read more -928 bytes, needed_len 68
JFFS2 error: (132) read_more: can not read -928 bytes from 0x00021420, error code: -22. JFFS2 error: (132) jffs2_do_read_inode_internal:
cannot read nodes for ino 27, returned error is -22 Returned error for crccheck of ino #27. Expect badness... read 408 bytes at 0x02a708(0), wbuf sz 1056 read more 128 bytes, needed_len 68
Calculates CRC (0x9ba4c9bd) for 418 bytes, csize 418
read 616 bytes at 0x02a638(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0x9bc4f1c7) for 140 bytes, csize 140
read 740 bytes at 0x02a5bc(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0x2e3599f9) for 56 bytes, csize 56

(...)

read 384 bytes at 0x7bae00(0),
wbuf sz 1056 read more 128 bytes, needed_len 68
Calculates CRC (0xc9aba857) for 444 bytes, csize 474
JFFS2 notice: (132) check_node_data: wrong data CRC in data node at 0x007baf80: read 0x948a5877, calculated 0xdfc9dfd2. JFFS2 warning: (132) jffs2_do_read_inode_internal: no data nodes found for ino #292 Returned error for crccheck of ino #292. Expect badness... read 844 bytes at 0x7bb054(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0x3f1fdc46) for 431 bytes, csize 431
read 288 bytes at 0x7bb280(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0x780a4799) for 348 bytes, csize 455
JFFS2 notice: (132) check_node_data: wrong data CRC in data node at 0x007bb3a0: read 0x2d0e3614, calculated 0x714e0613. JFFS2 warning: (132) jffs2_do_read_inode_internal: no data nodes found for ino #294
Returned error for crccheck of ino #294. Expect badness...
read 764 bytes at 0x7bb4c4(0), wbuf sz 1056
read more 128 bytes, needed_len 68
Calculates CRC (0xd80c376) for 262 bytes, csize 262
Checked all inodes but still 0x792a58 bytes of unchecked space?
No space for garbage collection. Aborting GC thread

Haavard,

Thanks! Could you please try the below patch - it should help.

From: Artem Bityutskiy <[email protected]>
Date: Wed, 30 May 2007 12:08:14 +0300
Subject: [PATCH] JFFS2: fix readinode()

If we have already read enough bytes, no need to call read_more().

---
 fs/jffs2/readinode.c |    9 ++++++---
 1 files changed, 6 insertions(+), 3 deletions(-)

index 4884d5e..5663e8c 100644
@@ -1044,7 +1044,8 @@ static int jffs2_get_inode_nodes(struct jffs2_sb_info *c, struct jffs2_inode_inf
 
 		case JFFS2_NODETYPE_DIRENT:
 
-			if (JFFS2_MIN_NODE_HEADER < sizeof(struct jffs2_raw_dirent)) {
+			if (JFFS2_MIN_NODE_HEADER < sizeof(struct jffs2_raw_dirent) &&
+			    len < sizeof(struct jffs2_raw_dirent)) {
 				err = read_more(c, ref, sizeof(struct jffs2_raw_dirent), &len, buf);
 				if (unlikely(err))
 					goto free_out;

@@ -1058,7 +1059,8 @@ static int jffs2_get_inode_nodes(struct jffs2_sb_info *c, struct jffs2_inode_inf
 
 		case JFFS2_NODETYPE_INODE:
 
-			if (JFFS2_MIN_NODE_HEADER < sizeof(struct jffs2_raw_inode)) {
+			if (JFFS2_MIN_NODE_HEADER < sizeof(struct jffs2_raw_inode) &&
+			    len < sizeof(struct jffs2_raw_inode)) {
 				err = read_more(c, ref, sizeof(struct jffs2_raw_inode), &len, buf);
 				if (unlikely(err))
 					goto free_out;

@@ -1071,7 +1073,8 @@ static int jffs2_get_inode_nodes(struct jffs2_sb_info *c, struct jffs2_inode_inf
 			break;
 
 		default:
-			if (JFFS2_MIN_NODE_HEADER < sizeof(struct jffs2_unknown_node)) {
+			if (JFFS2_MIN_NODE_HEADER < sizeof(struct jffs2_unknown_node) &&
+			    len < sizeof(struct jffs2_unknown_node)) {
 				err = read_more(c, ref, sizeof(struct jffs2_unknown_node), &len, buf);
 				if (unlikely(err))
 					goto free_out;

1.5.0.6

-- 
Best regards,
Artem Bityutskiy (Битюцкий Артём)

It does. No more messages, the GC thread stays alive and I can execute binaries from the mount. Thanks!

Haavard

OK, good, now I do not understand how and why it worked on NAND ...

Best regards,
Artem Bityutskiy (Битюцкий Артём)

Confirmed for AT91RM9200 too, patch did a job - mounting ok.

Best regards,
Ivan

Reverting that patch made mtd_dataflash work again on my test rig. So this is clearly a JFFS2 regression. (Tested on at45db642b, ~8MB, 1056 byte pages.)

Seems to me this should be added to the "known regressions" list for RC3 ... I've added Michal to the CC list, ISTR he is now tracking such regressions.

I also added Andrew Victor to the CC, since he's the one who ISTR added Dataflash support to JFFS2 and thus might have quick insights to what this patch broke.

- Dave