Bug 855648 - [ovirt-engine] connect storage server: distinguish between connection doesn't exists and permission error
[ovirt-engine] connect storage server: distinguish between connection doesn't...
Status: CLOSED NOTABUG
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.1.0
x86_64 Linux
unspecified Severity high
: ---
: 3.1.5
Assigned To: Liron Aravot
Haim
storage
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-09-09 10:48 EDT by Haim
Modified: 2016-02-10 11:35 EST (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-11-11 02:34:19 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Storage
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
engine.log (60.06 KB, application/x-gzip)
2012-09-09 11:42 EDT, Haim
no flags Details

  None (edit)
Description Haim 2012-09-09 10:48:15 EDT
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
Comment 1 Haim 2012-09-09 11:42:05 EDT
Created attachment 611247 [details]
engine.log
Comment 2 Liron Aravot 2012-11-07 10:10:52 EST
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?
Comment 3 Liron Aravot 2012-11-08 03:30:42 EST
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.

Note You need to log in before you can comment on or make changes to this bug.