Bug 855648 - [ovirt-engine] connect storage server: distinguish between connection doesn't exists and permission error
Summary: [ovirt-engine] connect storage server: distinguish between connection doesn't...
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine
Version: 3.1.0
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
: 3.1.5
Assignee: Liron Aravot
QA Contact: Haim
URL:
Whiteboard: storage
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-09-09 14:48 UTC by Haim
Modified: 2016-02-10 16:35 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-11-11 07:34:19 UTC
oVirt Team: Storage
Target Upstream Version:
Embargoed:


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

Description Haim 2012-09-09 14:48:15 UTC
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 15:42:05 UTC
Created attachment 611247 [details]
engine.log

Comment 2 Liron Aravot 2012-11-07 15:10:52 UTC
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 08:30:42 UTC
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.