Hi All,
I wanted to discuss this before considering a bug report. I think its possibly a freebsd/zfs interaction bug but the end result is corrupted data. There is evidence others have seen this, but it's rare.
Yesterday I copied a directory of about 400 jpg files about 1-10MB each locally on my freenas server (ssh in, and "cp -r <source> <dest>" where source and dest were on the same dataset).
cp failed on 5 files reporting cp: bad address. Those 5 files were truncated. From a practical perspective they were corrupted (not by by zfs, at least solely).
Repeating the copy to a new dest the same corrupted result on the same 5 files. Copying the files other ways, ie, using "cat <source> <dest>" resulted in a bit perfect file. Reboot and the original "cp" completes without error. Both tests prove the original file was ok. System had been up for 93 days before reboot. pool scrubs clean, no issues found/corrected. all disks smartctl and regular tests report ok. nothing in the logs. memory is tested good, its ECC and no panics etc. so the corrupted file was consistent on disk, it was just that cp failed to do its job. System is Xeon on supermicro board, LSI controller and wd red 8th disks in raid2. I don't think this is related to hardware.
I took a truss of a cp of a single file before rebooting which I have attached.
I have seen this once before some time ago, on an earlier iteration of Freenas 11 (can't remember version). It was just one file and I put it down to something funky with that file at the time and just deleted it.
This appears to be the same bug as #47668: https://redmine.ixsystems.com/issues/47668
Now what is scary here is that if I had not been watching the terminal session and seen the "cp: bad address" lines, those 5 files would lie there corrupt and eventually fall off my snapshot/replication/offsite backup scheme if left undetected.
I can't be sure, but the issue may not affect NFS/SMB/rsync/scp etc so this might only show up if manipulating files directly on the host. But. My fear is that if it occurs over one of those protocols would it error in a way that the user is aware?.
The issue appears to be mmap related, so it could affect other protocols (or it could be just in how cp uses mmap). I did find another information thread somewhere on a freebsd forum discussing the possibility of an mmap bug in cp but I can't find it right now. I'll add it if I re-find it. It implies, as does the source for cp, that mmap is only used for files <8MB.
I have no idea how to proceed from here. I can't think of anything I can do personally to troubleshoot except wait for it to happen again and me notice it and then do some more informed tests/diagnoses. Looking for input on what that might be, or if anyone knowledgable can advise on some diagnostics to do now.
I think this warrants a bug report, either here or upstream, but looking for advice on how to make that effective.
Wondering is there a way to detect this automatically. I've read some hints that there may be a way to force a panic for such a failure, maybe.. how and would this be wise?
Any other thoughts? Obviously this is a worrying situation for me given I rely on this platform for data integrity and backups can only go so far (backing up data since corrupted is not good), but I'm also hopeful to get to the bottom of it for the greater good. I think there is a sneaky edge case bug between cp/mmap/zfs to do with memory allocation perhaps (a reboot fixing it is worrying however). If I *knew* it was only cp affected I'd just not use it, my fear is silent corruption using nfs/smb etc.
Here's the truss:
I wanted to discuss this before considering a bug report. I think its possibly a freebsd/zfs interaction bug but the end result is corrupted data. There is evidence others have seen this, but it's rare.
Yesterday I copied a directory of about 400 jpg files about 1-10MB each locally on my freenas server (ssh in, and "cp -r <source> <dest>" where source and dest were on the same dataset).
cp failed on 5 files reporting cp: bad address. Those 5 files were truncated. From a practical perspective they were corrupted (not by by zfs, at least solely).
Repeating the copy to a new dest the same corrupted result on the same 5 files. Copying the files other ways, ie, using "cat <source> <dest>" resulted in a bit perfect file. Reboot and the original "cp" completes without error. Both tests prove the original file was ok. System had been up for 93 days before reboot. pool scrubs clean, no issues found/corrected. all disks smartctl and regular tests report ok. nothing in the logs. memory is tested good, its ECC and no panics etc. so the corrupted file was consistent on disk, it was just that cp failed to do its job. System is Xeon on supermicro board, LSI controller and wd red 8th disks in raid2. I don't think this is related to hardware.
I took a truss of a cp of a single file before rebooting which I have attached.
I have seen this once before some time ago, on an earlier iteration of Freenas 11 (can't remember version). It was just one file and I put it down to something funky with that file at the time and just deleted it.
This appears to be the same bug as #47668: https://redmine.ixsystems.com/issues/47668
Now what is scary here is that if I had not been watching the terminal session and seen the "cp: bad address" lines, those 5 files would lie there corrupt and eventually fall off my snapshot/replication/offsite backup scheme if left undetected.
I can't be sure, but the issue may not affect NFS/SMB/rsync/scp etc so this might only show up if manipulating files directly on the host. But. My fear is that if it occurs over one of those protocols would it error in a way that the user is aware?.
The issue appears to be mmap related, so it could affect other protocols (or it could be just in how cp uses mmap). I did find another information thread somewhere on a freebsd forum discussing the possibility of an mmap bug in cp but I can't find it right now. I'll add it if I re-find it. It implies, as does the source for cp, that mmap is only used for files <8MB.
I have no idea how to proceed from here. I can't think of anything I can do personally to troubleshoot except wait for it to happen again and me notice it and then do some more informed tests/diagnoses. Looking for input on what that might be, or if anyone knowledgable can advise on some diagnostics to do now.
I think this warrants a bug report, either here or upstream, but looking for advice on how to make that effective.
Wondering is there a way to detect this automatically. I've read some hints that there may be a way to force a panic for such a failure, maybe.. how and would this be wise?
Any other thoughts? Obviously this is a worrying situation for me given I rely on this platform for data integrity and backups can only go so far (backing up data since corrupted is not good), but I'm also hopeful to get to the bottom of it for the greater good. I think there is a sneaky edge case bug between cp/mmap/zfs to do with memory allocation perhaps (a reboot fixing it is worrying however). If I *knew* it was only cp affected I'd just not use it, my fear is silent corruption using nfs/smb etc.
Here's the truss:
Code:
root@vault:/mnt/mass1/piwigo/x # truss cp ../upload/2020/02/02/20200202174652-706ab1cc.jpg . mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34366177280 (0x800624000) issetugid() = 0 (0x0) lstat("/etc",{ mode=drwxr-xr-x ,inode=2,size=8128,blksize=4096 }) = 0 (0x0) lstat("/etc/libmap.conf",{ mode=-rw-r--r-- ,inode=118,size=145,blksize=4096 }) = 0 (0x0) openat(AT_FDCWD,"/etc/libmap.conf",O_RDONLY|O_CLOEXEC,00) = 3 (0x3) fstat(3,{ mode=-rw-r--r-- ,inode=118,size=145,blksize=4096 }) = 0 (0x0) mmap(0x0,145,PROT_READ,MAP_PRIVATE,3,0x0) = 34366210048 (0x80062c000) close(3) = 0 (0x0) munmap(0x80062c000,145) = 0 (0x0) openat(AT_FDCWD,"/var/run/ld-elf.so.hints",O_RDONLY|O_CLOEXEC,00) = 3 (0x3) read(3,"Ehnt\^A\0\0\0\M^@\0\0\0\M^S\0\0"...,128) = 128 (0x80) fstat(3,{ mode=-r--r--r-- ,inode=204,size=275,blksize=4096 }) = 0 (0x0) lseek(3,0x80,SEEK_SET) = 128 (0x80) read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,147) = 147 (0x93) close(3) = 0 (0x0) access("/lib/libc.so.7",F_OK) = 0 (0x0) openat(AT_FDCWD,"/lib/libc.so.7",O_RDONLY|O_CLOEXEC|O_VERIFY,00) = 3 (0x3) fstat(3,{ mode=-r--r--r-- ,inode=3071,size=1680112,blksize=131072 }) = 0 (0x0) mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,3,0x0) = 34366210048 (0x80062c000) mmap(0x0,3878912,PROT_NONE,MAP_GUARD,-1,0x0) = 34368278528 (0x800825000) mmap(0x800825000,1634304,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,3,0x0) = 34368278528 (0x800825000) mmap(0x800bb3000,49152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,3,0x18e000) = 34372005888 (0x800bb3000) mmap(0x800bbf000,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 34372055040 (0x800bbf000) munmap(0x80062c000,4096) = 0 (0x0) close(3) = 0 (0x0) munmap(0x80062b000,4096) = 0 (0x0) mmap(0x0,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34366205952 (0x80062b000) sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0) sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0) readlink("/etc/malloc.conf",0x7fffffffd6c0,1024) ERR#2 'No such file or directory' issetugid() = 0 (0x0) __sysctl(0x7fffffffd560,0x2,0x7fffffffd5b0,0x7fffffffd5a8,0x800984053,0xd) = 0 (0x0) __sysctl(0x7fffffffd5b0,0x2,0x7fffffffd674,0x7fffffffd668,0x0,0x0) = 0 (0x0) mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34372157440 (0x800bd8000) munmap(0x800bd8000,2097152) = 0 (0x0) mmap(0x0,4190208,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34372157440 (0x800bd8000) munmap(0x800bd8000,163840) = 0 (0x0) munmap(0x800e00000,1929216) = 0 (0x0) sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0) sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0) sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0) sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0) sigaction(SIGINFO,{ 0x4020e0 SA_RESTART ss_t },{ SIG_DFL 0x0 ss_t }) = 0 (0x0) stat(".",{ mode=drwxr-xr-x ,inode=2933,size=2,blksize=131072 }) = 0 (0x0) umask(0x1ff) = 18 (0x12) umask(0x12) = 511 (0x1ff) mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34374418432 (0x800e00000) fstatat(AT_FDCWD,"../upload/2020/02/02/20200202174652-706ab1cc.jpg",{ mode=-rw-r--r-- ,inode=421,size=3474211,blksize=131072 },0x0) = 0 (0x0) stat("./20200202174652-706ab1cc.jpg",0x7fffffffe888) ERR#2 'No such file or directory' openat(AT_FDCWD,"../upload/2020/02/02/20200202174652-706ab1cc.jpg",O_RDONLY,00) = 3 (0x3) openat(AT_FDCWD,"./20200202174652-706ab1cc.jpg",O_WRONLY|O_CREAT|O_TRUNC,0100644) = 4 (0x4) mmap(0x0,3474211,PROT_READ,MAP_SHARED,3,0x0) = 34376515584 (0x801000000) write(4,"\M^?\M-X\M^?\M-aQ\M^SExif\0\0II*"...,3474211) ERR#14 'Bad address' cp: write(2,"cp: ",4) = 4 (0x4) ./20200202174652-706ab1cc.jpgwrite(2,"./20200202174652-706ab1cc.jpg",29) = 29 (0x1d) : write(2,": ",2) = 2 (0x2) Bad address write(2,"Bad address\n",12) = 12 (0xc) munmap(0x801000000,3474211) = 0 (0x0) close(4) = 0 (0x0) close(3) = 0 (0x0) sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0) sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0) sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0) sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0) sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0) sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0) exit(0x1) process exit, rval = 1