On Tue 05 Mar 2013 05:28:17 PM CST, xianghuadu wrote:
hi all I recently in the research ovirt encounter a problem. In the vm migration occurs when the error: Migration failed due to Error: Could not connect to peer host. My environment is: KVM dell 2950 * 2 storage iscsi-target vm system windows 2008 r2 ovirt-log： 2013-03-05 14:52:23,074 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-42) [323d7ca8] VM centos 4cc23d92-8667-4710-9714-a67c0d178fa0 moved from MigratingFrom --> Up 2013-03-05 14:52:23,076 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-42) [323d7ca8] adding VM 4cc23d92-8667-4710-9714-a67c0d178fa0 to re-run list 2013-03-05 14:52:23,079 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-42) [323d7ca8] Rerun vm 4cc23d92-8667-4710-9714-a67c0d178fa0. Called from vds 205 2013-03-05 14:52:23,085 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-3-thread-49) [323d7ca8] START, MigrateStatusVDSCommand(HostName = 205, HostId = 4e7d1ae2-824e-11e2-bb4c-00188be4de29, vmId=4cc23d92-8667-4710-9714-a67c0d178fa0), log id: 618085d 2013-03-05 14:52:23,131 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-49) [323d7ca8] Failed in MigrateStatusVDS method 2013-03-05 14:52:23,132 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-49) [323d7ca8] Error code noConPeer and error message VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Could not connect to peer VDS 2013-03-05 14:52:23,134 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-49) [323d7ca8] Command org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand return value
Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusOnlyReturnForXmlRpc mStatus Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusForXmlRpc mCode 10 mMessage Could not connect to peer VDS 2013-03-05 14:52:23,138 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-49) [323d7ca8] HostName = 205 2013-03-05 14:52:23,139 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (pool-3-thread-49) [323d7ca8] Command MigrateStatusVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Could not connect to peer VDS 2013-03-05 14:52:23,141 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-3-thread-49) [323d7ca8] FINISH, MigrateStatusVDSCommand, log
vdsm-log： Thread-5969::DEBUG::2013-03-05 14:52:21,312::libvirtvm::283::vm.Vm::(_getDiskLatency) vmId=`4cc23d92-8667-4710-9714-a67c0d178fa0`::Disk vda latency not available Thread-5622::ERROR::2013-03-05 14:52:22,890::vm::200::vm.Vm::(_recover) vmId=`4cc23d92-8667-4710-9714-a67c0d178fa0`::Failed to destroy remote VM Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 198, in _recover self.destServer.destroy(self._vm.id) File "/usr/lib64/python2.6/xmlrpclib.py", line 1199, in __call__ return self.__send(self.__name, args) File "/usr/lib64/python2.6/xmlrpclib.py", line 1489, in __request verbose=self.__verbose File "/usr/lib64/python2.6/xmlrpclib.py", line 1253, in request return self._parse_response(h.getfile(), sock) File "/usr/lib64/python2.6/xmlrpclib.py", line 1382, in _parse_response response = file.read(1024) File "/usr/lib64/python2.6/socket.py", line 383, in read data = self._sock.recv(left) File "/usr/lib64/python2.6/ssl.py", line 215, in recv return self.read(buflen) File "/usr/lib64/python2.6/ssl.py", line 136, in read return self._sslobj.read(len) SSLError: The read operation timed out Thread-5622::ERROR::2013-03-05 14:52:22,909::vm::283::vm.Vm::(run) vmId=`4cc23d92-8667-4710-9714-a67c0d178fa0`::Failed to migrate Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 268, in run self._startUnderlyingMigration() File "/usr/share/vdsm/libvirtvm.py", line 443, in _startUnderlyingMigration response = self.destServer.migrationCreate(self._machineParams) File "/usr/lib64/python2.6/xmlrpclib.py", line 1199, in __call__ return self.__send(self.__name, args) File "/usr/lib64/python2.6/xmlrpclib.py", line 1489, in __request verbose=self.__verbose File "/usr/lib64/python2.6/xmlrpclib.py", line 1253, in request return self._parse_response(h.getfile(), sock) File "/usr/lib64/python2.6/xmlrpclib.py", line 1382, in _parse_response response = file.read(1024) File "/usr/lib64/python2.6/socket.py", line 383, in read data = self._sock.recv(left) File "/usr/lib64/python2.6/ssl.py", line 215, in recv return self.read(buflen) File "/usr/lib64/python2.6/ssl.py", line 136, in read return self._sslobj.read(len) SSLError: The read operation timed out Thread-5971::DEBUG::2013-03-05 14:52:23,384::BindingXMLRPC::903::vds::(wrapper) client [192.168.1.201]::call vmGetStats with ('4cc23d92-8667-4710-9714-a67c0d178fa0',) {} flowID [323d7ca8] Thread-5971::DEBUG::2013-03-05 14:52:23,385::libvirtvm::283::vm.Vm::(_getDiskLatency) vmId=`4cc23d92-8667-4710-9714-a67c0d178fa0`::Disk vda latency not available Thread-5971::DEBUG::2013-03-05 14:52:23,385::BindingXMLRPC::910::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '3135', 'displayIp': '192.168.1.235', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '-761593583205877164', 'balloonInfo': {'balloon_max': 524288, 'balloon_cur': 524288}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:a8:01:52', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '4cc23d92-8667-4710-9714-a67c0d178fa0', 'displayType': 'vnc', 'cpuUser': '1.85', 'disks': {u'vda': {'readRate': '0.00', 'truesize': '21474836480', 'apparentsize': '21474836480', 'writeRate': '407.16', 'imageID': '6b252eb8-ab9f-445f-9! 22e-52d86b c6d790'}, u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '0.67', 'elapsedTime': '9684', 'vmType': 'kvm', 'cpuSys': '5.93', 'appsList': [], 'guestIPs': ''}]} Thread-5972::DEBUG::2013-03-05 14:52:23,408::BindingXMLRPC::903::vds::(wrapper) client [192.168.1.201]::call vmGetMigrationStatus with ('4cc23d92-8667-4710-9714-a67c0d178fa0',) {} flowID [323d7ca8] Thread-5972::DEBUG::2013-03-05 14:52:23,408::BindingXMLRPC::910::vds::(wrapper) return vmGetMigrationStatus with {'status': {'message': 'Could not connect to peer VDS', 'code': 10}, 'progress': 10} Thread-21::DEBUG::2013-03-05 14:52:26,888::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd iflag=direct if=/dev/0e5827a5-6f3c-49be-be9b-0bfb65198644/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2013-03-05 14:52:26,900::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00036552 s, 11.2 MB/s\n'; <rc> = 0 Thread-5976::DEBUG::2013-03-05 14:52:31,555::task::568::TaskManager.Task::(_updateState) Task=`da545231-9538-412d-966e-a056ca7d074a`::moving from state init -> state preparing Thread-5976::INFO::2013-03-05 14:52:31,556::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-5976::INFO::2013-03-05 14:52:31,556::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'0e5827a5-6f3c-49be-be9b-0bfb65198644': {'delay': '0.0129568576813', 'lastCheck': '4.7', 'code': 0, 'valid': True}, u'4007f30a-f888-4587-b82c-40bcde401acb': {'delay': '0.0022189617157', 'lastCheck': '4.9', 'code': 0, 'valid': True}} Thread-5976::DEBUG::2013-03-05 14:52:31,556::task::1151::TaskManager.Task::(prepare) Task=`da545231-9538-412d-966e-a056ca7d074a`::finished: {u'0e5827a5-6f3c-49be-be9b-0bfb65198644': {'delay': '0.0129568576813', 'lastCheck': '4.7', 'code': 0, 'valid': True}, u'4007f30a-f888-4587-b82c-40bcde401acb': {'delay': '0.0022189617157', 'lastCheck': '4.9', 'code': 0, 'valid': True}} Thread-5976::DEBUG::2013-03-05 14:52:31,556::task::568::TaskManager.Task::(_updateState) Task=`da545231-9538-412d-966e-a056ca7d074a`::moving from state preparing -> state finished Thread-5976::DEBUG::2013-03-05 14:52:31,556::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-5976::DEBUG::2013-03-05 14:52:31,556::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-5976::DEBUG::2013-03-05 14:52:31,557::task::957::TaskManager.Task::(_decref) Task=`da545231-9538-412d-966e-a056ca7d074a`::ref 0 aborting False Thread-5977::DEBUG::2013-03-05 14:52:31,565::libvirtvm::283::vm.Vm::(_getDiskLatency) vmId=`4cc23d92-8667-4710-9714-a67c0d178fa0`::Disk vda latency not available Thread-21::DEBUG::2013-03-05 14:52:36,904::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd iflag=direct if=/dev/0e5827a5-6f3c-49be-be9b-0bfb65198644/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2013-03-05 14:52:36,917::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000400626 s, 10.2 MB/s\n'; <rc> = 0 VM Channels Listener::DEBUG::2013-03-05 14:52:41,337::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 18. Thread-5982::DEBUG::2013-03-05 14:52:41,786::task::568::TaskManager.Task::(_updateState) Task=`91d8929e-1349-4d74-9bcd-e0df406ce455`::moving from state init -> state preparing Thread-5982::INFO::2013-03-05 14:52:41,786::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-5982::INFO::2013-03-05 14:52:41,786::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'0e5827a5-6f3c-49be-be9b-0bfb65198644': {'delay': '0.0130889415741', 'lastCheck': '4.9', 'code': 0, 'valid': True}, u'4007f30a-f888-4587-b82c-40bcde401acb': {'delay': '0.00270700454712', 'lastCheck': '5.1', 'code': 0, 'valid': True}} Thread-5982::DEBUG::2013-03-05 14:52:41,787::task::1151::TaskManager.Task::(prepare) Task=`91d8929e-1349-4d74-9bcd-e0df406ce455`::finished: {u'0e5827a5-6f3c-49be-be9b-0bfb65198644': {'delay': '0.0130889415741', 'lastCheck': '4.9', 'code': 0, 'valid': True}, u'4007f30a-f888-4587-b82c-40bcde401acb': {'delay': '0.00270700454712', 'lastCheck': '5.1', 'code': 0, 'valid': True}} Thread-5982::DEBUG::2013-03-05 14:52:41,787::task::568::TaskManager.Task::(_updateState) Task=`91d8929e-1349-4d74-9bcd-e0df406ce455`::moving from state preparing -> state finished Thread-5982::DEBUG::2013-03-05 14:52:41,787::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-5982::DEBUG::2013-03-05 14:52:41,787::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-5982::DEBUG::2013-03-05 14:52:41,787::task::957::TaskManager.Task::(_decref) Task=`91d8929e-1349-4d74-9bcd-e0df406ce455`::ref 0 aborting False Thread-5983::DEBUG::2013-03-05 14:52:41,795::libvirtvm::283::vm.Vm::(_getDiskLatency) vmId=`4cc23d92-8667-4710-9714-a67c0d178fa0`::Disk vda latency not available Thread-21::DEBUG::2013-03-05 14:52:46,921::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd iflag=direct if=/dev/0e5827a5-6f3c-49be-be9b-0bfb65198644/metadata bs=4096 count=1' (cwd None) Thread-21::DEBUG::2013-03-05 14:52:46,933::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000389226 s, 10.5 MB/s\n'; <rc> = 0 Thread-5988::DEBUG::2013-03-05 14:52:52,015::task::568::TaskManager.Task::(_updateState) Task=`d8d9ccc1-f17b-4372-a27e-bbee4eda1736`::moving from state init -> state preparing Thread-5988::INFO::2013-03-05 14:52:52,016::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-5988::INFO::2013-03-05 14:52:52,016::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'0e5827a5-6f3c-49be-be9b-0bfb65198644': {'delay': '0.0129730701447', 'lastCheck': '5.1', 'code': 0, 'valid': True}, u'4007f30a-f888-4587-b82c-40bcde401acb': {'delay': '0.00222110748291', 'lastCheck': '5.3', 'code': 0, 'valid': True}} Thread-5988::DEBUG::2013-03-05 14:52:52,016::task::1151::TaskManager.Task::(prepare) Task=`d8d9ccc1-f17b-4372-a27e-bbee4eda1736`::finished: {u'0e5827a5-6f3c-49be-be9b-0bfb65198644': {'delay': '0.0129730701447', 'lastCheck': '5.1', 'code': 0, 'valid': True}, u'4007f30a-f888-4587-b82c-40bcde401acb': {'delay': '0.00222110748291', 'lastCheck': '5.3', 'code': 0, 'valid': True}} Thread-5988::DEBUG::2013-03-05 14:52:52,016::task::568::TaskManager.Task::(_updateState) Task=`d8d9ccc1-f17b-4372-a27e-bbee4eda1736`::moving from state preparing -> state finished
------------------------------------------------------------------------ xianghuadu
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
The vdsm log you pasted was logged by the recovery code on migration failure, not migration failure itself. You could paste the log messages above that here. From the traceback in _recovery, I suspect it's related to ssl. Does it work if you disable ssl? For how to disable ssl, please see http://www.ovirt.org/OVirt_-_disable_SSL_in_VDSM