2:40 p.m.
This is a multi-part message in MIME format.
--------------060105040505080104010504
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
Hi,
In sampling.py, remove() is being called without calling add() before,
which throws:
JsonRpc (StompReactor)::DEBUG::2015-04-28
17:35:55,061::stompReactor::94::Broker.StompAdapter::(handle_frame)
Handling message <StompFrame command=u'SEND'>
Thread-37401::DEBUG::2015-04-28
17:35:55,062::__init__::445::jsonrpc.JsonRpcServer::(_serveRequest)
Calling 'VM.destroy' in bridge with {u'vmID':
u'6ec9c0a0-2879-4bfe-9a79-92471881ebfe'}
JsonRpcServer::DEBUG::2015-04-28
17:35:55,062::__init__::482::jsonrpc.JsonRpcServer::(serve_requests)
Waiting for request
Thread-37401::INFO::2015-04-28
17:35:55,062::API::334::vds::(destroy) vmContainerLock acquired by
vm 6ec9c0a0-2879-4bfe-9a79-92471881ebfe
Thread-37401::DEBUG::2015-04-28
17:35:55,062::vm::3513::vm.Vm::(destroy)
vmId=`6ec9c0a0-2879-4bfe-9a79-92471881ebfe`::destroy Called
Thread-37401::INFO::2015-04-28
17:35:55,062::vm::3444::vm.Vm::(releaseVm)
vmId=`6ec9c0a0-2879-4bfe-9a79-92471881ebfe`::Release VM resources
Thread-37401::WARNING::2015-04-28
17:35:55,062::vm::375::vm.Vm::(_set_lastStatus)
vmId=`6ec9c0a0-2879-4bfe-9a79-92471881ebfe`::trying to set state to
Powering down when already Down
Thread-37401::ERROR::2015-04-28
17:35:55,063::__init__::469::jsonrpc.JsonRpcServer::(_serveRequest)
Internal server error
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py",
line 464, in _serveRequest
res = method(**params)
File "/usr/share/vdsm/rpc/Bridge.py", line 273, in _dynamicMethod
result = fn(*methodArgs)
File "/usr/share/vdsm/API.py", line 339, in destroy
res = v.destroy()
File "/usr/share/vdsm/virt/vm.py", line 3515, in destroy
result = self.doDestroy()
File "/usr/share/vdsm/virt/vm.py", line 3533, in doDestroy
return self.releaseVm()
File "/usr/share/vdsm/virt/vm.py", line 3448, in releaseVm
sampling.stats_cache.remove(self.id)
File "/usr/share/vdsm/virt/sampling.py", line 428, in remove
if vmid in self._vm_last_timestamp.keys():
KeyError: u'6ec9c0a0-2879-4bfe-9a79-92471881ebfe'
Thread-37401::DEBUG::2015-04-28
17:35:55,063::stompReactor::158::yajsonrpc.StompServer::(send)
Sending response
In file '/usr/share/vdsm/virt/sampling.py':
def add(self, vmid):
"""
Warm up the cache for the given VM.
This is to avoid races during the first sampling and the first
reporting, which may result in a VM wrongly reported as
unresponsive.
"""
with self._lock:
self._vm_last_timestamp[vmid] = self._clock()
def remove(self, vmid):
"""
Remove any data from the cache related to the given VM.
"""
with self._lock:
* if vmid in
self._vm_last_timestamp.keys():**<----------------- I patched here as a
workarround
** del self._vm_last_timestamp[vmid]*
--------------060105040505080104010504
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit
<html>
<head>
<meta http-equiv="content-type" content="text/html;
charset=utf-8">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hi,<br>
<br>
In sampling.py, remove() is being called without calling add()
before, which throws:<br>
<blockquote>JsonRpc (StompReactor)::DEBUG::2015-04-28
17:35:55,061::stompReactor::94::Broker.StompAdapter::(handle_frame)
Handling message <StompFrame command=u'SEND'><br>
Thread-37401::DEBUG::2015-04-28
17:35:55,062::__init__::445::jsonrpc.JsonRpcServer::(_serveRequest)
Calling 'VM.destroy' in bridge with {u'vmID':
u'6ec9c0a0-2879-4bfe-9a79-92471881ebfe'}<br>
JsonRpcServer::DEBUG::2015-04-28
17:35:55,062::__init__::482::jsonrpc.JsonRpcServer::(serve_requests)
Waiting for request<br>
Thread-37401::INFO::2015-04-28
17:35:55,062::API::334::vds::(destroy) vmContainerLock acquired by
vm 6ec9c0a0-2879-4bfe-9a79-92471881ebfe<br>
Thread-37401::DEBUG::2015-04-28
17:35:55,062::vm::3513::vm.Vm::(destroy)
vmId=`6ec9c0a0-2879-4bfe-9a79-92471881ebfe`::destroy Called<br>
Thread-37401::INFO::2015-04-28
17:35:55,062::vm::3444::vm.Vm::(releaseVm)
vmId=`6ec9c0a0-2879-4bfe-9a79-92471881ebfe`::Release VM resources<br>
Thread-37401::WARNING::2015-04-28
17:35:55,062::vm::375::vm.Vm::(_set_lastStatus)
vmId=`6ec9c0a0-2879-4bfe-9a79-92471881ebfe`::trying to set state
to Powering down when already Down<br>
Thread-37401::ERROR::2015-04-28
17:35:55,063::__init__::469::jsonrpc.JsonRpcServer::(_serveRequest)
Internal server error<br>
Traceback (most recent call last):<br>
File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py",
line 464, in _serveRequest<br>
res = method(**params)<br>
File "/usr/share/vdsm/rpc/Bridge.py", line 273, in
_dynamicMethod<br>
result = fn(*methodArgs)<br>
File "/usr/share/vdsm/API.py", line 339, in destroy<br>
res = v.destroy()<br>
File "/usr/share/vdsm/virt/vm.py", line 3515, in destroy<br>
result = self.doDestroy()<br>
File "/usr/share/vdsm/virt/vm.py", line 3533, in doDestroy<br>
return self.releaseVm()<br>
File "/usr/share/vdsm/virt/vm.py", line 3448, in releaseVm<br>
sampling.stats_cache.remove(self.id)<br>
File "/usr/share/vdsm/virt/sampling.py", line 428, in remove<br>
if vmid in self._vm_last_timestamp.keys():<br>
KeyError: u'6ec9c0a0-2879-4bfe-9a79-92471881ebfe'<br>
Thread-37401::DEBUG::2015-04-28
17:35:55,063::stompReactor::158::yajsonrpc.StompServer::(send)
Sending response<br>
</blockquote>
In file '/usr/share/vdsm/virt/sampling.py':<br>
<br>
def add(self, vmid):<br>
"""<br>
Warm up the cache for the given VM.<br>
This is to avoid races during the first sampling and the
first<br>
reporting, which may result in a VM wrongly reported as
unresponsive.<br>
"""<br>
with self._lock:<br>
self._vm_last_timestamp[vmid] = self._clock()<br>
<br>
def remove(self, vmid):<br>
"""<br>
Remove any data from the cache related to the given VM.<br>
"""<br>
with self._lock:<br>
<b> if vmid in self._vm_last_timestamp.keys():</b><b>
<----------------- I patched here as a workarround<br>
</b><b> del
self._vm_last_timestamp[vmid]</b><br>
<br>
</body>
</html>
--------------060105040505080104010504--
2:44 p.m.
New subject: VDSM - sampling.py - remove() called without previous add()
In sampling.py, remove() is being called without calling add()
before, which
throws:
Fixed in master, please update:
https://gerrit.ovirt.org/40223
Nir
4:33 a.m.
On 28-04-2015 17:44, Nir Soffer wrote:
> In sampling.py, remove() is being called without calling add()
before, which
> throws:
Fixed in master, please update:
https://gerrit.ovirt.org/40223
Hi Nir,
Still present:
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line
464, in _serveRequest
res = method(**params)
File "/usr/share/vdsm/rpc/Bridge.py", line 273, in _dynamicMethod
result = fn(*methodArgs)
File "/usr/share/vdsm/API.py", line 339, in destroy
res = v.destroy()
File "/usr/share/vdsm/virt/vm.py", line 3517, in destroy
result = self.doDestroy()
File "/usr/share/vdsm/virt/vm.py", line 3535, in doDestroy
return self.releaseVm()
File "/usr/share/vdsm/virt/vm.py", line 3450, in releaseVm
<-------------------------------- Also called here
sampling.stats_cache.remove(self.id)
File "/usr/share/vdsm/virt/sampling.py", line 428, in remove
del self._vm_last_timestamp[vmid]
Consider making the function foolproof/flow-independent:
428,429c428
< if vmid in self._vm_last_timestamp.keys():
< del self._vm_last_timestamp[vmid]
---
del self._vm_last_timestamp[vmid]
4:46 a.m.
----- Original Message -----
From: "Christopher Pereira" <kripper(a)imatronix.cl>
To: "Nir Soffer" <nsoffer(a)redhat.com>
Cc: devel(a)ovirt.org
Sent: Wednesday, April 29, 2015 12:33:01 PM
Subject: Re: [ovirt-devel] VDSM - sampling.py - remove() called without previous add()
On 28-04-2015 17:44, Nir Soffer wrote:
>> In sampling.py, remove() is being called without calling add() before,
>> which
>> throws:
> Fixed in master, please update:
> https://gerrit.ovirt.org/40223
>
Hi Nir,
Still present:
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line
464, in _serveRequest
res = method(**params)
File "/usr/share/vdsm/rpc/Bridge.py", line 273, in _dynamicMethod
result = fn(*methodArgs)
File "/usr/share/vdsm/API.py", line 339, in destroy
res = v.destroy()
File "/usr/share/vdsm/virt/vm.py", line 3517, in destroy
result = self.doDestroy()
File "/usr/share/vdsm/virt/vm.py", line 3535, in doDestroy
return self.releaseVm()
File "/usr/share/vdsm/virt/vm.py", line 3450, in releaseVm
<-------------------------------- Also called here
sampling.stats_cache.remove(self.id)
File "/usr/share/vdsm/virt/sampling.py", line 428, in remove
del self._vm_last_timestamp[vmid]
So you reproduced this bug with VDSM with 40223 applied (let's say, today's master
branch)?
Which flow is this, just shutdding down a VM?
I did basic sanity check as part of verification of 40223, and didn't noticed
blatant mistakes. :\
Bests,
--
Francesco Romani
RedHat Engineering Virtualization R & D
Phone: 8261328
IRC: fromani
4:57 a.m.
This is a multi-part message in MIME format.
--------------010803090902010902080006
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
On 29-04-2015 7:46, Francesco Romani wrote:
----- Original Message -----
> From: "Christopher Pereira" <kripper(a)imatronix.cl>
> To: "Nir Soffer" <nsoffer(a)redhat.com>
> Cc: devel(a)ovirt.org
> Sent: Wednesday, April 29, 2015 12:33:01 PM
> Subject: Re: [ovirt-devel] VDSM - sampling.py - remove() called without previous
add()
>
> On 28-04-2015 17:44, Nir Soffer wrote:
>>> In sampling.py, remove() is being called without calling add() before,
>>> which
>>> throws:
>> Fixed in master, please update:
>> https://gerrit.ovirt.org/40223
>>
> Hi Nir,
>
> Still present:
>
> Traceback (most recent call last):
> File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line
> 464, in _serveRequest
> res = method(**params)
> File "/usr/share/vdsm/rpc/Bridge.py", line 273, in _dynamicMethod
> result = fn(*methodArgs)
> File "/usr/share/vdsm/API.py", line 339, in destroy
> res = v.destroy()
> File "/usr/share/vdsm/virt/vm.py", line 3517, in destroy
> result = self.doDestroy()
> File "/usr/share/vdsm/virt/vm.py", line 3535, in doDestroy
> return self.releaseVm()
> File "/usr/share/vdsm/virt/vm.py", line 3450, in releaseVm
> <-------------------------------- Also called here
> sampling.stats_cache.remove(self.id)
> File "/usr/share/vdsm/virt/sampling.py", line 428, in remove
> del self._vm_last_timestamp[vmid]
So you reproduced this bug with VDSM with 40223 applied (let's say, today's
master branch)?
Yes. I cloned github and am pulling patches from gerrit.
I also checked the file to confirm the patch was applied.
Which flow is this, just shutdding down a VM?
I guess the VM
was down and about to start. It probably failed to start
because the MasterStorageDomain was down.
I did basic sanity check as part of verification of 40223, and
didn't noticed
blatant mistakes. :\
I saw the patch eliminating the remove() call from one section, but it
was also called on another one (vm.py, line 3450).
--------------010803090902010902080006
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 7bit
<html>
<head>
<meta content="text/html; charset=utf-8"
http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<br>
<div class="moz-signature">
<style>
.signature, .small-signature {
font-family:"Calibri","sans-serif";mso-fareast-font-family:"Times
New Roman";
color:#7F7F7F;
}
.signature {
font-size:10pt;
}
.small-signature {
font-size:8pt;
}</style></div>
<div class="moz-cite-prefix">On 29-04-2015 7:46, Francesco Romani
wrote:<br>
</div>
<blockquote
cite="mid:2087988230.7158335.1430304391574.JavaMail.zimbra@redhat.com"
type="cite">
<pre wrap="">----- Original Message -----
</pre>
<blockquote type="cite">
<pre wrap="">From: "Christopher Pereira" <a
class="moz-txt-link-rfc2396E"
href="mailto:kripper@imatronix.cl"><kripper@imatronix.cl></a>
To: "Nir Soffer" <a class="moz-txt-link-rfc2396E"
href="mailto:nsoffer@redhat.com"><nsoffer@redhat.com></a>
Cc: <a class="moz-txt-link-abbreviated"
href="mailto:devel@ovirt.org">devel@ovirt.org</a>
Sent: Wednesday, April 29, 2015 12:33:01 PM
Subject: Re: [ovirt-devel] VDSM - sampling.py - remove() called without previous add()
On 28-04-2015 17:44, Nir Soffer wrote:
</pre>
<blockquote type="cite">
<blockquote type="cite">
<pre wrap="">In sampling.py, remove() is being called without
calling add() before,
which
throws:
</pre>
</blockquote>
<pre wrap="">Fixed in master, please update:
<a class="moz-txt-link-freetext"
href="https://gerrit.ovirt.org/40223">https://gerrit.ovirt.o...
</pre>
</blockquote>
<pre wrap="">Hi Nir,
Still present:
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line
464, in _serveRequest
res = method(**params)
File "/usr/share/vdsm/rpc/Bridge.py", line 273, in _dynamicMethod
result = fn(*methodArgs)
File "/usr/share/vdsm/API.py", line 339, in destroy
res = v.destroy()
File "/usr/share/vdsm/virt/vm.py", line 3517, in destroy
result = self.doDestroy()
File "/usr/share/vdsm/virt/vm.py", line 3535, in doDestroy
return self.releaseVm()
File "/usr/share/vdsm/virt/vm.py", line 3450, in releaseVm
<-------------------------------- Also called here
sampling.stats_cache.remove(self.id)
File "/usr/share/vdsm/virt/sampling.py", line 428, in remove
del self._vm_last_timestamp[vmid]
</pre>
</blockquote>
<pre wrap="">
So you reproduced this bug with VDSM with 40223 applied (let's say, today's master
branch)?
</pre>
</blockquote>
Yes. I cloned github and am pulling patches from gerrit.<br>
I also checked the file to confirm the patch was applied.<br>
<br>
<blockquote
cite="mid:2087988230.7158335.1430304391574.JavaMail.zimbra@redhat.com"
type="cite">
<pre wrap="">Which flow is this, just shutdding down a VM?
</pre>
</blockquote>
I guess the VM was down and about to start. It probably failed to
start because the MasterStorageDomain was down.<br>
<blockquote
cite="mid:2087988230.7158335.1430304391574.JavaMail.zimbra@redhat.com"
type="cite">
<pre wrap="">I did basic sanity check as part of verification of
40223, and didn't noticed
blatant mistakes. :\
</pre>
</blockquote>
I saw the patch eliminating the remove() call from one section, but
it was also called on another one (vm.py, line 3450).<br>
<br>
</body>
</html>
--------------010803090902010902080006--
3282
days inactive
3283
days old
4 comments
3 participants
participants (3)
-
Christopher Pereira -
Francesco Romani -
Nir Soffer