Bug 1406283

It's not 100% reproducible.

We must see engine and vdsm log to tell if Engine "forgot" to require a re-plug, or vdsm failed to comply, and understand why.

For example, if the guest was not running, what you see is the expected behavior.

I would increase the priority of the bug when the required info is available.

Guest was running.

Time in logs 2016-12-20 10:27:44,708+02

Created attachment 1233750 [details]
Logs

I think you've attached only the source vdsm log:
2016-12-20 10:27:39,043 INFO  (jsonrpc/0) [vdsm.api] FINISH hotunplugNic 

could you add the one on the destination?

I attached the destination vdsm log

Created attachment 1233893 [details]
vdsm logs_source and destination

I wasn't able to reproduce. Reading logs it seems that your system tried to plug back. If you don't want to read all these findings, please scroll entirelly down, and invoke sql query for me. Thanks.

About provided error message: Listing in comment one ins't root cause or this error (which is probably irrelevant to nic not being plugged back) root cause is this, which happens moment before:


INFO  [org.ovirt.engine.core.bll.network.host.RefreshHostCommand] (org.ovirt.thread.pool-6-thread-37) [6e534471] Running command: RefreshHostCommand internal: true. Entities affected :  ID: 9a65b250-6e4f-46fc-8284-ecafc8f6d914 Type: VDSAction group MANIPULATE_HOST with role type ADMIN
2016-12-20 10:13:58,114+02 INFO  [org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (org.ovirt.thread.pool-6-thread-37) [75ec506f] Failed to Acquire Lock to object 'EngineLock:{exclusiveLocks='[9a65b250-6e4f-46fc-8284-ecafc8f6d914=<VDS, ACTION_TYPE_FAILED_OBJECT_LOCKED>, HOST_NETWORK9a65b250-6e4f-46fc-8284-ecafc8f6d914=<HOST_NETWORK, ACTION_TYPE_FAILED_SETUP_NETWORKS_OR_REFRESH_IN_PROGRESS>]', sharedLocks='null'}'
2016-12-20 10:13:58,115+02 WARN  [org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (org.ovirt.thread.pool-6-thread-37) [75ec506f] Validation of action 'RefreshHostCapabilities' failed for user SYSTEM. Reasons: VAR__ACTION__REFRESH,VAR__TYPE__HOST_CAPABILITIES,ACTION_TYPE_FAILED_OBJECT_LOCKED
2016-12-20 10:13:58,200+02 ERROR [org.ovirt.engine.core.bll.network.host.RefreshHostCommand] (org.ovirt.thread.pool-6-thread-37) [75ec506f] Transaction rolled-back for command 'org.ovirt.engine.core.bll.network.host.RefreshHostCommand'.


unplugging nics work this way: first is nic unplugged, then is updated vmdevice in-memory instance (it was queried from db before unplugging), then is called RefreshHostCommand (which is refresh caps followed by refreshHostDevices), note: this stage failed for you, and after that we're updating vmdevice record with one stored in memory. 

So:
1. refresh capabilities wasn't invoked, as it's validation phase failed to get lock (see: org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand#getExclusiveLocks) Because of that, refreshHostDevices wasn't invoked. And because of that, _probably_ respective device wasn't removed from DB and later on monitoring complaints about it. The true reason so seems to be lock being hold by someone, probably setupnetworkscommand.

2. it feels very weird, that we query db record, store it in memory, then update  host vmdevices, and then we're trying to update record, which might not exist. That's a little bit troubling in principle, but maybe it cannot introduce any error, I need to check it. But by design it does not look nice. In relation to point one, given device probably should have been deleted (but it wasn't, and that's causing problems), but if that's true, I don't know what we're normally updating as if everything goes OK, the record is deleted.

3. BUT even if I let fail validation phase of RefreshHostCapabilitiesCommand, nic were plugged back on my setup.

———
I need to investigate more:
a. i need to find out, how db changes after nic is unplugged during refreshHostDevices. This may shed some light on updating device after all of them are refreshed.
b. find out, why lock acquisition failed.

———

Back to not replugged nics: looking more into your logs it seems, that there was effort of plugging nics back. See:

2016-12-20 10:13:47,247+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnplugNicVDSCommand] (org.ovirt.thread.pool-6-thread-14) [34689a8d] START, HotUnplugNicVDSCommand(HostName = puma22.scl.lab.tlv.redhat.com, VmNicDeviceVDSParameters:{runAsync='true', hostId='16cdcc69-fea0-484c-830e-4760cd709d5b', vm.vm_name='t1', nic='VmNetworkInterface:{id='b72d8f09-8421-43fb-91f0-e3be2c3a8a59', networkName='sr1', vnicProfileName='sr1', vnicProfileId='742ab583-64b4-49ed-b0ff-4a71b473298e', speed='1000', type='5', macAddress='00:00:00:00:00:5b', active='true', linked='true', portMirroring='false', vmId='490f7b83-d2d5-4f60-87d0-4fb5e8842ec5', vmName='t1', vmTemplateId='null', QoSName='null', remoteNetworkName='null'}', vmDevice='VmDevice:{id='VmDeviceId:{deviceId='b72d8f09-8421-43fb-91f0-e3be2c3a8a59', vmId='490f7b83-d2d5-4f60-87d0-4fb5e8842ec5'}', device='hostdev', type='INTERFACE', bootOrder='0', specParams='[]', address='{slot=0x04, bus=0x00, domain=0x0000, type=pci, function=0x0}', managed='true', plugged='true', readOnly='false', deviceAlias='hostdev0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='pci_0000_05_10_0'}'}), log id: 7ece6ce2

2016-12-20 10:13:48,438+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnplugNicVDSCommand] (org.ovirt.thread.pool-6-thread-14) [34689a8d] FINISH, HotUnplugNicVDSCommand, log id: 7ece6ce2

2016-12-20 10:13:50,812+02 INFO  [org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (org.ovirt.thread.pool-6-thread-14) [15b18bde] Refresh host capabilities finished. Lock released. Monitoring can run now for host 'puma22.scl.lab.tlv.redhat.com' from data-center 'DC1'

2016-12-20 10:13:51,595+02 INFO  [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-14) [74927c5d] START, MigrateVDSCommand( MigrateVDSCommandParameters:{runAsync='true', hostId='16cdcc69-fea0-484c-830e-4760cd709d5b', vmId='490f7b83-d2d5-4f60-87d0-4fb5e8842ec5', srcHost='puma22.scl.lab.tlv.redhat.com', dstVdsId='9a65b250-6e4f-46fc-8284-ecafc8f6d914', dstHost='puma25.scl.lab.tlv.redhat.com:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='true', migrateCompressed='false', consoleAddress='null', maxBandwidth='5000', enableGuestEvents='true', convergenceSchedule='[init=[{name=setDowntime, params=[100]}], stalling=[{limit=1, action={name=setDowntime, params=[150]}}, {limit=2, action={name=setDowntime, params=[200]}}, {limit=3, action={name=setDowntime, params=[300]}}, {limit=4, action={name=setDowntime, params=[400]}}, {limit=6, action={name=setDowntime, params=[500]}}, {limit=-1, action={name=abort, params=[]}}]]'}), log id: 764e6739

2016-12-20 10:13:53,067+02 INFO  [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-14) [74927c5d] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 764e6739

2016-12-20 10:23:33,827+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotPlugNicVDSCommand] (default task-6) [400b2bd] START, HotPlugNicVDSCommand(HostName = puma25.scl.lab.tlv.redhat.com, VmNicDeviceVDSParameters:{runAsync='true', hostId='9a65b250-6e4f-46fc-8284-ecafc8f6d914', vm.vm_name='t1', nic='VmNetworkInterface:{id='b72d8f09-8421-43fb-91f0-e3be2c3a8a59', networkName='sr1', vnicProfileName='null', vnicProfileId='742ab583-64b4-49ed-b0ff-4a71b473298e', speed='1000', type='5', macAddress='00:00:00:00:00:5b', active='true', linked='true', portMirroring='false', vmId='490f7b83-d2d5-4f60-87d0-4fb5e8842ec5', vmName='t1', vmTemplateId='null', QoSName='null', remoteNetworkName='null'}', vmDevice='VmDevice:{id='VmDeviceId:{deviceId='b72d8f09-8421-43fb-91f0-e3be2c3a8a59', vmId='490f7b83-d2d5-4f60-87d0-4fb5e8842ec5'}', device='hostdev', type='INTERFACE', bootOrder='0', specParams='[]', address='{slot=0x04, bus=0x00, domain=0x0000, type=pci, function=0x0}', managed='true', plugged='false', readOnly='false', deviceAlias='hostdev0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='pci_0000_05_10_3'}'}), log id: 514f3133

2016-12-20 10:23:34,623+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotPlugNicVDSCommand] (default task-6) [400b2bd] FINISH, HotPlugNicVDSCommand, log id: 514f3133


If plugging of nics failed, you should see following in audit log:
VM_MIGRATION_NOT_ALL_VM_NICS_WERE_PLUGGED_BACK(12003, AuditLogSeverity.ERROR)
or
VM_MIGRATION_PLUGGING_VM_NICS_FAILED(12004, AuditLogSeverity.ERROR)

Can you please run: 
select * from audit_log a where a.log_type in (12003, 12004);
and share result?

-[ RECORD 1 ]-------+--------------------------------------------------------------------------
audit_log_id        | 13108
user_id             | 57c415d3-027a-01af-03f4-00000000025b
user_name           | admin@internal-authz
vm_id               | 490f7b83-d2d5-4f60-87d0-4fb5e8842ec5
vm_name             | t1
vm_template_id      | 00000000-0000-0000-0000-000000000000
vm_template_name    | Blank
vds_id              | 16cdcc69-fea0-484c-830e-4760cd709d5b
vds_name            | puma22.scl.lab.tlv.redhat.com
log_time            | 2016-12-20 10:13:57.344+02
log_type_name       | VM_MIGRATION_NOT_ALL_VM_NICS_WERE_PLUGGED_BACK
log_type            | 12003
severity            | 2
message             | After migration of t1, following vm nics failed to be plugged back: nic1.
processed           | f
storage_pool_id     | ea5798e5-47b6-4e81-8005-cceffdddcd5b
storage_pool_name   | DC1
storage_domain_id   | 
storage_domain_name | 
cluster_id          | f839c23a-843d-460a-ae74-4bdb4dec69c1
cluster_name        | CL2
correlation_id      | 4b83a8ba-6f96-4e47-a53f-881ae94b345e
job_id              | ad066ceb-ddc3-4c33-a8cf-6f4829302106
quota_id            | 
quota_name          | 
gluster_volume_id   | 00000000-0000-0000-0000-000000000000
gluster_volume_name | 
origin              | oVirt
custom_event_id     | -1
event_flood_in_sec  | 30
custom_data         | 
deleted             | f
call_stack          | 
brick_id            | 
brick_path          |

(In reply to Michael Burman from comment #3)
> Guest was running.
> 
> Time in logs 2016-12-20 10:27:44,708+02

The correct time is 10:13:57

cool so we have confirmed, that there was effort to plug them back and it failed. 

1. Can you try to plug it back manually?  Reason: Plugging nics back happens in flow, which does not present failures to the user, so we cannot see some error messates ... If plugging it manually back fails, you'll see failure message, and maybe it can be caused by no available VF on target host. That's theoretically possible if you have some failures before, there's some flaw in code, and because of that all free VF leaked.

2. if you can plug nic back manually, please enable debug loglevel and retry migration until it happens again. We saw above, that your call VdcActionType.RefreshHost failed. This call is made also after plugging nic back. If there isn't any flaw, it shouldn't do any harm and all allocated VF for this nics should be released, but nic will not be plugged. This is one probable reason why nic isn't plugged back.

Martin, ACTION_TYPE_FAILED_SETUP_NETWORKS_OR_REFRESH_IN_PROGRESS is worrying. What would happen if during concurrent migration (or concurrent hotplug for that matter)? Would only the first one succeed?

Hi Martin

I managed to reproduce the bug again)

Attaching log in debug 

-[ RECORD 1 ]-------+----------------------------------------------------------------------------------------
audit_log_id        | 4118
user_id             | 58579c26-02f3-0217-02c5-000000000334
user_name           | admin@internal-authz
vm_id               | ac172c6b-dc7a-489c-ba94-30739c554a8e
vm_name             | sr-iov-vm-testss
vm_template_id      | ff3181ac-5072-4fe0-8fd1-60fcce7bfe01
vm_template_name    | golden_mixed_virtio_template
vds_id              | a54ab60e-8a04-4942-b69d-5b179cb5804f
vds_name            | host_mixed_2
log_time            | 2016-12-21 16:15:18.902+02
log_type_name       | VM_MIGRATION_NOT_ALL_VM_NICS_WERE_PLUGGED_BACK
log_type            | 12003
severity            | 2
message             | After migration of sr-iov-vm-testss, following vm nics failed to be plugged back: nic1.
processed           | f
storage_pool_id     | 32e5af95-986b-497c-9861-b6d584bb3ef5
storage_pool_name   | golden_env_mixed
storage_domain_id   | 
storage_domain_name | 
cluster_id          | bae7b2f1-43ff-49aa-bc0b-38d2295fbfc7
cluster_name        | golden_env_mixed_1
correlation_id      | 32a4e0f2-f812-411d-ae6e-54690e987664
job_id              | 77801c6b-9a27-4993-b20d-68281dde005e
quota_id            | 
quota_name          | 
gluster_volume_id   | 00000000-0000-0000-0000-000000000000
gluster_volume_name | 
origin              | oVirt
custom_event_id     | -1
event_flood_in_sec  | 30
custom_data         | 
deleted             | f
call_stack          | 
brick_id            | 
brick_path          |

Created attachment 1234420 [details]
engine log in debug

Steps to reproduce the bug:

1) Create new VM
2) Attach/hotplug 'passthrough' vNIC to the VM and start it
3) Once started successfully and refresh caps invoked on host, immediately start migration. 

If starting the migration right away after the VM is UP and refresh caps invoked, this bug will happen.

when you tried it — can you remember whether it led to VF leakage? ~ if you have only one VF and this happened, were you able to plug it back?

note: even unplugging nic (ie no migration) has issue. Reasons are (partly?) described in comment 8, but if you do unplug, and there's bad luck with refresh, for some reason (probably produced exception) vmdevice isn't updated and VF leaks.

There is no VM leakage, i'm able to plug it back to the VM.

This bug is 100% reproducible.

(In reply to Michael Burman from comment #17)
> There is no VM leakage, i'm able to plug it back to the VM.
> 
> This bug is 100% reproducible.

There is no VF leakage, i'm able to plug it back to the VM.

just to clear possible confusion — I'm glad that your case does not lead to leakage. But simple unplugging nic can led to leakage for me, and that has to be fixed.

Missed 4.1.1, moving to 4.1.2.

(In reply to Yaniv Kaul from comment #20)
> Missed 4.1.1, moving to 4.1.2.

I would want this for the async, since it is blocking the feature.

(In reply to Yaniv Dary from comment #21)
> (In reply to Yaniv Kaul from comment #20)
> > Missed 4.1.1, moving to 4.1.2.
> 
> I would want this for the async, since it is blocking the feature.

I see a single patch merged to master. Donno if it can make it. Dan?

We still need another backport of https://gerrit.ovirt.org/#/q/status:merged+project:ovirt-engine+branch:ovirt-engine-4.1+topic:MigrationAndHostRefreshesMustNotMingle to ovirt-engine-4.1.1.z.

INFO: Bug status wasn't changed from MODIFIED to ON_QA due to the following reason:

[NO RELEVANT PATCHES FOUND]

For more info please contact: infra

Included in 4.1.1.6
https://gerrit.ovirt.org/gitweb?p=ovirt-engine.git;a=shortlog;h=refs/tags/ovirt-engine-4.1.1.6

Verified on - rhevm-4.1.1.6-0.1.el7.noarch and vdsm-4.19.10-1.el7ev.x86_64