Attachment 604499 Details for Bug 848266 – vdsm log when trying to start VM after upgrade

vdsm log when trying to start VM after upgrade

vdsm.log (text/plain), 23.91 KB, created by Chao Yang on 2012-08-15 04:41:46 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Chao Yang

Created: 2012-08-15 04:41:46 UTC

Size: 23.91 KB

patch

obsolete

>Thread-26::DEBUG::2012-08-15 11:33:36,720::task::588::TaskManager.Task::(_updateState) Task=`8954bf83-4be5-4839-82a0-64f7e74d125f`::moving from state preparing -> state finished
>Thread-26::DEBUG::2012-08-15 11:33:36,721::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-26::DEBUG::2012-08-15 11:33:36,721::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-26::DEBUG::2012-08-15 11:33:36,721::task::978::TaskManager.Task::(_decref) Task=`8954bf83-4be5-4839-82a0-64f7e74d125f`::ref 0 aborting False
>Thread-15::DEBUG::2012-08-15 11:33:41,383::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata bs=4096 count=1' (cwd None)
>Thread-15::DEBUG::2012-08-15 11:33:41,392::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000735824 s, 5.6 MB/s\n'; <rc> = 0
>Thread-15::DEBUG::2012-08-15 11:33:51,395::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata bs=4096 count=1' (cwd None)
>Thread-15::DEBUG::2012-08-15 11:33:51,403::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000735976 s, 5.6 MB/s\n'; <rc> = 0
>Thread-15::DEBUG::2012-08-15 11:34:01,406::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata bs=4096 count=1' (cwd None)
>Thread-15::DEBUG::2012-08-15 11:34:01,415::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000741221 s, 5.5 MB/s\n'; <rc> = 0
>Thread-15::DEBUG::2012-08-15 11:34:11,419::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata bs=4096 count=1' (cwd None)
>Thread-15::DEBUG::2012-08-15 11:34:11,427::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000886854 s, 4.6 MB/s\n'; <rc> = 0
>Thread-15::DEBUG::2012-08-15 11:34:21,431::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata bs=4096 count=1' (cwd None)
>Thread-15::DEBUG::2012-08-15 11:34:21,439::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000697159 s, 5.9 MB/s\n'; <rc> = 0
>Thread-31::DEBUG::2012-08-15 11:34:28,782::BindingXMLRPC::864::vds::(wrapper) client [10.66.4.148]::call vmCreate with ({'custom': {'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73device_0f6eb766-3a1d-43a6-b487-a861053407f5': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=0f6eb766-3a1d-43a6-b487-a861053407f5,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=1, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=ecbbe624-f409-4b67-ad54-3e5b6e7eef73,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=cc02340a-9bf9-42ac-a4aa-91a603849a43,Device=ide,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73device_0f6eb766-3a1d-43a6-b487-a861053407f5device_68dc2a6e-7731-47b7-b677-5b3cf7bc95addevice_1b419824-7579-4aa4-a0e2-01650399bf8d': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=1b419824-7579-4aa4-a0e2-01650399bf8d,Device=usb,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73device_0f6eb766-3a1d-43a6-b487-a861053407f5device_68dc2a6e-7731-47b7-b677-5b3cf7bc95ad': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=68dc2a6e-7731-47b7-b677-5b3cf7bc95ad,Device=spicevmc,Type=channel,BootOrder=0,SpecParams={},Address={port=2, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.3.0', 'vmId': '2445ad59-8c84-4315-9119-3f2f4820b946', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '8d15514f-b1fb-4030-8d27-970dda91b135', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '87bd229f-1980-4ac5-b6c8-dfc0da3a28a4', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'cow', 'bootOrder': '1', 'poolID': 'a9814774-ab07-46a9-abf8-e42a2fbf8f33', 'volumeID': '2961837b-6ff5-415c-98d2-030f5369ddb6', 'imageID': 'af0957a7-1499-4ba5-9e75-a4685a55c55d', 'specParams': {}, 'readonly': 'false', 'domainID': '9e871461-44df-4044-87ed-10a70e94758c', 'optional': 'false', 'deviceId': 'af0957a7-1499-4ba5-9e75-a4685a55c55d', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:42:04:0b', 'network': 'rhevm', 'specParams': {}, 'deviceId': '2deba7d4-4232-424f-9c62-acb4c66bda0d', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'portMirroring': ['rhevm']}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '1b419824-7579-4aa4-a0e2-01650399bf8d', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '5146b66e-0f60-4395-a6f9-6676240e2ce3'}], 'smp': '1', 'vmType': 'kvm', 'timeOffset': '0', 'memSize': 512, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1', 'vmName': 'rpro', 'display': 'qxl', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [5622aa4d]
>Thread-31::INFO::2012-08-15 11:34:28,798::API::579::vds::(_getNetworkIp) network None: using 0
>Thread-31::INFO::2012-08-15 11:34:28,799::API::216::vds::(create) vmContainerLock acquired by vm 2445ad59-8c84-4315-9119-3f2f4820b946
>Thread-32::DEBUG::2012-08-15 11:34:28,867::vm::565::vm.Vm::(_startUnderlyingVm) vmId=`2445ad59-8c84-4315-9119-3f2f4820b946`::Start
>Thread-31::DEBUG::2012-08-15 11:34:28,867::API::229::vds::(create) Total desktops after creation of 2445ad59-8c84-4315-9119-3f2f4820b946 is 1
>Thread-32::DEBUG::2012-08-15 11:34:28,868::vm::569::vm.Vm::(_startUnderlyingVm) vmId=`2445ad59-8c84-4315-9119-3f2f4820b946`::_ongoingCreations acquired
>Thread-31::DEBUG::2012-08-15 11:34:28,868::BindingXMLRPC::870::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.3.0', 'vmId': '2445ad59-8c84-4315-9119-3f2f4820b946', 'pid': '0', 'timeOffset': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73device_0f6eb766-3a1d-43a6-b487-a861053407f5': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=0f6eb766-3a1d-43a6-b487-a861053407f5,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=1, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=ecbbe624-f409-4b67-ad54-3e5b6e7eef73,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=cc02340a-9bf9-42ac-a4aa-91a603849a43,Device=ide,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73device_0f6eb766-3a1d-43a6-b487-a861053407f5device_68dc2a6e-7731-47b7-b677-5b3cf7bc95addevice_1b419824-7579-4aa4-a0e2-01650399bf8d': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=1b419824-7579-4aa4-a0e2-01650399bf8d,Device=usb,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0', 'device_cc02340a-9bf9-42ac-a4aa-91a603849a43device_ecbbe624-f409-4b67-ad54-3e5b6e7eef73device_0f6eb766-3a1d-43a6-b487-a861053407f5device_68dc2a6e-7731-47b7-b677-5b3cf7bc95ad': 'VmId=2445ad59-8c84-4315-9119-3f2f4820b946,DeviceId=68dc2a6e-7731-47b7-b677-5b3cf7bc95ad,Device=spicevmc,Type=channel,BootOrder=0,SpecParams={},Address={port=2, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '8d15514f-b1fb-4030-8d27-970dda91b135', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '87bd229f-1980-4ac5-b6c8-dfc0da3a28a4', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'cow', 'bootOrder': '1', 'poolID': 'a9814774-ab07-46a9-abf8-e42a2fbf8f33', 'volumeID': '2961837b-6ff5-415c-98d2-030f5369ddb6', 'imageID': 'af0957a7-1499-4ba5-9e75-a4685a55c55d', 'specParams': {}, 'readonly': 'false', 'domainID': '9e871461-44df-4044-87ed-10a70e94758c', 'optional': 'false', 'deviceId': 'af0957a7-1499-4ba5-9e75-a4685a55c55d', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:42:04:0b', 'network': 'rhevm', 'specParams': {}, 'deviceId': '2deba7d4-4232-424f-9c62-acb4c66bda0d', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'portMirroring': ['rhevm']}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '1b419824-7579-4aa4-a0e2-01650399bf8d', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '5146b66e-0f60-4395-a6f9-6676240e2ce3'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 512, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1', 'vmName': 'rpro', 'display': 'qxl', 'nice': '0'}}
>Thread-32::INFO::2012-08-15 11:34:28,868::libvirtvm::1292::vm.Vm::(_run) vmId=`2445ad59-8c84-4315-9119-3f2f4820b946`::VM wrapper has started
>Thread-32::DEBUG::2012-08-15 11:34:28,872::task::588::TaskManager.Task::(_updateState) Task=`1a99e81d-4ae1-44af-afa9-102a148c8315`::moving from state init -> state preparing
>Thread-32::INFO::2012-08-15 11:34:28,873::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='9e871461-44df-4044-87ed-10a70e94758c', spUUID='a9814774-ab07-46a9-abf8-e42a2fbf8f33', imgUUID='af0957a7-1499-4ba5-9e75-a4685a55c55d', volUUID='2961837b-6ff5-415c-98d2-030f5369ddb6', options=None)
>Thread-32::DEBUG::2012-08-15 11:34:28,874::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.9e871461-44df-4044-87ed-10a70e94758c`ReqID=`1c75d1e9-fb2a-4005-a8c7-d1a73c5cb73b`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-32::DEBUG::2012-08-15 11:34:28,875::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' for lock type 'shared'
>Thread-32::DEBUG::2012-08-15 11:34:28,875::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' is free. Now locking as 'shared' (1 active user)
>Thread-32::DEBUG::2012-08-15 11:34:28,876::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.9e871461-44df-4044-87ed-10a70e94758c`ReqID=`1c75d1e9-fb2a-4005-a8c7-d1a73c5cb73b`::Granted request
>Thread-32::DEBUG::2012-08-15 11:34:28,877::task::817::TaskManager.Task::(resourceAcquired) Task=`1a99e81d-4ae1-44af-afa9-102a148c8315`::_resourcesAcquired: Storage.9e871461-44df-4044-87ed-10a70e94758c (shared)
>Thread-32::DEBUG::2012-08-15 11:34:28,877::task::978::TaskManager.Task::(_decref) Task=`1a99e81d-4ae1-44af-afa9-102a148c8315`::ref 1 aborting False
>Thread-32::INFO::2012-08-15 11:34:28,879::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2147483648', 'apparentsize': '2147483648'}
>Thread-32::DEBUG::2012-08-15 11:34:28,879::task::1172::TaskManager.Task::(prepare) Task=`1a99e81d-4ae1-44af-afa9-102a148c8315`::finished: {'truesize': '2147483648', 'apparentsize': '2147483648'}
>Thread-32::DEBUG::2012-08-15 11:34:28,880::task::588::TaskManager.Task::(_updateState) Task=`1a99e81d-4ae1-44af-afa9-102a148c8315`::moving from state preparing -> state finished
>Thread-32::DEBUG::2012-08-15 11:34:28,880::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9e871461-44df-4044-87ed-10a70e94758c': < ResourceRef 'Storage.9e871461-44df-4044-87ed-10a70e94758c', isValid: 'True' obj: 'None'>}
>Thread-32::DEBUG::2012-08-15 11:34:28,881::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-32::DEBUG::2012-08-15 11:34:28,881::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c'
>Thread-32::DEBUG::2012-08-15 11:34:28,882::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' (0 active users)
>Thread-32::DEBUG::2012-08-15 11:34:28,882::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' is free, finding out if anyone is waiting for it.
>Thread-32::DEBUG::2012-08-15 11:34:28,882::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c', Clearing records.
>Thread-32::DEBUG::2012-08-15 11:34:28,883::task::978::TaskManager.Task::(_decref) Task=`1a99e81d-4ae1-44af-afa9-102a148c8315`::ref 0 aborting False
>Thread-32::INFO::2012-08-15 11:34:28,884::clientIF::227::vds::(prepareVolumePath) prepared volume path: 
>Thread-32::DEBUG::2012-08-15 11:34:28,884::task::588::TaskManager.Task::(_updateState) Task=`30c11b4a-ca3e-4d32-9d37-e5a39bf0e002`::moving from state init -> state preparing
>Thread-32::INFO::2012-08-15 11:34:28,885::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='9e871461-44df-4044-87ed-10a70e94758c', spUUID='a9814774-ab07-46a9-abf8-e42a2fbf8f33', imgUUID='af0957a7-1499-4ba5-9e75-a4685a55c55d', volUUID='2961837b-6ff5-415c-98d2-030f5369ddb6')
>Thread-32::DEBUG::2012-08-15 11:34:28,886::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.9e871461-44df-4044-87ed-10a70e94758c`ReqID=`70c0b122-b9ff-442c-821c-4940b0fb7dd2`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-32::DEBUG::2012-08-15 11:34:28,886::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' for lock type 'shared'
>Thread-32::DEBUG::2012-08-15 11:34:28,887::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' is free. Now locking as 'shared' (1 active user)
>Thread-32::DEBUG::2012-08-15 11:34:28,887::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.9e871461-44df-4044-87ed-10a70e94758c`ReqID=`70c0b122-b9ff-442c-821c-4940b0fb7dd2`::Granted request
>Thread-32::DEBUG::2012-08-15 11:34:28,888::task::817::TaskManager.Task::(resourceAcquired) Task=`30c11b4a-ca3e-4d32-9d37-e5a39bf0e002`::_resourcesAcquired: Storage.9e871461-44df-4044-87ed-10a70e94758c (shared)
>Thread-32::DEBUG::2012-08-15 11:34:28,888::task::978::TaskManager.Task::(_decref) Task=`30c11b4a-ca3e-4d32-9d37-e5a39bf0e002`::ref 1 aborting False
>Thread-32::DEBUG::2012-08-15 11:34:28,889::lvm::393::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-32::DEBUG::2012-08-15 11:34:28,890::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1IET_00010001%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 9e871461-44df-4044-87ed-10a70e94758c' (cwd None)
>Thread-32::DEBUG::2012-08-15 11:34:29,105::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-32::DEBUG::2012-08-15 11:34:29,115::lvm::422::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-32::DEBUG::2012-08-15 11:34:29,117::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct skip=4 bs=512 if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata count=1' (cwd None)
>Thread-32::DEBUG::2012-08-15 11:34:29,124::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000606454 s, 844 kB/s\n'; <rc> = 0
>Thread-32::DEBUG::2012-08-15 11:34:29,125::misc::334::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000606454 s, 844 kB/s'], size: 512
>Thread-32::INFO::2012-08-15 11:34:29,125::image::319::Storage.Image::(getChain) sdUUID=9e871461-44df-4044-87ed-10a70e94758c imgUUID=af0957a7-1499-4ba5-9e75-a4685a55c55d chain=[<storage.blockVolume.BlockVolume object at 0x14f0550>] 
>Thread-32::INFO::2012-08-15 11:34:29,126::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/a9814774-ab07-46a9-abf8-e42a2fbf8f33/9e871461-44df-4044-87ed-10a70e94758c/images/af0957a7-1499-4ba5-9e75-a4685a55c55d/2961837b-6ff5-415c-98d2-030f5369ddb6', 'chain': [{'path': '/rhev/data-center/a9814774-ab07-46a9-abf8-e42a2fbf8f33/9e871461-44df-4044-87ed-10a70e94758c/images/af0957a7-1499-4ba5-9e75-a4685a55c55d/2961837b-6ff5-415c-98d2-030f5369ddb6', 'domainID': '9e871461-44df-4044-87ed-10a70e94758c', 'volumeID': '2961837b-6ff5-415c-98d2-030f5369ddb6', 'imageID': 'af0957a7-1499-4ba5-9e75-a4685a55c55d'}]}
>Thread-32::DEBUG::2012-08-15 11:34:29,127::task::1172::TaskManager.Task::(prepare) Task=`30c11b4a-ca3e-4d32-9d37-e5a39bf0e002`::finished: {'path': '/rhev/data-center/a9814774-ab07-46a9-abf8-e42a2fbf8f33/9e871461-44df-4044-87ed-10a70e94758c/images/af0957a7-1499-4ba5-9e75-a4685a55c55d/2961837b-6ff5-415c-98d2-030f5369ddb6', 'chain': [{'path': '/rhev/data-center/a9814774-ab07-46a9-abf8-e42a2fbf8f33/9e871461-44df-4044-87ed-10a70e94758c/images/af0957a7-1499-4ba5-9e75-a4685a55c55d/2961837b-6ff5-415c-98d2-030f5369ddb6', 'domainID': '9e871461-44df-4044-87ed-10a70e94758c', 'volumeID': '2961837b-6ff5-415c-98d2-030f5369ddb6', 'imageID': 'af0957a7-1499-4ba5-9e75-a4685a55c55d'}]}
>Thread-32::DEBUG::2012-08-15 11:34:29,127::task::588::TaskManager.Task::(_updateState) Task=`30c11b4a-ca3e-4d32-9d37-e5a39bf0e002`::moving from state preparing -> state finished
>Thread-32::DEBUG::2012-08-15 11:34:29,128::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9e871461-44df-4044-87ed-10a70e94758c': < ResourceRef 'Storage.9e871461-44df-4044-87ed-10a70e94758c', isValid: 'True' obj: 'None'>}
>Thread-32::DEBUG::2012-08-15 11:34:29,128::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-32::DEBUG::2012-08-15 11:34:29,129::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c'
>Thread-32::DEBUG::2012-08-15 11:34:29,129::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' (0 active users)
>Thread-32::DEBUG::2012-08-15 11:34:29,130::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c' is free, finding out if anyone is waiting for it.
>Thread-32::DEBUG::2012-08-15 11:34:29,130::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9e871461-44df-4044-87ed-10a70e94758c', Clearing records.
>Thread-32::DEBUG::2012-08-15 11:34:29,131::task::978::TaskManager.Task::(_decref) Task=`30c11b4a-ca3e-4d32-9d37-e5a39bf0e002`::ref 0 aborting False
>Thread-32::INFO::2012-08-15 11:34:29,131::clientIF::227::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/a9814774-ab07-46a9-abf8-e42a2fbf8f33/9e871461-44df-4044-87ed-10a70e94758c/images/af0957a7-1499-4ba5-9e75-a4685a55c55d/2961837b-6ff5-415c-98d2-030f5369ddb6
>Thread-32::DEBUG::2012-08-15 11:34:29,140::vm::581::vm.Vm::(_startUnderlyingVm) vmId=`2445ad59-8c84-4315-9119-3f2f4820b946`::_ongoingCreations released
>Thread-32::ERROR::2012-08-15 11:34:29,140::vm::605::vm.Vm::(_startUnderlyingVm) vmId=`2445ad59-8c84-4315-9119-3f2f4820b946`::The vm start process failed
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 571, in _startUnderlyingVm
>    self._run()
>  File "/usr/share/vdsm/libvirtvm.py", line 1344, in _run
>    domxml = hooks.before_vm_start(self._buildCmdLine(), self.conf)
>  File "/usr/share/vdsm/libvirtvm.py", line 1206, in _buildCmdLine
>    devElem = dev.getXML()
>  File "/usr/share/vdsm/libvirtvm.py", line 1066, in getXML
>    if  utils.tobool(self.shared):
>AttributeError: 'Drive' object has no attribute 'shared'
>Thread-32::DEBUG::2012-08-15 11:34:29,146::vm::921::vm.Vm::(setDownStatus) vmId=`2445ad59-8c84-4315-9119-3f2f4820b946`::Changed state to Down: 'Drive' object has no attribute 'shared'
>Thread-15::DEBUG::2012-08-15 11:34:31,442::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata bs=4096 count=1' (cwd None)
>Thread-15::DEBUG::2012-08-15 11:34:31,451::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000653242 s, 6.3 MB/s\n'; <rc> = 0
>Thread-15::DEBUG::2012-08-15 11:34:41,456::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/9e871461-44df-4044-87ed-10a70e94758c/metadata bs=4096 count=1' (cwd None)
>Thread-15::DEBUG::2012-08-15 11:34:41,464::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000779023 s, 5.3 MB/s\n'; <rc> = 0
>^C
>

Actions: View

Attachments on bug 848266: 604499 | 604527