Original problem has been reported by a customer (error msgs and LBUG with stack in Description for this ticket), but I have been able to reproduce this LBUG on a recent master build, by simulating/injecting the catalog full/ENOSPC situation in llog_cat_new_log(), with fail_loc=0x137/OBD_FAIL_MDS_LLOG_CREATE_FAILED (i.e., permanent failure/-ENOSPC), and then simply forcing multiple+concurrent attempts to create ChangeLog records by running just 6x occurrences of the "while true; do touch /mnt/lustre/foodir/<file>; done &" script, each using a different file (to avoid locking and thus concurrency) and this on a Client+Server single node setup.
And as a possible fix, I wonder if in llog_cat_add_rec() we really need to reset "cathandle->u.chd.chd_current_log" to NULL, upon -ENOSPC error returned from llog_cat_new_log().
Not doing so should avoid to have llog_cat_declare_add_rec() repeatedly and unnecessarily create new+partially initialized LLOGs/llog_handle and assigned to "cathandle->u.chd.chd_current_log", this without llog_init_handle() never being called to initialize "loghandle->lgh_hdr".
Faccini Bruno (bruno.faccini@intel.com) uploaded a new patch: https://review.whamcloud.com/30897
Subject: LU-10527 obdclass: don't recycle loghandle upon ENOSPC
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 693e2e9e33302b49b08dd1054e6418945121f81c
With my patch, I have not been able to get any occurence of the crash even running the known reproducer during hours.
Just for history.
I also faced similar problem but with a little bit different stack trace:
7620028.883060] Lustre: 130784:0:(llog_cat.c:93:llog_cat_new_log()) snx11035-MDD0000: there are no more free slots in catalog [7620028.895696] LustreError: 130969:0:(llog_cat.c:329:llog_cat_current_log()) ASSERTION( llh ) failed: [7620028.906765] LustreError: 130969:0:(llog_cat.c:329:llog_cat_current_log()) LBUG [7620028.915204] Pid: 130969, comm: mdt00_056 [7620028.919888] [7620028.919888] Call Trace: [7620028.924859] [<ffffffffa0503895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs] [7620028.932940] [<ffffffffa0504007>] lbug_with_loc+0x47/0xb0 [libcfs] [7620028.940167] [<ffffffffa0644a02>] llog_cat_current_log+0x2c2/0x2d0 [obdclass] [7620028.948527] [<ffffffffa0647d81>] llog_cat_add_rec+0x61/0x450 [obdclass] [7620028.956320] [<ffffffffa063f169>] llog_add+0x89/0x1c0 [obdclass] [7620028.963317] [<ffffffffa0f80ab6>] ? osd_attr_set+0x166/0x460 [osd_ldiskfs] [7620028.971293] [<ffffffffa0dc54e2>] mdd_changelog_store+0xf2/0x260 [mdd] [7620028.978887] [<ffffffffa0dd2b96>] mdd_changelog_data_store+0x1a6/0x280 [mdd] [7620028.987145] [<ffffffffa0ddb171>] mdd_attr_set+0x1081/0x17a0 [mdd] [7620028.994357] [<ffffffffa0e430dd>] mdt_attr_set+0x25d/0x5c0 [mdt] [7620029.001373] [<ffffffffa0e43a3d>] mdt_reint_setattr+0x5fd/0xe40 [mdt] [7620029.008868] [<ffffffffa0e3c6dd>] mdt_reint_rec+0x5d/0x200 [mdt] [7620029.015878] [<ffffffffa0e22abb>] mdt_reint_internal+0x4cb/0x760 [mdt] [7620029.023468] [<ffffffffa0e231eb>] mdt_reint+0x6b/0x120 [mdt] [7620029.031496] [<ffffffffa09285de>] tgt_request_handle+0x6fe/0xaf0 [ptlrpc] [7620029.039414] [<ffffffffa08d7979>] ptlrpc_main+0xe49/0x1930 [ptlrpc] [7620029.046727] [<ffffffff810096f0>] ? __switch_to+0xd0/0x320 [7620029.053162] [<ffffffff81525eee>] ? thread_return+0x4e/0x760 [7620029.059805] [<ffffffffa08d6b30>] ? ptlrpc_main+0x0/0x1930 [ptlrpc] [7620029.067103] [<ffffffff8109ac66>] kthread+0x96/0xa0 [7620029.072842] [<ffffffff8100c20a>] child_rip+0xa/0x20 [7620029.078677] [<ffffffff8109abd0>] ? kthread+0x0/0xa0 [7620029.084519] [<ffffffff8100c200>] ? child_rip+0x0/0x20
The problem exists due to race between 3 threads doing: t1:llog_cat_current_log, t2:llog_cat_current_log and t3: llog_cat_declare_add_rec.
- t3: llog_cat_declare_add_rec :: chd_next_log = loghandle /* loghandle is not initialized yet */
- t1: llog_cat_current_log :: llog is full thus up_read LLOGH_CAT and try to use next log with write sem
- t2: llog_cat_current_log :: llog is full thus up_read LLOGH_CAT and try to use next log with write sem
- t1: llog_cat_current_log :: holds write LOGH_CAT semaphore /* llog is still full -> try to use next */
- t1: llog_cat_current_log :: chd_current_log = chd_next_log /* chd_next_log is not initialized yet */
- t1: llog_cat_current_log :: up_write LOGH_CAT sem
- t2: llog_cat_currnet_log :: holds write LOGH_CAT sem
- t2: llog_cat_current_log :: LASSERT(llh);
I have successfully reproduced the problem on the latest master with a small delay in llog_cat_current_log:
diff --git a/lustre/obdclass/llog_cat.c b/lustre/obdclass/llog_cat.c
index 5f8b9d1..4587d94 100644
--- a/lustre/obdclass/llog_cat.c
+++ b/lustre/obdclass/llog_cat.c
@@ -377,6 +377,7 @@ static struct llog_handle *llog_cat_current_log(struct llog_handle *cathandle,
up_read(&cathandle->lgh_lock);
/* time to use next log */
+ schedule_timeout_interruptible(msecs_to_jiffies(2000));
Example of reproducer:
lctl --device lustre-MDT0000 changelog_register #define OBD_FAIL_CAT_RECORDS 0x1312 lctl set_param fail_loc=0x1312 lctl set_param fail_val=2 for i in $(seq 0 50); do mkdir /mnt/lustre/dir$i; done for i in $(seq 0 32768); do for j in $(seq 0 50); do touch /mnt/lustre/dir$j/f$i& done done
I also have reproduced it on master + https://review.whamcloud.com/30897.
I believe LASSERT(llh) is not needed anymore and can't be removed. In combine with existed 30897 patch this should totally solve the issue.
The problem also exists in lustre 2.x.
Thanks Sergey,
And as we have already discussed in #30897, I have also removed the LASSERT(llh) in llog_cat_current_log() in my original patch for this ticket, and successfully tested it against your and my reproducers.
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/30897/
Subject: LU-10527 obdclass: don't recycle loghandle upon ENOSPC
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 5761b9576d39c44c02455b86eb86ce1276930e60
Landed for 2.12
Sebastien Piechurski (sebastien.piechurski@atos.net) uploaded a new patch: https://review.whamcloud.com/33850
Subject: LU-10527 obdclass: don't recycle loghandle upon ENOSPC
Project: fs/lustre-release
Branch: b2_10
Current Patch Set: 1
Commit: 8e4d631e08409e7e42d92453c1117cdd8fc6f374
We just hit this MDT crash with 2.10, and MDT wouldn't start. I had to clear changelog_users/catalog to be able to start MDT again. Would be nice to backport this patch to b2_10 ASAP thanks. Our average changelogs rate on our oak-MDT0000 is 6800/sec. We still also have tons of occurrence of LU-11205 "Failure to clear the changelog for user 1", this might be related. Peter, can this be considered as critical/urgent?
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/33850/
Subject: LU-10527 obdclass: don't recycle loghandle upon ENOSPC
Project: fs/lustre-release
Branch: b2_10
Current Patch Set:
Commit: 51e962be60cf599ecf154ea3a6b1c0f9882daac2
Thanks! 
Patrick Farrell (pfarrell@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/34335
Subject: LU-10527 obdclass: don't recycle loghandle upon ENOSPC
Project: fs/lustre-release
Branch: b2_10
Current Patch Set: 1
Commit: 1307d8af3536514781e0a87c8d0ff3b19caae50d
This patch has come up as a possible culprit for dramatically increased MDT failover issues in soak testing - See LU-11943. Revert is just for testing at the moment, not actually proposing reverting it.
Removing the patch from the tip of b2_10 causes the abort rate on MDT failover to go 50% to 0%, so it's pretty clearly the culprit.
So:
The LU-10527 patch is causing failures on MDT failover (recovery aborting), reporting apparent llog corruption.
Messages vary, but this is a common example:
Feb 22 16:03:22 soak-10 kernel: LustreError: 12847:0:(llog.c:588:llog_process_thread()) soaked-MDT0003-osp-MDT0002: [0x1:0xc002abb4:0x2] Invalid record: index 4 but expected 2
Unless someone has a quick suggestion for a fix, intention is to revert the patch while we look for a solution.
Patrick Farrell (pfarrell@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/34346
Subject: LU-10527 llog: Reset current log on ENOSPC
Project: fs/lustre-release
Branch: b2_10
Current Patch Set: 1
Commit: 155f4e866fc8f14da2b082898c00c0643c8bc919
Patrick Farrell (pfarrell@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/34347
Subject: LU-10527 llog: Reset current log on ENOSPC
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 6ab95bb7d53a7c6831bcfc56ce0c29481fa39189
Switched from revert to hopeful fix...
So I think that this ticket can be closed - the fixes to the original issue were tracked under LU-11943