Attachment 909919 Details for Bug 1110707 – vdsm.log

vdsm.log

vdsm.log (text/plain), 12.67 KB, created by lily on 2014-06-18 09:55:34 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: lily

Created: 2014-06-18 09:55:34 UTC

Size: 12.67 KB

patch

obsolete

>Thread-806::DEBUG::2014-06-18 16:53:33,072::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n362 bytes (362 B) copied, 0.000373556 s, 969 kB/s\n'; <rc> = 0
>Thread-803::DEBUG::2014-06-18 16:53:35,751::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/glusterSD/su04:neofs-images/c13bf545-2d42-4ee8-8ca1-a1413e01595e/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-803::DEBUG::2014-06-18 16:53:35,760::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n598 bytes (598 B) copied, 0.000801219 s, 746 kB/s\n'; <rc> = 0
>Thread-4260::DEBUG::2014-06-18 16:53:37,261::task::579::TaskManager.Task::(_updateState) Task=`7cf95aa1-8327-4bf3-af16-9fe4e1d29b81`::moving from state init -> state preparing
>Thread-4260::INFO::2014-06-18 16:53:37,262::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-4260::INFO::2014-06-18 16:53:37,262::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9c35648e-6f0b-46c2-9c1b-47f6af5e60f9': {'delay': '0.000373556', 'lastCheck': '4.2', 'code': 0, 'valid': True, 'version': 0}, '6a15d8bd-046e-443b-bac0-17a8bf057fba': {'delay': '0.000957227', 'lastCheck': '4.2', 'code': 0, 'valid': True, 'version': 3}, '93da6292-36f7-4970-af18-a8b56e5e45c7': {'delay': '0.000824325', 'lastCheck': '5.3', 'code': 0, 'valid': True, 'version': 3}, 'c13bf545-2d42-4ee8-8ca1-a1413e01595e': {'delay': '0.000801219', 'lastCheck': '1.5', 'code': 0, 'valid': True, 'version': 3}}
>Thread-4260::DEBUG::2014-06-18 16:53:37,262::task::1168::TaskManager.Task::(prepare) Task=`7cf95aa1-8327-4bf3-af16-9fe4e1d29b81`::finished: {'9c35648e-6f0b-46c2-9c1b-47f6af5e60f9': {'delay': '0.000373556', 'lastCheck': '4.2', 'code': 0, 'valid': True, 'version': 0}, '6a15d8bd-046e-443b-bac0-17a8bf057fba': {'delay': '0.000957227', 'lastCheck': '4.2', 'code': 0, 'valid': True, 'version': 3}, '93da6292-36f7-4970-af18-a8b56e5e45c7': {'delay': '0.000824325', 'lastCheck': '5.3', 'code': 0, 'valid': True, 'version': 3}, 'c13bf545-2d42-4ee8-8ca1-a1413e01595e': {'delay': '0.000801219', 'lastCheck': '1.5', 'code': 0, 'valid': True, 'version': 3}}
>Thread-4260::DEBUG::2014-06-18 16:53:37,262::task::579::TaskManager.Task::(_updateState) Task=`7cf95aa1-8327-4bf3-af16-9fe4e1d29b81`::moving from state preparing -> state finished
>Thread-4260::DEBUG::2014-06-18 16:53:37,263::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-4260::DEBUG::2014-06-18 16:53:37,263::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-4260::DEBUG::2014-06-18 16:53:37,263::task::974::TaskManager.Task::(_decref) Task=`7cf95aa1-8327-4bf3-af16-9fe4e1d29b81`::ref 0 aborting False
>Thread-4262::DEBUG::2014-06-18 16:53:39,107::BindingXMLRPC::965::vds::(wrapper) client [10.1.110.172]::call vmMigrate with ({'tunneled': 'false', 'dst': '10.1.110.173:54321', 'vmId': '66e4f53b-682a-4182-bfa8-2121cf36291a', 'method': 'online', 'src': '10.1.110.174'},) {} flowID [13b96d31]
>Thread-4262::DEBUG::2014-06-18 16:53:39,107::API::463::vds::(migrate) {'tunneled': 'false', 'dst': '10.1.110.173:54321', 'vmId': '66e4f53b-682a-4182-bfa8-2121cf36291a', 'method': 'online', 'src': '10.1.110.174'}
>Thread-4262::DEBUG::2014-06-18 16:53:39,108::BindingXMLRPC::972::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration in progress', 'code': 0}, 'progress': 0}
>Thread-4263::DEBUG::2014-06-18 16:53:39,109::vm::180::vm.Vm::(_setupVdsConnection) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::Destination server is: 10.1.110.173:54321
>Thread-4263::DEBUG::2014-06-18 16:53:39,110::vm::182::vm.Vm::(_setupVdsConnection) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::Initiating connection with destination
>Thread-4263::DEBUG::2014-06-18 16:53:39,167::vm::232::vm.Vm::(_prepareGuest) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::Migration started
>Thread-4263::DEBUG::2014-06-18 16:53:39,186::vm::314::vm.Vm::(run) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::migration semaphore acquired
>Thread-4263::DEBUG::2014-06-18 16:53:39,217::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/before_vm_migrate_source/60_dataplane' (cwd None)
>Thread-4263::DEBUG::2014-06-18 16:53:39,300::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-4263::INFO::2014-06-18 16:53:39,300::hooks::88::root::(_runHooksDir)
>Thread-4263::DEBUG::2014-06-18 16:53:39,506::vm::375::vm.Vm::(_startUnderlyingMigration) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::starting migration to qemu+tls://10.1.110.173/system with miguri tcp://10.1.110.173
>Thread-4264::DEBUG::2014-06-18 16:53:39,507::vm::733::vm.Vm::(run) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::migration downtime thread started
>Thread-4265::DEBUG::2014-06-18 16:53:39,508::vm::771::vm.Vm::(run) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::starting migration monitor thread
>Thread-4263::DEBUG::2014-06-18 16:53:40,275::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 38 edom: 10 level: 2 message: Unable to read from monitor: Connection reset by peer
>Thread-4263::DEBUG::2014-06-18 16:53:40,275::vm::748::vm.Vm::(cancel) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::canceling migration downtime thread
>Thread-4263::DEBUG::2014-06-18 16:53:40,275::vm::818::vm.Vm::(stop) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::stopping migration monitor thread
>Thread-4264::DEBUG::2014-06-18 16:53:40,275::vm::745::vm.Vm::(run) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::migration downtime thread exiting
>Thread-4263::ERROR::2014-06-18 16:53:40,276::vm::238::vm.Vm::(_recover) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::Unable to read from monitor: Connection reset by peer
>Thread-4263::ERROR::2014-06-18 16:53:40,382::vm::337::vm.Vm::(run) vmId=`66e4f53b-682a-4182-bfa8-2121cf36291a`::Failed to migrate
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 323, in run
>    self._startUnderlyingMigration()
>  File "/usr/share/vdsm/vm.py", line 403, in _startUnderlyingMigration
>    None, maxBandwidth)
>  File "/usr/share/vdsm/vm.py", line 841, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 76, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1178, in migrateToURI2
>    if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self)
>libvirtError: Unable to read from monitor: Connection reset by peer
>Thread-4267::DEBUG::2014-06-18 16:53:40,387::BindingXMLRPC::965::vds::(wrapper) client [10.1.110.172]::call vmGetStats with ('66e4f53b-682a-4182-bfa8-2121cf36291a',) {} flowID [590906ea]
>Thread-4267::DEBUG::2014-06-18 16:53:40,388::BindingXMLRPC::972::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '18186', 'displayIp': '0', 'displayPort': u'5902', 'session': 'Unknown', 'displaySecurePort': u'5903', 'timeOffset': '0', 'hash': '-3684830484207139002', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '698368'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet1': {'macAddr': '00:1a:4a:8b:a4:71', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet1'}}, 'vmId': '66e4f53b-682a-4182-bfa8-2121cf36291a', 'displayType': 'qxl', 'cpuUser': '0.54', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '3473408', 'writeLatency': '0', 'imageID': 'a4b98453-de36-4591-a6bd-3bffc4e49d27', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '3420160', 'writeRate': '0.00'}, u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '1.88', 'elapsedTime': '2232', 'vmType': 'kvm', 'cpuSys': '0.40', 'appsList': [], 'guestIPs': ''}]}
>Thread-4268::DEBUG::2014-06-18 16:53:40,430::BindingXMLRPC::965::vds::(wrapper) client [10.1.110.172]::call vmGetMigrationStatus with ('66e4f53b-682a-4182-bfa8-2121cf36291a',) {} flowID [590906ea]
>Thread-4268::DEBUG::2014-06-18 16:53:40,430::BindingXMLRPC::972::vds::(wrapper) return vmGetMigrationStatus with {'status': {'message': 'Fatal error during migration', 'code': 12}, 'progress': 0}
>Thread-4269::DEBUG::2014-06-18 16:53:40,763::BindingXMLRPC::965::vds::(wrapper) client [10.1.110.172]::call volumesList with () {} flowID [4a2ec0b9]
>Thread-4269::DEBUG::2014-06-18 16:53:40,807::BindingXMLRPC::972::vds::(wrapper) return volumesList with {'status': {'message': 'Done', 'code': 0}, 'volumes': {'yytest': {'transportType': ['TCP'], 'uuid': 'b7db1063-14e3-4c34-9fde-d8bf46431cb0', 'bricks': ['10.1.110.174:/data/test', '10.1.110.173:/data/test'], 'volumeName': 'yytest', 'volumeType': 'DISTRIBUTE', 'replicaCount': '1', 'brickCount': '2', 'distCount': '1', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}, 'volume1': {'transportType': ['TCP'], 'uuid': '4fe088dd-1462-4b72-b858-39e0048fb25f', 'bricks': ['10.1.110.173:/var/lib/exports/volume1'], 'volumeName': 'volume1', 'volumeType': 'DISTRIBUTE', 'replicaCount': '1', 'brickCount': '1', 'distCount': '1', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}, 'neofs-images': {'transportType': ['TCP'], 'uuid': 'b82339f3-8d72-43fc-ab66-4ae5d26719c2', 'bricks': ['10.1.110.173:/var/lib/exports/neofs-images', '10.1.110.174:/var/lib/exports/neofs-images'], 'volumeName': 'neofs-images', 'volumeType': 'REPLICATE', 'replicaCount': '2', 'brickCount': '2', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}, 'volume3': {'transportType': ['TCP'], 'uuid': 'a9ed1e07-875c-42c5-a007-11d6d0868a79', 'bricks': ['10.1.110.173:/var/lib/exports/volume3', '10.1.110.174:/var/lib/exports/volume3'], 'volumeName': 'volume3', 'volumeType': 'REPLICATE', 'replicaCount': '2', 'brickCount': '2', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'options': {'user.cifs': 'enable', 'nfs.disable': 'off', 'auth.allow': '*'}}, 'volme2': {'transportType': ['TCP'], 'uuid': '08f74cf1-f3e8-4115-a535-ee2ac824c066', 'bricks': ['10.1.110.173:/var/lib/exports/volume2', '10.1.110.174:/var/lib/exports/volume2'], 'volumeName': 'volme2', 'volumeType': 'REPLICATE', 'replicaCount': '2', 'brickCount': '2', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'options': {'cluster.server-quorum-type': 'server', 'cluster.eager-lock': 'enable', 'performance.stat-prefetch': 'off', 'auth.allow': '*', 'cluster.quorum-type': 'auto', 'performance.quick-read': 'off', 'network.remote-dio': 'enable', 'nfs.disable': 'off', 'performance.io-cache': 'off', 'storage.owner-uid': '36', 'user.cifs': 'enable', 'performance.read-ahead': 'off', 'storage.owner-gid': '36'}}}}
>Thread-805::DEBUG::2014-06-18 16:53:41,997::fileSD::222::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/glusterSD/su03:volme2/93da6292-36f7-4970-af18-a8b56e5e45c7/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-805::DEBUG::2014-06-18 16:53:42,006::fileSD::222::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n339 bytes (339 B) copied, 0.000550777 s, 615 kB/s\n'; <rc> = 0
>Thread-4270::DEBUG::2014-06-18 16:53:42,080::BindingXMLRPC::167::vds::(wrapper) client [10.1.110.172]
>Thread-4270::DEBUG::2014-06-18 16:53:42,080::task::579::TaskManager.Task::(_updateState) Task=`0b2a1a02-f549-4abc-91f7-c803ae824700`::moving from state init -> state preparing

Actions: View

Attachments on bug 1110707: 909918 | 909919 | 910203 | 910204