New subject: New setup - Failing to Activate storage domain on NFS shared storage

Monday, 18 January 2021

I installed ovirt node 4.4.4 as well as 4.4.5-pre and experience the same problem with
both versions. The issue occurs in both cockpit UI and tmux'd CLI of
ovirt-hosted-engine-setup. I get passed the point where the VM is created and running.
I tried to do some debugging on my own before reaching out to this list. Any help is much
appreciated!

ovirt node hardware: NUC format Jetway w/ Intel N3160 (Braswell 4 cores/4threads), 8GB
RAM, 64GB SSD. I understand this is underspec'd, but I believe it meets the minimum
requirements.

NFS server: 
* Ubuntu 19.10 w/ ZFS share w/ 17TB available space. 
* NFS share settings are just &#39;rw=(a)172.16.1.0/24&#39; but have also tried
'rw,sec=sys,anon=0' and &#39;(a)172.16.1.0/24,insecure&#39;
* The target directory is always empty and chown'd 36:36 with 0755 permissions.
* I have tried using both IP and DNS names. forward and reverse DNS works from ovirt host
and other systems on the network. 
* The NFS share always gets mounted successfully on the ovirt node system.
* I have tried auto and v3 NFS versions in other various combinations.
* I have also tried setting up an NFS server on a non-ZFS backed storage system that is
open to any host and get the same errors as shown below.
* I ran nfs-check.py script without issue against both NFS servers and followed other
verification steps listed on
https://www.ovirt.org/develop/troubleshooting-nfs-storage-issues.html

***Snip from ovirt-hosted-engine-setup***
          Please specify the storage you would like to use (glusterfs, iscsi, fc,
nfs)[nfs]: nfs                                                                            

          Please specify the nfs version you would like to use (auto, v3, v4, v4_0, v4_1,
v4_2)[auto]:                                                                     
          Please specify the full shared storage connection path to use (example:
host:/path): stumpy.mydomain.com:/tanker/ovirt/host_storage                               

          If needed, specify additional mount options for the connection to the
hosted-engine storagedomain (example: rsize=32768,wsize=32768) []: rw
[ INFO  ] Creating Storage Domain
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Execute just a specific set of steps]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Force facts gathering]
[ INFO  ] ok: [localhost]                                                                 

[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Wait for the storage interface to be up]

[ INFO  ] skipping: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Check local VM dir stat]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Enforce local VM dir existence]
[ INFO  ] skipping: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : include_tasks]
[ INFO  ] ok: [localhost]                                                                 

[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Obtain SSO token using username/password
credentials]                                                                      
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Fetch host facts]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Fetch cluster ID]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Fetch cluster facts]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Fetch Datacenter facts]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Fetch Datacenter ID]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Fetch Datacenter name]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Add NFS storage domain]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Add glusterfs storage domain]
[ INFO  ] skipping: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Add iSCSI storage domain]
[ INFO  ] skipping: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Add Fibre Channel storage domain]
[ INFO  ] skipping: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Get storage domain details]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Find the appliance OVF]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Parse OVF]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Get required size]
[ INFO  ] ok: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Remove unsuitable storage domain]
[ INFO  ] skipping: [localhost]
[ INFO  ] skipping: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Check storage domain free space]
[ INFO  ] skipping: [localhost]
[ INFO  ] TASK [ovirt.ovirt.hosted_engine_setup : Activate storage domain]
[ ERROR ] ovirtsdk4.Error: Fault reason is "Operation Failed". Fault detail is
"[]". HTTP response code is 400.
[ ERROR ] fatal: [localhost]: FAILED! => {"changed": false, "msg":
"Fault reason is \"Operation Failed\". Fault detail is \"[]\".
HTTP response code is 400."}
          Please specify the storage you would like to use (glusterfs, iscsi, fc,
nfs)[nfs]:

***End snippet**

The relevant section from
/var/log/ovirt-hosted-engine-setup/ovirt-hosted-engine-setup-ansible-create_storage_domain-20210116195220-bnfg1w.log:
**Snip***
2021-01-16 19:53:56,010-0700 DEBUG ansible on_any args
<ansible.executor.task_result.TaskResult object at 0x7f11a04c8320>  kwargs 
2021-01-16 19:53:57,219-0700 INFO ansible task start {'status': 'OK',
'ansible_type': 'task', 'ansible_playbook':
'/usr/share/ovirt-hosted-engine-setup/ansible/trigger_role.yml',
'ansible_task': 'ovirt.ovirt.hosted_engine_setup : Activate storage
domain'}
2021-01-16 19:53:57,220-0700 DEBUG ansible on_any args TASK:
ovirt.ovirt.hosted_engine_setup : Activate storage domain  kwargs is_conditional:False 
2021-01-16 19:53:57,221-0700 DEBUG ansible on_any args localhost TASK:
ovirt.ovirt.hosted_engine_setup : Activate storage domain  kwargs 
2021-01-16 19:54:00,346-0700 DEBUG var changed: host "localhost" var
"ansible_play_hosts" type "<class 'list'>" value:
"[]"
2021-01-16 19:54:00,347-0700 DEBUG var changed: host "localhost" var
"ansible_play_batch" type "<class 'list'>" value:
"[]"
2021-01-16 19:54:00,348-0700 DEBUG var changed: host "localhost" var
"play_hosts" type "<class 'list'>" value:
"[]"
2021-01-16 19:54:00,349-0700 ERROR ansible failed {
    "ansible_host": "localhost",
    "ansible_playbook":
"/usr/share/ovirt-hosted-engine-setup/ansible/trigger_role.yml",
    "ansible_result": {
        "_ansible_no_log": false,
        "changed": false,
        "exception": "Traceback (most recent call last):\n  File
\"/tmp/ansible_ovirt_storage_domain_payload_f38n25ab/ansible_ovirt_storage_domain_payload.zip/ansible_collections/ovirt/ovirt/plugins/modules/ovirt_storage_domain.py\",
line 783, in main\n  File
\"/tmp/ansible_ovirt_storage_domain_payload_f38n25ab/ansible_ovirt_storage_domain_payload.zip/ansible_collections/ovirt/ovirt/plugins/modules/ovirt_storage_domain.py\",
line 638, in post_create_check\n  File
\"/usr/lib64/python3.6/site-packages/ovirtsdk4/services.py\", line 3647, in
add\n    return self._internal_add(storage_domain, headers, query, wait)\n  File
\"/usr/lib64/python3.6/site-packages/ovirtsdk4/service.py\", line 232, in
_internal_add\n    return future.wait() if wait else future\n  File
\"/usr/lib64/python3.6/site-packages/ovirtsdk4/service.py\", line 55, in wait\n 
  return self._code(response)\n  File
\"/usr/lib64/python3.6/site-packages/ovirtsdk4/service.py\", line 229, in
callback\n    self._check_fault(respon
 se)\n  File \"/usr/lib64/python3.6/site-packages/ovirtsdk4/service.py\", line
132, in _check_fault\n    self._raise_error(response, body)\n  File
\"/usr/lib64/python3.6/site-packages/ovirtsdk4/service.py\", line 118, in
_raise_error\n    raise error\novirtsdk4.Error: Fault reason is \"Operation
Failed\". Fault detail is \"[]\". HTTP response code is 400.\n",
        "invocation": {
            "module_args": {
                "backup": null,
                "comment": null,
                "critical_space_action_blocker": null,
                "data_center": "Default",
                "description": null,
                "destroy": null,
                "discard_after_delete": null,
                "domain_function": "data",
                "fcp": null,
                "fetch_nested": false,
                "format": null,
                "glusterfs": null,
                "host": "brick.mydomain.com",
                "id": null,
                "iscsi": null,
                "localfs": null,
                "managed_block_storage": null,
                "name": "hosted_storage",
                "nested_attributes": [],
                "nfs": null,
                "poll_interval": 3,
                "posixfs": null,
                "state": "present",
                "timeout": 180,
                "wait": true,
                "warning_low_space": null,
                "wipe_after_delete": null
            }
        },
        "msg": "Fault reason is \"Operation Failed\". Fault
detail is \"[]\". HTTP response code is 400."
    },
    "ansible_task": "Activate storage domain",
    "ansible_type": "task",
    "status": "FAILED",
    "task_duration": 4
}
2021-01-16 19:54:00,350-0700 DEBUG ansible on_any args
<ansible.executor.task_result.TaskResult object at 0x7f11a05f2d30>  kwargs
ignore_errors:None 
2021-01-16 19:54:00,358-0700 INFO ansible stats {
    "ansible_playbook":
"/usr/share/ovirt-hosted-engine-setup/ansible/trigger_role.yml",
    "ansible_playbook_duration": "01:35 Minutes",
    "ansible_result": "type: <class 'dict'>\nstr:
{'localhost': {'ok': 23, 'failures': 1, 'unreachable': 0,
'changed': 0, 'skipped': 7, 'rescued': 0, 'ignored':
0}}",
    "ansible_type": "finish",
    "status": "FAILED"
}
2021-01-16 19:54:00,359-0700 INFO SUMMARY:
Duration	Task Name
--------	--------
[ < 1 sec ]	Execute just a specific set of steps
[  00:05  ]	Force facts gathering
[  00:03  ]	Check local VM dir stat
[  00:04  ]	Obtain SSO token using username/password credentials
[  00:04  ]	Fetch host facts
[  00:02  ]	Fetch cluster ID
[  00:04  ]	Fetch cluster facts
[  00:04  ]	Fetch Datacenter facts
[  00:02  ]	Fetch Datacenter ID
[  00:02  ]	Fetch Datacenter name
[  00:04  ]	Add NFS storage domain
[  00:04  ]	Get storage domain details
[  00:03  ]	Find the appliance OVF
[  00:03  ]	Parse OVF
[  00:02  ]	Get required size
[ FAILED  ]	Activate storage domain
2021-01-16 19:54:00,359-0700 DEBUG ansible on_any args
<ansible.executor.stats.AggregateStats object at 0x7f11a2e3b8d0>  kwargs 
**End snip**

The relevantsection from /var/log/vdsm/vdsm.log:
***begin snip***
2021-01-16 19:53:58,439-0700 INFO  (vmrecovery) [vdsm.api] START
getConnectedStoragePoolsList(options=None) from=internal,
task_id=b8b21668-189e-4b68-a7f0-c2d2ebf14546 (api:48)
2021-01-16 19:53:58,439-0700 INFO  (vmrecovery) [vdsm.api] FINISH
getConnectedStoragePoolsList return={'poollist': []} from=internal,
task_id=b8b21668-189e-4b68-a7f0-c2d2ebf14546 (api:54)
2021-01-16 19:53:58,440-0700 INFO  (vmrecovery) [vds] recovery: waiting for storage pool
to go up (clientIF:726)
2021-01-16 19:53:58,885-0700 INFO  (jsonrpc/3) [vdsm.api] START
connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000',
conList=[{'password': '********', 'protocol_version':
'auto', 'port': '', 'iqn': '',
'connection': 'stumpy:/tanker/ovirt/host_storage', 'ipv6_enabled':
'false', 'id': '3ffd1e3b-168e-4248-a2af-b28fbdf49eef',
'user': '', 'tpgt': '1'}], options=None)
from=::ffff:192.168.222.53,41192, flow_id=592e278f,
task_id=5bd52fa3-f790-4ed3-826d-c1f51e5f2291 (api:48)
2021-01-16 19:53:58,892-0700 INFO  (jsonrpc/3) [storage.StorageDomainCache] Invalidating
storage domain cache (sdc:74)
2021-01-16 19:53:58,892-0700 INFO  (jsonrpc/3) [vdsm.api] FINISH connectStorageServer
return={'statuslist': [{'id':
'3ffd1e3b-168e-4248-a2af-b28fbdf49eef', 'status': 0}]}
from=::ffff:192.168.222.53,41192, flow_id=592e278f,
task_id=5bd52fa3-f790-4ed3-826d-c1f51e5f2291 (api:54)
2021-01-16 19:53:58,914-0700 INFO  (jsonrpc/6) [vdsm.api] START
getStorageDomainInfo(sdUUID='54532dd4-3e5b-4885-b88e-599c81efb146', options=None)
from=::ffff:192.168.222.53,41192, flow_id=592e278f,
task_id=4d5a352d-6096-45b7-a4ee-b6e08ac02f7b (api:48)
2021-01-16 19:53:58,914-0700 INFO  (jsonrpc/6) [storage.StorageDomain]
sdUUID=54532dd4-3e5b-4885-b88e-599c81efb146 (fileSD:535)
2021-01-16 19:53:58,918-0700 INFO  (jsonrpc/6) [vdsm.api] FINISH getStorageDomainInfo
error=Domain is either partially accessible or entirely inaccessible:
('54532dd4-3e5b-4885-b88e-599c81efb146',) from=::ffff:192.168.222.53,41192,
flow_id=592e278f, task_id=4d5a352d-6096-45b7-a4ee-b6e08ac02f7b (api:52)
2021-01-16 19:53:58,918-0700 ERROR (jsonrpc/6) [storage.TaskManager.Task]
(Task='4d5a352d-6096-45b7-a4ee-b6e08ac02f7b') Unexpected error (task:880)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 887, in
_run
    return fn(*args, **kargs)
  File "<decorator-gen-131>", line 2, in getStorageDomainInfo
  File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in
method
    ret = func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 2796, in
getStorageDomainInfo
    dom = self.validateSdUUID(sdUUID)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 312, in
validateSdUUID
    sdDom.validate()
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileSD.py", line 538, in
validate
    raise se.StorageDomainAccessError(self.sdUUID)
vdsm.storage.exception.StorageDomainAccessError: Domain is either partially accessible or
entirely inaccessible: ('54532dd4-3e5b-4885-b88e-599c81efb146',)
2021-01-16 19:53:58,918-0700 INFO  (jsonrpc/6) [storage.TaskManager.Task]
(Task='4d5a352d-6096-45b7-a4ee-b6e08ac02f7b') aborting: Task is aborted:
"value=Domain is either partially accessible or entirely inaccessible:
('54532dd4-3e5b-4885-b88e-599c81efb146',) abortedcode=379" (task:1190)
2021-01-16 19:53:58,918-0700 ERROR (jsonrpc/6) [storage.Dispatcher] FINISH
getStorageDomainInfo error=Domain is either partially accessible or entirely inaccessible:
('54532dd4-3e5b-4885-b88e-599c81efb146',) (dispatcher:83)
2021-01-16 19:53:58,919-0700 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call
StorageDomain.getInfo failed (error 379) in 0.00 seconds (__init__:312)
2021-01-16 19:53:58,956-0700 INFO  (jsonrpc/1) [vdsm.api] START
createStoragePool(poolType=None, spUUID='91fb3f22-5795-11eb-ad9f-00163e3f4683',
poolName='Default', masterDom='54532dd4-3e5b-4885-b88e-599c81efb146',
domList=['54532dd4-3e5b-4885-b88e-599c81efb146'], masterVersion=7,
lockPolicy=None, lockRenewalIntervalSec=5, leaseTimeSec=60, ioOpTimeoutSec=10,
leaseRetries=3, options=None) from=::ffff:192.168.222.53,41192, flow_id=592e278f,
task_id=a946357f-537a-4c9c-9040-e70a98ee5643 (api:48)
2021-01-16 19:53:58,958-0700 INFO  (jsonrpc/1) [storage.StoragePool] updating pool
91fb3f22-5795-11eb-ad9f-00163e3f4683 backend from type NoneType instance 0x7f86e45f89d0 to
type StoragePoolDiskBackend instance 0x7f8680738408 (sp:157)
2021-01-16 19:53:58,958-0700 INFO  (jsonrpc/1) [storage.StoragePool]
spUUID=91fb3f22-5795-11eb-ad9f-00163e3f4683 poolName=Default
master_sd=54532dd4-3e5b-4885-b88e-599c81efb146
domList=['54532dd4-3e5b-4885-b88e-599c81efb146'] masterVersion=7
{'LEASERETRIES': 3, 'LEASETIMESEC': 60, 'LOCKRENEWALINTERVALSEC':
5, 'IOOPTIMEOUTSEC': 10} (sp:602)
2021-01-16 19:53:58,958-0700 INFO  (jsonrpc/1) [storage.StorageDomain]
sdUUID=54532dd4-3e5b-4885-b88e-599c81efb146 (fileSD:535)
2021-01-16 19:53:58,963-0700 ERROR (jsonrpc/1) [storage.StoragePool] Unexpected error
(sp:618)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/sp.py", line 613, in
create
    domain.validate()
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileSD.py", line 538, in
validate
    raise se.StorageDomainAccessError(self.sdUUID)
vdsm.storage.exception.StorageDomainAccessError: Domain is either partially accessible or
entirely inaccessible: ('54532dd4-3e5b-4885-b88e-599c81efb146',)
2021-01-16 19:53:58,963-0700 INFO  (jsonrpc/1) [vdsm.api] FINISH createStoragePool
error=Domain is either partially accessible or entirely inaccessible:
('54532dd4-3e5b-4885-b88e-599c81efb146',) from=::ffff:192.168.222.53,41192,
flow_id=592e278f, task_id=a946357f-537a-4c9c-9040-e70a98ee5643 (api:52)
2021-01-16 19:53:58,963-0700 ERROR (jsonrpc/1) [storage.TaskManager.Task]
(Task='a946357f-537a-4c9c-9040-e70a98ee5643') Unexpected error (task:880)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/sp.py", line 613, in
create
    domain.validate()
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileSD.py", line 538, in
validate
    raise se.StorageDomainAccessError(self.sdUUID)
vdsm.storage.exception.StorageDomainAccessError: Domain is either partially accessible or
entirely inaccessible: ('54532dd4-3e5b-4885-b88e-599c81efb146',)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 887, in
_run
    return fn(*args, **kargs)
  File "<decorator-gen-31>", line 2, in createStoragePool
  File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in
method
    ret = func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 1027, in
createStoragePool
    leaseParams)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/sp.py", line 619, in
create
    raise se.StorageDomainAccessError(sdUUID)
vdsm.storage.exception.StorageDomainAccessError: Domain is either partially accessible or
entirely inaccessible: ('54532dd4-3e5b-4885-b88e-599c81efb146',)
2021-01-16 19:53:58,964-0700 INFO  (jsonrpc/1) [storage.TaskManager.Task]
(Task='a946357f-537a-4c9c-9040-e70a98ee5643') aborting: Task is aborted:
"value=Domain is either partially accessible or entirely inaccessible:
('54532dd4-3e5b-4885-b88e-599c81efb146',) abortedcode=379" (task:1190)
2021-01-16 19:53:58,964-0700 ERROR (jsonrpc/1) [storage.Dispatcher] FINISH
createStoragePool error=Domain is either partially accessible or entirely inaccessible:
('54532dd4-3e5b-4885-b88e-599c81efb146',) (dispatcher:83)
2021-01-16 19:53:58,965-0700 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call
StoragePool.create failed (error 379) in 0.01 seconds (__init__:312)
2021-01-16 19:54:01,923-0700 INFO  (jsonrpc/5) [api.host] START getStats()
from=::ffff:192.168.222.53,41192 (api:48)
2021-01-16 19:54:01,964-0700 INFO  (jsonrpc/7) [api.host] START getAllVmStats()
from=::ffff:192.168.222.53,41192 (api:48)
2021-01-16 19:54:01,966-0700 INFO  (jsonrpc/7) [api.host] FINISH getAllVmStats
return={'status': {'code': 0, 'message': 'Done'},
'statsList': (suppressed)} from=::ffff:192.168.222.53,41192 (api:54)
2021-01-16 19:54:01,977-0700 INFO  (jsonrpc/5) [vdsm.api] START repoStats(domains=())
from=::ffff:192.168.222.53,41192, task_id=7a6c8536-3f1e-41b3-9ab7-bb58a5e75fac (api:48)
2021-01-16 19:54:01,978-0700 INFO  (jsonrpc/5) [vdsm.api] FINISH repoStats return={}
from=::ffff:192.168.222.53,41192, task_id=7a6c8536-3f1e-41b3-9ab7-bb58a5e75fac (api:54)
2021-01-16 19:54:01,980-0700 INFO  (jsonrpc/5) [vdsm.api] START multipath_health()
from=::ffff:192.168.222.53,41192, task_id=b8af45b5-6488-4940-b7d0-1d11b5f76db4 (api:48)
2021-01-16 19:54:01,981-0700 INFO  (jsonrpc/5) [vdsm.api] FINISH multipath_health
return={} from=::ffff:192.168.222.53,41192, task_id=b8af45b5-6488-4940-b7d0-1d11b5f76db4
(api:54)
2021-01-16 19:54:01,996-0700 INFO  (jsonrpc/5) [api.host] FINISH getStats
return={'status': {'code': 0, 'message': 'Done'},
'info': (suppressed)} from=::ffff:192.168.222.53,41192 (api:54)
***end snip***

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

New setup - Failing to Activate storage domain on NFS shared storage