[LU-11826] Cannot send after transport endpoint shutdown

• Type: Bug
• Resolution: Fixed
• Priority: Minor
• Affects Version/s: Lustre 2.10.6
• Environment: CentOS 7.4
• Severity: 3
• Assignee: Oleg Drokin
• Reporter: Campbell Mcleay (Inactive)

Description

When running multiple rm's of files, we get the following error in the shell:

/bin/rm: cannot remove '</some/file/path>’: Cannot send after transport endpoint shutdown

These coincide with the following error in /var/log/messages:

 Dec 24 11:13:09 foxtrot2 kernel: LustreError: 11-0: foxtrot-MDT0000-mdc-ffff883ff6b12800: operation mds_close to node 10.21.22.10@tcp failed: rc = -107Dec 24 11:13:09 foxtrot2 kernel: Lustre: foxtrot-MDT0000-mdc-ffff883ff6b12800: Connection to foxtrot-MDT0000 (at 10.21.22.10@tcp) was lost; in progress operations using this service will wait for recovery to completeDec 24 11:13:09 foxtrot2 kernel: LustreError: 167-0: foxtrot-MDT0000-mdc-ffff883ff6b12800: This client was evicted by foxtrot-MDT0000; in progress operations using this service will fail.Dec 24 11:13:09 foxtrot2 kernel: LustreError: 3598:0:(mdc_locks.c:1211:mdc_intent_getattr_async_interpret()) ldlm_cli_enqueue_fini: -5Dec 24 11:13:09 foxtrot2 kernel: LustreError: 3598:0:(mdc_locks.c:1211:mdc_intent_getattr_async_interpret()) Skipped 37 previous similar messagesDec 24 11:13:09 foxtrot2 kernel: LustreError: Skipped 50 previous similar messagesDec 24 11:13:09 foxtrot2 kernel: LustreError: 39322:0:(llite_lib.c:1512:ll_md_setattr()) md_setattr fails: rc = -5Dec 24 11:13:09 foxtrot2 kernel: LustreError: 38248:0:(file.c:172:ll_close_inode_openhandle()) foxtrot-clilmv-ffff883ff6b12800: inode [0x200030875:0x5d11:0x0] mdc close failed: rc = -107Dec 24 11:13:09 foxtrot2 kernel: LustreError: 38248:0:(file.c:172:ll_close_inode_openhandle()) Skipped 743 previous similar messagesDec 24 11:13:09 foxtrot2 kernel: LustreError: 41760:0:(vvp_io.c:1474:vvp_io_init()) foxtrot: refresh file layout [0x2000302ba:0x103db:0x0] error -108.Dec 24 11:13:09 foxtrot2 kernel: LustreError: 41760:0:(vvp_io.c:1474:vvp_io_init()) Skipped 310070 previous similar messagesDec 24 11:13:09 foxtrot2 kernel: LustreError: 44300:0:(mdc_request.c:1329:mdc_read_page()) foxtrot-MDT0000-mdc-ffff883ff6b12800: [0x20002cfcf:0x5a20:0x0] lock enqueue fails: rc = -108Dec 24 11:13:09 foxtrot2 kernel: LustreError: 39322:0:(llite_lib.c:1512:ll_md_setattr()) Skipped 5 previous similar messagesDec 24 11:13:09 foxtrot2 kernel: LustreError: 12816:0:(vvp_io.c:1474:vvp_io_init()) foxtrot: refresh file layout [0x200030766:0x18539:0x0] error -108.Dec 24 11:13:09 foxtrot2 kernel: LustreError: 39252:0:(vvp_io.c:1474:vvp_io_init()) foxtrot: refresh file layout [0x2000302ba:0x10403:0x0] error -108.Dec 24 11:13:09 foxtrot2 kernel: LustreError: 39252:0:(vvp_io.c:1474:vvp_io_init()) Skipped 143616 previous similar messagesDec 24 11:13:09 foxtrot2 kernel: LustreError: 44302:0:(file.c:172:ll_close_inode_openhandle()) foxtrot-clilmv-ffff883ff6b12800: inode [0x20000070c:0x2ea9:0x0] mdc close failed: rc = -108Dec 24 11:13:09 foxtrot2 kernel: LustreError: 44302:0:(file.c:172:ll_close_inode_openhandle()) Skipped 815 previous similar messagesDec 24 11:13:09 foxtrot2 kernel: LustreError: 12816:0:(vvp_io.c:1474:vvp_io_init()) Skipped 2986 previous similar messagesDec 24 11:13:10 foxtrot2 kernel: Lustre: foxtrot-MDT0000-mdc-ffff883ff6b12800: Connection restored to 10.21.22.10@tcp (at 10.21.22.10@tcp)

Issue Links

• is related to: LU-10945 Race between sending bl ast and lock cancel

Comments

[Oleg Drokin]

The ported patch is here: https://review.whamcloud.com/#/c/34131/

I hoped it would be done testing by now, but apparently we have some test system slowness where results take awhile to become available.

[Campbell Mcleay (Inactive)]

Hi Oleg,

Thanks, we'll try the patch, so let's go ahead with that.

Kind regards,

Campbell

[Oleg Drokin]

Thank you for the logs, these ones are helpful, though I wonder what version do you really run, since some of the messages in there don't appear to match my copy of 2.10.6

Anyway the issue you are hitting appears to be LU-10945, the telltale message in your logs is this:

00010000:00010000:27.0:1548163854.268356:0:4761:0:(ldlm_lockd.c:1685:ldlm_request_cancel()) ### server cancels blocked lock after 1548163854s ns: mdt-foxtrot-MDT0000_UUID lock: ffff8822c3821200/0x13866dfbc82358f1 lrc: 4/0,0 mode: PR/PR res: [0x20002f6d0:0x15746:0x0].0x0 bits 0x1b rrc: 5 type: IBT flags: 0x40200000000020 nid: 10.21.22.32@tcp remote: 0xc849fe70b80233f8 expref: 220164 pid: 7423 timeout: 0 lvb_type: 0

The patch https://review.whamcloud.com/#/c/32133/3 should help you except it does not apply to the b2_10 tree, I'll make a port.

Do you have ability to self-build Lustre with the patch (only MDS and OSSes would need the patched code)?

[Campbell Mcleay (Inactive)]

Hi Oleg,

Have uploaded the logs parsed via lctl df as well.

Thanks,

Campbell

[Oleg Drokin]

hm... How were these logs produced? I don't see any evictions in there?

I guess I failed to mention that when you have the dump on eviction setup, there would be /tmp/lustre-log-TIMESTAMP files dropped for every event that are all binary that you need to pass through "lctl df" to turn into text. It's those files that we need. Hopefully they are still there?

the lctl df step is not necessary, we can run that ourselves.

[Campbell Mcleay (Inactive)]

Hi Oleg,

Did you get a chance to take a look at those logs, and if so, were you able to determine what the issue was? 

Kind regards,

Campbell

[Campbell Mcleay (Inactive)]

Hi Oleg,

Two of the three clients lost connection with the MDS. Have dumped the logs out and ftp'ed them up. File names are:

fmds1-lustre.log.220119.gz

foxtrot2-lustre.log.220119.gz

foxtrot3-lustre.log.220119.gz

Regards,

Campbell

[Campbell Mcleay (Inactive)]

Thank you very much Oleg, that's a very handy parameter. I have set this on the clients and the MDS and resumed the deletes. Might take a little while for it to trigger, will send the results through if it disconnects again.

[Oleg Drokin]

I just noticed that you only capture 5 minutes of log in 3G, that might be enough since a normal lock timeout is like 200s and ast timeout is only about 7s.

[Oleg Drokin]

it's weird that your logs literally start with an eviction:

00010000:00020000:51.1F:1545412061.748721:0:0:0:(ldlm_lockd.c:333:waiting_locks_
callback()) ### lock callback timer expired after 0s: evicting client at 10.21.2
2.32@tcp  ns: mdt-foxtrot-MDT0000_UUID lock: ffff88268bb39400/0x13866bc8bdb565ba
 lrc: 4/0,0 mode: PR/PR res: [0x20002a5ed:0x16aa8:0x0].0x0 bits 0x1b rrc: 3 type
: IBT flags: 0x60200400000020 nid: 10.21.22.32@tcp remote: 0xc849fe3bc093e756 ex
pref: 63841 pid: 20017 timeout: 0 lvb_type: 0

it makes no sense to run days of logs on the clients waiting for the eviction, but you can set "dump logs on eviction" flag and so every time a client is evicted it would dump some logs, the first one would be containing all the history.
you can do this by setting dump_on_eviction=1 with lctl set_param on every client and on the mdt.

Also I don't see any evictions at 1547661781 timestamp in the logs, the preceedign evictions are at 1545663407 which clearly is too long ago and the next evictions are at 1547669576 which is 2+ hours way from your specified time (timezone calculation problem?) and does not match the eviction profile we saw in the initial report (ast timeout). In fact at no time we see "failed to reply to blocking AST" message in the mdt log.

Unfortunately the locks you gathered when you did already became kind of fragmented, so it would be really great if you can capture something from clients and servers using the dump on eviction method above (Lustre has three tier logging so even when logs start with a particular timestamp that does not mean there are no gaps in between those entries)

[Campbell Mcleay (Inactive)]

Hi,

Did you find anything of interest in the log I sent? Or do you need the client log? I'm finding it difficult to capture the log on the client as it may take a few days to trigger it and I can't watch it all the time. Even with 4GB of memory assigned to the debug log size, it only seems to capture 5 minutes worth (though the log is 3GB in size)

Regards,

Campbell