Hello, I'm using a 4 node cluster oVirt 4.1. After updating the Engine to 4.2.3.8 (and ContOS 7.5), I tried to update the nodes too. Unfortunally, the live migration is not working (any more). Maybe it's related to following error found in engine.log 2018-06-19 09:32:53,469+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-19 09:32:53,475+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050) I'm using the selfsigned CA provided with oVirt. Nodes (source and destination) OS-Version:RHEL - 7 - 4.1708.el7.centos Kernelversion: 3.10.0 - 693.21.1.el7.x86_64 KVM-Version:2.9.0 - 16.el7_4.14.1 LIBVIRT-Version:libvirt-3.2.0-14.el7_4.9 VDSM-Version:vdsm-4.19.45-1.el7.centos SPICE-Version:0.12.8 - 2.el7.1 CEPH-Version:librbd1-0.94.5-2.el7 Kernel Features:PTI: 1, IBPB: 0, IBRS: 0 engine.log for the mirgration: 2018-06-14 13:13:30,300+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-246968) [] EVENT_ID: VM_MIGRATION_START_SYSTEM_INITIATED(67), Migration initiated by system (VM: vm_to_migrate, Source: SOURCE, Destination: DESTINATION, Reason: Host preparing for maintenance). 2018-06-14 13:13:32,886+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmsStatisticsFetcher] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] Fetched 8 VMs from VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498' 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:38,356+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock Acquired to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:38,369+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Running command: SyncNetworkProviderCommand internal: true. 2018-06-14 13:14:38,370+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-14 13:14:38,379+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050) 2018-06-14 13:14:38,382+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock freed to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) moved from 'MigratingFrom' --> 'Up' 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Adding VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) to re-run list 2018-06-14 13:15:45,400+02 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmsMonitoring] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Rerun VM '4aff4193-ba75-481d-92b3-59b62cd8b111'. Called from VDS 'SOURCE' 2018-06-14 13:15:45,451+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateStatusVDSCommand(HostName = SOURCE, MigrateStatusVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111'}), log id: 25f95334 2018-06-14 13:15:45,453+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateStatusVDSCommand, log id: 25f95334 2018-06-14 13:15:45,478+02 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-247023) [] EVENT_ID: VM_MIGRATION_TRYING_RERUN(128), Failed to migrate VM vm_to_migrate to Host DESTINATION . Trying to migrate to another Host. 2018-06-14 13:15:45,557+02 INFO [org.ovirt.engine.core.bll.MigrateVmCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] Running command: MigrateVmCommand internal: true. Entities affected : ID: 4aff4193-ba75-481d-92b3-59b62cd8b111 Type: VMAction group MIGRATE_VM with role type USER 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateVDSCommand( MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost='10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 736d023f 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateBrokerVDSCommand(HostName = SOURCE, MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost='10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 58572c5b 2018-06-14 13:15:45,601+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateBrokerVDSCommand, log id: 58572c5b 2018-06-14 13:15:45,604+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 736d023f
Having the same issue after upgrading from ovirt 4.1 to 4.2.4. Attempting to migrate any VM results in an immediate failure. The engine log shows an error as follows. 2018-06-27 10:43:59,815-04 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-3) [] Migration of VM 'ASAP' to host 'ovirt-node-production1' failed: VM destroyed during the startup. 2018-06-27 10:43:59,819-04 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] VM '91be7864-3793-4583-accb-31b441af7b6a'(ASAP) moved from 'MigratingFrom' --> 'Up' On 06/19/2018 04:29 AM, rni@chef.net wrote:
Hello,
I'm using a 4 node cluster oVirt 4.1. After updating the Engine to 4.2.3.8 (and ContOS 7.5), I tried to update the nodes too. Unfortunally, the live migration is not working (any more). Maybe it's related to following error found in engine.log
2018-06-19 09:32:53,469+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-19 09:32:53,475+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050)
I'm using the selfsigned CA provided with oVirt.
Nodes (source and destination) OS-Version:RHEL - 7 - 4.1708.el7.centos Kernelversion: 3.10.0 - 693.21.1.el7.x86_64 KVM-Version:2.9.0 - 16.el7_4.14.1 LIBVIRT-Version:libvirt-3.2.0-14.el7_4.9 VDSM-Version:vdsm-4.19.45-1.el7.centos SPICE-Version:0.12.8 - 2.el7.1 CEPH-Version:librbd1-0.94.5-2.el7 Kernel Features:PTI: 1, IBPB: 0, IBRS: 0
engine.log for the mirgration: 2018-06-14 13:13:30,300+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-246968) [] EVENT_ID: VM_MIGRATION_START_SYSTEM_INITIATED(67), Migration initiated by system (VM: vm_to_migrate, Source: SOURCE, Destination: DESTINATION, Reason: Host preparing for maintenance). 2018-06-14 13:13:32,886+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmsStatisticsFetcher] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] Fetched 8 VMs from VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498' 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:38,356+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock Acquired to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:38,369+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Running command: SyncNetworkProviderCommand internal: true. 2018-06-14 13:14:38,370+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-14 13:14:38,379+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050) 2018-06-14 13:14:38,382+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock freed to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) moved from 'MigratingFrom' --> 'Up' 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Adding VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) to re-run list 2018-06-14 13:15:45,400+02 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmsMonitoring] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Rerun VM '4aff4193-ba75-481d-92b3-59b62cd8b111'. Called from VDS 'SOURCE' 2018-06-14 13:15:45,451+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateStatusVDSCommand(HostName = SOURCE, MigrateStatusVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111'}), log id: 25f95334 2018-06-14 13:15:45,453+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateStatusVDSCommand, log id: 25f95334 2018-06-14 13:15:45,478+02 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-247023) [] EVENT_ID: VM_MIGRATION_TRYING_RERUN(128), Failed to migrate VM vm_to_migrate to Host DESTINATION . Trying to migrate to another Host. 2018-06-14 13:15:45,557+02 INFO [org.ovirt.engine.core.bll.MigrateVmCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] Running command: MigrateVmCommand internal: true. Entities affected : ID: 4aff4193-ba75-481d-92b3-59b62cd8b111 Type: VMAction group MIGRATE_VM with role type USER 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateVDSCommand( MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost='10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 736d023f 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateBrokerVDSCommand(HostName = SOURCE, MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost='10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 58572c5b 2018-06-14 13:15:45,601+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateBrokerVDSCommand, log id: 58572c5b 2018-06-14 13:15:45,604+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 736d023f
_______________________________________________ Users mailing list -- users@ovirt.org To unsubscribe send an email to users-leave@ovirt.org Privacy Statement: https://www.ovirt.org/site/privacy-policy/ oVirt Code of Conduct: https://www.ovirt.org/community/about/community-guidelines/ List Archives: https://lists.ovirt.org/archives/list/users@ovirt.org/message/B6IEVX5XEBFHJC...
On 27 Jun 2018, at 16:47, Michael Watters <wattersm@watters.ws> wrote:
Having the same issue after upgrading from ovirt 4.1 to 4.2.4. Attempting to migrate any VM results in an immediate failure. The engine log shows an error as follows.
2018-06-27 10:43:59,815-04 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-3) [] Migration of VM 'ASAP' to host 'ovirt-node-production1' failed: VM destroyed during the startup. 2018-06-27 10:43:59,819-04 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] VM '91be7864-3793-4583-accb-31b441af7b6a'(ASAP) moved from 'MigratingFrom' --> ‘Up'
please include vdsm.logs from source and destination hypervisors Thanks, michal
On 06/19/2018 04:29 AM, rni@chef.net wrote:
Hello,
I'm using a 4 node cluster oVirt 4.1. After updating the Engine to 4.2.3.8 (and ContOS 7.5), I tried to update the nodes too. Unfortunally, the live migration is not working (any more). Maybe it's related to following error found in engine.log
2018-06-19 09:32:53,469+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-19 09:32:53,475+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050)
I'm using the selfsigned CA provided with oVirt.
Nodes (source and destination) OS-Version:RHEL - 7 - 4.1708.el7.centos Kernelversion: 3.10.0 - 693.21.1.el7.x86_64 KVM-Version:2.9.0 - 16.el7_4.14.1 LIBVIRT-Version:libvirt-3.2.0-14.el7_4.9 VDSM-Version:vdsm-4.19.45-1.el7.centos SPICE-Version:0.12.8 - 2.el7.1 CEPH-Version:librbd1-0.94.5-2.el7 Kernel Features:PTI: 1, IBPB: 0, IBRS: 0
engine.log for the mirgration: 2018-06-14 13:13:30,300+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-246968) [] EVENT_ID: VM_MIGRATION_START_SYSTEM_INITIATED(67), Migration initiated by system (VM: vm_to_migrate, Source: SOURCE, Destination: DESTINATION, Reason: Host preparing for maintenance). 2018-06-14 13:13:32,886+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmsStatisticsFetcher] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] Fetched 8 VMs from VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498' 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:38,356+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock Acquired to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:38,369+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Running command: SyncNetworkProviderCommand internal: true. 2018-06-14 13:14:38,370+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-14 13:14:38,379+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050) 2018-06-14 13:14:38,382+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock freed to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) moved from 'MigratingFrom' --> 'Up' 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Adding VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) to re-run list 2018-06-14 13:15:45,400+02 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmsMonitoring] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Rerun VM '4aff4193-ba75-481d-92b3-59b62cd8b111'. Called from VDS 'SOURCE' 2018-06-14 13:15:45,451+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateStatusVDSCommand(HostName = SOURCE, MigrateStatusVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111'}), log id: 25f95334 2018-06-14 13:15:45,453+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateStatusVDSCommand, log id: 25f95334 2018-06-14 13:15:45,478+02 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-247023) [] EVENT_ID: VM_MIGRATION_TRYING_RERUN(128), Failed to migrate VM vm_to_migrate to Host DESTINATION . Trying to migrate to another Host. 2018-06-14 13:15:45,557+02 INFO [org.ovirt.engine.core.bll.MigrateVmCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] Running command: MigrateVmCommand internal: true. Entities affected : ID: 4aff4193-ba75-481d-92b3-59b62cd8b111 Type: VMAction group MIGRATE_VM with role type USER 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateVDSCommand( MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost='10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 736d023f 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateBrokerVDSCommand(HostName = SOURCE, MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost='10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 58572c5b 2018-06-14 13:15:45,601+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateBrokerVDSCommand, log id: 58572c5b 2018-06-14 13:15:45,604+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 736d023f
_______________________________________________ Users mailing list -- users@ovirt.org To unsubscribe send an email to users-leave@ovirt.org Privacy Statement: https://www.ovirt.org/site/privacy-policy/ oVirt Code of Conduct: https://www.ovirt.org/community/about/community-guidelines/ List Archives: https://lists.ovirt.org/archives/list/users@ovirt.org/message/B6IEVX5XEBFHJC...
Users mailing list -- users@ovirt.org To unsubscribe send an email to users-leave@ovirt.org Privacy Statement: https://www.ovirt.org/site/privacy-policy/ oVirt Code of Conduct: https://www.ovirt.org/community/about/community-guidelines/ List Archives: https://lists.ovirt.org/archives/list/users@ovirt.org/message/63VCY4HBRVBVIB...
Hello, for my issue, her we go: vdsm.log source 2018-06-28 12:25:47,566+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:25:47,575+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:25:48,926+0200 INFO (jsonrpc/0) [vdsm.api] START migrate(params={u'incomingLimit': 2, u'src': u'10.157.8.40', u'dstqemu': u'192.168.1.113', u'autoConverge': u'false', u'tunneled': u'false', u'enableGuestEvents': False, u'dst': u'10.157.8.42:54321', u'vmId': u'a54af7cd-3b89-43c1-82b3-ae0c08d103d3', u'abortOnError': u'true', u'outgoingLimit': 2, u'compressed': u'false', u'maxBandwidth': 500, u'method': u'online', 'mode': 'remote'}) from=::ffff:10.157.8.36,53170, flow_id=db7c94d5-7e11-43b0-95d8-a9095e4f8e83 (api:46) 2018-06-28 12:25:48,929+0200 INFO (jsonrpc/0) [vdsm.api] FINISH migrate return={'status': {'message': 'Migration in progress', 'code': 0}, 'progress': 0} from=::ffff:10.157.8.36,53170, flow_id=db7c94d5-7e11-43b0-95d8-a9095e4f8e83 (api:52) 2018-06-28 12:25:48,930+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call VM.migrate succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:25:49,153+0200 INFO (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=554b6d96-89b0-4ff5-a2de-ced7f268d58c (api:46) 2018-06-28 12:25:49,154+0200 INFO (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000299843', 'lastCheck': '2.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000570989', 'lastCheck': '5.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000248445', 'lastCheck': '5.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000408845', 'lastCheck': '4.9', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=554b6d96-89b0-4ff5-a2de-ced7f268d58c (api:52) 2018-06-28 12:25:49,173+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:49,860+0200 INFO (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Creation of destination VM took: 0 seconds (migration:455) 2018-06-28 12:25:49,861+0200 INFO (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') starting migration to qemu+tls://10.157.8.42/system with miguri tcp://192.168.1.113 (migration:480) 2018-06-28 12:25:52,080+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:25:55,836+0200 INFO (periodic/7090) [vdsm.api] START repoStats(options=None) from=internal, task_id=07d6e59b-93a7-46ef-8ffe-a9b8d8f1d3b1 (api:46) 2018-06-28 12:25:55,837+0200 INFO (periodic/7090) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000349569', 'lastCheck': '5.3', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000632803', 'lastCheck': '1.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00025132', 'lastCheck': '2.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000334113', 'lastCheck': '1.6', 'valid': True}} from=internal, task_id=07d6e59b-93a7-46ef-8ffe-a9b8d8f1d3b1 (api:52) 2018-06-28 12:25:59,865+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 10 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:26:02,584+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:26:02,610+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:26:04,177+0200 INFO (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=6226131d-2afb-453f-8fdd-4814985f2602 (api:46) 2018-06-28 12:26:04,177+0200 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000240789', 'lastCheck': '3.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00048312', 'lastCheck': '0.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000303582', 'lastCheck': '0.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000334113', 'lastCheck': '3.5', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=6226131d-2afb-453f-8fdd-4814985f2602 (api:52) 2018-06-28 12:26:04,196+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:26:07,142+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:26:09,868+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:26:09,869+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 20 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:26:10,885+0200 INFO (periodic/7091) [vdsm.api] START repoStats(options=None) from=internal, task_id=55ee01e0-c474-44ee-a9a5-b1d5fd599043 (api:46) 2018-06-28 12:26:10,885+0200 INFO (periodic/7091) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000350665', 'lastCheck': '0.3', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00048312', 'lastCheck': '6.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000303582', 'lastCheck': '7.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000420027', 'lastCheck': '0.2', 'valid': True}} from=internal, task_id=55ee01e0-c474-44ee-a9a5-b1d5fd599043 (api:52) 2018-06-28 12:26:16,735+0200 INFO (itmap/0) [IOProcessClient] Starting client ioprocess-351445 (__init__:330) 2018-06-28 12:26:16,743+0200 INFO (ioprocess/11232) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,744+0200 INFO (itmap/1) [IOProcessClient] Starting client ioprocess-351446 (__init__:330) 2018-06-28 12:26:16,750+0200 INFO (itmap/2) [IOProcessClient] Starting client ioprocess-351447 (__init__:330) 2018-06-28 12:26:16,755+0200 INFO (ioprocess/11240) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,757+0200 INFO (itmap/3) [IOProcessClient] Starting client ioprocess-351448 (__init__:330) 2018-06-28 12:26:16,763+0200 INFO (ioprocess/11247) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,765+0200 INFO (itmap/4) [IOProcessClient] Starting client ioprocess-351449 (__init__:330) 2018-06-28 12:26:16,771+0200 INFO (ioprocess/11256) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,773+0200 INFO (itmap/5) [IOProcessClient] Starting client ioprocess-351450 (__init__:330) 2018-06-28 12:26:16,778+0200 INFO (ioprocess/11265) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,780+0200 INFO (itmap/6) [IOProcessClient] Starting client ioprocess-351451 (__init__:330) 2018-06-28 12:26:16,785+0200 INFO (ioprocess/11275) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,787+0200 INFO (itmap/7) [IOProcessClient] Starting client ioprocess-351452 (__init__:330) 2018-06-28 12:26:16,791+0200 INFO (ioprocess/11283) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,793+0200 INFO (itmap/8) [IOProcessClient] Starting client ioprocess-351453 (__init__:330) 2018-06-28 12:26:16,798+0200 INFO (ioprocess/11290) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,799+0200 INFO (itmap/9) [IOProcessClient] Starting client ioprocess-351454 (__init__:330) 2018-06-28 12:26:16,804+0200 INFO (ioprocess/11297) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,806+0200 INFO (itmap/10) [IOProcessClient] Starting client ioprocess-351455 (__init__:330) 2018-06-28 12:26:16,813+0200 INFO (ioprocess/11304) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,815+0200 INFO (ioprocess/11311) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:26:16,822+0200 INFO (monitor/48055e2) [storage.StorageDomain] Resource namespace 01_img_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:758) 2018-06-28 12:26:16,822+0200 INFO (monitor/48055e2) [storage.StorageDomain] Resource namespace 02_vol_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:767) 2018-06-28 12:26:17,617+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:26:17,628+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:26:19,199+0200 INFO (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=13488a51-8f0b-4ea0-89b7-3bc39bb68fa9 (api:46) 2018-06-28 12:26:19,199+0200 INFO (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000350665', 'lastCheck': '2.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00063241', 'lastCheck': '5.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000543002', 'lastCheck': '5.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000434669', 'lastCheck': '5.0', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=13488a51-8f0b-4ea0-89b7-3bc39bb68fa9 (api:52) 2018-06-28 12:26:19,218+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:26:19,871+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:26:19,872+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 30 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:26:22,198+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:26:25,922+0200 INFO (periodic/7090) [vdsm.api] START repoStats(options=None) from=internal, task_id=59c658bf-3f91-4c87-8942-549703fcfbfb (api:46) 2018-06-28 12:26:25,923+0200 INFO (periodic/7090) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000306354', 'lastCheck': '5.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000571317', 'lastCheck': '1.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000244739', 'lastCheck': '2.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000327441', 'lastCheck': '1.7', 'valid': True}} from=internal, task_id=59c658bf-3f91-4c87-8942-549703fcfbfb (api:52) 2018-06-28 12:26:29,874+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:26:29,875+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 40 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:26:32,636+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:26:32,662+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:26:34,220+0200 INFO (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=b219c494-760f-43fa-9220-22602e7b3aef (api:46) 2018-06-28 12:26:34,220+0200 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00027001', 'lastCheck': '3.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00069247', 'lastCheck': '0.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000463365', 'lastCheck': '0.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000327441', 'lastCheck': '3.5', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=b219c494-760f-43fa-9220-22602e7b3aef (api:52) 2018-06-28 12:26:34,244+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:26:37,252+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:26:38,944+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'714ca627-a9d2-4c2f-8e29-00165c3c0778', volUUID=u'171a4bcc-6e6b-4201-a2d9-1c08296517b7', options=None) from=internal, task_id=576397ad-8f47-45dd-bfaf-d5d50808c165 (api:46) 2018-06-28 12:26:38,944+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '128849018880', 'apparentsize': '128849018880'} from=internal, task_id=576397ad-8f47-45dd-bfaf-d5d50808c165 (api:52) 2018-06-28 12:26:38,945+0200 INFO (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'c2cfa750-22ce-4c1d-802e-1739c6926f78', volUUID=u'934fcb45-444b-45ef-975f-7d63f228dcc4', options=None) from=internal, task_id=18608522-878e-4cc1-aa84-6ebcb822d5fa (api:46) 2018-06-28 12:26:38,945+0200 INFO (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '19327352832', 'apparentsize': '19327352832'} from=internal, task_id=18608522-878e-4cc1-aa84-6ebcb822d5fa (api:52) 2018-06-28 12:26:38,946+0200 INFO (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cfe6d612-40cc-4f1d-990e-ae6c52a4f70f', volUUID=u'02af893d-647e-4906-8814-de4003506c96', options=None) from=internal, task_id=e3bc7fe2-2ced-4ae4-b5e4-64a4153172b3 (api:46) 2018-06-28 12:26:38,946+0200 INFO (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '26843545600', 'apparentsize': '26843545600'} from=internal, task_id=e3bc7fe2-2ced-4ae4-b5e4-64a4153172b3 (api:52) 2018-06-28 12:26:38,947+0200 INFO (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1a7022e0-54b5-419a-a144-439c8526e1cd', volUUID=u'f05a1e54-e612-41d2-a7cc-d4f7e16dfc4f', options=None) from=internal, task_id=8c9230ca-7c43-4c89-a799-1c98ebf74bab (api:46) 2018-06-28 12:26:38,947+0200 INFO (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=8c9230ca-7c43-4c89-a799-1c98ebf74bab (api:52) 2018-06-28 12:26:38,947+0200 INFO (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cb2d4f33-6fa6-4448-b1cc-c060297407b7', volUUID=u'e6168731-26fc-4dd2-92c1-443de74d49bb', options=None) from=internal, task_id=4b7ec2e7-79a4-425d-a295-5918126a33cf (api:46) 2018-06-28 12:26:38,948+0200 INFO (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '1099511627776', 'apparentsize': '1099511627776'} from=internal, task_id=4b7ec2e7-79a4-425d-a295-5918126a33cf (api:52) 2018-06-28 12:26:38,949+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5fc7b643-db9a-4162-a67d-fb61a8cd87f7', volUUID=u'd259d325-e2bc-4a2a-935b-6eca167c6b51', options=None) from=internal, task_id=1a011e63-21ab-4b35-bd47-79ff77634775 (api:46) 2018-06-28 12:26:38,949+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=1a011e63-21ab-4b35-bd47-79ff77634775 (api:52) 2018-06-28 12:26:38,950+0200 INFO (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'33235bbf-0156-421e-9391-0749247b6ba6', volUUID=u'0d2949b6-af0f-4de2-b29a-10dcb39ad857', options=None) from=internal, task_id=0f9ec553-58ac-48b4-97da-e5e08a861a6b (api:46) 2018-06-28 12:26:38,950+0200 INFO (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '5368709120', 'apparentsize': '5368709120'} from=internal, task_id=0f9ec553-58ac-48b4-97da-e5e08a861a6b (api:52) 2018-06-28 12:26:38,951+0200 INFO (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5149067a-b18c-41cf-a355-033317291148', volUUID=u'f0afa250-6704-410c-b9be-60b99cb28ce9', options=None) from=internal, task_id=ccfa4241-0799-4645-bbde-a3ccd866107d (api:46) 2018-06-28 12:26:38,951+0200 INFO (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '16106127360', 'apparentsize': '16106127360'} from=internal, task_id=ccfa4241-0799-4645-bbde-a3ccd866107d (api:52) 2018-06-28 12:26:38,952+0200 INFO (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'07c38269-db89-4f7e-9194-f0c8923ed879', volUUID=u'366d9d18-07fa-4342-9246-fc0f396e3059', options=None) from=internal, task_id=061ca7ab-d0fd-406b-989f-c9cd0246d80c (api:46) 2018-06-28 12:26:38,952+0200 INFO (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '25769803776', 'apparentsize': '25769803776'} from=internal, task_id=061ca7ab-d0fd-406b-989f-c9cd0246d80c (api:52) 2018-06-28 12:26:38,953+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'9d92c039-5c22-4459-bc8b-ca62f0d763dd', volUUID=u'b9abe859-bd8f-412d-b1ca-f814f17d2572', options=None) from=internal, task_id=c3aa0fd8-cfd6-47cc-8a4a-a799f2ccf232 (api:46) 2018-06-28 12:26:38,953+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '144149839872', 'apparentsize': '144149839872'} from=internal, task_id=c3aa0fd8-cfd6-47cc-8a4a-a799f2ccf232 (api:52) 2018-06-28 12:26:38,954+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'a2f86027-9569-411a-8dec-b5ef0b6a30cd', volUUID=u'1eb84b01-512a-4e08-b6bc-0c056c5c86b6', options=None) from=internal, task_id=8ad4c399-0fe3-4236-859d-d18a02e4cafd (api:46) 2018-06-28 12:26:38,954+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '72074919936', 'apparentsize': '72074919936'} from=internal, task_id=8ad4c399-0fe3-4236-859d-d18a02e4cafd (api:52) 2018-06-28 12:26:38,955+0200 INFO (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', volUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', options=None) from=internal, task_id=c5ecbbb8-503a-4e83-ac8e-9e1d63ac7347 (api:46) 2018-06-28 12:26:38,955+0200 INFO (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '53687091200', 'apparentsize': '53687091200'} from=internal, task_id=c5ecbbb8-503a-4e83-ac8e-9e1d63ac7347 (api:52) 2018-06-28 12:26:39,877+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:26:39,877+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 50 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:26:40,962+0200 INFO (periodic/7085) [vdsm.api] START repoStats(options=None) from=internal, task_id=52703fc2-7917-4f58-a390-425850ca3b24 (api:46) 2018-06-28 12:26:40,962+0200 INFO (periodic/7085) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000235121', 'lastCheck': '0.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00069247', 'lastCheck': '7.0', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000463365', 'lastCheck': '7.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000375592', 'lastCheck': '0.2', 'valid': True}} from=internal, task_id=52703fc2-7917-4f58-a390-425850ca3b24 (api:52) 2018-06-28 12:26:47,671+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:26:47,697+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:26:49,242+0200 INFO (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=7409865e-ff52-406b-b22d-f2934674de2e (api:46) 2018-06-28 12:26:49,242+0200 INFO (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000235121', 'lastCheck': '2.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000510816', 'lastCheck': '5.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000324262', 'lastCheck': '5.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000441143', 'lastCheck': '5.0', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=7409865e-ff52-406b-b22d-f2934674de2e (api:52) 2018-06-28 12:26:49,265+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.03 seconds (__init__:539) 2018-06-28 12:26:49,881+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:26:49,881+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 60 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:26:52,319+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:26:56,008+0200 INFO (periodic/7093) [vdsm.api] START repoStats(options=None) from=internal, task_id=dbbb6f8a-457c-4a6a-b1ec-3abd59962551 (api:46) 2018-06-28 12:26:56,009+0200 INFO (periodic/7093) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000316826', 'lastCheck': '5.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000514374', 'lastCheck': '2.0', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000374509', 'lastCheck': '2.2', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000400921', 'lastCheck': '1.8', 'valid': True}} from=internal, task_id=dbbb6f8a-457c-4a6a-b1ec-3abd59962551 (api:52) 2018-06-28 12:26:59,883+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:26:59,884+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 70 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:27:02,705+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:27:02,714+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:27:04,297+0200 INFO (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=4e03d286-f133-4767-8815-70f0fcdb8d44 (api:46) 2018-06-28 12:27:04,297+0200 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000339338', 'lastCheck': '3.8', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000629102', 'lastCheck': '0.3', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000554273', 'lastCheck': '0.5', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000380205', 'lastCheck': '0.1', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=4e03d286-f133-4767-8815-70f0fcdb8d44 (api:52) 2018-06-28 12:27:04,315+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:27:07,372+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:27:09,886+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:27:09,886+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 80 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:27:11,056+0200 INFO (periodic/7090) [vdsm.api] START repoStats(options=None) from=internal, task_id=0b893099-f458-458a-86cb-185409463a4c (api:46) 2018-06-28 12:27:11,056+0200 INFO (periodic/7090) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000252952', 'lastCheck': '0.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000629102', 'lastCheck': '7.1', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000554273', 'lastCheck': '7.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000380205', 'lastCheck': '0.3', 'valid': True}} from=internal, task_id=0b893099-f458-458a-86cb-185409463a4c (api:52) 2018-06-28 12:27:16,838+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351449 (__init__:598) 2018-06-28 12:27:16,838+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351446 (__init__:598) 2018-06-28 12:27:16,838+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351445 (__init__:598) 2018-06-28 12:27:16,839+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351454 (__init__:598) 2018-06-28 12:27:16,839+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351451 (__init__:598) 2018-06-28 12:27:16,839+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351455 (__init__:598) 2018-06-28 12:27:16,839+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351453 (__init__:598) 2018-06-28 12:27:16,839+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351450 (__init__:598) 2018-06-28 12:27:16,840+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351447 (__init__:598) 2018-06-28 12:27:16,840+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351452 (__init__:598) 2018-06-28 12:27:16,840+0200 INFO (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351448 (__init__:598) 2018-06-28 12:27:17,728+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:27:17,737+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:27:19,321+0200 INFO (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=5d54f7d8-0ebe-4175-b7b7-6b33cac964ad (api:46) 2018-06-28 12:27:19,321+0200 INFO (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000252952', 'lastCheck': '2.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000510061', 'lastCheck': '5.3', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000301065', 'lastCheck': '5.5', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000442633', 'lastCheck': '5.1', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=5d54f7d8-0ebe-4175-b7b7-6b33cac964ad (api:52) 2018-06-28 12:27:19,341+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:27:19,888+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:27:19,888+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 90 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:27:22,422+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:27:26,094+0200 INFO (periodic/7091) [vdsm.api] START repoStats(options=None) from=internal, task_id=97f4298f-dae2-4107-9f7a-e62b99e3c6d5 (api:46) 2018-06-28 12:27:26,094+0200 INFO (periodic/7091) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000345748', 'lastCheck': '5.6', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00064893', 'lastCheck': '2.1', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000473681', 'lastCheck': '2.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000367846', 'lastCheck': '1.9', 'valid': True}} from=internal, task_id=97f4298f-dae2-4107-9f7a-e62b99e3c6d5 (api:52) 2018-06-28 12:27:29,891+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:27:29,892+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 100 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:27:32,745+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:27:32,772+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:27:34,354+0200 INFO (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=2ffd5e90-01c0-46fa-bc86-74e2a0c9bdb5 (api:46) 2018-06-28 12:27:34,355+0200 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000366741', 'lastCheck': '3.8', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00067226', 'lastCheck': '0.4', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00046561', 'lastCheck': '0.6', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000365602', 'lastCheck': '0.1', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=2ffd5e90-01c0-46fa-bc86-74e2a0c9bdb5 (api:52) 2018-06-28 12:27:34,373+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:27:37,477+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:27:38,935+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'714ca627-a9d2-4c2f-8e29-00165c3c0778', volUUID=u'171a4bcc-6e6b-4201-a2d9-1c08296517b7', options=None) from=internal, task_id=28d944b0-ea96-4a56-afc1-4ca642804765 (api:46) 2018-06-28 12:27:38,936+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '128849018880', 'apparentsize': '128849018880'} from=internal, task_id=28d944b0-ea96-4a56-afc1-4ca642804765 (api:52) 2018-06-28 12:27:38,937+0200 INFO (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'c2cfa750-22ce-4c1d-802e-1739c6926f78', volUUID=u'934fcb45-444b-45ef-975f-7d63f228dcc4', options=None) from=internal, task_id=83d16ca0-5975-4e0f-84fe-1d63ed13783f (api:46) 2018-06-28 12:27:38,937+0200 INFO (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '19327352832', 'apparentsize': '19327352832'} from=internal, task_id=83d16ca0-5975-4e0f-84fe-1d63ed13783f (api:52) 2018-06-28 12:27:38,938+0200 INFO (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cfe6d612-40cc-4f1d-990e-ae6c52a4f70f', volUUID=u'02af893d-647e-4906-8814-de4003506c96', options=None) from=internal, task_id=161ed3bc-4d7d-4c9b-9915-f67829d7183d (api:46) 2018-06-28 12:27:38,938+0200 INFO (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '26843545600', 'apparentsize': '26843545600'} from=internal, task_id=161ed3bc-4d7d-4c9b-9915-f67829d7183d (api:52) 2018-06-28 12:27:38,939+0200 INFO (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1a7022e0-54b5-419a-a144-439c8526e1cd', volUUID=u'f05a1e54-e612-41d2-a7cc-d4f7e16dfc4f', options=None) from=internal, task_id=e4fd4063-be84-493f-8616-1a23ca7085b3 (api:46) 2018-06-28 12:27:38,939+0200 INFO (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=e4fd4063-be84-493f-8616-1a23ca7085b3 (api:52) 2018-06-28 12:27:38,939+0200 INFO (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cb2d4f33-6fa6-4448-b1cc-c060297407b7', volUUID=u'e6168731-26fc-4dd2-92c1-443de74d49bb', options=None) from=internal, task_id=6ada779f-ea02-48f2-99ea-e7090a7e4b18 (api:46) 2018-06-28 12:27:38,940+0200 INFO (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '1099511627776', 'apparentsize': '1099511627776'} from=internal, task_id=6ada779f-ea02-48f2-99ea-e7090a7e4b18 (api:52) 2018-06-28 12:27:38,940+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5fc7b643-db9a-4162-a67d-fb61a8cd87f7', volUUID=u'd259d325-e2bc-4a2a-935b-6eca167c6b51', options=None) from=internal, task_id=89408443-0882-42f5-9c61-4699fdab4556 (api:46) 2018-06-28 12:27:38,941+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=89408443-0882-42f5-9c61-4699fdab4556 (api:52) 2018-06-28 12:27:38,941+0200 INFO (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'33235bbf-0156-421e-9391-0749247b6ba6', volUUID=u'0d2949b6-af0f-4de2-b29a-10dcb39ad857', options=None) from=internal, task_id=e440afe9-a3fb-4942-9e68-3e14f5a9d271 (api:46) 2018-06-28 12:27:38,942+0200 INFO (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '5368709120', 'apparentsize': '5368709120'} from=internal, task_id=e440afe9-a3fb-4942-9e68-3e14f5a9d271 (api:52) 2018-06-28 12:27:38,942+0200 INFO (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5149067a-b18c-41cf-a355-033317291148', volUUID=u'f0afa250-6704-410c-b9be-60b99cb28ce9', options=None) from=internal, task_id=3399f449-2dcc-4d82-8285-f1945d0e2baf (api:46) 2018-06-28 12:27:38,942+0200 INFO (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '16106127360', 'apparentsize': '16106127360'} from=internal, task_id=3399f449-2dcc-4d82-8285-f1945d0e2baf (api:52) 2018-06-28 12:27:38,943+0200 INFO (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'07c38269-db89-4f7e-9194-f0c8923ed879', volUUID=u'366d9d18-07fa-4342-9246-fc0f396e3059', options=None) from=internal, task_id=1d361a42-8c9e-4885-a8ff-e7ce0c1c224f (api:46) 2018-06-28 12:27:38,943+0200 INFO (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '25769803776', 'apparentsize': '25769803776'} from=internal, task_id=1d361a42-8c9e-4885-a8ff-e7ce0c1c224f (api:52) 2018-06-28 12:27:38,944+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'9d92c039-5c22-4459-bc8b-ca62f0d763dd', volUUID=u'b9abe859-bd8f-412d-b1ca-f814f17d2572', options=None) from=internal, task_id=a17d38fc-772e-47ad-99e1-fd7fea5e2b97 (api:46) 2018-06-28 12:27:38,944+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '144149839872', 'apparentsize': '144149839872'} from=internal, task_id=a17d38fc-772e-47ad-99e1-fd7fea5e2b97 (api:52) 2018-06-28 12:27:38,945+0200 INFO (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'a2f86027-9569-411a-8dec-b5ef0b6a30cd', volUUID=u'1eb84b01-512a-4e08-b6bc-0c056c5c86b6', options=None) from=internal, task_id=aacf55d3-3fdd-49e1-af58-bae7ce9fbd6f (api:46) 2018-06-28 12:27:38,945+0200 INFO (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '72074919936', 'apparentsize': '72074919936'} from=internal, task_id=aacf55d3-3fdd-49e1-af58-bae7ce9fbd6f (api:52) 2018-06-28 12:27:38,945+0200 INFO (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', volUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', options=None) from=internal, task_id=6213f532-b194-467b-9799-02032e59af58 (api:46) 2018-06-28 12:27:38,946+0200 INFO (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '53687091200', 'apparentsize': '53687091200'} from=internal, task_id=6213f532-b194-467b-9799-02032e59af58 (api:52) 2018-06-28 12:27:39,894+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:27:39,894+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 110 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:27:41,143+0200 INFO (periodic/7085) [vdsm.api] START repoStats(options=None) from=internal, task_id=79f2e7e6-ef1d-47d8-87a9-46aefcd02467 (api:46) 2018-06-28 12:27:41,143+0200 INFO (periodic/7085) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000291026', 'lastCheck': '0.6', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00067226', 'lastCheck': '7.1', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00046561', 'lastCheck': '7.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000365602', 'lastCheck': '0.4', 'valid': True}} from=internal, task_id=79f2e7e6-ef1d-47d8-87a9-46aefcd02467 (api:52) 2018-06-28 12:27:41,313+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['metadata'] (lvm:1291) 2018-06-28 12:27:41,313+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['metadata']) (lvm:1319) 2018-06-28 12:27:41,475+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['ids'] (lvm:1291) 2018-06-28 12:27:41,476+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['ids']) (lvm:1319) 2018-06-28 12:27:41,544+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['leases'] (lvm:1291) 2018-06-28 12:27:41,544+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['leases']) (lvm:1319) 2018-06-28 12:27:41,622+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master'] (lvm:1291) 2018-06-28 12:27:41,623+0200 INFO (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master']) (lvm:1319) 2018-06-28 12:27:41,716+0200 INFO (monitor/68b8aaf) [storage.StorageDomain] Resource namespace 01_img_68b8aaff-770d-4a08-800b-0c15e94efaa8 already registered (sd:758) 2018-06-28 12:27:41,716+0200 INFO (monitor/68b8aaf) [storage.StorageDomain] Resource namespace 02_vol_68b8aaff-770d-4a08-800b-0c15e94efaa8 already registered (sd:767) 2018-06-28 12:27:41,716+0200 INFO (monitor/68b8aaf) [storage.StorageDomain] Resource namespace 03_lvm_68b8aaff-770d-4a08-800b-0c15e94efaa8 already registered (blockSD:989) 2018-06-28 12:27:47,784+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:27:47,809+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:27:49,415+0200 INFO (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=01be8d64-d54a-4c9d-979e-3971279eac9b (api:46) 2018-06-28 12:27:49,416+0200 INFO (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000291026', 'lastCheck': '2.6', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000573367', 'lastCheck': '5.4', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000457603', 'lastCheck': '5.6', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000393837', 'lastCheck': '5.2', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=01be8d64-d54a-4c9d-979e-3971279eac9b (api:52) 2018-06-28 12:27:49,435+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:27:49,896+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:27:49,897+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 120 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:27:52,532+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:27:56,181+0200 INFO (periodic/7093) [vdsm.api] START repoStats(options=None) from=internal, task_id=db929a1d-f13a-4ea3-89fb-4d8825204cac (api:46) 2018-06-28 12:27:56,182+0200 INFO (periodic/7093) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000398606', 'lastCheck': '5.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000667386', 'lastCheck': '2.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000471581', 'lastCheck': '2.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000276833', 'lastCheck': '2.0', 'valid': True}} from=internal, task_id=db929a1d-f13a-4ea3-89fb-4d8825204cac (api:52) 2018-06-28 12:27:59,899+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785) 2018-06-28 12:27:59,899+0200 INFO (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 130 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815) 2018-06-28 12:28:00,752+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['metadata'] (lvm:1291) 2018-06-28 12:28:00,752+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['metadata']) (lvm:1319) 2018-06-28 12:28:00,895+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['ids'] (lvm:1291) 2018-06-28 12:28:00,896+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['ids']) (lvm:1319) 2018-06-28 12:28:00,962+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['leases'] (lvm:1291) 2018-06-28 12:28:00,963+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['leases']) (lvm:1319) 2018-06-28 12:28:01,033+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master'] (lvm:1291) 2018-06-28 12:28:01,033+0200 INFO (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master']) (lvm:1319) 2018-06-28 12:28:01,113+0200 INFO (monitor/8924ce2) [storage.StorageDomain] Resource namespace 01_img_8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 already registered (sd:758) 2018-06-28 12:28:01,114+0200 INFO (monitor/8924ce2) [storage.StorageDomain] Resource namespace 02_vol_8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 already registered (sd:767) 2018-06-28 12:28:01,114+0200 INFO (monitor/8924ce2) [storage.StorageDomain] Resource namespace 03_lvm_8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 already registered (blockSD:989) 2018-06-28 12:28:02,822+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:28:02,848+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:28:04,455+0200 INFO (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=8d2d2379-1f5a-47a1-8b37-b922d13a02c6 (api:46) 2018-06-28 12:28:04,456+0200 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000321492', 'lastCheck': '3.9', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000650208', 'lastCheck': '0.5', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000296691', 'lastCheck': '0.7', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000362554', 'lastCheck': '0.2', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=8d2d2379-1f5a-47a1-8b37-b922d13a02c6 (api:52) 2018-06-28 12:28:04,473+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:28:07,585+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:28:09,902+0200 WARN (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') The migration took 140 seconds which is exceeding the configured maximum time for migrations of 131 seconds. The migration will be aborted. (migration:773) 2018-06-28 12:28:10,955+0200 ERROR (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Operation abgebrochen: Migrations-Job: abgebrochen durch Client (migration:287) 2018-06-28 12:28:11,174+0200 ERROR (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Failed to migrate (migration:429) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 411, in run self._startUnderlyingMigration(time.time()) File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 489, in _startUnderlyingMigration self._perform_with_downtime_thread(duri, muri) File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 556, in _perform_with_downtime_thread self._perform_migration(duri, muri) File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 529, in _perform_migration self._vm._dom.migrateToURI3(duri, params, flags) File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 69, in f ret = attr(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 123, in wrapper ret = f(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 1006, in wrapper return func(inst, *args, **kwargs) File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1679, in migrateToURI3 if ret == -1: raise libvirtError ('virDomainMigrateToURI3() failed', dom=self) libvirtError: Operation abgebrochen: Migrations-Job: abgebrochen durch Client 2 and vdsm.log from destination: 2018-06-28 12:25:01,919+0200 INFO (periodic/6162) [vdsm.api] START repoStats(options=None) from=internal, task_id=cb3869db-d960-49e0-ba4a-d726bf27539b (api:46) 2018-06-28 12:25:01,920+0200 INFO (periodic/6162) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000606644', 'lastCheck': '0.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000570293', 'lastCheck': '3.6', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000286344', 'lastCheck': '3.7', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000345685', 'lastCheck': '1.6', 'valid': True}} from=internal, task_id=cb3869db-d960-49e0-ba4a-d726bf27539b (api:52) 2018-06-28 12:25:04,109+0200 INFO (jsonrpc/0) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=dc938a7a-3c7a-40d3-9e06-7f712e7fc527 (api:46) 2018-06-28 12:25:04,110+0200 INFO (jsonrpc/0) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000606644', 'lastCheck': '2.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000570293', 'lastCheck': '5.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000286344', 'lastCheck': '5.9', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000345685', 'lastCheck': '3.7', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=dc938a7a-3c7a-40d3-9e06-7f712e7fc527 (api:52) 2018-06-28 12:25:04,157+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539) 2018-06-28 12:25:12,757+0200 INFO (jsonrpc/4) [vdsm.api] START setBalloonTarget(target=9874629) from=::1,46990 (api:46) 2018-06-28 12:25:12,774+0200 INFO (jsonrpc/4) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52) 2018-06-28 12:25:12,774+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:13,453+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:25:14,824+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:14,847+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:25:17,007+0200 INFO (periodic/6163) [vdsm.api] START repoStats(options=None) from=internal, task_id=3136344f-2e0d-4d0d-83a7-b6cd8809acbc (api:46) 2018-06-28 12:25:17,008+0200 INFO (periodic/6163) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000507353', 'lastCheck': '1.2', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000568841', 'lastCheck': '1.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000262659', 'lastCheck': '8.8', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000300632', 'lastCheck': '6.6', 'valid': True}} from=internal, task_id=3136344f-2e0d-4d0d-83a7-b6cd8809acbc (api:52) 2018-06-28 12:25:19,137+0200 INFO (jsonrpc/6) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=8c36bf93-c4b6-49a6-a019-82c02b98e03f (api:46) 2018-06-28 12:25:19,138+0200 INFO (jsonrpc/6) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000507353', 'lastCheck': '3.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000588412', 'lastCheck': '0.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000514061', 'lastCheck': '1.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000388286', 'lastCheck': '0.5', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=8c36bf93-c4b6-49a6-a019-82c02b98e03f (api:52) 2018-06-28 12:25:19,187+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539) 2018-06-28 12:25:27,960+0200 INFO (jsonrpc/1) [vdsm.api] START setBalloonTarget(target=9854363) from=::1,46990 (api:46) 2018-06-28 12:25:27,993+0200 INFO (jsonrpc/1) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52) 2018-06-28 12:25:27,994+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.03 seconds (__init__:539) 2018-06-28 12:25:28,530+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:29,870+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:29,914+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:25:32,113+0200 INFO (periodic/6162) [vdsm.api] START repoStats(options=None) from=internal, task_id=5c30fd65-66e8-4f36-b036-47bec09fd522 (api:46) 2018-06-28 12:25:32,114+0200 INFO (periodic/6162) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000500395', 'lastCheck': '0.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000620907', 'lastCheck': '3.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000339191', 'lastCheck': '3.9', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000404014', 'lastCheck': '1.7', 'valid': True}} from=internal, task_id=5c30fd65-66e8-4f36-b036-47bec09fd522 (api:52) 2018-06-28 12:25:34,151+0200 INFO (jsonrpc/5) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=9351125d-3a9e-4e22-9bdb-e86ed35032fd (api:46) 2018-06-28 12:25:34,151+0200 INFO (jsonrpc/5) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000500395', 'lastCheck': '2.8', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000620907', 'lastCheck': '5.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000339191', 'lastCheck': '6.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000404014', 'lastCheck': '3.8', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=9351125d-3a9e-4e22-9bdb-e86ed35032fd (api:52) 2018-06-28 12:25:34,198+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539) 2018-06-28 12:25:41,239+0200 INFO (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'6c94e2de-d65d-45f3-842e-68c006bc1a15', volUUID=u'70e61b28-fb15-4c0f-a425-bcbf8a506423', options=None) from=internal, task_id=d17b01b6-2321-49c9-a564-1689dacbae66 (api:46) 2018-06-28 12:25:41,240+0200 INFO (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '6442450944', 'apparentsize': '6442450944'} from=internal, task_id=d17b01b6-2321-49c9-a564-1689dacbae66 (api:52) 2018-06-28 12:25:41,241+0200 INFO (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'30e80e8a-a30d-4f4a-b593-d5df59acd6b9', volUUID=u'dc6b8058-895d-48c3-aff8-d381877a9904', options=None) from=internal, task_id=ca550e56-5d6c-4f71-aa82-f572feb23192 (api:46) 2018-06-28 12:25:41,241+0200 INFO (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=ca550e56-5d6c-4f71-aa82-f572feb23192 (api:52) 2018-06-28 12:25:41,242+0200 INFO (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'55a7014f-aaaa-4a48-8522-8d962fa3e37a', volUUID=u'd0a9a441-6c77-4539-8851-908e3d91331c', options=None) from=internal, task_id=633bf144-d519-42fc-949a-c3edab728255 (api:46) 2018-06-28 12:25:41,242+0200 INFO (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=633bf144-d519-42fc-949a-c3edab728255 (api:52) 2018-06-28 12:25:41,243+0200 INFO (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'0e3981b3-045b-4a66-a08e-b0bfccd81f5a', volUUID=u'acf2c734-b052-445b-98cc-e7f3eca8bd76', options=None) from=internal, task_id=8486f1b4-a8a8-4692-97ae-ea1c7f135758 (api:46) 2018-06-28 12:25:41,243+0200 INFO (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=8486f1b4-a8a8-4692-97ae-ea1c7f135758 (api:52) 2018-06-28 12:25:41,244+0200 INFO (periodic/6160) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'df435578-a524-4cd8-9b3d-74f36c4b182f', volUUID=u'd971520b-464b-4939-bff8-562572e9a439', options=None) from=internal, task_id=bc538510-62f6-4eba-bcb6-bbd1088b3673 (api:46) 2018-06-28 12:25:41,244+0200 INFO (periodic/6160) [vdsm.api] FINISH getVolumeSize return={'truesize': '67645734912', 'apparentsize': '67645734912'} from=internal, task_id=bc538510-62f6-4eba-bcb6-bbd1088b3673 (api:52) 2018-06-28 12:25:41,245+0200 INFO (periodic/6160) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'b5ee85a6-eaef-4cc4-9506-8ccd540a03fb', volUUID=u'd9853bb2-54c3-44c7-be61-862484ed031d', options=None) from=internal, task_id=83653b45-6b15-485f-9c7a-65df75e1af8a (api:46) 2018-06-28 12:25:41,245+0200 INFO (periodic/6160) [vdsm.api] FINISH getVolumeSize return={'truesize': '215822106624', 'apparentsize': '215822106624'} from=internal, task_id=83653b45-6b15-485f-9c7a-65df75e1af8a (api:52) 2018-06-28 12:25:41,246+0200 INFO (periodic/6162) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'6f19ce7b-78d4-4c04-a9e7-97cf2667fbc1', volUUID=u'465e9ac1-08ee-48ec-9159-7dde0ae00499', options=None) from=internal, task_id=d761d21f-6513-4507-b22a-ec1ba4ad2c98 (api:46) 2018-06-28 12:25:41,247+0200 INFO (periodic/6162) [vdsm.api] FINISH getVolumeSize return={'truesize': '17179869184', 'apparentsize': '17179869184'} from=internal, task_id=d761d21f-6513-4507-b22a-ec1ba4ad2c98 (api:52) 2018-06-28 12:25:41,248+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'157e6919-01d1-47d6-b2e9-4934a5e2743b', volUUID=u'bbe845e7-5b64-4a78-8c9c-c078d23ea50e', options=None) from=internal, task_id=5fffe581-8293-492b-87ac-6b2ac99617b6 (api:46) 2018-06-28 12:25:41,248+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '21474836480', 'apparentsize': '21474836480'} from=internal, task_id=5fffe581-8293-492b-87ac-6b2ac99617b6 (api:52) 2018-06-28 12:25:41,249+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'3ec22ced-a137-4c4c-8fdc-80afedde01d3', volUUID=u'b8aeb887-cc52-4941-b91c-10673a772d60', options=None) from=internal, task_id=6a76cbaa-6704-4c6d-80cb-84a8b7381f92 (api:46) 2018-06-28 12:25:41,249+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=6a76cbaa-6704-4c6d-80cb-84a8b7381f92 (api:52) 2018-06-28 12:25:41,250+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'b9b990e3-abcd-49e0-a4be-fa4f2e3ab17d', volUUID=u'd4eb437e-4442-4469-a3b7-c33ce3ef0619', options=None) from=internal, task_id=87adcf3e-0e0e-4a8e-8912-6985b06b6ee6 (api:46) 2018-06-28 12:25:41,250+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '44023414784', 'apparentsize': '44023414784'} from=internal, task_id=87adcf3e-0e0e-4a8e-8912-6985b06b6ee6 (api:52) 2018-06-28 12:25:41,251+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'ac124e30-064b-4af2-a32b-dea3d9a492a9', volUUID=u'fa387755-b06a-4fda-ad19-6761a765e257', options=None) from=internal, task_id=183a7469-58d8-4cad-8c63-a24c00df50bc (api:46) 2018-06-28 12:25:41,251+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '47244640256', 'apparentsize': '47244640256'} from=internal, task_id=183a7469-58d8-4cad-8c63-a24c00df50bc (api:52) 2018-06-28 12:25:41,252+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'983a5eff-5a53-4677-9d9f-899e500f8535', volUUID=u'5769e03a-2df4-4514-9b93-859fe453e6f9', options=None) from=internal, task_id=b2d4c682-4ffd-46ab-bb2f-cf03edfb1325 (api:46) 2018-06-28 12:25:41,252+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '107374182400', 'apparentsize': '107374182400'} from=internal, task_id=b2d4c682-4ffd-46ab-bb2f-cf03edfb1325 (api:52) 2018-06-28 12:25:41,253+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'53152751-8ae3-4760-aabf-e5f7b0ec6434', volUUID=u'6ad3a22b-dc92-45f8-b06b-27d22ba79ad3', options=None) from=internal, task_id=692228d9-624b-45f0-b0da-08fda6b434cc (api:46) 2018-06-28 12:25:41,253+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '21474836480', 'apparentsize': '21474836480'} from=internal, task_id=692228d9-624b-45f0-b0da-08fda6b434cc (api:52) 2018-06-28 12:25:41,254+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'28aa3761-33d2-4824-b3bb-55fd93996582', volUUID=u'8b7c0a22-79de-4e36-9e8a-934aad6d4c7e', options=None) from=internal, task_id=95868d0a-2efc-44a7-b688-da156122ad38 (api:46) 2018-06-28 12:25:41,254+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=95868d0a-2efc-44a7-b688-da156122ad38 (api:52) 2018-06-28 12:25:41,255+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'c9366f52-f1a8-411a-8e0c-3fcb0da264eb', volUUID=u'841b22dd-0ba0-487f-9256-b2e481b4d92b', options=None) from=internal, task_id=211d11fb-dfeb-45d8-93a2-17f0e4289cd0 (api:46) 2018-06-28 12:25:41,255+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '26843545600', 'apparentsize': '26843545600'} from=internal, task_id=211d11fb-dfeb-45d8-93a2-17f0e4289cd0 (api:52) 2018-06-28 12:25:41,256+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'55d90f2e-05d0-4a17-b066-ef52d0f21469', volUUID=u'cf7c3c97-1a7c-4b54-a21d-8d3232fb1667', options=None) from=internal, task_id=e2b43a11-334e-4f30-a7de-b41ffe5ceb33 (api:46) 2018-06-28 12:25:41,257+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '32212254720', 'apparentsize': '32212254720'} from=internal, task_id=e2b43a11-334e-4f30-a7de-b41ffe5ceb33 (api:52) 2018-06-28 12:25:41,257+0200 INFO (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'4910730a-1537-4564-80fe-5df0eb9ca276', volUUID=u'77593d90-f216-492d-aced-264ba5c0632f', options=None) from=internal, task_id=e28bdb33-9438-414e-9b58-f4f81c117c34 (api:46) 2018-06-28 12:25:41,258+0200 INFO (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '17716740096', 'apparentsize': '17716740096'} from=internal, task_id=e28bdb33-9438-414e-9b58-f4f81c117c34 (api:52) 2018-06-28 12:25:43,195+0200 INFO (jsonrpc/7) [vdsm.api] START setBalloonTarget(target=9835175) from=::1,46990 (api:46) 2018-06-28 12:25:43,211+0200 INFO (jsonrpc/7) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52) 2018-06-28 12:25:43,212+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:25:43,595+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:44,923+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:25:44,945+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:25:47,193+0200 INFO (periodic/6163) [vdsm.api] START repoStats(options=None) from=internal, task_id=0676d13f-11b7-473d-8c58-157bec36772f (api:46) 2018-06-28 12:25:47,193+0200 INFO (periodic/6163) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000490941', 'lastCheck': '1.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00065911', 'lastCheck': '1.4', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000546678', 'lastCheck': '9.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000449752', 'lastCheck': '6.8', 'valid': True}} from=internal, task_id=0676d13f-11b7-473d-8c58-157bec36772f (api:52) 2018-06-28 12:25:48,932+0200 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from ::ffff:10.157.8.40:35732 (protocoldetector:72) 2018-06-28 12:25:48,941+0200 INFO (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from ::ffff:10.157.8.40:35732 (protocoldetector:127) 2018-06-28 12:25:48,942+0200 INFO (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompreactor:103) 2018-06-28 12:25:48,943+0200 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompreactor:132) 2018-06-28 12:25:49,169+0200 INFO (jsonrpc/2) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=8c64d73b-10e4-45f7-8c49-43f5e6e61ee5 (api:46) 2018-06-28 12:25:49,170+0200 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000490941', 'lastCheck': '3.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000692455', 'lastCheck': '0.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000301581', 'lastCheck': '1.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000362669', 'lastCheck': '0.6', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=8c64d73b-10e4-45f7-8c49-43f5e6e61ee5 (api:52) 2018-06-28 12:25:49,218+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539) 2018-06-28 12:25:49,233+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.ping succeeded in 0.00 seconds (__init__:539) 2018-06-28 12:25:49,276+0200 INFO (jsonrpc/4) [vdsm.api] START __init__(cif=<clientIF.clientIF object at 0x255ef10>, params={u'status': u'Up', u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.3.0', u'afterMigrationStatus': u'', u'enableGuestEvents': False, u'vmId': u'a54af7cd-3b89-43c1-82b3-ae0c08d103d3', u'elapsedTimeOffset': 791575.6959090233, u'guestDiskMapping': {u'1fe4d656-8f59-4221-a': {u'name': u'/dev/vda'}}, u'transparentHugePages': u'true', u'timeOffset': u'0', u'cpuType': u'Westmere', u'custom': {u'device_3b6d92fa-999b-40cf-883e-209fa76b1751device_8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920device_83fbbdab-d906-4629-9c6a-29fc59410630': u"VmDevice:{id='VmDeviceId:{deviceId='83fbbdab-d906-4629-9c6a-29fc59410630', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='unix', type='CHANNEL', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapsho tId='null', logicalName='null', hostDevice='null'}", u'device_3b6d92fa-999b-40cf-883e-209fa76b1751device_8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920device_83fbbdab-d906-4629-9c6a-29fc59410630device_4bec2c2b-442c-4a7a-9759-a7a13729bc90': u"VmDevice:{id='VmDeviceId:{deviceId='4bec2c2b-442c-4a7a-9759-a7a13729bc90', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='tablet', type='UNKNOWN', specParams='[]', address='{bus=0, type=usb, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='input0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}", u'device_3b6d92fa-999b-40cf-883e-209fa76b1751': u"VmDevice:{id='VmDeviceId:{deviceId='3b6d92fa-999b-40cf-883e-209fa76b1751', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='ide', type='CONTROLLER', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='n ull', logicalName='null', hostDevice='null'}", u'device_3b6d92fa-999b-40cf-883e-209fa76b1751device_8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920': u"VmDevice:{id='VmDeviceId:{deviceId='8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='unix', type='CHANNEL', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}"}, u'pauseCode': u'NOERR', u'migrationDest': u'libvirt', u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0,1', u'memory': u'2096'}], u'smp': u'2', u'vmType': u'kvm', u'smpThreadsPerCore': u'1', u'_srcDomXML': u'<domain type=\'kvm\' id=\'4108\'>\n <name>bbgpvmas108</name>\n <uuid>a54af7cd-3b89-43c1-82b3-ae0c08d103d3</uuid>\n <metadata xmlns:ovirt="http://ovirt.org/vm/tune/1.0">\n <ovirt:qos/>\n </metadata>\n <maxMemory slots=\'16\' unit=\'KiB\'>8585216</maxM emory>\n <memory unit=\'KiB\'>2146304</memory>\n <currentMemory unit=\'KiB\'>2146304</currentMemory>\n <vcpu placement=\'static\' current=\'2\'>16</vcpu>\n <cputune>\n <shares>1020</shares>\n </cputune>\n <resource>\n <partition>/machine</partition>\n </resource>\n <sysinfo type=\'smbios\'>\n <system>\n <entry name=\'manufacturer\'>oVirt</entry>\n <entry name=\'product\'>oVirt Node</entry>\n <entry name=\'version\'>7-4.1708.el7.centos</entry>\n <entry name=\'serial\'>DF14F0EB-EAAF-33CB-BC4A-4D90DE3A5EEB</entry>\n <entry name=\'uuid\'>a54af7cd-3b89-43c1-82b3-ae0c08d103d3</entry>\n </system>\n </sysinfo>\n <os>\n <type arch=\'x86_64\' machine=\'pc-i440fx-rhel7.3.0\'>hvm</type>\n <smbios mode=\'sysinfo\'/>\n </os>\n <features>\n <acpi/>\n </features>\n <cpu mode=\'custom\' match=\'exact\' check=\'full\'>\n <model fallback=\'forbid\'>Westmere</model>\n <topology sockets=\'16\' cores=\'1\' threads=\'1\'/>\n <feature pol icy=\'require\' name=\'vme\'/>\n <feature policy=\'require\' name=\'pclmuldq\'/>\n <feature policy=\'require\' name=\'x2apic\'/>\n <feature policy=\'require\' name=\'hypervisor\'/>\n <feature policy=\'require\' name=\'arat\'/>\n <numa>\n <cell id=\'0\' cpus=\'0-1\' memory=\'2146304\' unit=\'KiB\'/>\n </numa>\n </cpu>\n <clock offset=\'variable\' adjustment=\'0\' basis=\'utc\'>\n <timer name=\'rtc\' tickpolicy=\'catchup\'/>\n <timer name=\'pit\' tickpolicy=\'delay\'/>\n <timer name=\'hpet\' present=\'no\'/>\n </clock>\n <on_poweroff>destroy</on_poweroff>\n <on_reboot>restart</on_reboot>\n <on_crash>destroy</on_crash>\n <devices>\n <emulator>/usr/libexec/qemu-kvm</emulator>\n <disk type=\'file\' device=\'cdrom\'>\n <driver name=\'qemu\' type=\'raw\'/>\n <source startupPolicy=\'optional\'/>\n <backingStore/>\n <target dev=\'hdc\' bus=\'ide\'/>\n <readonly/>\n <alias name=\'ide0-1-0\'/>\n <address type=\'dri ve\' controller=\'0\' bus=\'1\' target=\'0\' unit=\'0\'/>\n </disk>\n <disk type=\'block\' device=\'disk\' snapshot=\'no\'>\n <driver name=\'qemu\' type=\'raw\' cache=\'none\' error_policy=\'stop\' io=\'native\'/>\n <source dev=\'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289\'/>\n <backingStore/>\n <target dev=\'vda\' bus=\'virtio\'/>\n <serial>1fe4d656-8f59-4221-a859-2f7bcbdb43c3</serial>\n <boot order=\'1\'/>\n <alias name=\'virtio-disk0\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x05\' function=\'0x0\'/>\n </disk>\n <controller type=\'usb\' index=\'0\' model=\'piix3-uhci\'>\n <alias name=\'usb\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x01\' function=\'0x2\'/>\n </controller>\n <controller type=\'virtio-serial\' index=\'0\' ports=\'16\'>\n <alias name=\'virtio-serial0\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x04\' function=\'0x0\'/>\n </controller>\n <controller type=\'pci\' index=\'0\' model=\'pci-root\'>\n <alias name=\'pci.0\'/>\n </controller>\n <controller type=\'ide\' index=\'0\'>\n <alias name=\'ide\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x01\' function=\'0x1\'/>\n </controller>\n <interface type=\'bridge\'>\n <mac address=\'00:16:36:4f:bd:df\'/>\n <source bridge=\'VMs\'/>\n <target dev=\'vnet16\'/>\n <model type=\'virtio\'/>\n <filterref filter=\'vdsm-no-mac-spoofing\'/>\n <link state=\'up\'/>\n <alias name=\'net0\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x03\' function=\'0x0\'/>\n </interface>\n <interface type=\'bridge\'>\n <mac address=\'00:1a:4a:bd:ed:22\'/>\n <source bridge=\'Backup\'/>\n <target dev=\'vnet17\'/>\n <model t ype=\'virtio\'/>\n <filterref filter=\'vdsm-no-mac-spoofing\'/>\n <link state=\'up\'/>\n <alias name=\'net1\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x07\' function=\'0x0\'/>\n </interface>\n <channel type=\'unix\'>\n <source mode=\'bind\' path=\'/var/lib/libvirt/qemu/channels/a54af7cd-3b89-43c1-82b3-ae0c08d103d3.com.redhat.rhevm.vdsm\'/>\n <target type=\'virtio\' name=\'com.redhat.rhevm.vdsm\' state=\'connected\'/>\n <alias name=\'channel0\'/>\n <address type=\'virtio-serial\' controller=\'0\' bus=\'0\' port=\'1\'/>\n </channel>\n <channel type=\'unix\'>\n <source mode=\'bind\' path=\'/var/lib/libvirt/qemu/channels/a54af7cd-3b89-43c1-82b3-ae0c08d103d3.org.qemu.guest_agent.0\'/>\n <target type=\'virtio\' name=\'org.qemu.guest_agent.0\' state=\'disconnected\'/>\n <alias name=\'channel1\'/>\n <address type=\'virtio-serial\' controller=\'0\' bus=\'0\' port=\'2\'/>\n </channel>\n <inpu t type=\'tablet\' bus=\'usb\'>\n <alias name=\'input0\'/>\n <address type=\'usb\' bus=\'0\' port=\'1\'/>\n </input>\n <input type=\'mouse\' bus=\'ps2\'>\n <alias name=\'input1\'/>\n </input>\n <input type=\'keyboard\' bus=\'ps2\'>\n <alias name=\'input2\'/>\n </input>\n <graphics type=\'vnc\' port=\'5907\' autoport=\'yes\' listen=\'10.157.8.40\' keymap=\'de\' passwdValidTo=\'1970-01-01T00:00:01\'>\n <listen type=\'network\' address=\'10.157.8.40\' network=\'vdsm-ovirtmgmt\'/>\n </graphics>\n <video>\n <model type=\'vga\' vram=\'16384\' heads=\'1\' primary=\'yes\'/>\n <alias name=\'video0\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x02\' function=\'0x0\'/>\n </video>\n <memballoon model=\'virtio\'>\n <alias name=\'balloon0\'/>\n <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x06\' function=\'0x0\'/>\n </memballoon>\n </devices>\n <seclabel type=\'dynamic\' model=\ 'selinux\' relabel=\'yes\'>\n <label>system_u:system_r:svirt_t:s0:c76,c549</label>\n <imagelabel>system_u:object_r:svirt_image_t:s0:c76,c549</imagelabel>\n </seclabel>\n <seclabel type=\'dynamic\' model=\'dac\' relabel=\'yes\'>\n <label>+107:+107</label>\n <imagelabel>+107:+107</imagelabel>\n </seclabel>\n</domain>\n', u'memSize': 2096, u'smpCoresPerSocket': u'1', u'vmName': u'bbgpvmas108', u'nice': u'0', u'username': u'None', u'maxMemSize': 8384, u'bootMenuEnable': u'false', u'tabletEnable': u'true', u'smartcardEnable': u'false', u'clientIp': u'', u'guestFQDN': u'bbgpvmas108-test.bbg.michelin.com', u'guestAgentAPIVersion': 1, u'kvmEnable': u'true', u'pitReinjection': u'false', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'target': 2146304, u'alias': u'balloon0', u'specParams': {u'model': u'virtio'}, u'deviceId': u'046ac3a6-864d-4d70-9822-484c99b833e5', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x06'}, u'de vice': u'memballoon', u'type': u'balloon'}, {u'index': u'0', u'alias': u'usb', u'specParams': {}, u'deviceId': u'a24b60c7-dbd0-416d-8791-43e101aeaccb', u'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}, u'device': u'usb', u'model': u'piix3-uhci', u'type': u'controller'}, {u'alias': u'virtio-serial0', u'specParams': {}, u'deviceId': u'c17ebc13-fa7e-4308-937d-77c5e5d4dda9', u'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'virtio-serial', u'type': u'controller'}, {u'alias': u'video0', u'specParams': {u'vram': u'16384'}, u'deviceId': u'240119c6-b3c2-4d08-881b-39ff6fd8ff16', u'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'vga', u'type': u'video'}, {u'device': u'vnc', u'specParams': {u'displayNetwork': u'ovirtmgmt', u'keyMap': u'de', u'displayIp': u'10.157.8.40'}, u'type': u'graphics', u 'deviceId': u'00000026-0026-0026-0026-000000000175', u'port': u'5907'}, {u'nicModel': u'pv', u'macAddr': u'00:16:36:4f:bd:df', u'linkActive': True, u'network': u'VMs', u'filterParameters': [], u'alias': u'net0', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, u'deviceId': u'f4a97f85-b60b-4989-81c0-0b3dc1a25be4', u'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface', u'name': u'vnet16'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:bd:ed:22', u'linkActive': True, u'network': u'Backup', u'filterParameters': [], u'alias': u'net1', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, u'deviceId': u'84ce9f2d-fe1b-4529-9998-27d44573947f', u'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface', u'name': u'vnet17'}, {u'index': u '2', u'iface': u'ide', u'name': u'hdc', u'alias': u'ide0-1-0', u'specParams': {u'path': u''}, u'readonly': u'True', u'deviceId': u'd9cd7283-a7df-493f-8903-295baf2c8f37', u'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'cdrom', u'shared': u'false', u'path': u'', u'type': u'disk'}, {u'poolID': u'5849b030-626e-47cb-ad90-3ce782d831b3', u'volumeInfo': {u'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'volType': u'path'}, u'index': 0, u'iface': u'virtio', u'apparentsize': u'53687091200', u'alias': u'virtio-disk0', u'imageID': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', u'readonly': u'False', u'shared': u'false', u'truesize': u'53687091200', u'type': u'disk', u'domainID': u'68b8aaff-770d-4a08-800b-0c15e94efaa8', u'reqsize': u'0', u'format': u'raw', u'deviceId': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', u'address': {u'sl ot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'disk', u'path': u'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'propagateErrors': u'off', u'optional': u'false', u'name': u'vda', u'bootOrder': u'1', u'volumeID': u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'diskType': u'block', u'specParams': {}, u'discard': False, u'volumeChain': [{u'domainID': u'68b8aaff-770d-4a08-800b-0c15e94efaa8', u'leaseOffset': 164626432, u'volumeID': u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'leasePath': u'/dev/68b8aaff-770d-4a08-800b-0c15e94efaa8/leases', u'imageID': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', u'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289'}]}, {u'device': u'ide', u'alias': u'ide', u'type': u'controller ', u'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {u'device': u'unix', u'alias': u'channel0', u'type': u'channel', u'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'1'}}, {u'device': u'unix', u'alias': u'channel1', u'type': u'channel', u'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'2'}}, {u'device': u'tablet', u'alias': u'input0', u'type': u'input', u'address': {u'bus': u'0', u'type': u'usb', u'port': u'1'}}], u'memGuaranteedSize': 1024, u'maxVCpus': u'16', u'guestIPs': u'10.157.11.88', u'statusTime': u'12083235990', u'maxMemSlots': 16}, recover=False) from=::ffff:10.157.8.40,35732 (api:46) 2018-06-28 12:25:49,278+0200 INFO (jsonrpc/4) [vdsm.api] FINISH __init__ return=None from=::ffff:10.157.8.40,35732 (api:52) 2018-06-28 12:25:49,281+0200 INFO (vm/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') VM wrapper has started (vm:1968) 2018-06-28 12:25:49,282+0200 WARN (vm/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Unknown type found, device: '{u'device': u'tablet', u'alias': u'input0', u'type': u'input', u'address': {u'bus': u'0', u'type': u'usb', u'port': u'1'}}' found (vm:452) 2018-06-28 12:25:49,282+0200 INFO (vm/a54af7cd) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', volUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', options=None) from=internal, task_id=83e1bc92-a406-4b05-abc1-ef6c476435e5 (api:46) 2018-06-28 12:25:49,354+0200 INFO (vm/a54af7cd) [vdsm.api] FINISH getVolumeSize return={'truesize': '53687091200', 'apparentsize': '53687091200'} from=internal, task_id=83e1bc92-a406-4b05-abc1-ef6c476435e5 (api:52) 2018-06-28 12:25:49,355+0200 INFO (vm/a54af7cd) [vds] prepared volume path: (clientIF:380) 2018-06-28 12:25:49,356+0200 INFO (vm/a54af7cd) [vdsm.api] START prepareImage(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', leafUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', allowIllegal=False) from=internal, task_id=186f0bc0-58e0-48a6-b0bc-c7b9b7dfb19e (api:46) 2018-06-28 12:25:49,428+0200 INFO (vm/a54af7cd) [storage.LVM] Activating lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['fbbd2aac-cb7a-471b-b95f-270ce6d00289'] (lvm:1295) 2018-06-28 12:25:49,720+0200 INFO (vm/a54af7cd) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['leases'] (lvm:1291) 2018-06-28 12:25:49,720+0200 INFO (vm/a54af7cd) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['leases']) (lvm:1319) 2018-06-28 12:25:49,812+0200 INFO (vm/a54af7cd) [vdsm.api] FINISH prepareImage return={'info': {'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'volType': 'path'}, 'path': u'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'imgVolumesInfo': [{'domainID': u'68b8aaff-770d-4a08-800b-0c15e94efaa8', 'leaseOffset': 164626432, 'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'volumeID': 'fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'leasePath': '/dev/68b8aaff-770d-4a08-800b-0c15e94efaa8/leases', 'imageID': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3'}]} from=internal, task_id=186f0bc0-58e0-48a6-b0bc-c7b9b7dfb19e (api:52) 2018-06-28 12:25:49,814+0200 INFO (vm/a54af7cd) [vds] prepared volume path: /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289 (clientIF:380) 2018-06-28 12:25:49,857+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call VM.migrationCreate succeeded in 0.60 seconds (__init__:539) 2018-06-28 12:25:55,791+0200 INFO (itmap/0) [IOProcessClient] Starting client ioprocess-78498 (__init__:330) 2018-06-28 12:25:55,803+0200 INFO (ioprocess/3512) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:25:55,804+0200 INFO (itmap/1) [IOProcessClient] Starting client ioprocess-78499 (__init__:330) 2018-06-28 12:25:55,812+0200 INFO (itmap/2) [IOProcessClient] Starting client ioprocess-78500 (__init__:330) 2018-06-28 12:25:55,817+0200 INFO (ioprocess/3527) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:25:55,822+0200 INFO (ioprocess/3533) [IOProcess] Starting ioprocess (__init__:452) 2018-06-28 12:25:55,832+0200 INFO (monitor/48055e2) [storage.StorageDomain] Resource namespace 01_img_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:758) 2018-06-28 12:25:55,832+0200 INFO (monitor/48055e2) [storage.StorageDomain] Resource namespace 02_vol_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:767) 2018-06-28 12:25:55,836+0200 INFO (monitor/b5ae41a) [storage.StorageDomain] Resource namespace 01_img_b5ae41ac-7318-4748-9346-b08d8e5a9248 already registered (sd:758) 2018-06-28 12:25:55,836+0200 INFO (monitor/b5ae41a) [storage.StorageDomain] Resource namespace 02_vol_b5ae41ac-7318-4748-9346-b08d8e5a9248 already registered (sd:767) 2018-06-28 12:25:58,400+0200 INFO (jsonrpc/5) [vdsm.api] START setBalloonTarget(target=9817245) from=::1,46990 (api:46) 2018-06-28 12:25:58,417+0200 INFO (jsonrpc/5) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52) 2018-06-28 12:25:58,417+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:58,658+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539) 2018-06-28 12:25:59,959+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539) 2018-06-28 12:25:59,979+0200 ERROR (jsonrpc/6) [jsonrpc.JsonRpcServer] Internal server error (__init__:577) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 572, in _handle_request res = method(**params) File "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 202, in _dynamicMethod result = fn(*methodArgs) File "/usr/share/vdsm/API.py", line 1454, in getAllVmIoTunePolicies io_tune_policies_dict = self._cif.getAllVmIoTunePolicies() File "/usr/share/vdsm/clientIF.py", line 454, in getAllVmIoTunePolicies 'current_values': v.getIoTune()} File "/usr/share/vdsm/virt/vm.py", line 2859, in getIoTune result = self.getIoTuneResponse() File "/usr/share/vdsm/virt/vm.py", line 2878, in getIoTuneResponse res = self._dom.blockIoTune( File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 47, in __getattr__ % self.vmid) NotConnectedError: VM u'a54af7cd-3b89-43c1-82b3-ae0c08d103d3' was not started yet or was shut down 2018-06-28 12:25:59,981+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies failed (error -32603) in 0.00 seconds (__init__:539) 2018-06-28 12:26:02,275+0200 INFO (periodic/6160) [vdsm.api] START repoStats(options=None) from=internal, task_id=0fc8eaea-80b5-4a7d-aa70-78681613e5c6 (api:46) 2018-06-28 12:26:02,276+0200 INFO (periodic/6160) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000506027', 'lastCheck': '0.9', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000616951', 'lastCheck': '4.0', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000293051', 'lastCheck': '4.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000381327', 'lastCheck': '1.9', 'valid': True}} from=internal, task_id=0fc8eaea-80b5-4a7d-aa70-78681613e5c6 (api:52)
On 06/28/2018 02:18 AM, Michal Skrivanek wrote:
On 27 Jun 2018, at 16:47, Michael Watters <wattersm@watters.ws> wrote:
Having the same issue after upgrading from ovirt 4.1 to 4.2.4. Attempting to migrate any VM results in an immediate failure. The engine log shows an error as follows.
2018-06-27 10:43:59,815-04 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-3) [] Migration of VM 'ASAP' to host 'ovirt-node-production1' failed: VM destroyed during the startup. 2018-06-27 10:43:59,819-04 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] VM '91be7864-3793-4583-accb-31b441af7b6a'(ASAP) moved from 'MigratingFrom' --> ‘Up' please include vdsm.logs from source and destination hypervisors
Thanks, michal
No problem. Here are links to the logs as requested. source: https://paste.fedoraproject.org/paste/hWJBUrVhitOS1jQdkNF6yA destination: https://paste.fedoraproject.org/paste/0jdIJp~uOa3sgMbrly33NA I believe the issue may be related to this error. Any idea what would cause this? libvirtError: The name org.fedoraproject.FirewallD1 was not provided by any .service files
On 06/28/2018 02:18 AM, Michal Skrivanek wrote:
On 27 Jun 2018, at 16:47, Michael Watters <wattersm@watters.ws> wrote:
Having the same issue after upgrading from ovirt 4.1 to 4.2.4. Attempting to migrate any VM results in an immediate failure. The engine log shows an error as follows.
2018-06-27 10:43:59,815-04 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-3) [] Migration of VM 'ASAP' to host 'ovirt-node-production1' failed: VM destroyed during the startup. 2018-06-27 10:43:59,819-04 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] VM '91be7864-3793-4583-accb-31b441af7b6a'(ASAP) moved from 'MigratingFrom' --> ‘Up' please include vdsm.logs from source and destination hypervisors
Thanks, michal
I've also noticed that libvirtd is reporting errors. [root@mdct-ovirt-node-production1 ~]# systemctl status -l libvirtd ● libvirtd.service - Virtualization daemon Loaded: loaded (/usr/lib/systemd/system/libvirtd.service; enabled; vendor preset: enabled) Drop-In: /etc/systemd/system/libvirtd.service.d └─unlimited-core.conf Active: active (running) since Thu 2018-06-28 09:37:08 EDT; 2h 30min ago Docs: man:libvirtd(8) https://libvirt.org Main PID: 2402 (libvirtd) Tasks: 19 (limit: 32768) CGroup: /system.slice/libvirtd.service ├─2402 /usr/sbin/libvirtd --listen ├─2738 /usr/sbin/dnsmasq --conf-file=/var/lib/libvirt/dnsmasq/default.conf --leasefile-ro --dhcp-script=/usr/libexec/libvirt_leaseshelper └─2739 /usr/sbin/dnsmasq --conf-file=/var/lib/libvirt/dnsmasq/default.conf --leasefile-ro --dhcp-script=/usr/libexec/libvirt_leaseshelper Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.283+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.285+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.288+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.290+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.292+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.294+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.296+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.297+0000: 2474: warning : virObjectGetLockableObj:399 : Object cannot be NULL Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.297+0000: 2474: error : qemuMonitorGetMigrationParams:2609 : invalid argument: monitor must not be NULL Jun 28 11:40:51 mdct-ovirt-node-production1.example.com libvirtd[2402]: 2018-06-28 15:40:51.298+0000: 2651: error : virNetDevSendEthtoolIoctl:3029 : ethtool ioctl error: No such device
On Tue, Jun 19, 2018 at 11:39 AM <rni@chef.net> wrote:
Hello,
I'm using a 4 node cluster oVirt 4.1. After updating the Engine to 4.2.3.8 (and ContOS 7.5), I tried to update the nodes too. Unfortunally, the live migration is not working (any more). Maybe it's related to following error found in engine.log
2018-06-19 09:32:53,469+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-19 09:32:53,475+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [4d6a7dc4] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050)
Didi, do have an idea what can be the issue?
I'm using the selfsigned CA provided with oVirt.
Nodes (source and destination) OS-Version:RHEL - 7 - 4.1708.el7.centos Kernelversion: 3.10.0 - 693.21.1.el7.x86_64 KVM-Version:2.9.0 - 16.el7_4.14.1 LIBVIRT-Version:libvirt-3.2.0-14.el7_4.9 VDSM-Version:vdsm-4.19.45-1.el7.centos SPICE-Version:0.12.8 - 2.el7.1 CEPH-Version:librbd1-0.94.5-2.el7 Kernel Features:PTI: 1, IBPB: 0, IBRS: 0
engine.log for the mirgration: 2018-06-14 13:13:30,300+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-246968) [] EVENT_ID: VM_MIGRATION_START_SYSTEM_INITIATED(67), Migration initiated by system (VM: vm_to_migrate, Source: SOURCE, Destination: DESTINATION, Reason: Host preparing for maintenance). 2018-06-14 13:13:32,886+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmsStatisticsFetcher] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] Fetched 8 VMs from VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498' 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:32,887+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:13:47,939+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-42) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:02,993+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:18,042+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-67) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:33,090+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:14:38,356+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock Acquired to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:38,369+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Running command: SyncNetworkProviderCommand internal: true. 2018-06-14 13:14:38,370+02 WARN [org.ovirt.engine.core.bll.provider.network.openstack.CustomizedRESTEasyConnector] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Cannot register external providers trust store: java.io.IOException: Keystore was tampered with, or password was incorrect 2018-06-14 13:14:38,379+02 ERROR [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Command 'org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand' failed: EngineException: (Failed with error unable to find valid certification path to requested target and code 5050) 2018-06-14 13:14:38,382+02 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [6d991f10] Lock freed to object 'EngineLock:{exclusiveLocks='[d1457e7e-f29d-49ac-b635-2457a7cbc59f=PROVIDER]', sharedLocks=''}' 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:14:48,139+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:03,193+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:18,242+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) was unexpectedly detected as 'MigratingTo' on VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) (expected on 'ea7bae8f-d966-4baa-b8b4-a5522b88ec3a') 2018-06-14 13:15:33,293+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111' is migrating to VDS 'f3749f1e-a68d-424f-aa3a-f0ec996df498'(DESTINATION) ignoring it in the refresh until migration is done 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) moved from 'MigratingFrom' --> 'Up' 2018-06-14 13:15:45,377+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Adding VM '4aff4193-ba75-481d-92b3-59b62cd8b111'(vm_to_migrate) to re-run list 2018-06-14 13:15:45,400+02 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmsMonitoring] (EE-ManagedThreadFactory-engineScheduled-Thread-10) [] Rerun VM '4aff4193-ba75-481d-92b3-59b62cd8b111'. Called from VDS 'SOURCE' 2018-06-14 13:15:45,451+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateStatusVDSCommand(HostName = SOURCE, MigrateStatusVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111'}), log id: 25f95334 2018-06-14 13:15:45,453+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateStatusVDSCommand, log id: 25f95334 2018-06-14 13:15:45,478+02 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-247023) [] EVENT_ID: VM_MIGRATION_TRYING_RERUN(128), Failed to migrate VM vm_to_migrate to Host DESTINATION . Trying to migrate to another Host. 2018-06-14 13:15:45,557+02 INFO [org.ovirt.engine.core.bll.MigrateVmCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] Running command: MigrateVmCommand internal: true. Entities affected : ID: 4aff4193-ba75-481d-92b3-59b62cd8b111 Type: VMAction group MIGRATE_VM with role type USER 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateVDSCommand( MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost=' 10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 736d023f 2018-06-14 13:15:45,595+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] START, MigrateBrokerVDSCommand(HostName = SOURCE, MigrateVDSCommandParameters:{hostId='ea7bae8f-d966-4baa-b8b4-a5522b88ec3a', vmId='4aff4193-ba75-481d-92b3-59b62cd8b111', srcHost='10.157.8.37', dstVdsId='69ebacd7-ee55-4c52-abf1-437a14d5fb0d', dstHost=' 10.157.8.42:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='false', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='false', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='null', dstQemu='192.168.1.113'}), log id: 58572c5b 2018-06-14 13:15:45,601+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateBrokerVDSCommand, log id: 58572c5b 2018-06-14 13:15:45,604+02 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-247023) [] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 736d023f
_______________________________________________ Users mailing list -- users@ovirt.org To unsubscribe send an email to users-leave@ovirt.org Privacy Statement: https://www.ovirt.org/site/privacy-policy/ oVirt Code of Conduct: https://www.ovirt.org/community/about/community-guidelines/ List Archives: https://lists.ovirt.org/archives/list/users@ovirt.org/message/B6IEVX5XEBFHJC...
participants (4)
-
Michael Watters -
Michal Skrivanek -
Nir Soffer -
rni＠chef.net