Ceph

INFO:teuthology.task.workunit.client.0.out:[ RUN      ] LibRadosCmd.PGCmd
INFO:teuthology.task.workunit.client.0.out:test/librados/cmd.cc:102: Failure
INFO:teuthology.task.workunit.client.0.out:Value of: rados_pg_command(cluster, pgid.c_str(), (const char **)cmd, 1, "", 0, &buf, &buflen, &st, &stlen)
INFO:teuthology.task.workunit.client.0.out:  Actual: -2
INFO:teuthology.task.workunit.client.0.out:Expected: 0
INFO:teuthology.task.workunit.client.0.out:[  FAILED  ] LibRadosCmd.PGCmd (1102 ms)

we need to wait, somewhere, for the pg to exist on that osd.

with logs:

[ RUN      ] LibRadosCmd.PGCmd
2013-06-07 22:29:16.875346 7fac1b651780  1 -- :/0 messenger.start
2013-06-07 22:29:16.876315 7fac1b651780  1 -- :/1001007 --> 10.214.131.10:6790/0 -- auth(proto 0 30 bytes epoch 0) v1 -- ?+0 0x25880e0 con 0x2586c40
2013-06-07 22:29:16.876778 7fac1b649700  1 -- 10.214.131.10:0/1001007 learned my addr 10.214.131.10:0/1001007
2013-06-07 22:29:16.877163 7fac17302700 10 client.?.objecter ms_handle_connect 0x2586c40
2013-06-07 22:29:16.877208 7fac17302700 10 client.?.objecter resend_mon_ops
2013-06-07 22:29:16.877933 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 1 ==== mon_map v1 ==== 473+0+0 (3021958624 0 0) 0x7fac04000b10 con 0x2586c40
2013-06-07 22:29:16.878045 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 2 ==== auth_reply(proto 2 0 Success) v1 ==== 33+0+0 (3646334483 0 0) 0x7fac04000f40 con 0x2586c40
2013-06-07 22:29:16.878352 7fac17302700  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6790/0 -- auth(proto 2 32 bytes epoch 0) v1 -- ?+0 0x7fac000017c0 con 0x2586c40
2013-06-07 22:29:16.879150 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 3 ==== auth_reply(proto 2 0 Success) v1 ==== 206+0+0 (3786993653 0 0) 0x7fac04000f40 con 0x2586c40
2013-06-07 22:29:16.879261 7fac17302700  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6790/0 -- auth(proto 2 165 bytes epoch 0) v1 -- ?+0 0x7fac00001e30 con 0x2586c40
2013-06-07 22:29:16.880034 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 4 ==== auth_reply(proto 2 0 Success) v1 ==== 393+0+0 (2448327637 0 0) 0x7fac04000f40 con 0x2586c40
2013-06-07 22:29:16.880100 7fac17302700  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6790/0 -- mon_subscribe({monmap=0+}) v2 -- ?+0 0x257dc50 con 0x2586c40
2013-06-07 22:29:16.880261 7fac1b651780 10 client.4481.objecter maybe_request_map subscribing (onetime) to next osd map
2013-06-07 22:29:16.880290 7fac1b651780  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6790/0 -- mon_subscribe({monmap=2+,osdmap=0}) v2 -- ?+0 0x2588830 con 0x2586c40
2013-06-07 22:29:16.880311 7fac1b651780  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6790/0 -- mon_subscribe({monmap=2+,osdmap=0}) v2 -- ?+0 0x2588db0 con 0x2586c40
2013-06-07 22:29:16.880880 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 5 ==== mon_map v1 ==== 473+0+0 (3021958624 0 0) 0x7fac04001170 con 0x2586c40
2013-06-07 22:29:16.880962 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 6 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (910412080 0 0) 0x7fac04001360 con 0x2586c40
2013-06-07 22:29:16.881310 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 7 ==== osd_map(389..389 src has 1..389) v3 ==== 5597+0+0 (4287032395 0 0) 0x7fac04002530 con 0x2586c40
2013-06-07 22:29:16.881362 7fac17302700  3 client.4481.objecter handle_osd_map got epochs [389,389] > 0
2013-06-07 22:29:16.881368 7fac17302700  3 client.4481.objecter handle_osd_map decoding full epoch 389
2013-06-07 22:29:16.881507 7fac17302700 20 client.4481.objecter dump_active .. 0 homeless
2013-06-07 22:29:16.881526 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 8 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (910412080 0 0) 0x7fac04002740 con 0x2586c40
2013-06-07 22:29:16.881543 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 9 ==== osd_map(389..389 src has 1..389) v3 ==== 5597+0+0 (4287032395 0 0) 0x7fac04003ee0 con 0x2586c40
2013-06-07 22:29:16.881602 7fac1b651780 10 client.4481.objecter create_pool name=test-rados-api-plana30-1007-1
2013-06-07 22:29:16.881611 7fac1b651780 10 client.4481.objecter pool_op_submit 1
2013-06-07 22:29:16.881620 7fac1b651780  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6790/0 -- pool_op(create pool 0 auid 0 tid 1 name test-rados-api-plana30-1007-1 v0) v4 -- ?+0 0x258a300 con 0x2586c40
2013-06-07 22:29:16.881671 7fac17302700  3 client.4481.objecter handle_osd_map ignoring epochs [389,389] <= 389
2013-06-07 22:29:16.881680 7fac17302700 20 client.4481.objecter dump_active .. 0 homeless
2013-06-07 22:29:16.881692 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 10 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (910412080 0 0) 0x7fac040042c0 con 0x2586c40
2013-06-07 22:29:17.132254 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 11 ==== pool_op_reply(tid 1 (0) Success v390) v1 ==== 43+0+0 (153846711 0 0) 0x7fac04000f40 con 0x2586c40
2013-06-07 22:29:17.132308 7fac17302700 10 client.4481.objecter handle_pool_op_reply pool_op_reply(tid 1 (0) Success v390) v1
2013-06-07 22:29:17.132324 7fac17302700 10 client.4481.objecter have request 1 at 0x2579f50 Op: create
2013-06-07 22:29:17.132328 7fac17302700 20 client.4481.objecter waiting for client to reach epoch 390 before calling back
2013-06-07 22:29:17.132337 7fac17302700 10 client.4481.objecter maybe_request_map subscribing (onetime) to next osd map
2013-06-07 22:29:17.132355 7fac17302700  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6790/0 -- mon_subscribe({monmap=2+,osdmap=390}) v2 -- ?+0 0x7fac00007360 con 0x2586c40
2013-06-07 22:29:17.132383 7fac17302700 10 client.4481.objecter done
2013-06-07 22:29:17.133273 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 12 ==== osd_map(390..390 src has 1..390) v3 ==== 304+0+0 (4217877855 0 0) 0x7fac04000f40 con 0x2586c40
2013-06-07 22:29:17.133305 7fac17302700  3 client.4481.objecter handle_osd_map got epochs [390,390] > 389
2013-06-07 22:29:17.133328 7fac17302700  3 client.4481.objecter handle_osd_map decoding incremental epoch 390
2013-06-07 22:29:17.133376 7fac17302700 20 client.4481.objecter dump_active .. 0 homeless
2013-06-07 22:29:17.133399 7fac17302700  1 -- 10.214.131.10:0/1001007 <== mon.2 10.214.131.10:6790/0 13 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (910412080 0 0) 0x7fac04001150 con 0x2586c40
2013-06-07 22:29:17.133514 7fac1b651780 10 client.4481.objecter _submit_command 2 [asdfasdf]
2013-06-07 22:29:17.133609 7fac1b651780 10 client.4481.objecter recalc_command_target 2 now 0
2013-06-07 22:29:17.133615 7fac1b651780 10 client.4481.objecter _send_command 2
2013-06-07 22:29:17.133618 7fac1b651780  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6805/21770 -- command(tid 2: asdfasdf) v1 -- ?+0 0x258c010 con 0x258aa40
2013-06-07 22:29:17.134571 7fac17302700 10 client.4481.objecter ms_handle_connect 0x258aa40
2013-06-07 22:29:17.134591 7fac141fb700  1 -- 10.214.131.10:0/1001007 >> 10.214.131.10:6805/21770 pipe(0x258a7e0 sd=8 :60256 s=2 pgs=19 cs=1 l=1).setting up a delay queue on Pipe 0x258a7e0
2013-06-07 22:29:17.135558 7fac17302700  1 -- 10.214.131.10:0/1001007 <== osd.1 10.214.131.10:6805/21770 1 ==== command_reply(tid 2: -22 unparseable JSON asdfasdf) v1 ==== 33+0+1 (471822105 0 1809983544) 0x7fabf4000a00 con 0x258aa40
2013-06-07 22:29:17.135593 7fac17302700 10 client.4481.objecter _finish_command 2 = -22 unparseable JSON asdfasdf
2013-06-07 22:29:17.135634 7fac1b651780 10 client.4481.objecter _submit_command 3 [{"prefix":"pg", "cmd":"query", "pgid":"121.0"}]
2013-06-07 22:29:17.135649 7fac1b651780 10 client.4481.objecter recalc_command_target 3 now 0
2013-06-07 22:29:17.135651 7fac1b651780 10 client.4481.objecter _send_command 3
2013-06-07 22:29:17.135654 7fac1b651780  1 -- 10.214.131.10:0/1001007 --> 10.214.131.10:6805/21770 -- command(tid 3: {"prefix":"pg", "cmd":"query", "pgid":"121.0"}) v1 -- ?+0 0x258c3b0 con 0x258aa40
2013-06-07 22:29:17.136322 7fac17302700  1 -- 10.214.131.10:0/1001007 <== osd.1 10.214.131.10:6805/21770 2 ==== command_reply(tid 3: -2 i don't have pgid 121.0) v1 ==== 31+0+1 (4157416715 0 1809983544) 0x7fabf4000a00 con 0x258aa40
2013-06-07 22:29:17.136355 7fac17302700 10 test/librados/cmd.cc:102: Failure
Value of: rados_pg_command(cluster, pgid.c_str(), (const char **)cmd, 1, "", 0, &buf, &buflen, &st, &stlen)
  Actual: -2
Expected: 0
[  FAILED  ] LibRadosCmd.PGCmdclient.4481.objecter _finish_command 3 = -2 i don't have pgid 121.0
 (265 ms)