Thread-670::DEBUG::2014-11-27 15:53:15,237::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmCreate with ({'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'tabletEnable': 'true', 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'memGuaranteedSize': 512, 'transparentHugePages': 'true', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'SandyBridge', 'smp': '1', 'numaTune': {'nodeset': '0,1', 'mode': 'interleave'}, 'custom': {}, 'vmType': 'kvm', 'memSize': 512, 'smpCoresPerSocket': '1', 'vmName': '7c7aa9dedb57248f5da291117164f0d7', 'nice': '0', 'bootMenuEnable': 'false', 'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'ovirtmgmt', 'devices': [{'index': '3', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'vmPayload': {'volId': 'config-2', 'file': {'openstack/latest/meta_data.json': 'ewogICJsYXVuY2hfaW5kZXgiIDogIjAiLAogICJhdmFpbGFiaWxpdHlfem9uZSIgOiAibm92YSIs\nCiAgIm5ldHdvcmstaW50ZXJmYWNlcyIgOiAiYXV0byBldGgwXG5pZmFjZSBldGgwIGluZXQgc3Rh\ndGljXG4gIGFkZHJlc3MgMTAzLjQxLjEzNS44XG4gIG5ldG1hc2sgMjU1LjI1NS4yNTUuMFxuICBn\nYXRld2F5IDEwMy40MS4xMzUuMVxuYXV0byBldGgxXG5pZmFjZSBldGgxIGluZXQgc3RhdGljXG4g\nIGFkZHJlc3MgMTcyLjE2OC4xLjMzXG4gIG5ldG1hc2sgMjU1LjI1NS4yNTUuMFxuIiwKICAibmFt\nZSIgOiAicHVuaXQiLAogICJuZXR3b3JrX2NvbmZpZyIgOiB7CiAgICAiY29udGVudF9wYXRoIiA6\nICIvY29udGVudC8wMDAwIiwKICAgICJwYXRoIiA6ICIvZXRjL25ldHdvcmsvaW50ZXJmYWNlcyIK\nICB9LAogICJob3N0bmFtZSIgOiAicHVuaXQiLAogICJ1dWlkIiA6ICJkZGRiNjg2ZC1iNGZmLTQ5\nNGYtYTgwYS00YzA1NjNhNzRlMmEiLAogICJtZXRhIiA6IHsKICAgICJlc3NlbnRpYWwiIDogImZh\nbHNlIiwKICAgICJyb2xlIiA6ICJzZXJ2ZXIiLAogICAgImRzbW9kZSIgOiAibG9jYWwiCiAgfQp9\n', 'openstack/content/0000': 'YXV0byBldGgwCmlmYWNlIGV0aDAgaW5ldCBzdGF0aWMKICBhZGRyZXNzIDEwMy40MS4xMzUuOAog\nIG5ldG1hc2sgMjU1LjI1NS4yNTUuMAogIGdhdGV3YXkgMTAzLjQxLjEzNS4xCmF1dG8gZXRoMQpp\nZmFjZSBldGgxIGluZXQgc3RhdGljCiAgYWRkcmVzcyAxNzIuMTY4LjEuMzMKICBuZXRtYXNrIDI1\nNS4yNTUuMjU1LjAK\n', 'openstack/latest/user_data': 'I2Nsb3VkLWNvbmZpZwpzc2hfcHdhdXRoOiB0cnVlCmRpc2FibGVfcm9vdDogMApvdXRwdXQ6CiAg\nYWxsOiAnPj4gL3Zhci9sb2cvY2xvdWQtaW5pdC1vdXRwdXQubG9nJwpjaHBhc3N3ZDoKICBleHBp\ncmU6IGZhbHNlCnJ1bmNtZDoKLSAnc2VkIC1pICcnL15kYXRhc291cmNlX2xpc3Q6IC9kJycgL2V0\nYy9jbG91ZC9jbG91ZC5jZmc7IGVjaG8gJydkYXRhc291cmNlX2xpc3Q6CiAgWyJOb0Nsb3VkIiwg\nIkNvbmZpZ0RyaXZlIl0nJyA+PiAvZXRjL2Nsb3VkL2Nsb3VkLmNmZycKI2Nsb3VkLWNvbmZpZwpk\naXNhYmxlLWVjMi1tZXRhZGF0YTogdHJ1ZQpkaXNhYmxlX3Jvb3Q6IGZhbHNlCnNzaF9wd2F1dGg6\nIHRydWUKc3NoX2RlbGV0ZWtleXM6IHRydWUKY2hwYXNzd2Q6IHsgZXhwaXJlOiBGYWxzZSB9Cgp1\nc2VyczoKIC0gbmFtZTogcm9vdAogICBwcmltYXJ5LWdyb3VwOiByb290CiAgIHBhc3N3ZDogUEVl\nc1A4NnMKICAgbG9jay1wYXNzd2Q6IGZhbHNlCgpydW5jbWQ6CiAtIHNlZCAtaSAnL25hbWVzZXJ2\nZXIvZCcgL2V0Yy9yZXNvbHYuY29uZgogLSBlY2hvICduYW1lc2VydmVyIDEyMy4yNDIuMjI0LjUw\nJyA+PiAvZXRjL3Jlc29sdi5jb25mCiAtIGVjaG8gJ25hbWVzZXJ2ZXIgMTIzLjI0Mi4yMjQuNTEn\nID4+IC9ldGMvcmVzb2x2LmNvbmYKIC0gZWNobyAnbmFtZXNlcnZlciA4LjguOC44JyA+PiAvZXRj\nL3Jlc29sdi5jb25mCiAtIGVjaG8gJ25hbWVzZXJ2ZXIgOC44LjQuNCcgPj4gL2V0Yy9yZXNvbHYu\nY29uZgogLSBlY2hvICdyb290OlBFZXNQODZzJyB8IGNocGFzc3dkCiAtIHl1bSAteSB1cGRhdGUK\nIC0geXVtIC15IGluc3RhbGwgcmRhdGUKIC0gcmRhdGUgLXMgc3RkdGltZS5nb3YuaGs=\n'}}}, 'readonly': 'true', 'deviceId': '4bf1c2ca-f9a4-418b-8937-130525360e13', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'device': 'cirrus', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '2c906b52-d52f-4d0e-b289-e44b576b6c6c'}, {'index': '2', 'iface': 'ide', 'bootOrder': '2', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '3e7c06f6-cd71-44c0-be18-d10c41d72d3d', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '5b5a6f6c-4c1b-4451-b770-d257d86f571d', 'volumeID': '0b09c5f5-8d87-4113-a083-c006acb2117e', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'specParams': {}, 'readonly': 'false', 'domainID': '6c0d651a-1d85-4673-959c-2a271fb5e07d', 'deviceId': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1A:4A:98:6A:1F', 'linkActive': 'true', 'network': 'Internal', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {'average': 128000, 'peak': 128000, 'burst': 102400}, 'outbound': {'average': 128000, 'peak': 128000, 'burst': 102400}}, 'deviceId': '05ea7c1c-a1da-4205-b481-9ec39d195e7e', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'nicModel': 'pv', 'macAddr': '00:1A:4A:FD:F4:06', 'linkActive': 'true', 'network': '', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '1e2ef1ff-65c9-4fb8-9a8e-5af43384e3b9', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'index': '0', 'specParams': {}, 'deviceId': '0bf6c8bc-5845-49d6-b0ea-ed5e832cfd2a', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'device': 'virtio-serial', 'specParams': {}, 'type': 'controller', 'deviceId': '01e0d37d-2f16-4e43-81a4-eb8e3c3a87e9'}], 'timeOffset': '28800', 'maxVCpus': '16', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'vnc'},) {} flowID [234c1482] Thread-670::INFO::2014-11-27 15:53:15,237::clientIF::390::vds::(createVm) vmContainerLock acquired by vm ad162ac5-f781-4e2d-a066-02409bee2eb5 Thread-670::DEBUG::2014-11-27 15:53:15,258::clientIF::403::vds::(createVm) Total desktops after creation of ad162ac5-f781-4e2d-a066-02409bee2eb5 is 1 Thread-727::DEBUG::2014-11-27 15:53:15,258::vm::2259::vm.Vm::(_startUnderlyingVm) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Start Thread-670::DEBUG::2014-11-27 15:53:15,260::BindingXMLRPC::1139::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'tabletEnable': 'true', 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'memGuaranteedSize': 512, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'SandyBridge', 'smp': '1', 'numaTune': {'nodeset': '0,1', 'mode': 'interleave'}, 'custom': {}, 'vmType': 'kvm', 'memSize': 512, 'smpCoresPerSocket': '1', 'vmName': '7c7aa9dedb57248f5da291117164f0d7', 'nice': '0', 'status': 'WaitForLaunch', 'bootMenuEnable': 'false', 'pid': '0', 'displayIp': '43.252.177.19', 'displayPort': '-1', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'ovirtmgmt', 'devices': [{'index': '3', 'iface': 'ide', 'bootOrder': '1', 'specParams': {'vmPayload': {'volId': 'config-2', 'file': {'openstack/latest/meta_data.json': 'ewogICJsYXVuY2hfaW5kZXgiIDogIjAiLAogICJhdmFpbGFiaWxpdHlfem9uZSIgOiAibm92YSIs\nCiAgIm5ldHdvcmstaW50ZXJmYWNlcyIgOiAiYXV0byBldGgwXG5pZmFjZSBldGgwIGluZXQgc3Rh\ndGljXG4gIGFkZHJlc3MgMTAzLjQxLjEzNS44XG4gIG5ldG1hc2sgMjU1LjI1NS4yNTUuMFxuICBn\nYXRld2F5IDEwMy40MS4xMzUuMVxuYXV0byBldGgxXG5pZmFjZSBldGgxIGluZXQgc3RhdGljXG4g\nIGFkZHJlc3MgMTcyLjE2OC4xLjMzXG4gIG5ldG1hc2sgMjU1LjI1NS4yNTUuMFxuIiwKICAibmFt\nZSIgOiAicHVuaXQiLAogICJuZXR3b3JrX2NvbmZpZyIgOiB7CiAgICAiY29udGVudF9wYXRoIiA6\nICIvY29udGVudC8wMDAwIiwKICAgICJwYXRoIiA6ICIvZXRjL25ldHdvcmsvaW50ZXJmYWNlcyIK\nICB9LAogICJob3N0bmFtZSIgOiAicHVuaXQiLAogICJ1dWlkIiA6ICJkZGRiNjg2ZC1iNGZmLTQ5\nNGYtYTgwYS00YzA1NjNhNzRlMmEiLAogICJtZXRhIiA6IHsKICAgICJlc3NlbnRpYWwiIDogImZh\nbHNlIiwKICAgICJyb2xlIiA6ICJzZXJ2ZXIiLAogICAgImRzbW9kZSIgOiAibG9jYWwiCiAgfQp9\n', 'openstack/content/0000': 'YXV0byBldGgwCmlmYWNlIGV0aDAgaW5ldCBzdGF0aWMKICBhZGRyZXNzIDEwMy40MS4xMzUuOAog\nIG5ldG1hc2sgMjU1LjI1NS4yNTUuMAogIGdhdGV3YXkgMTAzLjQxLjEzNS4xCmF1dG8gZXRoMQpp\nZmFjZSBldGgxIGluZXQgc3RhdGljCiAgYWRkcmVzcyAxNzIuMTY4LjEuMzMKICBuZXRtYXNrIDI1\nNS4yNTUuMjU1LjAK\n', 'openstack/latest/user_data': 'I2Nsb3VkLWNvbmZpZwpzc2hfcHdhdXRoOiB0cnVlCmRpc2FibGVfcm9vdDogMApvdXRwdXQ6CiAg\nYWxsOiAnPj4gL3Zhci9sb2cvY2xvdWQtaW5pdC1vdXRwdXQubG9nJwpjaHBhc3N3ZDoKICBleHBp\ncmU6IGZhbHNlCnJ1bmNtZDoKLSAnc2VkIC1pICcnL15kYXRhc291cmNlX2xpc3Q6IC9kJycgL2V0\nYy9jbG91ZC9jbG91ZC5jZmc7IGVjaG8gJydkYXRhc291cmNlX2xpc3Q6CiAgWyJOb0Nsb3VkIiwg\nIkNvbmZpZ0RyaXZlIl0nJyA+PiAvZXRjL2Nsb3VkL2Nsb3VkLmNmZycKI2Nsb3VkLWNvbmZpZwpk\naXNhYmxlLWVjMi1tZXRhZGF0YTogdHJ1ZQpkaXNhYmxlX3Jvb3Q6IGZhbHNlCnNzaF9wd2F1dGg6\nIHRydWUKc3NoX2RlbGV0ZWtleXM6IHRydWUKY2hwYXNzd2Q6IHsgZXhwaXJlOiBGYWxzZSB9Cgp1\nc2VyczoKIC0gbmFtZTogcm9vdAogICBwcmltYXJ5LWdyb3VwOiByb290CiAgIHBhc3N3ZDogUEVl\nc1A4NnMKICAgbG9jay1wYXNzd2Q6IGZhbHNlCgpydW5jbWQ6CiAtIHNlZCAtaSAnL25hbWVzZXJ2\nZXIvZCcgL2V0Yy9yZXNvbHYuY29uZgogLSBlY2hvICduYW1lc2VydmVyIDEyMy4yNDIuMjI0LjUw\nJyA+PiAvZXRjL3Jlc29sdi5jb25mCiAtIGVjaG8gJ25hbWVzZXJ2ZXIgMTIzLjI0Mi4yMjQuNTEn\nID4+IC9ldGMvcmVzb2x2LmNvbmYKIC0gZWNobyAnbmFtZXNlcnZlciA4LjguOC44JyA+PiAvZXRj\nL3Jlc29sdi5jb25mCiAtIGVjaG8gJ25hbWVzZXJ2ZXIgOC44LjQuNCcgPj4gL2V0Yy9yZXNvbHYu\nY29uZgogLSBlY2hvICdyb290OlBFZXNQODZzJyB8IGNocGFzc3dkCiAtIHl1bSAteSB1cGRhdGUK\nIC0geXVtIC15IGluc3RhbGwgcmRhdGUKIC0gcmRhdGUgLXMgc3RkdGltZS5nb3YuaGs=\n'}}}, 'readonly': 'true', 'deviceId': '4bf1c2ca-f9a4-418b-8937-130525360e13', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'device': 'cirrus', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '2c906b52-d52f-4d0e-b289-e44b576b6c6c'}, {'index': '2', 'iface': 'ide', 'bootOrder': '2', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '3e7c06f6-cd71-44c0-be18-d10c41d72d3d', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '5b5a6f6c-4c1b-4451-b770-d257d86f571d', 'volumeID': '0b09c5f5-8d87-4113-a083-c006acb2117e', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'specParams': {}, 'readonly': 'false', 'domainID': '6c0d651a-1d85-4673-959c-2a271fb5e07d', 'deviceId': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1A:4A:98:6A:1F', 'linkActive': 'true', 'network': 'Internal', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {'average': 128000, 'peak': 128000, 'burst': 102400}, 'outbound': {'average': 128000, 'peak': 128000, 'burst': 102400}}, 'deviceId': '05ea7c1c-a1da-4205-b481-9ec39d195e7e', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'nicModel': 'pv', 'macAddr': '00:1A:4A:FD:F4:06', 'linkActive': 'true', 'network': '', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '1e2ef1ff-65c9-4fb8-9a8e-5af43384e3b9', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'index': '0', 'specParams': {}, 'deviceId': '0bf6c8bc-5845-49d6-b0ea-ed5e832cfd2a', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'device': 'virtio-serial', 'specParams': {}, 'type': 'controller', 'deviceId': '01e0d37d-2f16-4e43-81a4-eb8e3c3a87e9'}], 'timeOffset': '28800', 'maxVCpus': '16', 'clientIp': '', 'display': 'vnc'}} Thread-727::DEBUG::2014-11-27 15:53:15,260::vm::2263::vm.Vm::(_startUnderlyingVm) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::_ongoingCreations acquired Thread-727::INFO::2014-11-27 15:53:15,262::vm::3299::vm.Vm::(_run) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::VM wrapper has started Thread-727::DEBUG::2014-11-27 15:53:15,265::task::595::Storage.TaskManager.Task::(_updateState) Task=`c0e92275-982f-49a6-b758-322f097b8ef0`::moving from state init -> state preparing Thread-727::INFO::2014-11-27 15:53:15,267::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='6c0d651a-1d85-4673-959c-2a271fb5e07d', spUUID='5b5a6f6c-4c1b-4451-b770-d257d86f571d', imgUUID='1f31a58b-0c49-4a5e-960a-3fd8474b89ed', volUUID='0b09c5f5-8d87-4113-a083-c006acb2117e', options=None) ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,269::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,270::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,272::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,273::__init__::375::IOProcess::(_processLogs) (19211) Got request for method 'stat' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,289::__init__::375::IOProcess::(_processLogs) (19211) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,290::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,291::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-727::INFO::2014-11-27 15:53:15,291::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1054048256', 'apparentsize': '21474836480'} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,292::__init__::375::IOProcess::(_processLogs) Extracting request information... Thread-727::DEBUG::2014-11-27 15:53:15,292::task::1191::Storage.TaskManager.Task::(prepare) Task=`c0e92275-982f-49a6-b758-322f097b8ef0`::finished: {'truesize': '1054048256', 'apparentsize': '21474836480'} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,293::__init__::375::IOProcess::(_processLogs) (19212) Got request for method 'stat' Thread-727::DEBUG::2014-11-27 15:53:15,293::task::595::Storage.TaskManager.Task::(_updateState) Task=`c0e92275-982f-49a6-b758-322f097b8ef0`::moving from state preparing -> state finished ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,294::__init__::375::IOProcess::(_processLogs) (19212) Queuing response Thread-727::DEBUG::2014-11-27 15:53:15,294::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-727::DEBUG::2014-11-27 15:53:15,295::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-727::DEBUG::2014-11-27 15:53:15,295::task::993::Storage.TaskManager.Task::(_decref) Task=`c0e92275-982f-49a6-b758-322f097b8ef0`::ref 0 aborting False Thread-727::INFO::2014-11-27 15:53:15,410::clientIF::331::vds::(prepareVolumePath) prepared volume path: /var/run/vdsm/payload/ad162ac5-f781-4e2d-a066-02409bee2eb5.a6f2c7a13a5e1fca3b25a80d843d8b67.img Thread-727::INFO::2014-11-27 15:53:15,410::clientIF::331::vds::(prepareVolumePath) prepared volume path: Thread-727::DEBUG::2014-11-27 15:53:15,411::task::595::Storage.TaskManager.Task::(_updateState) Task=`61781916-7ae8-4f09-a2c8-5cd145b82dd8`::moving from state init -> state preparing Thread-727::INFO::2014-11-27 15:53:15,411::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='6c0d651a-1d85-4673-959c-2a271fb5e07d', spUUID='5b5a6f6c-4c1b-4451-b770-d257d86f571d', imgUUID='1f31a58b-0c49-4a5e-960a-3fd8474b89ed', leafUUID='0b09c5f5-8d87-4113-a083-c006acb2117e') Thread-727::DEBUG::2014-11-27 15:53:15,412::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d`ReqID=`182a7624-7ed7-4521-a6cd-7f64cd01cc33`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3210' at 'prepareImage' Thread-727::DEBUG::2014-11-27 15:53:15,412::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d' for lock type 'shared' Thread-727::DEBUG::2014-11-27 15:53:15,412::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d' is free. Now locking as 'shared' (1 active user) Thread-727::DEBUG::2014-11-27 15:53:15,412::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d`ReqID=`182a7624-7ed7-4521-a6cd-7f64cd01cc33`::Granted request Thread-727::DEBUG::2014-11-27 15:53:15,413::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`61781916-7ae8-4f09-a2c8-5cd145b82dd8`::_resourcesAcquired: Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d (shared) Thread-727::DEBUG::2014-11-27 15:53:15,413::task::993::Storage.TaskManager.Task::(_decref) Task=`61781916-7ae8-4f09-a2c8-5cd145b82dd8`::ref 1 aborting False ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,414::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,414::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,414::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,415::__init__::375::IOProcess::(_processLogs) (19213) Got request for method 'glob' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,675::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,675::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,675::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,676::__init__::375::IOProcess::(_processLogs) (19214) Got request for method 'statvfs ioprocess communication (12110)::DEBUG::2014-11-27 15:53:15,996::__init__::375::IOProcess::(_processLogs) (19214) Queuing response Thread-172::DEBUG::2014-11-27 15:53:15,997::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-172::DEBUG::2014-11-27 15:53:16,020::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n328 bytes (328 B) copied, 0.000478162 s, 686 kB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,021::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,021::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,021::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,021::__init__::375::IOProcess::(_processLogs) (19215) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,023::__init__::375::IOProcess::(_processLogs) (19215) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,024::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,024::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,025::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,025::__init__::375::IOProcess::(_processLogs) (19216) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,029::__init__::375::IOProcess::(_processLogs) (19216) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,029::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,030::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,030::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,030::__init__::375::IOProcess::(_processLogs) (19217) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,037::__init__::375::IOProcess::(_processLogs) (19217) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,038::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,038::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,038::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,039::__init__::375::IOProcess::(_processLogs) (19218) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,042::__init__::375::IOProcess::(_processLogs) (19218) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,094::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,094::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,095::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,095::__init__::375::IOProcess::(_processLogs) (19219) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,095::__init__::375::IOProcess::(_processLogs) (19219) Queuing response Thread-168::DEBUG::2014-11-27 15:53:16,096::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/43.252.176.12:_var_lib_exports_templates1/4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-168::DEBUG::2014-11-27 15:53:16,108::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000468886 s, 774 kB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,109::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,109::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,109::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,110::__init__::375::IOProcess::(_processLogs) (19220) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,110::__init__::375::IOProcess::(_processLogs) (19220) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,518::__init__::375::IOProcess::(_processLogs) (19213) Queuing response Thread-727::DEBUG::2014-11-27 15:53:16,520::fileSD::499::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,521::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,521::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,521::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,521::__init__::375::IOProcess::(_processLogs) (19221) Got request for method 'stat' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,522::__init__::375::IOProcess::(_processLogs) (19221) Queuing response Thread-727::DEBUG::2014-11-27 15:53:16,523::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/6c0d651a-1d85-4673-959c-2a271fb5e07d Thread-727::WARNING::2014-11-27 15:53:16,523::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/6c0d651a-1d85-4673-959c-2a271fb5e07d already exists Thread-727::DEBUG::2014-11-27 15:53:16,523::fileSD::474::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed to /var/run/vdsm/storage/6c0d651a-1d85-4673-959c-2a271fb5e07d/1f31a58b-0c49-4a5e-960a-3fd8474b89ed ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,524::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,524::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,525::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,525::__init__::375::IOProcess::(_processLogs) (19222) Got request for method 'stat' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,526::__init__::375::IOProcess::(_processLogs) (19222) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,526::__init__::375::IOProcess::(_processLogs) Receiving request... Thread-727::DEBUG::2014-11-27 15:53:16,526::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 0b09c5f5-8d87-4113-a083-c006acb2117e ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,527::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,528::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,528::__init__::375::IOProcess::(_processLogs) (19223) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,528::__init__::375::IOProcess::(_processLogs) (19223) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,528::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,529::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,530::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,530::__init__::375::IOProcess::(_processLogs) (19224) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,530::__init__::375::IOProcess::(_processLogs) (19224) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,530::__init__::375::IOProcess::(_processLogs) Receiving request... Thread-727::INFO::2014-11-27 15:53:16,531::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '6c0d651a-1d85-4673-959c-2a271fb5e07d', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', 'volumeID': u'0b09c5f5-8d87-4113-a083-c006acb2117e', 'leasePath': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e.lease', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed'}, 'path': u'/rhev/data-center/5b5a6f6c-4c1b-4451-b770-d257d86f571d/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', 'imgVolumesInfo': [{'domainID': '6c0d651a-1d85-4673-959c-2a271fb5e07d', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', 'volumeID': u'0b09c5f5-8d87-4113-a083-c006acb2117e', 'leasePath': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e.lease', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed'}]} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,531::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-727::DEBUG::2014-11-27 15:53:16,532::task::1191::Storage.TaskManager.Task::(prepare) Task=`61781916-7ae8-4f09-a2c8-5cd145b82dd8`::finished: {'info': {'domainID': '6c0d651a-1d85-4673-959c-2a271fb5e07d', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', 'volumeID': u'0b09c5f5-8d87-4113-a083-c006acb2117e', 'leasePath': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e.lease', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed'}, 'path': u'/rhev/data-center/5b5a6f6c-4c1b-4451-b770-d257d86f571d/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', 'imgVolumesInfo': [{'domainID': '6c0d651a-1d85-4673-959c-2a271fb5e07d', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', 'volumeID': u'0b09c5f5-8d87-4113-a083-c006acb2117e', 'leasePath': u'/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e.lease', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed'}]} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,532::__init__::375::IOProcess::(_processLogs) Extracting request information... Thread-727::DEBUG::2014-11-27 15:53:16,533::task::595::Storage.TaskManager.Task::(_updateState) Task=`61781916-7ae8-4f09-a2c8-5cd145b82dd8`::moving from state preparing -> state finished Thread-727::DEBUG::2014-11-27 15:53:16,534::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d': < ResourceRef 'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d', isValid: 'True' obj: 'None'>} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,534::__init__::375::IOProcess::(_processLogs) (19225) Got request for method 'access' Thread-727::DEBUG::2014-11-27 15:53:16,534::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:16,535::__init__::375::IOProcess::(_processLogs) (19225) Queuing response Thread-727::DEBUG::2014-11-27 15:53:16,536::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d' Thread-727::DEBUG::2014-11-27 15:53:16,537::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d' (0 active users) Thread-727::DEBUG::2014-11-27 15:53:16,537::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d' is free, finding out if anyone is waiting for it. Thread-727::DEBUG::2014-11-27 15:53:16,537::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.6c0d651a-1d85-4673-959c-2a271fb5e07d', Clearing records. Thread-727::DEBUG::2014-11-27 15:53:16,537::task::993::Storage.TaskManager.Task::(_decref) Task=`61781916-7ae8-4f09-a2c8-5cd145b82dd8`::ref 0 aborting False Thread-727::INFO::2014-11-27 15:53:16,537::clientIF::331::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/5b5a6f6c-4c1b-4451-b770-d257d86f571d/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e Thread-727::DEBUG::2014-11-27 15:53:16,574::vm::3333::vm.Vm::(_run) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`:: 7c7aa9dedb57248f5da291117164f0d7 ad162ac5-f781-4e2d-a066-02409bee2eb5 524288 524288 16
1f31a58b-0c49-4a5e-960a-3fd8474b89ed hvm oVirt oVirt Node 7-0.1406.el7.centos.2.5 4E618D6B-7BD0-1000-83BC-C454448FCAD4 ad162ac5-f781-4e2d-a066-02409bee2eb5 SandyBridge libvirtEventLoop::DEBUG::2014-11-27 15:53:17,453::vm::5461::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::event Started detail 0 opaque None Thread-727::DEBUG::2014-11-27 15:53:17,485::vm::5301::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Looking for drive with attributes {'name': u'hdc', 'bootOrder': u'2', 'boot': [], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path': '', 'type': u'cdrom'} Thread-727::DEBUG::2014-11-27 15:53:17,485::vm::5322::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': (u'2', u'2'), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', u'cdrom')} Thread-727::DEBUG::2014-11-27 15:53:17,485::vm::5341::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Matched {'name': (u'hdc', None), 'bootOrder': (u'2', None), 'boot': ([], None), 'readonly': (True, None), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, None), 'path': ('', None), 'type': (u'cdrom', None)} Thread-727::DEBUG::2014-11-27 15:53:17,486::vm::5301::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Looking for drive with attributes {'name': u'hdd', 'bootOrder': u'1', 'boot': [], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'1'}, 'path': u'/var/run/vdsm/payload/ad162ac5-f781-4e2d-a066-02409bee2eb5.a6f2c7a13a5e1fca3b25a80d843d8b67.img', 'type': u'cdrom'} Thread-727::DEBUG::2014-11-27 15:53:17,486::vm::5322::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Matched {'name': (u'hdd', u'hdd'), 'bootOrder': (u'1', u'1'), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'1'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'1'}), 'path': (u'/var/run/vdsm/payload/ad162ac5-f781-4e2d-a066-02409bee2eb5.a6f2c7a13a5e1fca3b25a80d843d8b67.img', '/var/run/vdsm/payload/ad162ac5-f781-4e2d-a066-02409bee2eb5.a6f2c7a13a5e1fca3b25a80d843d8b67.img'), 'type': (u'cdrom', u'cdrom')} Thread-727::DEBUG::2014-11-27 15:53:17,487::vm::5341::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Matched {'name': (u'hdd', None), 'bootOrder': (u'1', None), 'boot': ([], None), 'readonly': (True, None), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'1'}, None), 'path': (u'/var/run/vdsm/payload/ad162ac5-f781-4e2d-a066-02409bee2eb5.a6f2c7a13a5e1fca3b25a80d843d8b67.img', None), 'type': (u'cdrom', None)} Thread-727::DEBUG::2014-11-27 15:53:17,487::vm::5301::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Looking for drive with attributes {'name': u'vda', 'bootOrder': '', 'boot': [], 'readonly': False, 'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/rhev/data-center/5b5a6f6c-4c1b-4451-b770-d257d86f571d/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', 'type': u'disk'} Thread-727::DEBUG::2014-11-27 15:53:17,487::vm::5322::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Matched {'name': (u'vda', u'vda'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (False, False), 'address': ({u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/rhev/data-center/5b5a6f6c-4c1b-4451-b770-d257d86f571d/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', u'/rhev/data-center/5b5a6f6c-4c1b-4451-b770-d257d86f571d/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e'), 'type': (u'disk', u'disk')} Thread-727::DEBUG::2014-11-27 15:53:17,488::vm::5341::vm.Vm::(_getUnderlyingDriveInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Matched {'name': (u'vda', None), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (False, None), 'address': ({u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, None), 'path': (u'/rhev/data-center/5b5a6f6c-4c1b-4451-b770-d257d86f571d/6c0d651a-1d85-4673-959c-2a271fb5e07d/images/1f31a58b-0c49-4a5e-960a-3fd8474b89ed/0b09c5f5-8d87-4113-a083-c006acb2117e', None), 'type': (u'disk', None)} Thread-727::DEBUG::2014-11-27 15:53:17,580::sampling::405::vm.Vm::(start) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Start statistics collection Thread-729::DEBUG::2014-11-27 15:53:17,580::sampling::434::vm.Vm::(run) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Stats thread started Thread-727::DEBUG::2014-11-27 15:53:17,582::vmchannels::199::vds::(register) Add fileno 40 to listener's channels. Thread-729::DEBUG::2014-11-27 15:53:17,582::task::595::Storage.TaskManager.Task::(_updateState) Task=`6e852c00-3262-4c61-92ed-8e06e5f90be5`::moving from state init -> state preparing Thread-729::INFO::2014-11-27 15:53:17,583::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='6c0d651a-1d85-4673-959c-2a271fb5e07d', spUUID='5b5a6f6c-4c1b-4451-b770-d257d86f571d', imgUUID='1f31a58b-0c49-4a5e-960a-3fd8474b89ed', volUUID='0b09c5f5-8d87-4113-a083-c006acb2117e', options=None) Thread-727::WARNING::2014-11-27 15:53:17,584::vm::3971::vm.Vm::(_readPauseCode) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::_readPauseCode unsupported by libvirt vm ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,585::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,586::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,586::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,586::__init__::375::IOProcess::(_processLogs) (19226) Got request for method 'stat' Thread-727::DEBUG::2014-11-27 15:53:17,589::vm::2289::vm.Vm::(_startUnderlyingVm) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::_ongoingCreations released ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,600::__init__::375::IOProcess::(_processLogs) (19226) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,603::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,605::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,606::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,607::__init__::375::IOProcess::(_processLogs) (19227) Got request for method 'stat' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:17,608::__init__::375::IOProcess::(_processLogs) (19227) Queuing response Thread-729::INFO::2014-11-27 15:53:17,609::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1054048256', 'apparentsize': '21474836480'} Thread-729::DEBUG::2014-11-27 15:53:17,611::task::1191::Storage.TaskManager.Task::(prepare) Task=`6e852c00-3262-4c61-92ed-8e06e5f90be5`::finished: {'truesize': '1054048256', 'apparentsize': '21474836480'} Thread-729::DEBUG::2014-11-27 15:53:17,611::task::595::Storage.TaskManager.Task::(_updateState) Task=`6e852c00-3262-4c61-92ed-8e06e5f90be5`::moving from state preparing -> state finished Thread-729::DEBUG::2014-11-27 15:53:17,612::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-729::DEBUG::2014-11-27 15:53:17,613::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-729::DEBUG::2014-11-27 15:53:17,614::task::993::Storage.TaskManager.Task::(_decref) Task=`6e852c00-3262-4c61-92ed-8e06e5f90be5`::ref 0 aborting False VM Channels Listener::DEBUG::2014-11-27 15:53:18,270::vmchannels::107::vds::(_do_add_channels) fileno 40 was added to unconnected channels. VM Channels Listener::DEBUG::2014-11-27 15:53:18,270::vmchannels::133::vds::(_handle_unconnected) Trying to connect fileno 40. VM Channels Listener::DEBUG::2014-11-27 15:53:18,270::guestagent::200::vm.Vm::(_connect) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Attempting connection to /var/lib/libvirt/qemu/channels/ad162ac5-f781-4e2d-a066-02409bee2eb5.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2014-11-27 15:53:18,270::guestagent::203::vm.Vm::(_connect) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Connected to /var/lib/libvirt/qemu/channels/ad162ac5-f781-4e2d-a066-02409bee2eb5.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2014-11-27 15:53:18,271::vmchannels::149::vds::(_handle_unconnected) Connecting to fileno 40 succeeded. Thread-670::DEBUG::2014-11-27 15:53:18,783::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmGetStats with ('ad162ac5-f781-4e2d-a066-02409bee2eb5',) {} Thread-670::DEBUG::2014-11-27 15:53:18,784::BindingXMLRPC::1139::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'displayInfo': [{'tlsPort': '-1', 'ipAddress': '43.252.177.19', 'type': 'vnc', 'port': u'5900'}], 'hash': '-1183409230156560438', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '33919', 'displayIp': '43.252.177.19', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '28800', 'memUsage': '0', 'balloonInfo': {'balloon_max': '524288', 'balloon_target': '0', 'balloon_cur': '0', 'balloon_min': '524288'}, 'pauseCode': 'NOERR', 'clientIp': '', 'elapsedTime': '3', 'kvmEnable': 'true', 'network': {}, 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'vmType': 'kvm', 'cpuUser': '0.00', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLatency': '0', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'flushLatency': '0', 'truesize': '1054048256'}, u'hdd': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '1.20', 'username': 'Unknown', 'displayType': 'vnc', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]} Thread-670::DEBUG::2014-11-27 15:53:21,839::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmGetStats with ('ad162ac5-f781-4e2d-a066-02409bee2eb5',) {} Thread-670::DEBUG::2014-11-27 15:53:21,839::BindingXMLRPC::1139::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'displayInfo': [{'tlsPort': '-1', 'ipAddress': '43.252.177.19', 'type': 'vnc', 'port': u'5900'}], 'hash': '-1183409230156560438', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '33919', 'displayIp': '43.252.177.19', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '28800', 'memUsage': '0', 'balloonInfo': {'balloon_max': '524288', 'balloon_target': '0', 'balloon_cur': '0', 'balloon_min': '524288'}, 'pauseCode': 'NOERR', 'clientIp': '', 'elapsedTime': '6', 'kvmEnable': 'true', 'network': {}, 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'vmType': 'kvm', 'cpuUser': '0.00', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLatency': '0', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'flushLatency': '0', 'truesize': '1054048256'}, u'hdd': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.19', 'username': 'Unknown', 'displayType': 'vnc', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,125::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,126::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,126::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,126::__init__::375::IOProcess::(_processLogs) (19228) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,126::__init__::375::IOProcess::(_processLogs) (19228) Queuing response Thread-167::DEBUG::2014-11-27 15:53:24,127::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/ccr01.zne01.hkg1.ovt.36stack.com:_var_lib_exports_iso/ecebbb0b-a442-4e95-a5c2-e421616d81de/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-167::DEBUG::2014-11-27 15:53:24,141::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n375 bytes (375 B) copied, 0.00031615 s, 1.2 MB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,141::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,142::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,142::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,142::__init__::375::IOProcess::(_processLogs) (19229) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:24,142::__init__::375::IOProcess::(_processLogs) (19229) Queuing response Thread-670::DEBUG::2014-11-27 15:53:24,868::task::595::Storage.TaskManager.Task::(_updateState) Task=`46c8b0b9-069f-4630-9fb8-98c23f65bcad`::moving from state init -> state preparing Thread-670::INFO::2014-11-27 15:53:24,869::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-670::INFO::2014-11-27 15:53:24,869::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ecebbb0b-a442-4e95-a5c2-e421616d81de': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00031615', 'lastCheck': '0.7', 'valid': True}, '4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000468886', 'lastCheck': '8.8', 'valid': True}, '6c0d651a-1d85-4673-959c-2a271fb5e07d': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000478162', 'lastCheck': '8.8', 'valid': True}} Thread-670::DEBUG::2014-11-27 15:53:24,870::task::1191::Storage.TaskManager.Task::(prepare) Task=`46c8b0b9-069f-4630-9fb8-98c23f65bcad`::finished: {'ecebbb0b-a442-4e95-a5c2-e421616d81de': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00031615', 'lastCheck': '0.7', 'valid': True}, '4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000468886', 'lastCheck': '8.8', 'valid': True}, '6c0d651a-1d85-4673-959c-2a271fb5e07d': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000478162', 'lastCheck': '8.8', 'valid': True}} Thread-670::DEBUG::2014-11-27 15:53:24,870::task::595::Storage.TaskManager.Task::(_updateState) Task=`46c8b0b9-069f-4630-9fb8-98c23f65bcad`::moving from state preparing -> state finished Thread-670::DEBUG::2014-11-27 15:53:24,870::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-670::DEBUG::2014-11-27 15:53:24,870::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-670::DEBUG::2014-11-27 15:53:24,870::task::993::Storage.TaskManager.Task::(_decref) Task=`46c8b0b9-069f-4630-9fb8-98c23f65bcad`::ref 0 aborting False ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,044::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,044::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,044::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,044::__init__::375::IOProcess::(_processLogs) (19230) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,056::__init__::375::IOProcess::(_processLogs) (19230) Queuing response Thread-172::DEBUG::2014-11-27 15:53:26,057::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-172::DEBUG::2014-11-27 15:53:26,072::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n328 bytes (328 B) copied, 0.00053843 s, 609 kB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,073::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,073::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,073::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,073::__init__::375::IOProcess::(_processLogs) (19231) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,075::__init__::375::IOProcess::(_processLogs) (19231) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,075::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,076::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,076::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,076::__init__::375::IOProcess::(_processLogs) (19232) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,080::__init__::375::IOProcess::(_processLogs) (19232) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,080::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,081::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-168::DEBUG::2014-11-27 15:53:26,113::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/43.252.176.12:_var_lib_exports_templates1/4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-168::DEBUG::2014-11-27 15:53:26,123::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000506673 s, 716 kB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,124::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,124::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,124::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,124::__init__::375::IOProcess::(_processLogs) (19236) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:26,125::__init__::375::IOProcess::(_processLogs) (19236) Queuing response Thread-670::DEBUG::2014-11-27 15:53:27,947::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmGetStats with ('ad162ac5-f781-4e2d-a066-02409bee2eb5',) {} Thread-670::DEBUG::2014-11-27 15:53:27,948::BindingXMLRPC::1139::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'displayInfo': [{'tlsPort': '-1', 'ipAddress': '43.252.177.19', 'type': 'vnc', 'port': u'5900'}], 'hash': '-1183409230156560438', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '33919', 'displayIp': '43.252.177.19', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '28800', 'memUsage': '0', 'balloonInfo': {'balloon_max': '524288', 'balloon_target': '0', 'balloon_cur': '0', 'balloon_min': '524288'}, 'pauseCode': 'NOERR', 'clientIp': '', 'elapsedTime': '12', 'kvmEnable': 'true', 'network': {}, 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'vmType': 'kvm', 'cpuUser': '0.00', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLatency': '0', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'flushLatency': '0', 'truesize': '1054048256'}, u'hdd': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.30', 'username': 'Unknown', 'displayType': 'vnc', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]} Thread-670::DEBUG::2014-11-27 15:53:30,979::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmGetStats with ('ad162ac5-f781-4e2d-a066-02409bee2eb5',) {} Thread-670::DEBUG::2014-11-27 15:53:30,980::BindingXMLRPC::1139::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'displayInfo': [{'tlsPort': '-1', 'ipAddress': '43.252.177.19', 'type': 'vnc', 'port': u'5900'}], 'hash': '-1183409230156560438', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '33919', 'displayIp': '43.252.177.19', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '28800', 'memUsage': '0', 'balloonInfo': {'balloon_max': '524288', 'balloon_target': '0', 'balloon_cur': '0', 'balloon_min': '524288'}, 'pauseCode': 'NOERR', 'clientIp': '', 'elapsedTime': '15', 'kvmEnable': 'true', 'network': {}, 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'vmType': 'kvm', 'cpuUser': '0.00', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLatency': '0', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'flushLatency': '0', 'truesize': '1054048256'}, u'hdd': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '1.33', 'username': 'Unknown', 'displayType': 'vnc', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]} Thread-670::DEBUG::2014-11-27 15:53:34,012::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmGetStats with ('ad162ac5-f781-4e2d-a066-02409bee2eb5',) {} Thread-670::DEBUG::2014-11-27 15:53:34,013::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set Thread-670::DEBUG::2014-11-27 15:53:34,014::BindingXMLRPC::1139::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'displayInfo': [{'tlsPort': '-1', 'ipAddress': '43.252.177.19', 'type': 'vnc', 'port': u'5900'}], 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '33919', 'session': 'Unknown', 'vmType': 'kvm', 'timeOffset': '28800', 'balloonInfo': {'balloon_max': '524288', 'balloon_target': '0', 'balloon_cur': '524288', 'balloon_min': '524288'}, 'pauseCode': 'NOERR', 'network': {u'vnet0': {'macAddr': '00:1A:4A:98:6A:1F', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}, u'vnet1': {'macAddr': '00:1A:4A:FD:F4:06', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet1'}}, 'vmJobs': {}, 'cpuUser': '0.69', 'elapsedTime': '18', 'displayType': 'vnc', 'cpuSys': '1.40', 'appsList': [], 'vcpuCount': '1', 'clientIp': '', 'hash': '-1183409230156560438', 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'displayIp': '43.252.177.19', 'vcpuPeriod': 100000L, 'displayPort': u'5900', 'vcpuQuota': '-1', 'kvmEnable': 'true', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLatency': '0', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'flushLatency': '0', 'truesize': '1054048256'}, u'hdd': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.35', 'username': 'Unknown', 'status': 'Powering up', 'guestCPUCount': -1, 'guestIPs': '', 'displaySecurePort': '-1'}]} ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,144::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,145::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,145::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,145::__init__::375::IOProcess::(_processLogs) (19237) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,146::__init__::375::IOProcess::(_processLogs) (19237) Queuing response Thread-167::DEBUG::2014-11-27 15:53:34,147::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/ccr01.zne01.hkg1.ovt.36stack.com:_var_lib_exports_iso/ecebbb0b-a442-4e95-a5c2-e421616d81de/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-167::DEBUG::2014-11-27 15:53:34,164::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n375 bytes (375 B) copied, 0.000395992 s, 947 kB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,165::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,165::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,165::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,166::__init__::375::IOProcess::(_processLogs) (19238) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:34,166::__init__::375::IOProcess::(_processLogs) (19238) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,091::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,091::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,091::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,091::__init__::375::IOProcess::(_processLogs) (19239) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,102::__init__::375::IOProcess::(_processLogs) (19239) Queuing response Thread-172::DEBUG::2014-11-27 15:53:36,103::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/10.10.0.7:_vol1/6c0d651a-1d85-4673-959c-2a271fb5e07d/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-172::DEBUG::2014-11-27 15:53:36,122::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n328 bytes (328 B) copied, 0.000686312 s, 478 kB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,123::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,124::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,124::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,124::__init__::375::IOProcess::(_processLogs) (19240) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,125::__init__::375::IOProcess::(_processLogs) (19240) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,128::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,128::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,128::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,128::__init__::375::IOProcess::(_processLogs) (19241) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,129::__init__::375::IOProcess::(_processLogs) (19241) Queuing response Thread-168::DEBUG::2014-11-27 15:53:36,130::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/43.252.176.12:_var_lib_exports_templates1/4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,131::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,145::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,145::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,145::__init__::375::IOProcess::(_processLogs) (19242) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,147::__init__::375::IOProcess::(_processLogs) (19242) Queuing response Thread-168::DEBUG::2014-11-27 15:53:36,148::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000524206 s, 692 kB/s\n'; = 0 ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,149::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,149::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,150::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,150::__init__::375::IOProcess::(_processLogs) (19243) Got request for method 'access' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,150::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,150::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,150::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,151::__init__::375::IOProcess::(_processLogs) (19244) Got request for method 'statvfs' ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,151::__init__::375::IOProcess::(_processLogs) (19244) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,153::__init__::375::IOProcess::(_processLogs) (19243) Queuing response ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,154::__init__::375::IOProcess::(_processLogs) Receiving request... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,154::__init__::375::IOProcess::(_processLogs) Queuing request in the thread pool... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,154::__init__::375::IOProcess::(_processLogs) Extracting request information... ioprocess communication (12110)::DEBUG::2014-11-27 15:53:36,154::__init__::375::IOProcess::(_processLogs) (19245) Got request for method 'access' Thread-670::DEBUG::2014-11-27 15:53:37,046::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmGetStats with ('ad162ac5-f781-4e2d-a066-02409bee2eb5',) {} Thread-670::DEBUG::2014-11-27 15:53:37,047::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set Thread-670::DEBUG::2014-11-27 15:53:37,048::BindingXMLRPC::1139::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'displayInfo': [{'tlsPort': '-1', 'ipAddress': '43.252.177.19', 'type': 'vnc', 'port': u'5900'}], 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '33919', 'session': 'Unknown', 'vmType': 'kvm', 'timeOffset': '28800', 'balloonInfo': {'balloon_max': '524288', 'balloon_target': '0', 'balloon_cur': '524288', 'balloon_min': '524288'}, 'pauseCode': 'NOERR', 'network': {u'vnet0': {'macAddr': '00:1A:4A:98:6A:1F', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}, u'vnet1': {'macAddr': '00:1A:4A:FD:F4:06', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet1'}}, 'vmJobs': {}, 'cpuUser': '0.69', 'elapsedTime': '21', 'displayType': 'vnc', 'cpuSys': '1.40', 'appsList': [], 'vcpuCount': '1', 'clientIp': '', 'hash': '-1183409230156560438', 'vmId': 'ad162ac5-f781-4e2d-a066-02409bee2eb5', 'displayIp': '43.252.177.19', 'vcpuPeriod': 100000L, 'displayPort': u'5900', 'vcpuQuota': '-1', 'kvmEnable': 'true', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLatency': '0', 'imageID': '1f31a58b-0c49-4a5e-960a-3fd8474b89ed', 'flushLatency': '0', 'truesize': '1054048256'}, u'hdd': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'truesize': '0', 'apparentsize': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '1.38', 'username': 'Unknown', 'status': 'Powering up', 'guestCPUCount': -1, 'guestIPs': '', 'displaySecurePort': '-1'}]} GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:37,397::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:37,398::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:37,399::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set Thread-670::DEBUG::2014-11-27 15:53:40,077::task::595::Storage.TaskManager.Task::(_updateState) Task=`9df6db1c-b1d5-4b4b-acf3-dca559a1a7cf`::moving from state init -> state preparing Thread-670::INFO::2014-11-27 15:53:40,078::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-670::INFO::2014-11-27 15:53:40,078::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ecebbb0b-a442-4e95-a5c2-e421616d81de': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000395992', 'lastCheck': '5.9', 'valid': True}, '4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000524206', 'lastCheck': '3.9', 'valid': True}, '6c0d651a-1d85-4673-959c-2a271fb5e07d': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000686312', 'lastCheck': '3.9', 'valid': True}} Thread-670::DEBUG::2014-11-27 15:53:40,078::task::1191::Storage.TaskManager.Task::(prepare) Task=`9df6db1c-b1d5-4b4b-acf3-dca559a1a7cf`::finished: {'ecebbb0b-a442-4e95-a5c2-e421616d81de': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000395992', 'lastCheck': '5.9', 'valid': True}, '4b7c7f94-2cee-4fdc-9153-c2f8cd1f7c6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000524206', 'lastCheck': '3.9', 'valid': True}, '6c0d651a-1d85-4673-959c-2a271fb5e07d': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000686312', 'lastCheck': '3.9', 'valid': True}} Thread-670::DEBUG::2014-11-27 15:53:40,079::task::595::Storage.TaskManager.Task::(_updateState) Task=`9df6db1c-b1d5-4b4b-acf3-dca559a1a7cf`::moving from state preparing -> state finished Thread-670::DEBUG::2014-11-27 15:53:40,079::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-670::DEBUG::2014-11-27 15:53:40,079::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-670::DEBUG::2014-11-27 15:53:40,079::task::993::Storage.TaskManager.Task::(_decref) Task=`9df6db1c-b1d5-4b4b-acf3-dca559a1a7cf`::ref 0 aborting False Thread-670::DEBUG::2014-11-27 15:53:40,106::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:42,406::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:42,407::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:42,408::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set Thread-670::DEBUG::2014-11-27 15:53:43,152::BindingXMLRPC::1132::vds::(wrapper) client [10.10.0.4]::call vmGetStats with ('ad162ac5-f781-4e2d-a066-02409bee2eb5',) {} Thread-670::DEBUG::2014-11-27 15:53:43,152::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:42,406::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:42,407::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set GuestMonitor-7c7aa9dedb57248f5da291117164f0d7::DEBUG::2014-11-27 15:53:42,408::vm::486::vm.Vm::(_getUserCpuTuneInfo) vmId=`ad162ac5-f781-4e2d-a066-02409bee2eb5`::Domain Metadata is not set