[Cluster-devel] Assertion failure: sdp->sd_log_blks_free <= sdp->sd_jdesc->jd_blocks

[Ross Lagerwall <ross.lagerwall@citrix.com>]

On 3/19/19 6:48 PM, Bob Peterson wrote:
> ----- Original Message -----
>> Hi,
>>
>> Occasionally during testing, we see the following assertion failure in
>> log_pull_tail():
>>
>> [ 1104.061245] gfs2: fsid=xapi-clusterd:2d2cc24c-c48a-ca.0: fatal:
>> assertion "atomic_read(&sdp->sd_log_blks_free) <=
>> sdp->sd_jdesc->jd_blocks" failed
>> [ 1104.061245]    function = log_pull_tail, file = fs/gfs2/log.c, line = 510
>>
>> It always seems to happen shortly after journal recovery. I added some
>> debug logging at the point of the assertion failure and got the following:
> (snip)
>> Any ideas about this?
>>
>> Thanks,
>> --
>> Ross Lagerwall
> 
> Hi Ross,
> 
> I've been fighting with/debugging multiple recovery problems for a long time now.
> I've done countless (well, okay, thousands of) recovery tests and I can tell
> you that gfs2 recovery has some major problems. These problems usually don't
> occur when you have a few gfs2 mounts: they're much more likely when you have
> lots of gfs2 mounts. I'm using 32 mounts.
> 
> The problem you mentioned sounds vaguely familiar, but I can't find anything
> directly related. Make sure all your journals are the same size, and see if fsck.gfs2
> complains about the journal. Otherwise, it could be a side effect of one of the
> recovery issues I'm working on. Do you have other symptoms? Also, make sure
> multiple nodes aren't trying to use the same journal because of lock_nolock or
> something...I've made that mistake in the past.
> 

I think I've found the cause of the assertion I was hitting. Recovery 
sets sd_log_flush_head but does not take locks which means a concurrent 
call to gfs2_log_flush() can result in sd_log_head being set to 
sd_log_flush_head. A later call to gfs2_log_flush() will then hit an 
assertion failure in log_pull_tail() because the mismatch between 
sd_log_head and sd_log_tail means too many blocks are freed.

I've worked around it by taking the log_flush lock in the patch below 
and it seems to avoid the problem. However, tracing the recovery process 
I see that it sets sd_log_flush_head and then calls clean_journal() -> 
gfs2_write_log_header() -> gfs2_log_bmap() -> gfs2_log_incr_head(). This 
has:

	BUG_ON((sdp->sd_log_flush_head == sdp->sd_log_tail) &&
	       (sdp->sd_log_flush_head != sdp->sd_log_head));

... but sd_log_tail and sd_log_head have not been set by 
gfs2_recover_func() so it might still BUG_ON() during recovery if you're 
particularly unlucky.

I had a look at your "GFS2: Withdraw corruption patches [V2]" series but 
I didn't see anything that might fix this.

If you think this patch is useful then I can send it as a proper patch 
to the list.

Thanks,
Ross

--------------

gfs2: Take log_flush lock during recovery

Recovery sets sd_log_flush_head but does not take any locks which means
a concurrent call to gfs2_log_flush can result in sd_log_head being set
to sd_log_flush_head. A later call to gfs2_log_flush will then hit an
assertion failure in log_pull_tail because the mismatch between
sd_log_head and sd_log_tail means too many blocks are freed.

gfs2: fsid=xapi-clusterd:88a31b8e-4072-b0.1: fatal: assertion 
"atomic_read(&sdp->sd_log_blks_free) <= sdp->sd_jdesc->jd_blocks" failed
function = log_pull_tail, file = fs/gfs2/log.c, line = 510

diff --git a/fs/gfs2/recovery.c b/fs/gfs2/recovery.c
index 0f501f938d1c..5f7c3271e909 100644
--- a/fs/gfs2/recovery.c
+++ b/fs/gfs2/recovery.c
@@ -498,6 +498,8 @@ void gfs2_recover_func(struct work_struct *work)
  			goto fail_gunlock_thaw;
  		}

+		down_write(&sdp->sd_log_flush_lock);
+
  		t_tlck = ktime_get();
  		fs_info(sdp, "jid=%u: Replaying journal...\n", jd->jd_jid);

@@ -512,6 +514,8 @@ void gfs2_recover_func(struct work_struct *work)

  		clean_journal(jd, &head);

+		up_write(&sdp->sd_log_flush_lock);
+
  		gfs2_glock_dq_uninit(&thaw_gh);
  		t_rep = ktime_get();
  		fs_info(sdp, "jid=%u: Journal replayed in %lldms [jlck:%lldms, "