Bug #23529
Updated by Nathan Cutler about 6 years ago
I'm not sure why this test is in the rados suite, when it tests a CephFS-specific tool(?), but here we are. After some bisecting I determined that one of the following PRs (all CephFS-related) caused the following regression in jewel 10.2.11 release preparation: https://github.com/ceph/ceph/pull/19141 https://github.com/ceph/ceph/pull/19961 https://github.com/ceph/ceph/pull/19993 https://github.com/ceph/ceph/pull/20312 https://github.com/ceph/ceph/pull/20333 <-- this one, because it touches src/tools/cephfs/MDSUtility.cc The regression causes the TmapMigratePP.DataScan test (part of the RADOS API tests) tests, but integration testing didn't catch it because we don't ordinarily run the rados suite on CephFS PRs) to fail due to the following crash: <pre> 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: [ RUN ] TmapMigratePP.DataScan 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: Created ioctx for test-rados-api-smithi045-12726-1 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: common/Thread.cc: In function 'int Thread::join(void**)' thread 7f852bcd9d00 time 2018-03-30 10:36:32.371028 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: common/Thread.cc: 167: FAILED assert("join on thread that was never started" == 0) 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: ceph version 10.2.10-324-gabaf02e (abaf02eecd4b158d08315cccd7a61d084ee7a635) 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x80) [0x555a7bd7c240] 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2: (Thread::join(void**)+0xc9) [0x555a7bd67719] 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 3: (Finisher::stop()+0x1e1) [0x555a7bc9cbf1] 2018-03-30T10:36:32.375 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 4: (MDSUtility::shutdown()+0x19) [0x555a7b91d6a9] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 5: (MDSUtility::~MDSUtility()+0x115) [0x555a7b91d835] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 6: (TmapMigratePP_DataScan_Test::TestBody()+0x1d81) [0x555a7b909551] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 7: (void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*)+0x43) [0x555a7b949f03] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 8: (testing::Test::Run()+0xba) [0x555a7b941cba] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 9: (testing::TestInfo::Run()+0x118) [0x555a7b941e08] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 10: (testing::TestCase::Run()+0xb5) [0x555a7b941ee5] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 11: (testing::internal::UnitTestImpl::RunAllTests()+0x23f) [0x555a7b94284f] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 12: (bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*)+0x43) [0x555a7b94a3e3] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 13: (testing::UnitTest::Run()+0x40) [0x555a7b941fb0] 2018-03-30T10:36:32.376 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 14: (main()+0x134) [0x555a7b8ffe04] 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 15: (__libc_start_main()+0xf0) [0x7f85202b9830] 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 16: (_start()+0x29) [0x555a7b9075f9] 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2018-03-30 10:36:32.373540 7f852bcd9d00 -1 common/Thread.cc: In function 'int Thread::join(void**)' thread 7f852bcd9d00 time 2018-03-30 10:36:32.371028 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: common/Thread.cc: 167: FAILED assert("join on thread that was never started" == 0) 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: ceph version 10.2.10-324-gabaf02e (abaf02eecd4b158d08315cccd7a61d084ee7a635) 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x80) [0x555a7bd7c240] 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2: (Thread::join(void**)+0xc9) [0x555a7bd67719] 2018-03-30T10:36:32.377 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 3: (Finisher::stop()+0x1e1) [0x555a7bc9cbf1] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 4: (MDSUtility::shutdown()+0x19) [0x555a7b91d6a9] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 5: (MDSUtility::~MDSUtility()+0x115) [0x555a7b91d835] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 6: (TmapMigratePP_DataScan_Test::TestBody()+0x1d81) [0x555a7b909551] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 7: (void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*)+0x43) [0x555a7b949f03] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 8: (testing::Test::Run()+0xba) [0x555a7b941cba] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 9: (testing::TestInfo::Run()+0x118) [0x555a7b941e08] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 10: (testing::TestCase::Run()+0xb5) [0x555a7b941ee5] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 11: (testing::internal::UnitTestImpl::RunAllTests()+0x23f) [0x555a7b94284f] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 12: (bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*)+0x43) [0x555a7b94a3e3] 2018-03-30T10:36:32.378 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 13: (testing::UnitTest::Run()+0x40) [0x555a7b941fb0] 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 14: (main()+0x134) [0x555a7b8ffe04] 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 15: (__libc_start_main()+0xf0) [0x7f85202b9830] 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 16: (_start()+0x29) [0x555a7b9075f9] 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: --- begin dump of recent events --- 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -172> 2018-03-30 10:36:30.100147 7f852bcd9d00 5 asok(0x555a86b0a000) register_command perfcounters_dump hook 0x555a86aca030 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -171> 2018-03-30 10:36:30.100195 7f852bcd9d00 5 asok(0x555a86b0a000) register_command 1 hook 0x555a86aca030 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -170> 2018-03-30 10:36:30.100212 7f852bcd9d00 5 asok(0x555a86b0a000) register_command perf dump hook 0x555a86aca030 2018-03-30T10:36:32.379 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -169> 2018-03-30 10:36:30.100228 7f852bcd9d00 5 asok(0x555a86b0a000) register_command perfcounters_schema hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -168> 2018-03-30 10:36:30.100243 7f852bcd9d00 5 asok(0x555a86b0a000) register_command 2 hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -167> 2018-03-30 10:36:30.100257 7f852bcd9d00 5 asok(0x555a86b0a000) register_command perf schema hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -166> 2018-03-30 10:36:30.100272 7f852bcd9d00 5 asok(0x555a86b0a000) register_command perf reset hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -165> 2018-03-30 10:36:30.100299 7f852bcd9d00 5 asok(0x555a86b0a000) register_command config show hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -164> 2018-03-30 10:36:30.100314 7f852bcd9d00 5 asok(0x555a86b0a000) register_command config set hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -163> 2018-03-30 10:36:30.100329 7f852bcd9d00 5 asok(0x555a86b0a000) register_command config get hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -162> 2018-03-30 10:36:30.100344 7f852bcd9d00 5 asok(0x555a86b0a000) register_command config diff hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -161> 2018-03-30 10:36:30.100359 7f852bcd9d00 5 asok(0x555a86b0a000) register_command log flush hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -160> 2018-03-30 10:36:30.100373 7f852bcd9d00 5 asok(0x555a86b0a000) register_command log dump hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -159> 2018-03-30 10:36:30.100388 7f852bcd9d00 5 asok(0x555a86b0a000) register_command log reopen hook 0x555a86aca030 2018-03-30T10:36:32.380 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -158> 2018-03-30 10:36:30.108069 7f852bcd9d00 -1 WARNING: the following dangerous and experimental features are enabled: * 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -157> 2018-03-30 10:36:30.108362 7f852bcd9d00 -1 WARNING: the following dangerous and experimental features are enabled: * 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -156> 2018-03-30 10:36:30.111093 7f852bcd9d00 -1 WARNING: the following dangerous and experimental features are enabled: * 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -155> 2018-03-30 10:36:30.112979 7f852bcd9d00 5 asok(0x555a86b0a000) init /var/run/ceph/ceph-client.admin.12726.asok 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -154> 2018-03-30 10:36:30.113003 7f852bcd9d00 5 asok(0x555a86b0a000) bind_and_listen /var/run/ceph/ceph-client.admin.12726.asok 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -153> 2018-03-30 10:36:30.113043 7f852bcd9d00 5 asok(0x555a86b0a000) register_command 0 hook 0x555a86ac60c0 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -152> 2018-03-30 10:36:30.113060 7f852bcd9d00 5 asok(0x555a86b0a000) register_command version hook 0x555a86ac60c0 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -151> 2018-03-30 10:36:30.113073 7f852bcd9d00 5 asok(0x555a86b0a000) register_command git_version hook 0x555a86ac60c0 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -150> 2018-03-30 10:36:30.113089 7f852bcd9d00 5 asok(0x555a86b0a000) register_command help hook 0x555a86aca100 2018-03-30T10:36:32.381 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -149> 2018-03-30 10:36:30.113102 7f852bcd9d00 5 asok(0x555a86b0a000) register_command get_command_descriptions hook 0x555a86aca110 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -148> 2018-03-30 10:36:30.118305 7f851cfbf700 5 asok(0x555a86b0a000) entry start 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -147> 2018-03-30 10:36:30.120181 7f851cfbf700 5 asok(0x555a86b0a000) AdminSocket: request '0' '' to 0x555a86ac60c0 returned 1 bytes 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -146> 2018-03-30 10:36:32.329847 7f852bcd9d00 1 accepter.accepter.bind my_inst.addr is 0.0.0.0:6812/3148625219 need_addr=1 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -145> 2018-03-30 10:36:32.329862 7f852bcd9d00 1 -- 0.0.0.0:6812/3148625219 messenger.start 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -144> 2018-03-30 10:36:32.329915 7f852bcd9d00 5 asok(0x555a86b0a000) register_command objecter_requests hook 0x555a86aca390 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -143> 2018-03-30 10:36:32.329984 7f852bcd9d00 1 accepter.accepter.start 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -142> 2018-03-30 10:36:32.330013 7f852bcd9d00 10 monclient(hunting): build_initial_monmap 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -141> 2018-03-30 10:36:32.330056 7f852bcd9d00 10 monclient(hunting): init 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -140> 2018-03-30 10:36:32.330062 7f852bcd9d00 5 adding auth protocol: cephx 2018-03-30T10:36:32.382 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -139> 2018-03-30 10:36:32.330063 7f852bcd9d00 10 monclient(hunting): auth_supported 2 method cephx 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -138> 2018-03-30 10:36:32.330734 7f852bcd9d00 2 auth: KeyRing::load: loaded key file /etc/ceph/ceph.keyring 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -137> 2018-03-30 10:36:32.330813 7f852bcd9d00 10 monclient(hunting): _reopen_session rank -1 name 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -136> 2018-03-30 10:36:32.330887 7f852bcd9d00 10 monclient(hunting): picked mon.b con 0x555a86b44900 addr 172.21.15.142:6789/0 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -135> 2018-03-30 10:36:32.330899 7f852bcd9d00 10 monclient(hunting): _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -134> 2018-03-30 10:36:32.330902 7f852bcd9d00 1 -- 0.0.0.0:6812/3148625219 --> 172.21.15.142:6789/0 -- auth(proto 0 30 bytes epoch 0) v1 -- ?+0 0x555a86b23400 con 0x555a86b44900 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -133> 2018-03-30 10:36:32.330911 7f852bcd9d00 10 monclient(hunting): renew_subs 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -132> 2018-03-30 10:36:32.331233 7f852bcd3700 1 -- 172.21.15.45:6812/3148625219 learned my addr 172.21.15.45:6812/3148625219 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -131> 2018-03-30 10:36:32.331426 7f852bcd3700 2 -- 172.21.15.45:6812/3148625219 >> 172.21.15.142:6789/0 pipe(0x555a86c6f400 sd=21 :33148 s=1 pgs=0 cs=0 l=0 c=0x555a86b44900). got newly_acked_seq 0 vs out_seq 0 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -130> 2018-03-30 10:36:32.331859 7f8513fad700 2 -- 172.21.15.45:6812/3148625219 >> 172.21.15.142:6789/0 pipe(0x555a86c6f400 sd=21 :33148 s=2 pgs=21 cs=1 l=1 c=0x555a86b44900).reader got KEEPALIVE_ACK 2018-03-30T10:36:32.383 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -129> 2018-03-30 10:36:32.332038 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 <== mon.1 172.21.15.142:6789/0 1 ==== mon_map magic: 0 v1 ==== 473+0+0 (2781307839 0 0) 0x555a86c74880 con 0x555a86b44900 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -128> 2018-03-30 10:36:32.332060 7f85167b2700 10 monclient(hunting): handle_monmap mon_map magic: 0 v1 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -127> 2018-03-30 10:36:32.332075 7f85167b2700 10 monclient(hunting): got monmap 1, mon.b is now rank 1 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -126> 2018-03-30 10:36:32.332081 7f85167b2700 10 monclient(hunting): dump: 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: epoch 1 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: fsid 74488b29-f10b-4794-ae29-a8dc66f9f33b 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: last_changed 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: created 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 0: 172.21.15.45:6789/0 mon.a 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 1: 172.21.15.142:6789/0 mon.b 2018-03-30T10:36:32.384 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2: 172.21.15.45:6790/0 mon.c 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -125> 2018-03-30 10:36:32.332109 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 <== mon.1 172.21.15.142:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (1854154430 0 0) 0x555a86b23b80 con 0x555a86b44900 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -124> 2018-03-30 10:36:32.332132 7f85167b2700 10 monclient(hunting): my global_id is 4135 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -123> 2018-03-30 10:36:32.332187 7f85167b2700 10 monclient(hunting): _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -122> 2018-03-30 10:36:32.332199 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 --> 172.21.15.142:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- ?+0 0x555a86b23e00 con 0x555a86b44900 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -121> 2018-03-30 10:36:32.333149 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 <== mon.1 172.21.15.142:6789/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (4064857170 0 0) 0x555a86b23400 con 0x555a86b44900 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -120> 2018-03-30 10:36:32.333242 7f85167b2700 10 monclient(hunting): _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -119> 2018-03-30 10:36:32.333253 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 --> 172.21.15.142:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- ?+0 0x555a86b23b80 con 0x555a86b44900 2018-03-30T10:36:32.385 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -118> 2018-03-30 10:36:32.334002 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 <== mon.1 172.21.15.142:6789/0 4 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 580+0+0 (509217511 0 0) 0x555a86b23e00 con 0x555a86b44900 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -117> 2018-03-30 10:36:32.334115 7f85167b2700 1 monclient(hunting): found mon.b 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -116> 2018-03-30 10:36:32.334118 7f85167b2700 10 monclient: _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -115> 2018-03-30 10:36:32.334122 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 --> 172.21.15.142:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x555a86af8a00 con 0x555a86b44900 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -114> 2018-03-30 10:36:32.334144 7f852bcd9d00 5 monclient: authenticate success, global_id 4135 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -113> 2018-03-30 10:36:32.334158 7f852bcd9d00 10 monclient: renew_subs 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -112> 2018-03-30 10:36:32.334161 7f852bcd9d00 10 monclient: _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -111> 2018-03-30 10:36:32.334164 7f852bcd9d00 1 -- 172.21.15.45:6812/3148625219 --> 172.21.15.142:6789/0 -- mon_subscribe({osdmap=0}) v2 -- ?+0 0x555a86af8c00 con 0x555a86b44900 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -110> 2018-03-30 10:36:32.334873 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 <== mon.1 172.21.15.142:6789/0 5 ==== mon_map magic: 0 v1 ==== 473+0+0 (2781307839 0 0) 0x555a86c74640 con 0x555a86b44900 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -109> 2018-03-30 10:36:32.334893 7f85167b2700 10 monclient: handle_monmap mon_map magic: 0 v1 2018-03-30T10:36:32.386 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -108> 2018-03-30 10:36:32.334901 7f85167b2700 10 monclient: got monmap 1, mon.b is now rank 1 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -107> 2018-03-30 10:36:32.334906 7f85167b2700 10 monclient: dump: 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: epoch 1 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: fsid 74488b29-f10b-4794-ae29-a8dc66f9f33b 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: last_changed 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: created 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 0: 172.21.15.45:6789/0 mon.a 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 1: 172.21.15.142:6789/0 mon.b 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2: 172.21.15.45:6790/0 mon.c 2018-03-30T10:36:32.387 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -106> 2018-03-30 10:36:32.334926 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 <== mon.1 172.21.15.142:6789/0 6 ==== osd_map(7..7 src has 1..7) v3 ==== 9255+0+0 (3117215938 0 0) 0x555a86b24080 con 0x555a86b44900 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -105> 2018-03-30 10:36:32.335121 7f852bcd9d00 10 monclient: renew_subs 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -104> 2018-03-30 10:36:32.335129 7f852bcd9d00 10 monclient: _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -103> 2018-03-30 10:36:32.335134 7f852bcd9d00 1 -- 172.21.15.45:6812/3148625219 --> 172.21.15.142:6789/0 -- mon_subscribe({fsmap=0}) v2 -- ?+0 0x555a86af8e00 con 0x555a86b44900 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -102> 2018-03-30 10:36:32.335141 7f852bcd9d00 4 waiting for MDS map... 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -101> 2018-03-30 10:36:32.335465 7f85167b2700 1 -- 172.21.15.45:6812/3148625219 <== mon.1 172.21.15.142:6789/0 7 ==== fsmap(e 1) v1 ==== 319+0+0 (74130721 0 0) 0x555a86b943c0 con 0x555a86b44900 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -100> 2018-03-30 10:36:32.335490 7f852bcd9d00 4 Got MDS map 1 2018-03-30T10:36:32.388 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -99> 2018-03-30 10:36:32.335568 7f852bcd9d00 10 monclient(hunting): build_initial_monmap 2018-03-30T10:36:32.389 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -98> 2018-03-30 10:36:32.335628 7f852bcd9d00 1 librados: starting msgr at :/0 2018-03-30T10:36:32.389 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -97> 2018-03-30 10:36:32.335632 7f852bcd9d00 1 librados: starting objecter 2018-03-30T10:36:32.389 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -96> 2018-03-30 10:36:32.335697 7f852bcd9d00 5 asok(0x555a86b0a000) register_command objecter_requests hook 0x555a86aca510 EEXIST 2018-03-30T10:36:32.389 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -95> 2018-03-30 10:36:32.335752 7f852bcd9d00 1 -- :/0 messenger.start 2018-03-30T10:36:32.389 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -94> 2018-03-30 10:36:32.335772 7f852bcd9d00 1 librados: setting wanted keys 2018-03-30T10:36:32.389 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -93> 2018-03-30 10:36:32.335778 7f852bcd9d00 1 librados: calling monclient init 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -92> 2018-03-30 10:36:32.335779 7f852bcd9d00 10 monclient(hunting): init 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -91> 2018-03-30 10:36:32.335783 7f852bcd9d00 5 adding auth protocol: cephx 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -90> 2018-03-30 10:36:32.335784 7f852bcd9d00 10 monclient(hunting): auth_supported 2 method cephx 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -89> 2018-03-30 10:36:32.336207 7f852bcd9d00 2 auth: KeyRing::load: loaded key file /etc/ceph/ceph.keyring 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -88> 2018-03-30 10:36:32.336719 7f852bcd9d00 10 monclient(hunting): _reopen_session rank -1 name 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -87> 2018-03-30 10:36:32.337331 7f852bcd9d00 10 monclient(hunting): picked mon.b con 0x555a86b44d80 addr 172.21.15.142:6789/0 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -86> 2018-03-30 10:36:32.337382 7f852bcd9d00 10 monclient(hunting): _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -85> 2018-03-30 10:36:32.337387 7f852bcd9d00 1 -- :/1215501572 --> 172.21.15.142:6789/0 -- auth(proto 0 30 bytes epoch 0) v1 -- ?+0 0x555a86b24a80 con 0x555a86b44d80 2018-03-30T10:36:32.390 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -84> 2018-03-30 10:36:32.337394 7f852bcd9d00 10 monclient(hunting): renew_subs 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -83> 2018-03-30 10:36:32.337397 7f852bcd9d00 10 monclient(hunting): authenticate will time out at 2018-03-30 10:46:32.337397 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -82> 2018-03-30 10:36:32.337595 7f850fea4700 1 -- 172.21.15.45:0/1215501572 learned my addr 172.21.15.45:0/1215501572 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -81> 2018-03-30 10:36:32.337947 7f850fea4700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6789/0 pipe(0x555a86c70800 sd=22 :33164 s=1 pgs=0 cs=0 l=1 c=0x555a86b44d80). got newly_acked_seq 0 vs out_seq 0 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -80> 2018-03-30 10:36:32.338179 7f850fda3700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6789/0 pipe(0x555a86c70800 sd=22 :33164 s=2 pgs=22 cs=1 l=1 c=0x555a86b44d80).reader got KEEPALIVE_ACK 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -79> 2018-03-30 10:36:32.338322 7f85126a9700 1 -- 172.21.15.45:0/1215501572 <== mon.1 172.21.15.142:6789/0 1 ==== mon_map magic: 0 v1 ==== 473+0+0 (2781307839 0 0) 0x555a86cdab40 con 0x555a86b44d80 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -78> 2018-03-30 10:36:32.338342 7f85126a9700 10 monclient(hunting): handle_monmap mon_map magic: 0 v1 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -77> 2018-03-30 10:36:32.338351 7f85126a9700 10 monclient(hunting): got monmap 1, mon.b is now rank 1 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -76> 2018-03-30 10:36:32.338354 7f85126a9700 10 monclient(hunting): dump: 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: epoch 1 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: fsid 74488b29-f10b-4794-ae29-a8dc66f9f33b 2018-03-30T10:36:32.391 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: last_changed 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: created 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 0: 172.21.15.45:6789/0 mon.a 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 1: 172.21.15.142:6789/0 mon.b 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2: 172.21.15.45:6790/0 mon.c 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -75> 2018-03-30 10:36:32.338415 7f85126a9700 1 -- 172.21.15.45:0/1215501572 <== mon.1 172.21.15.142:6789/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (1549265827 0 0) 0x555a86b25480 con 0x555a86b44d80 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -74> 2018-03-30 10:36:32.338447 7f85126a9700 10 monclient(hunting): my global_id is 4138 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -73> 2018-03-30 10:36:32.338505 7f85126a9700 10 monclient(hunting): _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -72> 2018-03-30 10:36:32.338512 7f85126a9700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6789/0 -- auth(proto 2 32 bytes epoch 0) v1 -- ?+0 0x555a86b25700 con 0x555a86b44d80 2018-03-30T10:36:32.392 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -71> 2018-03-30 10:36:32.339508 7f85126a9700 1 -- 172.21.15.45:0/1215501572 <== mon.1 172.21.15.142:6789/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (2287285435 0 0) 0x555a86b24a80 con 0x555a86b44d80 2018-03-30T10:36:32.393 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -70> 2018-03-30 10:36:32.339596 7f85126a9700 10 monclient(hunting): _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.393 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -69> 2018-03-30 10:36:32.339604 7f85126a9700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6789/0 -- auth(proto 2 165 bytes epoch 0) v1 -- ?+0 0x555a86b25480 con 0x555a86b44d80 2018-03-30T10:36:32.393 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -68> 2018-03-30 10:36:32.340209 7f85126a9700 1 -- 172.21.15.45:0/1215501572 <== mon.1 172.21.15.142:6789/0 4 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 393+0+0 (1253944448 0 0) 0x555a86b25700 con 0x555a86b44d80 2018-03-30T10:36:32.393 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -67> 2018-03-30 10:36:32.340307 7f85126a9700 1 monclient(hunting): found mon.b 2018-03-30T10:36:32.393 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -66> 2018-03-30 10:36:32.340309 7f85126a9700 10 monclient: _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.393 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -65> 2018-03-30 10:36:32.340314 7f85126a9700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6789/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x555a86af9200 con 0x555a86b44d80 2018-03-30T10:36:32.393 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -64> 2018-03-30 10:36:32.340352 7f852bcd9d00 5 monclient: authenticate success, global_id 4138 2018-03-30T10:36:32.394 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -63> 2018-03-30 10:36:32.340366 7f852bcd9d00 10 monclient: renew_subs 2018-03-30T10:36:32.394 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -62> 2018-03-30 10:36:32.340369 7f852bcd9d00 10 monclient: _send_mon_message to mon.b at 172.21.15.142:6789/0 2018-03-30T10:36:32.394 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -61> 2018-03-30 10:36:32.340373 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6789/0 -- mon_subscribe({osdmap=0}) v2 -- ?+0 0x555a86af8c00 con 0x555a86b44d80 2018-03-30T10:36:32.394 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -60> 2018-03-30 10:36:32.340412 7f852bcd9d00 10 monclient: renew_subs - empty 2018-03-30T10:36:32.394 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -59> 2018-03-30 10:36:32.340436 7f852bcd9d00 1 librados: init done 2018-03-30T10:36:32.394 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -58> 2018-03-30 10:36:32.340731 7f85126a9700 1 -- 172.21.15.45:0/1215501572 <== mon.1 172.21.15.142:6789/0 5 ==== mon_map magic: 0 v1 ==== 473+0+0 (2781307839 0 0) 0x555a86cdafc0 con 0x555a86b44d80 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -57> 2018-03-30 10:36:32.340749 7f85126a9700 10 monclient: handle_monmap mon_map magic: 0 v1 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -56> 2018-03-30 10:36:32.340757 7f85126a9700 10 monclient: got monmap 1, mon.b is now rank 1 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -55> 2018-03-30 10:36:32.340759 7f85126a9700 10 monclient: dump: 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: epoch 1 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: fsid 74488b29-f10b-4794-ae29-a8dc66f9f33b 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: last_changed 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: created 2018-03-30 10:35:58.065228 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 0: 172.21.15.45:6789/0 mon.a 2018-03-30T10:36:32.395 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 1: 172.21.15.142:6789/0 mon.b 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2: 172.21.15.45:6790/0 mon.c 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -54> 2018-03-30 10:36:32.340815 7f85126a9700 1 -- 172.21.15.45:0/1215501572 <== mon.1 172.21.15.142:6789/0 6 ==== osd_map(7..7 src has 1..7) v3 ==== 9255+0+0 (3117215938 0 0) 0x555a86b25980 con 0x555a86b44d80 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -53> 2018-03-30 10:36:32.340909 7f852bcd9d00 4 datascan.main: pool 'test-rados-api-smithi045-12726-1' has ID 10 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -52> 2018-03-30 10:36:32.341010 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.45:6800/12084 -- osd_op(client.4138.0:1 10.0 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c84680 con 0x555a86b44f00 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -51> 2018-03-30 10:36:32.342369 7f850eb9f700 1 -- 172.21.15.45:0/1215501572 <== osd.2 172.21.15.45:6800/12084 1 ==== osd_op_reply(1 [pgls start_epoch 0] v7'1 uv1 ondisk = 1) v7 ==== 120+0+72 (3224404061 0 873242788) 0x555a86c849c0 con 0x555a86b44f00 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -50> 2018-03-30 10:36:32.342579 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.45:6800/12084 -- osd_op(client.4138.0:2 10.f0b56f30 10000000000.00000000 [tmap2omap 1~0] snapc 0=[] ondisk+write+known_if_redirected e7) v7 -- ?+0 0x555a86c84d00 con 0x555a86b44f00 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -49> 2018-03-30 10:36:32.344369 7f850eb9f700 1 -- 172.21.15.45:0/1215501572 <== osd.2 172.21.15.45:6800/12084 2 ==== osd_op_reply(2 10000000000.00000000 [tmap2omap 1~0] v7'2 uv2 ondisk = 0) v7 ==== 140+0+0 (3647296841 0 0) 0x555a86c849c0 con 0x555a86b44f00 2018-03-30T10:36:32.396 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -48> 2018-03-30 10:36:32.344498 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.45:6804/12085 -- osd_op(client.4138.0:3 10.1 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c85040 con 0x555a86b45500 2018-03-30T10:36:32.397 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -47> 2018-03-30 10:36:32.345383 7f850ea9e700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.45:6804/12085 pipe(0x555a86d1b400 sd=24 :52174 s=1 pgs=0 cs=0 l=1 c=0x555a86b45500). got newly_acked_seq 0 vs out_seq 0 2018-03-30T10:36:32.397 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -46> 2018-03-30 10:36:32.346004 7f850e99d700 1 -- 172.21.15.45:0/1215501572 <== osd.0 172.21.15.45:6804/12085 1 ==== osd_op_reply(3 [pgls start_epoch 0] v0'0 uv0 ondisk = 1) v7 ==== 120+0+44 (2330006328 0 3248547820) 0x555a86c84680 con 0x555a86b45500 2018-03-30T10:36:32.397 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -45> 2018-03-30 10:36:32.346115 7f850e99d700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6808/11909 -- osd_op(client.4138.0:4 10.2 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c84d00 con 0x555a86b45e00 2018-03-30T10:36:32.397 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -44> 2018-03-30 10:36:32.347516 7f850e79b700 1 -- 172.21.15.45:0/1215501572 <== osd.5 172.21.15.142:6808/11909 1 ==== osd_op_reply(4 [pgls start_epoch 0] v0'0 uv0 ondisk = 1) v7 ==== 120+0+44 (209282613 0 3248547820) 0x555a86c85a00 con 0x555a86b45e00 2018-03-30T10:36:32.397 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -43> 2018-03-30 10:36:32.347599 7f850e79b700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6804/11907 -- osd_op(client.4138.0:5 10.3 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c85d40 con 0x555a86b46400 2018-03-30T10:36:32.397 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -42> 2018-03-30 10:36:32.349549 7f850e599700 1 -- 172.21.15.45:0/1215501572 <== osd.4 172.21.15.142:6804/11907 1 ==== osd_op_reply(5 [pgls start_epoch 0] v0'0 uv0 ondisk = 1) v7 ==== 120+0+44 (2371184481 0 3248547820) 0x555a86c863c0 con 0x555a86b46400 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -41> 2018-03-30 10:36:32.350431 7f850e599700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6804/11907 -- osd_op(client.4138.0:6 10.4 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c86700 con 0x555a86b46400 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -40> 2018-03-30 10:36:32.351795 7f850e599700 1 -- 172.21.15.45:0/1215501572 <== osd.4 172.21.15.142:6804/11907 2 ==== osd_op_reply(6 [pgls start_epoch 0] v0'0 uv0 ondisk = 1) v7 ==== 120+0+44 (77986526 0 3248547820) 0x555a86c863c0 con 0x555a86b46400 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -39> 2018-03-30 10:36:32.351829 7f850e599700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.45:6800/12084 -- osd_op(client.4138.0:7 10.5 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c86a40 con 0x555a86b44f00 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -38> 2018-03-30 10:36:32.352328 7f850eb9f700 1 -- 172.21.15.45:0/1215501572 <== osd.2 172.21.15.45:6800/12084 3 ==== osd_op_reply(7 [pgls start_epoch 0] v0'0 uv0 ondisk = 1) v7 ==== 120+0+44 (2240412554 0 3248547820) 0x555a86c849c0 con 0x555a86b44f00 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -37> 2018-03-30 10:36:32.352368 7f850eb9f700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6808/11909 -- osd_op(client.4138.0:8 10.6 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c85d40 con 0x555a86b45e00 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -36> 2018-03-30 10:36:32.353082 7f850e79b700 1 -- 172.21.15.45:0/1215501572 <== osd.5 172.21.15.142:6808/11909 2 ==== osd_op_reply(8 [pgls start_epoch 0] v0'0 uv0 ondisk = 1) v7 ==== 120+0+44 (51482247 0 3248547820) 0x555a86c85a00 con 0x555a86b45e00 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -35> 2018-03-30 10:36:32.353171 7f850e79b700 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6800/11906 -- osd_op(client.4138.0:9 10.7 [pgls start_epoch 0] snapc 0=[] ack+read+known_if_redirected e7) v7 -- ?+0 0x555a86c86080 con 0x555a86b47000 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -34> 2018-03-30 10:36:32.354058 7f850e498700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6800/11906 pipe(0x555a86d34800 sd=27 :37670 s=1 pgs=0 cs=0 l=1 c=0x555a86b47000). got newly_acked_seq 0 vs out_seq 0 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -33> 2018-03-30 10:36:32.354720 7f850e397700 1 -- 172.21.15.45:0/1215501572 <== osd.3 172.21.15.142:6800/11906 1 ==== osd_op_reply(9 [pgls start_epoch 0] v7'1 uv1 ondisk = 1) v7 ==== 120+0+72 (1237327330 0 1611396578) 0x555a86c84d00 con 0x555a86b47000 2018-03-30T10:36:32.398 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -32> 2018-03-30 10:36:32.354783 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 --> 172.21.15.142:6800/11906 -- osd_op(client.4138.0:10 10.c9e0747 10000000001.00000000 [tmap2omap 1~0] snapc 0=[] ondisk+write+known_if_redirected e7) v7 -- ?+0 0x555a86c85380 con 0x555a86b47000 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -31> 2018-03-30 10:36:32.355335 7f850e397700 1 -- 172.21.15.45:0/1215501572 <== osd.3 172.21.15.142:6800/11906 2 ==== osd_op_reply(10 10000000001.00000000 [tmap2omap 1~0] v0'0 uv1 ondisk = 0) v7 ==== 140+0+0 (3265148123 0 0) 0x555a86c84d00 con 0x555a86b47000 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -30> 2018-03-30 10:36:32.355477 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 mark_down 0x555a86b45500 -- 0x555a86d1b400 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -29> 2018-03-30 10:36:32.356730 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 mark_down 0x555a86b44f00 -- 0x555a86d1a000 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -28> 2018-03-30 10:36:32.356771 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 mark_down 0x555a86b47000 -- 0x555a86d34800 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -27> 2018-03-30 10:36:32.356768 7f850eb9f700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.45:6800/12084 pipe(0x555a86d1a000 sd=23 :42206 s=4 pgs=11 cs=1 l=1 c=0x555a86b44f00).reader couldn't read tag, (0) Success 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -26> 2018-03-30 10:36:32.356785 7f850eb9f700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.45:6800/12084 pipe(0x555a86d1a000 sd=23 :42206 s=4 pgs=11 cs=1 l=1 c=0x555a86b44f00).fault (0) Success 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -25> 2018-03-30 10:36:32.356792 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 mark_down 0x555a86b46400 -- 0x555a86d33400 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -24> 2018-03-30 10:36:32.356812 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 mark_down 0x555a86b45e00 -- 0x555a86d32000 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -23> 2018-03-30 10:36:32.356815 7f850e599700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6804/11907 pipe(0x555a86d33400 sd=26 :35404 s=4 pgs=10 cs=1 l=1 c=0x555a86b46400).reader couldn't read tag, (0) Success 2018-03-30T10:36:32.399 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -22> 2018-03-30 10:36:32.356845 7f852bcd9d00 5 asok(0x555a86b0a000) unregister_command objecter_requests 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -21> 2018-03-30 10:36:32.356840 7f850e599700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6804/11907 pipe(0x555a86d33400 sd=26 :35404 s=4 pgs=10 cs=1 l=1 c=0x555a86b46400).fault (0) Success 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -20> 2018-03-30 10:36:32.356856 7f852bcd9d00 10 monclient: shutdown 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -19> 2018-03-30 10:36:32.356869 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 mark_down 0x555a86b44d80 -- 0x555a86c70800 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -18> 2018-03-30 10:36:32.356834 7f850e79b700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6808/11909 pipe(0x555a86d32000 sd=25 :35794 s=4 pgs=13 cs=1 l=1 c=0x555a86b45e00).reader couldn't read tag, (0) Success 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -17> 2018-03-30 10:36:32.356884 7f850e79b700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6808/11909 pipe(0x555a86d32000 sd=25 :35794 s=4 pgs=13 cs=1 l=1 c=0x555a86b45e00).fault (0) Success 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -16> 2018-03-30 10:36:32.356890 7f850e99d700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.45:6804/12085 pipe(0x555a86d1b400 sd=24 :52174 s=4 pgs=17 cs=1 l=1 c=0x555a86b45500).reader couldn't read tag, (0) Success 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -15> 2018-03-30 10:36:32.356935 7f850e99d700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.45:6804/12085 pipe(0x555a86d1b400 sd=24 :52174 s=4 pgs=17 cs=1 l=1 c=0x555a86b45500).fault (0) Success 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -14> 2018-03-30 10:36:32.356990 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 mark_down_all 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -13> 2018-03-30 10:36:32.357125 7f850e397700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6800/11906 pipe(0x555a86d34800 sd=27 :37670 s=4 pgs=14 cs=1 l=1 c=0x555a86b47000).reader couldn't read tag, (0) Success 2018-03-30T10:36:32.400 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -12> 2018-03-30 10:36:32.357144 7f850e397700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6800/11906 pipe(0x555a86d34800 sd=27 :37670 s=4 pgs=14 cs=1 l=1 c=0x555a86b47000).fault (0) Success 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -11> 2018-03-30 10:36:32.360979 7f850fda3700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6789/0 pipe(0x555a86c70800 sd=22 :33164 s=4 pgs=22 cs=1 l=1 c=0x555a86b44d80).reader couldn't read tag, (0) Success 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -10> 2018-03-30 10:36:32.360998 7f850fda3700 2 -- 172.21.15.45:0/1215501572 >> 172.21.15.142:6789/0 pipe(0x555a86c70800 sd=22 :33164 s=4 pgs=22 cs=1 l=1 c=0x555a86b44d80).fault (0) Success 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -9> 2018-03-30 10:36:32.364012 7f852bcd9d00 1 -- 172.21.15.45:0/1215501572 shutdown complete. 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -8> 2018-03-30 10:36:32.364024 7f852bcd9d00 1 librados: shutdown 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -7> 2018-03-30 10:36:32.364485 7f852bcd9d00 5 asok(0x555a86b0a000) unregister_command objecter_requests ENOENT 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -6> 2018-03-30 10:36:32.364494 7f852bcd9d00 10 monclient: shutdown 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -5> 2018-03-30 10:36:32.364498 7f852bcd9d00 1 -- 172.21.15.45:6812/3148625219 mark_down 0x555a86b44900 -- 0x555a86c6f400 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -4> 2018-03-30 10:36:32.364525 7f8513fad700 2 -- 172.21.15.45:6812/3148625219 >> 172.21.15.142:6789/0 pipe(0x555a86c6f400 sd=21 :33148 s=4 pgs=21 cs=1 l=1 c=0x555a86b44900).reader couldn't read tag, (0) Success 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -3> 2018-03-30 10:36:32.364546 7f8513fad700 2 -- 172.21.15.45:6812/3148625219 >> 172.21.15.142:6789/0 pipe(0x555a86c6f400 sd=21 :33148 s=4 pgs=21 cs=1 l=1 c=0x555a86b44900).fault (0) Success 2018-03-30T10:36:32.401 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -2> 2018-03-30 10:36:32.364651 7f852bcd9d00 1 -- 172.21.15.45:6812/3148625219 mark_down_all 2018-03-30T10:36:32.402 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: -1> 2018-03-30 10:36:32.368622 7f852bcd9d00 1 -- 172.21.15.45:6812/3148625219 shutdown complete. 2018-03-30T10:36:32.402 INFO:tasks.workunit.client.0.smithi045.stdout: api_tmap_migrate: 0> 2018-03-30 10:36:32.373540 </pre> The reproducer is <code>--suite rados --filter="rados/basic/{clusters/{fixed-2.yaml openstack.yaml} msgr-failures/few.yaml msgr/random.yaml objectstore/filestore-xfs.yaml rados.yaml tasks/rados_api_tests.yaml}"</code> Unfortunately, our integration testing didn't catch this because we don't ordinarily run the rados suite on CephFS PRs.