Bug #9458
client wrongly fenced
Status:
Resolved
Priority:
High
Assignee:
-
Category:
-
Target version:
-
% Done:
0%
Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Crash signature (v1):
Crash signature (v2):
Description
Sep 13 09:23:47 teuthology kernel: [173040.631244] ceph: mds0 reconnect start Sep 13 09:23:47 teuthology kernel: [173040.840651] libceph: mds0 10.214.134.10:6800 socket closed (con state OPEN) Sep 13 09:25:09 teuthology kernel: [173123.122670] ceph: mds0 recovery completed
on mds,
2014-09-13 09:23:47.575958 7f6cfd276700 1 -- 10.214.134.10:6800/33249 >> :/0 pipe(0x7f6cac0018f0 sd=41 :6800 s=0 pgs=0 cs=0 l=0 c=0x7f6cac001b80).accept sd=41 10.214.137.23:44498/0 2014-09-13 09:23:47.575986 7f6cfd276700 0 -- 10.214.134.10:6800/33249 >> 10.214.137.23:0/3633538031 pipe(0x7f6cac0018f0 sd=41 :6800 s=0 pgs=0 cs=0 l=0 c=0x7f6cac001b80).accept peer addr is really 10.214.137.23:0/3633538031 (socket is 10.214.137.23:44498/0) 2014-09-13 09:23:47.576396 7f6cfd276700 10 mds.0.76 existing session 0x7f6d40007470 for client.2359214 10.214.137.23:0/3633538031 existing con 0, new/authorizing con 0x7f6cac001b80 2014-09-13 09:23:47.576448 7f6d5effd700 10 mds.0.76 ms_handle_accept 10.214.137.23:0/3633538031 con 0x7f6cac001b80 session 0x7f6d40007470 2014-09-13 09:23:47.584330 7f6cfd276700 0 -- 10.214.134.10:6800/33249 >> 10.214.137.23:0/3633538031 pipe(0x7f6cac0018f0 sd=41 :6800 s=2 pgs=5445 cs=1 l=0 c=0x7f6cac001b80).fault with nothing to send, going to standby 2014-09-13 09:23:48.350871 7f6cfd074700 1 -- 10.214.134.10:6800/33249 >> :/0 pipe(0x7f6cac001e30 sd=42 :6800 s=0 pgs=0 cs=0 l=0 c=0x7f6cac003f60).accept sd=42 10.214.137.23:44499/0 2014-09-13 09:23:48.350903 7f6cfd074700 0 -- 10.214.134.10:6800/33249 >> 10.214.137.23:0/3633538031 pipe(0x7f6cac001e30 sd=42 :6800 s=0 pgs=0 cs=0 l=0 c=0x7f6cac003f60).accept peer addr is really 10.214.137.23:0/3633538031 (socket is 10.214.137.23:44499/0) 2014-09-13 09:24:37.193750 7f6d577fe700 1 mds.0.server reconnect gave up on client.2359214 10.214.137.23:0/3633538031 2014-09-13 09:24:37.194119 7f6d54ff9700 5 mds.0.log _submit_thread 23122002379~210 : ESession client.2359214 10.214.137.23:0/3633538031 close cmapv 105458427 (552 inos, v52108436) 2014-09-13 09:24:37.204730 7f6d57fff700 10 mds.0.server _session_logged client.2359214 10.214.137.23:0/3633538031 state_seq 2 close 105458427
this was burnupi21 and teuthology client
History
#1 Updated by Sage Weil about 9 years ago
teuthology was fenced again. not sure it was during a mds restart this time, either. notably the monitors went offline around 6:30am (full disks), but i'm not sure that was related.
#2 Updated by Sage Weil about 9 years ago
mds restarted and teuthology failed to reconnect again, 07:30:34.485721
#3 Updated by Greg Farnum about 9 years ago
- Assignee set to Greg Farnum
Taking a look; luckily we have at least some of the logging...
#4 Updated by Greg Farnum about 9 years ago
The MDS went into reconnect at 4:59:50
2014-09-17 04:59:50.571702 7f80658ad700 1 mds.0.107 handle_mds_map state change up:replay --> up:reconnect
2014-09-17 04:59:50.571705 7f80658ad700 1 mds.0.107 reconnect_start
2014-09-17 04:59:50.571706 7f80658ad700 1 mds.0.107 reopen_log
2014-09-17 04:59:50.571711 7f80658ad700 10 mds.0.cache rollback_uncommitted_fragments: 0 pending
2014-09-17 04:59:50.572274 7f80658ad700 1 mds.0.server reconnect_clients -- 4 sessions
2014-09-17 04:59:50.572289 7f80658ad700 10 mds.0.sessionmap dump
2014-09-17 04:59:50.572291 7f80658ad700 10 mds.0.sessionmap client.1633185 0x7f8048004710 state open completed {122544=0} prealloc_inos [10002c55db7~226,10002c55fe7~2,10002c5601e~1c,10002c5612b~1,10002c58260~2,10002c61672~3,10002c61676~4,10002c6167b~4,10002c61680~6,10002c61687~f,10003069331~2,1000306933b~21,1000306a5
70~2,1000306a58a~2d,1000306a5bb~10,1000306a5cc~1,1000306b6df~36,1000306b716~6,1000306b71d~a,1000306b7a3~2,1000306b7bb~a,100030e9f84~3,100030e9f8f~5,100030eeb98~a,100030efd1e~6,100030efe07~c,100030efe57~1f,100030efe77~2,100030efe7f~1f,100030efe9f~1,100030efea7~1,100030efed2~4,100030efed7~6,100030f03a3~3,100030f03ab~2,
100030f03b1~2,100030f03b4~4,100030f03bf~2,100030f0767~9,100030f07ba~1,100030f07c3~1,100030f0845~3,100030f0849~2,100030f0950~5,100030f0db8~5,100030f0f2e~3,100030f0f3c~2,100030f0f58~1,100030f0f5a~4,100030f1095~2,100030f109b~2] used_ions []
2014-09-17 04:59:50.572331 7f80658ad700 10 mds.0.sessionmap client.1756771 0x7f80480074b0 state open completed {20420926=0,20420927=0,20420928=0,20420929=0,20420930=0,20420931=0,20420932=0,20420933=0} prealloc_inos [10002d05cec~32e,10002d6a6ce~2,10002d6a6d1~a,10002dddd1b~d,10002ec1ea8~c,10002f34df6~1,10002f34e17~1,10
002f34e27~1,10002f34e2a~1,10002f34e3a~1,10002f34e40~1,10002f34e43~1,10002f34e46~1,10002f34e49~1,10002f34e4c~1,10002f34e4f~1,10002f34e52~1,10002fa9a4f~c,1000301cade~d,1000307ec9b~1,1000307ecb2~3,1000307ecb6~4,1000307ecbb~4,10003148c55~1,10003148c5a~1,10003148c5c~1,10003148c62~1,10003148c81~9] used_ions []
2014-09-17 04:59:50.572354 7f80658ad700 10 mds.0.sessionmap client.2651662 0x7f8048008020 state open completed {1915007=0,1915009=0,1915011=0,1915013=0,1915015=0,1915017=0,1915019=0,1915021=0,1915023=0,1915025=0,1915027=0,1915029=0,1915031=0,1915033=0,1915035=0,1915037=0,1915039=0,1915041=0,1915043=0,1915045=0,191504
7=0,1915049=0,1915051=0,1915053=0,1915055=0,1915057=0,1915059=0,1915061=0,1915063=0,1915065=0,1915067=0,1915069=0,1915071=0,1915073=0,1915075=0,1915077=0,1915079=0,1915081=0,1915083=0,1915085=0,1915087=0,1915089=0,1915091=0,1915093=0,1915095=0,1915097=0,1915099=0,1915101=0,1915103=0,1915105=0,1915107=0,1915109=0,1915
111=0,1915113=0,1915115=0,1915117=0,1915119=0,1915121=0,1915123=0,1915125=0,1915127=0,1915129=0,1915131=0,1915133=0,1915135=0,1915137=0,1915139=0,1915141=0,1915143=0,1915145=0,1915147=0,1915149=0,1915151=0,1915153=0,1915155=0,1915157=0,1915159=0,1915161=0,1915163=0,1915165=0,1915167=0,1915169=0,1915171=0,1915173=0,19
15175=0,1915177=0,1915179=0,1915181=0,1915183=0,1915185=0,1915187=0,1915189=0,1915191=0,1915193=0,1915195=0,1915197=0,1915199=0,1915201=0,1915203=0,1915205=0,1915207=0,1915209=0,1915211=0,1915213=0,1915215=0,1915217=0} prealloc_inos [10003453e6a~3dd] used_ions []
2014-09-17 04:59:50.572408 7f80658ad700 10 mds.0.sessionmap client.1756816 0x7f80480084d0 state open completed {} prealloc_inos [] used_ions []
It got reconnect messages from two clients (backup01, then gitbuilder-archive), and appears to have processed them correctly
2014-09-17 04:59:50.576813 7f80658ad700 1 -- 10.214.134.10:6801/29320 <== client.1756816 10.214.137.27:0/2508210603 1 ==== client_reconnect(1 caps) v2 ==== 0+0+84 (0 0 41256884) 0x7f7fb00016e0 con 0x7f7fa80011f0 ... 2014-09-17 04:59:50.630188 7f80658ad700 1 -- 10.214.134.10:6801/29320 <== client.1756771 10.214.137.25:0/1841820156 1 ==== client_reconnect(2081 caps) v2 ==== 0+0+321792 (0 0 776300702) 0x7f7fb8006a60 con 0x7f7fa8001760
But notice that the backup01 machine only claimed one cap -- perhaps it really wasn't using anything.
Also, flab (I'm assuming; that's what has the IP now) sent a bad message in between the two successful ones:
2014-09-17 04:59:50.602241 7f804d3e1700 -1 failed to decode message of type 24 v2: buffer::end_of_buffer 2014-09-17 04:59:50.602283 7f804d3e1700 0 -- 10.214.134.10:6801/29320 >> 10.214.131.102:0/1174985195 pipe(0x7f7fa8000980 sd=37 :6801 s=2 pgs=18231 cs=1 l=0 c=0x7f7fa8000c10).fault with nothing to send, going to standby
And that IP showed up again at least once. Similarly busted is teuthology:
2014-09-17 04:59:50.900718 7f804cbdd700 0 -- 10.214.134.10:6801/29320 >> 10.214.137.23:0/2533113401 pipe(0x7f7fa8001a40 sd=40 :6801 s=0 pgs=0 cs=0 l=0 c=0x7f7fa8001cd0).accept peer addr is really 10.214.137.23:0/2533113401 (socket is 10.214.137.23:56050/0) 2014-09-17 04:59:50.901068 7f804cbdd700 10 mds.0.107 existing session 0x7f8048008020 for client.2651662 10.214.137.23:0/2533113401 existing con 0, new/authorizing con 0x7f7fa8001cd0 2014-09-17 04:59:50.901119 7f80658ad700 10 mds.0.107 ms_handle_accept 10.214.137.23:0/2533113401 con 0x7f7fa8001cd0 session 0x7f8048008020 2014-09-17 04:59:50.901134 7f80658ad700 10 mds.0.107 session connection 0 -> 0x7f7fa8001cd0 2014-09-17 04:59:50.901375 7f804cbdd700 -1 failed to decode message of type 24 v2: buffer::end_of_buffer
The teuthology machine then sent bunches of cap messages, but never a reconnect.
#5 Updated by Greg Farnum about 9 years ago
- Project changed from CephFS to Linux kernel client
- Assignee deleted (
Greg Farnum) - Priority changed from Urgent to High
The kernel client is definitely doing something wrong here, but I don't know what — the userspace messenger is not increasing its in_seq so when the reconnect happens the kernel ought to be resending its reconnect message. Presumably it's not for reasons related to it being corrupted in the first place.
#6 Updated by Zheng Yan about 9 years ago
- Status changed from New to 7
is the client using 3.16 kernel? possibly due to missing following commit
commit c5c9a0bf1b03112d606edaab15f18e892e8b55af
Author: Yan, Zheng <zheng.z.yan@intel.com>
Date: Tue Jul 1 16:54:34 2014 +0800
ceph: include time stamp in replayed MDS requests
Signed-off-by: Yan, Zheng <zheng.z.yan@intel.com>
diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
index 92a2548..0225523 100644
--- a/fs/ceph/mds_client.c
+++ b/fs/ceph/mds_client.c
@@ -1904,6 +1904,7 @@ static int __prepare_send_request(struct ceph_mds_client *mdsc,
req->r_tid, ceph_mds_op_name(req->r_op), req->r_attempts);
if (req->r_got_unsafe) {
+ void *p;
/*
* Replay. Do not regenerate message (and rebuild
* paths, etc.); just use the original message.
@@ -1924,8 +1925,13 @@ static int __prepare_send_request(struct ceph_mds_client *mdsc,
/* remove cap/dentry releases from message */
rhead->num_releases = 0;
- msg->hdr.front_len = cpu_to_le32(req->r_request_release_offset);
- msg->front.iov_len = req->r_request_release_offset;
+
+ /* time stamp */
+ p = msg->front.iov_base + req->r_request_release_offset;
+ ceph_encode_copy(&p, &req->r_stamp, sizeof(req->r_stamp));
+
+ msg->front.iov_len = p - msg->front.iov_base;
+ msg->hdr.front_len = cpu_to_le32(msg->front.iov_len);
return 0;
}
#7 Updated by Zheng Yan almost 9 years ago
- Status changed from 7 to Resolved