Ceph » CephFS

The MDS log has the dump of session in up:reconnect state

2024-03-14T14:03:56.980+0000 7f29eeee7700  4 mds.0.30 apply_blocklist: killed 0, blocklisted sessions (25 blocklist entries, 1)
2024-03-14T14:03:56.980+0000 7f29eeee7700  1 mds.0.server reconnect_clients -- 1 sessions
2024-03-14T14:03:56.980+0000 7f29eeee7700 10 mds.0.sessionmap dump
2024-03-14T14:03:56.980+0000 7f29eeee7700 10 mds.0.sessionmap client.70093 0x55681f13f900 state open completed {} free_prealloc_inos [] delegated_inos []

and the reclaim message from the client came in later

2024-03-14T14:04:51.793+0000 7f29eeee7700  3 mds.0.server handle_client_reclaim client_reclaim(ganesha-controller-2-03e9 flags 0x1) v1 from client.101504

at this point, the MDS should have found the old session with the uuid, but it didn't.

I'm going to push a PR that adds some debug logs when the session with a uuid isn't found. Also, the reclaim reply message sent back to the client does not dump the reclaimed client addr. Those can be added for debugging.

debug pr to log missing session: https://github.com/ceph/ceph/pull/57859

When replaying the journal, there is a series of open -> close -> open for some sessions. E.g.:

2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4276642~121 / 4314625 2024-03-14T12:12:46.476034+0000: ESession client.56097 172.17.3.37:0/3465111544 close cmapv 43
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal ESession.replay sessionmap 42 < 43 close client.56097 172.17.3.37:0/3465111544
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal  removed session client.56097 172.17.3.37:0/3465111544
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.sessionmap remove_session s=0x55681f13e500 name=client.56097
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4276783~155 / 4314625 2024-03-14T12:14:12.519419+0000: ESession client.70093 172.17.3.37:0/149367982 open cmapv 44
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal ESession.replay sessionmap 43 < 44 open client.70093 172.17.3.37:0/149367982
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal  opened session client.70093 172.17.3.37:0/149367982
2024-03-14T14:03:55.999+0000 7f29e76d8700 20 mds.0.sessionmap replay_dirty_session s=0x55681f13e500 name=client.70093 v=43
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4276958~121 / 4314625 2024-03-14T12:14:13.125078+0000: ESession client.27141 172.17.3.37:0/601521236 close cmapv 45
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal ESession.replay sessionmap 44 < 45 close client.27141 172.17.3.37:0/601521236
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal  removed session client.27141 172.17.3.37:0/601521236
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.sessionmap remove_session s=0x55681f13ea00 name=client.27141
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4277099~121 / 4314625 2024-03-14T12:14:13.131195+0000: ESession client.70093 172.17.3.37:0/149367982 close cmapv 46
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal ESession.replay sessionmap 45 < 46 close client.70093 172.17.3.37:0/149367982
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal  removed session client.70093 172.17.3.37:0/149367982
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.sessionmap remove_session s=0x55681f13e500 name=client.70093
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4277240~528 / 4314625 2024-03-14T12:14:13.143734+0000: ESession client.70093 172.17.3.37:0/149367982 open cmapv 47
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal ESession.replay sessionmap 46 < 47 open client.70093 172.17.3.37:0/149367982
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal  opened session client.70093 172.17.3.37:0/149367982
2024-03-14T14:03:55.999+0000 7f29e76d8700 20 mds.0.sessionmap replay_dirty_session s=0x55681f13f900 name=client.70093 v=46
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4277788~386 / 4314625 2024-03-14T12:43:09.039075+0000: ESession client.76035 172.17.3.37:0/2206945919 open cmapv 48
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal ESession.replay sessionmap 47 < 48 open client.76035 172.17.3.37:0/2206945919
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.journal  opened session client.76035 172.17.3.37:0/2206945919
2024-03-14T14:03:55.999+0000 7f29e76d8700 20 mds.0.sessionmap replay_dirty_session s=0x55681f13fe00 name=client.76035 v=47

Consider the session client.70093 (which is the session that reclaimed)

2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4276783~155 / 4314625 2024-03-14T12:14:12.519419+0000: ESession client.70093 172.17.3.37:0/149367982 open cmapv 44
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4277099~121 / 4314625 2024-03-14T12:14:13.131195+0000: ESession client.70093 172.17.3.37:0/149367982 close cmapv 46
2024-03-14T14:03:55.999+0000 7f29e76d8700 10 mds.0.log _replay 4277240~528 / 4314625 2024-03-14T12:14:13.143734+0000: ESession client.70093 172.17.3.37:0/149367982 open cmapv 47

Why does this happen? I'd expect a ESession(.., open, ...) and only a ESession(..., close, ...) when the client disconnects.

FYI - this issues seems to happen during upgrade, but not totally sure. I'll have to reconfirm/retest.

https://github.com/ceph/ceph/pull/57859 which a debug change to be able to aid in debugging when this happens again has been merged.

ymo zhang wrote in #note-8:

hello Venky Shankar
I also encountered this problem during my recent test.

[...]

Through the analysis of the MDS logs, a scenario was discovered: after receiving the reclaim_reply, the lib sets the UUID and then sends MClientSession(request_close). Since the MDS status is still in client_replay, this message is placed in wait_for_active. When the MDS recovers to active_start, MClientSession(request_close) performs MsgRetry. While the close message is waiting for the callback _session_logged, at this time, MClientSession(request_open) sent by the lib due to the active state change of handle_mds_map is received. As the previous session information has not been removed by the close yet, the UUID is still cached in the MDS, resulting in failure.

[...]
[...]
[...]

!!

Please confirm if it is helpful to solve this problem. Thanks !!

Thanks for the detailed information. I will have a look today.

ymo zhang wrote in #note-8:

hello Venky Shankar
I also encountered this problem during my recent test.

[...]

Through the analysis of the MDS logs, a scenario was discovered: after receiving the reclaim_reply, the lib sets the UUID and then sends MClientSession(request_close). Since the MDS status is still in client_replay, this message is placed in wait_for_active. When the MDS recovers to active_start, MClientSession(request_close) performs MsgRetry. While the close message is waiting for the callback _session_logged, at this time, MClientSession(request_open) sent by the lib due to the active state change of handle_mds_map is received. As the previous session information has not been removed by the close yet, the UUID is still cached in the MDS, resulting in failure.

I think your analysis is accurate. The _close_sessions() in `Client::set_uuid()` call will drop `client_lock` waiting for the MDS to send `MClientSession(CEPH_SESSION_CLOSE)`. While handling MDS map, `Client::connect_mds_targets()` will call `Client::_open_mds_session()` which in turn initiates `MClientSession(CEPH_SESSION_REQUEST_OPEN)` with the updated metadata (uuid).

I am thinking of a fix right now...

Thank you for your reply.
My temporary solution for handling MClientSession (CEPH_SESSION_REQUEST_OPEN) is to check the current status of the session.
If it is closing, then:
if (session->is_closing()) {
mdlog->wait_for_safe(new MDSInternalContextWrapper(mds,
new C_MDS_RetryMessage(mds, m)));
return;
}

Please review whether it is feasible to wait for the processing of MClientSession (CEPH_SESSION_REQUEST_CLOSE) to be completed before handling the CEPH_SESSION_REQUEST_OPEN message. Are there any scenarios that have not been considered?
Thank you very much!

ymo zhang wrote in #note-12:

Thank you for your reply.
My temporary solution for handling MClientSession (CEPH_SESSION_REQUEST_OPEN) is to check the current status of the session.
If it is closing, then:
if (session->is_closing()) {
mdlog->wait_for_safe(new MDSInternalContextWrapper(mds,
new C_MDS_RetryMessage(mds, m)));
return;
}

Please review whether it is feasible to wait for the processing of MClientSession (CEPH_SESSION_REQUEST_CLOSE) to be completed before handling the CEPH_SESSION_REQUEST_OPEN message. Are there any scenarios that have not been considered?
Thank you very much!

I will check out this week and update. Thanks for the proposed fix.

Venky Shankar wrote in #note-13:

ymo zhang wrote in #note-12:

Thank you for your reply.
My temporary solution for handling MClientSession (CEPH_SESSION_REQUEST_OPEN) is to check the current status of the session.
If it is closing, then:
if (session->is_closing()) {
mdlog->wait_for_safe(new MDSInternalContextWrapper(mds,
new C_MDS_RetryMessage(mds, m)));
return;
}

Please review whether it is feasible to wait for the processing of MClientSession (CEPH_SESSION_REQUEST_CLOSE) to be completed before handling the CEPH_SESSION_REQUEST_OPEN message. Are there any scenarios that have not been considered?
Thank you very much!

I will check out this week and update. Thanks for the proposed fix.

Sorry for the delay. I will be working on this today.

ymo zhang wrote in #note-12:

Thank you for your reply.
My temporary solution for handling MClientSession (CEPH_SESSION_REQUEST_OPEN) is to check the current status of the session.
If it is closing, then:
if (session->is_closing()) {
mdlog->wait_for_safe(new MDSInternalContextWrapper(mds,
new C_MDS_RetryMessage(mds, m)));
return;
}

Please review whether it is feasible to wait for the processing of MClientSession (CEPH_SESSION_REQUEST_CLOSE) to be completed before handling the CEPH_SESSION_REQUEST_OPEN message. Are there any scenarios that have not been considered?
Thank you very much!

I am thinking if the fix needs to be in the user-space client, since this essentially is a race b/w session close and open messages (sent by and to the MDS).

Venky Shankar wrote in #note-15:

ymo zhang wrote in #note-12:

Thank you for your reply.
My temporary solution for handling MClientSession (CEPH_SESSION_REQUEST_OPEN) is to check the current status of the session.
If it is closing, then:
if (session->is_closing()) {
mdlog->wait_for_safe(new MDSInternalContextWrapper(mds,
new C_MDS_RetryMessage(mds, m)));
return;
}

Please review whether it is feasible to wait for the processing of MClientSession (CEPH_SESSION_REQUEST_CLOSE) to be completed before handling the CEPH_SESSION_REQUEST_OPEN message. Are there any scenarios that have not been considered?
Thank you very much!

I am thinking if the fix needs to be in the user-space client, since this essentially is a race b/w session close and open messages (sent by and to the MDS).

Hi @zhang6731 - I think your proposed solution to return the request on the MDS is a bit better than doing it on the client side. If done on the client side when handling mds map update, we would be blocking the messenger thread, even if client_lock is dropped. I will push a PR with your proposed fix and add your credits.

@zhang6731 ^^

I'm very glad that my fix was accepted. Thanks.

I am pushing a fix today for this.

Venky Shankar wrote in #note-18:

I am pushing a fix today for this.

Sorry. I wasn't able to get this done in the time I mentioned above.

It is in my list for tomorrow.