|
Repeat, got the full stack this time:
2015-08-25 12:33:20 Lustre: lustre-MDT0001: Imperative Recovery enabled, recovery window shrunk from 300-900 down to 150-450
2015-08-25 12:33:20 LustreError: 6140:0:(llog_osd.c:778:llog_osd_next_block()) ASSERTION( last_rec->lrh_index == tail->lrt_index ) failed:
2015-08-25 12:33:20 LustreError: 6134:0:(llog_osd.c:788:llog_osd_next_block()) lustre-MDT0005-osp-MDT0001: invalid llog tail at log id 0x3:1073742851/0 offset 3407872
2015-08-25 12:33:20 LustreError: 6134:0:(lod_dev.c:392:lod_sub_recovery_thread()) lustre-MDT0005-osp-MDT0001 getting update log failed: rc = -22
2015-08-25 12:33:20 LustreError: 6140:0:(llog_osd.c:778:llog_osd_next_block()) LBUG
2015-08-25 12:33:20 Pid: 6140, comm: lod0001_rec000b
2015-08-25 12:33:20
2015-08-25 12:33:20 Call Trace:
2015-08-25 12:33:20 [<ffffffffa04a2875>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
2015-08-25 12:33:20 [<ffffffffa04a2e77>] lbug_with_loc+0x47/0xb0 [libcfs]
2015-08-25 12:33:20 [<ffffffffa05f4d15>] llog_osd_next_block+0xb75/0xbf0 [obdclass]
2015-08-25 12:33:20 [<ffffffffa05e6b4e>] llog_process_thread+0x2de/0xfc0 [obdclass]
2015-08-25 12:33:20 [<ffffffffa05e78ed>] llog_process_or_fork+0xbd/0x5d0 [obdclass]
2015-08-25 12:33:20 [<ffffffffa12bc990>] ? lod_process_recovery_updates+0x0/0x420 [lod]
2015-08-25 12:33:20 [<ffffffffa05eadb8>] llog_cat_process_cb+0x458/0x600 [obdclass]
2015-08-25 12:33:20 [<ffffffffa05e71ba>] llog_process_thread+0x94a/0xfc0 [obdclass]
2015-08-25 12:33:20 [<ffffffffa05e78ed>] llog_process_or_fork+0xbd/0x5d0 [obdclass]
2015-08-25 12:33:20 [<ffffffffa05ea960>] ? llog_cat_process_cb+0x0/0x600 [obdclass]
2015-08-25 12:33:20 [<ffffffffa05e961d>] llog_cat_process_or_fork+0x1ad/0x300 [obdclass]
2015-08-25 12:33:20 [<ffffffffa12bc990>] ? lod_process_recovery_updates+0x0/0x420 [lod]
2015-08-25 12:33:20 [<ffffffffa12bc990>] ? lod_process_recovery_updates+0x0/0x420 [lod]
2015-08-25 12:33:20 [<ffffffffa04aebf1>] ? libcfs_debug_msg+0x41/0x50 [libcfs]
2015-08-25 12:33:20 [<ffffffffa05e9789>] llog_cat_process+0x19/0x20 [obdclass]
2015-08-25 12:33:20 [<ffffffffa12c1e4a>] lod_sub_recovery_thread+0x69a/0xbc0 [lod]
2015-08-25 12:33:20 [<ffffffffa12c17b0>] ? lod_sub_recovery_thread+0x0/0xbc0 [lod]
2015-08-25 12:33:20 [<ffffffff8109e78e>] kthread+0x9e/0xc0
2015-08-25 12:33:20 [<ffffffff8100c28a>] child_rip+0xa/0x20
2015-08-25 12:33:20 [<ffffffff8109e6f0>] ? kthread+0x0/0xc0
2015-08-25 12:33:20 [<ffffffff8100c280>] ? child_rip+0x0/0x20
Lustre log attached
|
|
Lustre log
|
|
I saw this on some master failures from last night. I attributed the failures to LU-3263. The assertions and stack traces look alike.
|
|
wangdi (di.wang@intel.com) uploaded a new patch: http://review.whamcloud.com/16084
Subject: LU-7039 llog: debug patches
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: de2d20f45a8e41a6e1510b596097e6c8ab270396
|
|
Cliff: could you please try this debug patch and get the debug log(-1 level) for me? thanks.
|
|
Per Cliff: we have tried the debug patch for a couple days and didn't get a debug log. Di is aware of this and will provide a new build.
|
|
cliff: could you please try the test with this build http://review.whamcloud.com/#/c/13942/ , I added a few debug information and also some fixes, which are not landed yet.
|
|
Same error happened during soak testing of build http://review.whamcloud.com/#/c/16685/
(see https://wiki.hpdd.intel.com/pages/viewpage.action?spaceKey=Releases&title=Soak+Testing+on+Lola#SoakTestingonLola-20150930)
Here's the stack trace:
Also attached the debug log. I hope it contains some usable informations.
|
|
debug log of MDS node lola-10
|
|
The node continuously panics with same error at the moment. On thing to add for the test set-up. AS we hit LDEV-193
MDTs are mounted with option 'abort_recovery'.
|
|
wangdi (di.wang@intel.com) uploaded a new patch: http://review.whamcloud.com/16714
Subject: LU-7039 llog: remove LASSERT check for record index
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: f07a1980bd1e5cb08a00108ef286adc6bad4b4ea
|
|
Frank, Cliff: I add some debug information in this patch. Could you please run test with this patch and collect -1 level debug log for me? Thank you.
|
|
yep, we'll create a build containing your patch and the fix for LDEV-24. Otherwise this bug has no chance to occur.
|
|
lola is updated with your patch, but MDSes crash on first mount.
|
|
A single debug message beside a LBUG was written:
|
|
According to the debug log
tail->lrt_len = 0 & tail->lrt_index = 0. Hmm, it seems update log is corrupted.
Frank: could you please mount MDT0 as ldiskfs,
and get me this file /mnt/mds1/update_log_dir/[0x2000284a3:0x2:0x0] and post it here. Thanks.
|
|
Sigh, according the debug log and real llog update file, it seems llog file is corrupted, and the end of llog file is filled with junks. Unfortunately there are no enough information to know why it is corrupted.
To fix the filesystem, it needs to mount all of MDTs as ldiskfs, and delete these files
Then restart lustre.
|
|
wangdi (di.wang@intel.com) uploaded a new patch: http://review.whamcloud.com/16740
Subject: LU-7039 llog: skip to next chunk for corrupt record
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: c612e7c78344b2ff88c0d5803b558c9991ab766f
|
|
This is not a real fix. Just fix log_reader to make it skip the corrupt records.
|
|
the same issue with LU-7100, but different llog
|
|
Di, I notice that changes made by you some time ago:
lgi->lgi_off = max_t(__u64, lgi->lgi_attr.la_size, lgi->lgi_off);
Not sure why that was made, could you explain that a bit? IIRC, that was done so because la_size may be not yet updated after first write, e.g. header, right?
If so then the same can happen with pad record, consider that pad was written, the lgi_off with offset is lost after that - it is rewriten by 0 for header update, but la_size may be not yet updated, so the record itself will overwrite the pad record.
The solution could be saving the lgi_off after pad writting in local variable and use it.
|
|
I've just cook the patch if that make sense: http://review.whamcloud.com/16771
|
|
Hmm, we suppose to update the size in osp cache, see osp_md_write(). Note: this is only for remote llog object, for local llog object, adding pad record will update la_size in time, since you also see this problem in LU-7100 for local log, so I doubt this is the reason.
|
|
If so, then we don't need max_t(__u64, lgi->lgi_attr.la_size, lgi->lgi_off); anymore, right? it can be just la_size always.
|
|
As I can see that obj->ooa may not exists, and it seems in most cases that is so, because it it is created just upon create of file what is not case with llog. Nevertheless, I agree that my suggestion doesn't explain corruption in local llog, I've added some debug in patch, let's wait for new issues.
|
|
Both patches installed for this bug + LDEV-24 patch that landed after creation of the build (see https://wiki.hpdd.intel.com/display/Releases/Soak+Testing+on+Lola#SoakTestingonLola-20151007) and the cleanup procedure was executed.
The error didn't happened since now.
The following error message was printed during failover of MDT-0004 from lola-10 --> lola-11 and on other MDSes, too:
Not sure whether it is related to this bug.
|
|
wangdi (di.wang@intel.com) uploaded a new patch: http://review.whamcloud.com/16797
Subject: LU-7039 tgt: Delete txn_callback correctly in tgt_init()
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 57daeb1473bbf2cf3c3cfde83890818beee55f28
|
|
wangdi (di.wang@intel.com) uploaded a new patch: http://review.whamcloud.com/16839
Subject: LU-7039 osp: set update req error once import invalid
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 946fbe320ab6f093885247ec8234f2e4a28b50dc
|
|
soak ran with build for CentOS-6.6 of build associated with change http://review.whamcloud.com/#/c/16838/
After reset of single MDS and remount the error occurred again:
|
|
I just figured out a way to reproduce the problem, and also prove my thought that the failure of llog records cause the corruption. I will update the patch.
|
|
I update the fix along with other DNE patches to http://review.whamcloud.com/16838 . After the test approved this actually works, I will update 16389.
|
|
Di, could you describe what caused llog corruption? Was it wrong usage of llog by external caller or problem inside llog itself?
|
|
Please check the test case replay single 117 in patch 16838. Basically it because of the llog header is not protected by lock when used by OSP for update log. Basically, it happens like this
1. For example OSP adds 3 updates into the OSP sending list. All of them will write to the same remote llog file. So they will share the same bitmap and log index etc. Though the bitmap in 2nd will include 1st's bit, and the 3rd includes both 1st and 2nd bits.
2. And the 1 updates failed for some reason, which might happen especially when we restart 2 MDTs at the same time in soak-test.
3. After recovery, it will keep writing 2nd and 3 rd updates, which might include 1st bitmap, but there are no 1st record because of the failure of step 2.
So right now, I will let all of updates in the sending list fail once this happen, then refresh the header and also llog size for the new RPC.
That said this probably not the reason for local log corruption. And another thing I do not understand is that why this just start to happen recently (since last 2 weeks)? I checked the recent commit for llog, and did not find any suspicious patch? Do you have any clue?
|
|
I don't see how the dt_attr_get() synchronized with dt_write() over OSP. As I can see there is no cache for attributes if llog wasn't created but opened. That means the dt_attr_get() will cause RPC to another server, but dt_write() might not be even applied remotely, so returned size might be smaller and llog will be corrupted as result. Is that true or I miss something?
|
|
the llog update (write + size update) is serialized by rpc_version, see osp_send_update_thread().
|
|
It is not about updates but about attr_get() which is not serialized with updates, so can return smaller size
|
|
They are serialize by lgh_lock in llog_cat_add_rec().
|
|
I don't see how lgh_lock helps here. Consider the following scenario:
- llog_osd_write() issues new record, write RPC is scheduled for another server
- new llog_osd_write() is called immediately and issues attr_get() RPC for the same llog to the remote server
- since these two RPCs are not serialized and were issued almost together technically the attr_get() RPC might return size value before write will be applied on remote server
This is not the case if llog write RPC is synchronous but it is not so, isn't it?
|
|
Hmm, Mike, I think you are right. We need update the size for the OSP object after write.
|
|
Do you mean to make opo_ooa exists all time? That would solve this problem I think.
|
|
Yes, I believe so. I added this fix to 16838 (along with a few other changes) and soak-test will try to see if this can resolve the corrupt issue.
|
|
wangdi (di.wang@intel.com) uploaded a new patch: http://review.whamcloud.com/16969
Subject: LU-7039 llog: update llog header and size
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 9191d9a7f79c739d71dc7652333b9f07456218ad
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/16797/
Subject: LU-7039 tgt: Delete txn_callback correctly in tgt_init()
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 44e9ec0b46fc46cc72bebbdc35e4a59a0397a81c
|
|
Di: For build '20151027' (https://wiki.hpdd.intel.com/display/Releases/Soak+Testing+on+Lola#SoakTestingonLola-20151027)
which doesn't include change 16797, as far as I can see, the problem is still present:
|
|
Frank: I updated http://review.whamcloud.com/16838, and added more debug information there. Could you please retry with the patch. Thanks.
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/16740/
Subject: LU-7039 llog: skip to next chunk for corrupt record
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 04f4023cf59b6e5a1634ba492cd813dcb1af0c7c
|
|
wangdi (di.wang@intel.com) uploaded a new patch: http://review.whamcloud.com/17199
Subject: LU-7039 recovery: abort update recovery once fails
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 70905df1d7ea16d50c927b6af9957bced89a0f3b
|
|
Just update, it seems corruption disappears in the build of 20151120, though we need run more test to confirm this. Currently the soak-test is blocked by LU-7456, and we will continue soak-test to check this problem once 7456 is fixed.
|
|
Just reminder, http://review.whamcloud.com/16969 and http://review.whamcloud.com/17199 are key fixes for this problem.
|
|
The error below happens during soak testing of change 16838 patch set #31 (no Wiki entry for build exits, yet) on cluster lola. DNE is enabled and MDSes are configured in active-active HA failover configuration.
- Primary resources of MDT lola-11 were failed back at Dec, 3 20:18.
The allocation of slabs increased continuously till ~ 31 GB till crash
- MDS node lola-11 crashed with oom-killer at Dec, 4 00:21 (local time). (see also
LU-7432)
- ptlrpc_cache seems to be the biggest consumer
Attached lola-11's messages, console log, vmcore-dmesg file, collectl (version V4.0.2-1) files (for time interval specified above). Also
attached files containing extracted counters for memory, slab totals and per slab allocation.
The crash dump has been saved to lola-1:/scratch/crashdumps/lu-7039/127.0.0.1-2015-12-04-00\:22\:36.
|
|
It turned out that the collectl raw files are to big to be uploaded to Jira. I saved them to lola-1:/scratch/crashdumps/lu-7039.
|
|
This OOM is not caused by llog corruption, so it is a new problem (LU-7517).
|
|
another instance on master DNE mode
https://testing.hpdd.intel.com/test_sets/b57ce146-bbfd-11e5-8506-5254006e85c2
client and server: lustre-master build#3305
|
|
Oleg Drokin (oleg.drokin@intel.com) merged in patch http://review.whamcloud.com/16969/
Subject: LU-7039 llog: update llog header and size
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: e1745ed18d8e28f3cf3d72df3b7ef50d83f36601
|
|
Landed for 2.8.0
|
Generated at Sat Feb 10 02:05:28 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
LU-7039.llog.txt.gz