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 (both CephFS-related, and both already merged) (all CephFS-related) caused a 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) 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.