Thread-39491::DEBUG::2013-10-09 08:13:20,926::task::579::TaskManager.Task::(_updateState) Task=`6605d9b7-8d14-4196-bad1-9d6035071efd`::moving from state init -> state preparing
Thread-39491::INFO::2013-10-09 08:13:20,926::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-39491::INFO::2013-10-09 08:13:20,926::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'f9a8f68d-268f-4c44-801a-fabe04741376': {'delay': '0.001031', 'lastCheck': '4.2', 'code': 0, 'valid': True, 'version': 3}, '03af78e4-8f68-40c3-adce-be2ccda9364f': {'delay': '0.000245213', 'lastCheck': '6.2', 'code': 0, 'valid': True, 'version': 0}, '0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6': {'delay': '0.000989595', 'lastCheck': '9.5', 'code': 0, 'valid': True, 'version': 3}}
Thread-39491::DEBUG::2013-10-09 08:13:20,927::task::1168::TaskManager.Task::(prepare) Task=`6605d9b7-8d14-4196-bad1-9d6035071efd`::finished: {'f9a8f68d-268f-4c44-801a-fabe04741376': {'delay': '0.001031', 'lastCheck': '4.2', 'code': 0, 'valid': True, 'version': 3}, '03af78e4-8f68-40c3-adce-be2ccda9364f': {'delay': '0.000245213', 'lastCheck': '6.2', 'code': 0, 'valid': True, 'version': 0}, '0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6': {'delay': '0.000989595', 'lastCheck': '9.5', 'code': 0, 'valid': True, 'version': 3}}
Thread-39491::DEBUG::2013-10-09 08:13:20,927::task::579::TaskManager.Task::(_updateState) Task=`6605d9b7-8d14-4196-bad1-9d6035071efd`::moving from state preparing -> state finished
Thread-39491::DEBUG::2013-10-09 08:13:20,927::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39491::DEBUG::2013-10-09 08:13:20,927::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39491::DEBUG::2013-10-09 08:13:20,927::task::974::TaskManager.Task::(_decref) Task=`6605d9b7-8d14-4196-bad1-9d6035071efd`::ref 0 aborting False
Thread-760::DEBUG::2013-10-09 08:13:21,432::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/localhost:_GLUSTER-VMSTORE01/0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-760::DEBUG::2013-10-09 08:13:21,442::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n556 bytes (556 B) copied, 0.00083172 s, 668 kB/s\n'; <rc> = 0
libvirtEventLoop::DEBUG::2013-10-09 08:13:22,874::vm::4723::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::event Suspended detail 0 opaque None
VM Channels Listener::ERROR::2013-10-09 08:13:23,316::vmChannels::53::vds::(_handle_event) Received 00000019 on fileno 49
VM Channels Listener::DEBUG::2013-10-09 08:13:23,317::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49.
VM Channels Listener::DEBUG::2013-10-09 08:13:23,317::guestIF::147::vm.Vm::(_connect) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Attempting connection to /var/lib/libvirt/qemu/channels/168d5fa1-21a3-47d4-a3bb-9874ffb50876.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2013-10-09 08:13:23,317::guestIF::158::vm.Vm::(_connect) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Failed to connect to /var/lib/libvirt/qemu/channels/168d5fa1-21a3-47d4-a3bb-9874ffb50876.com.redhat.rhevm.vdsm with 111
libvirtEventLoop::DEBUG::2013-10-09 08:13:23,507::vm::4723::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::event Stopped detail 3 opaque None
Thread-39472::DEBUG::2013-10-09 08:13:23,511::vm::733::vm.Vm::(cancel) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::canceling migration downtime thread
Thread-39472::DEBUG::2013-10-09 08:13:23,512::vm::803::vm.Vm::(stop) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::stopping migration monitor thread
Thread-39481::DEBUG::2013-10-09 08:13:23,512::vm::730::vm.Vm::(run) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::migration downtime thread exiting
Thread-39482::DEBUG::2013-10-09 08:13:23,515::libvirtconnection::101::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '168d5fa1-21a3-47d4-a3bb-9874ffb50876'
Thread-39472::DEBUG::2013-10-09 08:13:23,528::libvirtconnection::101::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '168d5fa1-21a3-47d4-a3bb-9874ffb50876'
Thread-39472::DEBUG::2013-10-09 08:13:23,529::vm::2448::vm.Vm::(setDownStatus) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Changed state to Down: Migration succeeded
Thread-39472::DEBUG::2013-10-09 08:13:23,529::vmChannels::205::vds::(unregister) Delete fileno 49 from listener.
Thread-39472::DEBUG::2013-10-09 08:13:23,529::sampling::292::vm.Vm::(stop) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Stop statistics collection
Thread-804::DEBUG::2013-10-09 08:13:23,529::sampling::323::vm.Vm::(run) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Stats thread finished
Thread-39472::DEBUG::2013-10-09 08:13:23,539::libvirtconnection::101::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '168d5fa1-21a3-47d4-a3bb-9874ffb50876'
Thread-39493::DEBUG::2013-10-09 08:13:23,952::task::579::TaskManager.Task::(_updateState) Task=`6e2818d6-4517-4ba0-bf6b-96fdddb54af2`::moving from state init -> state preparing
Thread-39493::INFO::2013-10-09 08:13:23,953::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-39493::INFO::2013-10-09 08:13:23,953::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'f9a8f68d-268f-4c44-801a-fabe04741376': {'delay': '0.001031', 'lastCheck': '7.2', 'code': 0, 'valid': True, 'version': 3}, '03af78e4-8f68-40c3-adce-be2ccda9364f': {'delay': '0.000245213', 'lastCheck': '9.2', 'code': 0, 'valid': True, 'version': 0}, '0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6': {'delay': '0.00083172', 'lastCheck': '2.5', 'code': 0, 'valid': True, 'version': 3}}
Thread-39493::DEBUG::2013-10-09 08:13:23,953::task::1168::TaskManager.Task::(prepare) Task=`6e2818d6-4517-4ba0-bf6b-96fdddb54af2`::finished: {'f9a8f68d-268f-4c44-801a-fabe04741376': {'delay': '0.001031', 'lastCheck': '7.2', 'code': 0, 'valid': True, 'version': 3}, '03af78e4-8f68-40c3-adce-be2ccda9364f': {'delay': '0.000245213', 'lastCheck': '9.2', 'code': 0, 'valid': True, 'version': 0}, '0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6': {'delay': '0.00083172', 'lastCheck': '2.5', 'code': 0, 'valid': True, 'version': 3}}
Thread-39493::DEBUG::2013-10-09 08:13:23,954::task::579::TaskManager.Task::(_updateState) Task=`6e2818d6-4517-4ba0-bf6b-96fdddb54af2`::moving from state preparing -> state finished
Thread-39493::DEBUG::2013-10-09 08:13:23,954::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39493::DEBUG::2013-10-09 08:13:23,954::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39493::DEBUG::2013-10-09 08:13:23,954::task::974::TaskManager.Task::(_decref) Task=`6e2818d6-4517-4ba0-bf6b-96fdddb54af2`::ref 0 aborting False
Thread-39495::DEBUG::2013-10-09 08:13:23,965::BindingXMLRPC::979::vds::(wrapper) client [192.168.13.200]::call vmGetStats with ('168d5fa1-21a3-47d4-a3bb-9874ffb50876',) {}
Thread-39495::DEBUG::2013-10-09 08:13:23,965::BindingXMLRPC::986::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'hash': '-5415809498006075024', 'exitMessage': 'Migration succeeded', 'vmId': '168d5fa1-21a3-47d4-a3bb-9874ffb50876', 'timeOffset': -2, 'exitCode': 0}]}
Thread-39496::DEBUG::2013-10-09 08:13:23,972::BindingXMLRPC::979::vds::(wrapper) client [192.168.13.200]::call vmDestroy with ('168d5fa1-21a3-47d4-a3bb-9874ffb50876',) {}
Thread-39496::INFO::2013-10-09 08:13:23,972::API::317::vds::(destroy) vmContainerLock acquired by vm 168d5fa1-21a3-47d4-a3bb-9874ffb50876
Thread-39496::DEBUG::2013-10-09 08:13:23,972::vm::4258::vm.Vm::(destroy) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::destroy Called
Thread-39496::INFO::2013-10-09 08:13:23,981::vm::4204::vm.Vm::(releaseVm) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Release VM resources
Thread-39496::WARNING::2013-10-09 08:13:23,981::vm::1717::vm.Vm::(_set_lastStatus) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::trying to set state to Powering down when already Down
Thread-39496::DEBUG::2013-10-09 08:13:23,981::sampling::292::vm.Vm::(stop) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Stop statistics collection
Thread-39496::DEBUG::2013-10-09 08:13:23,983::libvirtconnection::101::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '168d5fa1-21a3-47d4-a3bb-9874ffb50876'
Thread-39496::WARNING::2013-10-09 08:13:23,983::clientIF::337::vds::(teardownVolumePath) Drive is not a vdsm image: VOLWM_CHUNK_MB:1024 VOLWM_CHUNK_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:False _checkIoTuneCategories:<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f13e8248d50>> _customize:<bound method Drive._customize of <vm.Drive object at 0x7f13e8248d50>> _deviceXML:<disk device="cdrom" type="file">
      <driver name="qemu" type="raw"/>
      <source file="/var/run/vdsm/payload/168d5fa1-21a3-47d4-a3bb-9874ffb50876.d247f64dc74a2301f7adac970413c696.img" startupPolicy="optional"/>
      <target bus="ide" dev="hdd"/>
      <readonly/>
      <serial/>
      <alias name="ide0-1-1"/>
      <address bus="1" controller="0" target="0" type="drive" unit="1"/>
    </disk> _makeName:<bound method Drive._makeName of <vm.Drive object at 0x7f13e8248d50>> _validateIoTuneParams:<bound method Drive._validateIoTuneParams of <vm.Drive object at 0x7f13e8248d50>> address:{u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'1'} alias:ide0-1-1 apparentsize:0 blockDev:False cache:none conf:{'acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0', 'pid': '11360', 'memGuaranteedSize': 1024, 'transparentHugePages': 'true', 'displaySecurePort': u'5901', 'timeOffset': -2, 'cpuType': 'Conroe', 'smp': '1', 'custom': {}, 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 1024, 'vmName': 'cloudvm-brick1-001', 'nice': '0', 'clientIp': '', 'exitMessage': 'Migration succeeded', 'vmId': '168d5fa1-21a3-47d4-a3bb-9874ffb50876', 'displayIp': '0', 'keyboardLayout': 'en-us', 'displayPort': u'5900', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'exitCode': 0, 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '1', 'kvmEnable': 'true', 'pitReinjection': 'false', 'devices': [{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}, {'device': 'scsi', 'alias': u'scsi0', 'model': 'virtio-scsi', 'type': 'controller', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'device': 'usb', 'alias': u'usb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': 'ide', 'alias': u'ide0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': 'virtio-serial', 'alias': u'virtio-serial0', 'type': 'controller', 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'specParams': {'vram': '65536'}, 'alias': 'video0', 'deviceId': '944dda23-c2c9-4996-9d46-07903d31395c', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:0d:9a', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'custom': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': u'net0', 'deviceId': '156d915b-bc8e-429b-a544-ac14e78ad712', 'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'}, {'index': '3', 'iface': 'ide', 'name': u'hdd', 'alias': u'ide0-1-1', 'specParams': {'vmPayload': {'volId': 'config-2', 'file': {'openstack/latest/meta_data.json': 'ewogICJsYXVuY2hfaW5kZXgiIDogIjAiLAogICJhdmFpbGFiaWxpdHlfem9uZSIgOiAibm92YSIs\nCiAgInV1aWQiIDogImExOTdkNjliLTgwMWYtNDRmZC1iYzczLTNjOTNlOTFlZTI5YiIsCiAgIm1l\ndGEiIDogewogICAgImVzc2VudGlhbCIgOiAiZmFsc2UiLAogICAgInJvbGUiIDogInNlcnZlciIs\nCiAgICAiZHNtb2RlIiA6ICJsb2NhbCIKICB9Cn0=\n', 'openstack/latest/user_data': 'b3V0cHV0OgogIGFsbDogJz4+IC92YXIvbG9nL2Nsb3VkLWluaXQtb3V0cHV0LmxvZycKdXNlcjog\ncm9vdApydW5jbWQ6Ci0gJ3NlZCAtaSAnJy9eZGF0YXNvdXJjZV9saXN0OiAvZCcnIC9ldGMvY2xv\ndWQvY2xvdWQuY2ZnOyBlY2hvICcnZGF0YXNvdXJjZV9saXN0OgogIFsiTm9DbG91ZCIsICJDb25m\naWdEcml2ZSJdJycgPj4gL2V0Yy9jbG91ZC9jbG91ZC5jZmcnCg==\n'}}}, 'readonly': 'True', 'deviceId': '5ffafecb-45d2-42fa-8b83-a5b8dda61819', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'1'}, 'device': 'cdrom', 'shared': 'false', 'path': '/var/run/vdsm/payload/168d5fa1-21a3-47d4-a3bb-9874ffb50876.d247f64dc74a2301f7adac970413c696.img', 'type': 'disk'}, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': 'e6a975b4-42ee-4b82-8f39-39031f664e6a', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '10737418240', 'specParams': {}, 'imageID': '8a44bd23-970c-4715-8344-08cf51ff766b', 'readonly': 'False', 'shared': 'false', 'truesize': '5467648000', 'type': 'disk', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'volumeInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'volType': 'path'}, 'format': 'raw', 'deviceId': '8a44bd23-970c-4715-8344-08cf51ff766b', 'poolID': 'b30f1ed0-7643-4d77-bf65-9e54f2b60d30', 'device': 'disk', 'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'propagateErrors': 'off', 'optional': 'false', 'name': u'vda', 'bootOrder': u'1', 'volumeID': 'e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'alias': u'virtio-disk0', 'volumeChain': [{'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'vmVolInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'volType': 'path'}, 'volumeID': 'e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'imageID': '8a44bd23-970c-4715-8344-08cf51ff766b'}]}, {'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'reqsize': '0', 'index': '1', 'iface': 'virtio', 'apparentsize': '10737418240', 'specParams': {}, 'imageID': 'c40366d6-0fdc-4bb6-adf1-0f1a480779f3', 'readonly': 'False', 'shared': 'false', 'truesize': '10737418240', 'type': 'disk', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'volumeInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'volType': 'path'}, 'format': 'raw', 'deviceId': 'c40366d6-0fdc-4bb6-adf1-0f1a480779f3', 'poolID': 'b30f1ed0-7643-4d77-bf65-9e54f2b60d30', 'device': 'disk', 'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'propagateErrors': 'off', 'optional': 'false', 'name': u'vdb', 'volumeID': '595a7390-ffe8-4d43-a149-64d5e63922af', 'alias': u'virtio-disk1', 'volumeChain': [{'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'vmVolInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'volType': 'path'}, 'volumeID': '595a7390-ffe8-4d43-a149-64d5e63922af', 'imageID': 'c40366d6-0fdc-4bb6-adf1-0f1a480779f3'}]}, {'target': 1048576, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '0de4da86-3c9c-423f-b1d5-2f17912fb172', 'address': {'slot': '0x08', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}], 'status': 'Down', 'display': 'qxl'} createXmlElem:<bound method Drive.createXmlElem of <vm.Drive object at 0x7f13e8248d50>> device:cdrom deviceId:5ffafecb-45d2-42fa-8b83-a5b8dda61819 drv:raw getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Drive object at 0x7f13e8248d50>> getXML:<bound method Drive.getXML of <vm.Drive object at 0x7f13e8248d50>> iface:ide index:3 isDiskReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <vm.Drive object at 0x7f13e8248d50>> isVdsmImage:<bound method Drive.isVdsmImage of <vm.Drive object at 0x7f13e8248d50>> log:<logUtils.SimpleLogAdapter instance at 0x7f13d40d7f80> name:hdd networkDev:False path:/var/run/vdsm/payload/168d5fa1-21a3-47d4-a3bb-9874ffb50876.d247f64dc74a2301f7adac970413c696.img readonly:True reqsize:0 serial: shared:false specParams:{'vmPayload': {'volId': 'config-2', 'file': {'openstack/latest/meta_data.json': 'ewogICJsYXVuY2hfaW5kZXgiIDogIjAiLAogICJhdmFpbGFiaWxpdHlfem9uZSIgOiAibm92YSIs\nCiAgInV1aWQiIDogImExOTdkNjliLTgwMWYtNDRmZC1iYzczLTNjOTNlOTFlZTI5YiIsCiAgIm1l\ndGEiIDogewogICAgImVzc2VudGlhbCIgOiAiZmFsc2UiLAogICAgInJvbGUiIDogInNlcnZlciIs\nCiAgICAiZHNtb2RlIiA6ICJsb2NhbCIKICB9Cn0=\n', 'openstack/latest/user_data': 'b3V0cHV0OgogIGFsbDogJz4+IC92YXIvbG9nL2Nsb3VkLWluaXQtb3V0cHV0LmxvZycKdXNlcjog\ncm9vdApydW5jbWQ6Ci0gJ3NlZCAtaSAnJy9eZGF0YXNvdXJjZV9saXN0OiAvZCcnIC9ldGMvY2xv\ndWQvY2xvdWQuY2ZnOyBlY2hvICcnZGF0YXNvdXJjZV9saXN0OgogIFsiTm9DbG91ZCIsICJDb25m\naWdEcml2ZSJdJycgPj4gL2V0Yy9jbG91ZC9jbG91ZC5jZmcnCg==\n'}}} truesize:0 type:cdrom volExtensionChunk:1024 watermarkLimit:536870912
Traceback (most recent call last):
  File "/usr/share/vdsm/clientIF.py", line 331, in teardownVolumePath
    res = self.irs.teardownImage(drive['domainID'],
  File "/usr/share/vdsm/vm.py", line 1344, in __getitem__
    raise KeyError(key)
KeyError: 'domainID'
Thread-39496::WARNING::2013-10-09 08:13:23,985::clientIF::337::vds::(teardownVolumePath) Drive is not a vdsm image: VOLWM_CHUNK_MB:1024 VOLWM_CHUNK_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:False _checkIoTuneCategories:<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f13e8248e10>> _customize:<bound method Drive._customize of <vm.Drive object at 0x7f13e8248e10>> _deviceXML:<disk device="cdrom" type="file">
      <driver name="qemu" type="raw"/>
      <source startupPolicy="optional"/>
      <target bus="ide" dev="hdc"/>
      <readonly/>
      <serial/>
      <alias name="ide0-1-0"/>
      <address bus="1" controller="0" target="0" type="drive" unit="0"/>
    </disk> _makeName:<bound method Drive._makeName of <vm.Drive object at 0x7f13e8248e10>> _validateIoTuneParams:<bound method Drive._validateIoTuneParams of <vm.Drive object at 0x7f13e8248e10>> address:{u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'} alias:ide0-1-0 apparentsize:0 blockDev:False cache:none conf:{'acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0', 'pid': '11360', 'memGuaranteedSize': 1024, 'transparentHugePages': 'true', 'displaySecurePort': u'5901', 'timeOffset': -2, 'cpuType': 'Conroe', 'smp': '1', 'custom': {}, 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 1024, 'vmName': 'cloudvm-brick1-001', 'nice': '0', 'clientIp': '', 'exitMessage': 'Migration succeeded', 'vmId': '168d5fa1-21a3-47d4-a3bb-9874ffb50876', 'displayIp': '0', 'keyboardLayout': 'en-us', 'displayPort': u'5900', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'exitCode': 0, 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '1', 'kvmEnable': 'true', 'pitReinjection': 'false', 'devices': [{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}, {'device': 'scsi', 'alias': u'scsi0', 'model': 'virtio-scsi', 'type': 'controller', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'device': 'usb', 'alias': u'usb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': 'ide', 'alias': u'ide0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': 'virtio-serial', 'alias': u'virtio-serial0', 'type': 'controller', 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'specParams': {'vram': '65536'}, 'alias': 'video0', 'deviceId': '944dda23-c2c9-4996-9d46-07903d31395c', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:0d:9a', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'custom': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': u'net0', 'deviceId': '156d915b-bc8e-429b-a544-ac14e78ad712', 'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'}, {'index': '3', 'iface': 'ide', 'name': u'hdd', 'alias': u'ide0-1-1', 'specParams': {'vmPayload': {'volId': 'config-2', 'file': {'openstack/latest/meta_data.json': 'ewogICJsYXVuY2hfaW5kZXgiIDogIjAiLAogICJhdmFpbGFiaWxpdHlfem9uZSIgOiAibm92YSIs\nCiAgInV1aWQiIDogImExOTdkNjliLTgwMWYtNDRmZC1iYzczLTNjOTNlOTFlZTI5YiIsCiAgIm1l\ndGEiIDogewogICAgImVzc2VudGlhbCIgOiAiZmFsc2UiLAogICAgInJvbGUiIDogInNlcnZlciIs\nCiAgICAiZHNtb2RlIiA6ICJsb2NhbCIKICB9Cn0=\n', 'openstack/latest/user_data': 'b3V0cHV0OgogIGFsbDogJz4+IC92YXIvbG9nL2Nsb3VkLWluaXQtb3V0cHV0LmxvZycKdXNlcjog\ncm9vdApydW5jbWQ6Ci0gJ3NlZCAtaSAnJy9eZGF0YXNvdXJjZV9saXN0OiAvZCcnIC9ldGMvY2xv\ndWQvY2xvdWQuY2ZnOyBlY2hvICcnZGF0YXNvdXJjZV9saXN0OgogIFsiTm9DbG91ZCIsICJDb25m\naWdEcml2ZSJdJycgPj4gL2V0Yy9jbG91ZC9jbG91ZC5jZmcnCg==\n'}}}, 'readonly': 'True', 'deviceId': '5ffafecb-45d2-42fa-8b83-a5b8dda61819', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'1'}, 'device': 'cdrom', 'shared': 'false', 'path': '/var/run/vdsm/payload/168d5fa1-21a3-47d4-a3bb-9874ffb50876.d247f64dc74a2301f7adac970413c696.img', 'type': 'disk'}, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': 'e6a975b4-42ee-4b82-8f39-39031f664e6a', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '10737418240', 'specParams': {}, 'imageID': '8a44bd23-970c-4715-8344-08cf51ff766b', 'readonly': 'False', 'shared': 'false', 'truesize': '5467648000', 'type': 'disk', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'volumeInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'volType': 'path'}, 'format': 'raw', 'deviceId': '8a44bd23-970c-4715-8344-08cf51ff766b', 'poolID': 'b30f1ed0-7643-4d77-bf65-9e54f2b60d30', 'device': 'disk', 'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'propagateErrors': 'off', 'optional': 'false', 'name': u'vda', 'bootOrder': u'1', 'volumeID': 'e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'alias': u'virtio-disk0', 'volumeChain': [{'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'vmVolInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/8a44bd23-970c-4715-8344-08cf51ff766b/e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'volType': 'path'}, 'volumeID': 'e81f83fe-fc3f-4b1c-be73-c9495c8565f1', 'imageID': '8a44bd23-970c-4715-8344-08cf51ff766b'}]}, {'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'reqsize': '0', 'index': '1', 'iface': 'virtio', 'apparentsize': '10737418240', 'specParams': {}, 'imageID': 'c40366d6-0fdc-4bb6-adf1-0f1a480779f3', 'readonly': 'False', 'shared': 'false', 'truesize': '10737418240', 'type': 'disk', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'volumeInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'volType': 'path'}, 'format': 'raw', 'deviceId': 'c40366d6-0fdc-4bb6-adf1-0f1a480779f3', 'poolID': 'b30f1ed0-7643-4d77-bf65-9e54f2b60d30', 'device': 'disk', 'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'propagateErrors': 'off', 'optional': 'false', 'name': u'vdb', 'volumeID': '595a7390-ffe8-4d43-a149-64d5e63922af', 'alias': u'virtio-disk1', 'volumeChain': [{'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'domainID': 'f9a8f68d-268f-4c44-801a-fabe04741376', 'vmVolInfo': {'path': '/rhev/data-center/b30f1ed0-7643-4d77-bf65-9e54f2b60d30/f9a8f68d-268f-4c44-801a-fabe04741376/images/c40366d6-0fdc-4bb6-adf1-0f1a480779f3/595a7390-ffe8-4d43-a149-64d5e63922af', 'volType': 'path'}, 'volumeID': '595a7390-ffe8-4d43-a149-64d5e63922af', 'imageID': 'c40366d6-0fdc-4bb6-adf1-0f1a480779f3'}]}, {'target': 1048576, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '0de4da86-3c9c-423f-b1d5-2f17912fb172', 'address': {'slot': '0x08', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}], 'status': 'Down', 'display': 'qxl'} createXmlElem:<bound method Drive.createXmlElem of <vm.Drive object at 0x7f13e8248e10>> device:cdrom deviceId:e6a975b4-42ee-4b82-8f39-39031f664e6a drv:raw getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Drive object at 0x7f13e8248e10>> getXML:<bound method Drive.getXML of <vm.Drive object at 0x7f13e8248e10>> iface:ide index:2 isDiskReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <vm.Drive object at 0x7f13e8248e10>> isVdsmImage:<bound method Drive.isVdsmImage of <vm.Drive object at 0x7f13e8248e10>> log:<logUtils.SimpleLogAdapter instance at 0x7f13d40d7f80> name:hdc networkDev:False path: readonly:True reqsize:0 serial: shared:false specParams:{'path': ''} truesize:0 type:cdrom volExtensionChunk:1024 watermarkLimit:536870912
Traceback (most recent call last):
  File "/usr/share/vdsm/clientIF.py", line 331, in teardownVolumePath
    res = self.irs.teardownImage(drive['domainID'],
  File "/usr/share/vdsm/vm.py", line 1344, in __getitem__
    raise KeyError(key)
KeyError: 'domainID'
Thread-39496::DEBUG::2013-10-09 08:13:23,987::task::579::TaskManager.Task::(_updateState) Task=`ff487095-32fd-4f2d-9812-6fa3da50a37f`::moving from state init -> state preparing
Thread-39496::INFO::2013-10-09 08:13:23,987::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='f9a8f68d-268f-4c44-801a-fabe04741376', spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', imgUUID='8a44bd23-970c-4715-8344-08cf51ff766b', volUUID=None)
Thread-39496::DEBUG::2013-10-09 08:13:23,987::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.f9a8f68d-268f-4c44-801a-fabe04741376`ReqID=`2ff1714f-fc02-471f-95f6-1fc327feb5a2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3282' at 'teardownImage'
Thread-39496::DEBUG::2013-10-09 08:13:23,988::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' for lock type 'shared'
Thread-39496::DEBUG::2013-10-09 08:13:23,988::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' is free. Now locking as 'shared' (1 active user)
Thread-39496::DEBUG::2013-10-09 08:13:23,988::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.f9a8f68d-268f-4c44-801a-fabe04741376`ReqID=`2ff1714f-fc02-471f-95f6-1fc327feb5a2`::Granted request
Thread-39496::DEBUG::2013-10-09 08:13:23,989::task::811::TaskManager.Task::(resourceAcquired) Task=`ff487095-32fd-4f2d-9812-6fa3da50a37f`::_resourcesAcquired: Storage.f9a8f68d-268f-4c44-801a-fabe04741376 (shared)
Thread-39496::DEBUG::2013-10-09 08:13:23,989::task::974::TaskManager.Task::(_decref) Task=`ff487095-32fd-4f2d-9812-6fa3da50a37f`::ref 1 aborting False
Thread-39496::DEBUG::2013-10-09 08:13:23,997::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for 405cd85e-d111-4b1a-b4c1-b93b3d3a1dbc
Thread-39496::DEBUG::2013-10-09 08:13:24,007::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for e81f83fe-fc3f-4b1c-be73-c9495c8565f1
Thread-39496::DEBUG::2013-10-09 08:13:24,017::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for 405cd85e-d111-4b1a-b4c1-b93b3d3a1dbc
Thread-39496::DEBUG::2013-10-09 08:13:24,019::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for 405cd85e-d111-4b1a-b4c1-b93b3d3a1dbc
Thread-39496::DEBUG::2013-10-09 08:13:24,042::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for e81f83fe-fc3f-4b1c-be73-c9495c8565f1
Thread-39496::INFO::2013-10-09 08:13:24,057::image::215::Storage.Image::(getChain) sdUUID=f9a8f68d-268f-4c44-801a-fabe04741376 imgUUID=8a44bd23-970c-4715-8344-08cf51ff766b chain=[<storage.fileVolume.FileVolume object at 0x1389290>, <storage.fileVolume.FileVolume object at 0x1389690>] 
Thread-39496::INFO::2013-10-09 08:13:24,057::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None
Thread-39496::DEBUG::2013-10-09 08:13:24,058::task::1168::TaskManager.Task::(prepare) Task=`ff487095-32fd-4f2d-9812-6fa3da50a37f`::finished: None
Thread-39496::DEBUG::2013-10-09 08:13:24,058::task::579::TaskManager.Task::(_updateState) Task=`ff487095-32fd-4f2d-9812-6fa3da50a37f`::moving from state preparing -> state finished
Thread-39496::DEBUG::2013-10-09 08:13:24,058::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.f9a8f68d-268f-4c44-801a-fabe04741376': < ResourceRef 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376', isValid: 'True' obj: 'None'>}
Thread-39496::DEBUG::2013-10-09 08:13:24,058::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39496::DEBUG::2013-10-09 08:13:24,059::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376'
Thread-39496::DEBUG::2013-10-09 08:13:24,059::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' (0 active users)
Thread-39496::DEBUG::2013-10-09 08:13:24,059::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' is free, finding out if anyone is waiting for it.
Thread-39496::DEBUG::2013-10-09 08:13:24,059::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376', Clearing records.
Thread-39496::DEBUG::2013-10-09 08:13:24,059::task::974::TaskManager.Task::(_decref) Task=`ff487095-32fd-4f2d-9812-6fa3da50a37f`::ref 0 aborting False
Thread-39496::DEBUG::2013-10-09 08:13:24,060::task::579::TaskManager.Task::(_updateState) Task=`bd749c88-ce11-40ba-8572-7e94a33b386e`::moving from state init -> state preparing
Thread-39496::INFO::2013-10-09 08:13:24,060::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='f9a8f68d-268f-4c44-801a-fabe04741376', spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', imgUUID='c40366d6-0fdc-4bb6-adf1-0f1a480779f3', volUUID=None)
Thread-39496::DEBUG::2013-10-09 08:13:24,060::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.f9a8f68d-268f-4c44-801a-fabe04741376`ReqID=`324ddac7-3fdc-4c05-a7c8-f3e5973beee0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3282' at 'teardownImage'
Thread-39496::DEBUG::2013-10-09 08:13:24,061::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' for lock type 'shared'
Thread-39496::DEBUG::2013-10-09 08:13:24,061::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' is free. Now locking as 'shared' (1 active user)
Thread-39496::DEBUG::2013-10-09 08:13:24,061::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.f9a8f68d-268f-4c44-801a-fabe04741376`ReqID=`324ddac7-3fdc-4c05-a7c8-f3e5973beee0`::Granted request
Thread-39496::DEBUG::2013-10-09 08:13:24,061::task::811::TaskManager.Task::(resourceAcquired) Task=`bd749c88-ce11-40ba-8572-7e94a33b386e`::_resourcesAcquired: Storage.f9a8f68d-268f-4c44-801a-fabe04741376 (shared)
Thread-39496::DEBUG::2013-10-09 08:13:24,062::task::974::TaskManager.Task::(_decref) Task=`bd749c88-ce11-40ba-8572-7e94a33b386e`::ref 1 aborting False
Thread-39496::DEBUG::2013-10-09 08:13:24,065::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for 595a7390-ffe8-4d43-a149-64d5e63922af
Thread-39496::DEBUG::2013-10-09 08:13:24,075::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for c611e292-c302-4df7-b741-a7222d2b2afa
Thread-39496::DEBUG::2013-10-09 08:13:24,085::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for 595a7390-ffe8-4d43-a149-64d5e63922af
Thread-39496::DEBUG::2013-10-09 08:13:24,086::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for 595a7390-ffe8-4d43-a149-64d5e63922af
Thread-39496::DEBUG::2013-10-09 08:13:24,095::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for c611e292-c302-4df7-b741-a7222d2b2afa
Thread-39496::DEBUG::2013-10-09 08:13:24,118::fileVolume::520::Storage.Volume::(validateVolumePath) validate path for 595a7390-ffe8-4d43-a149-64d5e63922af
Thread-39496::INFO::2013-10-09 08:13:24,134::image::215::Storage.Image::(getChain) sdUUID=f9a8f68d-268f-4c44-801a-fabe04741376 imgUUID=c40366d6-0fdc-4bb6-adf1-0f1a480779f3 chain=[<storage.fileVolume.FileVolume object at 0x1389cd0>, <storage.fileVolume.FileVolume object at 0x13893d0>] 
Thread-39496::INFO::2013-10-09 08:13:24,134::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None
Thread-39496::DEBUG::2013-10-09 08:13:24,134::task::1168::TaskManager.Task::(prepare) Task=`bd749c88-ce11-40ba-8572-7e94a33b386e`::finished: None
Thread-39496::DEBUG::2013-10-09 08:13:24,134::task::579::TaskManager.Task::(_updateState) Task=`bd749c88-ce11-40ba-8572-7e94a33b386e`::moving from state preparing -> state finished
Thread-39496::DEBUG::2013-10-09 08:13:24,135::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.f9a8f68d-268f-4c44-801a-fabe04741376': < ResourceRef 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376', isValid: 'True' obj: 'None'>}
Thread-39496::DEBUG::2013-10-09 08:13:24,135::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39496::DEBUG::2013-10-09 08:13:24,135::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376'
Thread-39496::DEBUG::2013-10-09 08:13:24,135::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' (0 active users)
Thread-39496::DEBUG::2013-10-09 08:13:24,135::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376' is free, finding out if anyone is waiting for it.
Thread-39496::DEBUG::2013-10-09 08:13:24,136::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f9a8f68d-268f-4c44-801a-fabe04741376', Clearing records.
Thread-39496::DEBUG::2013-10-09 08:13:24,136::task::974::TaskManager.Task::(_decref) Task=`bd749c88-ce11-40ba-8572-7e94a33b386e`::ref 0 aborting False
Thread-39496::DEBUG::2013-10-09 08:13:24,136::task::579::TaskManager.Task::(_updateState) Task=`35f1cd6b-e790-490e-9609-c2eb7256fa94`::moving from state init -> state preparing
Thread-39496::INFO::2013-10-09 08:13:24,137::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='168d5fa1-21a3-47d4-a3bb-9874ffb50876')
Thread-39496::INFO::2013-10-09 08:13:24,138::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
Thread-39496::DEBUG::2013-10-09 08:13:24,138::task::1168::TaskManager.Task::(prepare) Task=`35f1cd6b-e790-490e-9609-c2eb7256fa94`::finished: None
Thread-39496::DEBUG::2013-10-09 08:13:24,139::task::579::TaskManager.Task::(_updateState) Task=`35f1cd6b-e790-490e-9609-c2eb7256fa94`::moving from state preparing -> state finished
Thread-39496::DEBUG::2013-10-09 08:13:24,139::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39496::DEBUG::2013-10-09 08:13:24,139::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39496::DEBUG::2013-10-09 08:13:24,139::task::974::TaskManager.Task::(_decref) Task=`35f1cd6b-e790-490e-9609-c2eb7256fa94`::ref 0 aborting False
Thread-39496::DEBUG::2013-10-09 08:13:24,140::vm::4252::vm.Vm::(deleteVm) vmId=`168d5fa1-21a3-47d4-a3bb-9874ffb50876`::Total desktops after destroy of 168d5fa1-21a3-47d4-a3bb-9874ffb50876 is 0
Thread-39496::DEBUG::2013-10-09 08:13:24,140::BindingXMLRPC::986::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
VM Channels Listener::DEBUG::2013-10-09 08:13:24,319::vmChannels::112::vds::(_do_del_channels) fileno 49 was removed from listener.
Thread-758::DEBUG::2013-10-09 08:13:24,771::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/cloud-001.test.btr.local:_var_lib_exports_iso/03af78e4-8f68-40c3-adce-be2ccda9364f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-758::DEBUG::2013-10-09 08:13:24,781::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.00021659 s, 1.6 MB/s\n'; <rc> = 0
Thread-757::DEBUG::2013-10-09 08:13:26,719::fileSD::238::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/localhost:_volume01/f9a8f68d-268f-4c44-801a-fabe04741376/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-757::DEBUG::2013-10-09 08:13:26,729::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n344 bytes (344 B) copied, 0.000870712 s, 395 kB/s\n'; <rc> = 0
Thread-39497::DEBUG::2013-10-09 08:13:26,944::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39497::DEBUG::2013-10-09 08:13:26,944::task::579::TaskManager.Task::(_updateState) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::moving from state init -> state preparing
Thread-39497::INFO::2013-10-09 08:13:26,945::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39497::ERROR::2013-10-09 08:13:26,945::task::850::TaskManager.Task::(_setError) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2123, in getAllTasksStatuses
    allTasksStatus = sp.getAllTasksStatuses()
  File "/usr/share/vdsm/storage/securable.py", line 66, in wrapper
    raise SecureError()
SecureError
Thread-39497::DEBUG::2013-10-09 08:13:26,945::task::869::TaskManager.Task::(_run) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::Task._run: a8f906fb-bd3d-4210-960e-2d4e4c6ab43c () {} failed - stopping task
Thread-39497::DEBUG::2013-10-09 08:13:26,945::task::1194::TaskManager.Task::(stop) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::stopping in state preparing (force False)
Thread-39497::DEBUG::2013-10-09 08:13:26,946::task::974::TaskManager.Task::(_decref) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::ref 1 aborting True
Thread-39497::INFO::2013-10-09 08:13:26,946::task::1151::TaskManager.Task::(prepare) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::aborting: Task is aborted: u'' - code 100
Thread-39497::DEBUG::2013-10-09 08:13:26,946::task::1156::TaskManager.Task::(prepare) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::Prepare: aborted: 
Thread-39497::DEBUG::2013-10-09 08:13:26,946::task::974::TaskManager.Task::(_decref) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::ref 0 aborting True
Thread-39497::DEBUG::2013-10-09 08:13:26,946::task::909::TaskManager.Task::(_doAbort) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::Task._doAbort: force False
Thread-39497::DEBUG::2013-10-09 08:13:26,947::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39497::DEBUG::2013-10-09 08:13:26,947::task::579::TaskManager.Task::(_updateState) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::moving from state preparing -> state aborting
Thread-39497::DEBUG::2013-10-09 08:13:26,947::task::534::TaskManager.Task::(__state_aborting) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::_aborting: recover policy none
Thread-39497::DEBUG::2013-10-09 08:13:26,947::task::579::TaskManager.Task::(_updateState) Task=`a8f906fb-bd3d-4210-960e-2d4e4c6ab43c`::moving from state aborting -> state failed
Thread-39497::DEBUG::2013-10-09 08:13:26,947::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39497::DEBUG::2013-10-09 08:13:26,947::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39497::ERROR::2013-10-09 08:13:26,948::dispatcher::70::Storage.Dispatcher.Protect::(run) 
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 62, in run
    result = ctask.prepare(self.func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 1159, in prepare
    raise self.error
SecureError
Thread-39498::DEBUG::2013-10-09 08:13:26,957::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39498::DEBUG::2013-10-09 08:13:26,957::task::579::TaskManager.Task::(_updateState) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::moving from state init -> state preparing
Thread-39498::INFO::2013-10-09 08:13:26,957::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39498::DEBUG::2013-10-09 08:13:26,958::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`ce246c2c-b73b-4c37-86ea-ff9140ecfe72`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39498::DEBUG::2013-10-09 08:13:26,958::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39498::DEBUG::2013-10-09 08:13:26,958::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39498::DEBUG::2013-10-09 08:13:26,959::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`ce246c2c-b73b-4c37-86ea-ff9140ecfe72`::Granted request
Thread-39498::DEBUG::2013-10-09 08:13:26,959::task::811::TaskManager.Task::(resourceAcquired) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39498::DEBUG::2013-10-09 08:13:26,959::task::974::TaskManager.Task::(_decref) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::ref 1 aborting False
Thread-39498::ERROR::2013-10-09 08:13:26,959::task::850::TaskManager.Task::(_setError) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 597, in spmStop
    pool.stopSpm()
  File "/usr/share/vdsm/storage/securable.py", line 66, in wrapper
    raise SecureError()
SecureError
Thread-39498::DEBUG::2013-10-09 08:13:26,960::task::869::TaskManager.Task::(_run) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::Task._run: 2f496a90-f9e0-4b5b-b628-5a30cc125ed4 ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39498::DEBUG::2013-10-09 08:13:26,960::task::1194::TaskManager.Task::(stop) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::stopping in state preparing (force False)
Thread-39498::DEBUG::2013-10-09 08:13:26,960::task::974::TaskManager.Task::(_decref) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::ref 1 aborting True
Thread-39498::INFO::2013-10-09 08:13:26,960::task::1151::TaskManager.Task::(prepare) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::aborting: Task is aborted: u'' - code 100
Thread-39498::DEBUG::2013-10-09 08:13:26,960::task::1156::TaskManager.Task::(prepare) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::Prepare: aborted: 
Thread-39498::DEBUG::2013-10-09 08:13:26,961::task::974::TaskManager.Task::(_decref) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::ref 0 aborting True
Thread-39498::DEBUG::2013-10-09 08:13:26,961::task::909::TaskManager.Task::(_doAbort) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::Task._doAbort: force False
Thread-39498::DEBUG::2013-10-09 08:13:26,961::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39498::DEBUG::2013-10-09 08:13:26,961::task::579::TaskManager.Task::(_updateState) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::moving from state preparing -> state aborting
Thread-39498::DEBUG::2013-10-09 08:13:26,961::task::534::TaskManager.Task::(__state_aborting) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::_aborting: recover policy none
Thread-39498::DEBUG::2013-10-09 08:13:26,962::task::579::TaskManager.Task::(_updateState) Task=`2f496a90-f9e0-4b5b-b628-5a30cc125ed4`::moving from state aborting -> state failed
Thread-39498::DEBUG::2013-10-09 08:13:26,962::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39498::DEBUG::2013-10-09 08:13:26,962::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39498::DEBUG::2013-10-09 08:13:26,962::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39498::DEBUG::2013-10-09 08:13:26,962::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39498::DEBUG::2013-10-09 08:13:26,963::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39498::DEBUG::2013-10-09 08:13:26,963::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39498::ERROR::2013-10-09 08:13:26,963::dispatcher::70::Storage.Dispatcher.Protect::(run) 
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 62, in run
    result = ctask.prepare(self.func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 1159, in prepare
    raise self.error
SecureError
Thread-39499::DEBUG::2013-10-09 08:13:27,157::task::579::TaskManager.Task::(_updateState) Task=`0db44208-7eb3-456a-8412-76edf7b64726`::moving from state init -> state preparing
Thread-39499::INFO::2013-10-09 08:13:27,157::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-39499::INFO::2013-10-09 08:13:27,158::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'f9a8f68d-268f-4c44-801a-fabe04741376': {'delay': '0.000870712', 'lastCheck': '0.4', 'code': 0, 'valid': True, 'version': 3}, '03af78e4-8f68-40c3-adce-be2ccda9364f': {'delay': '0.00021659', 'lastCheck': '2.4', 'code': 0, 'valid': True, 'version': 0}, '0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6': {'delay': '0.00083172', 'lastCheck': '5.7', 'code': 0, 'valid': True, 'version': 3}}
Thread-39499::DEBUG::2013-10-09 08:13:27,158::task::1168::TaskManager.Task::(prepare) Task=`0db44208-7eb3-456a-8412-76edf7b64726`::finished: {'f9a8f68d-268f-4c44-801a-fabe04741376': {'delay': '0.000870712', 'lastCheck': '0.4', 'code': 0, 'valid': True, 'version': 3}, '03af78e4-8f68-40c3-adce-be2ccda9364f': {'delay': '0.00021659', 'lastCheck': '2.4', 'code': 0, 'valid': True, 'version': 0}, '0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6': {'delay': '0.00083172', 'lastCheck': '5.7', 'code': 0, 'valid': True, 'version': 3}}
Thread-39499::DEBUG::2013-10-09 08:13:27,158::task::579::TaskManager.Task::(_updateState) Task=`0db44208-7eb3-456a-8412-76edf7b64726`::moving from state preparing -> state finished
Thread-39499::DEBUG::2013-10-09 08:13:27,158::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39499::DEBUG::2013-10-09 08:13:27,158::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39499::DEBUG::2013-10-09 08:13:27,159::task::974::TaskManager.Task::(_decref) Task=`0db44208-7eb3-456a-8412-76edf7b64726`::ref 0 aborting False
Thread-39501::DEBUG::2013-10-09 08:13:27,178::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39501::DEBUG::2013-10-09 08:13:27,179::task::579::TaskManager.Task::(_updateState) Task=`9f9d4b17-52da-4daa-adcc-7e45eb0611db`::moving from state init -> state preparing
Thread-39501::INFO::2013-10-09 08:13:27,179::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStoragePool(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', hostID=1, scsiKey='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', remove=False, options=None)
Thread-39501::DEBUG::2013-10-09 08:13:27,180::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`d766c6e2-ef8a-48a0-bc7a-7aad198375cb`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1080' at 'disconnectStoragePool'
Thread-39501::DEBUG::2013-10-09 08:13:27,180::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39501::DEBUG::2013-10-09 08:13:27,180::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39501::DEBUG::2013-10-09 08:13:27,180::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`d766c6e2-ef8a-48a0-bc7a-7aad198375cb`::Granted request
Thread-39501::DEBUG::2013-10-09 08:13:27,181::task::811::TaskManager.Task::(resourceAcquired) Task=`9f9d4b17-52da-4daa-adcc-7e45eb0611db`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39501::DEBUG::2013-10-09 08:13:27,181::task::974::TaskManager.Task::(_decref) Task=`9f9d4b17-52da-4daa-adcc-7e45eb0611db`::ref 1 aborting False
Thread-39501::INFO::2013-10-09 08:13:27,181::sp::716::Storage.StoragePool::(disconnect) Disconnect from the storage pool b30f1ed0-7643-4d77-bf65-9e54f2b60d30
Thread-757::DEBUG::2013-10-09 08:13:27,182::domainMonitor::161::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for f9a8f68d-268f-4c44-801a-fabe04741376
Thread-757::INFO::2013-10-09 08:13:27,182::clusterlock::197::SANLock::(releaseHostId) Releasing host id for domain f9a8f68d-268f-4c44-801a-fabe04741376 (id: 1)
Thread-757::DEBUG::2013-10-09 08:13:29,183::clusterlock::207::SANLock::(releaseHostId) Host id for domain f9a8f68d-268f-4c44-801a-fabe04741376 released successfully (id: 1)
Thread-758::DEBUG::2013-10-09 08:13:29,183::domainMonitor::161::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 03af78e4-8f68-40c3-adce-be2ccda9364f
Thread-760::DEBUG::2013-10-09 08:13:29,184::domainMonitor::161::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6
Thread-760::INFO::2013-10-09 08:13:29,184::clusterlock::197::SANLock::(releaseHostId) Releasing host id for domain 0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6 (id: 1)
Thread-760::DEBUG::2013-10-09 08:13:31,185::clusterlock::207::SANLock::(releaseHostId) Host id for domain 0c2417df-bea3-42a7-b10d-0b6a3e9e8ee6 released successfully (id: 1)
Thread-39501::INFO::2013-10-09 08:13:31,185::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStoragePool, Return response: True
Thread-39501::DEBUG::2013-10-09 08:13:31,186::task::1168::TaskManager.Task::(prepare) Task=`9f9d4b17-52da-4daa-adcc-7e45eb0611db`::finished: True
Thread-39501::DEBUG::2013-10-09 08:13:31,186::task::579::TaskManager.Task::(_updateState) Task=`9f9d4b17-52da-4daa-adcc-7e45eb0611db`::moving from state preparing -> state finished
Thread-39501::DEBUG::2013-10-09 08:13:31,186::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39501::DEBUG::2013-10-09 08:13:31,186::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39501::DEBUG::2013-10-09 08:13:31,186::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39501::DEBUG::2013-10-09 08:13:31,187::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39501::DEBUG::2013-10-09 08:13:31,187::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39501::DEBUG::2013-10-09 08:13:31,187::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39501::DEBUG::2013-10-09 08:13:31,187::task::974::TaskManager.Task::(_decref) Task=`9f9d4b17-52da-4daa-adcc-7e45eb0611db`::ref 0 aborting False
Thread-39502::DEBUG::2013-10-09 08:13:31,211::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39502::DEBUG::2013-10-09 08:13:31,211::task::579::TaskManager.Task::(_updateState) Task=`9aa5e805-08f0-40d4-9b2c-c0c97dfe93a5`::moving from state init -> state preparing
Thread-39502::INFO::2013-10-09 08:13:31,211::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=6, spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', conList=[{'port': '', 'connection': 'localhost:/GLUSTER-VMSTORE01', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'glusterfs', 'password': '******', 'id': 'e6ec718b-b349-4f58-9903-20a3a7e11403'}, {'port': '', 'connection': 'localhost:/volume01', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'glusterfs', 'password': '******', 'id': '76fd9d81-d1b8-41f8-b0f1-29812183059e'}], options=None)
Thread-39502::DEBUG::2013-10-09 08:13:31,212::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/localhost:_GLUSTER-VMSTORE01' (cwd None)
Thread-39502::DEBUG::2013-10-09 08:13:31,251::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/localhost:_volume01' (cwd None)
Thread-39502::DEBUG::2013-10-09 08:13:31,297::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-39502::DEBUG::2013-10-09 08:13:31,298::misc::809::SamplingMethod::(__call__) Got in to sampling method
Thread-39502::DEBUG::2013-10-09 08:13:31,298::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-39502::DEBUG::2013-10-09 08:13:31,298::misc::809::SamplingMethod::(__call__) Got in to sampling method
Thread-39502::DEBUG::2013-10-09 08:13:31,298::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-39502::DEBUG::2013-10-09 08:13:31,314::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-39502::DEBUG::2013-10-09 08:13:31,315::misc::817::SamplingMethod::(__call__) Returning last result
Thread-39502::DEBUG::2013-10-09 08:13:33,337::multipath::111::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-39502::DEBUG::2013-10-09 08:13:33,443::multipath::111::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-39502::DEBUG::2013-10-09 08:13:33,445::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-39502::DEBUG::2013-10-09 08:13:33,445::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-39502::DEBUG::2013-10-09 08:13:33,445::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-39502::DEBUG::2013-10-09 08:13:33,445::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-39502::DEBUG::2013-10-09 08:13:33,446::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-39502::DEBUG::2013-10-09 08:13:33,446::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-39502::DEBUG::2013-10-09 08:13:33,446::misc::817::SamplingMethod::(__call__) Returning last result
Thread-39502::INFO::2013-10-09 08:13:33,446::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'e6ec718b-b349-4f58-9903-20a3a7e11403'}, {'status': 0, 'id': '76fd9d81-d1b8-41f8-b0f1-29812183059e'}]}
Thread-39502::DEBUG::2013-10-09 08:13:33,447::task::1168::TaskManager.Task::(prepare) Task=`9aa5e805-08f0-40d4-9b2c-c0c97dfe93a5`::finished: {'statuslist': [{'status': 0, 'id': 'e6ec718b-b349-4f58-9903-20a3a7e11403'}, {'status': 0, 'id': '76fd9d81-d1b8-41f8-b0f1-29812183059e'}]}
Thread-39502::DEBUG::2013-10-09 08:13:33,447::task::579::TaskManager.Task::(_updateState) Task=`9aa5e805-08f0-40d4-9b2c-c0c97dfe93a5`::moving from state preparing -> state finished
Thread-39502::DEBUG::2013-10-09 08:13:33,447::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39502::DEBUG::2013-10-09 08:13:33,447::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39502::DEBUG::2013-10-09 08:13:33,447::task::974::TaskManager.Task::(_decref) Task=`9aa5e805-08f0-40d4-9b2c-c0c97dfe93a5`::ref 0 aborting False
Thread-39503::DEBUG::2013-10-09 08:13:33,458::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39503::DEBUG::2013-10-09 08:13:33,458::task::579::TaskManager.Task::(_updateState) Task=`10a039c8-fa73-492f-a5c4-c82987657c6f`::moving from state init -> state preparing
Thread-39503::INFO::2013-10-09 08:13:33,459::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', conList=[{'connection': 'cloud-001.test.btr.local:/var/lib/exports/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'bb4b5750-bd92-46c9-b0f8-919f0dfd8742', 'port': ''}], options=None)
Thread-39503::DEBUG::2013-10-09 08:13:33,459::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/cloud-001.test.btr.local:_var_lib_exports_iso' (cwd None)
Thread-39503::DEBUG::2013-10-09 08:13:33,498::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-39503::DEBUG::2013-10-09 08:13:33,499::misc::809::SamplingMethod::(__call__) Got in to sampling method
Thread-39503::DEBUG::2013-10-09 08:13:33,499::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-39503::DEBUG::2013-10-09 08:13:33,499::misc::809::SamplingMethod::(__call__) Got in to sampling method
Thread-39503::DEBUG::2013-10-09 08:13:33,500::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-39503::DEBUG::2013-10-09 08:13:33,514::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-39503::DEBUG::2013-10-09 08:13:33,515::misc::817::SamplingMethod::(__call__) Returning last result
Thread-39503::DEBUG::2013-10-09 08:13:36,535::multipath::111::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-39503::DEBUG::2013-10-09 08:13:36,590::multipath::111::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-39503::DEBUG::2013-10-09 08:13:36,591::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-39503::DEBUG::2013-10-09 08:13:36,591::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-39503::DEBUG::2013-10-09 08:13:36,591::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-39503::DEBUG::2013-10-09 08:13:36,591::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-39503::DEBUG::2013-10-09 08:13:36,592::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-39503::DEBUG::2013-10-09 08:13:36,592::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-39503::DEBUG::2013-10-09 08:13:36,592::misc::817::SamplingMethod::(__call__) Returning last result
Thread-39503::INFO::2013-10-09 08:13:36,592::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'bb4b5750-bd92-46c9-b0f8-919f0dfd8742'}]}
Thread-39503::DEBUG::2013-10-09 08:13:36,593::task::1168::TaskManager.Task::(prepare) Task=`10a039c8-fa73-492f-a5c4-c82987657c6f`::finished: {'statuslist': [{'status': 0, 'id': 'bb4b5750-bd92-46c9-b0f8-919f0dfd8742'}]}
Thread-39503::DEBUG::2013-10-09 08:13:36,593::task::579::TaskManager.Task::(_updateState) Task=`10a039c8-fa73-492f-a5c4-c82987657c6f`::moving from state preparing -> state finished
Thread-39503::DEBUG::2013-10-09 08:13:36,593::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39503::DEBUG::2013-10-09 08:13:36,593::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39503::DEBUG::2013-10-09 08:13:36,593::task::974::TaskManager.Task::(_decref) Task=`10a039c8-fa73-492f-a5c4-c82987657c6f`::ref 0 aborting False
Thread-39504::DEBUG::2013-10-09 08:13:36,985::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39504::DEBUG::2013-10-09 08:13:36,985::task::579::TaskManager.Task::(_updateState) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::moving from state init -> state preparing
Thread-39504::INFO::2013-10-09 08:13:36,986::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39504::ERROR::2013-10-09 08:13:36,986::task::850::TaskManager.Task::(_setError) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39504::DEBUG::2013-10-09 08:13:36,987::task::869::TaskManager.Task::(_run) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::Task._run: 7f032d8e-a3d3-410e-8739-89883c6ee305 () {} failed - stopping task
Thread-39504::DEBUG::2013-10-09 08:13:36,987::task::1194::TaskManager.Task::(stop) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::stopping in state preparing (force False)
Thread-39504::DEBUG::2013-10-09 08:13:36,988::task::974::TaskManager.Task::(_decref) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::ref 1 aborting True
Thread-39504::INFO::2013-10-09 08:13:36,988::task::1151::TaskManager.Task::(prepare) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39504::DEBUG::2013-10-09 08:13:36,988::task::1156::TaskManager.Task::(prepare) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::Prepare: aborted: Not SPM
Thread-39504::DEBUG::2013-10-09 08:13:36,988::task::974::TaskManager.Task::(_decref) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::ref 0 aborting True
Thread-39504::DEBUG::2013-10-09 08:13:36,988::task::909::TaskManager.Task::(_doAbort) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::Task._doAbort: force False
Thread-39504::DEBUG::2013-10-09 08:13:36,989::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39504::DEBUG::2013-10-09 08:13:36,989::task::579::TaskManager.Task::(_updateState) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::moving from state preparing -> state aborting
Thread-39504::DEBUG::2013-10-09 08:13:36,989::task::534::TaskManager.Task::(__state_aborting) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::_aborting: recover policy none
Thread-39504::DEBUG::2013-10-09 08:13:36,989::task::579::TaskManager.Task::(_updateState) Task=`7f032d8e-a3d3-410e-8739-89883c6ee305`::moving from state aborting -> state failed
Thread-39504::DEBUG::2013-10-09 08:13:36,989::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39504::DEBUG::2013-10-09 08:13:36,990::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39504::ERROR::2013-10-09 08:13:36,990::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39505::DEBUG::2013-10-09 08:13:36,997::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39505::DEBUG::2013-10-09 08:13:36,997::task::579::TaskManager.Task::(_updateState) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::moving from state init -> state preparing
Thread-39505::INFO::2013-10-09 08:13:36,998::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39505::DEBUG::2013-10-09 08:13:36,998::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`039a648b-a0b1-4f7b-a1e5-29dac054acc2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39505::DEBUG::2013-10-09 08:13:36,998::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39505::DEBUG::2013-10-09 08:13:36,999::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39505::DEBUG::2013-10-09 08:13:36,999::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`039a648b-a0b1-4f7b-a1e5-29dac054acc2`::Granted request
Thread-39505::DEBUG::2013-10-09 08:13:36,999::task::811::TaskManager.Task::(resourceAcquired) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39505::DEBUG::2013-10-09 08:13:36,999::task::974::TaskManager.Task::(_decref) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::ref 1 aborting False
Thread-39505::ERROR::2013-10-09 08:13:37,000::task::850::TaskManager.Task::(_setError) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39505::DEBUG::2013-10-09 08:13:37,000::task::869::TaskManager.Task::(_run) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::Task._run: e0aaad92-0657-48fa-91d7-1ee89a4e82de ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39505::DEBUG::2013-10-09 08:13:37,000::task::1194::TaskManager.Task::(stop) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::stopping in state preparing (force False)
Thread-39505::DEBUG::2013-10-09 08:13:37,000::task::974::TaskManager.Task::(_decref) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::ref 1 aborting True
Thread-39505::INFO::2013-10-09 08:13:37,001::task::1151::TaskManager.Task::(prepare) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39505::DEBUG::2013-10-09 08:13:37,001::task::1156::TaskManager.Task::(prepare) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39505::DEBUG::2013-10-09 08:13:37,001::task::974::TaskManager.Task::(_decref) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::ref 0 aborting True
Thread-39505::DEBUG::2013-10-09 08:13:37,001::task::909::TaskManager.Task::(_doAbort) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::Task._doAbort: force False
Thread-39505::DEBUG::2013-10-09 08:13:37,001::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39505::DEBUG::2013-10-09 08:13:37,002::task::579::TaskManager.Task::(_updateState) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::moving from state preparing -> state aborting
Thread-39505::DEBUG::2013-10-09 08:13:37,002::task::534::TaskManager.Task::(__state_aborting) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::_aborting: recover policy none
Thread-39505::DEBUG::2013-10-09 08:13:37,002::task::579::TaskManager.Task::(_updateState) Task=`e0aaad92-0657-48fa-91d7-1ee89a4e82de`::moving from state aborting -> state failed
Thread-39505::DEBUG::2013-10-09 08:13:37,002::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39505::DEBUG::2013-10-09 08:13:37,002::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39505::DEBUG::2013-10-09 08:13:37,002::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39505::DEBUG::2013-10-09 08:13:37,003::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39505::DEBUG::2013-10-09 08:13:37,003::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39505::DEBUG::2013-10-09 08:13:37,003::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39505::ERROR::2013-10-09 08:13:37,003::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39506::DEBUG::2013-10-09 08:13:47,029::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39506::DEBUG::2013-10-09 08:13:47,032::task::579::TaskManager.Task::(_updateState) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::moving from state init -> state preparing
Thread-39506::INFO::2013-10-09 08:13:47,032::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39506::ERROR::2013-10-09 08:13:47,032::task::850::TaskManager.Task::(_setError) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39506::DEBUG::2013-10-09 08:13:47,032::task::869::TaskManager.Task::(_run) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::Task._run: 786199e8-8fa9-4eb6-9a70-cffc1dbc79fe () {} failed - stopping task
Thread-39506::DEBUG::2013-10-09 08:13:47,033::task::1194::TaskManager.Task::(stop) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::stopping in state preparing (force False)
Thread-39506::DEBUG::2013-10-09 08:13:47,033::task::974::TaskManager.Task::(_decref) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::ref 1 aborting True
Thread-39506::INFO::2013-10-09 08:13:47,033::task::1151::TaskManager.Task::(prepare) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39506::DEBUG::2013-10-09 08:13:47,033::task::1156::TaskManager.Task::(prepare) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::Prepare: aborted: Not SPM
Thread-39506::DEBUG::2013-10-09 08:13:47,033::task::974::TaskManager.Task::(_decref) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::ref 0 aborting True
Thread-39506::DEBUG::2013-10-09 08:13:47,033::task::909::TaskManager.Task::(_doAbort) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::Task._doAbort: force False
Thread-39506::DEBUG::2013-10-09 08:13:47,033::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39506::DEBUG::2013-10-09 08:13:47,034::task::579::TaskManager.Task::(_updateState) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::moving from state preparing -> state aborting
Thread-39506::DEBUG::2013-10-09 08:13:47,034::task::534::TaskManager.Task::(__state_aborting) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::_aborting: recover policy none
Thread-39506::DEBUG::2013-10-09 08:13:47,034::task::579::TaskManager.Task::(_updateState) Task=`786199e8-8fa9-4eb6-9a70-cffc1dbc79fe`::moving from state aborting -> state failed
Thread-39506::DEBUG::2013-10-09 08:13:47,034::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39506::DEBUG::2013-10-09 08:13:47,034::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39506::ERROR::2013-10-09 08:13:47,034::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39507::DEBUG::2013-10-09 08:13:47,042::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39507::DEBUG::2013-10-09 08:13:47,042::task::579::TaskManager.Task::(_updateState) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::moving from state init -> state preparing
Thread-39507::INFO::2013-10-09 08:13:47,043::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39507::DEBUG::2013-10-09 08:13:47,043::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`7823a06a-4330-49b4-b14e-8748990f7ba0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39507::DEBUG::2013-10-09 08:13:47,043::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39507::DEBUG::2013-10-09 08:13:47,043::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39507::DEBUG::2013-10-09 08:13:47,044::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`7823a06a-4330-49b4-b14e-8748990f7ba0`::Granted request
Thread-39507::DEBUG::2013-10-09 08:13:47,044::task::811::TaskManager.Task::(resourceAcquired) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39507::DEBUG::2013-10-09 08:13:47,044::task::974::TaskManager.Task::(_decref) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::ref 1 aborting False
Thread-39507::ERROR::2013-10-09 08:13:47,044::task::850::TaskManager.Task::(_setError) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39507::DEBUG::2013-10-09 08:13:47,045::task::869::TaskManager.Task::(_run) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::Task._run: 17cf6e01-1721-410a-9976-cc065cf083dd ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39507::DEBUG::2013-10-09 08:13:47,045::task::1194::TaskManager.Task::(stop) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::stopping in state preparing (force False)
Thread-39507::DEBUG::2013-10-09 08:13:47,045::task::974::TaskManager.Task::(_decref) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::ref 1 aborting True
Thread-39507::INFO::2013-10-09 08:13:47,045::task::1151::TaskManager.Task::(prepare) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39507::DEBUG::2013-10-09 08:13:47,045::task::1156::TaskManager.Task::(prepare) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39507::DEBUG::2013-10-09 08:13:47,045::task::974::TaskManager.Task::(_decref) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::ref 0 aborting True
Thread-39507::DEBUG::2013-10-09 08:13:47,046::task::909::TaskManager.Task::(_doAbort) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::Task._doAbort: force False
Thread-39507::DEBUG::2013-10-09 08:13:47,046::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39507::DEBUG::2013-10-09 08:13:47,046::task::579::TaskManager.Task::(_updateState) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::moving from state preparing -> state aborting
Thread-39507::DEBUG::2013-10-09 08:13:47,046::task::534::TaskManager.Task::(__state_aborting) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::_aborting: recover policy none
Thread-39507::DEBUG::2013-10-09 08:13:47,046::task::579::TaskManager.Task::(_updateState) Task=`17cf6e01-1721-410a-9976-cc065cf083dd`::moving from state aborting -> state failed
Thread-39507::DEBUG::2013-10-09 08:13:47,046::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39507::DEBUG::2013-10-09 08:13:47,047::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39507::DEBUG::2013-10-09 08:13:47,047::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39507::DEBUG::2013-10-09 08:13:47,047::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39507::DEBUG::2013-10-09 08:13:47,047::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39507::DEBUG::2013-10-09 08:13:47,047::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39507::ERROR::2013-10-09 08:13:47,047::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39508::DEBUG::2013-10-09 08:13:57,071::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39508::DEBUG::2013-10-09 08:13:57,072::task::579::TaskManager.Task::(_updateState) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::moving from state init -> state preparing
Thread-39508::INFO::2013-10-09 08:13:57,073::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39508::ERROR::2013-10-09 08:13:57,073::task::850::TaskManager.Task::(_setError) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39508::DEBUG::2013-10-09 08:13:57,073::task::869::TaskManager.Task::(_run) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::Task._run: d4eafdaa-1892-4683-b935-1b8773e0de05 () {} failed - stopping task
Thread-39508::DEBUG::2013-10-09 08:13:57,073::task::1194::TaskManager.Task::(stop) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::stopping in state preparing (force False)
Thread-39508::DEBUG::2013-10-09 08:13:57,073::task::974::TaskManager.Task::(_decref) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::ref 1 aborting True
Thread-39508::INFO::2013-10-09 08:13:57,074::task::1151::TaskManager.Task::(prepare) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39508::DEBUG::2013-10-09 08:13:57,074::task::1156::TaskManager.Task::(prepare) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::Prepare: aborted: Not SPM
Thread-39508::DEBUG::2013-10-09 08:13:57,074::task::974::TaskManager.Task::(_decref) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::ref 0 aborting True
Thread-39508::DEBUG::2013-10-09 08:13:57,074::task::909::TaskManager.Task::(_doAbort) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::Task._doAbort: force False
Thread-39508::DEBUG::2013-10-09 08:13:57,074::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39508::DEBUG::2013-10-09 08:13:57,074::task::579::TaskManager.Task::(_updateState) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::moving from state preparing -> state aborting
Thread-39508::DEBUG::2013-10-09 08:13:57,075::task::534::TaskManager.Task::(__state_aborting) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::_aborting: recover policy none
Thread-39508::DEBUG::2013-10-09 08:13:57,075::task::579::TaskManager.Task::(_updateState) Task=`d4eafdaa-1892-4683-b935-1b8773e0de05`::moving from state aborting -> state failed
Thread-39508::DEBUG::2013-10-09 08:13:57,075::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39508::DEBUG::2013-10-09 08:13:57,075::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39508::ERROR::2013-10-09 08:13:57,075::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39509::DEBUG::2013-10-09 08:13:57,083::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39509::DEBUG::2013-10-09 08:13:57,083::task::579::TaskManager.Task::(_updateState) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::moving from state init -> state preparing
Thread-39509::INFO::2013-10-09 08:13:57,083::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39509::DEBUG::2013-10-09 08:13:57,084::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`14e5d997-e63f-4530-b328-43337c831023`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39509::DEBUG::2013-10-09 08:13:57,084::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39509::DEBUG::2013-10-09 08:13:57,084::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39509::DEBUG::2013-10-09 08:13:57,084::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`14e5d997-e63f-4530-b328-43337c831023`::Granted request
Thread-39509::DEBUG::2013-10-09 08:13:57,085::task::811::TaskManager.Task::(resourceAcquired) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39509::DEBUG::2013-10-09 08:13:57,085::task::974::TaskManager.Task::(_decref) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::ref 1 aborting False
Thread-39509::ERROR::2013-10-09 08:13:57,085::task::850::TaskManager.Task::(_setError) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39509::DEBUG::2013-10-09 08:13:57,085::task::869::TaskManager.Task::(_run) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::Task._run: 605e5474-762b-4e3a-b4c4-e94de9744048 ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39509::DEBUG::2013-10-09 08:13:57,085::task::1194::TaskManager.Task::(stop) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::stopping in state preparing (force False)
Thread-39509::DEBUG::2013-10-09 08:13:57,086::task::974::TaskManager.Task::(_decref) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::ref 1 aborting True
Thread-39509::INFO::2013-10-09 08:13:57,086::task::1151::TaskManager.Task::(prepare) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39509::DEBUG::2013-10-09 08:13:57,086::task::1156::TaskManager.Task::(prepare) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39509::DEBUG::2013-10-09 08:13:57,086::task::974::TaskManager.Task::(_decref) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::ref 0 aborting True
Thread-39509::DEBUG::2013-10-09 08:13:57,086::task::909::TaskManager.Task::(_doAbort) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::Task._doAbort: force False
Thread-39509::DEBUG::2013-10-09 08:13:57,086::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39509::DEBUG::2013-10-09 08:13:57,086::task::579::TaskManager.Task::(_updateState) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::moving from state preparing -> state aborting
Thread-39509::DEBUG::2013-10-09 08:13:57,087::task::534::TaskManager.Task::(__state_aborting) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::_aborting: recover policy none
Thread-39509::DEBUG::2013-10-09 08:13:57,087::task::579::TaskManager.Task::(_updateState) Task=`605e5474-762b-4e3a-b4c4-e94de9744048`::moving from state aborting -> state failed
Thread-39509::DEBUG::2013-10-09 08:13:57,087::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39509::DEBUG::2013-10-09 08:13:57,087::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39509::DEBUG::2013-10-09 08:13:57,087::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39509::DEBUG::2013-10-09 08:13:57,087::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39509::DEBUG::2013-10-09 08:13:57,088::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39509::DEBUG::2013-10-09 08:13:57,088::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39509::ERROR::2013-10-09 08:13:57,088::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39510::DEBUG::2013-10-09 08:14:07,107::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39510::DEBUG::2013-10-09 08:14:07,107::task::579::TaskManager.Task::(_updateState) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::moving from state init -> state preparing
Thread-39510::INFO::2013-10-09 08:14:07,108::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39510::ERROR::2013-10-09 08:14:07,108::task::850::TaskManager.Task::(_setError) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39510::DEBUG::2013-10-09 08:14:07,108::task::869::TaskManager.Task::(_run) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::Task._run: 2077cb85-2717-4bb9-82c7-ecd9f3011e40 () {} failed - stopping task
Thread-39510::DEBUG::2013-10-09 08:14:07,108::task::1194::TaskManager.Task::(stop) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::stopping in state preparing (force False)
Thread-39510::DEBUG::2013-10-09 08:14:07,108::task::974::TaskManager.Task::(_decref) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::ref 1 aborting True
Thread-39510::INFO::2013-10-09 08:14:07,109::task::1151::TaskManager.Task::(prepare) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39510::DEBUG::2013-10-09 08:14:07,109::task::1156::TaskManager.Task::(prepare) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::Prepare: aborted: Not SPM
Thread-39510::DEBUG::2013-10-09 08:14:07,109::task::974::TaskManager.Task::(_decref) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::ref 0 aborting True
Thread-39510::DEBUG::2013-10-09 08:14:07,109::task::909::TaskManager.Task::(_doAbort) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::Task._doAbort: force False
Thread-39510::DEBUG::2013-10-09 08:14:07,109::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39510::DEBUG::2013-10-09 08:14:07,109::task::579::TaskManager.Task::(_updateState) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::moving from state preparing -> state aborting
Thread-39510::DEBUG::2013-10-09 08:14:07,109::task::534::TaskManager.Task::(__state_aborting) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::_aborting: recover policy none
Thread-39510::DEBUG::2013-10-09 08:14:07,110::task::579::TaskManager.Task::(_updateState) Task=`2077cb85-2717-4bb9-82c7-ecd9f3011e40`::moving from state aborting -> state failed
Thread-39510::DEBUG::2013-10-09 08:14:07,110::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39510::DEBUG::2013-10-09 08:14:07,110::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39510::ERROR::2013-10-09 08:14:07,110::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39511::DEBUG::2013-10-09 08:14:07,116::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39511::DEBUG::2013-10-09 08:14:07,116::task::579::TaskManager.Task::(_updateState) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::moving from state init -> state preparing
Thread-39511::INFO::2013-10-09 08:14:07,116::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39511::DEBUG::2013-10-09 08:14:07,117::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`f3452b6b-e459-45ad-a7e1-3481179ca9e8`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39511::DEBUG::2013-10-09 08:14:07,117::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39511::DEBUG::2013-10-09 08:14:07,117::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39511::DEBUG::2013-10-09 08:14:07,117::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`f3452b6b-e459-45ad-a7e1-3481179ca9e8`::Granted request
Thread-39511::DEBUG::2013-10-09 08:14:07,118::task::811::TaskManager.Task::(resourceAcquired) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39511::DEBUG::2013-10-09 08:14:07,118::task::974::TaskManager.Task::(_decref) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::ref 1 aborting False
Thread-39511::ERROR::2013-10-09 08:14:07,118::task::850::TaskManager.Task::(_setError) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39511::DEBUG::2013-10-09 08:14:07,118::task::869::TaskManager.Task::(_run) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::Task._run: f520d149-88da-4caa-888f-1501dcf47f38 ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39511::DEBUG::2013-10-09 08:14:07,119::task::1194::TaskManager.Task::(stop) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::stopping in state preparing (force False)
Thread-39511::DEBUG::2013-10-09 08:14:07,119::task::974::TaskManager.Task::(_decref) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::ref 1 aborting True
Thread-39511::INFO::2013-10-09 08:14:07,119::task::1151::TaskManager.Task::(prepare) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39511::DEBUG::2013-10-09 08:14:07,119::task::1156::TaskManager.Task::(prepare) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39511::DEBUG::2013-10-09 08:14:07,119::task::974::TaskManager.Task::(_decref) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::ref 0 aborting True
Thread-39511::DEBUG::2013-10-09 08:14:07,119::task::909::TaskManager.Task::(_doAbort) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::Task._doAbort: force False
Thread-39511::DEBUG::2013-10-09 08:14:07,119::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39511::DEBUG::2013-10-09 08:14:07,120::task::579::TaskManager.Task::(_updateState) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::moving from state preparing -> state aborting
Thread-39511::DEBUG::2013-10-09 08:14:07,120::task::534::TaskManager.Task::(__state_aborting) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::_aborting: recover policy none
Thread-39511::DEBUG::2013-10-09 08:14:07,120::task::579::TaskManager.Task::(_updateState) Task=`f520d149-88da-4caa-888f-1501dcf47f38`::moving from state aborting -> state failed
Thread-39511::DEBUG::2013-10-09 08:14:07,120::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39511::DEBUG::2013-10-09 08:14:07,120::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39511::DEBUG::2013-10-09 08:14:07,120::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39511::DEBUG::2013-10-09 08:14:07,120::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39511::DEBUG::2013-10-09 08:14:07,121::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39511::DEBUG::2013-10-09 08:14:07,121::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39511::ERROR::2013-10-09 08:14:07,121::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39512::DEBUG::2013-10-09 08:14:17,141::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39512::DEBUG::2013-10-09 08:14:17,143::task::579::TaskManager.Task::(_updateState) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::moving from state init -> state preparing
Thread-39512::INFO::2013-10-09 08:14:17,143::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39512::ERROR::2013-10-09 08:14:17,144::task::850::TaskManager.Task::(_setError) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39512::DEBUG::2013-10-09 08:14:17,144::task::869::TaskManager.Task::(_run) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::Task._run: caccbf0e-61d7-4b5c-a64a-63a15ddfcc53 () {} failed - stopping task
Thread-39512::DEBUG::2013-10-09 08:14:17,144::task::1194::TaskManager.Task::(stop) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::stopping in state preparing (force False)
Thread-39512::DEBUG::2013-10-09 08:14:17,144::task::974::TaskManager.Task::(_decref) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::ref 1 aborting True
Thread-39512::INFO::2013-10-09 08:14:17,144::task::1151::TaskManager.Task::(prepare) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39512::DEBUG::2013-10-09 08:14:17,145::task::1156::TaskManager.Task::(prepare) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::Prepare: aborted: Not SPM
Thread-39512::DEBUG::2013-10-09 08:14:17,145::task::974::TaskManager.Task::(_decref) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::ref 0 aborting True
Thread-39512::DEBUG::2013-10-09 08:14:17,145::task::909::TaskManager.Task::(_doAbort) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::Task._doAbort: force False
Thread-39512::DEBUG::2013-10-09 08:14:17,145::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39512::DEBUG::2013-10-09 08:14:17,145::task::579::TaskManager.Task::(_updateState) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::moving from state preparing -> state aborting
Thread-39512::DEBUG::2013-10-09 08:14:17,145::task::534::TaskManager.Task::(__state_aborting) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::_aborting: recover policy none
Thread-39512::DEBUG::2013-10-09 08:14:17,145::task::579::TaskManager.Task::(_updateState) Task=`caccbf0e-61d7-4b5c-a64a-63a15ddfcc53`::moving from state aborting -> state failed
Thread-39512::DEBUG::2013-10-09 08:14:17,146::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39512::DEBUG::2013-10-09 08:14:17,146::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39512::ERROR::2013-10-09 08:14:17,146::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39513::DEBUG::2013-10-09 08:14:17,152::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39513::DEBUG::2013-10-09 08:14:17,153::task::579::TaskManager.Task::(_updateState) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::moving from state init -> state preparing
Thread-39513::INFO::2013-10-09 08:14:17,153::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39513::DEBUG::2013-10-09 08:14:17,153::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`dd61229b-0237-4036-8441-899d81d3610a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39513::DEBUG::2013-10-09 08:14:17,153::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39513::DEBUG::2013-10-09 08:14:17,154::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39513::DEBUG::2013-10-09 08:14:17,154::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`dd61229b-0237-4036-8441-899d81d3610a`::Granted request
Thread-39513::DEBUG::2013-10-09 08:14:17,154::task::811::TaskManager.Task::(resourceAcquired) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39513::DEBUG::2013-10-09 08:14:17,154::task::974::TaskManager.Task::(_decref) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::ref 1 aborting False
Thread-39513::ERROR::2013-10-09 08:14:17,155::task::850::TaskManager.Task::(_setError) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39513::DEBUG::2013-10-09 08:14:17,155::task::869::TaskManager.Task::(_run) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::Task._run: 6d91e588-a017-45e3-a5e4-d25bd962835e ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39513::DEBUG::2013-10-09 08:14:17,155::task::1194::TaskManager.Task::(stop) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::stopping in state preparing (force False)
Thread-39513::DEBUG::2013-10-09 08:14:17,155::task::974::TaskManager.Task::(_decref) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::ref 1 aborting True
Thread-39513::INFO::2013-10-09 08:14:17,155::task::1151::TaskManager.Task::(prepare) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39513::DEBUG::2013-10-09 08:14:17,155::task::1156::TaskManager.Task::(prepare) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39513::DEBUG::2013-10-09 08:14:17,156::task::974::TaskManager.Task::(_decref) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::ref 0 aborting True
Thread-39513::DEBUG::2013-10-09 08:14:17,156::task::909::TaskManager.Task::(_doAbort) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::Task._doAbort: force False
Thread-39513::DEBUG::2013-10-09 08:14:17,156::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39513::DEBUG::2013-10-09 08:14:17,156::task::579::TaskManager.Task::(_updateState) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::moving from state preparing -> state aborting
Thread-39513::DEBUG::2013-10-09 08:14:17,156::task::534::TaskManager.Task::(__state_aborting) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::_aborting: recover policy none
Thread-39513::DEBUG::2013-10-09 08:14:17,156::task::579::TaskManager.Task::(_updateState) Task=`6d91e588-a017-45e3-a5e4-d25bd962835e`::moving from state aborting -> state failed
Thread-39513::DEBUG::2013-10-09 08:14:17,156::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39513::DEBUG::2013-10-09 08:14:17,157::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39513::DEBUG::2013-10-09 08:14:17,157::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39513::DEBUG::2013-10-09 08:14:17,157::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39513::DEBUG::2013-10-09 08:14:17,157::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39513::DEBUG::2013-10-09 08:14:17,157::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39513::ERROR::2013-10-09 08:14:17,157::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39514::DEBUG::2013-10-09 08:14:27,189::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39514::DEBUG::2013-10-09 08:14:27,190::task::579::TaskManager.Task::(_updateState) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::moving from state init -> state preparing
Thread-39514::INFO::2013-10-09 08:14:27,190::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39514::ERROR::2013-10-09 08:14:27,190::task::850::TaskManager.Task::(_setError) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39514::DEBUG::2013-10-09 08:14:27,191::task::869::TaskManager.Task::(_run) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::Task._run: 4913daf7-db99-48cf-8e40-ddb73ff9fabc () {} failed - stopping task
Thread-39514::DEBUG::2013-10-09 08:14:27,191::task::1194::TaskManager.Task::(stop) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::stopping in state preparing (force False)
Thread-39514::DEBUG::2013-10-09 08:14:27,191::task::974::TaskManager.Task::(_decref) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::ref 1 aborting True
Thread-39514::INFO::2013-10-09 08:14:27,191::task::1151::TaskManager.Task::(prepare) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39514::DEBUG::2013-10-09 08:14:27,191::task::1156::TaskManager.Task::(prepare) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::Prepare: aborted: Not SPM
Thread-39514::DEBUG::2013-10-09 08:14:27,191::task::974::TaskManager.Task::(_decref) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::ref 0 aborting True
Thread-39514::DEBUG::2013-10-09 08:14:27,192::task::909::TaskManager.Task::(_doAbort) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::Task._doAbort: force False
Thread-39514::DEBUG::2013-10-09 08:14:27,192::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39514::DEBUG::2013-10-09 08:14:27,192::task::579::TaskManager.Task::(_updateState) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::moving from state preparing -> state aborting
Thread-39514::DEBUG::2013-10-09 08:14:27,192::task::534::TaskManager.Task::(__state_aborting) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::_aborting: recover policy none
Thread-39514::DEBUG::2013-10-09 08:14:27,192::task::579::TaskManager.Task::(_updateState) Task=`4913daf7-db99-48cf-8e40-ddb73ff9fabc`::moving from state aborting -> state failed
Thread-39514::DEBUG::2013-10-09 08:14:27,192::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39514::DEBUG::2013-10-09 08:14:27,192::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39514::ERROR::2013-10-09 08:14:27,193::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39515::DEBUG::2013-10-09 08:14:27,199::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39515::DEBUG::2013-10-09 08:14:27,199::task::579::TaskManager.Task::(_updateState) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::moving from state init -> state preparing
Thread-39515::INFO::2013-10-09 08:14:27,199::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39515::DEBUG::2013-10-09 08:14:27,200::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`bf8aecb2-89d9-444e-99e1-47d27c7795a1`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39515::DEBUG::2013-10-09 08:14:27,200::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39515::DEBUG::2013-10-09 08:14:27,200::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39515::DEBUG::2013-10-09 08:14:27,200::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`bf8aecb2-89d9-444e-99e1-47d27c7795a1`::Granted request
Thread-39515::DEBUG::2013-10-09 08:14:27,200::task::811::TaskManager.Task::(resourceAcquired) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39515::DEBUG::2013-10-09 08:14:27,201::task::974::TaskManager.Task::(_decref) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::ref 1 aborting False
Thread-39515::ERROR::2013-10-09 08:14:27,201::task::850::TaskManager.Task::(_setError) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39515::DEBUG::2013-10-09 08:14:27,201::task::869::TaskManager.Task::(_run) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::Task._run: a6cdce82-fc14-4df7-b85a-bc0546dc5413 ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39515::DEBUG::2013-10-09 08:14:27,201::task::1194::TaskManager.Task::(stop) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::stopping in state preparing (force False)
Thread-39515::DEBUG::2013-10-09 08:14:27,201::task::974::TaskManager.Task::(_decref) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::ref 1 aborting True
Thread-39515::INFO::2013-10-09 08:14:27,202::task::1151::TaskManager.Task::(prepare) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39515::DEBUG::2013-10-09 08:14:27,202::task::1156::TaskManager.Task::(prepare) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39515::DEBUG::2013-10-09 08:14:27,202::task::974::TaskManager.Task::(_decref) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::ref 0 aborting True
Thread-39515::DEBUG::2013-10-09 08:14:27,202::task::909::TaskManager.Task::(_doAbort) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::Task._doAbort: force False
Thread-39515::DEBUG::2013-10-09 08:14:27,202::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39515::DEBUG::2013-10-09 08:14:27,202::task::579::TaskManager.Task::(_updateState) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::moving from state preparing -> state aborting
Thread-39515::DEBUG::2013-10-09 08:14:27,202::task::534::TaskManager.Task::(__state_aborting) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::_aborting: recover policy none
Thread-39515::DEBUG::2013-10-09 08:14:27,202::task::579::TaskManager.Task::(_updateState) Task=`a6cdce82-fc14-4df7-b85a-bc0546dc5413`::moving from state aborting -> state failed
Thread-39515::DEBUG::2013-10-09 08:14:27,203::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39515::DEBUG::2013-10-09 08:14:27,203::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39515::DEBUG::2013-10-09 08:14:27,203::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39515::DEBUG::2013-10-09 08:14:27,203::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39515::DEBUG::2013-10-09 08:14:27,203::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39515::DEBUG::2013-10-09 08:14:27,203::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39515::ERROR::2013-10-09 08:14:27,204::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39516::DEBUG::2013-10-09 08:14:37,223::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39516::DEBUG::2013-10-09 08:14:37,224::task::579::TaskManager.Task::(_updateState) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::moving from state init -> state preparing
Thread-39516::INFO::2013-10-09 08:14:37,224::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39516::ERROR::2013-10-09 08:14:37,224::task::850::TaskManager.Task::(_setError) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39516::DEBUG::2013-10-09 08:14:37,225::task::869::TaskManager.Task::(_run) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::Task._run: e8cfe332-215a-44cb-99bf-0ec55f209f6a () {} failed - stopping task
Thread-39516::DEBUG::2013-10-09 08:14:37,225::task::1194::TaskManager.Task::(stop) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::stopping in state preparing (force False)
Thread-39516::DEBUG::2013-10-09 08:14:37,225::task::974::TaskManager.Task::(_decref) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::ref 1 aborting True
Thread-39516::INFO::2013-10-09 08:14:37,225::task::1151::TaskManager.Task::(prepare) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39516::DEBUG::2013-10-09 08:14:37,225::task::1156::TaskManager.Task::(prepare) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::Prepare: aborted: Not SPM
Thread-39516::DEBUG::2013-10-09 08:14:37,225::task::974::TaskManager.Task::(_decref) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::ref 0 aborting True
Thread-39516::DEBUG::2013-10-09 08:14:37,226::task::909::TaskManager.Task::(_doAbort) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::Task._doAbort: force False
Thread-39516::DEBUG::2013-10-09 08:14:37,226::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39516::DEBUG::2013-10-09 08:14:37,226::task::579::TaskManager.Task::(_updateState) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::moving from state preparing -> state aborting
Thread-39516::DEBUG::2013-10-09 08:14:37,226::task::534::TaskManager.Task::(__state_aborting) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::_aborting: recover policy none
Thread-39516::DEBUG::2013-10-09 08:14:37,226::task::579::TaskManager.Task::(_updateState) Task=`e8cfe332-215a-44cb-99bf-0ec55f209f6a`::moving from state aborting -> state failed
Thread-39516::DEBUG::2013-10-09 08:14:37,226::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39516::DEBUG::2013-10-09 08:14:37,226::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39516::ERROR::2013-10-09 08:14:37,227::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39517::DEBUG::2013-10-09 08:14:37,232::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39517::DEBUG::2013-10-09 08:14:37,233::task::579::TaskManager.Task::(_updateState) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::moving from state init -> state preparing
Thread-39517::INFO::2013-10-09 08:14:37,233::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39517::DEBUG::2013-10-09 08:14:37,233::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`8ef2e551-3a27-4390-81a8-bea2819419ee`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39517::DEBUG::2013-10-09 08:14:37,234::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39517::DEBUG::2013-10-09 08:14:37,234::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39517::DEBUG::2013-10-09 08:14:37,234::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`8ef2e551-3a27-4390-81a8-bea2819419ee`::Granted request
Thread-39517::DEBUG::2013-10-09 08:14:37,234::task::811::TaskManager.Task::(resourceAcquired) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39517::DEBUG::2013-10-09 08:14:37,235::task::974::TaskManager.Task::(_decref) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::ref 1 aborting False
Thread-39517::ERROR::2013-10-09 08:14:37,235::task::850::TaskManager.Task::(_setError) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39517::DEBUG::2013-10-09 08:14:37,235::task::869::TaskManager.Task::(_run) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::Task._run: ddaea45c-907b-4cbc-b126-581cd218519b ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39517::DEBUG::2013-10-09 08:14:37,235::task::1194::TaskManager.Task::(stop) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::stopping in state preparing (force False)
Thread-39517::DEBUG::2013-10-09 08:14:37,235::task::974::TaskManager.Task::(_decref) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::ref 1 aborting True
Thread-39517::INFO::2013-10-09 08:14:37,235::task::1151::TaskManager.Task::(prepare) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39517::DEBUG::2013-10-09 08:14:37,236::task::1156::TaskManager.Task::(prepare) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39517::DEBUG::2013-10-09 08:14:37,236::task::974::TaskManager.Task::(_decref) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::ref 0 aborting True
Thread-39517::DEBUG::2013-10-09 08:14:37,236::task::909::TaskManager.Task::(_doAbort) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::Task._doAbort: force False
Thread-39517::DEBUG::2013-10-09 08:14:37,236::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39517::DEBUG::2013-10-09 08:14:37,236::task::579::TaskManager.Task::(_updateState) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::moving from state preparing -> state aborting
Thread-39517::DEBUG::2013-10-09 08:14:37,236::task::534::TaskManager.Task::(__state_aborting) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::_aborting: recover policy none
Thread-39517::DEBUG::2013-10-09 08:14:37,236::task::579::TaskManager.Task::(_updateState) Task=`ddaea45c-907b-4cbc-b126-581cd218519b`::moving from state aborting -> state failed
Thread-39517::DEBUG::2013-10-09 08:14:37,237::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39517::DEBUG::2013-10-09 08:14:37,237::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39517::DEBUG::2013-10-09 08:14:37,237::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39517::DEBUG::2013-10-09 08:14:37,237::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39517::DEBUG::2013-10-09 08:14:37,237::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39517::DEBUG::2013-10-09 08:14:37,237::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39517::ERROR::2013-10-09 08:14:37,238::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39518::DEBUG::2013-10-09 08:14:47,256::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39518::DEBUG::2013-10-09 08:14:47,257::task::579::TaskManager.Task::(_updateState) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::moving from state init -> state preparing
Thread-39518::INFO::2013-10-09 08:14:47,257::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39518::ERROR::2013-10-09 08:14:47,257::task::850::TaskManager.Task::(_setError) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39518::DEBUG::2013-10-09 08:14:47,258::task::869::TaskManager.Task::(_run) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::Task._run: 722446b2-72f8-467e-a794-1f93cd0d8bb5 () {} failed - stopping task
Thread-39518::DEBUG::2013-10-09 08:14:47,258::task::1194::TaskManager.Task::(stop) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::stopping in state preparing (force False)
Thread-39518::DEBUG::2013-10-09 08:14:47,258::task::974::TaskManager.Task::(_decref) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::ref 1 aborting True
Thread-39518::INFO::2013-10-09 08:14:47,258::task::1151::TaskManager.Task::(prepare) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39518::DEBUG::2013-10-09 08:14:47,258::task::1156::TaskManager.Task::(prepare) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::Prepare: aborted: Not SPM
Thread-39518::DEBUG::2013-10-09 08:14:47,259::task::974::TaskManager.Task::(_decref) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::ref 0 aborting True
Thread-39518::DEBUG::2013-10-09 08:14:47,259::task::909::TaskManager.Task::(_doAbort) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::Task._doAbort: force False
Thread-39518::DEBUG::2013-10-09 08:14:47,259::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39518::DEBUG::2013-10-09 08:14:47,259::task::579::TaskManager.Task::(_updateState) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::moving from state preparing -> state aborting
Thread-39518::DEBUG::2013-10-09 08:14:47,259::task::534::TaskManager.Task::(__state_aborting) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::_aborting: recover policy none
Thread-39518::DEBUG::2013-10-09 08:14:47,259::task::579::TaskManager.Task::(_updateState) Task=`722446b2-72f8-467e-a794-1f93cd0d8bb5`::moving from state aborting -> state failed
Thread-39518::DEBUG::2013-10-09 08:14:47,259::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39518::DEBUG::2013-10-09 08:14:47,260::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39518::ERROR::2013-10-09 08:14:47,260::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39519::DEBUG::2013-10-09 08:14:47,266::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39519::DEBUG::2013-10-09 08:14:47,266::task::579::TaskManager.Task::(_updateState) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::moving from state init -> state preparing
Thread-39519::INFO::2013-10-09 08:14:47,267::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39519::DEBUG::2013-10-09 08:14:47,267::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`2f4ded3e-df2a-4f64-907a-f1d7e7406b2b`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39519::DEBUG::2013-10-09 08:14:47,267::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39519::DEBUG::2013-10-09 08:14:47,267::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39519::DEBUG::2013-10-09 08:14:47,268::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`2f4ded3e-df2a-4f64-907a-f1d7e7406b2b`::Granted request
Thread-39519::DEBUG::2013-10-09 08:14:47,268::task::811::TaskManager.Task::(resourceAcquired) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39519::DEBUG::2013-10-09 08:14:47,268::task::974::TaskManager.Task::(_decref) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::ref 1 aborting False
Thread-39519::ERROR::2013-10-09 08:14:47,268::task::850::TaskManager.Task::(_setError) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39519::DEBUG::2013-10-09 08:14:47,269::task::869::TaskManager.Task::(_run) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::Task._run: cea07374-4b08-463b-acf7-efe3a5e79e99 ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39519::DEBUG::2013-10-09 08:14:47,269::task::1194::TaskManager.Task::(stop) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::stopping in state preparing (force False)
Thread-39519::DEBUG::2013-10-09 08:14:47,269::task::974::TaskManager.Task::(_decref) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::ref 1 aborting True
Thread-39519::INFO::2013-10-09 08:14:47,269::task::1151::TaskManager.Task::(prepare) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39519::DEBUG::2013-10-09 08:14:47,269::task::1156::TaskManager.Task::(prepare) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39519::DEBUG::2013-10-09 08:14:47,269::task::974::TaskManager.Task::(_decref) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::ref 0 aborting True
Thread-39519::DEBUG::2013-10-09 08:14:47,269::task::909::TaskManager.Task::(_doAbort) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::Task._doAbort: force False
Thread-39519::DEBUG::2013-10-09 08:14:47,270::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39519::DEBUG::2013-10-09 08:14:47,270::task::579::TaskManager.Task::(_updateState) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::moving from state preparing -> state aborting
Thread-39519::DEBUG::2013-10-09 08:14:47,270::task::534::TaskManager.Task::(__state_aborting) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::_aborting: recover policy none
Thread-39519::DEBUG::2013-10-09 08:14:47,270::task::579::TaskManager.Task::(_updateState) Task=`cea07374-4b08-463b-acf7-efe3a5e79e99`::moving from state aborting -> state failed
Thread-39519::DEBUG::2013-10-09 08:14:47,270::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39519::DEBUG::2013-10-09 08:14:47,270::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39519::DEBUG::2013-10-09 08:14:47,271::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39519::DEBUG::2013-10-09 08:14:47,271::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39519::DEBUG::2013-10-09 08:14:47,271::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39519::DEBUG::2013-10-09 08:14:47,271::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39519::ERROR::2013-10-09 08:14:47,271::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39520::DEBUG::2013-10-09 08:14:57,291::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39520::DEBUG::2013-10-09 08:14:57,292::task::579::TaskManager.Task::(_updateState) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::moving from state init -> state preparing
Thread-39520::INFO::2013-10-09 08:14:57,292::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39520::ERROR::2013-10-09 08:14:57,292::task::850::TaskManager.Task::(_setError) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39520::DEBUG::2013-10-09 08:14:57,292::task::869::TaskManager.Task::(_run) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::Task._run: 0419570e-7933-498c-afa7-97cb0cfc878a () {} failed - stopping task
Thread-39520::DEBUG::2013-10-09 08:14:57,293::task::1194::TaskManager.Task::(stop) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::stopping in state preparing (force False)
Thread-39520::DEBUG::2013-10-09 08:14:57,293::task::974::TaskManager.Task::(_decref) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::ref 1 aborting True
Thread-39520::INFO::2013-10-09 08:14:57,293::task::1151::TaskManager.Task::(prepare) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39520::DEBUG::2013-10-09 08:14:57,293::task::1156::TaskManager.Task::(prepare) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::Prepare: aborted: Not SPM
Thread-39520::DEBUG::2013-10-09 08:14:57,293::task::974::TaskManager.Task::(_decref) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::ref 0 aborting True
Thread-39520::DEBUG::2013-10-09 08:14:57,293::task::909::TaskManager.Task::(_doAbort) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::Task._doAbort: force False
Thread-39520::DEBUG::2013-10-09 08:14:57,293::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39520::DEBUG::2013-10-09 08:14:57,294::task::579::TaskManager.Task::(_updateState) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::moving from state preparing -> state aborting
Thread-39520::DEBUG::2013-10-09 08:14:57,294::task::534::TaskManager.Task::(__state_aborting) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::_aborting: recover policy none
Thread-39520::DEBUG::2013-10-09 08:14:57,294::task::579::TaskManager.Task::(_updateState) Task=`0419570e-7933-498c-afa7-97cb0cfc878a`::moving from state aborting -> state failed
Thread-39520::DEBUG::2013-10-09 08:14:57,294::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39520::DEBUG::2013-10-09 08:14:57,294::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39520::ERROR::2013-10-09 08:14:57,294::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39521::DEBUG::2013-10-09 08:14:57,300::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39521::DEBUG::2013-10-09 08:14:57,300::task::579::TaskManager.Task::(_updateState) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::moving from state init -> state preparing
Thread-39521::INFO::2013-10-09 08:14:57,301::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39521::DEBUG::2013-10-09 08:14:57,301::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`5302450d-5541-4f65-9d52-f9afbba72d57`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39521::DEBUG::2013-10-09 08:14:57,301::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39521::DEBUG::2013-10-09 08:14:57,302::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39521::DEBUG::2013-10-09 08:14:57,302::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`5302450d-5541-4f65-9d52-f9afbba72d57`::Granted request
Thread-39521::DEBUG::2013-10-09 08:14:57,302::task::811::TaskManager.Task::(resourceAcquired) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39521::DEBUG::2013-10-09 08:14:57,302::task::974::TaskManager.Task::(_decref) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::ref 1 aborting False
Thread-39521::ERROR::2013-10-09 08:14:57,302::task::850::TaskManager.Task::(_setError) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39521::DEBUG::2013-10-09 08:14:57,303::task::869::TaskManager.Task::(_run) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::Task._run: 3bde630f-33b9-412b-8df9-9f076beffa70 ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39521::DEBUG::2013-10-09 08:14:57,303::task::1194::TaskManager.Task::(stop) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::stopping in state preparing (force False)
Thread-39521::DEBUG::2013-10-09 08:14:57,303::task::974::TaskManager.Task::(_decref) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::ref 1 aborting True
Thread-39521::INFO::2013-10-09 08:14:57,303::task::1151::TaskManager.Task::(prepare) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39521::DEBUG::2013-10-09 08:14:57,303::task::1156::TaskManager.Task::(prepare) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39521::DEBUG::2013-10-09 08:14:57,303::task::974::TaskManager.Task::(_decref) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::ref 0 aborting True
Thread-39521::DEBUG::2013-10-09 08:14:57,304::task::909::TaskManager.Task::(_doAbort) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::Task._doAbort: force False
Thread-39521::DEBUG::2013-10-09 08:14:57,304::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39521::DEBUG::2013-10-09 08:14:57,304::task::579::TaskManager.Task::(_updateState) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::moving from state preparing -> state aborting
Thread-39521::DEBUG::2013-10-09 08:14:57,304::task::534::TaskManager.Task::(__state_aborting) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::_aborting: recover policy none
Thread-39521::DEBUG::2013-10-09 08:14:57,304::task::579::TaskManager.Task::(_updateState) Task=`3bde630f-33b9-412b-8df9-9f076beffa70`::moving from state aborting -> state failed
Thread-39521::DEBUG::2013-10-09 08:14:57,304::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39521::DEBUG::2013-10-09 08:14:57,304::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39521::DEBUG::2013-10-09 08:14:57,305::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39521::DEBUG::2013-10-09 08:14:57,305::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39521::DEBUG::2013-10-09 08:14:57,305::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39521::DEBUG::2013-10-09 08:14:57,305::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39521::ERROR::2013-10-09 08:14:57,305::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39522::DEBUG::2013-10-09 08:15:07,324::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39522::DEBUG::2013-10-09 08:15:07,325::task::579::TaskManager.Task::(_updateState) Task=`51e5865b-6527-458f-9963-5dbac312e825`::moving from state init -> state preparing
Thread-39522::INFO::2013-10-09 08:15:07,325::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39522::ERROR::2013-10-09 08:15:07,326::task::850::TaskManager.Task::(_setError) Task=`51e5865b-6527-458f-9963-5dbac312e825`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39522::DEBUG::2013-10-09 08:15:07,326::task::869::TaskManager.Task::(_run) Task=`51e5865b-6527-458f-9963-5dbac312e825`::Task._run: 51e5865b-6527-458f-9963-5dbac312e825 () {} failed - stopping task
Thread-39522::DEBUG::2013-10-09 08:15:07,326::task::1194::TaskManager.Task::(stop) Task=`51e5865b-6527-458f-9963-5dbac312e825`::stopping in state preparing (force False)
Thread-39522::DEBUG::2013-10-09 08:15:07,326::task::974::TaskManager.Task::(_decref) Task=`51e5865b-6527-458f-9963-5dbac312e825`::ref 1 aborting True
Thread-39522::INFO::2013-10-09 08:15:07,326::task::1151::TaskManager.Task::(prepare) Task=`51e5865b-6527-458f-9963-5dbac312e825`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39522::DEBUG::2013-10-09 08:15:07,327::task::1156::TaskManager.Task::(prepare) Task=`51e5865b-6527-458f-9963-5dbac312e825`::Prepare: aborted: Not SPM
Thread-39522::DEBUG::2013-10-09 08:15:07,327::task::974::TaskManager.Task::(_decref) Task=`51e5865b-6527-458f-9963-5dbac312e825`::ref 0 aborting True
Thread-39522::DEBUG::2013-10-09 08:15:07,327::task::909::TaskManager.Task::(_doAbort) Task=`51e5865b-6527-458f-9963-5dbac312e825`::Task._doAbort: force False
Thread-39522::DEBUG::2013-10-09 08:15:07,327::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39522::DEBUG::2013-10-09 08:15:07,327::task::579::TaskManager.Task::(_updateState) Task=`51e5865b-6527-458f-9963-5dbac312e825`::moving from state preparing -> state aborting
Thread-39522::DEBUG::2013-10-09 08:15:07,327::task::534::TaskManager.Task::(__state_aborting) Task=`51e5865b-6527-458f-9963-5dbac312e825`::_aborting: recover policy none
Thread-39522::DEBUG::2013-10-09 08:15:07,327::task::579::TaskManager.Task::(_updateState) Task=`51e5865b-6527-458f-9963-5dbac312e825`::moving from state aborting -> state failed
Thread-39522::DEBUG::2013-10-09 08:15:07,328::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39522::DEBUG::2013-10-09 08:15:07,328::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39522::ERROR::2013-10-09 08:15:07,328::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39523::DEBUG::2013-10-09 08:15:07,334::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39523::DEBUG::2013-10-09 08:15:07,334::task::579::TaskManager.Task::(_updateState) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::moving from state init -> state preparing
Thread-39523::INFO::2013-10-09 08:15:07,334::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39523::DEBUG::2013-10-09 08:15:07,335::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`101a249f-8603-41d7-9052-83f03cd8cd02`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39523::DEBUG::2013-10-09 08:15:07,335::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39523::DEBUG::2013-10-09 08:15:07,335::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39523::DEBUG::2013-10-09 08:15:07,335::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`101a249f-8603-41d7-9052-83f03cd8cd02`::Granted request
Thread-39523::DEBUG::2013-10-09 08:15:07,336::task::811::TaskManager.Task::(resourceAcquired) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39523::DEBUG::2013-10-09 08:15:07,336::task::974::TaskManager.Task::(_decref) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::ref 1 aborting False
Thread-39523::ERROR::2013-10-09 08:15:07,336::task::850::TaskManager.Task::(_setError) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39523::DEBUG::2013-10-09 08:15:07,336::task::869::TaskManager.Task::(_run) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::Task._run: d9214b64-48c0-4bb8-8180-98b7249f31aa ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39523::DEBUG::2013-10-09 08:15:07,336::task::1194::TaskManager.Task::(stop) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::stopping in state preparing (force False)
Thread-39523::DEBUG::2013-10-09 08:15:07,337::task::974::TaskManager.Task::(_decref) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::ref 1 aborting True
Thread-39523::INFO::2013-10-09 08:15:07,337::task::1151::TaskManager.Task::(prepare) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39523::DEBUG::2013-10-09 08:15:07,337::task::1156::TaskManager.Task::(prepare) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39523::DEBUG::2013-10-09 08:15:07,337::task::974::TaskManager.Task::(_decref) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::ref 0 aborting True
Thread-39523::DEBUG::2013-10-09 08:15:07,337::task::909::TaskManager.Task::(_doAbort) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::Task._doAbort: force False
Thread-39523::DEBUG::2013-10-09 08:15:07,337::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39523::DEBUG::2013-10-09 08:15:07,337::task::579::TaskManager.Task::(_updateState) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::moving from state preparing -> state aborting
Thread-39523::DEBUG::2013-10-09 08:15:07,338::task::534::TaskManager.Task::(__state_aborting) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::_aborting: recover policy none
Thread-39523::DEBUG::2013-10-09 08:15:07,338::task::579::TaskManager.Task::(_updateState) Task=`d9214b64-48c0-4bb8-8180-98b7249f31aa`::moving from state aborting -> state failed
Thread-39523::DEBUG::2013-10-09 08:15:07,338::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39523::DEBUG::2013-10-09 08:15:07,338::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39523::DEBUG::2013-10-09 08:15:07,338::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39523::DEBUG::2013-10-09 08:15:07,338::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39523::DEBUG::2013-10-09 08:15:07,339::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39523::DEBUG::2013-10-09 08:15:07,339::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39523::ERROR::2013-10-09 08:15:07,339::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)", 'code': 309}}
Thread-39524::DEBUG::2013-10-09 08:15:17,358::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39524::DEBUG::2013-10-09 08:15:17,359::task::579::TaskManager.Task::(_updateState) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::moving from state init -> state preparing
Thread-39524::INFO::2013-10-09 08:15:17,359::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-39524::ERROR::2013-10-09 08:15:17,359::task::850::TaskManager.Task::(_setError) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2122, in getAllTasksStatuses
    raise se.SpmStatusError()
SpmStatusError: Not SPM: ()
Thread-39524::DEBUG::2013-10-09 08:15:17,360::task::869::TaskManager.Task::(_run) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::Task._run: df501ec1-e4cb-4cf7-96cc-c2038fca2bc4 () {} failed - stopping task
Thread-39524::DEBUG::2013-10-09 08:15:17,360::task::1194::TaskManager.Task::(stop) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::stopping in state preparing (force False)
Thread-39524::DEBUG::2013-10-09 08:15:17,360::task::974::TaskManager.Task::(_decref) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::ref 1 aborting True
Thread-39524::INFO::2013-10-09 08:15:17,360::task::1151::TaskManager.Task::(prepare) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::aborting: Task is aborted: 'Not SPM' - code 654
Thread-39524::DEBUG::2013-10-09 08:15:17,360::task::1156::TaskManager.Task::(prepare) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::Prepare: aborted: Not SPM
Thread-39524::DEBUG::2013-10-09 08:15:17,360::task::974::TaskManager.Task::(_decref) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::ref 0 aborting True
Thread-39524::DEBUG::2013-10-09 08:15:17,361::task::909::TaskManager.Task::(_doAbort) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::Task._doAbort: force False
Thread-39524::DEBUG::2013-10-09 08:15:17,361::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39524::DEBUG::2013-10-09 08:15:17,361::task::579::TaskManager.Task::(_updateState) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::moving from state preparing -> state aborting
Thread-39524::DEBUG::2013-10-09 08:15:17,361::task::534::TaskManager.Task::(__state_aborting) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::_aborting: recover policy none
Thread-39524::DEBUG::2013-10-09 08:15:17,361::task::579::TaskManager.Task::(_updateState) Task=`df501ec1-e4cb-4cf7-96cc-c2038fca2bc4`::moving from state aborting -> state failed
Thread-39524::DEBUG::2013-10-09 08:15:17,361::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39524::DEBUG::2013-10-09 08:15:17,361::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39524::ERROR::2013-10-09 08:15:17,362::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
Thread-39525::DEBUG::2013-10-09 08:15:17,367::BindingXMLRPC::177::vds::(wrapper) client [192.168.13.200]
Thread-39525::DEBUG::2013-10-09 08:15:17,368::task::579::TaskManager.Task::(_updateState) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::moving from state init -> state preparing
Thread-39525::INFO::2013-10-09 08:15:17,368::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='b30f1ed0-7643-4d77-bf65-9e54f2b60d30', options=None)
Thread-39525::DEBUG::2013-10-09 08:15:17,368::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`2fa0c474-8cd5-469c-b9af-6637467d5a05`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '594' at 'spmStop'
Thread-39525::DEBUG::2013-10-09 08:15:17,368::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' for lock type 'exclusive'
Thread-39525::DEBUG::2013-10-09 08:15:17,369::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free. Now locking as 'exclusive' (1 active user)
Thread-39525::DEBUG::2013-10-09 08:15:17,369::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30`ReqID=`2fa0c474-8cd5-469c-b9af-6637467d5a05`::Granted request
Thread-39525::DEBUG::2013-10-09 08:15:17,369::task::811::TaskManager.Task::(resourceAcquired) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::_resourcesAcquired: Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30 (exclusive)
Thread-39525::DEBUG::2013-10-09 08:15:17,369::task::974::TaskManager.Task::(_decref) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::ref 1 aborting False
Thread-39525::ERROR::2013-10-09 08:15:17,370::task::850::TaskManager.Task::(_setError) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 596, in spmStop
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 318, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',)
Thread-39525::DEBUG::2013-10-09 08:15:17,370::task::869::TaskManager.Task::(_run) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::Task._run: 68372d3c-7665-40c1-bbc7-13690f99316c ('b30f1ed0-7643-4d77-bf65-9e54f2b60d30',) {} failed - stopping task
Thread-39525::DEBUG::2013-10-09 08:15:17,370::task::1194::TaskManager.Task::(stop) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::stopping in state preparing (force False)
Thread-39525::DEBUG::2013-10-09 08:15:17,370::task::974::TaskManager.Task::(_decref) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::ref 1 aborting True
Thread-39525::INFO::2013-10-09 08:15:17,370::task::1151::TaskManager.Task::(prepare) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39525::DEBUG::2013-10-09 08:15:17,370::task::1156::TaskManager.Task::(prepare) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39525::DEBUG::2013-10-09 08:15:17,371::task::974::TaskManager.Task::(_decref) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::ref 0 aborting True
Thread-39525::DEBUG::2013-10-09 08:15:17,371::task::909::TaskManager.Task::(_doAbort) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::Task._doAbort: force False
Thread-39525::DEBUG::2013-10-09 08:15:17,371::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39525::DEBUG::2013-10-09 08:15:17,371::task::579::TaskManager.Task::(_updateState) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::moving from state preparing -> state aborting
Thread-39525::DEBUG::2013-10-09 08:15:17,371::task::534::TaskManager.Task::(__state_aborting) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::_aborting: recover policy none
Thread-39525::DEBUG::2013-10-09 08:15:17,371::task::579::TaskManager.Task::(_updateState) Task=`68372d3c-7665-40c1-bbc7-13690f99316c`::moving from state aborting -> state failed
Thread-39525::DEBUG::2013-10-09 08:15:17,371::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30': < ResourceRef 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', isValid: 'True' obj: 'None'>}
Thread-39525::DEBUG::2013-10-09 08:15:17,372::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39525::DEBUG::2013-10-09 08:15:17,372::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30'
Thread-39525::DEBUG::2013-10-09 08:15:17,372::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' (0 active users)
Thread-39525::DEBUG::2013-10-09 08:15:17,372::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30' is free, finding out if anyone is waiting for it.
Thread-39525::DEBUG::2013-10-09 08:15:17,372::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b30f1ed0-7643-4d77-bf65-9e54f2b60d30', Clearing records.
Thread-39525::ERROR::2013-10-09 08:15:17,372::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: