couldn't use rbd

All of lore.kernel.org
 help / color / mirror / Atom feed

* couldn't use rbd
@ 2012-02-02  9:49 Masuko Tomoya
  2012-02-03  1:26 ` Josh Durgin
  0 siblings, 1 reply; 9+ messages in thread
From: Masuko Tomoya @ 2012-02-02  9:49 UTC (permalink / raw)
  To: ceph-devel

Hi, all.

When I execute "rbd" command, it is not success.

root@ceph01:~# rbd list
(no response)

/var/log/ceph/mon.0.log
-----
2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0 <==
client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
0x1619c00 con 0x1615a00
2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0 <==
client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
0x1619a00 con 0x1615a00
2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0 <==
client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
0x161fc00 con 0x1615a00
2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0 <==
client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
0x163d780
2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0 <==
client.4112 10.68.119.191:0/1002580 5 ====
mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
0x1617a80 con 0x1615a00
2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
?+0 0x1619600
2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
?+0 0x163d900
2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0 <==
client.4112 10.68.119.191:0/1002580 6 ====
mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
0x16178c0 con 0x1615a00
2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
?+0 0x1619400
2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
?+0 0x161d300
-----

BTW, I could execute "rados lspools".

root@ceph01:~# rados lspools
data
metadata
rbd

I would like to use rbd volume and attach it as virtual device for VM
guest on KVM.

Could you advice to me ?


My environment is below.

*ceph cluster is configured on single server.
*server is ubuntu 10.10 maverick.
*ceph, librados2 and librbd1 packages are installed.
 (version: 0.38-1maverick)
*apparmor is disable.
*root@ceph01:/# ls -l /etc/ceph
total 16
-rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
-rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
-rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
-rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
*/var/lib/ceph/tmp is exists.
root@ceph01:/var/log# ls -l /var/lib/ceph/
total 4
drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp

*/etc/ceph/ceph.conf
[global]
        auth supported = cephx
        keyring = /etc/ceph/$name.keyring
[mon]
        mon data = /data/data/mon$id
        debug ms = 1
[mon.0]
        host = ceph01
        mon addr = 10.68.119.191:6789
[mds]

[mds.0]
        host = ceph01
[osd]
        osd data = /data/osd$id
        osd journal = /data/osd$id/journal
        osd journal size = 512
        osd class tmp = /var/lib/ceph/tmp
[osd.0]
        host = ceph01
        btrfs devs = /dev/sdb1


Waiting for your reply,

Tomoya.

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-02  9:49 couldn't use rbd Masuko Tomoya
@ 2012-02-03  1:26 ` Josh Durgin
  2012-02-03  8:51   ` Masuko Tomoya
  0 siblings, 1 reply; 9+ messages in thread
From: Josh Durgin @ 2012-02-03  1:26 UTC (permalink / raw)
  To: Masuko Tomoya; +Cc: ceph-devel

On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
> Hi, all.
>
> When I execute "rbd" command, it is not success.
>
> root@ceph01:~# rbd list
> (no response)
>
> /var/log/ceph/mon.0.log
> -----
> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
> 0x1619c00 con 0x1615a00
> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
> 0x1619a00 con 0x1615a00
> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
> 0x161fc00 con 0x1615a00
> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
> 0x163d780
> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
> client.4112 10.68.119.191:0/1002580 5 ====
> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
> 0x1617a80 con 0x1615a00
> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
> ?+0 0x1619600
> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
> ?+0 0x163d900
> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
> client.4112 10.68.119.191:0/1002580 6 ====
> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
> 0x16178c0 con 0x1615a00
> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
> ?+0 0x1619400
> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
> ?+0 0x161d300
> -----

No problems there.

>
> BTW, I could execute "rados lspools".
>
> root@ceph01:~# rados lspools
> data
> metadata
> rbd

This might mean the rbd image list object can't be read for some
reason, or the rbd tool is doing something weird that the rados tool
isn't. Can you share the output of 'ceph -s' and
'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20 
--debug-auth 20'?

You can run 'rados lspools' with those options as well and compare.

> I would like to use rbd volume and attach it as virtual device for VM
> guest on KVM.
>
> Could you advice to me ?
>
>
> My environment is below.
>
> *ceph cluster is configured on single server.
> *server is ubuntu 10.10 maverick.
> *ceph, librados2 and librbd1 packages are installed.
>   (version: 0.38-1maverick)
> *apparmor is disable.

apparmor shouldn't matter if you have libvirt 0.9.9 or newer.

> *root@ceph01:/# ls -l /etc/ceph
> total 16
> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
> */var/lib/ceph/tmp is exists.
> root@ceph01:/var/log# ls -l /var/lib/ceph/
> total 4
> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>
> */etc/ceph/ceph.conf
> [global]
>          auth supported = cephx
>          keyring = /etc/ceph/$name.keyring
> [mon]
>          mon data = /data/data/mon$id
>          debug ms = 1
> [mon.0]
>          host = ceph01
>          mon addr = 10.68.119.191:6789
> [mds]
>
> [mds.0]
>          host = ceph01
> [osd]
>          osd data = /data/osd$id
>          osd journal = /data/osd$id/journal
>          osd journal size = 512
>          osd class tmp = /var/lib/ceph/tmp
> [osd.0]
>          host = ceph01
>          btrfs devs = /dev/sdb1
>
>
> Waiting for your reply,
>
> Tomoya.



^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-03  1:26 ` Josh Durgin
@ 2012-02-03  8:51   ` Masuko Tomoya
  2012-02-03 17:05     ` Josh Durgin
  0 siblings, 1 reply; 9+ messages in thread
From: Masuko Tomoya @ 2012-02-03  8:51 UTC (permalink / raw)
  To: josh.durgin; +Cc: ceph-devel

Hi Josh,

Thank you for reply !

> This might mean the rbd image list object can't be read for some
> reason, or the rbd tool is doing something weird that the rados tool
> isn't. Can you share the output of 'ceph -s' and
> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
> --debug-auth 20'?

The output of 'ceph -s' is below.
-------
root@ceph01:~# ceph -s
2012-02-03 17:01:47.881960    pg v33: 6 pgs: 6 active+clean+degraded;
0 KB data, 1056 KB used, 15357 MB / 15358 MB avail
2012-02-03 17:01:47.882583   mds e9: 1/1/1 up {0=0=up:creating}
2012-02-03 17:01:47.882733   osd e21: 1 osds: 1 up, 1 in
2012-02-03 17:01:47.883042   log 2012-02-03 16:35:11.183897 osd.0
10.68.119.191:6801/2912 12 : [WRN] map e19 wrongly marked me down or
wrong addr
2012-02-03 17:01:47.883144   mon e1: 1 mons at {0=10.68.119.191:6789/0}

The output of 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
--debug-monc 20 --debug-auth 20' is below.
------
root@ceph01:~# rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
--debug-monc 20 --debug-auth 20
2012-02-03 17:02:10.910598 7f88cbb91720 monclient(hunting): build_initial_monmap
2012-02-03 17:02:10.910912 7f88cbb91720 -- :/0 messenger.start
2012-02-03 17:02:10.910966 7f88cbb91720 monclient(hunting): init
2012-02-03 17:02:10.911268 7f88cbb91720 auth: KeyRing::load: loaded
key file /etc/ceph/keyring.bin
2012-02-03 17:02:10.911952 7f88cbb91720 monclient(hunting): supporting
cephx auth protocol
2012-02-03 17:02:10.911984 7f88cbb91720 monclient(hunting): _reopen_session
2012-02-03 17:02:10.912098 7f88cbb91720 monclient(hunting):
_pick_new_mon picked mon.0 con 0x24603e0 addr 10.68.119.191:6789/0
2012-02-03 17:02:10.912124 7f88cbb91720 monclient(hunting):
_send_mon_message to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:02:10.951553 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6789/0 -- auth(proto 0 30 bytes) v1 -- ?+0 0x24606f0 con
0x24603e0
2012-02-03 17:02:10.951729 7f88cbb8f710 -- 10.68.119.191:0/1003500
learned my addr 10.68.119.191:0/1003500
2012-02-03 17:02:10.952949 7f88cbb91720 monclient(hunting): renew_subs
2012-02-03 17:02:10.953012 7f88cbb91720 monclient(hunting):
authenticate will time out at 2012-02-03 17:02:40.952983
2012-02-03 17:02:10.953392 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 1 ==== auth_reply(proto 2 0 Success) v1
==== 33+0+0 (1661896955 0 0) 0x24608d0 con 0x24603e0
2012-02-03 17:02:10.953444 7f88c9366710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:02:10.953455 7f88c9366710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:02:10.953462 7f88c9366710 cephx: set_have_need_key no
handler for service auth
2012-02-03 17:02:10.953504 7f88c9366710 cephx: validate_tickets want
37 have 0 need 37
2012-02-03 17:02:10.953526 7f88c9366710 monclient(hunting): my global_id is 4106
2012-02-03 17:02:10.953546 7f88c9366710 cephx client: handle_response ret = 0
2012-02-03 17:02:10.953557 7f88c9366710 cephx client:  got initial
server challenge 15014444581746095987
2012-02-03 17:02:10.953575 7f88c9366710 cephx client: build_request
2012-02-03 17:02:10.953586 7f88c9366710 cephx client:
validate_tickets: want=37 need=37 have=0
2012-02-03 17:02:10.953592 7f88c9366710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:02:10.953598 7f88c9366710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:02:10.953604 7f88c9366710 cephx: set_have_need_key no
handler for service auth
2012-02-03 17:02:10.953610 7f88c9366710 cephx: validate_tickets want
37 have 0 need 37
2012-02-03 17:02:10.953617 7f88c9366710 cephx client: want=37 need=37 have=0
2012-02-03 17:02:10.953920 7f88c9366710 cephx client: get auth session
key: client_challenge 394141338555354357
2012-02-03 17:02:10.953953 7f88c9366710 monclient(hunting):
_send_mon_message to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:02:10.953967 7f88c9366710 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6789/0 -- auth(proto 2 32 bytes) v1 -- ?+0 0x24608d0 con
0x24603e0
2012-02-03 17:02:10.954517 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 2 ==== auth_reply(proto 2 0 Success) v1
==== 206+0+0 (707160412 0 0) 0x24608d0 con 0x24603e0
2012-02-03 17:02:10.954535 7f88c9366710 cephx client: handle_response ret = 0
2012-02-03 17:02:10.954555 7f88c9366710 cephx client:  get_auth_session_key
2012-02-03 17:02:10.954576 7f88c9366710 cephx:
verify_service_ticket_reply got 1 keys
2012-02-03 17:02:10.954587 7f88c9366710 cephx: got key for service_id auth
2012-02-03 17:02:10.954696 7f88c9366710 cephx:  ticket.secret_id=2
2012-02-03 17:02:10.954737 7f88c9366710 cephx:
verify_service_ticket_reply service auth secret_id 2 session_key
AQCClCtPyL7gOBAAaDicPRG6NHbgUs+4YNntWQ== validity=43200.000000
2012-02-03 17:02:10.954756 7f88c9366710 cephx: ticket
expires=2012-02-04 05:02:10.954749 renew_after=2012-02-04
02:02:10.954749
2012-02-03 17:02:10.954764 7f88c9366710 cephx client:  want=37 need=37 have=0
2012-02-03 17:02:10.954771 7f88c9366710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:02:10.954777 7f88c9366710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:02:10.954783 7f88c9366710 cephx: validate_tickets want
37 have 32 need 5
2012-02-03 17:02:10.954792 7f88c9366710 cephx client: build_request
2012-02-03 17:02:10.954798 7f88c9366710 cephx client:
validate_tickets: want=37 need=5 have=32
2012-02-03 17:02:10.954804 7f88c9366710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:02:10.954810 7f88c9366710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:02:10.954816 7f88c9366710 cephx: validate_tickets want
37 have 32 need 5
2012-02-03 17:02:10.954823 7f88c9366710 cephx client: want=37 need=5 have=32
2012-02-03 17:02:10.954829 7f88c9366710 cephx client: get service
keys: want=37 need=5 have=32
2012-02-03 17:02:10.954875 7f88c9366710 monclient(hunting):
_send_mon_message to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:02:10.954891 7f88c9366710 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6789/0 -- auth(proto 2 165 bytes) v1 -- ?+0 0x24608d0
con 0x24603e0
2012-02-03 17:02:10.955499 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 3 ==== auth_reply(proto 2 0 Success) v1
==== 409+0+0 (2367917727 0 0) 0x2460df0 con 0x24603e0
2012-02-03 17:02:10.955518 7f88c9366710 cephx client: handle_response ret = 0
2012-02-03 17:02:10.955534 7f88c9366710 cephx client:
get_principal_session_key session_key
AQCClCtPyL7gOBAAaDicPRG6NHbgUs+4YNntWQ==
2012-02-03 17:02:10.955543 7f88c9366710 cephx:
verify_service_ticket_reply got 2 keys
2012-02-03 17:02:10.955550 7f88c9366710 cephx: got key for service_id mon
2012-02-03 17:02:10.955583 7f88c9366710 cephx:  ticket.secret_id=7
2012-02-03 17:02:10.955599 7f88c9366710 cephx:
verify_service_ticket_reply service mon secret_id 7 session_key
AQCClCtPiEvuOBAAAS1JWDWR4qsQNRbzS5sP3A== validity=3600.000000
2012-02-03 17:02:10.955612 7f88c9366710 cephx: ticket
expires=2012-02-03 18:02:10.955607 renew_after=2012-02-03
17:47:10.955607
2012-02-03 17:02:10.955619 7f88c9366710 cephx: got key for service_id osd
2012-02-03 17:02:10.955639 7f88c9366710 cephx:  ticket.secret_id=7
2012-02-03 17:02:10.955654 7f88c9366710 cephx:
verify_service_ticket_reply service osd secret_id 7 session_key
AQCClCtP2JHuOBAAiOPA//0jJgXE3fFj6O9Zgg== validity=3600.000000
2012-02-03 17:02:10.955666 7f88c9366710 cephx: ticket
expires=2012-02-03 18:02:10.955661 renew_after=2012-02-03
17:47:10.955661
2012-02-03 17:02:10.966672 7f88c9366710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:02:10.966727 7f88c9366710 monclient(hunting): found mon.0
2012-02-03 17:02:10.966742 7f88c9366710 monclient: _send_mon_message
to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:02:10.966794 7f88c9366710 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6789/0 -- mon_subscribe({monmap=0+}) v1 -- ?+0 0x24606f0
con 0x24603e0
2012-02-03 17:02:10.967235 7f88c9366710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:02:10.967251 7f88c9366710 cephx client: need_tickets:
want=37 need=0 have=37
2012-02-03 17:02:10.967259 7f88c9366710 monclient:
_check_auth_rotating not needed by client.admin
2012-02-03 17:02:10.967285 7f88cbb91720 monclient: authenticate
success, global_id 4106
2012-02-03 17:02:10.967452 7f88cbb91720 client.4106.objecter
maybe_request_map subscribing (onetime) to next osd map
2012-02-03 17:02:10.967472 7f88cbb91720 monclient: renew_subs
2012-02-03 17:02:10.967486 7f88cbb91720 monclient: _send_mon_message
to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:02:10.967500 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6789/0 -- mon_subscribe({monmap=0+,osdmap=0}) v1 -- ?+0
0x2460ca0 con 0x24603e0
2012-02-03 17:02:10.967512 7f88cbb91720 monclient: renew_subs
2012-02-03 17:02:10.967522 7f88cbb91720 monclient: _send_mon_message
to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:02:10.967533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6789/0 -- mon_subscribe({monmap=0+,osdmap=0}) v1 -- ?+0
0x2461ab0 con 0x24603e0
2012-02-03 17:02:10.970017 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 4 ==== mon_map v1 ==== 187+0+0 (1638929821
0 0) 0x2460cf0 con 0x24603e0
2012-02-03 17:02:10.970062 7f88c9366710 monclient: handle_monmap mon_map v1
2012-02-03 17:02:10.970114 7f88c9366710 monclient:  got monmap 1,
mon.0 is now rank 0
2012-02-03 17:02:10.970156 7f88c9366710 monclient: dump:
epoch 1
fsid fe5407e1-f9b0-69f4-4dfe-52ae762929ab
last_changed 2012-02-03 10:19:58.428136
created 2012-02-03 10:19:58.428136
0: 10.68.119.191:6789/0 mon.0

2012-02-03 17:02:10.970221 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 5 ==== mon_subscribe_ack(300s) v1 ====
20+0+0 (3873334622 0 0) 0x2461cd0 con 0x24603e0
2012-02-03 17:02:10.970250 7f88c9366710 monclient:
handle_subscribe_ack sent 2012-02-03 17:02:10.952969 renew after
2012-02-03 17:04:40.952969
2012-02-03 17:02:10.970281 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 6 ==== mon_map v1 ==== 187+0+0 (1638929821
0 0) 0x2461ee0 con 0x24603e0
2012-02-03 17:02:10.970324 7f88c9366710 monclient: handle_monmap mon_map v1
2012-02-03 17:02:10.970348 7f88c9366710 monclient:  got monmap 1,
mon.0 is now rank 0
2012-02-03 17:02:10.970379 7f88c9366710 monclient: dump:
epoch 1
fsid fe5407e1-f9b0-69f4-4dfe-52ae762929ab
last_changed 2012-02-03 10:19:58.428136
created 2012-02-03 10:19:58.428136
0: 10.68.119.191:6789/0 mon.0

2012-02-03 17:02:10.970431 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
==== 1284+0+0 (473305567 0 0) 0x2462630 con 0x24603e0
2012-02-03 17:02:10.970488 7f88c9366710 client.4106.objecter
handle_osd_map got epochs [21,21] > 0
2012-02-03 17:02:10.970507 7f88c9366710 client.4106.objecter
handle_osd_map decoding full epoch 21
2012-02-03 17:02:10.970664 7f88c9366710 client.4106.objecter
dump_active .. 0 homeless
2012-02-03 17:02:10.970863 7f88cbb91720 client.4106.objecter
recalc_op_target tid 1 pgid 2.30a98c1c acting [0]
2012-02-03 17:02:10.971004 7f88cbb91720 client.4106.objecter  note:
not requesting commit
2012-02-03 17:02:10.971391 7f88cbb91720 client.4106.objecter op_submit
oid rbd_directory @2 [read 0~0] tid 1 osd.0
2012-02-03 17:02:10.971465 7f88cbb91720 client.4106.objecter send_op 1 to osd.0
2012-02-03 17:02:10.971533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6801/2912 -- osd_op(client.4106.0:1 rbd_directory [read
0~0] 2.30a98c1c) v1 -- ?+0 0x24664c0 con 0x24661b0
2012-02-03 17:02:10.971558 7f88cbb91720 client.4106.objecter 1
unacked, 0 uncommitted
2012-02-03 17:02:10.971615 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 8 ==== mon_subscribe_ack(300s) v1 ====
20+0+0 (3873334622 0 0) 0x2462970 con 0x24603e0
2012-02-03 17:02:10.971638 7f88c9366710 monclient:
handle_subscribe_ack sent 0.000000, ignoring
2012-02-03 17:02:10.971666 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 9 ==== mon_map v1 ==== 187+0+0 (1638929821
0 0) 0x2462c50 con 0x24603e0
2012-02-03 17:02:10.971683 7f88c9366710 monclient: handle_monmap mon_map v1
2012-02-03 17:02:10.971704 7f88c9366710 monclient:  got monmap 1,
mon.0 is now rank 0
2012-02-03 17:02:10.971736 7f88c9366710 monclient: dump:
epoch 1
fsid fe5407e1-f9b0-69f4-4dfe-52ae762929ab
last_changed 2012-02-03 10:19:58.428136
created 2012-02-03 10:19:58.428136
0: 10.68.119.191:6789/0 mon.0

2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
handle_osd_map ignoring epochs [21,21] <= 21
2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
dump_active .. 0 homeless
2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
2.30a98c1c      osd.0   rbd_directory   [read 0~0]
2012-02-03 17:02:10.971851 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 11 ==== mon_subscribe_ack(300s) v1 ====
20+0+0 (3873334622 0 0) 0x24658c0 con 0x24603e0
2012-02-03 17:02:10.971870 7f88c9366710 monclient:
handle_subscribe_ack sent 0.000000, ignoring
2012-02-03 17:02:10.973607 7f88c6a60710 cephx client: build_authorizer
for service osd
2012-02-03 17:02:13.912816 7f88c8364710 monclient: tick
2012-02-03 17:02:13.912887 7f88c8364710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:02:13.912896 7f88c8364710 cephx client: need_tickets:
want=37 need=0 have=37
2012-02-03 17:02:13.912903 7f88c8364710 monclient:
_check_auth_rotating not needed by client.admin
2012-02-03 17:02:15.967773 7f88c7261710 client.4106.objecter tick
2012-02-03 17:02:20.969006 7f88c7261710 client.4106.objecter tick
2012-02-03 17:02:23.913191 7f88c8364710 monclient: tick
2012-02-03 17:02:23.913276 7f88c8364710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:02:23.913285 7f88c8364710 cephx client: need_tickets:
want=37 need=0 have=37
2012-02-03 17:02:23.913292 7f88c8364710 monclient:
_check_auth_rotating not needed by client.admin
2012-02-03 17:02:25.969271 7f88c7261710 client.4106.objecter tick
2012-02-03 17:02:25.969338 7f88c7261710 client.4106.objecter  tid 1 on
osd.0 is laggy
2012-02-03 17:02:25.969352 7f88c7261710 client.4106.objecter
maybe_request_map subscribing (onetime) to next osd map
2012-02-03 17:02:25.969368 7f88c7261710 monclient: renew_subs
2012-02-03 17:02:25.969410 7f88c7261710 monclient: _send_mon_message
to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:02:25.969433 7f88c7261710 -- 10.68.119.191:0/1003500 -->
10.68.119.191:6789/0 -- mon_subscribe({monmap=2+,osdmap=22}) v1 -- ?+0
0x2462970 con 0x24603e0
2012-02-03 17:02:25.969484 7f88c7261710 -- 10.68.119.191:0/1003500 -->
osd.0 10.68.119.191:6801/2912 -- ping v1 -- ?+0 0x2465890
2012-02-03 17:02:25.970074 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 12 ==== mon_subscribe_ack(300s) v1 ====
20+0+0 (3873334622 0 0) 0x2462970 con 0x24603e0
2012-02-03 17:02:25.970099 7f88c9366710 monclient:
handle_subscribe_ack sent 2012-02-03 17:02:25.969373 renew after
2012-02-03 17:04:55.969373
2012-02-03 17:02:30.970489 7f88c7261710 client.4106.objecter tick
2012-02-03 17:02:30.970556 7f88c7261710 client.4106.objecter  tid 1 on
osd.0 is laggy
2012-02-03 17:02:30.970574 7f88c7261710 client.4106.objecter
maybe_request_map subscribing (onetime) to next osd map
2012-02-03 17:02:30.970622 7f88c7261710 -- 10.68.119.191:0/1003500 -->
osd.0 10.68.119.191:6801/2912 -- ping v1 -- ?+0 0x2462970
2012-02-03 17:02:33.913630 7f88c8364710 monclient: tick
2012-02-03 17:02:33.913702 7f88c8364710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:02:33.913710 7f88c8364710 cephx client: need_tickets:
want=37 need=0 have=37
2012-02-03 17:02:33.913717 7f88c8364710 monclient:
_check_auth_rotating not needed by client.admin
2012-02-03 17:02:35.971828 7f88c7261710 client.4106.objecter tick
2012-02-03 17:02:35.971896 7f88c7261710 client.4106.objecter  tid 1 on
osd.0 is laggy
2012-02-03 17:02:35.971911 7f88c7261710 client.4106.objecter
maybe_request_map subscribing (onetime) to next osd map
2012-02-03 17:02:35.971946 7f88c7261710 -- 10.68.119.191:0/1003500 -->
osd.0 10.68.119.191:6801/2912 -- ping v1 -- ?+0 0x2462970
2012-02-03 17:02:40.972951 7f88c7261710 client.4106.objecter tick
2012-02-03 17:02:40.973014 7f88c7261710 client.4106.objecter  tid 1 on
osd.0 is laggy
2012-02-03 17:02:40.973027 7f88c7261710 client.4106.objecter
maybe_request_map subscribing (onetime) to next osd map
2012-02-03 17:02:40.973059 7f88c7261710 -- 10.68.119.191:0/1003500 -->
osd.0 10.68.119.191:6801/2912 -- ping v1 -- ?+0 0x2462970
2012-02-03 17:02:43.914127 7f88c8364710 monclient: tick
2012-02-03 17:02:43.914201 7f88c8364710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:02:43.914210 7f88c8364710 cephx client: need_tickets:
want=37 need=0 have=37
2012-02-03 17:02:43.914218 7f88c8364710 monclient:
_check_auth_rotating not needed by client.admin
2012-02-03 17:02:45.974193 7f88c7261710 client.4106.objecter tick
2012-02-03 17:02:45.974277 7f88c7261710 client.4106.objecter  tid 1 on
osd.0 is laggy
2012-02-03 17:02:45.974291 7f88c7261710 client.4106.objecter
maybe_request_map subscribing (onetime) to next osd map
2012-02-03 17:02:45.974324 7f88c7261710 -- 10.68.119.191:0/1003500 -->
osd.0 10.68.119.191:6801/2912 -- ping v1 -- ?+0 0x2462970


I executed 'rados lspools' with the same options.
-------
root@ceph01:~# rados lspools --log-to-stderr --debug-ms 1
--debug-objecter 20 --debug-monc 20 --debug-auth 20
2012-02-03 17:11:52.849708 7f9c59a59720 monclient(hunting): build_initial_monmap
2012-02-03 17:11:52.850071 7f9c59a59720 -- :/0 messenger.start
2012-02-03 17:11:52.850121 7f9c59a59720 monclient(hunting): init
2012-02-03 17:11:52.850469 7f9c59a59720 auth: KeyRing::load: loaded
key file /etc/ceph/keyring.bin
2012-02-03 17:11:52.851095 7f9c59a59720 monclient(hunting): supporting
cephx auth protocol
2012-02-03 17:11:52.851127 7f9c59a59720 monclient(hunting): _reopen_session
2012-02-03 17:11:52.851258 7f9c59a59720 monclient(hunting):
_pick_new_mon picked mon.0 con 0x771440 addr 10.68.119.191:6789/0
2012-02-03 17:11:52.851288 7f9c59a59720 monclient(hunting):
_send_mon_message to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:11:52.851833 7f9c59a59720 -- :/1003868 -->
10.68.119.191:6789/0 -- auth(proto 0 30 bytes) v1 -- ?+0 0x771760 con
0x771440
2012-02-03 17:11:52.851864 7f9c59a59720 monclient(hunting): renew_subs
2012-02-03 17:11:52.851922 7f9c59a59720 monclient(hunting):
authenticate will time out at 2012-02-03 17:12:22.851894
2012-02-03 17:11:52.852565 7f9c59a57710 -- 10.68.119.191:0/1003868
learned my addr 10.68.119.191:0/1003868
2012-02-03 17:11:52.854120 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 1 ==== auth_reply(proto 2 0 Success) v1
==== 33+0+0 (1236223873 0 0) 0x76e000 con 0x771440
2012-02-03 17:11:52.854189 7f9c5764b710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:11:52.854245 7f9c5764b710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:11:52.854261 7f9c5764b710 cephx: set_have_need_key no
handler for service auth
2012-02-03 17:11:52.854280 7f9c5764b710 cephx: validate_tickets want
37 have 0 need 37
2012-02-03 17:11:52.854294 7f9c5764b710 monclient(hunting): my global_id is 4107
2012-02-03 17:11:52.854311 7f9c5764b710 cephx client: handle_response ret = 0
2012-02-03 17:11:52.854523 7f9c5764b710 cephx client:  got initial
server challenge 9453701282273502885
2012-02-03 17:11:52.854554 7f9c5764b710 cephx client: build_request
2012-02-03 17:11:52.854567 7f9c5764b710 cephx client:
validate_tickets: want=37 need=37 have=0
2012-02-03 17:11:52.854580 7f9c5764b710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:11:52.854592 7f9c5764b710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:11:52.854603 7f9c5764b710 cephx: set_have_need_key no
handler for service auth
2012-02-03 17:11:52.854614 7f9c5764b710 cephx: validate_tickets want
37 have 0 need 37
2012-02-03 17:11:52.854626 7f9c5764b710 cephx client: want=37 need=37 have=0
2012-02-03 17:11:52.855052 7f9c5764b710 cephx client: get auth session
key: client_challenge 11458308468581777284
2012-02-03 17:11:52.855082 7f9c5764b710 monclient(hunting):
_send_mon_message to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:11:52.855104 7f9c5764b710 -- 10.68.119.191:0/1003868 -->
10.68.119.191:6789/0 -- auth(proto 2 32 bytes) v1 -- ?+0 0x76e000 con
0x771440
2012-02-03 17:11:52.856042 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 2 ==== auth_reply(proto 2 0 Success) v1
==== 206+0+0 (4278599348 0 0) 0x76e000 con 0x771440
2012-02-03 17:11:52.856072 7f9c5764b710 cephx client: handle_response ret = 0
2012-02-03 17:11:52.856083 7f9c5764b710 cephx client:  get_auth_session_key
2012-02-03 17:11:52.856096 7f9c5764b710 cephx:
verify_service_ticket_reply got 1 keys
2012-02-03 17:11:52.856106 7f9c5764b710 cephx: got key for service_id auth
2012-02-03 17:11:52.856333 7f9c5764b710 cephx:  ticket.secret_id=2
2012-02-03 17:11:52.856369 7f9c5764b710 cephx:
verify_service_ticket_reply service auth secret_id 2 session_key
AQDIlitPgOj/MhAASonUfgU6AS64ilA1CcYskQ== validity=43200.000000
2012-02-03 17:11:52.856394 7f9c5764b710 cephx: ticket
expires=2012-02-04 05:11:52.856384 renew_after=2012-02-04
02:11:52.856384
2012-02-03 17:11:52.856407 7f9c5764b710 cephx client:  want=37 need=37 have=0
2012-02-03 17:11:52.856418 7f9c5764b710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:11:52.856427 7f9c5764b710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:11:52.856437 7f9c5764b710 cephx: validate_tickets want
37 have 32 need 5
2012-02-03 17:11:52.856449 7f9c5764b710 cephx client: build_request
2012-02-03 17:11:52.856458 7f9c5764b710 cephx client:
validate_tickets: want=37 need=5 have=32
2012-02-03 17:11:52.856470 7f9c5764b710 cephx: set_have_need_key no
handler for service mon
2012-02-03 17:11:52.856480 7f9c5764b710 cephx: set_have_need_key no
handler for service osd
2012-02-03 17:11:52.856490 7f9c5764b710 cephx: validate_tickets want
37 have 32 need 5
2012-02-03 17:11:52.856499 7f9c5764b710 cephx client: want=37 need=5 have=32
2012-02-03 17:11:52.856509 7f9c5764b710 cephx client: get service
keys: want=37 need=5 have=32
2012-02-03 17:11:52.856618 7f9c5764b710 monclient(hunting):
_send_mon_message to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:11:52.856641 7f9c5764b710 -- 10.68.119.191:0/1003868 -->
10.68.119.191:6789/0 -- auth(proto 2 165 bytes) v1 -- ?+0 0x76e000 con
0x771440
2012-02-03 17:11:52.857320 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 3 ==== auth_reply(proto 2 0 Success) v1
==== 409+0+0 (1297679136 0 0) 0x76e280 con 0x771440
2012-02-03 17:11:52.857340 7f9c5764b710 cephx client: handle_response ret = 0
2012-02-03 17:11:52.857362 7f9c5764b710 cephx client:
get_principal_session_key session_key
AQDIlitPgOj/MhAASonUfgU6AS64ilA1CcYskQ==
2012-02-03 17:11:52.857374 7f9c5764b710 cephx:
verify_service_ticket_reply got 2 keys
2012-02-03 17:11:52.857384 7f9c5764b710 cephx: got key for service_id mon
2012-02-03 17:11:52.857420 7f9c5764b710 cephx:  ticket.secret_id=7
2012-02-03 17:11:52.857440 7f9c5764b710 cephx:
verify_service_ticket_reply service mon secret_id 7 session_key
AQDIlitPaPETMxAA7ySt6XbGvUPIIo5o4NhBqQ== validity=3600.000000
2012-02-03 17:11:52.857457 7f9c5764b710 cephx: ticket
expires=2012-02-03 18:11:52.857450 renew_after=2012-02-03
17:56:52.857450
2012-02-03 17:11:52.857468 7f9c5764b710 cephx: got key for service_id osd
2012-02-03 17:11:52.857553 7f9c5764b710 cephx:  ticket.secret_id=7
2012-02-03 17:11:52.862340 7f9c5764b710 cephx:
verify_service_ticket_reply service osd secret_id 7 session_key
AQDIlitPsGIUMxAARR3derMOFYPJX+SGVRmhPA== validity=3600.000000
2012-02-03 17:11:52.862386 7f9c5764b710 cephx: ticket
expires=2012-02-03 18:11:52.862378 renew_after=2012-02-03
17:56:52.862378
2012-02-03 17:11:52.862399 7f9c5764b710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:11:52.862410 7f9c5764b710 monclient(hunting): found mon.0
2012-02-03 17:11:52.862424 7f9c5764b710 monclient: _send_mon_message
to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:11:52.862469 7f9c5764b710 -- 10.68.119.191:0/1003868 -->
10.68.119.191:6789/0 -- mon_subscribe({monmap=0+}) v1 -- ?+0 0x76dd30
con 0x771440
2012-02-03 17:11:52.862805 7f9c5764b710 cephx: validate_tickets want
37 have 37 need 0
2012-02-03 17:11:52.862820 7f9c5764b710 cephx client: need_tickets:
want=37 need=0 have=37
2012-02-03 17:11:52.862829 7f9c5764b710 monclient:
_check_auth_rotating not needed by client.admin
2012-02-03 17:11:52.862850 7f9c59a59720 monclient: authenticate
success, global_id 4107
2012-02-03 17:11:52.863062 7f9c59a59720 client.4107.objecter
maybe_request_map subscribing (onetime) to next osd map
2012-02-03 17:11:52.863085 7f9c59a59720 monclient: renew_subs
2012-02-03 17:11:52.863097 7f9c59a59720 monclient: _send_mon_message
to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:11:52.863109 7f9c59a59720 -- 10.68.119.191:0/1003868 -->
10.68.119.191:6789/0 -- mon_subscribe({monmap=0+,osdmap=0}) v1 -- ?+0
0x76e280 con 0x771440
2012-02-03 17:11:52.863121 7f9c59a59720 monclient: renew_subs
2012-02-03 17:11:52.863131 7f9c59a59720 monclient: _send_mon_message
to mon.0 at 10.68.119.191:6789/0
2012-02-03 17:11:52.863142 7f9c59a59720 -- 10.68.119.191:0/1003868 -->
10.68.119.191:6789/0 -- mon_subscribe({monmap=0+,osdmap=0}) v1 -- ?+0
0x76ed70 con 0x771440
2012-02-03 17:11:52.865300 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 4 ==== mon_map v1 ==== 187+0+0 (1638929821
0 0) 0x76e280 con 0x771440
2012-02-03 17:11:52.865354 7f9c5764b710 monclient: handle_monmap mon_map v1
2012-02-03 17:11:52.865377 7f9c5764b710 monclient:  got monmap 1,
mon.0 is now rank 0
2012-02-03 17:11:52.865877 7f9c5764b710 monclient: dump:
epoch 1
fsid fe5407e1-f9b0-69f4-4dfe-52ae762929ab
last_changed 2012-02-03 10:19:58.428136
created 2012-02-03 10:19:58.428136
0: 10.68.119.191:6789/0 mon.0

2012-02-03 17:11:52.865922 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 5 ==== mon_subscribe_ack(300s) v1 ====
20+0+0 (3873334622 0 0) 0x770040 con 0x771440
2012-02-03 17:11:52.865944 7f9c5764b710 monclient:
handle_subscribe_ack sent 2012-02-03 17:11:52.851875 renew after
2012-02-03 17:14:22.851875
2012-02-03 17:11:52.865962 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 6 ==== mon_map v1 ==== 187+0+0 (1638929821
0 0) 0x770320 con 0x771440
2012-02-03 17:11:52.865972 7f9c5764b710 monclient: handle_monmap mon_map v1
2012-02-03 17:11:52.865984 7f9c5764b710 monclient:  got monmap 1,
mon.0 is now rank 0
2012-02-03 17:11:52.866001 7f9c5764b710 monclient: dump:
epoch 1
fsid fe5407e1-f9b0-69f4-4dfe-52ae762929ab
last_changed 2012-02-03 10:19:58.428136
created 2012-02-03 10:19:58.428136
0: 10.68.119.191:6789/0 mon.0

2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
handle_osd_map got epochs [21,21] > 0
2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
handle_osd_map decoding full epoch 21
2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
dump_active .. 0 homeless
data
metadata
rbd
2012-02-03 17:11:52.866605 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 8 ==== mon_subscribe_ack(300s) v1 ====
20+0+0 (3873334622 0 0) 0x770d80 con 0x771440
2012-02-03 17:11:52.866621 7f9c5764b710 monclient: discarding stray
monitor message mon_subscribe_ack(300s) v1
2012-02-03 17:11:52.866635 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 9 ==== mon_map v1 ==== 187+0+0 (1638929821
0 0) 0x76f050 con 0x771440
2012-02-03 17:11:52.866644 7f9c5764b710 monclient: discarding stray
monitor message mon_map v1
2012-02-03 17:11:52.866659 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
==== 1284+0+0 (473305567 0 0) 0x76f7a0 con 0x771440
2012-02-03 17:11:52.866668 7f9c5764b710 client.4107.objecter
handle_osd_map ignoring epochs [21,21] <= 21
2012-02-03 17:11:52.866676 7f9c5764b710 client.4107.objecter
dump_active .. 0 homeless
2012-02-03 17:11:52.866692 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 11 ==== mon_subscribe_ack(300s) v1 ====
20+0+0 (3873334622 0 0) 0x76fae0 con 0x771440
2012-02-03 17:11:52.866701 7f9c5764b710 monclient: discarding stray
monitor message mon_subscribe_ack(300s) v1
2012-02-03 17:11:52.867234 7f9c59a59720 -- 10.68.119.191:0/1003868
shutdown complete.

I compared those logs and found there is differences.
'rbd list'
2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500 <==
mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
handle_osd_map ignoring epochs [21,21] <= 21
2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
dump_active .. 0 homeless
2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
2.30a98c1c      osd.0   rbd_directory   [read 0~0]
--(snip)--

'rados lspools'
2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868 <==
mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
handle_osd_map got epochs [21,21] > 0
2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
handle_osd_map decoding full epoch 21
2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
dump_active .. 0 homeless
data
metadata
rbd
--(snip)--

What do these logs mean ?

>> *ceph cluster is configured on single server.
>> *server is ubuntu 10.10 maverick.
>> *ceph, librados2 and librbd1 packages are installed.
>>  (version: 0.38-1maverick)
>> *apparmor is disable.
>
>
> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.

I use libvirt 0.8.3 (latest version for maverick), so I disabled apparmor.



2012/2/2 Josh Durgin <josh.durgin@dreamhost.com>:
> On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
>>
>> Hi, all.
>>
>> When I execute "rbd" command, it is not success.
>>
>> root@ceph01:~# rbd list
>> (no response)
>>
>> /var/log/ceph/mon.0.log
>> -----
>> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
>> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
>> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>> 0x1619c00 con 0x1615a00
>> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
>> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
>> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>> 0x1619a00 con 0x1615a00
>> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
>> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
>> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>> 0x161fc00 con 0x1615a00
>> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
>> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
>> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
>> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
>> 0x163d780
>> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>> client.4112 10.68.119.191:0/1002580 5 ====
>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>> 0x1617a80 con 0x1615a00
>> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
>> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>> ?+0 0x1619600
>> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>> ?+0 0x163d900
>> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>> client.4112 10.68.119.191:0/1002580 6 ====
>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>> 0x16178c0 con 0x1615a00
>> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
>> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>> ?+0 0x1619400
>> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>> ?+0 0x161d300
>> -----
>
>
> No problems there.
>
>
>>
>> BTW, I could execute "rados lspools".
>>
>> root@ceph01:~# rados lspools
>> data
>> metadata
>> rbd
>
>
> This might mean the rbd image list object can't be read for some
> reason, or the rbd tool is doing something weird that the rados tool
> isn't. Can you share the output of 'ceph -s' and
> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
> --debug-auth 20'?
>
> You can run 'rados lspools' with those options as well and compare.
>
>
>> I would like to use rbd volume and attach it as virtual device for VM
>> guest on KVM.
>>
>> Could you advice to me ?
>>
>>
>> My environment is below.
>>
>> *ceph cluster is configured on single server.
>> *server is ubuntu 10.10 maverick.
>> *ceph, librados2 and librbd1 packages are installed.
>>  (version: 0.38-1maverick)
>> *apparmor is disable.
>
>
> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>
>
>> *root@ceph01:/# ls -l /etc/ceph
>> total 16
>> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
>> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
>> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
>> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
>> */var/lib/ceph/tmp is exists.
>> root@ceph01:/var/log# ls -l /var/lib/ceph/
>> total 4
>> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>>
>> */etc/ceph/ceph.conf
>> [global]
>>         auth supported = cephx
>>         keyring = /etc/ceph/$name.keyring
>> [mon]
>>         mon data = /data/data/mon$id
>>         debug ms = 1
>> [mon.0]
>>         host = ceph01
>>         mon addr = 10.68.119.191:6789
>> [mds]
>>
>> [mds.0]
>>         host = ceph01
>> [osd]
>>         osd data = /data/osd$id
>>         osd journal = /data/osd$id/journal
>>         osd journal size = 512
>>         osd class tmp = /var/lib/ceph/tmp
>> [osd.0]
>>         host = ceph01
>>         btrfs devs = /dev/sdb1
>>
>>
>> Waiting for your reply,
>>
>> Tomoya.
>
>
>
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-03  8:51   ` Masuko Tomoya
@ 2012-02-03 17:05     ` Josh Durgin
  2012-02-03 22:14       ` Masuko Tomoya
  0 siblings, 1 reply; 9+ messages in thread
From: Josh Durgin @ 2012-02-03 17:05 UTC (permalink / raw)
  To: Masuko Tomoya; +Cc: ceph-devel

On 02/03/2012 12:51 AM, Masuko Tomoya wrote:
> Hi Josh,
>
> Thank you for reply !
>
>> This might mean the rbd image list object can't be read for some
>> reason, or the rbd tool is doing something weird that the rados tool
>> isn't. Can you share the output of 'ceph -s' and
>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
>> --debug-auth 20'?
>
> The output of 'ceph -s' is below.
> -------
> root@ceph01:~# ceph -s
> 2012-02-03 17:01:47.881960    pg v33: 6 pgs: 6 active+clean+degraded;
> 0 KB data, 1056 KB used, 15357 MB / 15358 MB avail
> 2012-02-03 17:01:47.882583   mds e9: 1/1/1 up {0=0=up:creating}
> 2012-02-03 17:01:47.882733   osd e21: 1 osds: 1 up, 1 in
> 2012-02-03 17:01:47.883042   log 2012-02-03 16:35:11.183897 osd.0
> 10.68.119.191:6801/2912 12 : [WRN] map e19 wrongly marked me down or
> wrong addr
> 2012-02-03 17:01:47.883144   mon e1: 1 mons at {0=10.68.119.191:6789/0}
>
> The output of 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
> --debug-monc 20 --debug-auth 20' is below.
> ------
> root@ceph01:~# rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
> --debug-monc 20 --debug-auth 20

<snip>

> 2012-02-03 17:02:10.971391 7f88cbb91720 client.4106.objecter op_submit
> oid rbd_directory @2 [read 0~0] tid 1 osd.0
> 2012-02-03 17:02:10.971465 7f88cbb91720 client.4106.objecter send_op 1 to osd.0
> 2012-02-03 17:02:10.971533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
> 10.68.119.191:6801/2912 -- osd_op(client.4106.0:1 rbd_directory [read
> 0~0] 2.30a98c1c) v1 -- ?+0 0x24664c0 con 0x24661b0

Everything above here is normal - the rbd tool connected to the
monitors, got the monmap and osdmap, and sent a request to read the
'rbd_directory' object.

<snip>

> 2012-02-03 17:02:25.969338 7f88c7261710 client.4106.objecter  tid 1 on
> osd.0 is laggy

This means the osd isn't responding to the read. Check the osd log for
errors. If there's nothing obvious, add this to the osd section of your
ceph.conf and restart the osd:

     debug osd = 20
     debug ms = 1
     debug filestore = 20

Then run 'rbd ls' and look at what happens after
'osd_op.*rbd_directory' appears in the osd log.

<rados lspools log>

>
> I compared those logs and found there is differences.
> 'rbd list'
> 2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500<==
> mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
> ==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
> 2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
> handle_osd_map ignoring epochs [21,21]<= 21
> 2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
> dump_active .. 0 homeless
> 2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
> 2.30a98c1c      osd.0   rbd_directory   [read 0~0]
> --(snip)--
>
> 'rados lspools'
> 2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868<==
> mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
> ==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
> 2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
> handle_osd_map got epochs [21,21]>  0
> 2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
> handle_osd_map decoding full epoch 21
> 2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
> dump_active .. 0 homeless
> data
> metadata
> rbd
> --(snip)--
>
> What do these logs mean ?

The difference is that 'rbd ls' talks to the monitors and osds, while 
'rados lspools' just needs to talk to the monitors. The objecter 
dump_active part is listing in-flight osd requests.

>
>>> *ceph cluster is configured on single server.
>>> *server is ubuntu 10.10 maverick.
>>> *ceph, librados2 and librbd1 packages are installed.
>>>   (version: 0.38-1maverick)
>>> *apparmor is disable.
>>
>>
>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>
> I use libvirt 0.8.3 (latest version for maverick), so I disabled apparmor.
>
>
>
> 2012/2/2 Josh Durgin<josh.durgin@dreamhost.com>:
>> On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
>>>
>>> Hi, all.
>>>
>>> When I execute "rbd" command, it is not success.
>>>
>>> root@ceph01:~# rbd list
>>> (no response)
>>>
>>> /var/log/ceph/mon.0.log
>>> -----
>>> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
>>> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
>>> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>> 0x1619c00 con 0x1615a00
>>> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
>>> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
>>> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>> 0x1619a00 con 0x1615a00
>>> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
>>> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
>>> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>> 0x161fc00 con 0x1615a00
>>> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
>>> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
>>> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
>>> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
>>> 0x163d780
>>> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>> client.4112 10.68.119.191:0/1002580 5 ====
>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>> 0x1617a80 con 0x1615a00
>>> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
>>> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>> ?+0 0x1619600
>>> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>> ?+0 0x163d900
>>> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>> client.4112 10.68.119.191:0/1002580 6 ====
>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>> 0x16178c0 con 0x1615a00
>>> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
>>> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>> ?+0 0x1619400
>>> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>> ?+0 0x161d300
>>> -----
>>
>>
>> No problems there.
>>
>>
>>>
>>> BTW, I could execute "rados lspools".
>>>
>>> root@ceph01:~# rados lspools
>>> data
>>> metadata
>>> rbd
>>
>>
>> This might mean the rbd image list object can't be read for some
>> reason, or the rbd tool is doing something weird that the rados tool
>> isn't. Can you share the output of 'ceph -s' and
>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
>> --debug-auth 20'?
>>
>> You can run 'rados lspools' with those options as well and compare.
>>
>>
>>> I would like to use rbd volume and attach it as virtual device for VM
>>> guest on KVM.
>>>
>>> Could you advice to me ?
>>>
>>>
>>> My environment is below.
>>>
>>> *ceph cluster is configured on single server.
>>> *server is ubuntu 10.10 maverick.
>>> *ceph, librados2 and librbd1 packages are installed.
>>>   (version: 0.38-1maverick)
>>> *apparmor is disable.
>>
>>
>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>
>>
>>> *root@ceph01:/# ls -l /etc/ceph
>>> total 16
>>> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
>>> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
>>> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
>>> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
>>> */var/lib/ceph/tmp is exists.
>>> root@ceph01:/var/log# ls -l /var/lib/ceph/
>>> total 4
>>> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>>>
>>> */etc/ceph/ceph.conf
>>> [global]
>>>          auth supported = cephx
>>>          keyring = /etc/ceph/$name.keyring
>>> [mon]
>>>          mon data = /data/data/mon$id
>>>          debug ms = 1
>>> [mon.0]
>>>          host = ceph01
>>>          mon addr = 10.68.119.191:6789
>>> [mds]
>>>
>>> [mds.0]
>>>          host = ceph01
>>> [osd]
>>>          osd data = /data/osd$id
>>>          osd journal = /data/osd$id/journal
>>>          osd journal size = 512
>>>          osd class tmp = /var/lib/ceph/tmp
>>> [osd.0]
>>>          host = ceph01
>>>          btrfs devs = /dev/sdb1
>>>
>>>
>>> Waiting for your reply,
>>>
>>> Tomoya.
>>
>>
>>


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-03 17:05     ` Josh Durgin
@ 2012-02-03 22:14       ` Masuko Tomoya
  2012-02-03 22:36         ` Josh Durgin
  0 siblings, 1 reply; 9+ messages in thread
From: Masuko Tomoya @ 2012-02-03 22:14 UTC (permalink / raw)
  To: josh.durgin; +Cc: ceph-devel

Hi Josh,

Thank you for your comments.

>    debug osd = 20
>    debug ms = 1
>    debug filestore = 20

I added this to the osd section of ceph.conf and ran /etc/init.d/ceph
stop&start.

The output of OSD.log when 'rbd list' was executed is below.

-----
2012-02-04 04:29:22.457990 7fe0e08fb710 osd.0 32
OSD::ms_verify_authorizer name=client.admin auid=0
2012-02-04 04:29:22.458041 7fe0e08fb710 osd.0 32  new session
0x24f5240 con=0x24d4dc0 addr=10.68.119.191:0/1005110
2012-02-04 04:29:22.458069 7fe0e08fb710 osd.0 32  session 0x24f5240
has caps osdcaps(pools={} default allow= default_deny=)
2012-02-04 04:29:22.458415 7fe0e6c0a710 -- 10.68.119.191:6801/4992 <==
client.4201 10.68.119.191:0/1005110 1 ==== osd_op(client.4201.0:1
rbd_directory [read 0~0] 2.30a98c1c) v3 ==== 143+0+0 (3720164172 0 0)
0x24d8900 con 0x24d4dc0
2012-02-04 04:29:22.458442 7fe0e6c0a710 osd.0 32 _dispatch 0x24d8900
osd_op(client.4201.0:1 rbd_directory [read 0~0] 2.30a98c1c) v3
2012-02-04 04:29:22.458463 7fe0e6c0a710 osd.0 32
require_same_or_newer_map 32 (i am 32) 0x24d8900
2012-02-04 04:29:22.458487 7fe0e6c0a710 osd.0 32 _share_map_incoming
client.4201 10.68.119.191:0/1005110 32
2012-02-04 04:29:22.458507 7fe0e6c0a710 osd.0 32 hit non-existent pg
2.0, waiting
2012-02-04 04:29:22.641501 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:22.641695 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = no, randomly backing off
2012-02-04 04:29:22.718517 7fe0e12fe710 osd.0 32 update_osd_stat
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:22.718606 7fe0e12fe710 osd.0 32 heartbeat:
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:23.642595 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:23.642783 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = no, randomly backing off
2012-02-04 04:29:23.719789 7fe0e12fe710 osd.0 32 update_osd_stat
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:23.719861 7fe0e12fe710 osd.0 32 heartbeat:
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:24.620713 7fe0e12fe710 osd.0 32 update_osd_stat
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:24.620789 7fe0e12fe710 osd.0 32 heartbeat:
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:24.643651 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:24.643830 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = yes
2012-02-04 04:29:24.643845 7fe0edc18710 osd.0 32 sched_scrub
2012-02-04 04:29:24.643867 7fe0edc18710 osd.0 32  0.0p0 at 2012-02-03
10:25:51.380648 > 2012-02-03 04:29:24.643851 (86400 seconds ago)
2012-02-04 04:29:24.643875 7fe0edc18710 osd.0 32 sched_scrub done
2012-02-04 04:29:24.709018 7fe0e6c0a710 -- 10.68.119.191:6801/4992 <==
mds.0 10.68.119.191:6800/4916 444 ==== ping v1 ==== 0+0+0 (0 0 0)
0x251b600 con 0x2500640
2012-02-04 04:29:24.709091 7fe0e6c0a710 osd.0 32 _dispatch 0x251b600 ping v1
2012-02-04 04:29:24.709102 7fe0e6c0a710 osd.0 32 ping from mds.0
2012-02-04 04:29:25.321771 7fe0e12fe710 osd.0 32 update_osd_stat
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:25.321849 7fe0e12fe710 osd.0 32 heartbeat:
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:25.644596 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:25.644812 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = no, randomly backing off
2012-02-04 04:29:25.644832 7fe0edc18710 osd.0 32 do_mon_report
2012-02-04 04:29:25.644843 7fe0edc18710 osd.0 32 send_alive up_thru
currently 29 want 29
2012-02-04 04:29:25.644853 7fe0edc18710 osd.0 32 send_pg_stats
2012-02-04 04:29:25.965641 7fe0ea411710 filestore(/data/osd0)
sync_entry woke after 5.000199
2012-02-04 04:29:25.965748 7fe0ea411710 filestore(/data/osd0)
sync_entry waiting for max_interval 5.000000
2012-02-04 04:29:26.522826 7fe0e12fe710 osd.0 32 update_osd_stat
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:26.522899 7fe0e12fe710 osd.0 32 heartbeat:
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:26.645739 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:26.645943 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = no, randomly backing off
2012-02-04 04:29:27.646788 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:27.646982 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = yes
2012-02-04 04:29:27.646997 7fe0edc18710 osd.0 32 sched_scrub
2012-02-04 04:29:27.647018 7fe0edc18710 osd.0 32  0.0p0 at 2012-02-03
10:25:51.380648 > 2012-02-03 04:29:27.647003 (86400 seconds ago)
2012-02-04 04:29:27.647027 7fe0edc18710 osd.0 32 sched_scrub done
2012-02-04 04:29:27.723893 7fe0e12fe710 osd.0 32 update_osd_stat
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:27.723978 7fe0e12fe710 osd.0 32 heartbeat:
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:28.424886 7fe0e12fe710 osd.0 32 update_osd_stat
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:28.424957 7fe0e12fe710 osd.0 32 heartbeat:
osd_stat(1400 KB used, 15357 MB avail, 15358 MB total, peers []/[])
2012-02-04 04:29:28.647769 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:28.647971 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = no, randomly backing off
2012-02-04 04:29:29.648746 7fe0edc18710 osd.0 32 tick
2012-02-04 04:29:29.648955 7fe0edc18710 osd.0 32 scrub_should_schedule
loadavg 0 < max 0.5 = no, randomly backing off


2012/2/3 Josh Durgin <josh.durgin@dreamhost.com>:
> On 02/03/2012 12:51 AM, Masuko Tomoya wrote:
>>
>> Hi Josh,
>>
>> Thank you for reply !
>>
>>> This might mean the rbd image list object can't be read for some
>>> reason, or the rbd tool is doing something weird that the rados tool
>>> isn't. Can you share the output of 'ceph -s' and
>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
>>> --debug-auth 20'?
>>
>>
>> The output of 'ceph -s' is below.
>> -------
>> root@ceph01:~# ceph -s
>> 2012-02-03 17:01:47.881960    pg v33: 6 pgs: 6 active+clean+degraded;
>> 0 KB data, 1056 KB used, 15357 MB / 15358 MB avail
>> 2012-02-03 17:01:47.882583   mds e9: 1/1/1 up {0=0=up:creating}
>> 2012-02-03 17:01:47.882733   osd e21: 1 osds: 1 up, 1 in
>> 2012-02-03 17:01:47.883042   log 2012-02-03 16:35:11.183897 osd.0
>> 10.68.119.191:6801/2912 12 : [WRN] map e19 wrongly marked me down or
>> wrong addr
>> 2012-02-03 17:01:47.883144   mon e1: 1 mons at {0=10.68.119.191:6789/0}
>>
>> The output of 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>> --debug-monc 20 --debug-auth 20' is below.
>> ------
>> root@ceph01:~# rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>> --debug-monc 20 --debug-auth 20
>
>
> <snip>
>
>
>> 2012-02-03 17:02:10.971391 7f88cbb91720 client.4106.objecter op_submit
>> oid rbd_directory @2 [read 0~0] tid 1 osd.0
>> 2012-02-03 17:02:10.971465 7f88cbb91720 client.4106.objecter send_op 1 to
>> osd.0
>> 2012-02-03 17:02:10.971533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
>> 10.68.119.191:6801/2912 -- osd_op(client.4106.0:1 rbd_directory [read
>> 0~0] 2.30a98c1c) v1 -- ?+0 0x24664c0 con 0x24661b0
>
>
> Everything above here is normal - the rbd tool connected to the
> monitors, got the monmap and osdmap, and sent a request to read the
> 'rbd_directory' object.
>
> <snip>
>
>
>> 2012-02-03 17:02:25.969338 7f88c7261710 client.4106.objecter  tid 1 on
>> osd.0 is laggy
>
>
> This means the osd isn't responding to the read. Check the osd log for
> errors. If there's nothing obvious, add this to the osd section of your
> ceph.conf and restart the osd:
>
>    debug osd = 20
>    debug ms = 1
>    debug filestore = 20
>
> Then run 'rbd ls' and look at what happens after
> 'osd_op.*rbd_directory' appears in the osd log.
>
> <rados lspools log>
>
>
>>
>> I compared those logs and found there is differences.
>> 'rbd list'
>> 2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500<==
>> mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
>> ==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
>> 2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
>> handle_osd_map ignoring epochs [21,21]<= 21
>> 2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
>> dump_active .. 0 homeless
>> 2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
>> 2.30a98c1c      osd.0   rbd_directory   [read 0~0]
>> --(snip)--
>>
>> 'rados lspools'
>> 2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868<==
>> mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
>> ==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
>> 2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
>> handle_osd_map got epochs [21,21]>  0
>> 2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
>> handle_osd_map decoding full epoch 21
>> 2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
>> dump_active .. 0 homeless
>> data
>> metadata
>> rbd
>> --(snip)--
>>
>> What do these logs mean ?
>
>
> The difference is that 'rbd ls' talks to the monitors and osds, while 'rados
> lspools' just needs to talk to the monitors. The objecter dump_active part
> is listing in-flight osd requests.
>
>
>>
>>>> *ceph cluster is configured on single server.
>>>> *server is ubuntu 10.10 maverick.
>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>  (version: 0.38-1maverick)
>>>> *apparmor is disable.
>>>
>>>
>>>
>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>
>>
>> I use libvirt 0.8.3 (latest version for maverick), so I disabled apparmor.
>>
>>
>>
>> 2012/2/2 Josh Durgin<josh.durgin@dreamhost.com>:
>>>
>>> On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
>>>>
>>>>
>>>> Hi, all.
>>>>
>>>> When I execute "rbd" command, it is not success.
>>>>
>>>> root@ceph01:~# rbd list
>>>> (no response)
>>>>
>>>> /var/log/ceph/mon.0.log
>>>> -----
>>>> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
>>>> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
>>>> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>> 0x1619c00 con 0x1615a00
>>>> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
>>>> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
>>>> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>> 0x1619a00 con 0x1615a00
>>>> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
>>>> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
>>>> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>> 0x161fc00 con 0x1615a00
>>>> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
>>>> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
>>>> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
>>>> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
>>>> 0x163d780
>>>> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>> client.4112 10.68.119.191:0/1002580 5 ====
>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>> 0x1617a80 con 0x1615a00
>>>> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
>>>> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>> ?+0 0x1619600
>>>> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>> ?+0 0x163d900
>>>> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>> client.4112 10.68.119.191:0/1002580 6 ====
>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>> 0x16178c0 con 0x1615a00
>>>> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
>>>> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>> ?+0 0x1619400
>>>> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>> ?+0 0x161d300
>>>> -----
>>>
>>>
>>>
>>> No problems there.
>>>
>>>
>>>>
>>>> BTW, I could execute "rados lspools".
>>>>
>>>> root@ceph01:~# rados lspools
>>>> data
>>>> metadata
>>>> rbd
>>>
>>>
>>>
>>> This might mean the rbd image list object can't be read for some
>>> reason, or the rbd tool is doing something weird that the rados tool
>>> isn't. Can you share the output of 'ceph -s' and
>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
>>> --debug-auth 20'?
>>>
>>> You can run 'rados lspools' with those options as well and compare.
>>>
>>>
>>>> I would like to use rbd volume and attach it as virtual device for VM
>>>> guest on KVM.
>>>>
>>>> Could you advice to me ?
>>>>
>>>>
>>>> My environment is below.
>>>>
>>>> *ceph cluster is configured on single server.
>>>> *server is ubuntu 10.10 maverick.
>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>  (version: 0.38-1maverick)
>>>> *apparmor is disable.
>>>
>>>
>>>
>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>
>>>
>>>> *root@ceph01:/# ls -l /etc/ceph
>>>> total 16
>>>> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
>>>> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
>>>> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
>>>> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
>>>> */var/lib/ceph/tmp is exists.
>>>> root@ceph01:/var/log# ls -l /var/lib/ceph/
>>>> total 4
>>>> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>>>>
>>>> */etc/ceph/ceph.conf
>>>> [global]
>>>>         auth supported = cephx
>>>>         keyring = /etc/ceph/$name.keyring
>>>> [mon]
>>>>         mon data = /data/data/mon$id
>>>>         debug ms = 1
>>>> [mon.0]
>>>>         host = ceph01
>>>>         mon addr = 10.68.119.191:6789
>>>> [mds]
>>>>
>>>> [mds.0]
>>>>         host = ceph01
>>>> [osd]
>>>>         osd data = /data/osd$id
>>>>         osd journal = /data/osd$id/journal
>>>>         osd journal size = 512
>>>>         osd class tmp = /var/lib/ceph/tmp
>>>> [osd.0]
>>>>         host = ceph01
>>>>         btrfs devs = /dev/sdb1
>>>>
>>>>
>>>> Waiting for your reply,
>>>>
>>>> Tomoya.
>>>
>>>
>>>
>>>
>
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-03 22:14       ` Masuko Tomoya
@ 2012-02-03 22:36         ` Josh Durgin
  2012-02-03 22:54           ` Masuko Tomoya
  0 siblings, 1 reply; 9+ messages in thread
From: Josh Durgin @ 2012-02-03 22:36 UTC (permalink / raw)
  To: Masuko Tomoya; +Cc: ceph-devel

On 02/03/2012 02:14 PM, Masuko Tomoya wrote:
> Hi Josh,
>
> Thank you for your comments.
>
>>     debug osd = 20
>>     debug ms = 1
>>     debug filestore = 20
>
> I added this to the osd section of ceph.conf and ran /etc/init.d/ceph
> stop&start.
>
> The output of OSD.log when 'rbd list' was executed is below.
>
> -----
> 2012-02-04 04:29:22.457990 7fe0e08fb710 osd.0 32
> OSD::ms_verify_authorizer name=client.admin auid=0
> 2012-02-04 04:29:22.458041 7fe0e08fb710 osd.0 32  new session
> 0x24f5240 con=0x24d4dc0 addr=10.68.119.191:0/1005110
> 2012-02-04 04:29:22.458069 7fe0e08fb710 osd.0 32  session 0x24f5240
> has caps osdcaps(pools={} default allow= default_deny=)
> 2012-02-04 04:29:22.458415 7fe0e6c0a710 -- 10.68.119.191:6801/4992<==
> client.4201 10.68.119.191:0/1005110 1 ==== osd_op(client.4201.0:1
> rbd_directory [read 0~0] 2.30a98c1c) v3 ==== 143+0+0 (3720164172 0 0)
> 0x24d8900 con 0x24d4dc0
> 2012-02-04 04:29:22.458442 7fe0e6c0a710 osd.0 32 _dispatch 0x24d8900
> osd_op(client.4201.0:1 rbd_directory [read 0~0] 2.30a98c1c) v3
> 2012-02-04 04:29:22.458463 7fe0e6c0a710 osd.0 32
> require_same_or_newer_map 32 (i am 32) 0x24d8900
> 2012-02-04 04:29:22.458487 7fe0e6c0a710 osd.0 32 _share_map_incoming
> client.4201 10.68.119.191:0/1005110 32
> 2012-02-04 04:29:22.458507 7fe0e6c0a710 osd.0 32 hit non-existent pg
> 2.0, waiting

The pg should have been created already. What's the output of 'ceph pg 
dump'?

>
>
> 2012/2/3 Josh Durgin<josh.durgin@dreamhost.com>:
>> On 02/03/2012 12:51 AM, Masuko Tomoya wrote:
>>>
>>> Hi Josh,
>>>
>>> Thank you for reply !
>>>
>>>> This might mean the rbd image list object can't be read for some
>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>> isn't. Can you share the output of 'ceph -s' and
>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
>>>> --debug-auth 20'?
>>>
>>>
>>> The output of 'ceph -s' is below.
>>> -------
>>> root@ceph01:~# ceph -s
>>> 2012-02-03 17:01:47.881960    pg v33: 6 pgs: 6 active+clean+degraded;
>>> 0 KB data, 1056 KB used, 15357 MB / 15358 MB avail
>>> 2012-02-03 17:01:47.882583   mds e9: 1/1/1 up {0=0=up:creating}
>>> 2012-02-03 17:01:47.882733   osd e21: 1 osds: 1 up, 1 in
>>> 2012-02-03 17:01:47.883042   log 2012-02-03 16:35:11.183897 osd.0
>>> 10.68.119.191:6801/2912 12 : [WRN] map e19 wrongly marked me down or
>>> wrong addr
>>> 2012-02-03 17:01:47.883144   mon e1: 1 mons at {0=10.68.119.191:6789/0}
>>>
>>> The output of 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>> --debug-monc 20 --debug-auth 20' is below.
>>> ------
>>> root@ceph01:~# rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>> --debug-monc 20 --debug-auth 20
>>
>>
>> <snip>
>>
>>
>>> 2012-02-03 17:02:10.971391 7f88cbb91720 client.4106.objecter op_submit
>>> oid rbd_directory @2 [read 0~0] tid 1 osd.0
>>> 2012-02-03 17:02:10.971465 7f88cbb91720 client.4106.objecter send_op 1 to
>>> osd.0
>>> 2012-02-03 17:02:10.971533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
>>> 10.68.119.191:6801/2912 -- osd_op(client.4106.0:1 rbd_directory [read
>>> 0~0] 2.30a98c1c) v1 -- ?+0 0x24664c0 con 0x24661b0
>>
>>
>> Everything above here is normal - the rbd tool connected to the
>> monitors, got the monmap and osdmap, and sent a request to read the
>> 'rbd_directory' object.
>>
>> <snip>
>>
>>
>>> 2012-02-03 17:02:25.969338 7f88c7261710 client.4106.objecter  tid 1 on
>>> osd.0 is laggy
>>
>>
>> This means the osd isn't responding to the read. Check the osd log for
>> errors. If there's nothing obvious, add this to the osd section of your
>> ceph.conf and restart the osd:
>>
>>     debug osd = 20
>>     debug ms = 1
>>     debug filestore = 20
>>
>> Then run 'rbd ls' and look at what happens after
>> 'osd_op.*rbd_directory' appears in the osd log.
>>
>> <rados lspools log>
>>
>>
>>>
>>> I compared those logs and found there is differences.
>>> 'rbd list'
>>> 2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500<==
>>> mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
>>> ==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
>>> 2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
>>> handle_osd_map ignoring epochs [21,21]<= 21
>>> 2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
>>> dump_active .. 0 homeless
>>> 2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
>>> 2.30a98c1c      osd.0   rbd_directory   [read 0~0]
>>> --(snip)--
>>>
>>> 'rados lspools'
>>> 2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868<==
>>> mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
>>> ==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
>>> 2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
>>> handle_osd_map got epochs [21,21]>    0
>>> 2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
>>> handle_osd_map decoding full epoch 21
>>> 2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
>>> dump_active .. 0 homeless
>>> data
>>> metadata
>>> rbd
>>> --(snip)--
>>>
>>> What do these logs mean ?
>>
>>
>> The difference is that 'rbd ls' talks to the monitors and osds, while 'rados
>> lspools' just needs to talk to the monitors. The objecter dump_active part
>> is listing in-flight osd requests.
>>
>>
>>>
>>>>> *ceph cluster is configured on single server.
>>>>> *server is ubuntu 10.10 maverick.
>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>   (version: 0.38-1maverick)
>>>>> *apparmor is disable.
>>>>
>>>>
>>>>
>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>
>>>
>>> I use libvirt 0.8.3 (latest version for maverick), so I disabled apparmor.
>>>
>>>
>>>
>>> 2012/2/2 Josh Durgin<josh.durgin@dreamhost.com>:
>>>>
>>>> On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
>>>>>
>>>>>
>>>>> Hi, all.
>>>>>
>>>>> When I execute "rbd" command, it is not success.
>>>>>
>>>>> root@ceph01:~# rbd list
>>>>> (no response)
>>>>>
>>>>> /var/log/ceph/mon.0.log
>>>>> -----
>>>>> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
>>>>> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
>>>>> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>> 0x1619c00 con 0x1615a00
>>>>> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
>>>>> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
>>>>> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>> 0x1619a00 con 0x1615a00
>>>>> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
>>>>> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
>>>>> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>> 0x161fc00 con 0x1615a00
>>>>> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
>>>>> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
>>>>> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
>>>>> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
>>>>> 0x163d780
>>>>> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>> client.4112 10.68.119.191:0/1002580 5 ====
>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>> 0x1617a80 con 0x1615a00
>>>>> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
>>>>> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>> ?+0 0x1619600
>>>>> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>> ?+0 0x163d900
>>>>> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>> client.4112 10.68.119.191:0/1002580 6 ====
>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>> 0x16178c0 con 0x1615a00
>>>>> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
>>>>> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>> ?+0 0x1619400
>>>>> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>> ?+0 0x161d300
>>>>> -----
>>>>
>>>>
>>>>
>>>> No problems there.
>>>>
>>>>
>>>>>
>>>>> BTW, I could execute "rados lspools".
>>>>>
>>>>> root@ceph01:~# rados lspools
>>>>> data
>>>>> metadata
>>>>> rbd
>>>>
>>>>
>>>>
>>>> This might mean the rbd image list object can't be read for some
>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>> isn't. Can you share the output of 'ceph -s' and
>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20
>>>> --debug-auth 20'?
>>>>
>>>> You can run 'rados lspools' with those options as well and compare.
>>>>
>>>>
>>>>> I would like to use rbd volume and attach it as virtual device for VM
>>>>> guest on KVM.
>>>>>
>>>>> Could you advice to me ?
>>>>>
>>>>>
>>>>> My environment is below.
>>>>>
>>>>> *ceph cluster is configured on single server.
>>>>> *server is ubuntu 10.10 maverick.
>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>   (version: 0.38-1maverick)
>>>>> *apparmor is disable.
>>>>
>>>>
>>>>
>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>>
>>>>
>>>>> *root@ceph01:/# ls -l /etc/ceph
>>>>> total 16
>>>>> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
>>>>> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
>>>>> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
>>>>> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
>>>>> */var/lib/ceph/tmp is exists.
>>>>> root@ceph01:/var/log# ls -l /var/lib/ceph/
>>>>> total 4
>>>>> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>>>>>
>>>>> */etc/ceph/ceph.conf
>>>>> [global]
>>>>>          auth supported = cephx
>>>>>          keyring = /etc/ceph/$name.keyring
>>>>> [mon]
>>>>>          mon data = /data/data/mon$id
>>>>>          debug ms = 1
>>>>> [mon.0]
>>>>>          host = ceph01
>>>>>          mon addr = 10.68.119.191:6789
>>>>> [mds]
>>>>>
>>>>> [mds.0]
>>>>>          host = ceph01
>>>>> [osd]
>>>>>          osd data = /data/osd$id
>>>>>          osd journal = /data/osd$id/journal
>>>>>          osd journal size = 512
>>>>>          osd class tmp = /var/lib/ceph/tmp
>>>>> [osd.0]
>>>>>          host = ceph01
>>>>>          btrfs devs = /dev/sdb1
>>>>>
>>>>>
>>>>> Waiting for your reply,
>>>>>
>>>>> Tomoya.
>>>>
>>>>
>>>>
>>>>
>>


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-03 22:36         ` Josh Durgin
@ 2012-02-03 22:54           ` Masuko Tomoya
  2012-02-03 23:01             ` Josh Durgin
  0 siblings, 1 reply; 9+ messages in thread
From: Masuko Tomoya @ 2012-02-03 22:54 UTC (permalink / raw)
  To: Josh Durgin; +Cc: ceph-devel

Hi,

The output of 'ceph pg dump' is below.

root@ceph01:~# ceph pg dump
2012-02-04 07:50:15.453151 mon <- [pg,dump]
2012-02-04 07:50:15.453734 mon.0 -> 'dumped all in format plain' (0)
version 63
last_osdmap_epoch 37
last_pg_scan 1
full_ratio 0.95
nearfull_ratio 0.85
pg_stat objects mip     degr    unf     kb      bytes   log
disklog state   v       reported        up      acting  last_scrub
1.1p0   0       0       0       0       0       0       0       0
 active+clean+degraded   0'0     34'30   [0]     [0] 0'0
2012-02-03 10:25:55.383343
0.0p0   0       0       0       0       0       0       0       0
 active+clean+degraded   0'0     34'32   [0]     [0] 0'0
2012-02-03 10:25:51.380648
1.0p0   0       0       0       0       0       0       0       0
 active+clean+degraded   0'0     34'30   [0]     [0] 0'0
2012-02-03 10:25:53.381291
0.1p0   0       0       0       0       0       0       0       0
 active+clean+degraded   0'0     34'32   [0]     [0] 0'0
2012-02-03 10:25:52.380881
2.0p0   0       0       0       0       0       0       0       0
 active+clean+degraded   0'0     34'30   [0]     [0] 0'0
2012-02-03 10:25:59.387441
2.1p0   0       0       0       0       0       0       0       0
 active+clean+degraded   0'0     34'30   [0]     [0] 0'0
2012-02-03 10:26:04.392778
pool 0  0       0       0       0       0       0       0       0
pool 1  0       0       0       0       0       0       0       0
pool 2  0       0       0       0       0       0       0       0
 sum    0       0       0       0       0       0       0       0
osdstat kbused  kbavail kb      hb in   hb out
0       1568    15726032        15727600        []      []
 sum    1568    15726032        15727600


2012/2/3 Josh Durgin <josh.durgin@dreamhost.com>:
> On 02/03/2012 02:14 PM, Masuko Tomoya wrote:
>>
>> Hi Josh,
>>
>> Thank you for your comments.
>>
>>>    debug osd = 20
>>>    debug ms = 1
>>>    debug filestore = 20
>>
>>
>> I added this to the osd section of ceph.conf and ran /etc/init.d/ceph
>> stop&start.
>>
>> The output of OSD.log when 'rbd list' was executed is below.
>>
>> -----
>> 2012-02-04 04:29:22.457990 7fe0e08fb710 osd.0 32
>> OSD::ms_verify_authorizer name=client.admin auid=0
>> 2012-02-04 04:29:22.458041 7fe0e08fb710 osd.0 32  new session
>> 0x24f5240 con=0x24d4dc0 addr=10.68.119.191:0/1005110
>> 2012-02-04 04:29:22.458069 7fe0e08fb710 osd.0 32  session 0x24f5240
>> has caps osdcaps(pools={} default allow= default_deny=)
>> 2012-02-04 04:29:22.458415 7fe0e6c0a710 -- 10.68.119.191:6801/4992<==
>> client.4201 10.68.119.191:0/1005110 1 ==== osd_op(client.4201.0:1
>> rbd_directory [read 0~0] 2.30a98c1c) v3 ==== 143+0+0 (3720164172 0 0)
>> 0x24d8900 con 0x24d4dc0
>> 2012-02-04 04:29:22.458442 7fe0e6c0a710 osd.0 32 _dispatch 0x24d8900
>> osd_op(client.4201.0:1 rbd_directory [read 0~0] 2.30a98c1c) v3
>> 2012-02-04 04:29:22.458463 7fe0e6c0a710 osd.0 32
>> require_same_or_newer_map 32 (i am 32) 0x24d8900
>> 2012-02-04 04:29:22.458487 7fe0e6c0a710 osd.0 32 _share_map_incoming
>> client.4201 10.68.119.191:0/1005110 32
>> 2012-02-04 04:29:22.458507 7fe0e6c0a710 osd.0 32 hit non-existent pg
>> 2.0, waiting
>
>
> The pg should have been created already. What's the output of 'ceph pg
> dump'?
>
>
>>
>>
>> 2012/2/3 Josh Durgin<josh.durgin@dreamhost.com>:
>>>
>>> On 02/03/2012 12:51 AM, Masuko Tomoya wrote:
>>>>
>>>>
>>>> Hi Josh,
>>>>
>>>> Thank you for reply !
>>>>
>>>>> This might mean the rbd image list object can't be read for some
>>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>>> isn't. Can you share the output of 'ceph -s' and
>>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc
>>>>> 20
>>>>> --debug-auth 20'?
>>>>
>>>>
>>>>
>>>> The output of 'ceph -s' is below.
>>>> -------
>>>> root@ceph01:~# ceph -s
>>>> 2012-02-03 17:01:47.881960    pg v33: 6 pgs: 6 active+clean+degraded;
>>>> 0 KB data, 1056 KB used, 15357 MB / 15358 MB avail
>>>> 2012-02-03 17:01:47.882583   mds e9: 1/1/1 up {0=0=up:creating}
>>>> 2012-02-03 17:01:47.882733   osd e21: 1 osds: 1 up, 1 in
>>>> 2012-02-03 17:01:47.883042   log 2012-02-03 16:35:11.183897 osd.0
>>>> 10.68.119.191:6801/2912 12 : [WRN] map e19 wrongly marked me down or
>>>> wrong addr
>>>> 2012-02-03 17:01:47.883144   mon e1: 1 mons at {0=10.68.119.191:6789/0}
>>>>
>>>> The output of 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>>> --debug-monc 20 --debug-auth 20' is below.
>>>> ------
>>>> root@ceph01:~# rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>>> --debug-monc 20 --debug-auth 20
>>>
>>>
>>>
>>> <snip>
>>>
>>>
>>>> 2012-02-03 17:02:10.971391 7f88cbb91720 client.4106.objecter op_submit
>>>> oid rbd_directory @2 [read 0~0] tid 1 osd.0
>>>> 2012-02-03 17:02:10.971465 7f88cbb91720 client.4106.objecter send_op 1
>>>> to
>>>> osd.0
>>>> 2012-02-03 17:02:10.971533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
>>>> 10.68.119.191:6801/2912 -- osd_op(client.4106.0:1 rbd_directory [read
>>>> 0~0] 2.30a98c1c) v1 -- ?+0 0x24664c0 con 0x24661b0
>>>
>>>
>>>
>>> Everything above here is normal - the rbd tool connected to the
>>> monitors, got the monmap and osdmap, and sent a request to read the
>>> 'rbd_directory' object.
>>>
>>> <snip>
>>>
>>>
>>>> 2012-02-03 17:02:25.969338 7f88c7261710 client.4106.objecter  tid 1 on
>>>> osd.0 is laggy
>>>
>>>
>>>
>>> This means the osd isn't responding to the read. Check the osd log for
>>> errors. If there's nothing obvious, add this to the osd section of your
>>> ceph.conf and restart the osd:
>>>
>>>    debug osd = 20
>>>    debug ms = 1
>>>    debug filestore = 20
>>>
>>> Then run 'rbd ls' and look at what happens after
>>> 'osd_op.*rbd_directory' appears in the osd log.
>>>
>>> <rados lspools log>
>>>
>>>
>>>>
>>>> I compared those logs and found there is differences.
>>>> 'rbd list'
>>>> 2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500<==
>>>> mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
>>>> ==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
>>>> 2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
>>>> handle_osd_map ignoring epochs [21,21]<= 21
>>>> 2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
>>>> dump_active .. 0 homeless
>>>> 2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
>>>> 2.30a98c1c      osd.0   rbd_directory   [read 0~0]
>>>> --(snip)--
>>>>
>>>> 'rados lspools'
>>>> 2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868<==
>>>> mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
>>>> ==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
>>>> 2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
>>>> handle_osd_map got epochs [21,21]>    0
>>>> 2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
>>>> handle_osd_map decoding full epoch 21
>>>> 2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
>>>> dump_active .. 0 homeless
>>>> data
>>>> metadata
>>>> rbd
>>>> --(snip)--
>>>>
>>>> What do these logs mean ?
>>>
>>>
>>>
>>> The difference is that 'rbd ls' talks to the monitors and osds, while
>>> 'rados
>>> lspools' just needs to talk to the monitors. The objecter dump_active
>>> part
>>> is listing in-flight osd requests.
>>>
>>>
>>>>
>>>>>> *ceph cluster is configured on single server.
>>>>>> *server is ubuntu 10.10 maverick.
>>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>>  (version: 0.38-1maverick)
>>>>>> *apparmor is disable.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>>
>>>>
>>>>
>>>> I use libvirt 0.8.3 (latest version for maverick), so I disabled
>>>> apparmor.
>>>>
>>>>
>>>>
>>>> 2012/2/2 Josh Durgin<josh.durgin@dreamhost.com>:
>>>>>
>>>>>
>>>>> On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
>>>>>>
>>>>>>
>>>>>>
>>>>>> Hi, all.
>>>>>>
>>>>>> When I execute "rbd" command, it is not success.
>>>>>>
>>>>>> root@ceph01:~# rbd list
>>>>>> (no response)
>>>>>>
>>>>>> /var/log/ceph/mon.0.log
>>>>>> -----
>>>>>> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
>>>>>> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>> 0x1619c00 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
>>>>>> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>> 0x1619a00 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
>>>>>> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>> 0x161fc00 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
>>>>>> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
>>>>>> 0x163d780
>>>>>> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>> client.4112 10.68.119.191:0/1002580 5 ====
>>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>>> 0x1617a80 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>>> ?+0 0x1619600
>>>>>> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>>> ?+0 0x163d900
>>>>>> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>> client.4112 10.68.119.191:0/1002580 6 ====
>>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>>> 0x16178c0 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
>>>>>> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>>> ?+0 0x1619400
>>>>>> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>>> ?+0 0x161d300
>>>>>> -----
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> No problems there.
>>>>>
>>>>>
>>>>>>
>>>>>> BTW, I could execute "rados lspools".
>>>>>>
>>>>>> root@ceph01:~# rados lspools
>>>>>> data
>>>>>> metadata
>>>>>> rbd
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> This might mean the rbd image list object can't be read for some
>>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>>> isn't. Can you share the output of 'ceph -s' and
>>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc
>>>>> 20
>>>>> --debug-auth 20'?
>>>>>
>>>>> You can run 'rados lspools' with those options as well and compare.
>>>>>
>>>>>
>>>>>> I would like to use rbd volume and attach it as virtual device for VM
>>>>>> guest on KVM.
>>>>>>
>>>>>> Could you advice to me ?
>>>>>>
>>>>>>
>>>>>> My environment is below.
>>>>>>
>>>>>> *ceph cluster is configured on single server.
>>>>>> *server is ubuntu 10.10 maverick.
>>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>>  (version: 0.38-1maverick)
>>>>>> *apparmor is disable.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>>>
>>>>>
>>>>>> *root@ceph01:/# ls -l /etc/ceph
>>>>>> total 16
>>>>>> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
>>>>>> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
>>>>>> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
>>>>>> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
>>>>>> */var/lib/ceph/tmp is exists.
>>>>>> root@ceph01:/var/log# ls -l /var/lib/ceph/
>>>>>> total 4
>>>>>> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>>>>>>
>>>>>> */etc/ceph/ceph.conf
>>>>>> [global]
>>>>>>         auth supported = cephx
>>>>>>         keyring = /etc/ceph/$name.keyring
>>>>>> [mon]
>>>>>>         mon data = /data/data/mon$id
>>>>>>         debug ms = 1
>>>>>> [mon.0]
>>>>>>         host = ceph01
>>>>>>         mon addr = 10.68.119.191:6789
>>>>>> [mds]
>>>>>>
>>>>>> [mds.0]
>>>>>>         host = ceph01
>>>>>> [osd]
>>>>>>         osd data = /data/osd$id
>>>>>>         osd journal = /data/osd$id/journal
>>>>>>         osd journal size = 512
>>>>>>         osd class tmp = /var/lib/ceph/tmp
>>>>>> [osd.0]
>>>>>>         host = ceph01
>>>>>>         btrfs devs = /dev/sdb1
>>>>>>
>>>>>>
>>>>>> Waiting for your reply,
>>>>>>
>>>>>> Tomoya.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>
>
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-03 22:54           ` Masuko Tomoya
@ 2012-02-03 23:01             ` Josh Durgin
  2012-02-04  0:31               ` Masuko Tomoya
  0 siblings, 1 reply; 9+ messages in thread
From: Josh Durgin @ 2012-02-03 23:01 UTC (permalink / raw)
  To: Masuko Tomoya; +Cc: ceph-devel

On 02/03/2012 02:54 PM, Masuko Tomoya wrote:
> Hi,
>
> The output of 'ceph pg dump' is below.
>
> root@ceph01:~# ceph pg dump
> 2012-02-04 07:50:15.453151 mon<- [pg,dump]
> 2012-02-04 07:50:15.453734 mon.0 ->  'dumped all in format plain' (0)
> version 63
> last_osdmap_epoch 37
> last_pg_scan 1
> full_ratio 0.95
> nearfull_ratio 0.85
> pg_stat objects mip     degr    unf     kb      bytes   log
> disklog state   v       reported        up      acting  last_scrub
> 1.1p0   0       0       0       0       0       0       0       0
>   active+clean+degraded   0'0     34'30   [0]     [0] 0'0
> 2012-02-03 10:25:55.383343
> 0.0p0   0       0       0       0       0       0       0       0
>   active+clean+degraded   0'0     34'32   [0]     [0] 0'0
> 2012-02-03 10:25:51.380648
> 1.0p0   0       0       0       0       0       0       0       0
>   active+clean+degraded   0'0     34'30   [0]     [0] 0'0
> 2012-02-03 10:25:53.381291
> 0.1p0   0       0       0       0       0       0       0       0
>   active+clean+degraded   0'0     34'32   [0]     [0] 0'0
> 2012-02-03 10:25:52.380881
> 2.0p0   0       0       0       0       0       0       0       0
>   active+clean+degraded   0'0     34'30   [0]     [0] 0'0
> 2012-02-03 10:25:59.387441
> 2.1p0   0       0       0       0       0       0       0       0
>   active+clean+degraded   0'0     34'30   [0]     [0] 0'0
> 2012-02-03 10:26:04.392778
> pool 0  0       0       0       0       0       0       0       0
> pool 1  0       0       0       0       0       0       0       0
> pool 2  0       0       0       0       0       0       0       0
>   sum    0       0       0       0       0       0       0       0
> osdstat kbused  kbavail kb      hb in   hb out
> 0       1568    15726032        15727600        []      []
>   sum    1568    15726032        15727600
>

You hit a bug in 0.38 that made the default crushmap for one osd
contain no pgs. This was fixed in 0.39, so I'd suggest upgrading and
re-running mkcephfs.

>
> 2012/2/3 Josh Durgin<josh.durgin@dreamhost.com>:
>> On 02/03/2012 02:14 PM, Masuko Tomoya wrote:
>>>
>>> Hi Josh,
>>>
>>> Thank you for your comments.
>>>
>>>>     debug osd = 20
>>>>     debug ms = 1
>>>>     debug filestore = 20
>>>
>>>
>>> I added this to the osd section of ceph.conf and ran /etc/init.d/ceph
>>> stop&start.
>>>
>>> The output of OSD.log when 'rbd list' was executed is below.
>>>
>>> -----
>>> 2012-02-04 04:29:22.457990 7fe0e08fb710 osd.0 32
>>> OSD::ms_verify_authorizer name=client.admin auid=0
>>> 2012-02-04 04:29:22.458041 7fe0e08fb710 osd.0 32  new session
>>> 0x24f5240 con=0x24d4dc0 addr=10.68.119.191:0/1005110
>>> 2012-02-04 04:29:22.458069 7fe0e08fb710 osd.0 32  session 0x24f5240
>>> has caps osdcaps(pools={} default allow= default_deny=)
>>> 2012-02-04 04:29:22.458415 7fe0e6c0a710 -- 10.68.119.191:6801/4992<==
>>> client.4201 10.68.119.191:0/1005110 1 ==== osd_op(client.4201.0:1
>>> rbd_directory [read 0~0] 2.30a98c1c) v3 ==== 143+0+0 (3720164172 0 0)
>>> 0x24d8900 con 0x24d4dc0
>>> 2012-02-04 04:29:22.458442 7fe0e6c0a710 osd.0 32 _dispatch 0x24d8900
>>> osd_op(client.4201.0:1 rbd_directory [read 0~0] 2.30a98c1c) v3
>>> 2012-02-04 04:29:22.458463 7fe0e6c0a710 osd.0 32
>>> require_same_or_newer_map 32 (i am 32) 0x24d8900
>>> 2012-02-04 04:29:22.458487 7fe0e6c0a710 osd.0 32 _share_map_incoming
>>> client.4201 10.68.119.191:0/1005110 32
>>> 2012-02-04 04:29:22.458507 7fe0e6c0a710 osd.0 32 hit non-existent pg
>>> 2.0, waiting
>>
>>
>> The pg should have been created already. What's the output of 'ceph pg
>> dump'?
>>
>>
>>>
>>>
>>> 2012/2/3 Josh Durgin<josh.durgin@dreamhost.com>:
>>>>
>>>> On 02/03/2012 12:51 AM, Masuko Tomoya wrote:
>>>>>
>>>>>
>>>>> Hi Josh,
>>>>>
>>>>> Thank you for reply !
>>>>>
>>>>>> This might mean the rbd image list object can't be read for some
>>>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>>>> isn't. Can you share the output of 'ceph -s' and
>>>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc
>>>>>> 20
>>>>>> --debug-auth 20'?
>>>>>
>>>>>
>>>>>
>>>>> The output of 'ceph -s' is below.
>>>>> -------
>>>>> root@ceph01:~# ceph -s
>>>>> 2012-02-03 17:01:47.881960    pg v33: 6 pgs: 6 active+clean+degraded;
>>>>> 0 KB data, 1056 KB used, 15357 MB / 15358 MB avail
>>>>> 2012-02-03 17:01:47.882583   mds e9: 1/1/1 up {0=0=up:creating}
>>>>> 2012-02-03 17:01:47.882733   osd e21: 1 osds: 1 up, 1 in
>>>>> 2012-02-03 17:01:47.883042   log 2012-02-03 16:35:11.183897 osd.0
>>>>> 10.68.119.191:6801/2912 12 : [WRN] map e19 wrongly marked me down or
>>>>> wrong addr
>>>>> 2012-02-03 17:01:47.883144   mon e1: 1 mons at {0=10.68.119.191:6789/0}
>>>>>
>>>>> The output of 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>>>> --debug-monc 20 --debug-auth 20' is below.
>>>>> ------
>>>>> root@ceph01:~# rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>>>> --debug-monc 20 --debug-auth 20
>>>>
>>>>
>>>>
>>>> <snip>
>>>>
>>>>
>>>>> 2012-02-03 17:02:10.971391 7f88cbb91720 client.4106.objecter op_submit
>>>>> oid rbd_directory @2 [read 0~0] tid 1 osd.0
>>>>> 2012-02-03 17:02:10.971465 7f88cbb91720 client.4106.objecter send_op 1
>>>>> to
>>>>> osd.0
>>>>> 2012-02-03 17:02:10.971533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
>>>>> 10.68.119.191:6801/2912 -- osd_op(client.4106.0:1 rbd_directory [read
>>>>> 0~0] 2.30a98c1c) v1 -- ?+0 0x24664c0 con 0x24661b0
>>>>
>>>>
>>>>
>>>> Everything above here is normal - the rbd tool connected to the
>>>> monitors, got the monmap and osdmap, and sent a request to read the
>>>> 'rbd_directory' object.
>>>>
>>>> <snip>
>>>>
>>>>
>>>>> 2012-02-03 17:02:25.969338 7f88c7261710 client.4106.objecter  tid 1 on
>>>>> osd.0 is laggy
>>>>
>>>>
>>>>
>>>> This means the osd isn't responding to the read. Check the osd log for
>>>> errors. If there's nothing obvious, add this to the osd section of your
>>>> ceph.conf and restart the osd:
>>>>
>>>>     debug osd = 20
>>>>     debug ms = 1
>>>>     debug filestore = 20
>>>>
>>>> Then run 'rbd ls' and look at what happens after
>>>> 'osd_op.*rbd_directory' appears in the osd log.
>>>>
>>>> <rados lspools log>
>>>>
>>>>
>>>>>
>>>>> I compared those logs and found there is differences.
>>>>> 'rbd list'
>>>>> 2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500<==
>>>>> mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
>>>>> ==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
>>>>> 2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
>>>>> handle_osd_map ignoring epochs [21,21]<= 21
>>>>> 2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
>>>>> dump_active .. 0 homeless
>>>>> 2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
>>>>> 2.30a98c1c      osd.0   rbd_directory   [read 0~0]
>>>>> --(snip)--
>>>>>
>>>>> 'rados lspools'
>>>>> 2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868<==
>>>>> mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
>>>>> ==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
>>>>> 2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
>>>>> handle_osd_map got epochs [21,21]>      0
>>>>> 2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
>>>>> handle_osd_map decoding full epoch 21
>>>>> 2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
>>>>> dump_active .. 0 homeless
>>>>> data
>>>>> metadata
>>>>> rbd
>>>>> --(snip)--
>>>>>
>>>>> What do these logs mean ?
>>>>
>>>>
>>>>
>>>> The difference is that 'rbd ls' talks to the monitors and osds, while
>>>> 'rados
>>>> lspools' just needs to talk to the monitors. The objecter dump_active
>>>> part
>>>> is listing in-flight osd requests.
>>>>
>>>>
>>>>>
>>>>>>> *ceph cluster is configured on single server.
>>>>>>> *server is ubuntu 10.10 maverick.
>>>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>>>   (version: 0.38-1maverick)
>>>>>>> *apparmor is disable.
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>>>
>>>>>
>>>>>
>>>>> I use libvirt 0.8.3 (latest version for maverick), so I disabled
>>>>> apparmor.
>>>>>
>>>>>
>>>>>
>>>>> 2012/2/2 Josh Durgin<josh.durgin@dreamhost.com>:
>>>>>>
>>>>>>
>>>>>> On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> Hi, all.
>>>>>>>
>>>>>>> When I execute "rbd" command, it is not success.
>>>>>>>
>>>>>>> root@ceph01:~# rbd list
>>>>>>> (no response)
>>>>>>>
>>>>>>> /var/log/ceph/mon.0.log
>>>>>>> -----
>>>>>>> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1 ====
>>>>>>> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>>> 0x1619c00 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1 ====
>>>>>>> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>>> 0x1619a00 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
>>>>>>> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>>> 0x161fc00 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+}) v2
>>>>>>> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 -- ?+0
>>>>>>> 0x163d780
>>>>>>> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>> client.4112 10.68.119.191:0/1002580 5 ====
>>>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>>>> 0x1617a80 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>>>> ?+0 0x1619600
>>>>>>> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>>>> ?+0 0x163d900
>>>>>>> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>> client.4112 10.68.119.191:0/1002580 6 ====
>>>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>>>> 0x16178c0 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
>>>>>>> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>>>> ?+0 0x1619400
>>>>>>> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>>>> ?+0 0x161d300
>>>>>>> -----
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> No problems there.
>>>>>>
>>>>>>
>>>>>>>
>>>>>>> BTW, I could execute "rados lspools".
>>>>>>>
>>>>>>> root@ceph01:~# rados lspools
>>>>>>> data
>>>>>>> metadata
>>>>>>> rbd
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> This might mean the rbd image list object can't be read for some
>>>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>>>> isn't. Can you share the output of 'ceph -s' and
>>>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc
>>>>>> 20
>>>>>> --debug-auth 20'?
>>>>>>
>>>>>> You can run 'rados lspools' with those options as well and compare.
>>>>>>
>>>>>>
>>>>>>> I would like to use rbd volume and attach it as virtual device for VM
>>>>>>> guest on KVM.
>>>>>>>
>>>>>>> Could you advice to me ?
>>>>>>>
>>>>>>>
>>>>>>> My environment is below.
>>>>>>>
>>>>>>> *ceph cluster is configured on single server.
>>>>>>> *server is ubuntu 10.10 maverick.
>>>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>>>   (version: 0.38-1maverick)
>>>>>>> *apparmor is disable.
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>>>>
>>>>>>
>>>>>>> *root@ceph01:/# ls -l /etc/ceph
>>>>>>> total 16
>>>>>>> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
>>>>>>> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
>>>>>>> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
>>>>>>> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
>>>>>>> */var/lib/ceph/tmp is exists.
>>>>>>> root@ceph01:/var/log# ls -l /var/lib/ceph/
>>>>>>> total 4
>>>>>>> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>>>>>>>
>>>>>>> */etc/ceph/ceph.conf
>>>>>>> [global]
>>>>>>>          auth supported = cephx
>>>>>>>          keyring = /etc/ceph/$name.keyring
>>>>>>> [mon]
>>>>>>>          mon data = /data/data/mon$id
>>>>>>>          debug ms = 1
>>>>>>> [mon.0]
>>>>>>>          host = ceph01
>>>>>>>          mon addr = 10.68.119.191:6789
>>>>>>> [mds]
>>>>>>>
>>>>>>> [mds.0]
>>>>>>>          host = ceph01
>>>>>>> [osd]
>>>>>>>          osd data = /data/osd$id
>>>>>>>          osd journal = /data/osd$id/journal
>>>>>>>          osd journal size = 512
>>>>>>>          osd class tmp = /var/lib/ceph/tmp
>>>>>>> [osd.0]
>>>>>>>          host = ceph01
>>>>>>>          btrfs devs = /dev/sdb1
>>>>>>>
>>>>>>>
>>>>>>> Waiting for your reply,
>>>>>>>
>>>>>>> Tomoya.
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>
>>


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: couldn't use rbd
  2012-02-03 23:01             ` Josh Durgin
@ 2012-02-04  0:31               ` Masuko Tomoya
  0 siblings, 0 replies; 9+ messages in thread
From: Masuko Tomoya @ 2012-02-04  0:31 UTC (permalink / raw)
  To: Josh Durgin; +Cc: ceph-devel

Hi,

I upgraded ceph to 0.41 and re-running mkcephfs.
I found my issue is fixed.

-----
root@ceph01:~# rbd list
pool rbd doesn't contain rbd images
root@ceph01:~# rbd create test --size 1024
root@ceph01:~# rbd list
test
-----

Josh, thank you for your advices.


2012/2/3 Josh Durgin <josh.durgin@dreamhost.com>:
> On 02/03/2012 02:54 PM, Masuko Tomoya wrote:
>>
>> Hi,
>>
>> The output of 'ceph pg dump' is below.
>>
>> root@ceph01:~# ceph pg dump
>> 2012-02-04 07:50:15.453151 mon<- [pg,dump]
>> 2012-02-04 07:50:15.453734 mon.0 ->  'dumped all in format plain' (0)
>> version 63
>> last_osdmap_epoch 37
>> last_pg_scan 1
>> full_ratio 0.95
>> nearfull_ratio 0.85
>> pg_stat objects mip     degr    unf     kb      bytes   log
>> disklog state   v       reported        up      acting  last_scrub
>> 1.1p0   0       0       0       0       0       0       0       0
>>  active+clean+degraded   0'0     34'30   [0]     [0] 0'0
>> 2012-02-03 10:25:55.383343
>> 0.0p0   0       0       0       0       0       0       0       0
>>  active+clean+degraded   0'0     34'32   [0]     [0] 0'0
>> 2012-02-03 10:25:51.380648
>> 1.0p0   0       0       0       0       0       0       0       0
>>  active+clean+degraded   0'0     34'30   [0]     [0] 0'0
>> 2012-02-03 10:25:53.381291
>> 0.1p0   0       0       0       0       0       0       0       0
>>  active+clean+degraded   0'0     34'32   [0]     [0] 0'0
>> 2012-02-03 10:25:52.380881
>> 2.0p0   0       0       0       0       0       0       0       0
>>  active+clean+degraded   0'0     34'30   [0]     [0] 0'0
>> 2012-02-03 10:25:59.387441
>> 2.1p0   0       0       0       0       0       0       0       0
>>  active+clean+degraded   0'0     34'30   [0]     [0] 0'0
>> 2012-02-03 10:26:04.392778
>> pool 0  0       0       0       0       0       0       0       0
>> pool 1  0       0       0       0       0       0       0       0
>> pool 2  0       0       0       0       0       0       0       0
>>  sum    0       0       0       0       0       0       0       0
>> osdstat kbused  kbavail kb      hb in   hb out
>> 0       1568    15726032        15727600        []      []
>>  sum    1568    15726032        15727600
>>
>
> You hit a bug in 0.38 that made the default crushmap for one osd
> contain no pgs. This was fixed in 0.39, so I'd suggest upgrading and
> re-running mkcephfs.
>
>
>>
>> 2012/2/3 Josh Durgin<josh.durgin@dreamhost.com>:
>>>
>>> On 02/03/2012 02:14 PM, Masuko Tomoya wrote:
>>>>
>>>>
>>>> Hi Josh,
>>>>
>>>> Thank you for your comments.
>>>>
>>>>>    debug osd = 20
>>>>>    debug ms = 1
>>>>>    debug filestore = 20
>>>>
>>>>
>>>>
>>>> I added this to the osd section of ceph.conf and ran /etc/init.d/ceph
>>>> stop&start.
>>>>
>>>> The output of OSD.log when 'rbd list' was executed is below.
>>>>
>>>> -----
>>>> 2012-02-04 04:29:22.457990 7fe0e08fb710 osd.0 32
>>>> OSD::ms_verify_authorizer name=client.admin auid=0
>>>> 2012-02-04 04:29:22.458041 7fe0e08fb710 osd.0 32  new session
>>>> 0x24f5240 con=0x24d4dc0 addr=10.68.119.191:0/1005110
>>>> 2012-02-04 04:29:22.458069 7fe0e08fb710 osd.0 32  session 0x24f5240
>>>> has caps osdcaps(pools={} default allow= default_deny=)
>>>> 2012-02-04 04:29:22.458415 7fe0e6c0a710 -- 10.68.119.191:6801/4992<==
>>>> client.4201 10.68.119.191:0/1005110 1 ==== osd_op(client.4201.0:1
>>>> rbd_directory [read 0~0] 2.30a98c1c) v3 ==== 143+0+0 (3720164172 0 0)
>>>> 0x24d8900 con 0x24d4dc0
>>>> 2012-02-04 04:29:22.458442 7fe0e6c0a710 osd.0 32 _dispatch 0x24d8900
>>>> osd_op(client.4201.0:1 rbd_directory [read 0~0] 2.30a98c1c) v3
>>>> 2012-02-04 04:29:22.458463 7fe0e6c0a710 osd.0 32
>>>> require_same_or_newer_map 32 (i am 32) 0x24d8900
>>>> 2012-02-04 04:29:22.458487 7fe0e6c0a710 osd.0 32 _share_map_incoming
>>>> client.4201 10.68.119.191:0/1005110 32
>>>> 2012-02-04 04:29:22.458507 7fe0e6c0a710 osd.0 32 hit non-existent pg
>>>> 2.0, waiting
>>>
>>>
>>>
>>> The pg should have been created already. What's the output of 'ceph pg
>>> dump'?
>>>
>>>
>>>>
>>>>
>>>> 2012/2/3 Josh Durgin<josh.durgin@dreamhost.com>:
>>>>>
>>>>>
>>>>> On 02/03/2012 12:51 AM, Masuko Tomoya wrote:
>>>>>>
>>>>>>
>>>>>>
>>>>>> Hi Josh,
>>>>>>
>>>>>> Thank you for reply !
>>>>>>
>>>>>>> This might mean the rbd image list object can't be read for some
>>>>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>>>>> isn't. Can you share the output of 'ceph -s' and
>>>>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc
>>>>>>> 20
>>>>>>> --debug-auth 20'?
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> The output of 'ceph -s' is below.
>>>>>> -------
>>>>>> root@ceph01:~# ceph -s
>>>>>> 2012-02-03 17:01:47.881960    pg v33: 6 pgs: 6 active+clean+degraded;
>>>>>> 0 KB data, 1056 KB used, 15357 MB / 15358 MB avail
>>>>>> 2012-02-03 17:01:47.882583   mds e9: 1/1/1 up {0=0=up:creating}
>>>>>> 2012-02-03 17:01:47.882733   osd e21: 1 osds: 1 up, 1 in
>>>>>> 2012-02-03 17:01:47.883042   log 2012-02-03 16:35:11.183897 osd.0
>>>>>> 10.68.119.191:6801/2912 12 : [WRN] map e19 wrongly marked me down or
>>>>>> wrong addr
>>>>>> 2012-02-03 17:01:47.883144   mon e1: 1 mons at
>>>>>> {0=10.68.119.191:6789/0}
>>>>>>
>>>>>> The output of 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>>>>> --debug-monc 20 --debug-auth 20' is below.
>>>>>> ------
>>>>>> root@ceph01:~# rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20
>>>>>> --debug-monc 20 --debug-auth 20
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> <snip>
>>>>>
>>>>>
>>>>>> 2012-02-03 17:02:10.971391 7f88cbb91720 client.4106.objecter op_submit
>>>>>> oid rbd_directory @2 [read 0~0] tid 1 osd.0
>>>>>> 2012-02-03 17:02:10.971465 7f88cbb91720 client.4106.objecter send_op 1
>>>>>> to
>>>>>> osd.0
>>>>>> 2012-02-03 17:02:10.971533 7f88cbb91720 -- 10.68.119.191:0/1003500 -->
>>>>>> 10.68.119.191:6801/2912 -- osd_op(client.4106.0:1 rbd_directory [read
>>>>>> 0~0] 2.30a98c1c) v1 -- ?+0 0x24664c0 con 0x24661b0
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> Everything above here is normal - the rbd tool connected to the
>>>>> monitors, got the monmap and osdmap, and sent a request to read the
>>>>> 'rbd_directory' object.
>>>>>
>>>>> <snip>
>>>>>
>>>>>
>>>>>> 2012-02-03 17:02:25.969338 7f88c7261710 client.4106.objecter  tid 1 on
>>>>>> osd.0 is laggy
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> This means the osd isn't responding to the read. Check the osd log for
>>>>> errors. If there's nothing obvious, add this to the osd section of your
>>>>> ceph.conf and restart the osd:
>>>>>
>>>>>    debug osd = 20
>>>>>    debug ms = 1
>>>>>    debug filestore = 20
>>>>>
>>>>> Then run 'rbd ls' and look at what happens after
>>>>> 'osd_op.*rbd_directory' appears in the osd log.
>>>>>
>>>>> <rados lspools log>
>>>>>
>>>>>
>>>>>>
>>>>>> I compared those logs and found there is differences.
>>>>>> 'rbd list'
>>>>>> 2012-02-03 17:02:10.971770 7f88c9366710 -- 10.68.119.191:0/1003500<==
>>>>>> mon.0 10.68.119.191:6789/0 10 ==== osd_map(21..21 src has 1..21) v2
>>>>>> ==== 1284+0+0 (473305567 0 0) 0x24655a0 con 0x24603e0
>>>>>> 2012-02-03 17:02:10.971789 7f88c9366710 client.4106.objecter
>>>>>> handle_osd_map ignoring epochs [21,21]<= 21
>>>>>> 2012-02-03 17:02:10.971801 7f88c9366710 client.4106.objecter
>>>>>> dump_active .. 0 homeless
>>>>>> 2012-02-03 17:02:10.971815 7f88c9366710 client.4106.objecter 1
>>>>>> 2.30a98c1c      osd.0   rbd_directory   [read 0~0]
>>>>>> --(snip)--
>>>>>>
>>>>>> 'rados lspools'
>>>>>> 2012-02-03 17:11:52.866072 7f9c5764b710 -- 10.68.119.191:0/1003868<==
>>>>>> mon.0 10.68.119.191:6789/0 7 ==== osd_map(21..21 src has 1..21) v2
>>>>>> ==== 1284+0+0 (473305567 0 0) 0x770a70 con 0x771440
>>>>>> 2012-02-03 17:11:52.866103 7f9c5764b710 client.4107.objecter
>>>>>> handle_osd_map got epochs [21,21]>      0
>>>>>> 2012-02-03 17:11:52.866111 7f9c5764b710 client.4107.objecter
>>>>>> handle_osd_map decoding full epoch 21
>>>>>> 2012-02-03 17:11:52.866272 7f9c5764b710 client.4107.objecter
>>>>>> dump_active .. 0 homeless
>>>>>> data
>>>>>> metadata
>>>>>> rbd
>>>>>> --(snip)--
>>>>>>
>>>>>> What do these logs mean ?
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> The difference is that 'rbd ls' talks to the monitors and osds, while
>>>>> 'rados
>>>>> lspools' just needs to talk to the monitors. The objecter dump_active
>>>>> part
>>>>> is listing in-flight osd requests.
>>>>>
>>>>>
>>>>>>
>>>>>>>> *ceph cluster is configured on single server.
>>>>>>>> *server is ubuntu 10.10 maverick.
>>>>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>>>>  (version: 0.38-1maverick)
>>>>>>>> *apparmor is disable.
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> I use libvirt 0.8.3 (latest version for maverick), so I disabled
>>>>>> apparmor.
>>>>>>
>>>>>>
>>>>>>
>>>>>> 2012/2/2 Josh Durgin<josh.durgin@dreamhost.com>:
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On 02/02/2012 01:49 AM, Masuko Tomoya wrote:
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> Hi, all.
>>>>>>>>
>>>>>>>> When I execute "rbd" command, it is not success.
>>>>>>>>
>>>>>>>> root@ceph01:~# rbd list
>>>>>>>> (no response)
>>>>>>>>
>>>>>>>> /var/log/ceph/mon.0.log
>>>>>>>> -----
>>>>>>>> 2012-02-02 17:58:19.801762 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>>> client.? 10.68.119.191:0/1002580 1 ==== auth(proto 0 30 bytes) v1
>>>>>>>> ====
>>>>>>>> 56+0+0 (625540289 0 0) 0x1619a00 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.801919 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>>>> 0x1619c00 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.802505 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>>> client.? 10.68.119.191:0/1002580 2 ==== auth(proto 2 32 bytes) v1
>>>>>>>> ====
>>>>>>>> 58+0+0 (346146289 0 0) 0x161fc00 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.802673 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>>>> 0x1619a00 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.803473 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>>> client.? 10.68.119.191:0/1002580 3 ==== auth(proto 2 165 bytes) v1
>>>>>>>> ==== 191+0+0 (3737796417 0 0) 0x1619600 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.803745 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> 10.68.119.191:0/1002580 -- auth_reply(proto 2 0 Success) v1 -- ?+0
>>>>>>>> 0x161fc00 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.804425 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>>> client.? 10.68.119.191:0/1002580 4 ==== mon_subscribe({monmap=0+})
>>>>>>>> v2
>>>>>>>> ==== 23+0+0 (1620593354 0 0) 0x1617380 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.804488 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1635700 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.804517 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> client.? 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>>>>> ?+0
>>>>>>>> 0x163d780
>>>>>>>> 2012-02-02 17:58:19.804550 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>>> client.4112 10.68.119.191:0/1002580 5 ====
>>>>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>>>>> 0x1617a80 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.804578 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617380 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.804656 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>>>>> ?+0 0x1619600
>>>>>>>> 2012-02-02 17:58:19.804744 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>>>>> ?+0 0x163d900
>>>>>>>> 2012-02-02 17:58:19.804778 7ff4bbfb1710 -- 10.68.119.191:6789/0<==
>>>>>>>> client.4112 10.68.119.191:0/1002580 6 ====
>>>>>>>> mon_subscribe({monmap=0+,osdmap=0}) v2 ==== 42+0+0 (982583713 0 0)
>>>>>>>> 0x16178c0 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.804811 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> 10.68.119.191:0/1002580 -- mon_map v1 -- ?+0 0x1617a80 con 0x1615a00
>>>>>>>> 2012-02-02 17:58:19.804855 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> client.? 10.68.119.191:0/1002580 -- osd_map(3..3 src has 1..3) v1 --
>>>>>>>> ?+0 0x1619400
>>>>>>>> 2012-02-02 17:58:19.804884 7ff4bbfb1710 -- 10.68.119.191:6789/0 -->
>>>>>>>> client.4112 10.68.119.191:0/1002580 -- mon_subscribe_ack(300s) v1 --
>>>>>>>> ?+0 0x161d300
>>>>>>>> -----
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> No problems there.
>>>>>>>
>>>>>>>
>>>>>>>>
>>>>>>>> BTW, I could execute "rados lspools".
>>>>>>>>
>>>>>>>> root@ceph01:~# rados lspools
>>>>>>>> data
>>>>>>>> metadata
>>>>>>>> rbd
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> This might mean the rbd image list object can't be read for some
>>>>>>> reason, or the rbd tool is doing something weird that the rados tool
>>>>>>> isn't. Can you share the output of 'ceph -s' and
>>>>>>> 'rbd ls --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc
>>>>>>> 20
>>>>>>> --debug-auth 20'?
>>>>>>>
>>>>>>> You can run 'rados lspools' with those options as well and compare.
>>>>>>>
>>>>>>>
>>>>>>>> I would like to use rbd volume and attach it as virtual device for
>>>>>>>> VM
>>>>>>>> guest on KVM.
>>>>>>>>
>>>>>>>> Could you advice to me ?
>>>>>>>>
>>>>>>>>
>>>>>>>> My environment is below.
>>>>>>>>
>>>>>>>> *ceph cluster is configured on single server.
>>>>>>>> *server is ubuntu 10.10 maverick.
>>>>>>>> *ceph, librados2 and librbd1 packages are installed.
>>>>>>>>  (version: 0.38-1maverick)
>>>>>>>> *apparmor is disable.
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> apparmor shouldn't matter if you have libvirt 0.9.9 or newer.
>>>>>>>
>>>>>>>
>>>>>>>> *root@ceph01:/# ls -l /etc/ceph
>>>>>>>> total 16
>>>>>>>> -rw-r--r-- 1 root root 340 2012-02-02 17:28 ceph.conf
>>>>>>>> -rw------- 1 root root  92 2012-02-02 17:28 client.admin.keyring
>>>>>>>> -rw------- 1 root root  85 2012-02-02 17:28 mds.0.keyring
>>>>>>>> -rw------- 1 root root  85 2012-02-02 17:28 osd.0.keyring
>>>>>>>> */var/lib/ceph/tmp is exists.
>>>>>>>> root@ceph01:/var/log# ls -l /var/lib/ceph/
>>>>>>>> total 4
>>>>>>>> drwxrwxrwx 2 root root 4096 2011-11-11 09:28 tmp
>>>>>>>>
>>>>>>>> */etc/ceph/ceph.conf
>>>>>>>> [global]
>>>>>>>>         auth supported = cephx
>>>>>>>>         keyring = /etc/ceph/$name.keyring
>>>>>>>> [mon]
>>>>>>>>         mon data = /data/data/mon$id
>>>>>>>>         debug ms = 1
>>>>>>>> [mon.0]
>>>>>>>>         host = ceph01
>>>>>>>>         mon addr = 10.68.119.191:6789
>>>>>>>> [mds]
>>>>>>>>
>>>>>>>> [mds.0]
>>>>>>>>         host = ceph01
>>>>>>>> [osd]
>>>>>>>>         osd data = /data/osd$id
>>>>>>>>         osd journal = /data/osd$id/journal
>>>>>>>>         osd journal size = 512
>>>>>>>>         osd class tmp = /var/lib/ceph/tmp
>>>>>>>> [osd.0]
>>>>>>>>         host = ceph01
>>>>>>>>         btrfs devs = /dev/sdb1
>>>>>>>>
>>>>>>>>
>>>>>>>> Waiting for your reply,
>>>>>>>>
>>>>>>>> Tomoya.
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>
>>>
>
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2012-02-04  0:31 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2012-02-02  9:49 couldn't use rbd Masuko Tomoya
2012-02-03  1:26 ` Josh Durgin
2012-02-03  8:51   ` Masuko Tomoya
2012-02-03 17:05     ` Josh Durgin
2012-02-03 22:14       ` Masuko Tomoya
2012-02-03 22:36         ` Josh Durgin
2012-02-03 22:54           ` Masuko Tomoya
2012-02-03 23:01             ` Josh Durgin
2012-02-04  0:31               ` Masuko Tomoya

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.