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

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

[Ross Lagerwall]

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:

[  862.335390] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: 
Trying to acquire journal lock...
[  862.364578] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: 
Looking at journal...
[  862.475108] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: 
Acquiring the transaction lock...
[  862.475110] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: 
Replaying journal...
[  862.475538] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: 
Replayed 1 of 4 blocks
[  862.475539] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: Found 
3 revoke tags
[  862.484394] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: 
Journal replayed in 149ms [jlck:29ms, jhead:110ms, tlck:0ms, replay:9ms]
[  862.484431] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: recover jid 
0 result success
[  862.484434] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: jid=0: Done
[  862.484545] gfs2: fsid=xapi-clusterd:9f0b3587-c0f3-c8.1: recover 
generation 4 done
[  863.362577] DBG: log_blks_free = 14838 jd_blocks = 8192
[  863.362578] DBG: dist = 6663 new_tail = 1025 sd_log_tail = 2554
[  863.362579] DBG: sd_log_head = 1025 sd_log_head_flush = 1027
[  863.362579] DBG: sd_log_idle = 0
[  863.362580] DBG: sd_ail1_list empty? = yes

It looks to me that something messes with sd_log_tail and 
sd_log_head/sd_log_head_flush during recovery which causes a subsequent 
call to gfs2_log_flush() to hit the assertion.

Any ideas about this?

Thanks,
-- 
Ross Lagerwall

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

[Bob Peterson]

----- 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.

Regards,

Bob Peterson
Red Hat File Systems

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

[Ross Lagerwall]

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, "

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

[Bob Peterson]

----- 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.

Regards,

Bob Peterson
Red Hat File Systems

[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

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

[Bob Peterson]

Hi Ross,

----- Original Message -----
> > I think the problem may actually be a regression with patch 588bff95c94ef.
> 
> 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.

Hi Ross,

Okay, it looks like I really screwed up patch 588bff95c94ef. The patch
I posted yesterday is grossly inadequate and that code path needs some major
fixing. I'm in the process of getting it fixed properly. Sorry I didn't
cc you on that last patch. I'll cc you on the new one when it's ready, but
it may take a couple hours to get it ready.

Regards,

Bob Peterson
Red Hat File Systems