[LU-10593] Cannot mount client if SSK is setup over IB network

• Status: Open
• Project: Lustre
• Affects Version/s: Lustre 2.11.0
• Type: Bug
• Priority: Minor
• Reporter: Sarah Liu
• Assignee: James A Simmons
• Resolution: Unresolved
• Severity: 3

Description

This is an IB specific issue, has been seen on 2.10.1 and master branch. Test with same config on TCP pass.

This is what I got with IB network when trying to mount client. I have tried with different flavors (skpi, ski, gss null) and all failed with same error. The patch https://review.whamcloud.com/30937
doesn't help with this issue.

[104174.396583] LustreError: 48209:0:(gss_keyring.c:1426:gss_kt_update()) negotiation: rpc err -13, gss err 0
[104174.410110] LustreError: 48209:0:(gss_keyring.c:1426:gss_kt_update()) Skipped 4 previous similar messages
[104174.423357] Lustre: 48209:0:(sec_gss.c:316:cli_ctx_expire()) ctx ffff880824f1e540(0->lustre-MDT0000_UUID) get expired: 1517010602(+200s)
[104174.441414] Lustre: 48209:0:(sec_gss.c:316:cli_ctx_expire()) Skipped 4 previous similar messages
[104199.411600] Lustre: 45094:0:(sec_gss.c:1226:gss_cli_ctx_fini_common()) gss.keyring@ffff8807f2a62400: destroy ctx ffff88105aa0dec0(0->lustre-MDT0000_UUID)
[104199.432714] Lustre: 45094:0:(sec_gss.c:1226:gss_cli_ctx_fini_common()) Skipped 5 previous similar messages
[104249.405563] LustreError: 48222:0:(gss_keyring.c:1426:gss_kt_update()) negotiation: rpc err -13, gss err 0
[104249.418953] LustreError: 48222:0:(gss_keyring.c:1426:gss_kt_update()) Skipped 2 previous similar messages
[104249.432234] Lustre: 48222:0:(sec_gss.c:316:cli_ctx_expire()) ctx ffff88105aa0c180(0->lustre-MDT0000_UUID) get expired: 1517010677(+200s)
[104249.450371] Lustre: 48222:0:(sec_gss.c:316:cli_ctx_expire()) Skipped 2 previous similar messages
[104299.408796] Lustre: 45094:0:(sec_gss.c:1226:gss_cli_ctx_fini_common()) gss.keyring@ffff8807f2a62400: destroy ctx ffff88105aa0cf00(0->lustre-MDT0000_UUID)
[104299.429934] Lustre: 45094:0:(sec_gss.c:1226:gss_cli_ctx_fini_common()) Skipped 3 previous similar messages

Comments

[Peter Jones]

simmonsja and sbuisson is this a known issue?

[James A Simmons]

This is exactly my problem I see.

[Sebastien Buisson (Inactive)]

Hi Sarah, James,

I am trying to setup an IB-based test cluster to investigate this issue. In the meantime, do you have the opportunity to try again with debug activated on all nodes?

• lsvcgssd daemon launched with '-vv' flag;
• request-key debug: move /usr/sbin/request-key to /usr/sbin/request-key.orig, and create a shell script named /usr/sbin/request-key with following content:

  #!/bin/bash
  /usr/sbin/request-key.orig -d $*
  

• lctl set_param sptlrpc.gss.lgss_keyring.debug_level=4
• lctl set_param debug=+sec

Some debug info will be available in dmesg and lustre debug logs, but for userspace debug info you will have to use journalctl.

Thanks,
Sebastien.

[Sarah Liu]

client console

[ 1060.602386] LustreError: 4000:0:(gss_keyring.c:849:gss_sec_lookup_ctx_kr()) failed request key: -13
[ 1060.612583] LustreError: 4000:0:(sec.c:448:sptlrpc_req_get_ctx()) req ffff880842b90300: fail to get context
[ 1060.623549] LustreError: 4000:0:(lmv_obd.c:319:lmv_connect_mdc()) target lustre-MDT0000_UUID connect error -111
[ 1060.634916] LustreError: 4000:0:(llite_lib.c:284:client_common_fill_super()) cannot connect to lustre-clilmv-ffff8801738d6000: rc = -111
[ 1060.741909] LustreError: 4000:0:(lov_obd.c:876:lov_cleanup()) lustre-clilov-ffff8801738d6000: lov tgt 0 not cleaned! deathrow=0, lovrc=1
[ 1060.757081] Lustre: Unmounted lustre-client
[ 1060.762761] LustreError: 4000:0:(obd_mount.c:1583:lustre_fill_super()) Unable to mount  (-111)
mount.lustre: mount onyx-80-ib@o2ib:/lustre at /mnt/lustre failed: Connection refused
[root@onyx-79 ~]# 

MDS dmesg. MDS debug please see attached

[  742.528583] alg: No test for adler32 (adler32-zlib)
[  742.534137] alg: No test for crc32 (crc32-table)
[  743.298513] Lustre: Lustre: Build Version: 2.10.57_57_g98ddc99
[  743.369060] LNet: Using FMR for registration
[  743.404231] LNet: Added LNI 192.168.1.80@o2ib [8/256/0/180]
[  743.413664] LNet: Added LNI 10.2.2.52@tcp [8/256/0/180]
[  743.419594] LNet: Accept secure, port 988
[  743.519797] LDISKFS-fs (sdb1): recovery complete
[  743.530730] LDISKFS-fs (sdb1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc
[  743.740193] Lustre: MGS: Connection restored to 9eed7cd8-6b21-4821-b7ce-181f90e7c677 (at 0@lo)
[  745.368317] LNet: 3884:0:(o2iblnd_cb.c:3294:kiblnd_check_conns()) Timed out tx for 192.168.1.82@o2ib: 4295411 seconds
[  745.406187] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 300-900
[  758.369573] LNet: 3884:0:(o2iblnd_cb.c:3294:kiblnd_check_conns()) Timed out tx for 192.168.1.82@o2ib: 4295424 seconds
[  770.387018] Lustre: lustre-MDT0000: Connection restored to 9eed7cd8-6b21-4821-b7ce-181f90e7c677 (at 0@lo)
[  771.370844] LNet: 3884:0:(o2iblnd_cb.c:3294:kiblnd_check_conns()) Timed out tx for 192.168.1.82@o2ib: 4295437 seconds
[  796.373327] LNet: 3884:0:(o2iblnd_cb.c:3294:kiblnd_check_conns()) Timed out tx for 192.168.1.82@o2ib: 4295462 seconds
[  821.375835] LNet: 3884:0:(o2iblnd_cb.c:3294:kiblnd_check_conns()) Timed out tx for 192.168.1.82@o2ib: 4295487 seconds
[  827.771270] Lustre: MGS: Connection restored to d1e5edfc-64c0-4708-b7f3-ab19e20a579e (at 192.168.1.82@o2ib)
[  835.247329] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.1.82@o2ib (at 192.168.1.82@o2ib)
[  835.258711] Lustre: Skipped 1 previous similar message
[ 1039.470883] Lustre: MGS: Connection restored to 3bb9b7f5-bfdf-013f-4c84-dc859d55a7ec (at 192.168.1.79@o2ib)
[ 1064.301828] Lustre: MGS: Connection restored to 3bb9b7f5-bfdf-013f-4c84-dc859d55a7ec (at 192.168.1.79@o2ib)
[root@onyx-80 ~]# 

[Jeremy Filizetti]

Did you add the debugging the Sebastien asked? Without that information from the client it will be hard to see what is wrong since it appears to be during the request-key portion.

I have ran into an issue where the server side lsvcgss loses access to the key for some reason. This may require me to rework the key handling so that keys remain associated with lustre processes. However, this returns a GSS error to the client not an RPC error so it's a different issue.

[Sebastien Buisson (Inactive)]

True Jeremy

Hopefully I managed to reproduce the issue on a test system at DDN (negotiation: rpc err -13, gss err 0). I figured out how to make it work with Kerberos, but I guess it would be the same with Shared Key.

The issue stems from the fact that context negotiation process needs to perform name resolution at some point:

lgssc_kr_negotiate_{krb,manual}
   lgss_get_service_str
      ipv4_nid2hostname
         lnet_nid2hostname

So in order to make it work, your Lustre nodes' NIDs on IB must have an associated hostname that can be resolved by each other node. With Kerberos, the credentials must be created for these IB-based hostnames.

It explains why it works out of the box when using a TCP based interconnect network. NIDs naturally match nodes' hostnames

Do you agree to close this ticket with 'configuration issue' as the reason?

Cheers,
Sebastien.

[James A Simmons]

No I would consider this a real bug. Not all interconnects have IP address. Consider the Cray Gemini interconnects. Also discussion is under way about using the IB hardware address instead of an IP address as a lookup in the lnet layer. That change will then make IB totally unusable. We do need a proper solution.

[Sebastien Buisson (Inactive)]

James,

I would tend to consider what you suggest as an enhancement or feature request. Even in the case of using the IB hardware address instead of an IP address as a lookup in the lnet layer, Kerberos credentials must be associated to nodes. So probably that would mean adapting the way name resolution is carried out today, once this change for IB hardware address is done...

Sebastien.

[Sarah Liu]

Sebastien,

1. the above logs was with debug enabled.
2. I used hostname when mount

on MDS ping client. and vice versa

[root@onyx-80 ~]# lctl ping onyx-79-ib@o2ib
This command has been deprecated. Plesae use 'lnetctl ping'
12345-0@lo
12345-192.168.1.79@o2ib
12345-10.2.2.51@tcp
[root@onyx-80 ~]# 

[root@onyx-79 ~]# lctl ping onyx-80-ib@o2ib
This command has been deprecated. Plesae use 'lnetctl ping'
12345-0@lo
12345-192.168.1.80@o2ib
12345-10.2.2.52@tcp
[root@onyx-79 ~]

[Sebastien Buisson (Inactive)]

> Not all interconnects have IP addresses.

For this kind of interconnect there is already an existing mechanism in Lustre. You can put a script named /etc/lustre/nid2hostname on all your nodes, which takes 3 parameters:

• $lnd is a string identifying the LND, like "PTL4LND"
• $netid is the network identifier in hex format, like "0x12"
• $nid is the NID in hex format
  The script is supposed to output the corresponding hostname, or an error message starting with '@' for error logging.

Note that at the moment this script is only called in the case of a PTL4LND interconnect type, as QSWLND or GMLND for instance were deprecated by patch https://review.whamcloud.com/23621 some time ago.

[sebg-crd-pm (Inactive)]

Does SSK function available on Lustre 2.12 or 2.10.6  IB network ?

I have test Lustre 2.12 or 2.10.6 (IB network) also got the same error.

[ 877.959783] LustreError: 14203:0:(gss_keyring.c:1423:gss_kt_update()) negotiation: rpc err -13, gss err 0
[ 877.959878] Lustre: 14203:0:(sec_gss.c:315:cli_ctx_expire()) ctx ffff8b207acc3200(0->testfs-MDT0000_UUID) get expired: 1549873937(+200s)
[ 877.968204] Lustre: 13621:0:(sec_gss.c:1225:gss_cli_ctx_fini_common()) gss.keyring@ffff8b207c897300: destroy ctx ffff8b2077e8fec0(0->testfs-MDT0000_UUID)
[ 877.968213] Lustre: 13621:0:(sec_gss.c:1225:gss_cli_ctx_fini_common()) Skipped 1 previous similar message
[ 978.206863] LustreError: 14303:0:(gss_keyring.c:1423:gss_kt_update()) negotiation: rpc err -13, gss err 0

 

[Jeremy Filizetti]

The problem Sebastien pointed out with hostname resolution is probably your issue.  You will need to resolve the reverse lookup for your IB addresses.

 

You can increase debugging on the client with:

 

[root@r01svr1 ~]# echo 3 > /proc/fs/lustre/sptlrpc/gss/lgss_keyring/debug_level

 

And look in you logs for something similar to:

 

Feb 12 14:48:45 r01svr1 lgss_keyring: [22410]:INFO:main(): key 441386067, desc 0@e, ugid 0:0, sring 279671070, coinfo 14:sk:0:0:r:n:1:0x500000a0a0a13:SiteA2-MDT0000-mdc-ffff964c12745800:0x500000a0a0601:1
Feb 12 14:48:45 r01svr1 lgss_keyring: [22410]:DEBUG:parse_callout_info(): parse call out info: secid 14, mech sk, ugid 0:0, is_root 1, is_mdt 0, is_ost 0, svc type n, svc 1, nid 0x500000a0a0a13, tgt SiteA2-MDT0000-mdc-ffff964c12745800, self nid 0x500000a0a0601, pid 1
Feb 12 14:48:45 r01svr1 lgss_keyring: [22410]:INFO:sk_create_cred(): Creating credentials for target: SiteA2-MDT0000-mdc-ffff964c12745800 with nodemap: (null)
Feb 12 14:48:45 r01svr1 lgss_keyring: [22410]:INFO:sk_create_cred(): Searching for key with description: lustre:SiteA2
Feb 12 14:48:45 r01svr1 lgss_keyring: [22411]:ERROR:ipv4_nid2hostname(): O2IBLND: can't resolve 0x130a0a0a
Feb 12 14:48:45 r01svr1 lgss_keyring: [22411]:ERROR:lgss_get_service_str(): cannot resolve hostname from nid 500000a0a0a13
Feb 12 14:48:45 r01svr1 lgss_keyring: [22411]:ERROR:lgssc_kr_negotiate_manual(): key 1a4f0453: failed to construct service string

 

 

[sebg-crd-pm (Inactive)]

The log ssk_20190213.logseems got the same hostname resolution issue.

 

You will need to resolve the reverse lookup for your IB addresses.

=>What should I  do anything for resolve  IB addresses ?

 

[Jeremy Filizetti]

Just make sure you when you do an "nslookup <ipoib address>" it resolves to a hostname and things should progress beyond that issue.