Data Corruption - ZFS saves the day, again

We came across an interesting issue with data corruption and I think it might be interesting to some of you. While preparing a new cluster deployment and filling it up with data we suddenly started to see below messages:

XXX cl_runtime: [ID 856360 kern.warning] WARNING: QUORUM_GENERIC: quorum_read_keys error:
 Reading the registration keys failed on quorum device /dev/did/rdsk/d7s2 with error 22.

The d7 quorum device was marked as being offline and we could not bring it online again. There isn't much in documentation about the above message except that it is probably a firmware problem on a disk array and we should contact a vendor. But lets investigate first what is really going on.

By looking at the source code I found that the above message is printed from within quorum_device_generic_impl::quorum_read_keys() and it will only happen if quorum_pgre_key_read() returns with return code 22 (actually any other than 0 or EACCESS but from the syslog message we already suspect that the return code is 22).

The quorum_pgre_key_read() calls quorum_scsi_sector_read() and passes its return code as its own. The quorum_scsi_sector_read() will return with an error only if quorum_ioctl_with_retries() returns with an error or if there is a checksum mismatch.

This is the relevant source code:

406 int
407 quorum_scsi_sector_read(
[...]
449  error = quorum_ioctl_with_retries(vnode_ptr, USCSICMD, (intptr_t)&ucmd,
450      &retval);
451  if (error != 0) {
452   CMM_TRACE(("quorum_scsi_sector_read: ioctl USCSICMD "
453       "returned error (%d).\n", error));
454   kmem_free(ucmd.uscsi_rqbuf, (size_t)SENSE_LENGTH);
455   return (error);
456  }
457
458  //
459  // Calculate and compare the checksum if check_data is true.
460  // Also, validate the pgres_id string at the beg of the sector.
461  //
462  if (check_data) {
463   PGRE_CALCCHKSUM(chksum, sector, iptr);
464
465   // Compare the checksum.
466   if (PGRE_GETCHKSUM(sector) != chksum) {
467    CMM_TRACE(("quorum_scsi_sector_read: "
468        "checksum mismatch.\n"));
469    kmem_free(ucmd.uscsi_rqbuf, (size_t)SENSE_LENGTH);
470    return (EINVAL);
471   }
472
473   //
474   // Validate the PGRE string at the beg of the sector.
475   // It should contain PGRE_ID_LEAD_STRING[1|2].
476   //
477   if ((os::strncmp((char *)sector->pgres_id, PGRE_ID_LEAD_STRING1,
478       strlen(PGRE_ID_LEAD_STRING1)) != 0) &&
479       (os::strncmp((char *)sector->pgres_id, PGRE_ID_LEAD_STRING2,
480       strlen(PGRE_ID_LEAD_STRING2)) != 0)) {
481    CMM_TRACE(("quorum_scsi_sector_read: pgre id "
482        "mismatch. The sector id is %s.\n",
483        sector->pgres_id));
484    kmem_free(ucmd.uscsi_rqbuf, (size_t)SENSE_LENGTH);
485    return (EINVAL);
486   }
487
488  }
489  kmem_free(ucmd.uscsi_rqbuf, (size_t)SENSE_LENGTH);
490
491  return (error);
492 }

With a simple DTrace script I could verify if the quorum_scsi_sector_read() does indeed return with 22 and also I could print what else is going on within the function:

56  -> __1cXquorum_scsi_sector_read6FpnFvnode_LpnLpgre_sector_b_i_ 6308555744942019 enter
56    -> __1cZquorum_ioctl_with_retries6FpnFvnode_ilpi_i_ 6308555744957176 enter
56    <- __1cZquorum_ioctl_with_retries6FpnFvnode_ilpi_i_ 6308555745089857 rc: 0 
56    -> __1cNdbg_print_bufIdbprintf6MpcE_v_ 6308555745108310 enter
56      -> __1cNdbg_print_bufLdbprintf_va6Mbpcrpv_v_ 6308555745120941 enter
56        -> __1cCosHsprintf6FpcpkcE_v_      6308555745134231 enter
56        <- __1cCosHsprintf6FpcpkcE_v_      6308555745148729 rc: 2890607504684 
56      <- __1cNdbg_print_bufLdbprintf_va6Mbpcrpv_v_ 6308555745162898 rc: 1886718112 
56    <- __1cNdbg_print_bufIdbprintf6MpcE_v_ 6308555745175529 rc: 1886718112 
56  <- __1cXquorum_scsi_sector_read6FpnFvnode_LpnLpgre_sector_b_i_ 6308555745188599 rc: 22   

From the above output we know that the quorum_ioctl_with_retries() returns with 0 so it must be a checksum mismatch! As CMM_TRACE() is being called above and there are only three of them in the code lets check with DTrace which one it is:

21  -> __1cNdbg_print_bufIdbprintf6MpcE_v_   6309628794339298 quorum_scsi_sector_read: checksum mismatch.

So now I knew exactly what part of the code is casing the quorum device to be marked offline. The issue might have been caused by many things like: a bug in a disk array firmware, a problem on an SAN, a bug in a HBA's firmware, a bug in a qlc driver or a bug in SC software, or... However because the issue suggests a data corruption and we are loading the cluster with a copy of a database we might have a bigger issue that just an offline quorum device. The configuration is a such that we are using ZFS to mirror between two disks arrays. We have been restoring a couple of TBs of data into and we haven't read almost anything back. Thankfully it is ZFS so we might force a re-check off all data in the pool and I did. ZFS found 14 corrupted blocks and even identified which file is affected. The interesting thing here is that for all blocks both copies on both sides of the mirror were affected. This almost eliminates a possibility of a firmware problem on disk arrays and suggest that the issue was caused by something misbehaving on the host itself. There is still a possibility of an issue on SAN as well. It is very unlikely to be a bug in ZFS as the corruption affected reservation keys as well which has basically nothing to do with ZFS at all. Then we are still writing more and more data into the pool and I'm repeating scrubs and I'm not getting any new corrupted blocks nor quorum is misbehaving (I fixed it by temporarily adding another one, removing the original and re-adding it again while removing the temporary one).

While I still have to find what caused the data corruption the most important thing here is ZFS. Just think about it - what would happen if we were running on any other file system like: UFS, VxFS, ext3, ext4, JFS, XFS, ... Well, almost anything could have happened with them like some data of could be corrupted, some files lost, system could crash, fsck could be forced to run for many hours and still not being able to fix the filesystem and it definitely wouldn't be able to detect any data corruption withing files or everything would be running fine for days, months and then suddenly the system would panic, etc. when application would try to access the corrupted blocks for the first time. Thanks to ZFS what have actually happened? All corrupted blocks were identified, unfortunately both mirrored copies were affected so ZFS can't fix them but it did identified a single file which was affected by all these blocks. We can just remove the file which is only 2GB and restore it again. And all of these while the system was running and we haven't even stopped the restore or didn't have to start from the beginning. Most importantly there is no uncertainty about the state of the filesystem or data within it.

The other important conclusion is that DTrace is a sysadmin's best friend :)