Created attachment 38232 [details]
kernel panic from a digital cam point of view

Just to clarify the nodelalloc on the screenshot: it was just a try to pass it mount, to see what's going on when some parameter will be passed.

Hmm.... is this panic repeatable?

And can you send me the first 4k of the filesystem?  i.e., do a "dd if=/dev/dsk/by-label/MyBook of=/tmp/sb.img bs=4k count=1" and then attach /tmp/sb.img to this bug?

Thanks,

-- Ted

Created attachment 38252 [details]
first 4k of the filesystem dumped with dd

(In reply to comment #3)
> Hmm.... is this panic repeatable?

yes, it occurs always, just a few seconds after mount.

> And can you send me the first 4k of the filesystem?  i.e., do a "dd
> if=/dev/dsk/by-label/MyBook of=/tmp/sb.img bs=4k count=1" and then attach
> /tmp/sb.img to this bug?

uploaded

> Thanks,
> 
> -- Ted

Thanks,
Freddy

Ooops, sorry, I needed the block #1 of the file system, which means I need the first two 4k blocks....   so could you send me:

dd if=/dev/dsk/by-label/MyBook of=/tmp/sb.img bs=4k count=2

... and send attach the revised sb.img file.

Many thanks!!

Created attachment 38262 [details]
first 2 blocks of the filesystem dumped with dd

(In reply to comment #6)
> Ooops, sorry, I needed the block #1 of the file system, which means I need
> the
> first two 4k blocks....   so could you send me:
> 
> dd if=/dev/dsk/by-label/MyBook of=/tmp/sb.img bs=4k count=2
> 
> ... and send attach the revised sb.img file.

uploaded

> Many thanks!!

no problem!

Stale data on disk being picked up as mount options after

8b67f04ab9de5d8f3a71aef72bf02c995a506db5 ext4: Add mount options in superblock

perhaps?

Well, one question is how did the stale data get put there in the first place?  The entire superblock is zero'ed out by mke2fs.

This will be probably hard, because I have no idea what mkfs version was used to create the filesystem.

I there is a way to fix it on the user space side?

I don't know for sure if there is, because I don't yet know what the problem is.

Could you provide an e2image -r (bzipped up) (in private if you like) and I can see if I can reproduce it?

-Eric

(In reply to comment #10)
> Well, one question is how did the stale data get put there in the first
> place? 
> The entire superblock is zero'ed out by mke2fs.

The s_mount_options field has the unfortunate distinction of being the first field beyond 0x200 in the superblock (i.e. second sector of 1kB superblock area).  This means it could have been corrupted at some time in the past by an incomplete write or similar, and no e2fsck will have checked/fixed this.

Looking at the 'dd' output, it is clear that both the area before and after the 512-bytes of the original superblock were clobbered by 0xffff data at one time or another, and I suspect the superblock was rewritten from a backup copy but only the first sector was written to disk.

(In reply to comment #12)
> I there is a way to fix it on the user space side?

Fairly simple, for this specific case.  It should overwrite the 512-byte area beyond the superblock with zeroes:

dd if=/dev/zero of=/dev/dsk/by-label/MyBook bs=512 count=1 seek=3 skip=3

That said, I don't know how common or unusual this kind of garbage data is in this area of the filesystem.  It might make sense that errors parsing of the s_mount_options field is not taken as a fatal error at mount time, since this can make a system unbootable, and no e2fsck will fix it.

For e2fsck, it probably makes sense to limit the data in s_mount_opts to printable ASCII characters, and otherwise zero out any remaining data.  I'm not sure what to do for the rest of the superblock, however.

Should e2fsck zero out that data if s_mount_opts is found to be bad?  Should we wait until every field is defined, and then fix them on a case-by-case basis?  The former is preferable because otherwise it means the kernel can never start using any of these fields without e2fsck having verified the content first, but it has the drawback that any corruption just to s_mount_opts may wipe out the rest of the superblock.

In that regard, it would have been preferable to locate the "s_first_error" and "s_last_error" fields near the end of the 1kB superblock range, instead of quickly consuming the rest of the space in the first sector (which we know will be written atomically), which is why it would be nice if such changes were discussed and reviewed on the mailing list rather than being presented as a fait-accompli in some kernel update and/or e2fsprogs release.

(In reply to comment #14)
> (In reply to comment #12)
> > I there is a way to fix it on the user space side?
> 
> Fairly simple, for this specific case.  It should overwrite the 512-byte area
> beyond the superblock with zeroes:
> 
> dd if=/dev/zero of=/dev/dsk/by-label/MyBook bs=512 count=1 seek=3 skip=3

that did the trick! Many thanks Andreas!

It works now:
Nov 30 18:00:07 aquarius kernel: EXT4-fs (sdb1): mounted filesystem with writeback data mode. Opts: (null)

...but after 5 min. kernel logs a nasty message:

Nov 30 18:05:07 aquarius kernel: EXT4-fs (sdb1): error count: 4294967295
Nov 30 18:05:07 aquarius kernel: EXT4-fs (sdb1): initial error at 4294967295: ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ:-1: inode 4294967295: block 18446744073709551615
Nov 30 18:05:07 aquarius kernel: EXT4-fs (sdb1): last error at 4294967295: ÿÿÿÿÿÿÿÿÿÿÿÿÿÿ:-1: inode 4294967295: block 18446744073709551615

Something is scribbling on / has scribbled on the front of your filesystem, it seems.

hexdumping the first 2 blocks you sent:

00000580  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
*
000005e0  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff 0f 00  |................|
000005f0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000600  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
*
00000660  ff ff ff ff ff ff ff 01  00 00 00 00 00 00 00 00  |................|
00000670  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000680  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
*
000006e0  ff ff ff ff ff ff ff ff  0f 00 00 00 00 00 00 00  |................|
00000580  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
*
000005e0  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff 0f 00  |................|
000005f0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000600  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
*
00000660  ff ff ff ff ff ff ff 01  00 00 00 00 00 00 00 00  |................|
00000670  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000680  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
*
000006e0  ff ff ff ff ff ff ff ff  0f 00 00 00 00 00 00 00  |................|
000006f0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000700  ff ff ff ff 7f 00 00 00  00 00 00 00 00 00 00 00  |................|
00000710  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|


superblock starts at 0x400; so here we are at offset 0x180 to 0x310 in the sb.

There's a lot of "-1" (0xff) in there with a few other values.  This translates into the "4294967295" values you see above.

The various error tracking bits are in this part of the superblock so you're seeing the -1/4294967295 pop out in the error reporting code:

 	__le32	s_error_count;		/* number of fs errors */
 	__le32	s_first_error_time;	/* first time an error happened */
 	__le32	s_first_error_ino;	/* inode involved in first error */
/*1a0*/	__le64	s_first_error_block;	/* block involved of first error */
/*1a8*/	__u8	s_first_error_func[32];	/* function where the error happened */
/*1c8*/	__le32	s_first_error_line;	/* line number where error happened */
 	__le32	s_last_error_time;	/* most recent time of an error */
/*1d0*/	__le32	s_last_error_ino;	/* inode involved in last error */
 	__le32	s_last_error_line;	/* line number where error happened */
 	__le64	s_last_error_block;	/* block involved of last error */
/*1e0*/	__u8	s_last_error_func[32];	/* function where the error happened */

Your dd above should have zeroed this out, though, which makes me wonder how you got 1's back in here.  It could be anything, though I wonder if it's possible that it's a stray bitmap....

What kind of storage is this?

(In reply to comment #17)
> Something is scribbling on / has scribbled on the front of your filesystem,
> it
> seems.

I think/hope this is all old garbage that e2fsck has never cared about fixing.

> The various error tracking bits are in this part of the superblock so you're
> seeing the -1/4294967295 pop out in the error reporting code:

Right, and while it will be annoying to get this printed every day, it doesn't actually hurt any operation of the filesystem.
 
> Your dd above should have zeroed this out, though, which makes me wonder how
> you got 1's back in here.  It could be anything, though I wonder if it's
> possible that it's a stray bitmap....

No, my "dd" command only zeroed out the second half of the superblock (starting at 0x600, the s_mount_opts field.  It didn't touch the "error" parts of the superblock, for simplicity/safety.  It should be possible to zero out these fields, even from userspace on a mounted filesystem, since the superblock is direct-mapped to the buffer.  Whether you do this depends on whether the annoyance of the error message is higher than the risk that the following command might clobber your filesystem (which of course I hope it doesn't):

dd if=/dev/zero of=/dev/dsk/by-label/MyBook bs=1 seek=0x17c skip=0x17c count=0x84

(In reply to comment #17)
> Something is scribbling on / has scribbled on the front of your filesystem,
> it
> seems.

"is scribbling" is the right one. After doing a dd once more, just after error msg, the file system was altered (compared visually in text editor). 

> What kind of storage is this?

external usb disk by western digital:
# skdump /dev/disk/by-label/MyBook
Device: sat12:/dev/disk/by-label/MyBook
Type: 12 Byte SCSI ATA SAT Passthru
Size: 305242 MiB
Model: [WDC WD3200AAKS-00SBA0]
Serial: [WD-WCAPZ2842083]
Firmware: [12.01B01]
SMART Available: yes

Unfortunately, the oops is back. Tried to run fsck -f on the unlucky partition causes a hard lockup (only reset helps). For this time, it was something with
ext4_msg, I will do a screenshot tomorrow.

(In reply to comment #18)


> > Your dd above should have zeroed this out, though, which makes me wonder
> how
> > you got 1's back in here.  It could be anything, though I wonder if it's
> > possible that it's a stray bitmap....
> 
> No, my "dd" command only zeroed out the second half of the superblock
> (starting
> at 0x600, the s_mount_opts field.  It didn't touch the "error" parts of the
> superblock, for simplicity/safety.

Oh, sorry, I just assumed.  Thanks for the clarification.

-Eric