|
Herbert
To be clear - are all your filesystems affected or just this one?
Peter
|
|
Herbert
An LNET engineer is examining the code in light of the messages you are seeing. Do you have any particular questions at this time? Do you want to pose these via the ticket or setup a concall?
Peter
|
|
In the syslog, I'm seeing:
Feb 20 07:50:21 kern:err:nbp8-mds1 LNetError: 2497:0:(o2iblnd_cb.c:2267:kiblnd_passive_connect()) Can't accept 10.151.40.87@o2ib on NA (ib1:0:10.151.27.60): bad dst nid 10.151.27.60@o2ib
This occurs when a node receives an RDMA_CM_EVENT_CONNECT_REQUEST, but the destination nid in the message doesn't correspond to any local NIs.
from the errors you pasted in the description all of them seem to revolve around nid: 10.151.27.60@o2ib.
Are there any issues around that node? Is it configured properly?
Seems like 10.151.40.87@o2ib is attempting to establish connection with 10.151.27.60@o2ib (which looks like the MGC in your setup), but that node, doesn't have a network interface configured with that NID.
|
|
More info... It looks like the MDS running in osp_sync_process_queues and it blocks all other process. It looks like is responding to clients but all console access and host access is hung. I am uploading process trace and a list of running process.
|
|
Looking at this newly uploaded log, it seems the problem is LU-5188.
I know you have this patch in your tree, but it appears to be incomplete. Here's your patch from your tree:
And the proper patch from our tree is:
So if you update the RETURN part of it - the problem should go away. Did you pick wrong version of the patch perhaps?
You might want to add LU-4743 to your tree that has a somewhat similar nature.
|
|
Also looking through LU-5188 you also need http://review.whamcloud.com/#/c/10828/4 as a follow on to that fix we have in our tree too.
|
|
Our LU-5188 patch was an early version. We tested with that patch and it seemed to have solved our
problem.
|
|
Could you take a look at our code at https://github.com/jlan/lustre-nas
'nas-2.4.3' branch, Oleg? Review http://review.whamcloud.com/#/c/10828/4 can not be applied cleanly.
Our code in osp_sync_process_record(), the default case of "switch (rec->lrh_type)" is as below:
default:
CERROR("unknown record type: %x\n", rec->lrh_type);
rc = -EINVAL;
break;
It sets rc and does a break. You do not set rc and did not have break.
|
|
Ah, if I picked up LU-4743 before LU-5188, then there would be no conflict.
|
|
Oleg likely will not be online for a few hours but he was talking about lu-4743 when he initially started looking at the info from Mahmoud. LU-4743 was landed for 2.5.2 and so has been widely exposed.
|
|
Thanks, Peter. I have resolved the conflict and built a set of new server rpms.
|
|
Great! Please continue to keep us informed
|
|
Got a LBUG with new patches in play
nbp8-mds1 login: Lustre: 4864:0:(client.c:1878:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1424540000/real 1424540001] req@ffff883fee2e5000 x1493738361717656/t0(0) o8->nbp8-OST005d-osc-MDT0000@10.151.27.77@o2ib:28/4 lens 400/544 e 0 to 1 dl 1424540105 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
Lustre: 4864:0:(client.c:1878:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1424540000/real 1424540001] req@ffff883fee0da400 x1493738361717612/t0(0) o8->nbp8-OST0076-osc-MDT0000@10.151.27.76@o2ib:28/4 lens 400/544 e 0 to 1 dl 1424540105 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
Lustre: 4864:0:(client.c:1878:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1424540001/real 1424540001] req@ffff883fec2ee800 x1493738361718180/t0(0) o8->nbp8-OST0103-osc-MDT0000@10.151.27.87@o2ib:28/4 lens 400/544 e 0 to 1 dl 1424540106 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
Lustre: 4864:0:(client.c:1878:ptlrpc_expire_one_request()) Skipped 179 previous similar messages
LustreError: 5529:0:(osp_sync.c:487:osp_sync_new_setattr_job()) nbp8-OST001b-osc-MDT0000: invalid setattr record, lsr_valid:68
LustreError: 5511:0:(osp_sync.c:888:osp_sync_thread()) ASSERTION( thread->t_flags != SVC_RUNNING ) failed: 1 changes, 1 in progress, 1 in flight
LustreError: 5511:0:(osp_sync.c:888:osp_sync_thread()) LBUG
Pid: 5511, comm: os p -s31yn o-0ut
of 32 cpus in kdb, waiting for the rest, timeout in 10 second(s)
Call Trace:
[<ffffffffa0489895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
[<ffffffffa0489e97>] lbug_with_loc+0x47/0xb0 [libcfs]
[<ffffffffa0f6c07a>] osp_sync_thread+0x76a/0x7e0 [osp]
[<ffffffffa0f6b910>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0ca>] child_rip+0xa/0x20
[<ffffffffa0f6b910>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffffa0f6b910>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
Kernel panic - not syncing: LBUG
Pid: 5511, comm: osp-syn-0 Not tainted 2.6.32-358.23.2.el6.20140115.x86_64.lustre243 #1
Call Trace:
[<ffffffff8153ef9e>] ? panic+0xa7/0x190
[<ffffffffa0489eeb>] ? lbug_with_loc+0x9b/0xb0 [libcfs]
[<ffffffffa0f6c07a>] ? osp_sync_thread+0x76a/0x7e0 [osp]
[<ffffffffa0f6b910>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0ca>] ? child_rip+0xa/0x20
[<ffffffffa0f6b910>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffffa0f6b910>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
|
|
Attaching full process trace for LBUG.
see service200.LBUG.gz
|
|
hm
so the sync thread exit prematurely. That's certainly unexpected.
I'll try to trigger this on my test system with some extra debug to better understand how does it exit like that all of a sudden.
|
|
Ok, so I see this problem also exists in master.
I am still digging around to see if this is the proper solution or if we want to change something else (hence no patch in gerrit),
but meanwhile this in-line patch should help you out, it certainyl does for me.
Please give it a try (against your tree, only needed on MDS):
|
|
no luck....
------------------------------------------------------------------------
nbp8-mds1 login: LustreError: 5418:0:(osp_sync.c:487:osp_sync_new_setattr_job()) nbp8-OST0000-osc-MDT0000: invalid setattr record, lsr_valid:68
LustreError: 5416:0:(osp_sync.c:891:osp_sync_thread()) ASSERTION( thread->t_flags != SVC_RUNNING ) failed: 18446744073709551615 changes, 0 in progress, 0 in flight
LustreError: 5416:0:(osp_sync.c:891:osp_sync_thread()) LBUG
31 out of 32 cpus in kdb, waiting for the rest, timeout in 10 second(s)
Pid: 5416, comm: osp-syn-78
Call Trace:
[<ffffffffa0489895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
[<ffffffffa0489e97>] lbug_with_loc+0x47/0xb0 [libcfs]
[<ffffffffa0f6c08a>] osp_sync_thread+0x76a/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0ca>] child_rip+0xa/0x20
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
LustreError: 5430:0:(osp_sync.c:891:osp_sync_thread()) ASSERTION( thread->t_flags != SVC_RUNNING ) failed: 18446744073709551615 changes, 0 in progress, 0 in flight
LustreError: 5430:0:(osp_sync.c:891:osp_sync_thread()) LBUG
Pid: 5430, comm: osp-syn-156
Call Trace:
[<ffffffffa0489895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
[<ffffffffa0489e97>] lbug_with_loc+0x47/0xb0 [libcfs]
[<ffffffffa0f6c08a>] osp_sync_thread+0x76a/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0ca>] child_rip+0xa/0x20
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
LustreError: 5426:0:(osp_sync.c:891:osp_sync_thread()) ASSERTION( thread->t_flags != SVC_RUNNING ) failed: 18446744073709551615 changes, 0 in progress, 0 in flight
LustreError: 5426:0:(osp_sync.c:891:osp_sync_thread()) LBUG
Pid: 5426, comm: osp-syn-234
Call Trace:
[<ffffffffa0489895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
[<ffffffffa0489e97>] lbug_with_loc+0x47/0xb0 [libcfs]
[<ffffffffa0f6c08a>] osp_sync_thread+0x76a/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0ca>] child_rip+0xa/0x20
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
Kernel panic - not syncing: LBUG
Pid: 5416, comm: osp-syn-78 Tainted: G W --------------- 2.6.32-358.23.2.el6.20140115.x86_64.lustre243 #1
Call Trace:
[<ffffffff8153ef9e>] ? panic+0xa7/0x190
[<ffffffffa0489eeb>] ? lbug_with_loc+0x9b/0xb0 [libcfs]
[<ffffffffa0f6c08a>] ? osp_sync_thread+0x76a/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0ca>] ? child_rip+0xa/0x20
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffffa0f6b920>] ? osp_sync_thread+0x0/0x7e0 [osp]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
.All cpus are now in kdb
Entering kdb (current=0xffff88200dcea040, pid 5416) on processor 10 Oops: (null)
due to oops @ 0x0
kdba_dumpregs: pt_regs not available, use bt* or pid to select a different task
[10]kdb>
|
|
Hm, so there's changes counter unedrflow in this case then that I don't see in my testing.
Thanks, I'll keep digging.
|
|
We reverted to running on 2.4.3-7nasS and the MDS came up. Will run on this until we get a more complete patch.
|
|
hm, so it came up and there was no chatter in the logs about invalid records anymore? Perhaps my path was just succesful enough to clear them out so your reversion was ok?
Did the crash happened soon after/immediately after MDS restart?
The invalid record you show was change of GID and CTIME which while technically should not have been possible, examining the code I see that in fact we did not ensure the exclusivity of the value until much later patch taht you don't have (LU-5296).
Something as simple as chgrp on an (old, as in existign for some time) file should have caused this. I am not advocating for you to try this on a production system, but if you have a test system where you can give this a try - that would be interesting.
|
|
Running 2.4.3-7nasS version risks a different kind of panic. 
|
|
we are moving backup to 13nasS
|
|
The crash would happen as soon as the OST connected.
|
|
Ok, so with this extra bit of info I see what was missing in my patch.
Should have been this:
But with the bad record gone - you do not really need it immediately until you obtain another one.
I did some more probing around and it seems that any chgrp (and potentially chown) on your filesystem will generate a bad record, though.
You probably can test this theory on a test filesystem of some sort.
|
|
Mahmoud/Jay
What is your current status? Is nobackupp8 back in service?
Peter
|
|
Hi Peter - The last status before the site team went quiet is that the file system is online with jobs running.
|
|
Mahmoud put 2.4.3-13nasS on nobackupp8, the version that were running when we ran into problems. However, it seems the situation that hit the site is not there and the production system has been stable.
Nevertheless, the bug is still there. We just hope it remains sleeping until you have a fix.
|
|
With lustre 2.4.3 how do we run a full lfsck? I can run on the MDT but I like to check the objects on the OSTs.
|
|
do you mean online lfsck or the offline version. I am not sure we support offline lfsck in 2.4, and online one was pretty basic at the time. Do you suspect any corruptions?
Additionally I wonder if you did a chgrp/chon experiment on a test fs by any chance to see if that is what generates the bad log records?
|
|
We are continuing to see the osp_sync error but we are not locking up the mds. We are running with you last patch provided here. It looks like these errors started showing up ~Feb 19 18:00:00. I have attached console log for reference.
I haven't test the chrp/chon yet but will try it out on the test filesystem.
I know we have had bad group/user ownership for OST object due a bug (I forget the LU) so we been struggling to get our blockquota correct. (I think https://jira.hpdd.intel.com/browse/LU-1267 fixed that issue) We must have some type of corruption and bad records that we need to clear-up.
Also, after recovery of the filesystem we have some users reporting file creation dates in the future.
|
|
Hm, so looking into your logs I see towards the end:
There are no log timestamps, but this certainly looks like symptoms before my patch.
Converting 1424413862 from unix seconds into normal time in EST timezone yields "Fri Feb 20 01:31:02 2015"? Is this the correct log uploaded? I wonder what current messages are that you are seeing?
Also please note that if you have any chown/chmod activity in your real filesystem - this is the message you will most likely see (but with no crash and not as many repetitions of course - my patch in comments here is what prevents repetitions/crashes). This is because you are also missing another follow on patch - from LU-5296.
When LU-4345 was ported to b2_5 it actually also included a number of other fixes as you can see in http://review.whamcloud.com/11435 and you miss some of them.
Time in the future might be a different problem - how much into the future?
Rearding the fsck, I just confirmed that old offline lfsck did not really pay any attention to object ownership so running that would not help bring your system into order.
I imagine best way to ensure correct ownership of objects in 2.4.3 is to just chown files to correct user/group (after you have LU-5296 fix!) all over again.
|
|
>Also please note that if you have any chown/chmod activity in your real filesystem - this is
> the message you will most likely see (but with no crash and not as many repetitions of
> course - my patch in comments here is what prevents repetitions/crashes). This is because
> you are also missing another follow on patch - from LU-5296.
The LU-5296 is a fix to a regression introduced in LU-4690 (commit #9511). Since we do not have LU-4690, should the regression affect us? The commit #9511 is a MAJOR patch that I am scared to pick up unless you provide us a 2.4.x (or at least a 2.5.x) version.
|
|
> When LU-4345 was ported to b2_5 it actually also included a number of other fixes as you
> can see in http://review.whamcloud.com/11435 and you miss some of them.
The version of LU-4345 patch we have here is patch set 1. Your final b2_4 patch for LU-4345 is patch set 7.
I will upgrade to patch set 7. BTW, it would be #10462/7, rather than #11435, which is for b2_5.
|
|
Well, the thing of the matter is that currently you are running with a unique set of patches that nobody else runs, so exposure is very little, as opposed to b2_5 that runs with patch 11435 that incorporates a number of fixes.
I specifically pointed at LU-5296 because it seems to be fixing a problem you seem to be fixing, namely this part (don't apply it alone, this is just a demonstration):
First hunk starts to really enforce filtering of what's placed into lsr_valid to ensure we only place there the two valid bits and nothing else. Before the patch all sorts of unrelated stuff might be set (CTIME is the most common - also seen in your logs) that trips the check in the second hunk. - this is a regression of sorts introduced by LU-4345 and that's why you need it, without any regards of possible interactions with LU-4690 that you are not carryign anyway.
change 10462 looks like a good one based on the list of patches in there (and some quick checks). The main risk remains that this is code that (next to) nobody have run, and even though it looks like almost identical to b2_5, there might be some other code paths not hit in b2_5 for example (there were after all changes in b2_5 compared to b2_4).
|
|
OK, the two code hunks you quoted above are in both patch LU-5296 (#10989) and in
LU-4345 ( #10462/7 and #11435). By saying "this is a regression of sorts introduced by LU-4345", I bet you meant to say earlier patch set, especially patch set #1 of #10462). So, either #10462/7 or #11435 of LU-4345 should fix the regression already. Am I correct?
If I am correct, then I do not really need LU-5296(#10989)? Or do I still need #10989 for other code fixes besides the two hunks?
Between #10462/7 and #11435, which one do you recommend us to pick? Remember we are running code based on b2_4.
It is kind of scary to know that we probably the only one running b2_4..., code paths the (next to) nobody have run...
|
|
you are correct that the regression was only part of patchset 1 and if you use 10462 patchset 7 then you should be fine.
11435 is not really applicable to your tree then as it's b2_5 based, I only brought it in as the example of what things you really needed, but I did not know there was a right-sized b2_4 backport too.
|
|
With patchset 7 of LU-4345 in place, do we still need the patch you provided at 21/Feb/15 7:47 PM?
|
|
Well. Once you have LU-4345 patchset 7, the only reason for my patch would be to combat the condition of disk corruption of an llog record - i.e. if somehow an llog record becomes corrupted in such a way that lsr_valid becomes invalid and triggers the check - you'll have a crash exactly like you had after applying the updated patch from LU-5188. Chance of that is much-much smaller than before so I imagine it's ok not to carry it until we hash out a final version.
|
|
Oleg, I just updated nas-2.5.3 to up to today of b2_5. It already has LU-4345, but b2_5 does not have LU-5188. Do I need to cherry-pick LU-5188 from master to nas-2.5.3?
|
|
b2_5 version of LU-4345 http://review.whamcloud.com/11435 already includes LU05188 patch as well, so you should be fine.
|
|
Emoly
Could you please turn Oleg's suggestion here - https://jira.hpdd.intel.com/browse/LU-6269?focusedCommentId=107620&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-107620 into a proper patch? Oleg has also suggested that you use a failloc to trigger this condition.
Thanks
Peter
|
|
OSP sync thread can't handle invalid record properly, see LU-5297.
|
|
Emoly Liu (emoly.liu@intel.com) uploaded a new patch: http://review.whamcloud.com/14806
Subject: LU-6269 osp: decrease opd_syn_changes for an invalid rec
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 1ecf3aff71b3ab3b6c6432d033535e31243878dc
|
|
The remaining work here will be tracked under LU-5297
|
|
Peter, do we need LU-5297 in 2.4.3 and 2.5.3? And, I guess I need Review #14806?
|
|
Jay
Review #14806 has been deprecated in favor of the approach being taken under LU-5297. This is a long-term improvement and need not be something you rush to pick up as a fix. You only ran into this issue in the first place due to confusion about patch versions that should no longer be a factor.
Peter
|
|
Thank you for clarification, Peter!
|
Generated at Sat Feb 10 01:58:45 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
nbp8-mds1.syslog