Bug 855648
| Summary: | [ovirt-engine] connect storage server: distinguish between connection doesn't exists and permission error | ||||||
|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Virtualization Manager | Reporter: | Haim <hateya> | ||||
| Component: | ovirt-engine | Assignee: | Liron Aravot <laravot> | ||||
| Status: | CLOSED NOTABUG | QA Contact: | Haim <hateya> | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 3.1.0 | CC: | amureini, dyasny, iheim, lpeer, Rhev-m-bugs, sgrinber, yeylon, ykaul | ||||
| Target Milestone: | --- | ||||||
| Target Release: | 3.1.5 | ||||||
| Hardware: | x86_64 | ||||||
| OS: | Linux | ||||||
| Whiteboard: | storage | ||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2012-11-11 07:34:19 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | Storage | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
Created attachment 611247 [details]
engine.log
Haim, i see proper prints in the attached log: 1. [org.ovirt.engine.core.bll.storage.POSIXFSStorageHelper] (ajp-/127.0.0.1:8009-18) [c5c2994] The connection with details filer01.q a.lab.tlv.redhat.com:/hateya failed because of error code 477 and error message is: problem while trying to mount target 2. [org.ovirt.engine.core.bll.storage.POSIXFSStorageHelper] (ajp-/127.0.0.1:8009-18) [c5c2994] The connection with details filer01.q a.lab.tlv.redhat.com:/hateya failed because of error code 477 and error message is: problem while trying to mount target should I close this bug? bad copy - 2. [org.ovirt.engine.core.bll.storage.POSIXFSStorageHelper] (ajp-/127.0.0.1:8009-2) [7a8b9d03] The connection with details filer01.qa.lab.tlv.redhat.com:/hateya1 failed because of error code 469 and error message is: permission settings on the specified path do not allow access to the storage. |
Description of problem: engine should distinguish between connection failure such as mounted directory doesn't exists and permission error on mounted directory. vdsm does support and returns different errors for both cases, however, engine parse those errors but fail them within the same can_do_action. this will improve debugging experience. example: 1) create new posix fs from type gluster where mounted dir doesn't exists: engine: ###### 2012-09-09 20:35:42,828 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-18) [c5c2994] START, V alidateStorageServerConnectionVDSCommand(vdsId = 38a0c460-f768-11e1-a387-001a4a16970e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POSI XFS, connectionList = [{ id: null, connection: filer01.qa.lab.tlv.redhat.com:/hateya, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nfsR etrans: null, nfsTimeo: null };]), log id: 7af955d 2012-09-09 20:35:42,860 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-18) [c5c2994] FINISH, ValidateStorageServerConnectionVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: 7af955d 2012-09-09 20:35:42,879 INFO [org.ovirt.engine.core.bll.storage.AddStorageServerConnectionCommand] (ajp-/127.0.0.1:8009-18) [c5c2994] Running command: AddStor ageServerConnectionCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2012-09-09 20:35:42,883 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-18) [c5c2994] START, ConnectStora geServerVDSCommand(vdsId = 38a0c460-f768-11e1-a387-001a4a16970e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POSIXFS, connectionList = [{ id: null, connection: filer01.qa.lab.tlv.redhat.com:/hateya, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo : null };]), log id: 2f03c6bf 2012-09-09 20:35:44,549 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-18) [c5c2994] FINISH, ConnectStor ageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=477}, log id: 2f03c6bf 2012-09-09 20:35:44,554 ERROR [org.ovirt.engine.core.bll.storage.POSIXFSStorageHelper] (ajp-/127.0.0.1:8009-18) [c5c2994] The connection with details filer01.q a.lab.tlv.redhat.com:/hateya failed because of error code 477 and error message is: problem while trying to mount target 2012-09-09 20:35:44,986 WARN [org.ovirt.engine.core.dal.job.ExecutionMessageDirector] (ajp-/127.0.0.1:8009-16) [69ff0eae] The message key AddPosixFsStorageDom ain is missing from bundles/ExecutionMessages 2012-09-09 20:35:45,013 WARN [org.ovirt.engine.core.bll.storage.AddPosixFsStorageDomainCommand] (ajp-/127.0.0.1:8009-16) [69ff0eae] CanDoAction of action AddP osixFsStorageDomain failed. Reasons:VAR__ACTION__ADD,VAR__TYPE__STORAGE__DOMAIN,ACTION_TYPE_FAILED_STORAGE_CONNECTION_NOT_EXIST 2012-09-09 20:35:45,106 INFO [org.ovirt.engine.core.bll.storage.RemoveStorageServerConnectionCommand] (ajp-/127.0.0.1:8009-15) [10b99f1f] Running command: Rem oveStorageServerConnectionCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2012-09-09 20:35:45,108 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-15) [10b99f1f] START, Disconne ctStorageServerVDSCommand(vdsId = 38a0c460-f768-11e1-a387-001a4a16970e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POSIXFS, connection List = [{ id: null, connection: filer01.qa.lab.tlv.redhat.com:/hateya, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nfsRetrans: null, n fsTimeo: null };]), log id: 14bce9f 2012-09-09 20:35:47,182 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-15) [10b99f1f] FINISH, Disconn ectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=477}, log id: 14bce9f 2012-09-09 20:39:22,987 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-18) [6a9ccbe9] START, ValidateStorageServerConnectionVDSCommand(vdsId = 38a0c460-f768-11e1-a387-001a4a16970e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POS IXFS, connectionList = [{ id: null, connection: filer01.qa.lab.tlv.redhat.com:/hateya2, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nf sRetrans: null, nfsTimeo: null };]), log id: 4dd8ec23 vdsm: #### Thread-18204::INFO::2012-09-09 17:38:12,512::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=6, spUUID='00000000-0 000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'filer01.qa.lab.tlv.redhat.com:/hateya2', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'gl usterfs', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000'}], options=None) Thread-18204::INFO::2012-09-09 17:38:12,512::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslis t': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]} Thread-18204::DEBUG::2012-09-09 17:38:12,513::task::1172::TaskManager.Task::(prepare) Task=`745aa3e4-3704-484c-87d9-fbe0e1e56694`::finished: {'statuslist': [{' status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]} Thread-18204::DEBUG::2012-09-09 17:38:12,513::task::588::TaskManager.Task::(_updateState) Task=`745aa3e4-3704-484c-87d9-fbe0e1e56694`::moving from state prepar ing -> state finished Thread-18204::DEBUG::2012-09-09 17:38:12,520::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-18204::DEBUG::2012-09-09 17:38:12,520::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-18204::DEBUG::2012-09-09 17:38:12,521::task::978::TaskManager.Task::(_decref) Task=`745aa3e4-3704-484c-87d9-fbe0e1e56694`::ref 0 aborting False Thread-18205::DEBUG::2012-09-09 17:38:12,573::BindingXMLRPC::164::vds::(wrapper) [10.35.97.14] Thread-18205::DEBUG::2012-09-09 17:38:12,574::task::588::TaskManager.Task::(_updateState) Task=`78334727-5240-4606-a466-dfb5287bdaea`::moving from state init - > state preparing Thread-18205::INFO::2012-09-09 17:38:12,575::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=6, spUUID='00000000-0000-0000-00 00-000000000000', conList=[{'port': '', 'connection': 'filer01.qa.lab.tlv.redhat.com:/hateya2', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'glusterfs', ' password': '******', 'id': '00000000-0000-0000-0000-000000000000'}], options=None) Thread-18205::DEBUG::2012-09-09 17:38:12,580::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/mount -t glusterfs filer01.qa.lab.tlv.redhat.c om:/hateya2 /rhev/data-center/mnt/filer01.qa.lab.tlv.redhat.com:_hateya2' (cwd None) Thread-18205::ERROR::2012-09-09 17:38:13,100::hsm::1975::Storage.HSM::(connectStorageServer) Could not connect to storageServer Traceback (most recent call last): File "/usr/share/vdsm/storage/hsm.py", line 1972, in connectStorageServer conObj.connect() File "/usr/share/vdsm/storage/storageServer.py", line 181, in connect self._mount.mount(self.options, self._vfsType) File "/usr/share/vdsm/storage/mount.py", line 198, in mount return self._runcmd(cmd, timeout) File "/usr/share/vdsm/storage/mount.py", line 214, in _runcmd raise MountError(rc, ";".join((out, err))) MountError: (1, 'Mount failed. Please check the log file for more details.\n;') 2) create new posix fs from type gluster where mounted dir exists but without proper permissions: engine: vdsm: #### Thread-18227::INFO::2012-09-09 17:38:39,223::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=6, spUUID='00000000-0000-0000-00 00-000000000000', conList=[{'port': '', 'connection': 'filer01.qa.lab.tlv.redhat.com:/hateya1', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'glusterfs', ' password': '******', 'id': '00000000-0000-0000-0000-000000000000'}], options=None) Thread-18227::DEBUG::2012-09-09 17:38:39,229::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/mount -t glusterfs filer01.qa.lab.tlv.redhat.c om:/hateya1 /rhev/data-center/mnt/filer01.qa.lab.tlv.redhat.com:_hateya1' (cwd None) Thread-18227::DEBUG::2012-09-09 17:38:43,770::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/filer01.qa. lab.tlv.redhat.com:_hateya1' (cwd None) Thread-18227::ERROR::2012-09-09 17:38:43,799::hsm::1975::Storage.HSM::(connectStorageServer) Could not connect to storageServer Traceback (most recent call last): File "/usr/share/vdsm/storage/hsm.py", line 1972, in connectStorageServer conObj.connect() File "/usr/share/vdsm/storage/storageServer.py", line 184, in connect fileSD.validateDirAccess(self.getMountObj().getRecord().fs_file) File "/usr/share/vdsm/storage/fileSD.py", line 56, in validateDirAccess raise se.StorageServerAccessPermissionError(dirPath) StorageServerAccessPermissionError: Permission settings on the specified path do not allow access to the storage. Verify permission settings on the specified s torage path.: 'path = /rhev/data-center/mnt/filer01.qa.lab.tlv.redhat.com:_hateya1' 2012-09-09 20:39:49,599 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-2) [7a8b9d03] START, ValidateStorageServerConnectionVDSCommand(vdsId = 38a0c460-f768-11e1-a387-001a4a16970e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POSIXFS, connectionList = [{ id: null, connection: filer01.qa.lab.tlv.redhat.com:/hateya1, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 24e33e77 2012-09-09 20:39:49,666 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-2) [7a8b9d03] FINISH, ValidateStorageServerConnectionVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: 24e33e77 2012-09-09 20:39:49,693 INFO [org.ovirt.engine.core.bll.storage.AddStorageServerConnectionCommand] (ajp-/127.0.0.1:8009-2) [7a8b9d03] Running command: AddStorageServerConnectionCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2012-09-09 20:39:49,695 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-2) [7a8b9d03] START, ConnectStorageServerVDSCommand(vdsId = 38a0c460-f768-11e1-a387-001a4a16970e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POSIXFS, connectionList = [{ id: null, connection: filer01.qa.lab.tlv.redhat.com:/hateya1, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 61cc1ca4 2012-09-09 20:39:54,304 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-2) [7a8b9d03] FINISH, ConnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=469}, log id: 61cc1ca4 2012-09-09 20:39:54,306 ERROR [org.ovirt.engine.core.bll.storage.POSIXFSStorageHelper] (ajp-/127.0.0.1:8009-2) [7a8b9d03] The connection with details filer01.qa.lab.tlv.redhat.com:/hateya1 failed because of error code 469 and error message is: permission settings on the specified path do not allow access to the storage. verify permission settings on the specified storage path. 2012-09-09 20:39:54,379 WARN [org.ovirt.engine.core.dal.job.ExecutionMessageDirector] (ajp-/127.0.0.1:8009-18) [5df0f760] The message key AddPosixFsStorageDomain is missing from bundles/ExecutionMessages 2012-09-09 20:39:54,413 WARN [org.ovirt.engine.core.bll.storage.AddPosixFsStorageDomainCommand] (ajp-/127.0.0.1:8009-18) [5df0f760] CanDoAction of action AddPosixFsStorageDomain failed. Reasons:VAR__ACTION__ADD,VAR__TYPE__STORAGE__DOMAIN,ACTION_TYPE_FAILED_STORAGE_CONNECTION_NOT_EXIST 2012-09-09 20:39:54,522 INFO [org.ovirt.engine.core.bll.storage.RemoveStorageServerConnectionCommand] (ajp-/127.0.0.1:8009-14) [15e0e199] Running command: RemoveStorageServerConnectionCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2012-09-09 20:39:54,523 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-14) [15e0e199] START, DisconnectStorageServerVDSCommand(vdsId = 38a0c460-f768-11e1-a387-001a4a16970e, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POSIXFS, connectionList = [{ id: null, connection: filer01.qa.lab.tlv.redhat.com:/hateya1, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 2c821f70 2012-09-09 20:39:56,191 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-14) [15e0e199] FINISH, DisconnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=477}, log id: 2c821f70