Bug 1299886

Summary: AttributeError: 'SourceThread' object has no attribute '_destServer' in vdsm log when failing to migrate VM to destination
Product: [oVirt] vdsm Reporter: Michael Burman <mburman>
Component: CoreAssignee: Nir Soffer <nsoffer>
Status: CLOSED CURRENTRELEASE QA Contact: Israel Pinto <ipinto>
Severity: low Docs Contact:
Priority: low    
Version: 4.17.17CC: bugs, mburman, mgoldboi, michal.skrivanek, nsoffer
Target Milestone: ovirt-3.6.5Keywords: Reopened
Target Release: 4.17.25Flags: rule-engine: ovirt-3.6.z+
rule-engine: planning_ack+
rule-engine: devel_ack+
rule-engine: testing_ack+
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: 3.6.5-1 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-04-21 14:40:26 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Virt RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Michael Burman 2016-01-19 13:30:27 UTC
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 14:12:59 UTC
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 10:46:13 UTC
(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 21:59:02 UTC
Michael, would you be kind to verify the patch?

Comment 4 Michael Burman 2016-02-07 15:10:46 UTC
Done)

Comment 5 Nir Soffer 2016-03-18 19:45:32 UTC
Michal, I think we should fix this for next 3.6, the fix is trivial.

Comment 6 Nir Soffer 2016-03-18 19:50:00 UTC
Another case from the user list:
http://lists.ovirt.org/pipermail/users/2016-March/038545.html

Comment 7 Nir Soffer 2016-03-18 19:52:03 UTC
Michael, would you like to verify the 3.6 backport?
http://gerrit.ovirt.org/54949

Comment 8 Michal Skrivanek 2016-03-18 20:05:52 UTC
sure, why not

Comment 9 Michael Burman 2016-03-20 09:24:49 UTC
(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 08:47:05 UTC
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