Hi all
Since I moved my internal HD into a USB dock externally and mount the ext4
filesystem on it, I regularly get the following errors after it has been
mounted for a while (see timecode). It doesn't seem to matter which recent
kernel I use.
[1048401.773270] EXT4-fs (sde8): mounted filesystem with writeback data mode.
Opts: (null)
[1048702.736011] EXT4-fs (sde8): error count: 3
[1048702.736016] EXT4-fs (sde8): initial error at 1289053677:
ext4_journal_start_sb:251
[1048702.736018] EXT4-fs (sde8): last error at 1289080948: ext4_put_super:719
I've forced an fs check numerous times but nothing comes up. There was only
one occasion where the filesystem mounted RO but that was months ago and has
since been fine.
This does not appear to cause any actual problems and happens it seems at
_precisely_ the moment the hard drive decides to go into sleep mode as I hear
it spin down. hdparm is unable to extract details from the hard drive when it
is plugged into the usb dock.
The options used on this are as follows:
tune2fs 1.41.12 (17-May-2010)
Filesystem volume name: backup
Last mounted on: /media/backup
Filesystem UUID: 4eff5eb7-89fb-4db1-8cfd-f09db598a00b
Filesystem magic number: 0xEF53
Filesystem revision #: 1 (dynamic)
Filesystem features: has_journal ext_attr resize_inode dir_index filetype
needs_recovery extent flex_bg sparse_super large_file huge_file uninit_bg
dir_nlink extra_isize
Filesystem flags: signed_directory_hash
Default mount options: journal_data_writeback
Filesystem state: clean
Errors behavior: Continue
Filesystem OS type: Linux
Inode count: 22593536
Block count: 90355576
Reserved block count: 0
Free blocks: 30330219
Free inodes: 21828725
First block: 0
Block size: 4096
Fragment size: 4096
Reserved GDT blocks: 1002
Blocks per group: 32768
Fragments per group: 32768
Inodes per group: 8192
Inode blocks per group: 512
Flex block group size: 16
Filesystem created: Fri Jun 19 22:38:36 2009
Last mount time: Tue Dec 28 09:36:34 2010
Last write time: Tue Dec 28 09:36:34 2010
Mount count: 8
Maximum mount count: -1
Last checked: Sun Dec 19 21:50:05 2010
Check interval: 0 (<none>)
Lifetime writes: 1992 GB
Reserved blocks uid: 0 (user root)
Reserved blocks gid: 0 (group root)
First inode: 11
Inode size: 256
Required extra isize: 28
Desired extra isize: 28
Journal inode: 8
Default directory hash: half_md4
Directory Hash Seed: 5cdfe619-0de5-4bcd-85d2-5fa5f4f13da7
Journal backup: inode blocks
lsusb
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 005 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 007 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 006 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 002 Device 008: ID 046d:c70a Logitech, Inc. MX5000 Cordless Desktop
Bus 002 Device 007: ID 046d:c70e Logitech, Inc. MX1000 Bluetooth Laser Mouse
Bus 002 Device 006: ID 0424:2228 Standard Microsystems Corp. 9-in-2 Card
Reader
Bus 002 Device 005: ID 046d:0b02 Logitech, Inc. BT Mini-Receiver (HID proxy
mode)
Bus 002 Device 004: ID 04b8:012c Seiko Epson Corp. Perfection V350 (GT-F700)
Bus 002 Device 003: ID 0424:2602 Standard Microsystems Corp. USB 2.0 Hub
Bus 002 Device 002: ID 0424:2514 Standard Microsystems Corp. USB 2.0 Hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 1759:5000 LucidPort Technology, Inc.
Bus 001 Device 002: ID 1058:1100 Western Digital Technologies, Inc.
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
lspci
00:00.0 Host bridge: Intel Corporation 82P965/G965 Memory Controller Hub (rev
02)
00:01.0 PCI bridge: Intel Corporation 82P965/G965 PCI Express Root Port (rev
02)
00:1a.0 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI
Controller #4 (rev 02)
00:1a.1 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI
Controller #5 (rev 02)
00:1a.7 USB Controller: Intel Corporation 82801H (ICH8 Family) USB2 EHCI
Controller #2 (rev 02)
00:1b.0 Audio device: Intel Corporation 82801H (ICH8 Family) HD Audio
Controller (rev 02)
00:1c.0 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 1
(rev 02)
00:1c.3 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 4
(rev 02)
00:1c.4 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 5
(rev 02)
00:1d.0 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI
Controller #1 (rev 02)
00:1d.1 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI
Controller #2 (rev 02)
00:1d.2 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI
Controller #3 (rev 02)
00:1d.7 USB Controller: Intel Corporation 82801H (ICH8 Family) USB2 EHCI
Controller #1 (rev 02)
00:1e.0 PCI bridge: Intel Corporation 82801 PCI Bridge (rev f2)
00:1f.0 ISA bridge: Intel Corporation 82801HB/HR (ICH8/R) LPC Interface
Controller (rev 02)
00:1f.2 SATA controller: Intel Corporation 82801HB (ICH8) 4 port SATA AHCI
Controller (rev 02)
00:1f.3 SMBus: Intel Corporation 82801H (ICH8 Family) SMBus Controller (rev
02)
01:00.0 VGA compatible controller: nVidia Corporation G96 [GeForce 9400 GT]
(rev a1)
02:00.0 SATA controller: JMicron Technology Corp. JMB362/JMB363 Serial ATA
Controller (rev 02)
02:00.1 IDE interface: JMicron Technology Corp. JMB362/JMB363 Serial ATA
Controller (rev 02)
03:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168B PCI
Express Gigabit Ethernet controller (rev 01)
05:02.0 Multimedia video controller: Brooktree Corporation Bt878 Video Capture
(rev 11)
05:02.1 Multimedia controller: Brooktree Corporation Bt878 Audio Capture (rev
11)
Pointers would be appreciated, even if it's just "it's harmless, ignore it".
Thanks,
Con
--
-ck
On Tue, Dec 28, 2010 at 09:53:45AM +1100, Con Kolivas wrote:
>
> Since I moved my internal HD into a USB dock externally and mount the ext4
> filesystem on it, I regularly get the following errors after it has been
> mounted for a while (see timecode). It doesn't seem to matter which recent
> kernel I use.
>
> [1048401.773270] EXT4-fs (sde8): mounted filesystem with writeback data mode.
> Opts: (null)
> [1048702.736011] EXT4-fs (sde8): error count: 3
> [1048702.736016] EXT4-fs (sde8): initial error at 1289053677:
> ext4_journal_start_sb:251
> [1048702.736018] EXT4-fs (sde8): last error at 1289080948: ext4_put_super:719
That's actually not an error. It's a report which is generated every
24 hours, indicating that there has been 3 errors since the last time
the error count has been cleared, with the first error taking place at
Sat Nov 6 10:27:57 2010 (US/Eastern) in the function
ext4_journal_start_sb(), at line 251, and the most recent error taking
place at Sat Nov 6 18:02:28 2010 (US/Eastern), in the function
ext4_put_super() at line 719. This is a new feature which was added
in 2.6.36.
This information (which is stored in the ext4 superblock) gets cleared
by e2fsck version 1.41.13 or newer (1.41.14 is the most recently
released version). If you are using an older version of e2fsck, this
information won't get cleared, which is not a disaster, although it
could potentially get annoying. The solution is to simply to upgrade
to the newest version of e2fsprogs if you are using the 2.6.36 or
newer kernel.
The idea behind this feature is to make sure that if there was a file
system corruption detected, it wouldn't be lost due to log files
getting overflowed. It's also helpful when users report problems to
distribution support lines, since it makes it more likely support
personnel will be able to determine that there has been some file
system corrutpion issues, perhaps caused by hardware problems, or some
other cause, including kernel bugs.
Hope this helps explain what you're seeing!
- Ted
On Mon, Dec 27, 2010 at 09:53:43PM -0500, Ted Ts'o wrote:
> On Tue, Dec 28, 2010 at 09:53:45AM +1100, Con Kolivas wrote:
> > [1048401.773270] EXT4-fs (sde8): mounted filesystem with writeback data mode.
> > Opts: (null)
> > [1048702.736011] EXT4-fs (sde8): error count: 3
> > [1048702.736016] EXT4-fs (sde8): initial error at 1289053677:
> > ext4_journal_start_sb:251
> > [1048702.736018] EXT4-fs (sde8): last error at 1289080948: ext4_put_super:719
>
> That's actually not an error. It's a report which is generated every
> 24 hours, indicating that there has been 3 errors since the last time
> the error count has been cleared, with the first error taking place at
> Sat Nov 6 10:27:57 2010 (US/Eastern) in the function
> ext4_journal_start_sb(), at line 251, and the most recent error taking
> place at Sat Nov 6 18:02:28 2010 (US/Eastern), in the function
> ext4_put_super() at line 719. This is a new feature which was added
> in 2.6.36.
Nice. But the issue you're not mentioning is: What errors could have
happened on the 6th of november? Should Con worry about those errors?
OK, the chances are that he has rebooted since november, and that an
older fsck fixed the errors, but not cleared the "fs errror log". Would
these errors have triggered a "remount-readonly" if the fs was mounted
like that?
I don't reboot that often:
obelix:~> uptime
09:16:19 up 175 days, 19:04, 19 users, load average: 110.10, 110.61, 111.22
(and yes, the load is quite high on that machine. I won't polute this
thread about that....)
Roger.
--
** [email protected] ** http://www.BitWizard.nl/ ** +31-15-2600998 **
** Delftechpark 26 2628 XH Delft, The Netherlands. KVK: 27239233 **
*-- BitWizard writes Linux device drivers for any device you may have! --*
Q: It doesn't work. A: Look buddy, doesn't work is an ambiguous statement.
Does it sit on the couch all day? Is it unemployed? Please be specific!
Define 'it' and what it isn't doing. --------- Adapted from lxrbot FAQ
On Tue, 28 Dec 2010 19:19:17 Rogier Wolff wrote:
> On Mon, Dec 27, 2010 at 09:53:43PM -0500, Ted Ts'o wrote:
> > On Tue, Dec 28, 2010 at 09:53:45AM +1100, Con Kolivas wrote:
> > > [1048401.773270] EXT4-fs (sde8): mounted filesystem with writeback data
> > > mode. Opts: (null)
> > > [1048702.736011] EXT4-fs (sde8): error count: 3
> > > [1048702.736016] EXT4-fs (sde8): initial error at 1289053677:
> > > ext4_journal_start_sb:251
> > > [1048702.736018] EXT4-fs (sde8): last error at 1289080948:
> > > ext4_put_super:719
> >
> > That's actually not an error. It's a report which is generated every
> > 24 hours, indicating that there has been 3 errors since the last time
> > the error count has been cleared, with the first error taking place at
> > Sat Nov 6 10:27:57 2010 (US/Eastern) in the function
> > ext4_journal_start_sb(), at line 251, and the most recent error taking
> > place at Sat Nov 6 18:02:28 2010 (US/Eastern), in the function
> > ext4_put_super() at line 719. This is a new feature which was added
> > in 2.6.36.
>
> Nice. But the issue you're not mentioning is: What errors could have
> happened on the 6th of november? Should Con worry about those errors?
>
> OK, the chances are that he has rebooted since november, and that an
> older fsck fixed the errors, but not cleared the "fs errror log". Would
> these errors have triggered a "remount-readonly" if the fs was mounted
> like that?
Indeed the FS was remounted as RO at the time. I had to power down the USB
device and power it up again after umounting the FS and then doing an FSCK
before it was usable again, and the machine had about a month of uptime when
it happened. It has not caused a problem since.
Thanks,
Con
--
-ck
On Tue, Dec 28, 2010 at 10:19 AM, Rogier Wolff <[email protected]> wrote:
> On Mon, Dec 27, 2010 at 09:53:43PM -0500, Ted Ts'o wrote:
>> On Tue, Dec 28, 2010 at 09:53:45AM +1100, Con Kolivas wrote:
>> > [1048401.773270] EXT4-fs (sde8): mounted filesystem with writeback data mode.
>> > Opts: (null)
>> > [1048702.736011] EXT4-fs (sde8): error count: 3
>> > [1048702.736016] EXT4-fs (sde8): initial error at 1289053677:
>> > ext4_journal_start_sb:251
>> > [1048702.736018] EXT4-fs (sde8): last error at 1289080948: ext4_put_super:719
>>
>> That's actually not an error. ?It's a report which is generated every
>> 24 hours, indicating that there has been 3 errors since the last time
>> the error count has been cleared, with the first error taking place at
>> Sat Nov 6 10:27:57 2010 (US/Eastern) in the function
>> ext4_journal_start_sb(), at line 251, and the most recent error taking
>> place at Sat Nov 6 18:02:28 2010 (US/Eastern), in the function
>> ext4_put_super() at line 719. ?This is a new feature which was added
>> in 2.6.36.
>
> Nice. But the issue you're not mentioning is: What errors could have
> happened on the 6th of november? Should Con worry about those errors?
>
Ted,
I would like to use this opportunity to remind you about my
record_journal_errstr()
implementation, see:
https://github.com/amir73il/ext4-snapshots/blob/next3-stable/fs/next3/super.c#L157
It records the initial errors messages (which I found to be the most
interesting),
in a message buffer on the unused space after the journal super block
(3K on a 4K block fs).
fsck prints out those messages and clears the buffer.
In under a year of Next3 fs in beta and production, it has helped me many times
to analyse bugs post-mortem and find the problem.
If there is demand, I can post the patch for Ext4.
Amir.
> OK, the chances are that he has rebooted since november, and that an
> older fsck fixed the errors, but not cleared the "fs errror log". Would
> these errors have triggered a "remount-readonly" if the fs was mounted
> like that?
>
> I don't reboot that often:
>
> obelix:~> uptime
> ?09:16:19 up 175 days, 19:04, 19 users, ?load average: 110.10, 110.61, 111.22
>
> (and yes, the load is quite high on that machine. I won't polute this
> thread about that....)
>
> ? ? ? ?Roger.
>
> --
> ** [email protected] ** http://www.BitWizard.nl/ ** +31-15-2600998 **
> ** ? ?Delftechpark 26 2628 XH ?Delft, The Netherlands. KVK: 27239233 ? ?**
> *-- BitWizard writes Linux device drivers for any device you may have! --*
> Q: It doesn't work. A: Look buddy, doesn't work is an ambiguous statement.
> Does it sit on the couch all day? Is it unemployed? Please be specific!
> Define 'it' and what it isn't doing. --------- Adapted from lxrbot FAQ
> --
> To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
> the body of a message to [email protected]
> More majordomo info at ?http://vger.kernel.org/majordomo-info.html
>
On 12/28/2010 03:53 AM, Ted Ts'o wrote:
> On Tue, Dec 28, 2010 at 09:53:45AM +1100, Con Kolivas wrote:
>
>> Since I moved my internal HD into a USB dock externally and mount the ext4
>> filesystem on it, I regularly get the following errors after it has been
>> mounted for a while (see timecode). It doesn't seem to matter which recent
>> kernel I use.
>>
>> [1048401.773270] EXT4-fs (sde8): mounted filesystem with writeback data mode.
>> Opts: (null)
>> [1048702.736011] EXT4-fs (sde8): error count: 3
>> [1048702.736016] EXT4-fs (sde8): initial error at 1289053677:
>> ext4_journal_start_sb:251
>> [1048702.736018] EXT4-fs (sde8): last error at 1289080948: ext4_put_super:719
>>
> That's actually not an error. It's a report which is generated every
> 24 hours, indicating that there has been 3 errors since the last time
> the error count has been cleared, with the first error taking place at
> Sat Nov 6 10:27:57 2010 (US/Eastern) in the function
> ext4_journal_start_sb(), at line 251, and the most recent error taking
> place at Sat Nov 6 18:02:28 2010 (US/Eastern), in the function
> ext4_put_super() at line 719. This is a new feature which was added
> in 2.6.36.
>
This is going to be a faq...
I suppose the datetime is encoded (what format is that?) in that long
number after "at".
May I suggest the datetime gets decoded in the printing?
Also may I suggest that the error happens immediately after mount and
not after 300 seconds from mount?
I just subscribed to this list exactly to report the same kind of error.
Last week I was doing reliability tests for open-iscsi and this error
drove me crazy. I spent days in tests where I thought I could reproduce
an error in open-iscsi by disconnecting and reconnecting the network; I
even reported this to the open-iscsi mailing list, but in fact it was an
old error of the filesystem and it was not getting cleared by my older
e2fsck 1.41.11 .
If that happened immediately after mount or if it spitted the datetime
in human readable format, I would have immediately guessed it was due to
an existing "filesystem problem" (even though I was running fsck.ext4 -f
prior to each mount) but instead I thought it was due to my 5 minutes of
"networks disconnection tests" I was doing after each mount. DOH!
Anyway thanks for your work: excellent filesystem.
PS: I have a question for you regarding ext4 behaviour with SCSI
commands resubmissions... ok I am opening another thread for that.
On Tue, Dec 28, 2010 at 11:41:53AM +0100, torn5 wrote:
>
> This is going to be a faq...
> I suppose the datetime is encoded (what format is that?) in that
> long number after "at".
Number of seconds since January 1st, 1970 midnight GMT. (Standard
Unix-time format). It's hard for the kernel to decode it since it
doesn't know what time-zone you are in, or what your local legislature
has done vis-a-vis arbitrary and cabritious adjustments to the
start/stop date of daylight savings time, etc.
It's easy enough to decode it using perl:
perl -e '$t = localtime(1289053677); print "$t\n"'
> May I suggest the datetime gets decoded in the printing?
> Also may I suggest that the error happens immediately after mount
> and not after 300 seconds from mount?
Hmmm.... maybe. The idea behind the 300 second delay was for the root
file system, to let e2fsck have a chance to fix the file system before
reporting the errors at mount time.
- Ted
On Tue, Dec 28, 2010 at 09:19:17AM +0100, Rogier Wolff wrote:
> > That's actually not an error. It's a report which is generated every
> > 24 hours, indicating that there has been 3 errors since the last time
> > the error count has been cleared, with the first error taking place at
> > Sat Nov 6 10:27:57 2010 (US/Eastern) in the function
> > ext4_journal_start_sb(), at line 251, and the most recent error taking
> > place at Sat Nov 6 18:02:28 2010 (US/Eastern), in the function
> > ext4_put_super() at line 719. This is a new feature which was added
> > in 2.6.36.
>
> Nice. But the issue you're not mentioning is: What errors could have
> happened on the 6th of november? Should Con worry about those errors?
It looks like those errors were probably caused by I/O errors while
writing to the journal. Maybe due to a flakey USB connection,
perhaps? It would be useful to look at the /var/log/messagfes around
that date to get a more detailed look.
> OK, the chances are that he has rebooted since november, and that an
> older fsck fixed the errors, but not cleared the "fs errror log". Would
> these errors have triggered a "remount-readonly" if the fs was mounted
> like that?
Yes, errors that get recorded into the superblock are also errors that
would cause a read-only remount if the file system is set that way.
- Ted
Ted Ts'o <[email protected]> writes:
> On Tue, Dec 28, 2010 at 11:41:53AM +0100, torn5 wrote:
>>
>> This is going to be a faq...
>> I suppose the datetime is encoded (what format is that?) in that
>> long number after "at".
>
> Number of seconds since January 1st, 1970 midnight GMT. (Standard
> Unix-time format). It's hard for the kernel to decode it since it
> doesn't know what time-zone you are in, or what your local legislature
> has done vis-a-vis arbitrary and cabritious adjustments to the
> start/stop date of daylight savings time, etc.
>
> It's easy enough to decode it using perl:
>
> perl -e '$t = localtime(1289053677); print "$t\n"'
The "date" program can decode these values too:
date -d @1289053677
--
Ben Pfaff
http://benpfaff.org
On 12/28/2010 03:32 PM, Ted Ts'o wrote:
> On Tue, Dec 28, 2010 at 11:41:53AM +0100, torn5 wrote:
>
>> This is going to be a faq...
>> I suppose the datetime is encoded (what format is that?) in that
>> long number after "at".
>>
> Number of seconds since January 1st, 1970 midnight GMT. (Standard
> Unix-time format). It's hard for the kernel to decode it since it
> doesn't know what time-zone you are in, or what your local legislature
> has done vis-a-vis arbitrary and cabritious adjustments to the
> start/stop date of daylight savings time, etc.
>
I suggest to decode it in GMT then.
Like this it's not possible to guess it's a "time" value, and hence that
it's an *old* error. I thought it was a pointer to something, and so I
thought the error was happening now, or more likely (since it was
triggered after 300 seconds) that it was some inconsistency in the
filesystem being detected now, in some kind of lazy check.