Project

General

Profile

Actions
Copy link

Bug #40340

closed

kernel client stuck at opening forever after network outage.

Added by Xiaoxi Chen almost 5 years ago. Updated over 3 years ago.

Status:
Can't reproduce
Priority:
Normal
Assignee:
Jeff Layton
Category:
fs/ceph
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Crash signature (v1):
Crash signature (v2):

Description

We dont retry(in ceph code) for sending create_session_open_msg. Thus once a network outage happen and mds evict the client, the client will try to reconnect and go through 

static int __open_session(struct ceph_mds_client *mdsc,
              struct ceph_mds_session *session)

However, if the tcp connection cannot be established after tcp_syn_retries times. The TCP establishment will be given up and leaving the session_state to CEPH_MDS_SESSION_OPENING for ever. We dont retry anymore.

The only way out is remount, or fail-over the mds...

Can we check in __do_request, if the session stuck in opening for long enough, eg mdsc->mdsmap->m_session_timeout >> 2, we will do __open_session again?

current code

if (session->s_state == CEPH_MDS_SESSION_NEW ||
            session->s_state == CEPH_MDS_SESSION_CLOSING)
            __open_session(mdsc, session);

new code

renew_interval = mdsc->mdsmap->m_session_timeout >> 2;
if (session->s_state == CEPH_MDS_SESSION_NEW ||
            session->s_state == CEPH_MDS_SESSION_CLOSING ||
            session->s_state == CEPH_MDS_SESSION_OPENING &&
            time_after_eq(jiffies, HZ*renew_interval + session->s_renew_requested))
            __open_session(mdsc, session);

Actions
Copy link
 #1

Updated by Xiaoxi Chen almost 5 years ago

Step to reproduce

1. [MDS]ceph --daemon /path-to-admin-socket/ session evict <client_id>

2. [Client] After 2MSL there will be no TCP between MDS and the client.

3. [Client] use IPTABLE to block all traffic to the MDS

4. [Client] use "ls" to trigger a reconnect

5. [Client] can see session stuck in opening. TCP in sync_sent

6. [Client] After some time, the TCP connection given up, mds_session still in opening.

7. [Client] Remove IPTABLE rules will not bring it back.

Actions
Copy link
 #2

Updated by Zheng Yan almost 5 years ago

does peer_reset() get called after tcp timeout

Actions
Copy link
 #3

Updated by Xiaoxi Chen almost 5 years ago

Negative.

The peer_reset get called during eviction but not after connection establish timeout.

2264570:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.692046] libceph: mds31 10.199.75.178:6801 connection reset
2264643:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.702065] libceph: reset on mds31
2264644:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.702746] ceph: mds31 closed our session
2264645:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.703531] ceph: mds31 reconnect start
2264647:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.704257] ceph: dispose_cap_releases mds31
2264650:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.704281] ceph: replay_unsafe_requests mds31
2264651:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.704284] ceph: iterate_session_caps ffff9384b5473800 mds31
2264653:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.704295] ceph: early_kick_flushing_caps mds31
2264691:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.706150] ceph: __unregister_session mds31 ffff9384b5473800
2264693:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.706161] ceph: handle_session mds31 close ffff9384b5473800 state reconnecting seq 0
2264694:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.706163] ceph: mds31 reconnect denied
2264695:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.707625] ceph: cleanup_session_requests mds31
2264697:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.707628] ceph: iterate_session_caps ffff9384b5473800 mds31
2264698:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.707629] ceph: dispose_cap_releases mds31
2264699:Jun 13 08:59:21 lvscallogorgworkerceph-3209173 kernel: [ 4938.707631] ceph: kick_requests mds31
2304604:Jun 13 09:00:11 lvscallogorgworkerceph-3209173 kernel: [ 4988.710445] ceph: forward tid 10 to mds31 (we resend)
2304606:Jun 13 09:00:11 lvscallogorgworkerceph-3209173 kernel: [ 4988.710449] ceph: choose_mds using resend_mds mds31
2304607:Jun 13 09:00:11 lvscallogorgworkerceph-3209173 kernel: [ 4988.710451] ceph: register_session: mds31
2304611:Jun 13 09:00:11 lvscallogorgworkerceph-3209173 kernel: [ 4988.710457] ceph: do_request mds31 session ffff938c99f17800 state new
2304612:Jun 13 09:00:11 lvscallogorgworkerceph-3209173 kernel: [ 4988.710459] ceph: open_session to mds31 (up:active)
3719341:Jun 13 09:01:31 lvscallogorgworkerceph-3209173 kernel: [ 5068.598443] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
3719379:Jun 13 09:01:31 lvscallogorgworkerceph-3209173 kernel: [ 5068.598601] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4054480:Jun 13 09:01:40 lvscallogorgworkerceph-3209173 kernel: [ 5078.196296] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4054551:Jun 13 09:01:40 lvscallogorgworkerceph-3209173 kernel: [ 5078.196428] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4216098:Jun 13 09:01:43 lvscallogorgworkerceph-3209173 kernel: [ 5081.105174] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4216113:Jun 13 09:01:43 lvscallogorgworkerceph-3209173 kernel: [ 5081.105214] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4220730:Jun 13 09:01:44 lvscallogorgworkerceph-3209173 kernel: [ 5082.162412] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4220745:Jun 13 09:01:44 lvscallogorgworkerceph-3209173 kernel: [ 5082.162441] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4450091:Jun 13 09:01:54 lvscallogorgworkerceph-3209173 kernel: [ 5091.829993] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4450116:Jun 13 09:01:54 lvscallogorgworkerceph-3209173 kernel: [ 5091.830042] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4526515:Jun 13 09:01:55 lvscallogorgworkerceph-3209173 kernel: [ 5093.349646] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4526531:Jun 13 09:01:55 lvscallogorgworkerceph-3209173 kernel: [ 5093.349678] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4545353:Jun 13 09:02:04 lvscallogorgworkerceph-3209173 kernel: [ 5102.339665] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4545369:Jun 13 09:02:04 lvscallogorgworkerceph-3209173 kernel: [ 5102.339698] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4545587:Jun 13 09:02:10 lvscallogorgworkerceph-3209173 kernel: [ 5107.954759] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4545603:Jun 13 09:02:10 lvscallogorgworkerceph-3209173 kernel: [ 5107.954791] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4546026:Jun 13 09:02:12 lvscallogorgworkerceph-3209173 kernel: [ 5110.050893] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4546042:Jun 13 09:02:12 lvscallogorgworkerceph-3209173 kernel: [ 5110.050925] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4546110:Jun 13 09:02:15 lvscallogorgworkerceph-3209173 kernel: [ 5113.206560] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active
4546126:Jun 13 09:02:15 lvscallogorgworkerceph-3209173 kernel: [ 5113.206592] ceph: check_new_map mds31 state up:active -> up:active (session opening)
4546351:Jun 13 09:02:18 lvscallogorgworkerceph-3209173 kernel: [ 5115.955698] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
4934099:Jun 13 09:04:26 lvscallogorgworkerceph-3209173 kernel: [ 5243.944823] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
5819727:Jun 13 09:06:35 lvscallogorgworkerceph-3209173 kernel: [ 5372.829756] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
8798764:Jun 13 09:08:44 lvscallogorgworkerceph-3209173 kernel: [ 5501.899284] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
13634243:Jun 13 09:10:59 lvscallogorgworkerceph-3209173 kernel: [ 5636.702035] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
15870027:Jun 13 09:13:14 lvscallogorgworkerceph-3209173 kernel: [ 5771.912604] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
20979042:Jun 13 09:15:38 lvscallogorgworkerceph-3209173 kernel: [ 5916.228381] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
26743064:Jun 13 09:18:19 lvscallogorgworkerceph-3209173 kernel: [ 6076.551269] libceph: mds31 10.199.75.178:6801 socket closed (con state CONNECTING)
29327696:Jun 13 09:19:39 lvscallogorgworkerceph-3209173 kernel: [ 6157.052018] libceph: mds31 10.199.75.178:6801 socket closed (con state NEGOTIATING)
31920295:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.651404] ceph: handle_session mds31 open ffff938c99f17800 state opening seq 0
31920296:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.651406] ceph: renewed_caps mds31 ttl now 4299715015, was fresh, now fresh
31920297:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.651408] ceph: request_close_session mds31 state closing seq 0
31920327:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.653600] ceph: __unregister_session mds31 ffff938c99f17800
31920329:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.653615] ceph: handle_session mds31 close ffff938c99f17800 state closing seq 0
31920330:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.653617] ceph: cleanup_session_requests mds31
31920332:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.653619] ceph: iterate_session_caps ffff938c99f17800 mds31
31920333:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.653621] ceph: dispose_cap_releases mds31
31920334:Jun 13 09:21:48 lvscallogorgworkerceph-3209173 kernel: [ 6285.653622] ceph: kick_requests mds31
32651961:Jun 13 09:23:05 lvscallogorgworkerceph-3209173 kernel: [ 6363.278188] ceph: mdsmap_decode 33/33 3829363 mds31.323072 10.199.75.178:6801 up:active

Actions
Copy link
 #4

Updated by Xiaoxi Chen almost 5 years ago

140 06/13/2019 09:21:22 AM umount /import/ceph/
141 06/13/2019 09:23:05 AM mount -a

The time of umount

Actions
Copy link
 #5

Updated by Zheng Yan almost 5 years ago

maybe calling peer_reset after tcp timeout is a better fix

Actions
Copy link
 #6

Updated by Xiaoxi Chen almost 5 years ago

hmm, re-read the code seems we will backoff and retry every 5mins....not sure if I read it correctly and how it hit into this situation..

Actions
Copy link
 #7

Updated by Ilya Dryomov over 4 years ago

  • Category set to fs/ceph
Actions
Copy link
 #8

Updated by Jeff Layton over 4 years ago

  • Status changed from New to Need More Info
  • Assignee set to Jeff Layton

I wonder if the fix for tracker #41551 might also fix this? Could you re-test on a kernel with commit c3cd561a41603b and let us know if it helps?

Actions
Copy link
 #9

Updated by Jeff Layton over 3 years ago

  • Status changed from Need More Info to Can't reproduce

No response in over a year. Closing.

Actions
Copy link

Also available in: Atom PDF