Ceph » Linux kernel client

The kclient just sent a reconnect request after the mds failovered or restarted and when the kclient received the session reset, not RECONNECT mdsmap:

2023-08-09T06:16:04.330510+00:00 smithi190 kernel: libceph: mds0 (2)172.21.15.190:6834 session reset
2023-08-09T06:16:04.330607+00:00 smithi190 kernel: ceph: [45034a4b-ab2e-4a3a-9945-7e70a3231d64 4670] mds_peer_reset: mds0 closed our session
2023-08-09T06:16:04.330652+00:00 smithi190 kernel: ceph: [45034a4b-ab2e-4a3a-9945-7e70a3231d64 4670] send_mds_reconnect: mds0 reconnect start

But the reconnect request was received during the mds was in up:replay state:

2023-08-09T06:16:04.335+0000 7f95a05f6700 10 mds.0.0 update_log_config log_to_monitors true
2023-08-09T06:16:04.335+0000 7f95a05f6700 10 mds.0.0 create_logger
2023-08-09T06:16:04.335+0000 7f95a05f6700  7 mds.0.server operator(): full = 0 epoch = 0
2023-08-09T06:16:04.335+0000 7f95a05f6700  4 mds.0.purge_queue operator():  data pool 4 not found in OSDMap
2023-08-09T06:16:04.335+0000 7f95a05f6700 10 mds.0.server apply_blocklist: killed 0
2023-08-09T06:16:04.335+0000 7f95a05f6700  4 mds.0.0 apply_blocklist: killed 0, blocklisted sessions (0 blocklist entries, 0)
2023-08-09T06:16:04.335+0000 7f95a05f6700 10 mds.a handle_mds_map: handling map as rank 0
2023-08-09T06:16:04.335+0000 7f95a05f6700  1 mds.0.231 handle_mds_map i am now mds.0.231
2023-08-09T06:16:04.335+0000 7f95a05f6700  1 mds.0.231 handle_mds_map state change up:standby --> up:replay
2023-08-09T06:16:04.335+0000 7f95a05f6700  5 mds.beacon.a set_want_state: up:standby -> up:replay
2023-08-09T06:16:04.335+0000 7f95a05f6700  1 mds.0.231 replay_start
2023-08-09T06:16:04.335+0000 7f95a05f6700  1 mds.0.231  waiting for osdmap 147 (which blocklists prior instance)

...

2023-08-09T06:16:04.338+0000 7f95a2dfb700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >> [v2:172.21.15.190:6800/84327,v1:172.21.15.190:6801/84327] conn(0x555f83345400 msgr2=0x555f8257d180 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).operator() setting up a delay queue
2023-08-09T06:16:04.338+0000 7f95a2dfb700  1 --2- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >> [v2:172.21.15.190:6800/84327,v1:172.21.15.190:6801/84327] conn(0x555f83345400 0x555f8257d180 crc :-1 s=READY pgs=294 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).ready entity=osd.0 client_cookie=0 server_cookie=0 in_seq=0 out_seq=0
2023-08-09T06:16:04.338+0000 7f95a3dfd700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >> [v2:172.21.15.193:6824/84630,v1:172.21.15.193:6825/84630] conn(0x555f83344000 msgr2=0x555f8257c680 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).operator() setting up a delay queue
2023-08-09T06:16:04.338+0000 7f95a3dfd700  1 --2- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >> [v2:172.21.15.193:6824/84630,v1:172.21.15.193:6825/84630] conn(0x555f83344000 0x555f8257c680 crc :-1 s=READY pgs=264 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).ready entity=osd.7 client_cookie=0 server_cookie=0 in_seq=0 out_seq=0
2023-08-09T06:16:04.340+0000 7f95a3dfd700  1 --2- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >>  conn(0x555f83354000 0x555f8257d700 unknown :-1 s=NONE pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0).accept
2023-08-09T06:16:04.340+0000 7f95a3dfd700  1 --2- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >>  conn(0x555f83354000 0x555f8257d700 unknown :-1 s=BANNER_ACCEPTING pgs=0 cs=0 l=0 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=1 required=1
2023-08-09T06:16:04.341+0000 7f95a3dfd700 10 mds.a parse_caps: parsing auth_cap_str='allow'
2023-08-09T06:16:04.341+0000 7f95a05f6700 10 mds.a  new session 0x555f824a0300 for client.4670 172.21.15.190:0/1539903001 con 0x555f83354000
2023-08-09T06:16:04.341+0000 7f95a05f6700 10 mds.a parse_caps: parsing auth_cap_str='allow'
2023-08-09T06:16:04.341+0000 7f95a05f6700 10 mds.a ms_handle_accept 172.21.15.190:0/1539903001 con 0x555f83354000 session 0x555f824a0300
2023-08-09T06:16:04.341+0000 7f95a3dfd700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >> 172.21.15.190:0/1539903001 conn(0x555f83354000 msgr2=0x555f8257d700 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=0).operator() setting up a delay queue
2023-08-09T06:16:04.341+0000 7f95a3dfd700  1 --2- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] >> 172.21.15.190:0/1539903001 conn(0x555f83354000 0x555f8257d700 crc :-1 s=READY pgs=1590 cs=0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).ready entity=client.4670 client_cookie=7136c3bb06ae8991 server_cookie=f3d5a73cd05d2d1 in_seq=0 out_seq=0
2023-08-09T06:16:04.341+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] <== client.4670 172.21.15.190:0/1539903001 1 ==== client_request(client.4670:192920 rmdir #0x10000009597/ip32 2023-08-09T06:15:48.151937+0000 RETRY=1 REPLAY caller_uid=1000, caller_gid=1275{6,36,1000,1275,}) v6 ==== 192+0+0 (crc 0 0 0) 0x555f831b1340 con 0x555f83354000
2023-08-09T06:16:04.341+0000 7f95a05f6700  3 mds.0.server not active yet, waiting
2023-08-09T06:16:04.341+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] <== client.4670 172.21.15.190:0/1539903001 2 ==== client_request(client.4670:192922 unlink #0x10000009597/gpio.h 2023-08-09T06:15:48.169936+0000 RETRY=1 REPLAY caller_uid=1000, caller_gid=1275{6,36,1000,1275,}) v6 ==== 194+0+0 (crc 0 0 0) 0x555f831b1600 con 0x555f83354000
2023-08-09T06:16:04.341+0000 7f95a05f6700  3 mds.0.server not active yet, waiting
2023-08-09T06:16:04.341+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] <== client.4670 172.21.15.190:0/1539903001 3 ==== client_request(client.4670:192925 unlink #0x100000097ee/smsc_fdc37m81x.h 2023-08-09T06:15:48.173936+0000 RETRY=1 REPLAY caller_uid=1000, caller_gid=1275{6,36,1000,1275,}) v6 ==== 204+0+0 (crc 0 0 0) 0x555f831b18c0 con 0x555f83354000
2023-08-09T06:16:04.341+0000 7f95a05f6700  3 mds.0.server not active yet, waiting
2023-08-09T06:16:04.341+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] <== client.4670 172.21.15.190:0/1539903001 4 ==== client_request(client.4670:192927 unlink #0x100000097ee/pci.h 2023-08-09T06:15:48.175936+0000 RETRY=1 REPLAY caller_uid=1000, caller_gid=1275{6,36,1000,1275,}) v6 ==== 193+0+0 (crc 0 0 0) 0x555f831b1b80 con 0x555f83354000
2023-08-09T06:16:04.341+0000 7f95a05f6700  3 mds.0.server not active yet, waiting
2023-08-09T06:16:04.341+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] <== client.4670 172.21.15.190:0/1539903001 5 ==== client_request(client.4670:192929 unlink #0x100000097ee/rbtx4939.h 2023-08-09T06:15:48.177936+0000 RETRY=1 caller_uid=1000, caller_gid=1275{6,36,1000,1275,}) v6 ==== 198+0+0 (crc 0 0 0) 0x555f8330c000 con 0x555f83354000
2023-08-09T06:16:04.341+0000 7f95a05f6700  3 mds.0.server not active yet, waiting
2023-08-09T06:16:04.341+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] <== client.4670 172.21.15.190:0/1539903001 6 ==== client_reconnect(14 caps 3 realms ) v3 ==== 0+0+1105 (crc 0 0 0) 0x555f8325eea0 con 0x555f83354000
2023-08-09T06:16:04.341+0000 7f95a05f6700  7 mds.0.server handle_client_reconnect client.4670
2023-08-09T06:16:04.341+0000 7f95a05f6700 20 mds.0.231 get_session have 0x555f824a0300 client.4670 172.21.15.190:0/1539903001 state closed
2023-08-09T06:16:04.341+0000 7f95a05f6700  0 mds.0.server  ignoring msg from not-open sessionclient_reconnect(14 caps 3 realms ) v3
2023-08-09T06:16:04.341+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] --> 172.21.15.190:0/1539903001 -- client_session(close) v5 -- 0x555f82480a80 con 0x555f83354000

Just before the sessionmap being loaded and replayed and the mds just create a new session, which the state was STATE_CLOSED, and then rejected the session connection as above. And just after this the sessionmap journal logs was load and replayed, but it's too late:

2023-08-09T06:16:04.447+0000 7f959a5ea700 10 MDSIOContextBase::complete: N12_GLOBAL__N_112C_IO_SM_LoadE
2023-08-09T06:16:04.447+0000 7f959a5ea700 10 MDSContext::complete: N12_GLOBAL__N_112C_IO_SM_LoadE
2023-08-09T06:16:04.447+0000 7f959a5ea700 10 mds.0.sessionmap _load_finish loaded version 62854
2023-08-09T06:16:04.447+0000 7f959a5ea700 10 mds.0.sessionmap _load_finish: omap load complete
2023-08-09T06:16:04.447+0000 7f959a5ea700 10 mds.0.sessionmap _load_finish: v 62854, 1 sessions
2023-08-09T06:16:04.447+0000 7f959a5ea700 10 mds.0.sessionmap dump
2023-08-09T06:16:04.447+0000 7f959a5ea700 10 mds.0.sessionmap client.4670 0x555f83366500 state open completed {182651=0x0} free_prealloc_inos [0x1000000f4cb~0x6e,0x1000000f560~0xfb,0x1000000f673~0x3d0] delegated_inos []

And then in kclient it just closed and then removed the session:

2023-08-09T06:16:04.351724+00:00 smithi190 kernel: ceph: [45034a4b-ab2e-4a3a-9945-7e70a3231d64 4670] handle_session: mds0 reconnect denied
2023-08-09T06:16:04.351865+00:00 smithi190 kernel: ceph: [45034a4b-ab2e-4a3a-9945-7e70a3231d64 4670] cleanup_session_requests:  dropping unsafe request 192920
2023-08-09T06:16:04.373983+00:00 smithi190 kernel: ceph: [45034a4b-ab2e-4a3a-9945-7e70a3231d64 4670] cleanup_session_requests:  dropping unsafe request 192922
2023-08-09T06:16:04.374060+00:00 smithi190 kernel: ceph: [45034a4b-ab2e-4a3a-9945-7e70a3231d64 4670] cleanup_session_requests:  dropping unsafe request 192925
2023-08-09T06:16:04.395601+00:00 smithi190 kernel: ceph: [45034a4b-ab2e-4a3a-9945-7e70a3231d64 4670] cleanup_session_requests:  dropping unsafe request 192927
2023-08-09T06:17:02.501817+00:00 smithi190 kernel: libceph: mds0 (2)172.21.15.190:6834 socket closed (con state OPEN)

And then when the RECONNECT mdsmap came, the kclient will skip reconnecting it and then mds timedout waiting reconnection:

2023-08-09T06:16:57.688+0000 7f95a2dfb700  5 mds.beacon.a received beacon reply up:reconnect seq 16 rtt 0
2023-08-09T06:16:58.338+0000 7f959edf3700 20 mds.0.231 get_task_status
2023-08-09T06:16:58.338+0000 7f959edf3700 20 mds.0.231 schedule_update_timer_task
2023-08-09T06:16:58.370+0000 7f959c5ee700  2 mds.0.cache Memory usage:  total 477004, rss 168768, heap 207104, baseline 182528, 0 / 24084 inodes have caps, 0 caps, 0 caps per inode
2023-08-09T06:16:58.370+0000 7f959c5ee700 10 mds.0.cache cache not ready for trimming
2023-08-09T06:16:58.370+0000 7f959c5ee700 10 mds.0.cache releasing free memory
2023-08-09T06:16:58.370+0000 7f959c5ee700 20 mds.0.cache upkeep thread waiting interval 1.000000000s
2023-08-09T06:16:59.370+0000 7f959c5ee700  2 mds.0.cache Memory usage:  total 477004, rss 168768, heap 207104, baseline 182528, 0 / 24084 inodes have caps, 0 caps, 0 caps per inode
2023-08-09T06:16:59.370+0000 7f959c5ee700 10 mds.0.cache cache not ready for trimming
2023-08-09T06:16:59.370+0000 7f959c5ee700 20 mds.0.cache upkeep thread waiting interval 1.000000000s
2023-08-09T06:16:59.925+0000 7f959edf3700  7 mds.0.server reconnect timed out, 1 clients have not reconnected in time
2023-08-09T06:16:59.925+0000 7f959edf3700  1 mds.0.server reconnect gives up on client.4670 172.21.15.190:0/1539903001
2023-08-09T06:16:59.925+0000 7f959edf3700  0 log_channel(cluster) log [WRN] : evicting unresponsive client smithi190:0 (4670), after waiting 45.5268 seconds during MDS startup
2023-08-09T06:16:59.925+0000 7f959edf3700  1 mds.0.231 Evicting (and blocklisting) client session 4670 (172.21.15.190:0/1539903001)
2023-08-09T06:16:59.925+0000 7f959edf3700  0 log_channel(cluster) log [INF] : Evicting (and blocklisting) client session 4670 (172.21.15.190:0/1539903001)
2023-08-09T06:16:59.925+0000 7f959edf3700  4 mds.0.231 Preparing blocklist command... (wait=0)
2023-08-09T06:16:59.925+0000 7f959edf3700  4 mds.0.231 Sending mon blocklist command: {"prefix":"osd blocklist", "blocklistop":"add","addr":"172.21.15.190:0/1539903001"}
2023-08-09T06:16:59.925+0000 7f959edf3700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] --> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] -- mon_command({"prefix":"osd blocklist", "blocklistop":"add","addr":"172.21.15.190:0/1539903001"} v 0) v1 -- 0x555f83323200 con 0x555f831b3000
2023-08-09T06:16:59.925+0000 7f959edf3700  1 mds.0.server reconnect will complete once clients are evicted
2023-08-09T06:16:59.929+0000 7f959f5f4700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] --> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] -- log(2 entries from seq 1 at 2023-08-09T06:16:59.927048+0000) v1 -- 0x555f824808c0 con 0x555f831b3000
...
2023-08-09T06:17:00.376+0000 7f95a05f6700  7 mds.0.server operator(): full = 0 epoch = 148
2023-08-09T06:17:00.376+0000 7f95a05f6700 10 mds.0.server kill_session 0x555f83366500
2023-08-09T06:17:00.376+0000 7f95a05f6700 10 mds.0.server journal_close_session : client.4670 172.21.15.190:0/1539903001 pending_prealloc_inos [] free_prealloc_inos [] delegated_inos [0x1000000f4cb~0x6e,0x1000000f560~0xfb,0x1000000f673~0x3d0]
2023-08-09T06:17:00.376+0000 7f95a05f6700 20 mds.0.sessionmap mark_projected s=0x555f83366500 name=client.4670 pv=62855 -> 62856
2023-08-09T06:17:00.376+0000 7f95a05f6700 10 mds.0.server apply_blocklist: killed 1
2023-08-09T06:17:00.376+0000 7f95a05f6700  4 mds.0.231 apply_blocklist: killed 1, blocklisted sessions (1 blocklist entries, 1)
2023-08-09T06:17:00.376+0000 7f95a05f6700  4 mds.0.231 set_osd_epoch_barrier: epoch=148
2023-08-09T06:17:00.376+0000 7f95a05f6700  1 -- [v2:172.21.15.190:6834/4117966589,v1:172.21.15.190:6835/4117966589] --> [v2:172.21.15.190:3300/0,v1:172.21.15.190:6789/0] -- mon_subscribe({osdmap=149}) v3 -- 0x555f83265380 con 0x555f831b3000

To fix this in kclient we should skip reconnecting if the mds is not ready.