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

[Ross Lagerwall]

On 3/25/19 3:29 PM, Bob Peterson wrote:
> ----- Original Message -----
>> 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
> 
> Hi Ross,
> 
> I think you found a valid bug, but that's not the proper solution.
> The reason is: I think journal replay and journal flushing should both be
> protected by the exclusive (EX) glock taken on the journal itself.
> 
> I think the problem may actually be a regression with patch 588bff95c94ef.
> Because of that patch, function clean_journal now sets sdp->sd_log_flush_head
> but its caller, gfs2_recover_func, is used to recover any node's journal, not
> just its own. The bug is that clean_journal should only set sd_log_flush_head
> if (and only if) it's replaying its own journal, not someone else's.
> If it sets sd_log_flush_head while replaying another node's journal, that
> will only lead to a problem like this.
> 
> I'll try and whip up another patch and perhaps you can test it for me.
> 
> FWIW, I've never seen this problem manifest on my recovery tests, but it
> still might be causing some of the weird problems I'm seeing.
> 

(Replying on this thread since I didn't get CCed on the patch.)

I still hit the assertion with this patch. gfs2_log_write_header() is 
unconditionally called and it calls gfs2_log_bmap() which changes 
sd_log_flush_head in the success path.

FWIW we hit this assertion periodically during testing but I found that 
I could get it to trigger almost every time during recovery with some 
well-placed sleeps and a kthread that continuously calls gfs2_log_flush().

-----8<----------

diff --git a/fs/gfs2/log.c b/fs/gfs2/log.c
index ee20ea42e7b5..8bd87082a110 100644
--- a/fs/gfs2/log.c
+++ b/fs/gfs2/log.c
@@ -820,6 +820,10 @@ void gfs2_log_flush(struct gfs2_sbd *sdp, struct 
gfs2_glock *gl, u32 flags)
  	}
  	lops_after_commit(sdp, tr);

+       if (flags & GFS2_LFC_LOGD_TEST) {
+               msleep(1000);
+       }
+
  	gfs2_log_lock(sdp);
  	sdp->sd_log_head = sdp->sd_log_flush_head;
  	sdp->sd_log_blks_reserved = 0;
diff --git a/fs/gfs2/log.h b/fs/gfs2/log.h
index 20241436126d..9d658efdb57a 100644
--- a/fs/gfs2/log.h
+++ b/fs/gfs2/log.h
@@ -79,6 +79,7 @@ extern void gfs2_ail1_flush(struct gfs2_sbd *sdp, 
struct writeback_control *wbc)

  extern void gfs2_log_shutdown(struct gfs2_sbd *sdp);
  extern int gfs2_logd(void *data);
+extern int gfs2_logd2(void *data);
  extern void gfs2_add_revoke(struct gfs2_sbd *sdp, struct gfs2_bufdata 
*bd);
  extern void gfs2_write_revokes(struct gfs2_sbd *sdp);

diff --git a/fs/gfs2/super.c b/fs/gfs2/super.c
index a971862b186e..1d7f32c1960a 100644
--- a/fs/gfs2/super.c
+++ b/fs/gfs2/super.c
@@ -378,6 +378,7 @@ static int init_threads(struct gfs2_sbd *sdp)
  	int error = 0;

  	p = kthread_run(gfs2_logd, sdp, "gfs2_logd");
+	p = kthread_run(gfs2_logd2, sdp, "gfs2_logd2");
  	if (IS_ERR(p)) {
  		error = PTR_ERR(p);
  		fs_err(sdp, "can't start logd thread: %d\n", error);
@@ -1763,3 +1764,17 @@ const struct super_operations gfs2_super_ops = {
  	.show_options		= gfs2_show_options,
  };

+int gfs2_logd2(void *data)
+{
+	struct gfs2_sbd *sdp = data;
+
+	msleep(30000);
+
+	for (;;) {
+		msleep(100);
+		gfs2_log_flush(sdp, NULL, GFS2_LOG_HEAD_FLUSH_NORMAL |
+			       GFS2_LFC_LOGD_TEST);
+	}
+
+	return 0;
+}
diff --git a/include/uapi/linux/gfs2_ondisk.h 
b/include/uapi/linux/gfs2_ondisk.h
index 2dc10a034de1..ebae3a21c98e 100644
--- a/include/uapi/linux/gfs2_ondisk.h
+++ b/include/uapi/linux/gfs2_ondisk.h
@@ -431,6 +431,7 @@ struct gfs2_ea_header {
  #define GFS2_LFC_TRANS_END		0x01000000
  #define GFS2_LFC_LOGD_JFLUSH_REQD	0x02000000
  #define GFS2_LFC_LOGD_AIL_FLUSH_REQD	0x04000000
+#define GFS2_LFC_LOGD_TEST     0x08000000

  #define LH_V1_SIZE (offsetofend(struct gfs2_log_header, lh_hash))


Thanks,
-- 
Ross Lagerwall