Help with filing a [maybe] ZFS/mmap bug.

[Richard Todd]

George Hartzell <hartzell at alerce.com> writes:

> Hi All,
>
> I have what I think is a ZFS related bug.  Unfortunately my simplest
> test case is a bit cumbersome and I haven't definitively proven that
> the problem is ZFS related.

> I'm hoping for some feedback on how to move forward.
>
> Quick background: I rip my CD's using grip and produce flac files.  I
> tag the music using Musicbrainz' Picard and transcode it to mp3's
> within Picard using a plugin that I wrote.  Picard is a python based
> app and uses the Mutagen library to tag files.

[summary: Picard seems to trigger an mmap consistency bug in ZFS].

Aw, crud.  I ran into what may be this same issue a few years ago, 
under almost identical circumstances (picard with Ogg files instead of 
flac), but never got around to writing up a proper mailinglist post on it.
I *thought* it had been fixed some time back, though I'm not entirely
sure because I've been running with my local patch to py-mutagen to disable
its mmap() usage. 

Anyway, here's what I recall from when I was trying to track this down way
back when:

1) Your suspicions are right, it's definitely a ZFS/mmap interaction bug. 
UFS filesystems didn't show the bug.

2) It's triggered by the insert_bytes or delete_bytes function in py-mutagen.

3) As long as the in-memory version of that chunk of the file stuck around
in memory, the file read OK, but the data on disk was corrupt, so if that
data got evicted from cache and had to be reread, or if you forced the 
cache data to be disposed of by unmounting and remounting the FS, you would
see a corrupt file.  (Rebooting, of course, would also allow the corrupted
file data to become visible again.)  

I'll attach my patch to disable py-mutagen's mmap usage in insert/delete_bytes
below.  Try it and see if it makes the corruption problems go away.  If so,
that narrows your search down to those two routines in py-mutagen and what
they're doing.  

I *had* what at the time I recall was a simple C++ test program that
managed to trigger the bug more-or-less reliably.  Unfortunately, it
doesn't look like my test case still works, i.e., the test program
doesn't seem to trigger the bug either on the 10-CURRENT box or RELENG-9
VM I'm trying them on now.  As I recall, the bug's presence was dependent on
fairly picky details on what exact offsets were used on the mmap()s and the
write()s, so it may be that different offsets from what I tried will still show
the bug.  

Anyway, what I'd suggest is the following: see if my patch for py-mutagen
disabling the mmap() in those two functions lets you run picard reliably.
If so, then the issue is triggered by one or both of those two routines;
hack them to print out the exact offsets used on each call and use that to 
try and code up a simple C++ test case.  

Here's the py-mutagen patch:

--- mutagen/_util.py.orig	2008-06-01 01:33:00.000000000 -0500
+++ mutagen/_util.py	2009-04-11 18:16:53.363758128 -0500
@@ -213,12 +213,6 @@
     fobj.write('\x00' * size)
     fobj.flush()
     try:
-        try:
-            import mmap
-            map = mmap.mmap(fobj.fileno(), filesize + size)
-            try: map.move(offset + size, offset, movesize)
-            finally: map.close()
-        except (ValueError, EnvironmentError, ImportError):
             # handle broken mmap scenarios
             locked = lock(fobj)
             fobj.truncate(filesize)
@@ -272,17 +266,11 @@
     try:
         if movesize > 0:
             fobj.flush()
-            try:
-                import mmap
-                map = mmap.mmap(fobj.fileno(), filesize)
-                try: map.move(offset, offset + size, movesize)
-                finally: map.close()
-            except (ValueError, EnvironmentError, ImportError):
-                # handle broken mmap scenarios
-                locked = lock(fobj)
-                fobj.seek(offset + size)
-                buf = fobj.read(BUFFER_SIZE)
-                while buf:
+            # handle broken mmap scenarios
+            locked = lock(fobj)
+            fobj.seek(offset + size)
+            buf = fobj.read(BUFFER_SIZE)
+            while buf:
                     fobj.seek(offset)
                     fobj.write(buf)
                     offset += len(buf)


and here's my test case:

# This is a shell archive.  Save it in a file, remove anything before
# this line, and then unpack it by entering "sh file".  Note, it may
# create directories; files and directories will be owned by you and
# have default permissions.
#
# This archive contains:
#
#	gen4.cpp
#	test4.sh
#
echo x - gen4.cpp
sed 's/^X//' >gen4.cpp << 'END-of-gen4.cpp'
X/*
X** Program to create a file of data and do some mmap()ing writes to it. 
X*/
X
X#include <stdio.h>
X#include <stdlib.h>
X#include <stdint.h>
X#include <unistd.h>
X#include <string.h>
X#include <fcntl.h>
X#include <sys/types.h>
X#include <sys/mman.h>
X
X/* Insert size bytes (zeros) into file at offset */
Xvoid
Xinsert_bytes(int fd, unsigned int size, unsigned int offset)
X{
X    unsigned int filesize = lseek(fd, (off_t)0, SEEK_END);
X    unsigned int movesize = filesize - offset;
X    
X    char *buf = new char[size];
X    for (unsigned int i = 0 ; i < size ; ++i) {
X	buf[i] = '\0';
X    }
X    write(fd, buf, size);
X
X    char *addr = (char *) mmap((void *)NULL, filesize+size, PROT_READ|PROT_WRITE, MAP_SHARED, fd, offset);
X    memmove(addr+size, addr, movesize);
X    if (munmap(addr, filesize+size)) {
X	perror("munmap");
X    }
X}
X
X/* Delete size bytes (zeros) from file at offset */
Xvoid
Xdelete_bytes(int fd, unsigned int size, unsigned int offset)
X{
X    unsigned int filesize = lseek(fd, (off_t)0, SEEK_END);
X    unsigned int movesize = filesize - offset - size;
X
X    char *addr = (char *) mmap((void *)NULL, filesize, PROT_READ|PROT_WRITE, MAP_SHARED, fd, offset);
X    memmove(addr, addr+size, movesize);
X    if (munmap(addr, filesize)) {
X	perror("munmap");
X    }
X    ftruncate(fd, filesize - size);
X}
X
X    
X
X/* Usage: gen1 filename number-of-seconds */
Xint
Xmain(int argc, char **argv)
X{
X    char *fname = argv[1];
X    FILE *f = fopen(fname, "w");
X
X    unsigned int size = 1024;
X
X    for (unsigned int i = 0 ; i < size ; ++i) {
X	char c = i & 0xff;
X	fwrite((void *)&c, 1, 1, f);
X    }
X
X    fclose(f);
X
X    int fd = open(fname, O_RDWR);
X
X    unsigned int S1 = atoi(argv[2]);
X#define O1 0
X    insert_bytes(fd, S1, O1);
X    
X    (void) lseek(fd, (off_t) O1, SEEK_SET);
X
X#define S2 1
X#define O2 (O1+S1)
X
X    delete_bytes(fd, S2, O2);
X    
X    exit(0);
X}
END-of-gen4.cpp
echo x - test4.sh
sed 's/^X//' >test4.sh << 'END-of-test4.sh'
X#!/bin/sh
X# Set the following variables appropriately
X# ZFSFS name of your ZFS filesystem to test
X# ZFSMP mount point of your ZFS filesystem to test
X# ZFSDIR a writable dir somewhere under ZFSMP
X# UFSDIR a writable dir somewhere on a UFS filesystem
X# Script takes one argument, S1, a number of bytes.  
X
XZFSFS=u1
XZFSMP=/u1
XZFSDIR=/u1/tmp
XUFSDIR=/var/tmp
X
XNAME=$ZFSDIR/foo1
XS1=$1
Xrm $NAME
X./gen4 $NAME $S1
Xmd5 $NAME
Xcp $NAME $UFSDIR/before
Xls -l $NAME
Xsudo umount $ZFSMP
Xsudo mount -t zfs $ZFSFS $ZFSMP
Xmd5 $NAME
Xls -l $NAME
Xcp $NAME $UFSDIR/after
Xcmp -l $UFSDIR/before $UFSDIR/after
END-of-test4.sh
exit