Bug 1575773

Created attachment 1432832 [details]
evm.log.gz

Hello, this is what I see in my event list:

in rails c:

pp EmsEvent.pluck(:id, :timestamp, :event_type, :vm_ems_ref)

produces:
[1009,
  Wed, 09 May 2018 12:17:23 UTC +00:00,
  "virtualMachines_delete_BeginRequest",
  "2586c64b-38b4-4527-a140-012d49dfc02c\\miq-azure-test2\\microsoft.compute/virtualmachines\\ladastest8"],
 [1010,
  Wed, 09 May 2018 12:17:25 UTC +00:00,
  "virtualMachines_delete_EndRequest",
  "2586c64b-38b4-4527-a140-012d49dfc02c\\miq-azure-test2\\microsoft.compute/virtualmachines\\ladastest8"],
 [1020,
  Wed, 09 May 2018 12:19:51 UTC +00:00,
  "virtualMachines_delete_EndRequest",
  "2586c64b-38b4-4527-a140-012d49dfc02c\\miq-azure-test2\\microsoft.compute/virtualmachines\\ladastest8"]]

---------

So I am getting the virtualMachines_delete_EndRequest twice. First time it arrives, the Vm is not really deleted and it seems like the API response is still returning it's running. The second time it arrives, it is actually deleted, so that causes archival in CFME.

Do you see just 1 virtualMachines_delete_EndRequest ?

From the evm.log attached here -- seems like I received 3 events actually, but spaced further apart:

[----] I, [2018-05-07T16:32:31.748637 #12567:581114]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourceGroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/temp-bsquizz2

[----] I, [2018-05-07T16:34:37.361368 #12567:581114]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourcegroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/temp-bsquizz2

[----] I, [2018-05-07T16:44:29.316545 #12567:581114]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourcegroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/temp-bsquizz2

That last one comes in 12 min after the first, and 4 min after I did a full provider refresh which had already updated the VM status to the correct state (archived), so I'm not sure if that third event would have led to the proper change or not.

Could you retest this? For me, the second event leads to VM archival. (I tried both master and g-release). For me second event came in about 2-5 minutes.

The first event is too fast, the Vm is not deleted yet, so the API returns the Vm is still running.

Created attachment 1433993 [details]
new upstream log

Created attachment 1433994 [details]
new downstream log

Tested again on latest nightly (May 8) and a 5.9.2.4 appliance (evm log attached)

On upstream 2 events came in. After the second, the VM power state went to 'unknown' but the VM was never archived. Around 15min later I did a full refresh and the VM was archived.

$ zgrep "bsquizz-temp" new-evm.log-upstream | grep "Caught event virtualMachines_delete_EndRequest"
[----] I, [2018-05-09T13:26:00.130894 #16170:885130]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourceGroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-temp
[----] I, [2018-05-09T13:28:30.618341 #16170:885130]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourcegroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-temp


On the downstream test 3 events came in. Similar behavior to above. After the second event, power state went to 'unknown'. Even after the 3rd event came in, the VM remains unarchived.


$ zgrep "bsquizz-anothervm" new-evm.log-downstream | grep "Caught event virtualMachines_delete_EndRequest"
[----] I, [2018-05-09T13:58:24.986737 #34093:649114]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourceGroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-anothervm
[----] I, [2018-05-09T14:00:15.273860 #34093:649114]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourcegroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-anothervm
[----] I, [2018-05-09T14:10:14.849364 #34093:649114]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourcegroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-anothervm

Interesting, in my env I see it being archived. It's all about timing. The VM is archived when we do API query and Azure doesn't return the VM.


I might be able a tweak the targeted refresh a bit, but the question is, if it's correct to archive it on our side, when the Vm still exists in Azure?

Could check if you'll see this behavior also for other entities?

I could see in azure.log for these scenarios that we sent GET requests for the deleted VMs and received HTTP 404 responses, I am assuming this is what caused the power state to switch to 'unknown', but at that point shouldn't we have considered the VM removed from azure?

The archival is driven by fetching Vm (code here: https://github.com/Ladas/manageiq-providers-azure/blob/3d0b18c8380d5fdf6863f1a4105c1bf3ff2ee953/app/models/manageiq/providers/azure/inventory/collector/target_collection.rb#L135), fetching of the state is done separately after that.

Theoretically, we could take the missing status as archived Vm, I need to verify with Dan Berger.

https://github.com/ManageIQ/manageiq-providers-azure/pull/255

New commit detected on ManageIQ/manageiq-providers-azure/master:

https://github.com/ManageIQ/manageiq-providers-azure/commit/949a23dd25ab883a87fe5d5b430442d135e9434d
commit 949a23dd25ab883a87fe5d5b430442d135e9434d
Author:     Ladislav Smola <lsmola>
AuthorDate: Mon May 14 03:43:59 2018 -0400
Commit:     Ladislav Smola <lsmola>
CommitDate: Mon May 14 03:43:59 2018 -0400

    Archive VM with no status

    Archive VM with no status, which should solve that VMs are not
    sometimes archived by targeted refresh. We receive event that VM
    was deleted, but when doing API query, the Vm is still returned.
    When fetching Vm's state, we do get uknown state (azure returns 404)

    Fixes https://bugzilla.redhat.com/show_bug.cgi?id=1575773

 app/models/manageiq/providers/azure/inventory/parser/cloud_manager.rb | 5 +-
 1 file changed, 4 insertions(+), 1 deletion(-)

Created attachment 1459737 [details]
5.10.0.4 azure log

Created attachment 1459738 [details]
5.10.0.4 evm debug log

Testing this on 5.10.0.4, I still do not see the VM get archived after it is deleted in Azure. See the attached logs (the '5.10.0.4' evm and azure logs) for the VM named 'bsquizz-rhel74-new'. The VM is created, and once it appears in CFME, I delete it on Azure. The delete event comes in here:

[----] I, [2018-07-18T11:18:24.045091 #30997:3d8f74]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourcegroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-rhel74-new

Brandon, do you see more of these events? I usually saw 1 event, where the VM state was active or deleting, then another event, when it was really deleted.

Yes there does appear to be 2 delete_EndRequest events in the log for the VM

[----] I, [2018-07-18T11:16:08.867400 #30997:3d8f74]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourceGroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-rhel74-new


[----] I, [2018-07-18T11:18:24.045091 #30997:3d8f74]  INFO -- : MIQ(ManageIQ::Providers::Azure::CloudManager::EventCatcher::Runner#process_event) EMS [] as [086e2864-00b5-49bb-83fe-354d7a32bfe3] Caught event virtualMachines_delete_EndRequest for /subscriptions/c9e72ccc-b20e-48bd-a0c8-879c6dbcbfbb/resourcegroups/bsquizz-resource-grp/providers/Microsoft.Compute/virtualMachines/bsquizz-rhel74-new

Brandon, can you give me access to this appliance? Both UI and ssh please. There is something wrong with it, I see that the targeted refresh is not running properly, instead it runs the old full refresh.

Looks like the graph refresh is not enabled. Did you disable it manually? It should be enabled by default, so if you haven't changed that, we might have some issues with the advanced settings.

I didn't disable it myself, I'll double check the settings. That appliance was a temp test appliance. I'll spin up another today, reproduce, and leave it up for you to log into.

Wait, it's disabled by default. https://github.com/Ladas/manageiq-providers-azure/blob/835c86dfb83eb1a59c896f6d553494810d6f15bc/config/settings.yml#L56

I need to check with Bronagh, what should be the default.

So now you'll need to enable it, to verify this BZ

It was disabled by default as a temporary measure, the plan was to enable it after it has tested in the field and we had a chance to get feedback. It was included in 4.6. I think its safe to enable it by default now.

https://github.com/ManageIQ/manageiq-providers-azure/pull/280 enabling it by default here

Thanks. Testing again with that option enabled, but Azure events seem to be coming in very slowly today, so I'll wait and try verifying again later.

By the time the event comes in, the VM is fully deleted, and we see:
[----] D, [2018-07-19T14:28:14.965676 #54374:7a353ac] DEBUG -- : MIQ(ManageIQ::Providers::Azure::Inventory::Collector::TargetCollection#safe_targeted_request) Record not found Error Class=Azure::Armrest::NotFoundException, Message=The Resource 'Microsoft.Compute/virtualMachines/tmp-b-ubuntu' under resource group 'bsquizz-resource-grp' was not found.

So I'm not currently hitting the same scenario as before (where the VM is there but with an unknown state)

Azure is behaving better now -- verified on CFME 5.10.0.8 -- VM is deleted, delete event arrived, targeted refresh occurred but we did NOT hit the "NotFoundException" (since VM was still in the process of being deleted), but VM state switched to 'Archived' in the UI.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2019:0212