Gentoo Forums
Gentoo Forums
Gentoo Forums
Quick Search: in
[solved] Do I have silent data corruption or false positive?
View unanswered posts
View posts from last 24 hours

 
Reply to topic    Gentoo Forums Forum Index Kernel & Hardware
View previous topic :: View next topic  
Author Message
tholin
Apprentice
Apprentice


Joined: 04 Oct 2008
Posts: 176

PostPosted: Tue Dec 25, 2018 10:03 pm    Post subject: [solved] Do I have silent data corruption or false positive? Reply with quote

I'm struggling with a bit of a conundrum. I have a weekly cron job that looks like this.
Code:
date >> /var/log/cshatag.log.err
find / -xdev -type f -print0 | xargs -0 -n 1 -P 8 cshatag > /dev/null 2>> /var/log/cshatag.log.err

cshatag is https://github.com/rfjakob/cshatag
"cshatag is a tool to detect silent data corruption. It writes the mtime and the sha256 checksum of a file into the file's extended attributes. When run again, it compares stored mtime and checksum. If it finds that the mtime is unchanged but the checksum has changed, it warns on stderr. In any case, the status of the file is printed to stdout and the stored checksum is updated."

My cshatag.log.err looks like this:
Code:
Error: corrupt file "/usr/lib32/misc/glibc/getconf/POSIX_V6_ILP32_OFFBIG"                                         
Error: corrupt file "/usr/include/pugiconfig.hpp"
Error: corrupt file "/usr/include/pugixml.hpp"
Sun Jul  1 12:45:21 CEST 2018
Sun Jul  8 12:00:01 CEST 2018
Sun Jul 15 12:00:01 CEST 2018
Sun Jul 22 12:00:01 CEST 2018
Sun Jul 29 12:00:01 CEST 2018
Sun Aug  5 12:00:01 CEST 2018
Sun Aug 12 12:00:01 CEST 2018
Sun Aug 19 12:00:01 CEST 2018
Sun Aug 26 12:00:02 CEST 2018
Sun Sep  2 12:00:01 CEST 2018
Sun Sep  9 12:00:01 CEST 2018
Sun Sep 16 12:00:01 CEST 2018
Sun Sep 23 12:00:01 CEST 2018
Sun Sep 30 12:00:01 CEST 2018
Sun Oct  7 12:00:01 CEST 2018
Sun Oct 14 12:00:01 CEST 2018
Sun Oct 21 12:00:01 CEST 2018
Sun Oct 28 11:10:01 CET 2018
Sun Oct 28 12:00:01 CET 2018
Sun Nov  4 12:00:01 CET 2018
Sun Nov 11 12:00:01 CET 2018
Sun Nov 18 12:00:01 CET 2018
Sun Nov 25 12:00:01 CET 2018
Sun Dec  2 12:00:01 CET 2018
Sun Dec  9 12:00:01 CET 2018
Sun Dec 16 12:00:01 CET 2018
Sun Dec 23 12:00:01 CET 2018
Error: corrupt file "/usr/share/zoneinfo/Africa/Libreville"

I'm trying to find the cause of those errors.

Comparing the Libreville file with my daily backups shows that the file's content hasn't changed at all for a long time. Not even after the "corruption".

One of the flaws of cshatag is that is uses mtime to check if a file has changed. Mtime can be changed from userspace so a process could modify a file and reset the mtime back to what it was. Cshatag would then report corruption in the file.

/usr/share/zoneinfo/Africa/Libreville belongs to sys-libs/timezone-data
Code:
genlop sys-libs/timezone-data
     [...]
     Fri Aug 31 08:05:18 2018 >>> sys-libs/timezone-data-2018e
     Sun Nov 11 11:43:31 2018 >>> sys-libs/timezone-data-2018g
     Mon Dec 17 11:58:47 2018 >>> sys-libs/timezone-data-2018g-r1

sys-libs/timezone-data was updated just before the corruption so maybe the new Libreville file got different data but the same mtime?
No, that's not the case. Portage overwrite files by moving the new file over the old. The old inode is then deleted along with its extended attributes.

I run a daily backup with borg and borg also saves the xattr. Here are the xattr for Libreville:
Code:
# file: root-fs-2018-12-15T20:06:30/mnt/borg-tmp-root/usr/share/zoneinfo/Africa/Libreville
user.shatag.sha256="42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce"
user.shatag.ts="1541933004.000000000"

# file: root-fs-2018-12-16T20:07:38/mnt/borg-tmp-root/usr/share/zoneinfo/Africa/Libreville
user.shatag.sha256="42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce"
user.shatag.ts="1541933004.000000000"

root-fs-2018-12-17T20:07:24 no xattr
root-fs-2018-12-18T20:08:44 no xattr
root-fs-2018-12-19T20:07:10 no xattr
root-fs-2018-12-20T20:08:08 no xattr
root-fs-2018-12-21T20:34:12 no xattr
root-fs-2018-12-22T20:07:22 no xattr

# file: root-fs-2018-12-23T20:07:00/mnt/borg-tmp-root/usr/share/zoneinfo/Africa/Libreville
user.shatag.sha256="42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce"
user.shatag.ts="1545044245.000000000"

# file: root-fs-2018-12-24T20:06:48/mnt/borg-tmp-root/usr/share/zoneinfo/Africa/Libreville
user.shatag.sha256="42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce"
user.shatag.ts="1545044245.000000000"

Libreville had normal cshatag xattr up until 2018-12-16T20:07:38. Then timezone-data was updated on Dec 17 11:58:47. After that the xattr are missing. That is what I would expect when portage replace files. The interesting thing is that the corruption was detected Dec 23 12:00:01 and at that time Libreville shouldn't have had any cshatag xattr. Cshatag will write a new xattr when it finds corruption so all the dates after Dec 23 12:00:01 have normal xattr.

So why is cshatag complaining about corruption on a file with no cshatag metadata?

Perhaps the SSD got some transient error, or bad ram or bad cpu? Those errors are unlikely to result in a false corruption warning in a file with no cshatag metadata and no other symptoms.

"find | xargs" is racy and gives "No such file or directory" errors if files are removed before xargs executes. One idea I had was that if a directory is modified while find reads it it might output the same file twice? In that case two cshatag will access the data concurrently which causes a corruption warning. But find use getdents() and that looks atomic for small directories like /usr/share/zoneinfo/Africa. There is also no reason to believe that directory was modified while cshatag ran.

My root fs is an old ext4 without nanosecond timestamps. Due to the coarse resolution of the timestamps, if I run cshatag, modifiy the data and run cshatag again all in less than 1 sec I'll get a corruption warning because the timestamps are not high-res enough to pick up the change. But I didn't run cshatag twice in a row and I didn't modify Libreville while cshatag was running.

Since there was no cshatag metadata in the Libreville file cshatag will set the none existing timestamps to zero. If there was also a bug in ext4 that causes fstat() to return zero timestamps that would result in a false corruption warning. Cshatag also doesn't check for errors when it calls fstat(). If the call fails that could also explain the problem?

Does anyone have a better explanation? The code for cshatag isn't great but I don't see any obvious problem that would cause this.
https://github.com/rfjakob/cshatag/blob/master/cshatag.c

I'd hate to just write this off as a false positive just because I can't find the cause.


Last edited by tholin on Mon Apr 29, 2019 8:48 am; edited 1 time in total
Back to top
View user's profile Send private message
mike155
Veteran
Veteran


Joined: 17 Sep 2010
Posts: 1544
Location: Frankfurt, Germany

PostPosted: Wed Dec 26, 2018 1:39 pm    Post subject: Reply with quote

tholin, I tried to reproduce the problem you reported.
Code:
# ls -la /usr/share/zoneinfo/Africa/Libreville
-rw-r--r-- 10 root root 157 Dec 17 14:05 /usr/share/zoneinfo/Africa/Libreville

# cshatag  /usr/share/zoneinfo/Africa/Libreville
<outdated> /usr/share/zoneinfo/Africa/Libreville
 stored: 0000000000000000000000000000000000000000000000000000000000000000 0000000000.000000000
 actual: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545051959.804593054

# cshatag  /usr/share/zoneinfo/Africa/Libreville
<ok> /usr/share/zoneinfo/Africa/Libreville

So far, so good.

I re-installed timezone-data and ran cshatag again:
Code:
# emerge --onehsot timezone-data

# ls -la /usr/share/zoneinfo/Africa/Libreville
-rw-r--r-- 10 root root 157 Dec 26 14:10 /usr/share/zoneinfo/Africa/Libreville

# cshatag  /usr/share/zoneinfo/Africa/Libreville
<outdated> /usr/share/zoneinfo/Africa/Libreville
 stored: 0000000000000000000000000000000000000000000000000000000000000000 0000000000.000000000
 actual: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545829848.447020184

Emerge overwrites the existing file. The 'last modification time' of the file is set to the current time. Consequently, cshatag recognizes the file as a 'new' file. Everything as expected.

During my tests, I noticed a strange behavior of cshatag. I ran cshatag in a loop, and I got:

Code:
# while [ 1 ]; do cshatag /usr/share/zoneinfo/Africa/Libreville; done

<ok> /usr/share/zoneinfo/Africa/Libreville
<ok> /usr/share/zoneinfo/Africa/Libreville
<ok> /usr/share/zoneinfo/Africa/Libreville
<ok> /usr/share/zoneinfo/Africa/Libreville
<outdated> /usr/share/zoneinfo/Africa/Libreville
 stored: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545829848.4470201845
 actual: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545829848.447020184
<ok> /usr/share/zoneinfo/Africa/Libreville
<ok> /usr/share/zoneinfo/Africa/Libreville
<ok> /usr/share/zoneinfo/Africa/Libreville
...
<outdated> /usr/share/zoneinfo/Africa/Libreville
 stored: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545829848.4470201849
 actual: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545829848.447020184
<ok> /usr/share/zoneinfo/Africa/Libreville
<ok> /usr/share/zoneinfo/Africa/Libreville
...
<outdated> /usr/share/zoneinfo/Africa/Libreville
 stored: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545829848.4470201843
 actual: 42cd9efcdecb38a4748cdc6f7d8229f883525b90cb6bc69e7dc0e2e2c711b2ce 1545829848.447020184
<ok> /usr/share/zoneinfo/Africa/Libreville

Although I didn't touch or change Libreville, cshatag thinks that the file is outdated in one out of approximately 50 calls. I didn't look at the code of the program, but there's something wrong. Maybe a rounding error?
Back to top
View user's profile Send private message
mike155
Veteran
Veteran


Joined: 17 Sep 2010
Posts: 1544
Location: Frankfurt, Germany

PostPosted: Wed Dec 26, 2018 3:01 pm    Post subject: Reply with quote

I found at least one bug in the program. In line 154:
Code:
char ts[100];
/*
* Initialize to zero-length string - if fgetxattr fails this is what we get
*/
ts[0]=0;
fgetxattr(fd, "user.shatag.ts", ts, sizeof(ts));
/*
* If sscanf fails (because ts is zero-length) variables stay zero
*/
sscanf( ts,"%llu.%lu", &xa.s, &xa.ns );

fgetxattr is used to read the stored timestamp. Unfortunately, the string returned by fgetxattr() isn't NULL-terminated, at least not on my machine. If I look at ts after the fgetxattr() call, I see the timestamp and additionally two random characters. In most cases, scanf() will simply ignores those characters. But if they happen to be digits, scanf will write the wrong values to xa.

The code should be something like:
Code:
char ts[100];

ssize_t retval = fgetxattr( fd, "user.shatag.ts", ts, sizeof(ts) - 1 );

if ( retval > 0 ) {
    ts[retval] = 0;
} else {
    ts[0] = 0;
}

/*
* If sscanf fails (because ts is zero-length) variables stay zero
*/

sscanf( ts, "%llu.%lu", &xa.s, &xa.ns );

After I replaced the original code with my fix, the problem I reported in my previous post disappeared.

A similar bug can be found in line 146, where fgetxattr() is used to read the stored hash of the file. That bug is probably (I didn't test it) the culprit for the problem reported by tholin.
Back to top
View user's profile Send private message
tholin
Apprentice
Apprentice


Joined: 04 Oct 2008
Posts: 176

PostPosted: Wed Dec 26, 2018 3:36 pm    Post subject: Reply with quote

Thanks for looking into the problem.

When I examine my local cshatag.c I find this difference from github:
Code:
diff --git a/cshatag.c b/cshatag.c
index f92fc65..5a9734b 100644
--- a/cshatag.c
+++ b/cshatag.c
@@ -152,6 +152,7 @@ xa_t getstoredxa(FILE *f)
         *    10     .     9     => len=20
         */
        char ts[100];
+       memset(ts, 0, sizeof(ts));
        /*
         * Initialize to zero-length string - if fgetxattr fails this is what we get
         */

I don't know where that memset comes from but I probably added it myself and forgot about it. I've been using cshatag for a long time so at some point I probably noticed that problem and added an ugly fix. The fgetxattr at line 146 is null terminated on the next line.

I don't see how that would explain my original problem. Without xattr tags fgetxattr() should fail and the two strings should be zero length (line 145, 158). The only possibility I've noticed is if the call to fstat() on 99 fails, the uninitialized buf could be zero and would match the zeroed xa.s, xa.ns.
Back to top
View user's profile Send private message
tholin
Apprentice
Apprentice


Joined: 04 Oct 2008
Posts: 176

PostPosted: Mon Apr 29, 2019 8:47 am    Post subject: Reply with quote

I got another corruption warning and finally figured out what is causing it. I'm stupid, that's what's causing it. I used xargs -P 8 to run 8 cshatag processes in parallel to get better utilization of the SSD. Since those processes work on different files it's safe... except I forgot hardlinks exist.

If there are hardlinks those processes could end up working on the same inode at the same time. If there are a lot of hardlinks in the same directory, like that timezone-data folder, the risk increases. Cshatag can't write the two extended attributes atomically so occasionally a cshatag process will only see one of the attributes and interpret that as corruption.

The solution is simple. Stop running multiple cshatag instances. Unfortunately that makes the scrub time go from 10 min to 30 min. I considered implementing file locking but if cshatag locks files some other program want to lock that other program will probably malfunction somehow.
Back to top
View user's profile Send private message
Hu
Moderator
Moderator


Joined: 06 Mar 2007
Posts: 14163

PostPosted: Tue Apr 30, 2019 1:42 am    Post subject: Reply with quote

As a quick compromise, you could do two passes of scrubbing. One pass touches only files that have exactly 1 link, and enables parallel operation. The other pass touches only files that have more than 1 link, and does not enable parallel operation.

Another option would be to generate the full list, eliminate redundant names, then run a parallel scrub on the remaining entries. As a lightly tested pipeline based way to do this:
Code:
find $paths -type f -a '-(' '-(' -links 1 -print0 '-)' -o '-(' -links +1 -fprintf /dev/fd/3 '%D.%i\t%p\0' '-)' '-)' 3> >( sort -k1,1 -u -z | cut -f2- -z ) | xargs $expr
Files with exactly one link are sent to stdout as-is, null-separated. Files with more than one link are printed to fd 3, prefixed by their device+inode, and null terminated. Descriptor 3 is attached to a pipeline that uses sort to discard entries that have the same first field, then uses cut to avoid printing that field.
Back to top
View user's profile Send private message
tholin
Apprentice
Apprentice


Joined: 04 Oct 2008
Posts: 176

PostPosted: Tue Apr 30, 2019 8:03 pm    Post subject: Reply with quote

Hu wrote:
Another option would be to generate the full list, eliminate redundant names, then run a parallel scrub on the remaining entries.

I considered something like that but couldn't come up with a solution that wasn't racy. Two files without hardlinks could be passed to cshatag for parallel processing but before cshatag runs one file is deleted and replaced with a hardlink to the other. Running app-arch/hardlink while the scrubbing takes place could result in that situation. There might be other programs doing things like that. It's unlikely but it could happen and I don't want to chase down any more false positives.
Back to top
View user's profile Send private message
Display posts from previous:   
Reply to topic    Gentoo Forums Forum Index Kernel & Hardware All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum