Bug 1299886 - AttributeError: 'SourceThread' object has no attribute '_destServer' in vdsm log when failing to migrate VM to destination
AttributeError: 'SourceThread' object has no attribute '_destServer' in vdsm ...
Status: CLOSED CURRENTRELEASE
Product: vdsm
Classification: oVirt
Component: Core (Show other bugs)
4.17.17
x86_64 Linux
low Severity low (vote)
: ovirt-3.6.5
: 4.17.25
Assigned To: Nir Soffer
Israel Pinto
: Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2016-01-19 08:30 EST by Michael Burman
Modified: 2016-04-21 10:40 EDT (History)
5 users (show)

See Also:
Fixed In Version: 3.6.5-1
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-04-21 10:40:26 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Virt
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
rule-engine: ovirt‑3.6.z+
rule-engine: planning_ack+
rule-engine: devel_ack+
rule-engine: testing_ack+


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 52897 master MERGED virt: migration: initialize SourceThread._destServer on __init__ 2016-02-07 10:56 EST
oVirt gerrit 54949 ovirt-3.6 MERGED virt: migration: initialize SourceThread._destServer on __init__ 2016-03-21 04:03 EDT

  None (edit)
Description Michael Burman 2016-01-19 08:30:27 EST
Description of problem:
AttributeError: 'SourceThread' object has no attribute '_destServer' in vdsm log when failing to migrate VM to destination.

Following errors appears in vdsm log if destination not reachable or can't be found. 
It's a bug in the code and we shouldn't see this error in the vdsm log. 
See - vim /usr/share/vdsm/virt/migration.py +208


Thread-499::ERROR::2016-01-19 08:19:14,160::migration::208::virt.vm::(_recover) vmId=`0974fb9c-131f-4ee4-a428-1d8172e489a2`::[Errno -2] Name or service not known
Thread-499::ERROR::2016-01-19 08:19:14,160::migration::213::virt.vm::(_recover) vmId=`0974fb9c-131f-4ee4-a428-1d8172e489a2`::Failed to destroy remote VM
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/migration.py", line 211, in _recover
    self._destServer.destroy(self._vm.id)
AttributeError: 'SourceThread' object has no attribute '_destServer'
Thread-499::DEBUG::2016-01-19 08:19:14,160::__init__::206::jsonrpc.Notification::(emit) Sending event {"params": {"notify_time": 4301361260, "0974fb9c-131f-4ee4-a428-1d8172e489a2": {"status": "Migration Source"}},
 "jsonrpc": "2.0", "method": "|virt|VM_status|0974fb9c-131f-4ee4-a428-1d8172e489a2"}
Thread-499::ERROR::2016-01-19 08:19:14,160::migration::310::virt.vm::(run) vmId=`0974fb9c-131f-4ee4-a428-1d8172e489a2`::Failed to migrate
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/migration.py", line 278, in run
    self._setupVdsConnection()
  File "/usr/share/vdsm/virt/migration.py", line 143, in _setupVdsConnection
    client = self._createClient(port)
  File "/usr/share/vdsm/virt/migration.py", line 130, in _createClient
    self.remoteHost, int(port), sslctx)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 1267, in create_connected_socket
    sock.connect((host, port))
  File "/usr/lib64/python2.7/site-packages/M2Crypto/SSL/Connection.py", line 181, in connect
    self.socket.connect(addr)
  File "/usr/lib64/python2.7/socket.py", line 224, in meth
    return getattr(self._sock,name)(*args)
gaierror: [Errno -2] Name or service not known

 

Version-Release number of selected component (if applicable):
vdsm- 4.17.17
Comment 1 Michal Skrivanek 2016-01-29 09:12:59 EST
this is useful debug info in migration failure recovery flow

(also next time, please attach full log as well)
Comment 2 Dan Kenigsberg 2016-01-31 05:46:13 EST
(In reply to Michal Skrivanek from comment #1)
> this is useful debug info in migration failure recovery flow
> 
> (also next time, please attach full log as well)

The failure to connect to a destination server should be logged, that is clear.

The bug here is that the exception-handling code uses a data member before its initialization.

I'm taking the liberty to re-open this bug, and send a patch.
Comment 3 Dan Kenigsberg 2016-02-04 16:59:02 EST
Michael, would you be kind to verify the patch?
Comment 4 Michael Burman 2016-02-07 10:10:46 EST
Done)
Comment 5 Nir Soffer 2016-03-18 15:45:32 EDT
Michal, I think we should fix this for next 3.6, the fix is trivial.
Comment 6 Nir Soffer 2016-03-18 15:50:00 EDT
Another case from the user list:
http://lists.ovirt.org/pipermail/users/2016-March/038545.html
Comment 7 Nir Soffer 2016-03-18 15:52:03 EDT
Michael, would you like to verify the 3.6 backport?
http://gerrit.ovirt.org/54949
Comment 8 Michal Skrivanek 2016-03-18 16:05:52 EDT
sure, why not
Comment 9 Michael Burman 2016-03-20 05:24:49 EDT
(In reply to Nir Soffer from comment #7)
> Michael, would you like to verify the 3.6 backport?
> http://gerrit.ovirt.org/54949

Done)
Comment 10 Israel Pinto 2016-04-14 04:47:05 EDT
Verify with:
RHEVM:3.6.5.3-0.1.el6 
Host:
OS Version:RHEL - 7.2 - 9.el7_2.1
Kernel Version:3.10.0 - 327.13.1.el7.x86_64
KVM Version:2.3.0 - 31.el7_2.10
LIBVIRT Version:libvirt-1.2.17-13.el7_2.4
VDSM Version:vdsm-4.17.26-0.el7ev
SPICE Version:0.12.4 - 15.el7

steps:
Case 1:
1. Migrate VM
2. Reboot destination host 
Case 2:
1. Migrate VM
2. Disconnect NIC (ifdown nic_name)

Results:PASS 
In both cases the migrate failed, and not reference in the log for:

AttributeError: 'SourceThread' object has no attribute '_destServer


vdsm log output:
----------------------------------------------------
Case1: With reboot for dest host after migration started: 
----------------------------------------------------
Thread-41738::DEBUG::2016-04-14 11:24:25,914::__init__::206::jsonrpc.Notification::(emit) Sending event {"params": {"notify_time": 5187293370, "d3d27d79-4534-4806-aa59-4684a7d8625b": {"status": "Migration Source"}}, "jsonrpc": "2.0", "method": "|virt|VM_status|d3d27d79-4534-4806-aa59-4684a7d8625b"}
Thread-41738::ERROR::2016-04-14 11:24:25,915::migration::310::virt.vm::(run) vmId=`d3d27d79-4534-4806-aa59-4684a7d8625b`::Failed to migrate
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/migration.py", line 298, in run
    self._startUnderlyingMigration(time.time())
  File "/usr/share/vdsm/virt/migration.py", line 364, in _startUnderlyingMigration
    self._perform_migration(duri, muri)
  File "/usr/share/vdsm/virt/migration.py", line 403, in _perform_migration
    self._vm._dom.migrateToURI3(duri, params, flags)
  File "/usr/share/vdsm/virt/virdomain.py", line 68, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 124, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 1313, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1836, in migrateToURI3
    if ret == -1: raise libvirtError ('virDomainMigrateToURI3() failed', dom=self)
libvirtError: internal error: process exited while connecting to monitor:
***********************************
-----------------------------------
Case 2: With disconnect the nic:
----------------------------------
Thread-41821::ERROR::2016-04-14 11:29:43,489::migration::214::virt.vm::(_recover) vmId=`d3d27d79-4534-4806-aa59-4684a7d8625b`::Failed to destroy remote VM
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/migration.py", line 212, in _recover
    self._destServer.destroy(self._vm.id)
  File "/usr/lib/python2.7/site-packages/vdsm/jsonrpcvdscli.py", line 68, in _callMethod
    raise JsonRpcNoResponseError(method)
JsonRpcNoResponseError: [-32605] No response for JSON-RPC VM.destroy request.
Thread-41821::DEBUG::2016-04-14 11:29:43,509::__init__::206::jsonrpc.Notification::(emit) Sending event {"params": {"notify_time": 5187610970, "d3d27d79-4534-4806-aa59-4684a7d8625b": {"status": "Migration Source"}}, "jsonrpc": "2.0", "method": "|virt|VM_status|d3d27d79-4534-4806-aa59-4684a7d8625b"}
Thread-41821::ERROR::2016-04-14 11:29:43,510::migration::310::virt.vm::(run) vmId=`d3d27d79-4534-4806-aa59-4684a7d8625b`::Failed to migrate
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/migration.py", line 298, in run
    self._startUnderlyingMigration(time.time())
  File "/usr/share/vdsm/virt/migration.py", line 364, in _startUnderlyingMigration
    self._perform_migration(duri, muri)
  File "/usr/share/vdsm/virt/migration.py", line 403, in _perform_migration
    self._vm._dom.migrateToURI3(duri, params, flags)
  File "/usr/share/vdsm/virt/virdomain.py", line 68, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 124, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 1313, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1836, in migrateToURI3
    if ret == -1: raise libvirtError ('virDomainMigrateToURI3() failed', dom=self)
libvirtError: internal error: received hangup / error event on socket

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