"Could not connect host to Data Center" after rebooting, how to resolve?
Hi list, I had to do some fsck-related things last week on my ovirt box (centos, single node and NFS on localhost). Afterwards ovirt refused to start VMs according to the webinterface because it can't connect host to Data Center. On my OS it works fine (I just replaced the IP by 'IP'): [root@server ovirt-engine]# df Filesystem 1K-blocks Used Available Use% Mounted on /dev/mapper/vg_leiden-lv_root 51606140 6872592 42112108 15% / tmpfs 3978120 0 3978120 0% /dev/shm /dev/sdb1 495844 99542 370702 22% /boot /dev/mapper/vg_server-lv_home 62990260 2584272 57206196 5% /home /dev/sda1 5814366992 4629615452 1184751540 80% /raid IP:/raid/ovirt/data 5814367232 4629615616 1184751616 80% /rhev/data-center/mnt/IP:_raid_ovirt_data IP:/raid/ovirt/iso 5814367232 4629615616 1184751616 80% /rhev/data-center/mnt/IP:_raid_ovirt_iso in my event log in the webinterface I found correlation ID 7a735111 . So grepping my logs for that one: engine.log:2014-04-30 15:59:22,851 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp--127.0.0.1-8702-8) [7a735111] Lock Acquired to object EngineLock [exclusiveLocks= key: 6bee0e2d-961c-453d-a266-e4623f91e162 value: STORAGE engine.log:2014-04-30 15:59:22,888 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Running command: ActivateStorageDomainCommand internal: false. Entities affected : ID: 6bee0e2d-961c-453d-a266-e4623f91e162 Type: Storage engine.log:2014-04-30 15:59:22,894 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Lock freed to object EngineLock [exclusiveLocks= key: 6bee0e2d-961c-453d-a266-e4623f91e162 value: STORAGE engine.log:2014-04-30 15:59:22,895 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] ActivateStorage Domain. Before Connect all hosts to pool. Time:4/30/14 3:59 PM engine.log:2014-04-30 15:59:22,945 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] START, ActivateStorageDomainVDSCommand( storagePoolId = 00000002-0002-0002-0002-0000000000ec, ignoreFailoverLimit = false, storageDomainId = 6bee0e2d-961c-453d-a266-e4623f91e162), log id: 5fecb439 engine.log:2014-04-30 15:59:23,011 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] hostFromVds::selectedVds - server, spmStatus Unknown_Pool, storage pool Default engine.log:2014-04-30 15:59:23,015 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] START, ConnectStoragePoolVDSCommand(HostName = server, HostId = ff23de79-f17c-439d-939e-d8f3d9672367, storagePoolId = 00000002-0002-0002-0002-0000000000ec, vds_spm_id = 1, masterDomainId = 6bee0e2d-961c-453d-a266-e4623f91e162, masterVersion = 1), log id: 15866a95 engine.log:2014-04-30 15:59:23,151 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] FINISH, ConnectStoragePoolVDSCommand, log id: 15866a95 engine.log:2014-04-30 15:59:23,152 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Could not connect host to Data Center(Storage issue) engine.log:2014-04-30 15:59:23,156 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] FINISH, ActivateStorageDomainVDSCommand, log id: 5fecb439 engine.log:2014-04-30 15:59:23,157 ERROR [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Command org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Could not connect host to Data Center(Storage issue) (Failed with error ENGINE and code 5001) engine.log:2014-04-30 15:59:23,162 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Command [id=c2d8b433-f203-4d9e-b241-222eebf3dbae]: Compensating CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; snapshot: EntityStatusSnapshot [id=storagePoolId = 00000002-0002-0002-0002-0000000000ec, storageId = 6bee0e2d-961c-453d-a266-e4623f91e162, status=InActive]. engine.log:2014-04-30 15:59:23,170 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-49) [7a735111] Correlation ID: 7a735111, Job ID: 75dcda45-e0a3-46e3-b79f-8df9f0ed9d85, Call Stack: null, Custom Event ID: -1, Message: Failed to activate Storage Domain data (Data Center Default) by admin I guess the most relevant error is: engine.log:2014-04-30 15:59:23,152 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Could not connect host to Data Center(Storage issue) Okay so it can't connect to the data center. Well the NFS storage is mounted and looks fine. The directory is indeed looking fine: [root@leiden data]# ls -al total 12 drwxr-xr-x. 3 vdsm kvm 4096 Mar 30 03:27 . drwxr-xr-x. 4 vdsm kvm 4096 Mar 30 03:26 .. drwxr-xr-x. 5 vdsm kvm 4096 Mar 30 03:27 6bee0e2d-961c-453d-a266-e4623f91e162 -rwxr-xr-x. 1 vdsm kvm 0 Mar 30 03:27 __DIRECT_IO_TEST__ (and in the uuid there are indeed my VMs). How should I solve this? To me everything looks just fine. Cheers Boudewijn Ector
Hi, Could you please attach the vdsm logs for the host for the time around the logs you pasted from the engine.log? Thanks, Gadi Ickowicz ----- Original Message ----- From: "Boudewijn Ector ICT" <administratie@boduewijnector.nl> To: "users" <users@ovirt.org> Sent: Wednesday, April 30, 2014 5:09:39 PM Subject: [ovirt-users] "Could not connect host to Data Center" after rebooting, how to resolve? Hi list, I had to do some fsck-related things last week on my ovirt box (centos, single node and NFS on localhost). Afterwards ovirt refused to start VMs according to the webinterface because it can't connect host to Data Center. On my OS it works fine (I just replaced the IP by 'IP'): [root@server ovirt-engine]# df Filesystem 1K-blocks Used Available Use% Mounted on /dev/mapper/vg_leiden-lv_root 51606140 6872592 42112108 15% / tmpfs 3978120 0 3978120 0% /dev/shm /dev/sdb1 495844 99542 370702 22% /boot /dev/mapper/vg_server-lv_home 62990260 2584272 57206196 5% /home /dev/sda1 5814366992 4629615452 1184751540 80% /raid IP:/raid/ovirt/data 5814367232 4629615616 1184751616 80% /rhev/data-center/mnt/IP:_raid_ovirt_data IP:/raid/ovirt/iso 5814367232 4629615616 1184751616 80% /rhev/data-center/mnt/IP:_raid_ovirt_iso in my event log in the webinterface I found correlation ID 7a735111 . So grepping my logs for that one: engine.log:2014-04-30 15:59:22,851 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp--127.0.0.1-8702-8) [7a735111] Lock Acquired to object EngineLock [exclusiveLocks= key: 6bee0e2d-961c-453d-a266-e4623f91e162 value: STORAGE engine.log:2014-04-30 15:59:22,888 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Running command: ActivateStorageDomainCommand internal: false. Entities affected : ID: 6bee0e2d-961c-453d-a266-e4623f91e162 Type: Storage engine.log:2014-04-30 15:59:22,894 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Lock freed to object EngineLock [exclusiveLocks= key: 6bee0e2d-961c-453d-a266-e4623f91e162 value: STORAGE engine.log:2014-04-30 15:59:22,895 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] ActivateStorage Domain. Before Connect all hosts to pool. Time:4/30/14 3:59 PM engine.log:2014-04-30 15:59:22,945 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] START, ActivateStorageDomainVDSCommand( storagePoolId = 00000002-0002-0002-0002-0000000000ec, ignoreFailoverLimit = false, storageDomainId = 6bee0e2d-961c-453d-a266-e4623f91e162), log id: 5fecb439 engine.log:2014-04-30 15:59:23,011 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] hostFromVds::selectedVds - server, spmStatus Unknown_Pool, storage pool Default engine.log:2014-04-30 15:59:23,015 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] START, ConnectStoragePoolVDSCommand(HostName = server, HostId = ff23de79-f17c-439d-939e-d8f3d9672367, storagePoolId = 00000002-0002-0002-0002-0000000000ec, vds_spm_id = 1, masterDomainId = 6bee0e2d-961c-453d-a266-e4623f91e162, masterVersion = 1), log id: 15866a95 engine.log:2014-04-30 15:59:23,151 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] FINISH, ConnectStoragePoolVDSCommand, log id: 15866a95 engine.log:2014-04-30 15:59:23,152 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Could not connect host to Data Center(Storage issue) engine.log:2014-04-30 15:59:23,156 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] FINISH, ActivateStorageDomainVDSCommand, log id: 5fecb439 engine.log:2014-04-30 15:59:23,157 ERROR [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Command org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Could not connect host to Data Center(Storage issue) (Failed with error ENGINE and code 5001) engine.log:2014-04-30 15:59:23,162 INFO [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] Command [id=c2d8b433-f203-4d9e-b241-222eebf3dbae]: Compensating CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; snapshot: EntityStatusSnapshot [id=storagePoolId = 00000002-0002-0002-0002-0000000000ec, storageId = 6bee0e2d-961c-453d-a266-e4623f91e162, status=InActive]. engine.log:2014-04-30 15:59:23,170 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-49) [7a735111] Correlation ID: 7a735111, Job ID: 75dcda45-e0a3-46e3-b79f-8df9f0ed9d85, Call Stack: null, Custom Event ID: -1, Message: Failed to activate Storage Domain data (Data Center Default) by admin I guess the most relevant error is: engine.log:2014-04-30 15:59:23,152 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-49) [7a735111] IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Could not connect host to Data Center(Storage issue) Okay so it can't connect to the data center. Well the NFS storage is mounted and looks fine. The directory is indeed looking fine: [root@leiden data]# ls -al total 12 drwxr-xr-x. 3 vdsm kvm 4096 Mar 30 03:27 . drwxr-xr-x. 4 vdsm kvm 4096 Mar 30 03:26 .. drwxr-xr-x. 5 vdsm kvm 4096 Mar 30 03:27 6bee0e2d-961c-453d-a266-e4623f91e162 -rwxr-xr-x. 1 vdsm kvm 0 Mar 30 03:27 __DIRECT_IO_TEST__ (and in the uuid there are indeed my VMs). How should I solve this? To me everything looks just fine. Cheers Boudewijn Ector _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
Gadi Ickowicz schreef op 1-5-2014 7:54:
Hi,
Could you please attach the vdsm logs for the host for the time around the logs you pasted from the engine.log?
Thanks, Gadi Ickowicz
Sure I wasn't even aware of the /var/log/vdsm directory...
vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,043::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [61130377] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,044::task::595::TaskManager.Task::(_updateState) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,044::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '192.168.1.44:/raid/ovirt/data', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b', 'port': ''}], options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,048::hsm::2317::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_data vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,049::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('6bee0e2d-961c-453d-a266-e4623f91e162',) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {6bee0e2d-961c-453d-a266-e4623f91e162: storage.nfsSD.findDomain, 5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee: storage.nfsSD.findDomain} vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,050::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::task::1185::TaskManager.Task::(prepare) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::finished: {'statuslist': [{'status': 0, 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::task::595::TaskManager.Task::(_updateState) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,051::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,051::task::990::TaskManager.Task::(_decref) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,098::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [2e8f350] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,098::task::595::TaskManager.Task::(_updateState) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,099::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '192.168.1.44:/raid/ovirt/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919', 'port': ''}], options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,104::hsm::2317::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_iso vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,105::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee',) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,105::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {6bee0e2d-961c-453d-a266-e4623f91e162: storage.nfsSD.findDomain, 5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee: storage.nfsSD.findDomain} vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,105::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::task::1185::TaskManager.Task::(prepare) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::finished: {'statuslist': [{'status': 0, 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::task::595::TaskManager.Task::(_updateState) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,107::task::990::TaskManager.Task::(_decref) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,841::task::595::TaskManager.Task::(_updateState) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:05,841::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:05,842::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::task::1185::TaskManager.Task::(prepare) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::finished: {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::task::595::TaskManager.Task::(_updateState) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,843::task::990::TaskManager.Task::(_decref) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,149::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,150::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,150::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000000ec', options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,150::task::866::TaskManager.Task::(_setError) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,158::task::885::TaskManager.Task::(_run) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Task._run: e4c461f3-6608-43a1-9a48-5a771ac7989c ('00000002-0002-0002-0002-0000000000ec',) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,158::task::1211::TaskManager.Task::(stop) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::990::TaskManager.Task::(_decref) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,159::task::1168::TaskManager.Task::(prepare) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::1173::TaskManager.Task::(prepare) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Prepare: aborted: Unknown pool id, pool not connected vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::990::TaskManager.Task::(_decref) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::925::TaskManager.Task::(_doAbort) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::550::TaskManager.Task::(__state_aborting) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,161::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,177::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,177::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,177::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,178::task::866::TaskManager.Task::(_setError) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::885::TaskManager.Task::(_run) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Task._run: ec07873a-5498-42ff-9403-3ad83f4b08c0 () {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::1211::TaskManager.Task::(stop) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::990::TaskManager.Task::(_decref) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,178::task::1168::TaskManager.Task::(prepare) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::aborting: Task is aborted: 'Not SPM' - code 654 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::1173::TaskManager.Task::(prepare) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Prepare: aborted: Not SPM vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::990::TaskManager.Task::(_decref) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::925::TaskManager.Task::(_doAbort) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::task::550::TaskManager.Task::(__state_aborting) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,180::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,244::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,244::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,245::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000000ec', options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,245::task::866::TaskManager.Task::(_setError) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,245::task::885::TaskManager.Task::(_run) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Task._run: e4168665-b47d-45f9-8901-727761acbefb ('00000002-0002-0002-0002-0000000000ec',) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::1211::TaskManager.Task::(stop) Task=`e4168665-b47d-45f9-8901-727761acbefb`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::990::TaskManager.Task::(_decref) Task=`e4168665-b47d-45f9-8901-727761acbefb`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,246::task::1168::TaskManager.Task::(prepare) Task=`e4168665-b47d-45f9-8901-727761acbefb`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::1173::TaskManager.Task::(prepare) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Prepare: aborted: Unknown pool id, pool not connected vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::990::TaskManager.Task::(_decref) Task=`e4168665-b47d-45f9-8901-727761acbefb`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::925::TaskManager.Task::(_doAbort) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::550::TaskManager.Task::(__state_aborting) Task=`e4168665-b47d-45f9-8901-727761acbefb`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,248::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,311::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,312::task::595::TaskManager.Task::(_updateState) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,312::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='00000002-0002-0002-0002-0000000000ec', hostID=1, msdUUID='6bee0e2d-961c-453d-a266-e4623f91e162', masterVersion=1, domainsMap=None, options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc44804a-eafd-4c6d-9362-4d1b58dbc332`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1007' at 'connectStoragePool' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc44804a-eafd-4c6d-9362-4d1b58dbc332`::Granted request vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.00000002-0002-0002-0002-0000000000ec`ReqID=`92d7be18-2aaf-402d-a185-c36818ee5aa4`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1055' at '_connectStoragePool' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.00000002-0002-0002-0002-0000000000ec' for lock type 'exclusive' pe 'exclusive' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.00000002-0002-0002-0002-0000000000ec' is free. Now locking as 'exclusive' (1 active user) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,315::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.00000002-0002-0002-0002-0000000000ec`ReqID=`92d7be18-2aaf-402d-a185-c36818ee5aa4`::Granted request vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,316::sp::133::Storage.StoragePool::(setBackend) updating pool 00000002-0002-0002-0002-0000000000ec backend from type NoneType instance 0x3cd1372210 to type StoragePoolDiskBackend instance 0x7f84e8062fc8 vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,316::sp::618::Storage.StoragePool::(connect) Connect host #1 to the storage pool 00000002-0002-0002-0002-0000000000ec with master domain: 6bee0e2d-961c-453d-a266-e4623f91e162 (ver = 1) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::764::SamplingMethod::(__call__) Got in to sampling method vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::764::SamplingMethod::(__call__) Got in to sampling method vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,319::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,319::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,343::misc::772::SamplingMethod::(__call__) Returning last result vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,343::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,364::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,365::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,365::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,367::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,367::misc::772::SamplingMethod::(__call__) Returning last result vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,383::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_data/6bee0e2d-961c-453d-a266-e4623f91e162 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,384::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,392::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[] vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:07,392::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.00000002-0002-0002-0002-0000000000ec' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.00000002-0002-0002-0002-0000000000ec' (0 active users) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.00000002-0002-0002-0002-0000000000ec' is free, finding out if anyone is waiting for it. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.00000002-0002-0002-0002-0000000000ec', Clearing records. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,395::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records. vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,395::task::866::TaskManager.Task::(_setError) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::885::TaskManager.Task::(_run) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Task._run: b9440814-a49e-446f-bfee-05f3bb3f73fd ('00000002-0002-0002-0002-0000000000ec', 1, '6bee0e2d-961c-453d-a266-e4623f91e162', 1, None) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::1211::TaskManager.Task::(stop) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::990::TaskManager.Task::(_decref) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,397::task::1168::TaskManager.Task::(prepare) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::aborting: Task is aborted: u"'VERSION'" - code 100 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,397::task::1173::TaskManager.Task::(prepare) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Prepare: aborted: 'VERSION' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,397::task::990::TaskManager.Task::(_decref) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::ref 0 aborting True
When looking for messages with ERROR or WARNING tags:
vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,150::task::866::TaskManager.Task::(_setError) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,161::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,178::task::866::TaskManager.Task::(_setError) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,180::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,245::task::866::TaskManager.Task::(_setError) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,248::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:07,392::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,395::task::866::TaskManager.Task::(_setError) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,399::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,462::task::866::TaskManager.Task::(_setError) Task=`c107a3de-819b-44c5-8739-f31ea6cc3b91`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,465::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,493::task::866::TaskManager.Task::(_setError) Task=`df7f16b1-72fe-43e9-ab76-7b59a694819e`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,496::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,558::task::866::TaskManager.Task::(_setError) Task=`68c69145-33b5-4fcb-8c91-47b27edf2d98`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,561::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:17,694::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,697::task::866::TaskManager.Task::(_setError) Task=`f807fd52-5495-4633-8615-b0923ff16e1d`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,701::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,765::task::866::TaskManager.Task::(_setError) Task=`5a0268e4-58e4-4e5f-a87a-89da345d373e`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,768::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,786::task::866::TaskManager.Task::(_setError) Task=`7e2d100d-3670-4b91-b861-9fbd43c5b110`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,789::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,860::task::866::TaskManager.Task::(_setError) Task=`833a9952-107a-437a-bc93-99849e0e0612`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,865::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:28,010::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:28,013::task::866::TaskManager.Task::(_setError) Task=`e999e46e-9a5f-43ba-881d-145c38fcb18f`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:28,017::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,078::task::866::TaskManager.Task::(_setError) Task=`7d632291-beb9-4bec-9d14-ce9b7d240e49`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,082::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,097::task::866::TaskManager.Task::(_setError) Task=`1f7a2469-c5f5-460f-a09e-3ff7f666dfe1`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,101::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,163::task::866::TaskManager.Task::(_setError) Task=`a793071a-13e2-4c66-8c63-34501c7becec`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,166::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}}
Thank you very much already. Boudewijn Ector
On 01-05-14 12:48, Boudewijn Ector wrote:
Gadi Ickowicz schreef op 1-5-2014 7:54:
Hi,
Could you please attach the vdsm logs for the host for the time around the logs you pasted from the engine.log?
Thanks, Gadi Ickowicz
Sure I wasn't even aware of the /var/log/vdsm directory...
vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,043::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [61130377] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,044::task::595::TaskManager.Task::(_updateState) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,044::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '192.168.1.44:/raid/ovirt/data', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b', 'port': ''}], options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,048::hsm::2317::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_data vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,049::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('6bee0e2d-961c-453d-a266-e4623f91e162',) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {6bee0e2d-961c-453d-a266-e4623f91e162: storage.nfsSD.findDomain, 5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee: storage.nfsSD.findDomain} vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,050::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::task::1185::TaskManager.Task::(prepare) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::finished: {'statuslist': [{'status': 0, 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::task::595::TaskManager.Task::(_updateState) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,051::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,051::task::990::TaskManager.Task::(_decref) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,098::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [2e8f350] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,098::task::595::TaskManager.Task::(_updateState) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,099::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '192.168.1.44:/raid/ovirt/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919', 'port': ''}], options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,104::hsm::2317::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_iso vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,105::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee',) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,105::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {6bee0e2d-961c-453d-a266-e4623f91e162: storage.nfsSD.findDomain, 5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee: storage.nfsSD.findDomain} vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,105::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::task::1185::TaskManager.Task::(prepare) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::finished: {'statuslist': [{'status': 0, 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::task::595::TaskManager.Task::(_updateState) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,107::task::990::TaskManager.Task::(_decref) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,841::task::595::TaskManager.Task::(_updateState) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:05,841::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:05,842::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::task::1185::TaskManager.Task::(prepare) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::finished: {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::task::595::TaskManager.Task::(_updateState) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,843::task::990::TaskManager.Task::(_decref) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,149::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,150::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,150::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000000ec', options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,150::task::866::TaskManager.Task::(_setError) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,158::task::885::TaskManager.Task::(_run) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Task._run: e4c461f3-6608-43a1-9a48-5a771ac7989c ('00000002-0002-0002-0002-0000000000ec',) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,158::task::1211::TaskManager.Task::(stop) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::990::TaskManager.Task::(_decref) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,159::task::1168::TaskManager.Task::(prepare) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::1173::TaskManager.Task::(prepare) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Prepare: aborted: Unknown pool id, pool not connected vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::990::TaskManager.Task::(_decref) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::925::TaskManager.Task::(_doAbort) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::550::TaskManager.Task::(__state_aborting) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,161::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,177::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,177::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,177::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,178::task::866::TaskManager.Task::(_setError) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::885::TaskManager.Task::(_run) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Task._run: ec07873a-5498-42ff-9403-3ad83f4b08c0 () {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::1211::TaskManager.Task::(stop) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::990::TaskManager.Task::(_decref) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,178::task::1168::TaskManager.Task::(prepare) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::aborting: Task is aborted: 'Not SPM' - code 654 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::1173::TaskManager.Task::(prepare) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Prepare: aborted: Not SPM vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::990::TaskManager.Task::(_decref) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::925::TaskManager.Task::(_doAbort) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::task::550::TaskManager.Task::(__state_aborting) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,180::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,244::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,244::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,245::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000000ec', options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,245::task::866::TaskManager.Task::(_setError) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,245::task::885::TaskManager.Task::(_run) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Task._run: e4168665-b47d-45f9-8901-727761acbefb ('00000002-0002-0002-0002-0000000000ec',) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::1211::TaskManager.Task::(stop) Task=`e4168665-b47d-45f9-8901-727761acbefb`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::990::TaskManager.Task::(_decref) Task=`e4168665-b47d-45f9-8901-727761acbefb`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,246::task::1168::TaskManager.Task::(prepare) Task=`e4168665-b47d-45f9-8901-727761acbefb`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::1173::TaskManager.Task::(prepare) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Prepare: aborted: Unknown pool id, pool not connected vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::990::TaskManager.Task::(_decref) Task=`e4168665-b47d-45f9-8901-727761acbefb`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::925::TaskManager.Task::(_doAbort) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::550::TaskManager.Task::(__state_aborting) Task=`e4168665-b47d-45f9-8901-727761acbefb`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,248::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,311::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,312::task::595::TaskManager.Task::(_updateState) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,312::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='00000002-0002-0002-0002-0000000000ec', hostID=1, msdUUID='6bee0e2d-961c-453d-a266-e4623f91e162', masterVersion=1, domainsMap=None, options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc44804a-eafd-4c6d-9362-4d1b58dbc332`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1007' at 'connectStoragePool' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc44804a-eafd-4c6d-9362-4d1b58dbc332`::Granted request vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.00000002-0002-0002-0002-0000000000ec`ReqID=`92d7be18-2aaf-402d-a185-c36818ee5aa4`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1055' at '_connectStoragePool' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.00000002-0002-0002-0002-0000000000ec' for lock type 'exclusive' pe 'exclusive' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.00000002-0002-0002-0002-0000000000ec' is free. Now locking as 'exclusive' (1 active user) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,315::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.00000002-0002-0002-0002-0000000000ec`ReqID=`92d7be18-2aaf-402d-a185-c36818ee5aa4`::Granted request vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,316::sp::133::Storage.StoragePool::(setBackend) updating pool 00000002-0002-0002-0002-0000000000ec backend from type NoneType instance 0x3cd1372210 to type StoragePoolDiskBackend instance 0x7f84e8062fc8 vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,316::sp::618::Storage.StoragePool::(connect) Connect host #1 to the storage pool 00000002-0002-0002-0002-0000000000ec with master domain: 6bee0e2d-961c-453d-a266-e4623f91e162 (ver = 1) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::764::SamplingMethod::(__call__) Got in to sampling method vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::764::SamplingMethod::(__call__) Got in to sampling method vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,319::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,319::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,343::misc::772::SamplingMethod::(__call__) Returning last result vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,343::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,364::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,365::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,365::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,367::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,367::misc::772::SamplingMethod::(__call__) Returning last result vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,383::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_data/6bee0e2d-961c-453d-a266-e4623f91e162 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,384::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,392::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[] vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:07,392::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.00000002-0002-0002-0002-0000000000ec' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.00000002-0002-0002-0002-0000000000ec' (0 active users) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.00000002-0002-0002-0002-0000000000ec' is free, finding out if anyone is waiting for it. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.00000002-0002-0002-0002-0000000000ec', Clearing records. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,395::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records. vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,395::task::866::TaskManager.Task::(_setError) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::885::TaskManager.Task::(_run) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Task._run: b9440814-a49e-446f-bfee-05f3bb3f73fd ('00000002-0002-0002-0002-0000000000ec', 1, '6bee0e2d-961c-453d-a266-e4623f91e162', 1, None) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::1211::TaskManager.Task::(stop) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::990::TaskManager.Task::(_decref) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,397::task::1168::TaskManager.Task::(prepare) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::aborting: Task is aborted: u"'VERSION'" - code 100 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,397::task::1173::TaskManager.Task::(prepare) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Prepare: aborted: 'VERSION' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,397::task::990::TaskManager.Task::(_decref) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::ref 0 aborting True When looking for messages with ERROR or WARNING tags:
vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,150::task::866::TaskManager.Task::(_setError) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,161::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,178::task::866::TaskManager.Task::(_setError) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,180::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,245::task::866::TaskManager.Task::(_setError) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,248::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:07,392::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,395::task::866::TaskManager.Task::(_setError) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,399::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,462::task::866::TaskManager.Task::(_setError) Task=`c107a3de-819b-44c5-8739-f31ea6cc3b91`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,465::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,493::task::866::TaskManager.Task::(_setError) Task=`df7f16b1-72fe-43e9-ab76-7b59a694819e`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,496::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,558::task::866::TaskManager.Task::(_setError) Task=`68c69145-33b5-4fcb-8c91-47b27edf2d98`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,561::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:17,694::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,697::task::866::TaskManager.Task::(_setError) Task=`f807fd52-5495-4633-8615-b0923ff16e1d`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,701::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,765::task::866::TaskManager.Task::(_setError) Task=`5a0268e4-58e4-4e5f-a87a-89da345d373e`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,768::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,786::task::866::TaskManager.Task::(_setError) Task=`7e2d100d-3670-4b91-b861-9fbd43c5b110`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,789::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,860::task::866::TaskManager.Task::(_setError) Task=`833a9952-107a-437a-bc93-99849e0e0612`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,865::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:28,010::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:28,013::task::866::TaskManager.Task::(_setError) Task=`e999e46e-9a5f-43ba-881d-145c38fcb18f`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:28,017::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,078::task::866::TaskManager.Task::(_setError) Task=`7d632291-beb9-4bec-9d14-ce9b7d240e49`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,082::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,097::task::866::TaskManager.Task::(_setError) Task=`1f7a2469-c5f5-460f-a09e-3ff7f666dfe1`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,101::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,163::task::866::TaskManager.Task::(_setError) Task=`a793071a-13e2-4c66-8c63-34501c7becec`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,166::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}}
Thank you very much already.
Boudewijn Ector _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
Bump, anyone? I'm quite a bit disappointed about the lack of debugability of ovirt actually. Cheers, Boudewijn
On 05/05/2014 11:44 PM, Boudewijn Ector wrote:
On 01-05-14 12:48, Boudewijn Ector wrote:
Gadi Ickowicz schreef op 1-5-2014 7:54:
Hi,
Could you please attach the vdsm logs for the host for the time around the logs you pasted from the engine.log?
Thanks, Gadi Ickowicz
Sure I wasn't even aware of the /var/log/vdsm directory...
vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,043::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [61130377] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,044::task::595::TaskManager.Task::(_updateState) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,044::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '192.168.1.44:/raid/ovirt/data', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b', 'port': ''}], options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,048::hsm::2317::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_data vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,049::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('6bee0e2d-961c-453d-a266-e4623f91e162',) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {6bee0e2d-961c-453d-a266-e4623f91e162: storage.nfsSD.findDomain, 5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee: storage.nfsSD.findDomain} vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,050::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::task::1185::TaskManager.Task::(prepare) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::finished: {'statuslist': [{'status': 0, 'id': '3021c4ab-5cb8-455b-be5f-2c79b0e3b23b'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::task::595::TaskManager.Task::(_updateState) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,050::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,051::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,051::task::990::TaskManager.Task::(_decref) Task=`217a7d59-fe83-4be5-b7e5-ce19c17a8d82`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,098::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [2e8f350] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,098::task::595::TaskManager.Task::(_updateState) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,099::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '192.168.1.44:/raid/ovirt/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919', 'port': ''}], options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,104::hsm::2317::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_iso vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,105::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee',) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,105::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {6bee0e2d-961c-453d-a266-e4623f91e162: storage.nfsSD.findDomain, 5e8c1e89-f2b8-492c-adb8-e9a9e15a79ee: storage.nfsSD.findDomain} vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:00,105::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::task::1185::TaskManager.Task::(prepare) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::finished: {'statuslist': [{'status': 0, 'id': '87de82d7-bc85-41ab-9ca7-3b39a75be919'}]} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::task::595::TaskManager.Task::(_updateState) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,106::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:00,107::task::990::TaskManager.Task::(_decref) Task=`dc6f1b1a-1162-4a3d-865d-d9ad9c3603f8`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,841::task::595::TaskManager.Task::(_updateState) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:05,841::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:05,842::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::task::1185::TaskManager.Task::(prepare) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::finished: {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::task::595::TaskManager.Task::(_updateState) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::moving from state preparing -> state finished vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,842::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:05,843::task::990::TaskManager.Task::(_decref) Task=`885311ca-275f-4bdc-9cab-88e91a8ac7c2`::ref 0 aborting False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,149::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,150::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,150::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000000ec', options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,150::task::866::TaskManager.Task::(_setError) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,158::task::885::TaskManager.Task::(_run) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Task._run: e4c461f3-6608-43a1-9a48-5a771ac7989c ('00000002-0002-0002-0002-0000000000ec',) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,158::task::1211::TaskManager.Task::(stop) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::990::TaskManager.Task::(_decref) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,159::task::1168::TaskManager.Task::(prepare) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::1173::TaskManager.Task::(prepare) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Prepare: aborted: Unknown pool id, pool not connected vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::990::TaskManager.Task::(_decref) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,159::task::925::TaskManager.Task::(_doAbort) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::550::TaskManager.Task::(__state_aborting) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::task::595::TaskManager.Task::(_updateState) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,160::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,161::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,177::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,177::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,177::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,178::task::866::TaskManager.Task::(_setError) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::885::TaskManager.Task::(_run) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Task._run: ec07873a-5498-42ff-9403-3ad83f4b08c0 () {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::1211::TaskManager.Task::(stop) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,178::task::990::TaskManager.Task::(_decref) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,178::task::1168::TaskManager.Task::(prepare) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::aborting: Task is aborted: 'Not SPM' - code 654 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::1173::TaskManager.Task::(prepare) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Prepare: aborted: Not SPM vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::990::TaskManager.Task::(_decref) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::925::TaskManager.Task::(_doAbort) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,179::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::task::550::TaskManager.Task::(__state_aborting) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::task::595::TaskManager.Task::(_updateState) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,180::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,180::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,244::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,244::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,245::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000000ec', options=None) vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,245::task::866::TaskManager.Task::(_setError) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,245::task::885::TaskManager.Task::(_run) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Task._run: e4168665-b47d-45f9-8901-727761acbefb ('00000002-0002-0002-0002-0000000000ec',) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::1211::TaskManager.Task::(stop) Task=`e4168665-b47d-45f9-8901-727761acbefb`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::990::TaskManager.Task::(_decref) Task=`e4168665-b47d-45f9-8901-727761acbefb`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,246::task::1168::TaskManager.Task::(prepare) Task=`e4168665-b47d-45f9-8901-727761acbefb`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::1173::TaskManager.Task::(prepare) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Prepare: aborted: Unknown pool id, pool not connected vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::990::TaskManager.Task::(_decref) Task=`e4168665-b47d-45f9-8901-727761acbefb`::ref 0 aborting True vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,246::task::925::TaskManager.Task::(_doAbort) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Task._doAbort: force False vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state preparing -> state aborting vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::550::TaskManager.Task::(__state_aborting) Task=`e4168665-b47d-45f9-8901-727761acbefb`::_aborting: recover policy none vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::task::595::TaskManager.Task::(_updateState) Task=`e4168665-b47d-45f9-8901-727761acbefb`::moving from state aborting -> state failed vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,247::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,248::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,311::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,312::task::595::TaskManager.Task::(_updateState) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::moving from state init -> state preparing vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,312::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='00000002-0002-0002-0002-0000000000ec', hostID=1, msdUUID='6bee0e2d-961c-453d-a266-e4623f91e162', masterVersion=1, domainsMap=None, options=None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc44804a-eafd-4c6d-9362-4d1b58dbc332`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1007' at 'connectStoragePool' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,313::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc44804a-eafd-4c6d-9362-4d1b58dbc332`::Granted request vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.00000002-0002-0002-0002-0000000000ec`ReqID=`92d7be18-2aaf-402d-a185-c36818ee5aa4`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1055' at '_connectStoragePool' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.00000002-0002-0002-0002-0000000000ec' for lock type 'exclusive' pe 'exclusive' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,314::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.00000002-0002-0002-0002-0000000000ec' is free. Now locking as 'exclusive' (1 active user) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,315::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.00000002-0002-0002-0002-0000000000ec`ReqID=`92d7be18-2aaf-402d-a185-c36818ee5aa4`::Granted request vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,316::sp::133::Storage.StoragePool::(setBackend) updating pool 00000002-0002-0002-0002-0000000000ec backend from type NoneType instance 0x3cd1372210 to type StoragePoolDiskBackend instance 0x7f84e8062fc8 vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,316::sp::618::Storage.StoragePool::(connect) Connect host #1 to the storage pool 00000002-0002-0002-0002-0000000000ec with master domain: 6bee0e2d-961c-453d-a266-e4623f91e162 (ver = 1) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,317::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::764::SamplingMethod::(__call__) Got in to sampling method vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,318::misc::764::SamplingMethod::(__call__) Got in to sampling method vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,319::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,319::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,343::misc::772::SamplingMethod::(__call__) Returning last result vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,343::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,364::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,365::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,365::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,366::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,367::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,367::misc::772::SamplingMethod::(__call__) Returning last result vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,383::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.1.44:_raid_ovirt_data/6bee0e2d-961c-453d-a266-e4623f91e162 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,384::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,392::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[] vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:07,392::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.00000002-0002-0002-0002-0000000000ec' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.00000002-0002-0002-0002-0000000000ec' (0 active users) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.00000002-0002-0002-0002-0000000000ec' is free, finding out if anyone is waiting for it. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,393::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.00000002-0002-0002-0002-0000000000ec', Clearing records. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,394::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it. vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,395::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records. vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,395::task::866::TaskManager.Task::(_setError) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Unexpected error vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::885::TaskManager.Task::(_run) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Task._run: b9440814-a49e-446f-bfee-05f3bb3f73fd ('00000002-0002-0002-0002-0000000000ec', 1, '6bee0e2d-961c-453d-a266-e4623f91e162', 1, None) {} failed - stopping task vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::1211::TaskManager.Task::(stop) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::stopping in state preparing (force False) vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,396::task::990::TaskManager.Task::(_decref) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::ref 1 aborting True vdsm.log.11:Thread-23::INFO::2014-04-30 15:50:07,397::task::1168::TaskManager.Task::(prepare) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::aborting: Task is aborted: u"'VERSION'" - code 100 vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,397::task::1173::TaskManager.Task::(prepare) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Prepare: aborted: 'VERSION' vdsm.log.11:Thread-23::DEBUG::2014-04-30 15:50:07,397::task::990::TaskManager.Task::(_decref) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::ref 0 aborting True When looking for messages with ERROR or WARNING tags:
vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,150::task::866::TaskManager.Task::(_setError) Task=`e4c461f3-6608-43a1-9a48-5a771ac7989c`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,161::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,178::task::866::TaskManager.Task::(_setError) Task=`ec07873a-5498-42ff-9403-3ad83f4b08c0`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,180::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,245::task::866::TaskManager.Task::(_setError) Task=`e4168665-b47d-45f9-8901-727761acbefb`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,248::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:07,392::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,395::task::866::TaskManager.Task::(_setError) Task=`b9440814-a49e-446f-bfee-05f3bb3f73fd`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:07,399::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,462::task::866::TaskManager.Task::(_setError) Task=`c107a3de-819b-44c5-8739-f31ea6cc3b91`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,465::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,493::task::866::TaskManager.Task::(_setError) Task=`df7f16b1-72fe-43e9-ab76-7b59a694819e`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,496::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,558::task::866::TaskManager.Task::(_setError) Task=`68c69145-33b5-4fcb-8c91-47b27edf2d98`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,561::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:17,694::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,697::task::866::TaskManager.Task::(_setError) Task=`f807fd52-5495-4633-8615-b0923ff16e1d`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:17,701::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,765::task::866::TaskManager.Task::(_setError) Task=`5a0268e4-58e4-4e5f-a87a-89da345d373e`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,768::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,786::task::866::TaskManager.Task::(_setError) Task=`7e2d100d-3670-4b91-b861-9fbd43c5b110`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,789::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,860::task::866::TaskManager.Task::(_setError) Task=`833a9952-107a-437a-bc93-99849e0e0612`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:27,865::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::WARNING::2014-04-30 15:50:28,010::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:28,013::task::866::TaskManager.Task::(_setError) Task=`e999e46e-9a5f-43ba-881d-145c38fcb18f`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:28,017::dispatcher::68::Storage.Dispatcher.Protect::(run) 'VERSION' vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,078::task::866::TaskManager.Task::(_setError) Task=`7d632291-beb9-4bec-9d14-ce9b7d240e49`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,082::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,097::task::866::TaskManager.Task::(_setError) Task=`1f7a2469-c5f5-460f-a09e-3ff7f666dfe1`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,101::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,163::task::866::TaskManager.Task::(_setError) Task=`a793071a-13e2-4c66-8c63-34501c7becec`::Unexpected error vdsm.log.11:Thread-23::ERROR::2014-04-30 15:50:38,166::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('00000002-0002-0002-0002-0000000000ec',)", 'code': 309}}
Thank you very much already.
Boudewijn Ector _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
Bump, anyone? I'm quite a bit disappointed about the lack of debugability of ovirt actually.
Cheers,
Boudewijn _______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
was this resolved?
participants (4)
-
Boudewijn Ector -
Boudewijn Ector ICT -
Gadi Ickowicz -
Itamar Heim