<div dir="ltr"><br><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Apr 20, 2017 at 11:55 AM, Piotr Kliczewski <span dir="ltr"><<a href="mailto:piotr.kliczewski@gmail.com" target="_blank">piotr.kliczewski@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="HOEnZb"><div class="h5">On Thu, Apr 20, 2017 at 10:32 AM, Yaniv Kaul <<a href="mailto:ykaul@redhat.com">ykaul@redhat.com</a>> wrote:<br>
> No, that's not the issue.<br>
> I've seen it happening few times.<br>
><br>
> 1. It always with the ISO domain (which we don't use anyway in o-s-t)<br>
> 2. Apparently, only one host is asking for a mount:<br>
> authenticated mount request from <a href="http://192.168.201.4:713" rel="noreferrer" target="_blank">192.168.201.4:713</a> for /exports/nfs/iso<br>
> (/exports/nfs/iso)<br>
><br>
> (/var/log/messages of the NFS server)<br>
><br>
> And indeed, you can see in[1] that host1 made the request and all is well on<br>
> it.<br>
><br>
> However, there are connection issues with host0 which cause a timeout to<br>
> connectStorageServer():<br>
> From[2]:<br>
><br>
> 2017-04-19 18:58:58,465-04 DEBUG<br>
> [org.ovirt.vdsm.jsonrpc.<wbr>client.internal.<wbr>ResponseWorker] (ResponseWorker) []<br>
> Message received:<br>
> {"jsonrpc":"2.0","error":{"<wbr>code":"lago-basic-suite-<wbr>master-host0:192912448","<wbr>message":"Vds<br>
> timeout occured"},"id":null}<br>
><br>
> 2017-04-19 18:58:58,475-04 ERROR<br>
> [org.ovirt.engine.core.dal.<wbr>dbbroker.auditloghandling.<wbr>AuditLogDirector]<br>
> (org.ovirt.thread.pool-7-<wbr>thread-37) [755b908a] EVENT_ID:<br>
> VDS_BROKER_COMMAND_FAILURE(10,<wbr>802), Correlation ID: null, Call Stack: null,<br>
> Custom Event ID: -1, Message: VDSM lago-basic-suite-master-host0 command<br>
> ConnectStorageServerVDS failed: Message timeout which can be caused by<br>
> communication issues<br>
> 2017-04-19 18:58:58,475-04 INFO<br>
> [org.ovirt.engine.core.<wbr>vdsbroker.vdsbroker.<wbr>ConnectStorageServerVDSCommand<wbr>]<br>
> (org.ovirt.thread.pool-7-<wbr>thread-37) [755b908a] Command<br>
> 'org.ovirt.engine.core.<wbr>vdsbroker.vdsbroker.<wbr>ConnectStorageServerVDSCommand<wbr>'<br>
> return value '<br>
> ServerConnectionStatusReturn:{<wbr>status='Status [code=5022, message=Message<br>
> timeout which can be caused by communication issues]'}<br>
><br>
><br>
> I wonder why, but on /var/log/messages[3], I'm seeing:<br>
> Apr 19 18:56:58 lago-basic-suite-master-host0 journal: vdsm Executor WARN<br>
> Worker blocked: <Worker name=jsonrpc/3 running <Task <JsonRpcTask {'params':<br>
> {u'connectionParams': [{u'id': u'4ca8fc84-d872-4a7f-907f-<wbr>9445bda7b6d1',<br>
> u'connection': u'192.168.201.3:/exports/nfs/<wbr>share1', u'iqn': u'', u'user':<br>
> u'', u'tpgt': u'1', u'protocol_version': u'4.2', u'password': '********',<br>
> u'port': u''}], u'storagepoolID': u'00000000-0000-0000-0000-<wbr>000000000000',<br>
> u'domainType': 1}, 'jsonrpc': '2.0', 'method':<br>
> u'StoragePool.<wbr>connectStorageServer', 'id':<br>
> u'057da9c2-1e67-4c2f-9511-<wbr>7d9de250386b'} at 0x2f44110> timeout=60,<br>
> duration=60 at 0x2f44310> task#=9 at 0x2ac11d0><br>
> ...<br>
><br>
<br>
</div></div>I see following sequence:<br>
<br>
The message is sent:<br>
<br>
2017-04-19 18:55:58,020-04 DEBUG<br>
[org.ovirt.vdsm.jsonrpc.<wbr>client.reactors.stomp.<wbr>StompCommonClient]<br>
(org.ovirt.thread.pool-7-<wbr>thread-37) [755b908a] Message sent: SEND<br>
destination:jms.topic.vdsm_<wbr>requests<br>
content-length:381<br>
ovirtCorrelationId:755b908a<br>
reply-to:jms.topic.vdsm_<wbr>responses<br>
<br>
<JsonRpcRequest id: "057da9c2-1e67-4c2f-9511-<wbr>7d9de250386b", method:<br>
StoragePool.<wbr>connectStorageServer, params:<br>
{storagepoolID=00000000-0000-<wbr>0000-0000-000000000000, domainType=1,<br>
connectionParams=[{password=, protocol_version=4.2, port=, iqn=,<br>
connection=192.168.201.3:/<wbr>exports/nfs/share1,<br>
id=4ca8fc84-d872-4a7f-907f-<wbr>9445bda7b6d1, user=, tpgt=1}]}><br>
<br>
There is no response for specified amount of time and we timeout:<br>
<span class=""><br>
2017-04-19 18:58:58,465-04 DEBUG<br>
[org.ovirt.vdsm.jsonrpc.<wbr>client.internal.<wbr>ResponseWorker]<br>
(ResponseWorker) [] Message received:<br>
{"jsonrpc":"2.0","error":{"<wbr>code":"lago-basic-suite-<wbr>master-host0:192912448","<wbr>message":"Vds<br>
timeout occured"},"id":null}<br>
<br>
</span>As Yaniv pointed here is why we never get the response:<br>
<br>
Apr 19 18:58:58 lago-basic-suite-master-host0 journal: vdsm Executor<br>
<span class="">WARN Worker blocked: <Worker name=jsonrpc/3 running <Task <JsonRpcTask<br>
{'params': {u'connectionParams': [{u'id':<br>
u'4ca8fc84-d872-4a7f-907f-<wbr>9445bda7b6d1', u'connection':<br>
u'192.168.201.3:/exports/nfs/<wbr>share1', u'iqn': u'', u'user': u'',<br>
u'tpgt': u'1', u'protocol_version': u'4.2', u'password': '********',<br>
u'port': u''}], u'storagepoolID':<br>
u'00000000-0000-0000-0000-<wbr>000000000000', u'domainType': 1}, 'jsonrpc':<br>
'2.0', 'method': u'StoragePool.<wbr>connectStorageServer', 'id':<br>
u'057da9c2-1e67-4c2f-9511-<wbr>7d9de250386b'} at 0x2f44110> timeout=60,<br>
</span>duration=180 at 0x2f44310> task#=9 at 0x2ac11d0><br>
<span class=""><br>
><br>
> 3. Also, there is still the infamous unable to update response issues.<br>
><br>
<br>
</span>When we see timeout on a call our default behavior is to reconnect<br>
when we clean pending messages.<br>
As a result when we reconnect and receive a response from the message<br>
sent before disconnect<br>
we say it is unknown to us.<br></blockquote><div><br></div><div>But the example I've given was earlier than the storage issue?</div><div>Y.</div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div class="HOEnZb"><div class="h5"><br>
> {"jsonrpc":"2.0","method":"<wbr>Host.ping","params":{},"id":"<wbr>7cb6052f-c732-4f7c-bd2d-<wbr>e48c2ae1f5e0"}�<br>
> 2017-04-19 18:54:27,843-04 DEBUG<br>
> [org.ovirt.vdsm.jsonrpc.<wbr>client.reactors.stomp.<wbr>StompCommonClient]<br>
> (org.ovirt.thread.pool-7-<wbr>thread-15) [62d198cc] Message sent: SEND<br>
> destination:jms.topic.vdsm_<wbr>requests<br>
> content-length:94<br>
> ovirtCorrelationId:62d198cc<br>
> reply-to:jms.topic.vdsm_<wbr>responses<br>
><br>
> <JsonRpcRequest id: "7cb6052f-c732-4f7c-bd2d-<wbr>e48c2ae1f5e0", method:<br>
> Host.ping, params: {}><br>
> 2017-04-19 18:54:27,885-04 DEBUG<br>
> [org.ovirt.vdsm.jsonrpc.<wbr>client.reactors.stomp.impl.<wbr>Message]<br>
> (org.ovirt.thread.pool-7-<wbr>thread-16) [1f9aac13] SEND<br>
> ovirtCorrelationId:1f9aac13<br>
> destination:jms.topic.vdsm_<wbr>requests<br>
> reply-to:jms.topic.vdsm_<wbr>responses<br>
> content-length:94<br>
><br>
> ...<br>
><br>
> {"jsonrpc": "2.0", "id": "7cb6052f-c732-4f7c-bd2d-<wbr>e48c2ae1f5e0", "result":<br>
> true}�<br>
> 2017-04-19 18:54:32,132-04 DEBUG<br>
> [org.ovirt.vdsm.jsonrpc.<wbr>client.internal.<wbr>ResponseWorker] (ResponseWorker) []<br>
> Message received: {"jsonrpc": "2.0", "id":<br>
> "7cb6052f-c732-4f7c-bd2d-<wbr>e48c2ae1f5e0", "result": true}<br>
> 2017-04-19 18:54:32,133-04 ERROR<br>
> [org.ovirt.vdsm.jsonrpc.<wbr>client.JsonRpcClient] (ResponseWorker) [] Not able<br>
> to update response for "7cb6052f-c732-4f7c-bd2d-<wbr>e48c2ae1f5e0"<br>
><br>
><br>
> Would be nice to understand why.<br>
><br>
><br>
><br>
> 4. Lastly, MOM is not running. Why?<br>
><br>
><br>
> Please open a bug with the details from item #2 above.<br>
> Y.<br>
><br>
><br>
> [1]<br>
> <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6403/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-002_bootstrap.py/lago-basic-suite-master-host1/_var_log/vdsm/supervdsm.log" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>test-repo_ovirt_experimental_<wbr>master/6403/artifact/exported-<wbr>artifacts/basic-suit-master-<wbr>el7/test_logs/basic-suite-<wbr>master/post-002_bootstrap.py/<wbr>lago-basic-suite-master-host1/<wbr>_var_log/vdsm/supervdsm.log</a><br>
> [2]<br>
> <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6403/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-002_bootstrap.py/lago-basic-suite-master-engine/_var_log/ovirt-engine/engine.log" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>test-repo_ovirt_experimental_<wbr>master/6403/artifact/exported-<wbr>artifacts/basic-suit-master-<wbr>el7/test_logs/basic-suite-<wbr>master/post-002_bootstrap.py/<wbr>lago-basic-suite-master-<wbr>engine/_var_log/ovirt-engine/<wbr>engine.log</a><br>
> [3]<br>
> <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6403/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-002_bootstrap.py/lago-basic-suite-master-host0/_var_log/messages" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>test-repo_ovirt_experimental_<wbr>master/6403/artifact/exported-<wbr>artifacts/basic-suit-master-<wbr>el7/test_logs/basic-suite-<wbr>master/post-002_bootstrap.py/<wbr>lago-basic-suite-master-host0/<wbr>_var_log/messages</a><br>
><br>
><br>
><br>
><br>
><br>
> On Thu, Apr 20, 2017 at 9:27 AM, Gil Shinar <<a href="mailto:gshinar@redhat.com">gshinar@redhat.com</a>> wrote:<br>
>><br>
>> Test failed: add_secondary_storage_domains<br>
>> Link to suspected patches:<br>
>> Link to Job:<br>
>> <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6403" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>test-repo_ovirt_experimental_<wbr>master/6403</a><br>
>> Link to all logs:<br>
>> <a href="http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/6403/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-002_bootstrap.py" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>test-repo_ovirt_experimental_<wbr>master/6403/artifact/exported-<wbr>artifacts/basic-suit-master-<wbr>el7/test_logs/basic-suite-<wbr>master/post-002_bootstrap.py</a><br>
>><br>
>><br>
>> Error seems to be:<br>
>> 2017-04-19 18:58:58,774-0400 ERROR (jsonrpc/2) [storage.TaskManager.Task]<br>
>> (Task='8f9699ed-cc2f-434b-<wbr>aa1e-b3c8ff30324a') Unexpected error (task:871)<br>
>> Traceback (most recent call last):<br>
>> File "/usr/lib/python2.7/site-<wbr>packages/vdsm/storage/task.py"<wbr>, line 878,<br>
>> in _run<br>
>> return fn(*args, **kargs)<br>
>> File "/usr/lib/python2.7/site-<wbr>packages/vdsm/logUtils.py", line 52, in<br>
>> wrapper<br>
>> res = f(*args, **kwargs)<br>
>> File "/usr/share/vdsm/storage/hsm.<wbr>py", line 2709, in<br>
>> getStorageDomainInfo<br>
>> dom = self.validateSdUUID(sdUUID)<br>
>> File "/usr/share/vdsm/storage/hsm.<wbr>py", line 298, in validateSdUUID<br>
>> sdDom = sdCache.produce(sdUUID=sdUUID)<br>
>> File "/usr/share/vdsm/storage/sdc.<wbr>py", line 112, in produce<br>
>> domain.getRealDomain()<br>
>> File "/usr/share/vdsm/storage/sdc.<wbr>py", line 53, in getRealDomain<br>
>> return self._cache._realProduce(self.<wbr>_sdUUID)<br>
>> File "/usr/share/vdsm/storage/sdc.<wbr>py", line 136, in _realProduce<br>
>> domain = self._findDomain(sdUUID)<br>
>> File "/usr/share/vdsm/storage/sdc.<wbr>py", line 153, in _findDomain<br>
>> return findMethod(sdUUID)<br>
>> File "/usr/share/vdsm/storage/sdc.<wbr>py", line 178, in _findUnfetchedDomain<br>
>> raise se.StorageDomainDoesNotExist(<wbr>sdUUID)<br>
>> StorageDomainDoesNotExist: Storage domain does not exist:<br>
>> (u'ac3bbc93-26ba-4ea8-8e76-<wbr>c5b761f01931',)<br>
>> 2017-04-19 18:58:58,777-0400 INFO (jsonrpc/2) [storage.TaskManager.Task]<br>
>> (Task='8f9699ed-cc2f-434b-<wbr>aa1e-b3c8ff30324a') aborting: Task is aborted:<br>
>> 'Storage domain does not exist' - code 358 (task:1176)<br>
>> 2017-04-19 18:58:58,777-0400 ERROR (jsonrpc/2) [storage.Dispatcher]<br>
>> {'status': {'message': "Storage domain does not exist:<br>
>> (u'ac3bbc93-26ba-4ea8-8e76-<wbr>c5b761f01931',)", 'code': 358}} (dispatcher:78)<br>
>><br>
>> ______________________________<wbr>_________________<br>
>> Devel mailing list<br>
>> <a href="mailto:Devel@ovirt.org">Devel@ovirt.org</a><br>
>> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank">http://lists.ovirt.org/<wbr>mailman/listinfo/devel</a><br>
><br>
><br>
><br>
> ______________________________<wbr>_________________<br>
> Devel mailing list<br>
> <a href="mailto:Devel@ovirt.org">Devel@ovirt.org</a><br>
> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank">http://lists.ovirt.org/<wbr>mailman/listinfo/devel</a><br>
</div></div></blockquote></div><br></div></div>