Ceph » CephFS

http://pulpito.ceph.com/teuthology-2016-11-28_17:15:02-fs-master---basic-smithi/583404/

This is manifesting as a cephfs test getting stuck waiting for daemons to be healthy, because one is stuck in creating.

It looks like the patch for http://tracker.ceph.com/issues/17942 changed this code recently, but I can't see how it broke.

The interesting bit of the log is when the osdmap eventually arrives, and TID 31 is just mysteriously missing (seemingly never gets sent to an OSD) (in mds.a.log)

2016-11-28 20:01:38.284480 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 11 ==== osd_map(93..93 src has 1..93) v3 ==== 2336+0+0 (824521463 0 0) 0x5597771c2780 con 0x55977711f000
2016-11-28 20:01:38.284760 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6800/8985 -- osd_op(unknown.0.123:1 23.844f3494 200.00000000 [writefull 0~90] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727c000 con 0
2016-11-28 20:01:38.284823 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:2 23.64e96f8f 400.00000000 [writefull 0~22] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727c340 con 0
2016-11-28 20:01:38.284851 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:3 23.6b2cdaff 1.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727c680 con 0
2016-11-28 20:01:38.284877 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6800/8985 -- osd_op(unknown.0.123:4 23.232c0e14 1.00000000.inode [writefull 0~532] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727c9c0 con 0
2016-11-28 20:01:38.284923 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:5 23.c2e541b0 600.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727cd00 con 0
2016-11-28 20:01:38.284952 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:6 23.c2e541b0 600.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727d040 con 0
2016-11-28 20:01:38.285032 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:7 23.81580290 601.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727d6c0 con 0
2016-11-28 20:01:38.285083 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:8 23.81580290 601.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727da00 con 0
2016-11-28 20:01:38.285117 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:9 23.2a8b6bd0 602.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727e080 con 0
2016-11-28 20:01:38.285142 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:10 23.2a8b6bd0 602.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727e3c0 con 0
2016-11-28 20:01:38.285168 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:11 23.7a4d91b0 603.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727ea40 con 0
2016-11-28 20:01:38.285198 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:12 23.7a4d91b0 603.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727ed80 con 0
2016-11-28 20:01:38.285262 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6800/2718 -- osd_op(unknown.0.123:13 23.43e85c95 604.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727f400 con 0
2016-11-28 20:01:38.285296 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6800/2718 -- osd_op(unknown.0.123:14 23.43e85c95 604.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727f740 con 0
2016-11-28 20:01:38.285341 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6800/2718 -- osd_op(unknown.0.123:15 23.d0c18e1d 605.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728c000 con 0
2016-11-28 20:01:38.285372 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6800/2718 -- osd_op(unknown.0.123:16 23.d0c18e1d 605.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728c340 con 0
2016-11-28 20:01:38.285400 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6800/8985 -- osd_op(unknown.0.123:17 23.f89eaaf4 606.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728c9c0 con 0
2016-11-28 20:01:38.285433 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6800/8985 -- osd_op(unknown.0.123:18 23.f89eaaf4 606.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728cd00 con 0
2016-11-28 20:01:38.285559 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6800/8985 -- osd_op(unknown.0.123:19 23.bb590b7c 607.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728d380 con 0
2016-11-28 20:01:38.285608 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6800/8985 -- osd_op(unknown.0.123:20 23.bb590b7c 607.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728c9c0 con 0
2016-11-28 20:01:38.285640 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6800/2718 -- osd_op(unknown.0.123:21 23.c4405e8e 608.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728cd00 con 0
2016-11-28 20:01:38.285672 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6800/2718 -- osd_op(unknown.0.123:22 23.c4405e8e 608.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728d6c0 con 0
2016-11-28 20:01:38.285692 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:23 23.60b82d07 609.00000000 [omap-set-header 0~274] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977728dd40 con 0
2016-11-28 20:01:38.286035 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:24 23.60b82d07 609.00000000 [create 0~0,setxattr parent (62),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727c000 con 0
2016-11-28 20:01:38.286095 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:25 23.c5265ab3 100.00000000 [omap-set-header 0~274,omap-set-vals 0~4774] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727e3c0 con 0
2016-11-28 20:01:38.286137 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:26 23.85dde07f 100.00000000.inode [writefull 0~532] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727ea40 con 0
2016-11-28 20:01:38.286202 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:27 23.b852b893 mds0_inotable [writefull 0~34] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727f0c0 con 0
2016-11-28 20:01:38.286241 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:28 23.3270c60b mds0_sessionmap [omap-set-header 0~14] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727ed80 con 0
2016-11-28 20:01:38.286282 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6800/2718 -- osd_op(unknown.0.123:29 23.d90270ad mds_snaptable [writefull 0~46] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727c340 con 0
2016-11-28 20:01:38.286311 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6800/8985 -- osd_op(unknown.0.123:30 23.6e5f474 200.00000001 [delete] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727f740 con 0
2016-11-28 20:01:38.286338 7f70c4189700  7 mds.0.server operator(): full = 0 epoch = 93
2016-11-28 20:01:38.286352 7f70c4189700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.101:6789/0 -- mon_subscribe({osdmap=94}) v2 -- 0x559777218600 con 0
2016-11-28 20:01:38.286382 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 12 ==== mon_get_version_reply(handle=1 version=93) v2 ==== 24+0+0 (2145240 0 0) 0x55977701a000 con 0x55977711f000
2016-11-28 20:01:38.286407 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 13 ==== mon_get_version_reply(handle=2 version=93) v2 ==== 24+0+0 (3407645371 0 0) 0x559777019c00 con 0x55977711f000
2016-11-28 20:01:38.286429 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 14 ==== mon_get_version_reply(handle=3 version=93) v2 ==== 24+0+0 (1901283381 0 0) 0x55977701a800 con 0x55977711f000
2016-11-28 20:01:38.286445 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 15 ==== mon_get_version_reply(handle=4 version=93) v2 ==== 24+0+0 (1485348492 0 0) 0x559777019e00 con 0x55977711f000
2016-11-28 20:01:38.286427 7f70be97e700  1 -- 172.21.15.101:6805/375414265 --> 172.21.15.116:6804/2780 -- osd_op(unknown.0.123:32 23.95e3ab 200.00000003 [delete] snapc 0=[] ondisk+write+known_if_redirected+full_force e93) v7 -- 0x55977727c9c0 con 0
2016-11-28 20:01:38.286456 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 16 ==== mon_get_version_reply(handle=5 version=93) v2 ==== 24+0+0 (3804716034 0 0) 0x55977701aa00 con 0x55977711f000
2016-11-28 20:01:38.286466 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 17 ==== mon_get_version_reply(handle=6 version=93) v2 ==== 24+0+0 (704343393 0 0) 0x55977701ae00 con 0x55977711f000
2016-11-28 20:01:38.286476 7f70c4189700  1 -- 172.21.15.101:6805/375414265 <== mon.0 172.21.15.101:6789/0 18 ==== mon_get_version_reply(handle=7 version=93) v2 ==== 24+0+0 (2478092271 0 0) 0x55977701b000 con 0x55977711f000