Bug 1574744 - Slow prepareImage prevents the HostedEngine from starting
Summary: Slow prepareImage prevents the HostedEngine from starting
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-hosted-engine-ha
Version: 4.1.10
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ovirt-4.2.4
: ---
Assignee: Martin Sivák
QA Contact: meital avital
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-04 00:08 UTC by Germano Veit Michel
Modified: 2019-05-16 13:18 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-05-18 07:53:37 UTC
oVirt Team: SLA
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 3435041 0 None None None 2018-05-08 03:18:25 UTC

Description Germano Veit Michel 2018-05-04 00:08:34 UTC
Description of problem:

Some lvm commands take slightly longer than usual (around 3s each). This is not ideal but the consequences are quit ugly. The HostedEngine won't start and the whole environment is down.

1. Agent calls broker with set_storage_domain, and waits for 30s, times out waiting for the response

MainThread::ERROR::2018-05-02 14:39:58,973::brokerlink::280::ovirt_hosted_engine_ha.lib.brokerlink.BrokerLink::(_communicate) Connection closed: Connection timed out

MainThread::INFO::2018-05-02 14:39:58,973::hosted_engine::595::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_initialize_broker) Failed set the storage domain: 'Failed to set storage domain VdsmBackend, options {'hosted-engine.lockspace': '7B22696D6167655F75756964223A202235666336663538652D623563662D343065622D626134352D323335353765633166373263222C202270617468223A206E756C6C2C2022766F6C756D655F75756964223A202263323031636136382D393565322D346237612D393539392D653230363037633337393739227D', 'sp_uuid': '00000000-0000-0000-0000-000000000000', 'dom_type': 'fc', 'hosted-engine.metadata': '7B22696D6167655F75756964223A202233633062646266632D343339342D343361612D393661652D643362383534393733663364222C202270617468223A206E756C6C2C2022766F6C756D655F75756964223A202263396439346563322D633838392D343632652D393861622D616564336435356537333263227D', 'sd_uuid': '381e37fb-394c-4511-b088-88501085aed1'}: Connection timed out'. Waiting '5's before the next attempt

2. Broker receives the request

Thread-64::DEBUG::2018-05-02 14:39:28,943::listener::163::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Input: set-storage-domain VdsmBackend hosted-engine.lockspace=7B22696D6167655F75756964223A202235666336663538652D623563662D343065622D626134352D323335353765633166373263222C202270617468223A206E756C6C2C2022766F6C756D655F75756964223A202263323031636136382D393565322D346237612D393539392D653230363037633337393739227D sp_uuid=00000000-0000-0000-0000-000000000000 dom_type=fc hosted-engine.metadata=7B22696D6167655F75756964223A202233633062646266632D343339342D343361612D393661652D643362383534393733663364222C202270617468223A206E756C6C2C2022766F6C756D655F75756964223A202263396439346563322D633838392D343632652D393861622D616564336435356537333263227D sd_uuid=381e37fb-394c-4511-b088-88501085aed1
Thread-64::DEBUG::2018-05-02 14:39:28,943::listener::238::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(_dispatch) Request type set-storage-domain from 140381265266432
Thread-64::DEBUG::2018-05-02 14:39:28,944::storage_broker::65::ovirt_hosted_engine_ha.broker.storage_broker.StorageBroker::(set_storage_domain) Connecting to <ovirt_hosted_engine_ha.lib.storage_backends.VdsmBackend object at 0x26075d0>

3. Broker contacts VDSM

Thread-64::DEBUG::2018-05-02 14:39:28,944::storage_backends::395::ovirt_hosted_engine_ha.lib.storage_backends::(connect) Connecting to VDSM

Thread-64::DEBUG::2018-05-02 14:39:31,956::util::209::ovirt_hosted_engine_ha.lib.storage_backends::(connect_vdsm_json_rpc) {'status': {'message': 'Done', 'code': 0}, u'systemProductName': u'Synergy 480 Gen9', u'systemSerialNumber': u'VCGGLCV001', u'systemFamily': u'Synergy', u'systemUUID': u'C21FA933-C275-4016-909E-6C9B0558ECD8', u'systemManufacturer': u'HP'}

4. Broker requests prepare-image for hosted-engine.lockspace to VDSM

Thread-64::DEBUG::2018-05-02 14:39:46,891::storage_backends::246::ovirt_hosted_engine_ha.lib.storage_backends::(_get_volume_path) prepareImage: '{'status': {'message': 'Done', 'code': 0}, u'path': u'/var/run/vdsm/storage/381e37fb-394c-4511-b088-88501085aed1/5fc6f58e-b5cf-40eb-ba45-23557ec1f72c/c201ca68-95e2-4b7a-9599-e20607c37979'}'
Thread-64::DEBUG::2018-05-02 14:39:46,892::storage_backends::248::ovirt_hosted_engine_ha.lib.storage_backends::(_get_volume_path) prepareImage: returned '/var/run/vdsm/storage/381e37fb-394c-4511-b088-88501085aed1/5fc6f58e-b5cf-40eb-ba45-23557ec1f72c/c201ca68-95e2-4b7a-9599-e20607c37979' as path
Thread-64::INFO::2018-05-02 14:39:46,892::storage_backends::119::ovirt_hosted_engine_ha.lib.storage_backends::(_check_symlinks) Cleaning up stale LV link '/rhev/data-center/mnt/blockSD/381e37fb-394c-4511-b088-88501085aed1/ha_agent/hosted-engine.lockspace'

5. Broker requests prepare-image for hosted-engine.metadata to VDSM

Thread-64::DEBUG::2018-05-02 14:40:01,708::storage_backends::246::ovirt_hosted_engine_ha.lib.storage_backends::(_get_volume_path) prepareImage: '{'status': {'message': 'Done', 'code': 0}, u'path': u'/var/run/vdsm/storage/381e37fb-394c-4511-b088-88501085aed1/3c0bdbfc-4394-43aa-96ae-d3b854973f3d/c9d94ec2-c889-462e-98ab-aed3d55e732c'}'
Thread-64::DEBUG::2018-05-02 14:40:01,708::storage_backends::248::ovirt_hosted_engine_ha.lib.storage_backends::(_get_volume_path) prepareImage: returned '/var/run/vdsm/storage/381e37fb-394c-4511-b088-88501085aed1/3c0bdbfc-4394-43aa-96ae-d3b854973f3d/c9d94ec2-c889-462e-98ab-aed3d55e732c' as path
Thread-64::INFO::2018-05-02 14:40:01,709::storage_backends::119::ovirt_hosted_engine_ha.lib.storage_backends::(_check_symlinks) Cleaning up stale LV link '/rhev/data-center/mnt/blockSD/381e37fb-394c-4511-b088-88501085aed1/ha_agent/hosted-engine.metadata'

6. Broker returns with success. 

Thread-64::DEBUG::2018-05-02 14:40:01,711::listener::170::ovirt_hosted_engine_ha.broker.listener.ConnectionHandler::(handle) Response: success 39876048

But this took 32,744s. And the agent will only wait for 30s (hardcoded):
MESSAGE_READ_TIMEOUT_SEC = 30.0

So this never completes, the HostedEngine is down and cannot be started.

On the VDSM side, the lvm commands take slightly longer than usual:

2018-05-03 20:33:54,537+0000 DEBUG (jsonrpc/0) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-87 /usr/bin/sudo -n /sbin/lvm lvchange --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/360002ac000000000000000020001f7c1|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --refresh 381e37fb-394c-4511-b088-88501085aed1/leases (cwd None) (commands:69)

...~3 secs (lvm refresh)...

2018-05-03 20:33:58,192+0000 DEBUG (jsonrpc/0) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:93)

SUMMARY:
* Agent requests set_storage_domain to broker and waits 30s for reply
* Broker succeeds in doing it but takes 32,744s, because each prepareImage call to VDSM takes ~15s.
* 32,744s > 30s, Agent closes the connection due to timeout, and never sees the successful return, even if all succeeded.

REQUESTED:
* Not sure if MESSAGE_READ_TIMEOUT_SEC should be configurable to workaround such scenarios and bring up the HE. 
* Why prepareImage all the time for images that are already prepared? I remember some fixes around this, maybe this is already improved in 4.2?

Version-Release number of selected component (if applicable):
ovirt-hosted-engine-ha-2.1.11-1.el7ev.noarch

Comment 1 Martin Sivák 2018-05-04 09:31:45 UTC
This is significantly improved in 4.2, we do not refresh the volumes anymore if all is fine.

Comment 2 Germano Veit Michel 2018-05-08 03:05:58 UTC
(In reply to Martin Sivák from comment #1)
> This is significantly improved in 4.2, we do not refresh the volumes anymore
> if all is fine.

In 4.1 I can see that once the images are prepared and all is running fine, it does not refresh the volumes anymore.

But here we are seeing a loop of:

1. agent start
2. prepare images
3. timeout (takes more than 30s)
4. goto 1

So after agent restart, it tries to prepareImages again, even if the images are already prepared.

Was this changed in 4.2?

Comment 3 Martin Sivák 2018-05-09 13:03:21 UTC
Probably not. I guess increasing the timeout is possible, although 30 seconds is a bit extreme.

Comment 5 Martin Sivák 2018-05-14 10:58:24 UTC
Hmm I just realized we changed the architecture in 4.2. Is there a way to check whether this is happening in 4.2 as well? The connection command is internal to broker there and no communication timeout should be happening.

Comment 6 Germano Veit Michel 2018-05-15 04:41:36 UTC
(In reply to Martin Sivák from comment #5)
> Hmm I just realized we changed the architecture in 4.2. Is there a way to
> check whether this is happening in 4.2 as well? The connection command is
> internal to broker there and no communication timeout should be happening.

Maybe add some sleeps on vdsm prepareImages code?

Comment 7 Germano Veit Michel 2018-05-18 01:15:02 UTC
Another ticket. We are troubleshooting the slow lvs commands, which shouldn't happen.

But it would be nicer if this mechanism was more resilient with slow lvm/storage, especially to bring the HE up.

Comment 8 Germano Veit Michel 2018-05-18 05:25:35 UTC
Hi Martin,

I added a sleep(20) in API.py for Image.prepare for the Hosted_Engine SD:

    def prepare(self, volumeID, allowIllegal=False):
        if self._sdUUID == "21ae95db-0f97-4c06-bb60-e3ba541400f0":
            time.sleep(20)
        return self._irs.prepareImage(self._sdUUID, self._spUUID,
                                      self._UUID, volumeID,
                                      allowIllegal=allowIllegal)

Version: ovirt-hosted-engine-ha-2.2.11-1.el7ev.noarch

This is the result of every prepareImage call from the broker/agent to the HE SD:
2018-05-18 10:50:26,624+0530 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Image.prepare succeeded in 20.04 seconds (__init__:573)

Given there are 4 images to prepare this should easily go above 30s.

And there is no timeout on the ha daemons, all is working fine (but slowly). So the new mechanism is more resilient to storage slowdowns.

If you agree that this test is valid, feel free to close the bug.

Comment 9 Martin Sivák 2018-05-18 07:53:37 UTC
Thanks Germano, yes we improved the behaviour a lot in 4.2. The test seems to be fine, this method is exactly what we call to prepare the images.

Since the bug was reported against 4.1 and we seem to fixed it in 4.2 I will close as current release. There is no backport likely as it was almost a complete rewrite of the storage part.

Comment 10 Franta Kust 2019-05-16 13:08:42 UTC
BZ<2>Jira Resync


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