ext4 complete session data loss - openSUSE 12.3

keithtynan · October 28, 2015, 9:53pm

Symptoms
Occasionally (11 times in the last 6 months, but more frequently in the last 2 months) I discover that a complete session’s worth of data has not been written back to the disc. This extends from system files (e.g. /var/log/messages will have a gap) to application files (e.g. emails, edits are lost) and includes all users during that session.

I normally run 1 session per day, so in effect, a complete day’s data is lost.

The sessions that have lost all of their data have been running for several hours and terminate normally (i.e. no system crash or power fail).

Configuration
O/s=openSUSE 12.3
Disc type=SATA-3 6Gb/s 600MB/s 1TB HDD
Partition 1=swap space on /dev/sda1 as swap
Partition 2=root (/) on /dev/sda2 as ext4
Subdirectories=61661
Files=726899
Max. file size=140737486266368=128TB=/proc/kcore
(next largest=84343583232=78.5GB)
The configuration is 3.5 years old.

Attempted remedy
Sometimes, if aware of the loss, I can recover the last two lost sessions by forcing an fsck next time the machine is booted ([FONT=courier new]root> [/FONT]touch /forcefsck). This seems to have the side-effect that data from the current session (i.e. the one from which the ‘touch’ is issued) is lost.

I have tried forcing fsck on a regular basis by two mechanisms:

root> sudo tune2fs -c 1 /dev/sda2
YaST.BootLoader.grub2BootLoaderOptions.OptionalKernelCommandLineParameter> <string +> [FONT=courier new]fsck.mode=force[/FONT]

I have also tried configuring ext4 to write immediately to disc (removing delayed allocation), by adding the following qualifier to the device definition in /etc/fstab via YaST:
YaST.Software.Partitioner.HardDisk.sda2.Edit.fstabOptions> ArbitraryOptionValue=[FONT=courier new]nodelalloc[/FONT]
Data loss re-occurred with mechanism 1) in place.
I‘ve only just set up mechanism 2), so I don’t have any evidence for its effectiveness.

Diagnosis
Due to the fact that I can ‘restore’ my lost data by running fsck, I conclude that this restoration is coming from the ext4 journal and therefore does not indicate a fault with the disc drive (do you agree?).

My steps to remove delayed allocation do not appear to have solved the problem; the symptoms have continued since I did this.

Doing an fsck at every boot is a repair strategy and therefore not satisfactory; I want to be able to prevent the fault in the first place.

I’m at a loss with this and would welcome any help.

Regards

gogalthorp · October 28, 2015, 10:42pm

How are you shutting down? Sounds like the correct procedure is not being taken. Typically what you describe happens if you simply shut off the power.

sync is a command line option that forces the memory caches and I also think the journal

keithtynan · October 29, 2015, 8:53pm

I use KDE 4.10.5 and shut down using:
Kickoff Application Launcher -> Leave -> Shutdown
every time.
(On the rare occasions when this hangs, I shutdown using root> shutdown now.)

I can categorically state that data loss hass occurred when I’ve shut down using the ‘normal’ action through Kickoff.

Since this problem has become more frequent, I now tend to logoff all users, then shut down using the ‘power’ icon on the KDE login window…

knurpht · October 30, 2015, 9:29am

First of all: openSUSE 12.3 is past it’s end-of-life, you should upgrade to a more recent version. I suggest you wait a couple of days doing so, and install LEAP 42.1 ( released on 5th of November ). Not many of us here will still have 12.3 running on their systems.

But, I have my doubts this is an openSUSE or even a linux problem, if I were you I’d seriously investigate the hardware, i.e. the disk. Look at the output of dmesg f.e.

Another thing: if you post output, please post it between CODE tags, it’s the # in the editor header.

gogalthorp · October 30, 2015, 4:44pm

Run smartctl to see the health of the drive itself.

keithtynan · October 30, 2015, 9:33pm

Thanks for the replies people.

Helpful though your suggestions are, I fail to see how, in these data loss cases, nothing is written (or at least appears to have been written) to the hard disc in the space of several hours of operation. I can accept that there may be delayed allocation, but really, still delayed after several hours?

Knurpht> First of all: openSUSE 12.3 is past it’s end-of-life, you should upgrade to a more recent version.

I run 13.2 in a VirtualBox guest, but have kept my host at 12.3 for ease of maintenance.

Knurpht> I have my doubts this is an openSUSE or even a linux problem, if I were you I’d seriously investigate the hardware, i.e. the disk.

Yes, but replacing the disc without knowing the nature ofproblem is a bit ‘sledgehammer to a nut’, wouldn’t you agree?

gogalthorp> Run smartctl to see the health of the drive itself.

I ran it once and it indicated no self tests, so I then ran a short test, then a long test. Output follows:

pegasus:~ # smartctl --all /dev/sda2
smartctl 6.0 2012-10-10 r3643 [x86_64-linux-3.7.10-1.45-desktop] (SUSE RPM)
Copyright (C) 2002-12, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family:     Seagate Barracuda 7200.14 (AF)
Device Model:     ST1000DM003-9YN162
Serial Number:    S1D1AVZZ
LU WWN Device Id: 5 000c50 04adb7904
Firmware Version: CC4D
User Capacity:    1,000,204,886,016 bytes [1.00 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    7200 rpm
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ATA8-ACS T13/1699-D revision 4
SATA Version is:  SATA 3.0, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Fri Oct 30 19:30:50 2015 GMT

==> WARNING: A firmware update for this drive may be available,
see the following Seagate web pages:
http://knowledge.seagate.com/articles/en_US/FAQ/207931en
http://knowledge.seagate.com/articles/en_US/FAQ/223651en

SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x00) Offline data collection activity
                                        was never started.
                                        Auto Offline Data Collection: Disabled.
Self-test execution status:      (   0) The previous self-test routine completed
                                        without error or no self-test has ever 
                                        been run.
Total time to complete Offline 
data collection:                (  575) seconds.
Offline data collection
capabilities:                    (0x73) SMART execute Offline immediate.
                                        Auto Offline data collection on/off support.
                                        Suspend Offline collection upon new
                                        command.
                                        No Offline surface scan supported.
                                        Self-test supported.
                                        Conveyance Self-test supported.
                                        Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                                        power-saving mode.
                                        Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                                        General Purpose Logging supported.
Short self-test routine 
recommended polling time:        (   1) minutes.
Extended self-test routine
recommended polling time:        ( 109) minutes.
Conveyance self-test routine
recommended polling time:        (   2) minutes.
SCT capabilities:              (0x3085) SCT Status supported.

SMART Attributes Data Structure revision number: 10
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000f   108   099   006    Pre-fail  Always       -       18046632
  3 Spin_Up_Time            0x0003   097   097   000    Pre-fail  Always       -       0
  4 Start_Stop_Count        0x0032   099   099   020    Old_age   Always       -       1348
  5 Reallocated_Sector_Ct   0x0033   100   100   036    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000f   064   053   030    Pre-fail  Always       -       120353716702
  9 Power_On_Hours          0x0032   092   092   000    Old_age   Always       -       7536
 10 Spin_Retry_Count        0x0013   100   100   097    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   099   099   020    Old_age   Always       -       1348
183 Runtime_Bad_Block       0x0032   100   100   000    Old_age   Always       -       0
184 End-to-End_Error        0x0032   100   100   099    Old_age   Always       -       0
187 Reported_Uncorrect      0x0032   100   100   000    Old_age   Always       -       0
188 Command_Timeout         0x0032   100   099   000    Old_age   Always       -       0 0 3
189 High_Fly_Writes         0x003a   085   085   000    Old_age   Always       -       15
190 Airflow_Temperature_Cel 0x0022   064   052   045    Old_age   Always       -       36 (Min/Max 22/40)
191 G-Sense_Error_Rate      0x0032   100   100   000    Old_age   Always       -       0
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always       -       41
193 Load_Cycle_Count        0x0032   046   046   000    Old_age   Always       -       109913
194 Temperature_Celsius     0x0022   036   048   000    Old_age   Always       -       36 (0 17 0 0 0)
197 Current_Pending_Sector  0x0012   100   100   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0010   100   100   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x003e   200   200   000    Old_age   Always       -       0
240 Head_Flying_Hours       0x0000   100   253   000    Old_age   Offline      -       6910h+45m+13.337s
241 Total_LBAs_Written      0x0000   100   253   000    Old_age   Offline      -       102207197928576
242 Total_LBAs_Read         0x0000   100   253   000    Old_age   Offline      -       81647700048631

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%      7535         -
# 2  Short offline       Completed without error       00%      7533         -

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.

pegasus:~ #

That seems to suggest there are no permanent faults with the partition/disc and what I’m seeing are intermittent faults?

Knurpht> Look at the output of dmesg f.e.

I’ve run that, but don’t see anything that shouts ‘disc fault’ to me. This bit looks relevant, is there anything else you’d like to see?


   57.989243] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: acl,user_xattr
   58.239061] EXT4-fs (sda2): re-mounted. Opts: acl,user_xattr,nodelalloc
   58.842955] systemd[1]: systemd 195 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ; suse)
   59.036144] systemd[1]: Inserted module 'autofs4'
   59.052897] systemd[1]: Set hostname to <pegasus.TYNANCHEW>.
   59.459014] systemd[1]: Starting Collect Read-Ahead Data...
   59.464380] systemd[1]: Starting Replay Read-Ahead Data...
   59.471345] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
   59.471392] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
   59.471407] systemd[1]: Starting Syslog Socket.
   59.471449] systemd[1]: Listening on Syslog Socket.
   59.471460] systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
   59.471483] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
   59.471491] systemd[1]: Starting Delayed Shutdown Socket.
   59.471513] systemd[1]: Listening on Delayed Shutdown Socket.
   59.471522] systemd[1]: Starting Encrypted Volumes.
   59.471537] systemd[1]: Reached target Encrypted Volumes.
   59.471552] systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point.
   59.471624] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
   59.471663] systemd[1]: Starting udev Kernel Socket.
   59.471687] systemd[1]: Listening on udev Kernel Socket.
   59.471717] systemd[1]: Starting udev Control Socket.
   59.471741] systemd[1]: Listening on udev Control Socket.
   59.471750] systemd[1]: Expecting device dev-disk-by\x2did-ata\x2dST1000DM003\x2d9YN162_S1D1AVZZ\x2dpart1.device...
   59.471767] systemd[1]: Starting Journal Socket.
   59.471800] systemd[1]: Listening on Journal Socket.
   59.471815] systemd[1]: Mounting Huge Pages File System...
   59.472066] systemd-readahead[272]: Bumped block_nr parameter of 8:0 to 20480. This is a temporary hack and should be removed one day.
   59.477247] systemd[1]: Mounting POSIX Message Queue File System...
   59.480342] systemd[1]: Starting Create dynamic rule for /dev/root link...
   59.487268] systemd[1]: Starting Journal Service...
   59.490229] systemd[1]: Started Journal Service.
   59.490358] systemd[1]: Starting LSB: Set default boot entry if called...
   59.492788] systemd[1]: Started Collect Read-Ahead Data.
   59.492920] systemd[1]: Started Replay Read-Ahead Data.
   59.510391] systemd[1]: Starting Load Kernel Modules...
   59.512142] systemd[1]: Starting Setup Virtual Console...
   59.523414] systemd[1]: Started Set Up Additional Binary Formats.
   59.523455] systemd[1]: Started File System Check on Root Device.
   59.523473] systemd[1]: Starting Remount Root and Kernel File Systems...
   60.703620] systemd-udevd[294]: starting version 195
   60.744210] EXT4-fs (sda2): re-mounted. Opts: acl,user_xattr,nodelalloc

gogalthorp · October 30, 2015, 10:00pm

In a properly set up OS shut down should commit all caches and journals. If you start up and have to run fsck and that restores the data that tells that the data was written to the disk but the disk was not shut down properly and it remains in the journal . Anything in memory is lost when power is off.

exactly how are you actually running fsck because it will not correct anything if run on a mounted file system??? Also with some programs if you do not explicitly save the data will not be written if you just shut things down.

You no there is NO maintenance for 12.3 any more for some time now. So no bug fixes or updates or security fixes.

I have to admit I have never heard of anything like this if the shut down is correct and you running 12.3 make trouble shooting hard.

keithtynan · November 1, 2015, 6:22pm

Agreed.

I run fsck (or at lest, I think I run fsck) via the boot loader prior to mounting root:
YaST -> BootLoader -> GRUB2 BootLoaderOptions -> OptionalKernelCommandLineParameter -> …fsck.mode=force

2015-11-01T09:01:09.943633+00:00 pegasus rsyslogd: [origin software="rsyslogd" swVersion="7.2.7" x-pid="670" x-info="http://www.rsyslog.com"] start

 2015-11-01T09:01:09.943654+00:00 pegasus systemd[1]: Started Collect Read-Ahead Data.
 2015-11-01T09:01:09.944088+00:00 pegasus kernel:     0.000000] Initializing cgroup subsys cpuset
 2015-11-01T09:01:09.944099+00:00 pegasus systemd[1]: Started Replay Read-Ahead Data.
 2015-11-01T09:01:09.944095+00:00 pegasus kernel:     0.000000] Initializing cgroup subsys cpu
 2015-11-01T09:01:09.944109+00:00 pegasus systemd[1]: Starting Load Kernel Modules...
 2015-11-01T09:01:09.944116+00:00 pegasus systemd[1]: Starting Setup Virtual Console...

 2015-11-01T09:01:09.944126+00:00 pegasus systemd[1]: Started Set Up Additional Binary Formats.
 2015-11-01T09:01:09.944113+00:00 pegasus kernel:     0.000000] Linux version 3.7.10-1.45-desktop (geeko@buildhost) (gcc version 4.7.2 20130108 [gcc-4_7-branch revision 195012] (SUSE Linux) ) #1 SMP PREEMPT Tue Dec 16 20:27:58 UTC 2014 (4c885a1)
** 2015-11-01T09:01:09.944130+00:00 pegasus kernel:     0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-3.7.10-1.45-desktop root=UUID=dddb02d5-96e5-434c-ab87-8148309ff92a resume=/dev/disk/by-id/ata-ST1000DM003-9YN162_S1D1AVZZ-part1 splash=silent quiet showopts fsck.mode=force**
 2015-11-01T09:01:09.944134+00:00 pegasus kernel:     0.000000] e820: BIOS-provided physical RAM map:
** 2015-11-01T09:01:09.944135+00:00 pegasus systemd[1]: Started File System Check on Root Device.**
 2015-11-01T09:01:09.944136+00:00 pegasus kernel:     0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ebff] usable
 2015-11-01T09:01:09.944141+00:00 pegasus kernel:     0.000000] BIOS-e820: [mem 0x000000000009ec00-0x000000000009ffff] reserved
 2015-11-01T09:01:09.944142+00:00 pegasus kernel:     0.000000] BIOS-e820: [mem 0x00000000000e0000-0x00000000000fffff] reserved
** 2015-11-01T09:01:09.944142+00:00 pegasus systemd[1]: Starting Remount Root and Kernel File Systems...**
:

I accept what you say about staying with 12.3. I’ve been running 13.2 in a Guest VM for a while and have proved that my apps run in it OK. However, moving will take me a while. I’ll probably use it as an excuse to get a new (larger) HDD too.

I’ve read suggestions that BtrFS lacks provenance and is still a bit buggy. It soulds like it’d be safer to stay with ext4. Do you agree?

gogalthorp · November 1, 2015, 6:34pm

BTRFS seems stable but because of the inclusion of the snapper program to take periodic snaps of the FS it does require at least double the space needed in ext4.

From your description I’d say something has gone wrong in the shutdown process since that is the point the journal should be written. Also you indicated that this is random and does not appear every time the machine is shut down. :\