From kripper at imatronix.cl Wed Apr 29 06:57:05 2015 Content-Type: multipart/mixed; boundary="===============4902883491110154945==" MIME-Version: 1.0 From: Christopher Pereira To: devel at ovirt.org Subject: Re: [ovirt-devel] VDSM - sampling.py - remove() called without previous add() Date: Wed, 29 Apr 2015 07:57:00 -0300 Message-ID: <5540B8FC.3090507@imatronix.cl> In-Reply-To: 2087988230.7158335.1430304391574.JavaMail.zimbra@redhat.com --===============4902883491110154945== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable This is a multi-part message in MIME format. --------------010803090902010902080006 Content-Type: text/plain; charset=3Dutf-8; format=3Dflowed Content-Transfer-Encoding: 7bit On 29-04-2015 7:46, Francesco Romani wrote: > ----- Original Message ----- >> From: "Christopher Pereira" >> To: "Nir Soffer" >> 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 =3D method(**params) >> File "/usr/share/vdsm/rpc/Bridge.py", line 273, in _dynamicMethod >> result =3D fn(*methodArgs) >> File "/usr/share/vdsm/API.py", line 339, in destroy >> res =3D v.destroy() >> File "/usr/share/vdsm/virt/vm.py", line 3517, in destroy >> result =3D 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 not= iced > 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=3Dutf-8 Content-Transfer-Encoding: 7bit
On 29-04-2015 7:46, Francesco Romani wrote:
----- Original Message -----

From: "Christopher Pereira" <kripper(a)imatronix.c=
l>
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 pre=
vious 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 =3D method(**params)
   File "/usr/share/vdsm/rpc/Bridge.py", line 273, in _dynamicMethod
     result =3D fn(*methodArgs)
   File "/usr/share/vdsm/API.py", line 339, in destroy
     res =3D v.destroy()
   File "/usr/share/vdsm/virt/vm.py", line 3517, in destroy
     result =3D 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 40=
223, 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-- --===============4902883491110154945== Content-Type: multipart/alternative MIME-Version: 1.0 Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="attachment.bin" VGhpcyBpcyBhIG11bHRpLXBhcnQgbWVzc2FnZSBpbiBNSU1FIGZvcm1hdC4KLS0tLS0tLS0tLS0t LS0wMTA4MDMwOTA5MDIwMTA5MDIwODAwMDYKQ29udGVudC1UeXBlOiB0ZXh0L3BsYWluOyBjaGFy c2V0PXV0Zi04OyBmb3JtYXQ9Zmxvd2VkCkNvbnRlbnQtVHJhbnNmZXItRW5jb2Rpbmc6IDdiaXQK CgpPbiAyOS0wNC0yMDE1IDc6NDYsIEZyYW5jZXNjbyBSb21hbmkgd3JvdGU6Cj4gLS0tLS0gT3Jp Z2luYWwgTWVzc2FnZSAtLS0tLQo+PiBGcm9tOiAiQ2hyaXN0b3BoZXIgUGVyZWlyYSIgPGtyaXBw ZXJAaW1hdHJvbml4LmNsPgo+PiBUbzogIk5pciBTb2ZmZXIiIDxuc29mZmVyQHJlZGhhdC5jb20+ Cj4+IENjOiBkZXZlbEBvdmlydC5vcmcKPj4gU2VudDogV2VkbmVzZGF5LCBBcHJpbCAyOSwgMjAx NSAxMjozMzowMSBQTQo+PiBTdWJqZWN0OiBSZTogW292aXJ0LWRldmVsXSBWRFNNIC0gc2FtcGxp bmcucHkgLSByZW1vdmUoKSBjYWxsZWQgd2l0aG91dCBwcmV2aW91cyBhZGQoKQo+Pgo+PiBPbiAy OC0wNC0yMDE1IDE3OjQ0LCBOaXIgU29mZmVyIHdyb3RlOgo+Pj4+IEluIHNhbXBsaW5nLnB5LCBy ZW1vdmUoKSBpcyBiZWluZyBjYWxsZWQgd2l0aG91dCBjYWxsaW5nIGFkZCgpIGJlZm9yZSwKPj4+ PiB3aGljaAo+Pj4+IHRocm93czoKPj4+IEZpeGVkIGluIG1hc3RlciwgcGxlYXNlIHVwZGF0ZToK Pj4+IGh0dHBzOi8vZ2Vycml0Lm92aXJ0Lm9yZy80MDIyMwo+Pj4KPj4gSGkgTmlyLAo+Pgo+PiBT dGlsbCBwcmVzZW50Ogo+Pgo+PiBUcmFjZWJhY2sgKG1vc3QgcmVjZW50IGNhbGwgbGFzdCk6Cj4+ ICAgICBGaWxlICIvdXNyL2xpYi9weXRob24yLjcvc2l0ZS1wYWNrYWdlcy95YWpzb25ycGMvX19p bml0X18ucHkiLCBsaW5lCj4+IDQ2NCwgaW4gX3NlcnZlUmVxdWVzdAo+PiAgICAgICByZXMgPSBt ZXRob2QoKipwYXJhbXMpCj4+ICAgICBGaWxlICIvdXNyL3NoYXJlL3Zkc20vcnBjL0JyaWRnZS5w eSIsIGxpbmUgMjczLCBpbiBfZHluYW1pY01ldGhvZAo+PiAgICAgICByZXN1bHQgPSBmbigqbWV0 aG9kQXJncykKPj4gICAgIEZpbGUgIi91c3Ivc2hhcmUvdmRzbS9BUEkucHkiLCBsaW5lIDMzOSwg aW4gZGVzdHJveQo+PiAgICAgICByZXMgPSB2LmRlc3Ryb3koKQo+PiAgICAgRmlsZSAiL3Vzci9z aGFyZS92ZHNtL3ZpcnQvdm0ucHkiLCBsaW5lIDM1MTcsIGluIGRlc3Ryb3kKPj4gICAgICAgcmVz dWx0ID0gc2VsZi5kb0Rlc3Ryb3koKQo+PiAgICAgRmlsZSAiL3Vzci9zaGFyZS92ZHNtL3ZpcnQv dm0ucHkiLCBsaW5lIDM1MzUsIGluIGRvRGVzdHJveQo+PiAgICAgICByZXR1cm4gc2VsZi5yZWxl YXNlVm0oKQo+PiAgICAgRmlsZSAiL3Vzci9zaGFyZS92ZHNtL3ZpcnQvdm0ucHkiLCBsaW5lIDM0 NTAsIGluIHJlbGVhc2VWbQo+PiA8LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0gQWxz byBjYWxsZWQgaGVyZQo+PiAgICAgICBzYW1wbGluZy5zdGF0c19jYWNoZS5yZW1vdmUoc2VsZi5p ZCkKPj4gICAgIEZpbGUgIi91c3Ivc2hhcmUvdmRzbS92aXJ0L3NhbXBsaW5nLnB5IiwgbGluZSA0 MjgsIGluIHJlbW92ZQo+PiAgICAgICBkZWwgc2VsZi5fdm1fbGFzdF90aW1lc3RhbXBbdm1pZF0K PiBTbyB5b3UgcmVwcm9kdWNlZCB0aGlzIGJ1ZyB3aXRoIFZEU00gd2l0aCA0MDIyMyBhcHBsaWVk IChsZXQncyBzYXksIHRvZGF5J3MgbWFzdGVyIGJyYW5jaCk/Clllcy4gSSBjbG9uZWQgZ2l0aHVi IGFuZCBhbSBwdWxsaW5nIHBhdGNoZXMgZnJvbSBnZXJyaXQuCkkgYWxzbyBjaGVja2VkIHRoZSBm aWxlIHRvIGNvbmZpcm0gdGhlIHBhdGNoIHdhcyBhcHBsaWVkLgoKPiBXaGljaCBmbG93IGlzIHRo aXMsIGp1c3Qgc2h1dGRkaW5nIGRvd24gYSBWTT8KSSBndWVzcyB0aGUgVk0gd2FzIGRvd24gYW5k IGFib3V0IHRvIHN0YXJ0LiBJdCBwcm9iYWJseSBmYWlsZWQgdG8gc3RhcnQgCmJlY2F1c2UgdGhl IE1hc3RlclN0b3JhZ2VEb21haW4gd2FzIGRvd24uCj4gSSBkaWQgYmFzaWMgc2FuaXR5IGNoZWNr IGFzIHBhcnQgb2YgdmVyaWZpY2F0aW9uIG9mIDQwMjIzLCBhbmQgZGlkbid0IG5vdGljZWQKPiBi bGF0YW50IG1pc3Rha2VzLiA6XAo+Ckkgc2F3IHRoZSBwYXRjaCBlbGltaW5hdGluZyB0aGUgcmVt b3ZlKCkgY2FsbCBmcm9tIG9uZSBzZWN0aW9uLCBidXQgaXQgCndhcyBhbHNvIGNhbGxlZCBvbiBh bm90aGVyIG9uZSAodm0ucHksIGxpbmUgMzQ1MCkuCgoKLS0tLS0tLS0tLS0tLS0wMTA4MDMwOTA5 MDIwMTA5MDIwODAwMDYKQ29udGVudC1UeXBlOiB0ZXh0L2h0bWw7IGNoYXJzZXQ9dXRmLTgKQ29u dGVudC1UcmFuc2Zlci1FbmNvZGluZzogN2JpdAoKPGh0bWw+CiAgPGhlYWQ+CiAgICA8bWV0YSBj b250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9dXRmLTgiIGh0dHAtZXF1aXY9IkNvbnRlbnQtVHlw ZSI+CiAgPC9oZWFkPgogIDxib2R5IGJnY29sb3I9IiNGRkZGRkYiIHRleHQ9IiMwMDAwMDAiPgog ICAgPGJyPgogICAgPGRpdiBjbGFzcz0ibW96LXNpZ25hdHVyZSI+CiAgICAgIDxzdHlsZT4KLnNp Z25hdHVyZSwgLnNtYWxsLXNpZ25hdHVyZSB7Cglmb250LWZhbWlseToiQ2FsaWJyaSIsInNhbnMt c2VyaWYiO21zby1mYXJlYXN0LWZvbnQtZmFtaWx5OiJUaW1lcyBOZXcgUm9tYW4iOwoJY29sb3I6 IzdGN0Y3RjsKfQoKLnNpZ25hdHVyZSB7Cglmb250LXNpemU6MTBwdDsKfQoKLnNtYWxsLXNpZ25h dHVyZSB7Cglmb250LXNpemU6OHB0Owp9PC9zdHlsZT48L2Rpdj4KICAgIDxkaXYgY2xhc3M9Im1v ei1jaXRlLXByZWZpeCI+T24gMjktMDQtMjAxNSA3OjQ2LCBGcmFuY2VzY28gUm9tYW5pCiAgICAg IHdyb3RlOjxicj4KICAgIDwvZGl2PgogICAgPGJsb2NrcXVvdGUKICAgICAgY2l0ZT0ibWlkOjIw ODc5ODgyMzAuNzE1ODMzNS4xNDMwMzA0MzkxNTc0LkphdmFNYWlsLnppbWJyYUByZWRoYXQuY29t IgogICAgICB0eXBlPSJjaXRlIj4KICAgICAgPHByZSB3cmFwPSIiPi0tLS0tIE9yaWdpbmFsIE1l c3NhZ2UgLS0tLS0KPC9wcmU+CiAgICAgIDxibG9ja3F1b3RlIHR5cGU9ImNpdGUiPgogICAgICAg IDxwcmUgd3JhcD0iIj5Gcm9tOiAiQ2hyaXN0b3BoZXIgUGVyZWlyYSIgPGEgY2xhc3M9Im1vei10 eHQtbGluay1yZmMyMzk2RSIgaHJlZj0ibWFpbHRvOmtyaXBwZXJAaW1hdHJvbml4LmNsIj4mbHQ7 a3JpcHBlckBpbWF0cm9uaXguY2wmZ3Q7PC9hPgpUbzogIk5pciBTb2ZmZXIiIDxhIGNsYXNzPSJt b3otdHh0LWxpbmstcmZjMjM5NkUiIGhyZWY9Im1haWx0bzpuc29mZmVyQHJlZGhhdC5jb20iPiZs dDtuc29mZmVyQHJlZGhhdC5jb20mZ3Q7PC9hPgpDYzogPGEgY2xhc3M9Im1vei10eHQtbGluay1h YmJyZXZpYXRlZCIgaHJlZj0ibWFpbHRvOmRldmVsQG92aXJ0Lm9yZyI+ZGV2ZWxAb3ZpcnQub3Jn PC9hPgpTZW50OiBXZWRuZXNkYXksIEFwcmlsIDI5LCAyMDE1IDEyOjMzOjAxIFBNClN1YmplY3Q6 IFJlOiBbb3ZpcnQtZGV2ZWxdIFZEU00gLSBzYW1wbGluZy5weSAtIHJlbW92ZSgpIGNhbGxlZCB3 aXRob3V0IHByZXZpb3VzIGFkZCgpCgpPbiAyOC0wNC0yMDE1IDE3OjQ0LCBOaXIgU29mZmVyIHdy b3RlOgo8L3ByZT4KICAgICAgICA8YmxvY2txdW90ZSB0eXBlPSJjaXRlIj4KICAgICAgICAgIDxi bG9ja3F1b3RlIHR5cGU9ImNpdGUiPgogICAgICAgICAgICA8cHJlIHdyYXA9IiI+SW4gc2FtcGxp bmcucHksIHJlbW92ZSgpIGlzIGJlaW5nIGNhbGxlZCB3aXRob3V0IGNhbGxpbmcgYWRkKCkgYmVm b3JlLAp3aGljaAp0aHJvd3M6CjwvcHJlPgogICAgICAgICAgPC9ibG9ja3F1b3RlPgogICAgICAg ICAgPHByZSB3cmFwPSIiPkZpeGVkIGluIG1hc3RlciwgcGxlYXNlIHVwZGF0ZToKPGEgY2xhc3M9 Im1vei10eHQtbGluay1mcmVldGV4dCIgaHJlZj0iaHR0cHM6Ly9nZXJyaXQub3ZpcnQub3JnLzQw MjIzIj5odHRwczovL2dlcnJpdC5vdmlydC5vcmcvNDAyMjM8L2E+Cgo8L3ByZT4KICAgICAgICA8 L2Jsb2NrcXVvdGU+CiAgICAgICAgPHByZSB3cmFwPSIiPkhpIE5pciwKClN0aWxsIHByZXNlbnQ6 CgpUcmFjZWJhY2sgKG1vc3QgcmVjZW50IGNhbGwgbGFzdCk6CiAgIEZpbGUgIi91c3IvbGliL3B5 dGhvbjIuNy9zaXRlLXBhY2thZ2VzL3lhanNvbnJwYy9fX2luaXRfXy5weSIsIGxpbmUKNDY0LCBp biBfc2VydmVSZXF1ZXN0CiAgICAgcmVzID0gbWV0aG9kKCoqcGFyYW1zKQogICBGaWxlICIvdXNy L3NoYXJlL3Zkc20vcnBjL0JyaWRnZS5weSIsIGxpbmUgMjczLCBpbiBfZHluYW1pY01ldGhvZAog ICAgIHJlc3VsdCA9IGZuKCptZXRob2RBcmdzKQogICBGaWxlICIvdXNyL3NoYXJlL3Zkc20vQVBJ LnB5IiwgbGluZSAzMzksIGluIGRlc3Ryb3kKICAgICByZXMgPSB2LmRlc3Ryb3koKQogICBGaWxl ICIvdXNyL3NoYXJlL3Zkc20vdmlydC92bS5weSIsIGxpbmUgMzUxNywgaW4gZGVzdHJveQogICAg IHJlc3VsdCA9IHNlbGYuZG9EZXN0cm95KCkKICAgRmlsZSAiL3Vzci9zaGFyZS92ZHNtL3ZpcnQv dm0ucHkiLCBsaW5lIDM1MzUsIGluIGRvRGVzdHJveQogICAgIHJldHVybiBzZWxmLnJlbGVhc2VW bSgpCiAgIEZpbGUgIi91c3Ivc2hhcmUvdmRzbS92aXJ0L3ZtLnB5IiwgbGluZSAzNDUwLCBpbiBy ZWxlYXNlVm0KJmx0Oy0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tIEFsc28gY2FsbGVk IGhlcmUKICAgICBzYW1wbGluZy5zdGF0c19jYWNoZS5yZW1vdmUoc2VsZi5pZCkKICAgRmlsZSAi L3Vzci9zaGFyZS92ZHNtL3ZpcnQvc2FtcGxpbmcucHkiLCBsaW5lIDQyOCwgaW4gcmVtb3ZlCiAg ICAgZGVsIHNlbGYuX3ZtX2xhc3RfdGltZXN0YW1wW3ZtaWRdCjwvcHJlPgogICAgICA8L2Jsb2Nr cXVvdGU+CiAgICAgIDxwcmUgd3JhcD0iIj4KU28geW91IHJlcHJvZHVjZWQgdGhpcyBidWcgd2l0 aCBWRFNNIHdpdGggNDAyMjMgYXBwbGllZCAobGV0J3Mgc2F5LCB0b2RheSdzIG1hc3RlciBicmFu Y2gpPwo8L3ByZT4KICAgIDwvYmxvY2txdW90ZT4KICAgIFllcy4gSSBjbG9uZWQgZ2l0aHViIGFu ZCBhbSBwdWxsaW5nIHBhdGNoZXMgZnJvbSBnZXJyaXQuPGJyPgogICAgSSBhbHNvIGNoZWNrZWQg dGhlIGZpbGUgdG8gY29uZmlybSB0aGUgcGF0Y2ggd2FzIGFwcGxpZWQuPGJyPgogICAgPGJyPgog ICAgPGJsb2NrcXVvdGUKICAgICAgY2l0ZT0ibWlkOjIwODc5ODgyMzAuNzE1ODMzNS4xNDMwMzA0 MzkxNTc0LkphdmFNYWlsLnppbWJyYUByZWRoYXQuY29tIgogICAgICB0eXBlPSJjaXRlIj4KICAg ICAgPHByZSB3cmFwPSIiPldoaWNoIGZsb3cgaXMgdGhpcywganVzdCBzaHV0ZGRpbmcgZG93biBh IFZNPwo8L3ByZT4KICAgIDwvYmxvY2txdW90ZT4KICAgIEkgZ3Vlc3MgdGhlIFZNIHdhcyBkb3du IGFuZCBhYm91dCB0byBzdGFydC4gSXQgcHJvYmFibHkgZmFpbGVkIHRvCiAgICBzdGFydCBiZWNh dXNlIHRoZSBNYXN0ZXJTdG9yYWdlRG9tYWluIHdhcyBkb3duLjxicj4KICAgIDxibG9ja3F1b3Rl CiAgICAgIGNpdGU9Im1pZDoyMDg3OTg4MjMwLjcxNTgzMzUuMTQzMDMwNDM5MTU3NC5KYXZhTWFp bC56aW1icmFAcmVkaGF0LmNvbSIKICAgICAgdHlwZT0iY2l0ZSI+CiAgICAgIDxwcmUgd3JhcD0i Ij5JIGRpZCBiYXNpYyBzYW5pdHkgY2hlY2sgYXMgcGFydCBvZiB2ZXJpZmljYXRpb24gb2YgNDAy MjMsIGFuZCBkaWRuJ3Qgbm90aWNlZApibGF0YW50IG1pc3Rha2VzLiA6XAoKPC9wcmU+CiAgICA8 L2Jsb2NrcXVvdGU+CiAgICBJIHNhdyB0aGUgcGF0Y2ggZWxpbWluYXRpbmcgdGhlIHJlbW92ZSgp IGNhbGwgZnJvbSBvbmUgc2VjdGlvbiwgYnV0CiAgICBpdCB3YXMgYWxzbyBjYWxsZWQgb24gYW5v dGhlciBvbmUgKHZtLnB5LCBsaW5lIDM0NTApLjxicj4KICAgIDxicj4KICA8L2JvZHk+CjwvaHRt bD4KCi0tLS0tLS0tLS0tLS0tMDEwODAzMDkwOTAyMDEwOTAyMDgwMDA2LS0K --===============4902883491110154945==--