SPLError: 864:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC

This system is running rc14 with only 3.5Gbyte of RAM. This happened during an rsync.

VERIFY3(sa.sa_magic == 0x2F505A) failed (1319160994 == 3100762)
SPLError: 864:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC
SPL: Showing stack for process 864
Pid: 864, comm: txg_sync Tainted: P           ---------------    2.6.32-279.22.1.el6.x86_64 #1
Call Trace:
[<ffffffffa02dd5a7>] ? spl_debug_dumpstack+0x27/0x40 [spl]
[<ffffffffa02dec81>] ? spl_debug_bug+0x81/0xd0 [spl]
[<ffffffffa0452226>] ? zfs_space_delta_cb+0x286/0x290 [zfs]
[<ffffffffa03ce5a9>] ? dbuf_rele_and_unlock+0x169/0x210 [zfs]
[<ffffffffa03dd235>] ? dmu_objset_userquota_get_ids+0xc5/0x420 [zfs]
[<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
[<ffffffffa03eab83>] ? dnode_sync+0xa3/0xa60 [zfs]
[<ffffffffa03d13a9>] ? dbuf_sync_list+0x59/0x80 [zfs]
[<ffffffffa03eafef>] ? dnode_sync+0x50f/0xa60 [zfs]
[<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
[<ffffffffa03da819>] ? dmu_objset_sync_dnodes+0x89/0xb0 [zfs]
[<ffffffffa03daa2f>] ? dmu_objset_sync+0x1ef/0x360 [zfs]
[<ffffffffa03d9b20>] ? dmu_objset_write_ready+0x0/0x50 [zfs]
[<ffffffffa03daba0>] ? dmu_objset_write_done+0x0/0x70 [zfs]
[<ffffffffa03ed03c>] ? dsl_dataset_sync+0x4c/0x60 [zfs]
[<ffffffffa03fc1bf>] ? dsl_pool_sync+0xcf/0x540 [zfs]
[<ffffffffa041047e>] ? spa_sync+0x39e/0xa00 [zfs]
[<ffffffff8105f8ac>] ? try_to_wake_up+0x24c/0x3e0
[<ffffffff81012a69>] ? read_tsc+0x9/0x20
[<ffffffffa0422d87>] ? txg_sync_thread+0x307/0x590 [zfs]
[<ffffffff810527f9>] ? set_user_nice+0xc9/0x130
[<ffffffffa0422a80>] ? txg_sync_thread+0x0/0x590 [zfs]
[<ffffffffa02e64d8>] ? thread_generic_wrapper+0x68/0x80 [spl]
[<ffffffffa02e6470>] ? thread_generic_wrapper+0x0/0x80 [spl]
[<ffffffff81090876>] ? kthread+0x96/0xa0
[<ffffffff8100c0ca>] ? child_rip+0xa/0x20
[<ffffffff810907e0>] ? kthread+0x0/0xa0
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
SPL: Dumping log to /tmp/spl-log.1361200575.864

The log is at http://wwwlehre.dhbw-stuttgart.de/~bziller/spl-log.1361200575.864.gz

[behlendorf]

The offending VERIFY was recently introduced by a94addd which was a back ported fix from Illumos, see https://www.illumos.org/issues/3208. @ahrens any thoughts on this? Was there a follow fix we perhaps missed?

[maxximino]

@behlendorf look at that numbers in binary:

1001110101000001100110010100010 = 1319160994
1011110101000001011010          = 3100762

They are suspiciously similar.
The problem could be caused by memory corruption (as you've noticed in issue #1263 ?)

[ahrens]

@behlendorf I haven't seen this before, and there was no follow-on fix. Can you get a crash dump and examine the rest of the sa structure to see if it seems to be correct aside from the sa_magic? Or use zdb to examine the on-disk state and see if it still has an invalid sa_magic?

@maxximino How exactly are those numbers (0x2f505a and 0x4ea0cca2) similar? They have no (nonzero) bytes in common.

I'm sorry, behlendorf, maxximo, ahrens.
This SPLerror must relate to jimmyH/zfs@c8d5f5a which added L2ARC compression. It did run fine at first for some weeks. But now after disabling L2ARC compression, the error doesn't occur any longer.

[behlendorf]

@bziller Thanks for following up and letting us know.

[skiselkov]

@bziller I highly doubt that this was caused by L2ARC compression, since buffer corruption in L2ARC traversal would have been caught by the L2ARC checksum, since we compress after checksumming and verify after decompression - see lines 4811 and 4853 in jimmyH/zfs@c8d5f5a for the compression side and lines 4442 and 4448 for the decompression side.

@skiselkov You're right, because I just got a SPL Panic again with a plain rc14 install. Sorry again :(

Feb 26 08:26:32 moria kernel: VERIFY3(sa.sa_magic == 0x2F505A) failed (1281434586 == 3100762)
Feb 26 08:26:32 moria kernel: SPLError: 29875:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC
Feb 26 08:26:32 moria kernel: SPL: Showing stack for process 29875
Feb 26 08:26:32 moria kernel: Pid: 29875, comm: txg_sync Tainted: P           ---------------    2.6.32-279.22.1.el6.x86_64 #1
Feb 26 08:26:32 moria kernel: Call Trace:
Feb 26 08:26:32 moria kernel: [<ffffffffa04dd5a7>] ? spl_debug_dumpstack+0x27/0x40 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffffa04dec81>] ? spl_debug_bug+0x81/0xd0 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffffa06dcc36>] ? zfs_space_delta_cb+0x286/0x290 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa06591d9>] ? dbuf_rele_and_unlock+0x169/0x210 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0667c45>] ? dmu_objset_userquota_get_ids+0xc5/0x420 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
Feb 26 08:26:32 moria kernel: [<ffffffffa0675593>] ? dnode_sync+0xa3/0xa60 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa065bf19>] ? dbuf_sync_list+0x59/0x80 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
Feb 26 08:26:32 moria kernel: [<ffffffffa06652e9>] ? dmu_objset_sync_dnodes+0x89/0xb0 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa06654dd>] ? dmu_objset_sync+0x1cd/0x330 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa06645f0>] ? dmu_objset_write_ready+0x0/0x50 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0665640>] ? dmu_objset_write_done+0x0/0x70 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0677a4c>] ? dsl_dataset_sync+0x4c/0x60 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0686bcf>] ? dsl_pool_sync+0xcf/0x540 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa069ae8e>] ? spa_sync+0x39e/0xa00 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff8105f8ac>] ? try_to_wake_up+0x24c/0x3e0
Feb 26 08:26:32 moria kernel: [<ffffffff81012a69>] ? read_tsc+0x9/0x20
Feb 26 08:26:32 moria kernel: [<ffffffffa06ad797>] ? txg_sync_thread+0x307/0x590 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff810527f9>] ? set_user_nice+0xc9/0x130
Feb 26 08:26:32 moria kernel: [<ffffffffa06ad490>] ? txg_sync_thread+0x0/0x590 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa04e64d8>] ? thread_generic_wrapper+0x68/0x80 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffffa04e6470>] ? thread_generic_wrapper+0x0/0x80 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffff81090876>] ? kthread+0x96/0xa0
Feb 26 08:26:32 moria kernel: [<ffffffff8100c0ca>] ? child_rip+0xa/0x20
Feb 26 08:26:32 moria kernel: [<ffffffff810907e0>] ? kthread+0x0/0xa0
Feb 26 08:26:32 moria kernel: [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
Feb 26 08:26:32 moria kernel: SPL: Dumping log to /tmp/spl-log.1361863592.29875

spl-log and more messages ('task blocked') at http://wwwlehre.dhbw-stuttgart.de/~bziller/spl-log.1361863592.29875.gz and http://wwwlehre.dhbw-stuttgart.de/~bziller/messages.1361863592.29875.gz

[ryao]

I wrote a few posts over the course of thinking about this, so I decided consolidate my thoughts into a single post and delete any ideas that further thinking revealed to be obsolete.

@bziller This looks like a duplicate of openzfs/spl#157, which was determined to have been caused by memory corruption. Does your system use ECC memory? If not, I am going to guess that a corrupt pointer caused nonsense to be copied into the sa_magic field, which was then written to disk with a good checksum. You might be able to identify the bad file by watching rsync's behavior. It likely freezes on a given file, which would be the bad one.

@ahrens @behlendorf It might be best to handle this differently than we do now. If the magic number is invalid, we could invoke the failmode behavior. We could also implement a flag to zpool scrub will identify bad blocks that have valid checksums when there are redundant copies by doing a byte-by-byte comparison of the redundant data when checksums are valid to verify that the blocks are actually sane. If a comparison fails, but the majority of copies agree (e.g. 2/3), then we can do self healing. If we cannot get a majority, then the best we could do is to mark all copies as being bad. What are your thoughts about these ideas?

[ahrens]

@ryao I think you are proposing two changes to the scrub code:

1. Check that all ditto'ed copies of a block agree. Given that we already check that all copies of the block have the same, correct checksum, I'm inclined to simply trust the checksum algorithm here. I don't see a lot of benefit to trying to catch copies that are different but have the same checksum. If this is a realistic failure mode, I'd suggest using a stronger checksum algorithm (e.g. sha256).
2. Do some semantic verification while scrubbing. This seems fine; there is quite a bit you can verify when examining each block independently (e.g. the magic numbers as you pointed out). I'd suggest that you build this into the zio pipeline so that this verification can (optionally) happen whenever we read a block, whether via scrub or the normal read path. You could have a per-object type callback like the byteswap callbacks.

@ryao The system has ECC. A 24h memtest86+ run didn't find any bad memory.

But basically this error means that I have bad data with a good checksum on disk?
What are the possible (easy) ways the fix this (besides restoring from backup)?
In openzfs/spl#157 (comment) behlendorf mentions disabling that VERIFY, deleting the offending file(s) and reenabling the VERIFY.
How should I disable this VERIFY?

[nedbass]

It's interesting that in each reported instance of this bug, sa.sa_magic seems to contain a timestamp in seconds since the epoch.

See also https://groups.google.com/a/zfsonlinux.org/forum/?fromgroups=#!topic/zfs-discuss/Vp02RDQ2GjI

[nedbass]

I wonder if this is related to #1240. In that bug, we found that sa_find_sizes() might incorrectly indicate that the a spill block won't be needed. Accordingly, the variable spillhdrsize is left set to zero in sa_build_layouts(). Now the following code from sa_build_layouts() handles the transition from a bonus to a spill buffer. Note that if spillhdrsize is zero then data_start points to the sahdr, and subsequent writes would corrupt the header, overwriting the sa_magic field.

 756                 if (buf_space < length) {  /* switch to spill buffer */
 757                         VERIFY(spilling);
 758                         VERIFY(bonustype == DMU_OT_SA);
 759                         if (buftype == SA_BONUS && !sa->sa_force_spill) {
 760                                 sa_find_layout(hdl->sa_os, hash, attrs_start,
 761                                     lot_count, tx, &lot);
 762                                 SA_SET_HDR(sahdr, lot->lot_num, hdrsize);
 763                         }
 764 
 765                         buftype = SA_SPILL;
 766                         hash = -1ULL;
 767                         len_idx = 0;
 768 
 769                         sahdr = (sa_hdr_phys_t *)hdl->sa_spill->db_data;
 770                         sahdr->sa_magic = SA_MAGIC;
 771                         data_start = (void *)((uintptr_t)sahdr +
 772                             spillhdrsize);
 773                         attrs_start = &attrs[i];
 774                         buf_space = hdl->sa_spill->db_size - spillhdrsize;
 775                         lot_count = 0;
 776                 }

[nedbass]

On second thought I guess that theory doesn't hold up, since we panicked in that case. Also there's a SA_SET_HDR further down that would rewrite the header.