Hi @all, i’ve had a strange problem creating a VM with ceph as storage backend. I closely followed the offical ceph deployment instructions.
When I create a new VM it fails with: Error executing image transfer script: Error cloning one/one-2 to one/one-2-11-0 in cluster-node-12.
In the log journal I found some more informations:
[Z0][DiM][D]: Deploying VM 13
[VM 13][Z0][VM][I]: New state is ACTIVE
[Z0][ReM][D]: Req:5936 UID:0 VirtualMachineDeploy result SUCCESS, 13
[VM 13][Z0][VM][I]: New LCM state is PROLOG
[Z0][TM][D]: Message received: LOG I 13 Command execution fail: /var/lib/one/remotes/tm/ceph/clone admin-node-02:one/one-2 cluster-node-10:/var/lib/one//datastores/102/13/disk.0 13 101
[VM 13][Z0][TM][I]: Command execution fail: /var/lib/one/remotes/tm/ceph/clone admin-node-02:one/one-2 cluster-node-10:/var/lib/one//datastores/102/13/disk.0 13 101
[Z0][TM][D]: Message received: LOG I 13 /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:66:in `block in <main>': undefined method `elements' for nil:NilClass (NoMethodError)
[VM 13][Z0][TM][I]: /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:66:in `block in <main>': undefined method `elements' for nil:NilClass (NoMethodError)
[Z0][TM][D]: Message received: LOG I 13 from /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:60:in `each'
[VM 13][Z0][TM][I]: from /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:60:in `each'
[Z0][TM][D]: Message received: LOG I 13 from /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:60:in `<main>'
[VM 13][Z0][TM][I]: from /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:60:in `<main>'
[Z0][TM][D]: Message received: LOG E 13 clone: Command " RBD="rbd"
[VM 13][Z0][TM][E]: clone: Command " RBD="rbd"
[Z0][TM][D]: Message received: LOG I 13
[VM 13][Z0][TM][I]:
[Z0][TM][D]: Message received: LOG I 13 rbd info one/one-2-13-0 >/dev/null 2>&1 && exit 0
[VM 13][Z0][TM][I]: rbd info one/one-2-13-0 >/dev/null 2>&1 && exit 0
[Z0][TM][D]: Message received: LOG I 13
[VM 13][Z0][TM][I]:
[Z0][TM][D]: Message received: LOG I 13 rbd_make_snap one/one-2
[VM 13][Z0][TM][I]: rbd_make_snap one/one-2
[Z0][TM][D]: Message received: LOG I 13
[VM 13][Z0][TM][I]:
[Z0][TM][D]: Message received: LOG I 13 set -e -o pipefail
[VM 13][Z0][TM][I]: set -e -o pipefail
[Z0][TM][D]: Message received: LOG I 13
[VM 13][Z0][TM][I]:
[Z0][TM][D]: Message received: LOG I 13 if [ "$(rbd_format one/one-2)" = "2" ]; then
[VM 13][Z0][TM][I]: if [ "$(rbd_format one/one-2)" = "2" ]; then
[Z0][TM][D]: Message received: LOG I 13 rbd clone "one/one-2@snap" one/one-2-13-0
[VM 13][Z0][TM][I]: rbd clone "one/one-2@snap" one/one-2-13-0
[Z0][TM][D]: Message received: LOG I 13 else
[VM 13][Z0][TM][I]: else
[Z0][TM][D]: Message received: LOG I 13 rbd copy one/one-2 one/one-2-13-0
[VM 13][Z0][TM][I]: rbd copy one/one-2 one/one-2-13-0
[Z0][TM][D]: Message received: LOG I 13 fi
[VM 13][Z0][TM][I]: fi
[Z0][TM][D]: Message received: LOG I 13
[VM 13][Z0][TM][I]:
[Z0][TM][D]: Message received: LOG I 13 if [ -n "" -a "" -gt "" ]; then
[VM 13][Z0][TM][I]: if [ -n "" -a "" -gt "" ]; then
[Z0][TM][D]: Message received: LOG I 13 rbd resize one/one-2-13-0 --size
[VM 13][Z0][TM][I]: rbd resize one/one-2-13-0 --size
[Z0][TM][D]: Message received: LOG I 13 fi" failed: 2016-11-29 10:10:38.626275 7f7fe115bd40 -1 auth: unable to find a keyring on /etc/ceph/ceph.client.admin.keyring,/etc/ceph/ceph.keyring,/etc/ceph/keyring,/etc/ceph/keyring.bin: (2) No such file or directory
[VM 13][Z0][TM][I]: fi" failed: 2016-11-29 10:10:38.626275 7f7fe115bd40 -1 auth: unable to find a keyring on /etc/ceph/ceph.client.admin.keyring,/etc/ceph/ceph.keyring,/etc/ceph/keyring,/etc/ceph/keyring.bin: (2) No such file or directory
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.628053 7f7fe115bd40 -1 monclient(hunting): authenticate NOTE: no keyring found; disabled cephx authentication
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.628053 7f7fe115bd40 -1 monclient(hunting): authenticate NOTE: no keyring found; disabled cephx authentication
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.628083 7f7fe115bd40 0 librados: client.admin authentication error (95) Operation not supported
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.628083 7f7fe115bd40 0 librados: client.admin authentication error (95) Operation not supported
[Z0][TM][D]: Message received: LOG I 13 rbd: couldn't connect to the cluster!
[VM 13][Z0][TM][I]: rbd: couldn't connect to the cluster!
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.644590 7f2d916acd40 -1 auth: unable to find a keyring on /etc/ceph/ceph.client.admin.keyring,/etc/ceph/ceph.keyring,/etc/ceph/keyring,/etc/ceph/keyring.bin: (2) No such file or directory
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.644590 7f2d916acd40 -1 auth: unable to find a keyring on /etc/ceph/ceph.client.admin.keyring,/etc/ceph/ceph.keyring,/etc/ceph/keyring,/etc/ceph/keyring.bin: (2) No such file or directory
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.645622 7f2d916acd40 -1 monclient(hunting): authenticate NOTE: no keyring found; disabled cephx authentication
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.645622 7f2d916acd40 -1 monclient(hunting): authenticate NOTE: no keyring found; disabled cephx authentication
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.645628 7f2d916acd40 0 librados: client.admin authentication error (95) Operation not supported
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.645628 7f2d916acd40 0 librados: client.admin authentication error (95) Operation not supported
[Z0][TM][D]: Message received: LOG I 13 rbd: couldn't connect to the cluster!
[VM 13][Z0][TM][I]: rbd: couldn't connect to the cluster!
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.665635 7f946591bd40 -1 auth: unable to find a keyring on /etc/ceph/ceph.client.admin.keyring,/etc/ceph/ceph.keyring,/etc/ceph/keyring,/etc/ceph/keyring.bin: (2) No such file or directory
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.665635 7f946591bd40 -1 auth: unable to find a keyring on /etc/ceph/ceph.client.admin.keyring,/etc/ceph/ceph.keyring,/etc/ceph/keyring,/etc/ceph/keyring.bin: (2) No such file or directory
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.667485 7f946591bd40 -1 monclient(hunting): authenticate NOTE: no keyring found; disabled cephx authentication
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.667485 7f946591bd40 -1 monclient(hunting): authenticate NOTE: no keyring found; disabled cephx authentication
[Z0][TM][D]: Message received: LOG I 13 2016-11-29 10:10:38.667513 7f946591bd40 0 librados: client.admin authentication error (95) Operation not supported
[VM 13][Z0][TM][I]: 2016-11-29 10:10:38.667513 7f946591bd40 0 librados: client.admin authentication error (95) Operation not supported
[Z0][TM][D]: Message received: LOG I 13 rbd: couldn't connect to the cluster!
[VM 13][Z0][TM][I]: rbd: couldn't connect to the cluster!
[Z0][TM][D]: Message received: LOG E 13 Error cloning one/one-2 to one/one-2-13-0 in cluster-node-10
[VM 13][Z0][TM][E]: Error cloning one/one-2 to one/one-2-13-0 in cluster-node-10
[Z0][TM][D]: Message received: LOG I 13 ExitCode: 95
[VM 13][Z0][TM][I]: ExitCode: 95
[Z0][TM][D]: Message received: TRANSFER FAILURE 13 Error cloning one/one-2 to one/one-2-13-0 in cluster-node-10
[VM 13][Z0][TM][E]: Error executing image transfer script: Error cloning one/one-2 to one/one-2-13-0 in cluster-node-10
[VM 13][Z0][VM][I]: New LCM state is PROLOG_FAILURE
It seems the failing command is:
/var/lib/one/remotes/tm/ceph/clone admin-node-02:one/one-2 cluster-node-10:/var/lib/one//datastores/102/13/disk.0 13 101
But if I manually run this command as oneuser on the on the command line it works without a problem:
$ rbd --id libvirt -p one list
one-2
$ ./clone admin-node-02:one/one-2 cluster-node-10:/var/lib/one//datastores/102/13/disk.0 13 101
$ rbd --id libvirt -p one list
one-2
one-2-13-0
If you look closely at the log journal, it seems that the rbd commands are not called with --id libvirt:
[Z0][TM][D]: Message received: LOG E 13 clone: Command " RBD="rbd"
[Z0][TM][D]: Message received: LOG E 13 clone: Command " RBD="rbd"
[Z0][TM][D]: Message received: LOG I 13 rbd info one/one-2-13-0 >/dev/null 2>&1 && exit 0
[Z0][TM][D]: Message received: LOG I 13
[Z0][TM][D]: Message received: LOG I 13 rbd_make_snap one/one-2
[Z0][TM][D]: Message received: LOG I 13
[Z0][TM][D]: Message received: LOG I 13 set -e -o pipefail
[Z0][TM][D]: Message received: LOG I 13
[Z0][TM][D]: Message received: LOG I 13 if [ "$(rbd_format one/one-2)" = "2" ]; then
[Z0][TM][D]: Message received: LOG I 13 rbd clone "one/one-2@snap" one/one-2-13-0
[Z0][TM][D]: Message received: LOG I 13 else
[Z0][TM][D]: Message received: LOG I 13 rbd copy one/one-2 one/one-2-13-0
[Z0][TM][D]: Message received: LOG I 13 fi
[Z0][TM][D]: Message received: LOG I 13
[Z0][TM][D]: Message received: LOG I 13 if [ -n "" -a "" -gt "" ]; then
[Z0][TM][D]: Message received: LOG I 13 rbd resize one/one-2-13-0 --size
[Z0][TM][D]: Message received: LOG I 13 fi"
Leading to unable to find a keyring errors with rbd. And this is because the xpath call went wrong:
[Z0][TM][D]: Message received: LOG I 13 /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:66:in `block in <main>': undefined method `elements' for nil:NilClass (NoMethodError)
[Z0][TM][D]: Message received: LOG I 13 from /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:60:in `each'
[Z0][TM][D]: Message received: LOG I 13 from /var/lib/one/remotes/tm/ceph/../../datastore/xpath.rb:60:in `<main>'
But why? Manually called the xpath command works:
$ onevm show -x 13 | /var/lib/one/remotes/datastore/xpath.rb --stdin /VM/TEMPLATE/DISK[DISK_ID=0]/CEPH_USER
libvirt
Maybe there is some kind of a race condition? After adding some more debug output to the clone script I found that the real command failing was onevm show -x 13. It simply couldn’t connect to the XML_RCP endpoint, cause is wasn’t running on localhost but on a floating-ip (HA Setup). It worked manually because I had set the ONE_XMLRPC environment variable via .bashrc.
Solution: I reconfigured oned to listen to 0.0.0.0 so it’s reachable again for the cli commands.
So this was a hard one, costs me 2 days to figure out and I thought I share it here, maybe it’s of some help vor someone. But on the other hand I think it would be nice if the cli commands had a config file for setting those king things …
Markus
PS.: Bash is hard to debug!