manageiq / manageiq-providers-kubevirt Goto Github PK

View Code? Open in Web Editor NEW

4.0 7.0 28.0 499 KB

ManageIQ plugin for the Kubevirt provider.

Home Page: https://kubevirt.io/

License: Apache License 2.0

Ruby 99.20% Shell 0.80%

manageiq-providers-kubevirt's Introduction

ManageIQ::Providers::Kubevirt

ManageIQ plugin for the KubeVirt provider.

Things that work

Currently the provider supports the following simple use cases:

Add the provider using token authentication.
Clone virtual machines from templates.
Connect to the SPICE console of the virtual machines.
Virtual machine power management: stop and start

Things that don't work

The Kubernetes API suports authentication using client side digital certificates, tokens and user name and passwords. The KubeVirt provider only supports tokens. The UI already has the posibility to specify other authentication mechanisms, but they don't work in the provider side yet.
The use of client certificates should probably be part of the ManageIQ core, as many other providers may want to support them. For example, oVirt could use them in combination with an authentication configuration that uses the client certificate subject as the user name.
The UI works for initial validation and credentials, and for adding the provider, but it doesn't work for editing the provider: it doesn't show the selected authentication method, and it doesn't show the token.

Things that should be changed

Kubernetes has a namespace concept that is currently ignored by the provider, it only uses the default namespace, and that is hard-coded. We should consider making the namespace part of the initial dialog to add the provider, like the authentication details or the IP address.
In KubeVirt virtual machine instances are started when they are created. Virtual machine represent stopped vm.
The provider considers the KubeVirt configuration the source of truth. That should be changed, the source of truth should be the ManageIQ database.
There is no event tracker. The refresh of the inventory is only performed manually, or when a new virtual machine is added.
The inventory refresh uses the graph refresh mechanism, but it always performs a full refresh, there are no specific targers (like virtual machines, or hosts) implemented yet.
The kubeclient gem that the provider uses to talk to the Kubernetes API doesn't support the sub-resource mechanism used by the KubeVirt API for SPICE details. In addition Kubernetes itself doesn't yet support sub-resources for custom resource definitions. As a result the provider has to extract the SPICE proxy URL from the configuration of the spice-proxy service.

Notes

How to get the default token from Kubernetes

List the set of secrets:

$ kubectl get secrets
NAME                  TYPE                                  DATA      AGE
default-token-7psxt   kubernetes.io/service-account-token   3         20d

Get the details of the default token:

# kubectl describe secret default-token-7psxt
Name:         default-token-7psxt
Namespace:    default
Labels:       <none>
Annotations:  kubernetes.io/service-account.name=default
              kubernetes.io/service-account.uid=d748bdb5-f9dc-11e7-9332-525400d6a390

Type:  kubernetes.io/service-account-token

Data
====
ca.crt:     1025 bytes
namespace:  7 bytes
token:      eyJhbGciO...
...

The token is the value of the token attribute.

The extracted value can now be used to authenticate with the Kubernetes API, setting the Authorization header:

Authorization: Bearer eyJ...

Development

See the section on plugins in the ManageIQ Developer Setup

For quick local setup run bin/setup, which will clone the core ManageIQ repository under the spec directory and setup necessary config files. If you have already cloned it, you can run bin/update to bring the core ManageIQ code up to date.

License

The gem is available as open source under the terms of the Apache License 2.0.

Contributing

Fork it
Create your feature branch (git checkout -b my-new-feature)
Commit your changes (git commit -am 'Add some feature')
Push to the branch (git push origin my-new-feature)
Create new Pull Request

manageiq-providers-kubevirt's People

Contributors

Stargazers

Watchers

manageiq-providers-kubevirt's Issues

Wrongly shown valid auth tick

After adding an OpenShift as a Container provider & KubeVirt for Virtualization, if the token was valid, but with different role/access, and the ManageIQ cannot refresh/fetch data from the provider, it still shows the green tick.
This is not fully a bug, as the token might be valid, but if the provider is not able to fetch the exact or any details with that token, then it does not make sense to make that auth a green tick.

Power state not shown in all vm page

With the enhancement of #82 , I can see the expected power state in VM detail page

But, the all VM page doesn't show these new states

[Tracker] VM state not synced

This issue tracks [1].

[1] https://bugzilla.redhat.com/1593570

Kubernetes ovm name validation change

With issue kubevirt/kubevirt#1092 , kubevirt should be updated to not allow creation VM with unsupported name format

VM retirement notification

When retiring a VM on KubeVirt, I am seeing sometimes the VM name is not populated, though this is not consistent, only seeing it sometimes

Cannot edit the default or virtualization endpoint alone

When an administrator wants to change just one token, validation for both seem to be required (when editing the container provider)

This is when the token for default is not valid anymore

VMs not getting retired

KubeVirt version: 0.4
Manageiq: Version master.20180406233346_c9e7f02

Retiring VMs from ManageIQ shows them retired, but they're not actually deleted on the kubevirt side

Save button not getting enabled when Editing Infra provider

When editing virtualization endpoint for a token change, the save button is not getting enabled, even after waiting for quite few minutes

[Tracker] Unexpected error on requests page

This issue is opened to track https://bugzilla.redhat.com/1584172

[Tracker] [Regression] Cannot retire VM

This isssue was opened to track https://bugzilla.redhat.com/1584010

VM not getting powered on

Note: This happens time to time

Provisioning request of a VM gets stuck in 'Active', checking it on openshift, the offline VM was created, but it was not powered on, didn't find anything openshift logs and events.
in manageiq,
automation.log

[----] I, [2018-05-16T04:56:12.453707 #2157:124d140]  INFO -- : Q-task_id([r9_miq_provision_request_9]) Processed State=[limits]
[----] W, [2018-05-16T04:56:12.453789 #2157:124d140]  WARN -- : Q-task_id([r9_miq_provision_request_9]) Skipping to state finished

But the request state in UI was still Active

Correct virtualization token shows error in authentication

For a existing provider, when the token for both default and virtualization was changed, and we just edit the token for virtualization, the authentication status for virtualization shows ! but functions (like provisioning VMs) are working.

virtualization gets affected with Default token change

For a existing provider, which had both default and virtualization tokens same, and then that token is deleted from openshift, if we change token for just default with the new created token (which also is valid token for virtualization), the virtualization seems to be working fine where it should not be.

404 error with KubeVirt virtualization

When adding the OpenShift provider, and selecting the KubeVirt virtualization, if the openshift doesn't have kubevirt but the token for Virtualization validation is successful, we get the error
Credential validation was not successful: HTTP status code 404, 404 Not Found

Add better error message

When going to add a new provider, if a user session has expired, rather then taking out to the login page, it keeps giving the error
Something went wrong, please check the logs for more information.
Message here is confusing as you won't find anything wrong in the log

[Tracker] VM Templates not getting synced

This issue tracks [1].

[1] https://bugzilla.redhat.com/1593567

[Tracker] Parameter values not correctly updated during template processing

This issue was opened to track https://bugzilla.redhat.com/1598699

Error in Service catalog when passing field values from dialog

when passing a value to the dialog which was configured to take value option_0_number_of_vms, and ordering it with a value to get multiple VMs gets stuck with error

Here's the evm.log for that request

[----] I, [2018-03-06T00:00:19.676219 #9142:2aeba5d00f50]  INFO -- : MIQ(MiqScheduleWorker::Runner#rufus_remove_schedules_by_tag) Unscheduling 1 jobs with tag: miq_schedules_3
[----] I, [2018-03-06T02:01:15.272344 #9096:2aeba5d00f50]  INFO -- : MIQ(Metric.reindex) Reindexing table metrics_3
[----] E, [2018-03-06T02:01:15.272893 #9096:2aeba5d00f50] ERROR -- : MIQ(MiqQueue#deliver) Message id: [29293], Error: [PG::UndefinedTable: ERROR:  relation "metrics_3" does not exist
: REINDEX TABLE "metrics_3"]
[----] E, [2018-03-06T02:01:15.273041 #9096:2aeba5d00f50] ERROR -- : [ActiveRecord::StatementInvalid]: PG::UndefinedTable: ERROR:  relation "metrics_3" does not exist
: REINDEX TABLE "metrics_3"  Method:[block in method_missing]
[----] I, [2018-03-07T00:00:22.230629 #947:2aabaed24f54]  INFO -- : MIQ(MiqScheduleWorker::Runner#rufus_remove_schedules_by_tag) Unscheduling 1 jobs with tag: miq_schedules_3
[----] I, [2018-03-07T02:01:10.092173 #902:2aabaed24f54]  INFO -- : MIQ(Metric.reindex) Reindexing table metrics_3
[----] E, [2018-03-07T02:01:10.092812 #902:2aabaed24f54] ERROR -- : MIQ(MiqQueue#deliver) Message id: [36179], Error: [PG::UndefinedTable: ERROR:  relation "metrics_3" does not exist
: REINDEX TABLE "metrics_3"]
[----] E, [2018-03-07T02:01:10.092962 #902:2aabaed24f54] ERROR -- : [ActiveRecord::StatementInvalid]: PG::UndefinedTable: ERROR:  relation "metrics_3" does not exist
: REINDEX TABLE "metrics_3"  Method:[block in method_missing]
[----] I, [2018-03-07T08:56:11.307062 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#deliver) Message id: [38490], Delivering...
[----] I, [2018-03-07T08:56:11.309697 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAeEngine.deliver) Delivering {"request"=>"vm_provision"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.3] with state [] to Automate
[----] I, [2018-03-07T08:56:25.059324 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAeEngine.deliver) Requeuing {:object_type=>"ManageIQ::Providers::Kubevirt::InfraManager::Provision", :object_id=>3, :attrs=>{"request"=>"vm_provision"}, :instance_name=>"AUTOMATION", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :state=>"CheckProvisioned", :ae_fsm_started=>nil, :ae_state_started=>"2018-03-07 08:56:23 UTC", :ae_state_retries=>1, :ae_state_previous=>"---\n\"/ManageIQ/Infrastructure/VM/Provisioning/StateMachines/VMProvision_vm/template\":\n  ae_state: CheckProvisioned\n  ae_state_retries: 1\n  ae_state_started: 2018-03-07 08:56:23 UTC\n  ae_state_max_retries: 100\n"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.3] with state [CheckProvisioned] to Automate for delivery in [60] seconds
[----] I, [2018-03-07T08:56:25.069100 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue.put) Message id: [38501],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [100], State: [ready], Deliver On: [2018-03-07 08:57:25 UTC], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Kubevirt::InfraManager::Provision", :object_id=>3, :attrs=>{"request"=>"vm_provision"}, :instance_name=>"AUTOMATION", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :state=>"CheckProvisioned", :ae_fsm_started=>nil, :ae_state_started=>"2018-03-07 08:56:23 UTC", :ae_state_retries=>1, :ae_state_previous=>"---\n\"/ManageIQ/Infrastructure/VM/Provisioning/StateMachines/VMProvision_vm/template\":\n  ae_state: CheckProvisioned\n  ae_state_retries: 1\n  ae_state_started: 2018-03-07 08:56:23 UTC\n  ae_state_max_retries: 100\n"}]
[----] I, [2018-03-07T08:56:25.069194 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#after_ae_delivery) ae_result="retry"
[----] I, [2018-03-07T08:56:25.069386 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#delivered) Message id: [38490], State: [ok], Delivered in [13.762294227] seconds
[----] I, [2018-03-07T08:57:21.101165 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#deliver) Message id: [38500], Delivering...
[----] I, [2018-03-07T08:57:21.102879 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#execute) Executing VM Provisioning request: [Provision from [linux-vm-template] to [vparekh-test001]]
[----] I, [2018-03-07T08:57:21.132789 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#execute) VM Provisioning initiated
[----] I, [2018-03-07T08:57:21.163489 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <run_provision>
[----] I, [2018-03-07T08:57:21.175042 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <create_destination>
[----] I, [2018-03-07T08:57:21.185585 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <determine_placement>
[----] I, [2018-03-07T08:57:21.193569 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <prepare_provision>
[----] I, [2018-03-07T08:57:21.230768 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#prepare_provision) Default Clone Options: [:name](String) = "vparekh-test001"
[----] I, [2018-03-07T08:57:21.230866 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <start_clone_task>
[----] I, [2018-03-07T08:57:21.266415 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provisioning 'linux-vm-template' to 'vparekh-test001'
[----] I, [2018-03-07T08:57:21.266488 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Source template name is 'linux-vm-template'
[----] I, [2018-03-07T08:57:21.266544 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Destination virtual machine name is 'vparekh-test001'
[----] I, [2018-03-07T08:57:21.266707 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Clone options: [:name](String) = "vparekh-test001"
[----] I, [2018-03-07T08:57:21.266941 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:initial_pass](TrueClass) = true
[----] I, [2018-03-07T08:57:21.267062 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:src_vm_id][0](Integer) = 3
[----] I, [2018-03-07T08:57:21.267144 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:src_vm_id][1](String) = "linux-vm-template"
[----] I, [2018-03-07T08:57:21.267240 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:miq_request_dialog_name](String) = "miq_provision_kubevirt_dialogs_template"
[----] I, [2018-03-07T08:57:21.267326 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:current_tab_key](Symbol) = :service
[----] I, [2018-03-07T08:57:21.267411 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_phone](NilClass) = nil
[----] I, [2018-03-07T08:57:21.267493 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_country](NilClass) = nil
[----] I, [2018-03-07T08:57:21.267587 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_phone_mobile](NilClass) = nil
[----] I, [2018-03-07T08:57:21.267669 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_title](NilClass) = nil
[----] I, [2018-03-07T08:57:21.267747 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_first_name](NilClass) = nil
[----] I, [2018-03-07T08:57:21.267830 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_manager](NilClass) = nil
[----] I, [2018-03-07T08:57:21.267919 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_address](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268001 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_company](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268079 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_last_name](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268164 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_manager_mail](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268249 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_city](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268329 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_department](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268407 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_load_ldap](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268490 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_manager_phone](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268584 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_state](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268666 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_office](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268744 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_zip](NilClass) = nil
[----] I, [2018-03-07T08:57:21.268822 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_email](String) = "[email protected]"
[----] I, [2018-03-07T08:57:21.268902 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:request_notes](NilClass) = nil
[----] I, [2018-03-07T08:57:21.269035 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:provision_type][0](String) = "native_clone"
[----] I, [2018-03-07T08:57:21.269111 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:provision_type][1](String) = "Native Clone"
[----] I, [2018-03-07T08:57:21.269224 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:number_of_vms][0](Integer) = 10
[----] I, [2018-03-07T08:57:21.269300 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:number_of_vms][1](String) = "10"
[----] I, [2018-03-07T08:57:21.269383 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_description](NilClass) = nil
[----] I, [2018-03-07T08:57:21.269469 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_prefix](NilClass) = nil
[----] I, [2018-03-07T08:57:21.269558 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_name](String) = "vparekh-test"
[----] I, [2018-03-07T08:57:21.269665 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:schedule_type][0](String) = "schedule"
[----] I, [2018-03-07T08:57:21.269740 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:schedule_type][1](String) = "Schedule"
[----] I, [2018-03-07T08:57:21.269847 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_auto_start][0](TrueClass) = true
[----] I, [2018-03-07T08:57:21.269922 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_auto_start][1](Integer) = 1
[----] I, [2018-03-07T08:57:21.270029 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:schedule_time](ActiveSupport::TimeWithZone) = Wed, 07 Mar 2018 01:00:00 UTC +00:00
[----] I, [2018-03-07T08:57:21.270137 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:retirement][0](Integer) = 0
[----] I, [2018-03-07T08:57:21.270227 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:retirement][1](String) = "Indefinite"
[----] I, [2018-03-07T08:57:21.270331 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:retirement_warn][0](Integer) = 604800
[----] I, [2018-03-07T08:57:21.270408 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:retirement_warn][1](String) = "1 Week"
[----] I, [2018-03-07T08:57:21.270519 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:stateless][0](FalseClass) = false
[----] I, [2018-03-07T08:57:21.270611 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:stateless][1](Integer) = 0
[----] I, [2018-03-07T08:57:21.270720 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_memory][0](String) = "4096"
[----] I, [2018-03-07T08:57:21.270795 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_memory][1](String) = "4096"
[----] I, [2018-03-07T08:57:21.270870 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:start_date](String) = "03/07/2018"
[----] I, [2018-03-07T08:57:21.270943 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:start_hour](String) = "1"
[----] I, [2018-03-07T08:57:21.271022 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:start_min](String) = "00"
[----] I, [2018-03-07T08:57:21.271190 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:src_ems_id][0](Integer) = 20
[----] I, [2018-03-07T08:57:21.271267 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:src_ems_id][1](String) = "k6t-ocp Virtualization Manager"
[----] I, [2018-03-07T08:57:21.271345 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:requester_group](String) = "EvmGroup-super_administrator"
[----] I, [2018-03-07T08:57:21.271426 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:owner_group](NilClass) = nil
[----] I, [2018-03-07T08:57:21.271503 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:delivered_on](Time) = 2018-03-07 08:56:05 UTC
[----] I, [2018-03-07T08:57:21.271594 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:pass](Integer) = 1
[----] I, [2018-03-07T08:57:21.271674 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:dns_domain](NilClass) = nil
[----] I, [2018-03-07T08:57:21.271749 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_target_name](String) = "vparekh-test001"
[----] I, [2018-03-07T08:57:21.271820 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#log_clone_options) Provision options: [:vm_target_hostname](String) = "vparekh-test001"
[----] I, [2018-03-07T08:57:21.271986 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager#with_provider_connection) Connecting through ManageIQ::Providers::Kubevirt::InfraManager: [k6t-ocp Virtualization Manager]
[----] I, [2018-03-07T08:57:22.638211 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager#with_provider_connection) Connecting through ManageIQ::Providers::Kubevirt::InfraManager: [k6t-ocp Virtualization Manager]
[----] I, [2018-03-07T08:57:22.661837 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager#with_provider_connection) Connecting through ManageIQ::Providers::Kubevirt::InfraManager: [k6t-ocp Virtualization Manager]
[----] I, [2018-03-07T08:57:24.384493 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <poll_destination_in_vmdb>
[----] I, [2018-03-07T08:57:24.453839 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#poll_destination_in_vmdb) Unable to find VM [vparekh-test001] with ems_ref [8ee20e50-21e5-11e8-b116-fa163ecafec3], will retry
[----] I, [2018-03-07T08:57:24.467846 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue.put) Message id: [38522],  id: [], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [3], Task id: [], Command: [ManageIQ::Providers::Kubevirt::InfraManager::Provision.poll_destination_in_vmdb], Timeout: [600], Priority: [100], State: [ready], Deliver On: [2018-03-07 08:57:34 UTC], Data: [], Args: []
[----] I, [2018-03-07T08:57:24.469471 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#delivered) Message id: [38500], State: [ok], Delivered in [3.368327403] seconds
[----] I, [2018-03-07T08:57:24.474705 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#m_callback) Message id: [38500], Invoking Callback with args: ["ok", "Message delivered successfully", "#<MiqQueue id: 38522, target_id: nil, priority: 100, method_name: \"poll_destination_in_vmdb\", state: \"ready\", created_on: \"2018-03-07 08:57:24\", updated_on: \"2018-03-07 08:57:24\", lock_version: 0, task_id: nil, deliver_on: \"2018-03-07 08:57:34\", queue_name: \"generic\", class_name: \"ManageIQ::Providers::Kubevirt::InfraManager::Provi...\", instance_id: 3, args: [], miq_callback: {:class_name=>\"ManageIQ::Providers::Kubevirt::InfraManager::Provision\", :instance_id=>3, :method_name=>:execute_callback},..."]
[----] I, [2018-03-07T08:57:33.034368 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#deliver) Message id: [38501], Delivering...
[----] I, [2018-03-07T08:57:33.039913 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAeEngine.deliver) Delivering {"request"=>"vm_provision"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.3] with state [CheckProvisioned] to Automate
[----] I, [2018-03-07T08:57:35.320258 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAeEngine.deliver) Requeuing {:object_type=>"ManageIQ::Providers::Kubevirt::InfraManager::Provision", :object_id=>3, :attrs=>{"request"=>"vm_provision"}, :instance_name=>"AUTOMATION", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :state=>"CheckProvisioned", :ae_fsm_started=>nil, :ae_state_started=>"2018-03-07 08:56:23 UTC", :ae_state_retries=>2, :ae_state_previous=>"---\n\"/ManageIQ/Infrastructure/VM/Provisioning/StateMachines/VMProvision_vm/template\":\n  ae_state: CheckProvisioned\n  ae_state_retries: 2\n  ae_state_started: 2018-03-07 08:56:23 UTC\n  ae_state_max_retries: 100\n"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.3] with state [CheckProvisioned] to Automate for delivery in [60] seconds
[----] I, [2018-03-07T08:57:35.329869 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue.put) Message id: [38532],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [100], State: [ready], Deliver On: [2018-03-07 08:58:35 UTC], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Kubevirt::InfraManager::Provision", :object_id=>3, :attrs=>{"request"=>"vm_provision"}, :instance_name=>"AUTOMATION", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :state=>"CheckProvisioned", :ae_fsm_started=>nil, :ae_state_started=>"2018-03-07 08:56:23 UTC", :ae_state_retries=>2, :ae_state_previous=>"---\n\"/ManageIQ/Infrastructure/VM/Provisioning/StateMachines/VMProvision_vm/template\":\n  ae_state: CheckProvisioned\n  ae_state_retries: 2\n  ae_state_started: 2018-03-07 08:56:23 UTC\n  ae_state_max_retries: 100\n"}]
[----] I, [2018-03-07T08:57:35.329982 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#after_ae_delivery) ae_result="retry"
[----] I, [2018-03-07T08:57:35.330196 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#delivered) Message id: [38501], State: [ok], Delivered in [2.295803903] seconds
[----] I, [2018-03-07T08:57:35.803618 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#deliver) Message id: [38522], Delivering...
[----] I, [2018-03-07T08:57:35.840087 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <customize_destination>
[----] I, [2018-03-07T08:57:35.847628 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <post_provision>
[----] I, [2018-03-07T08:57:35.854094 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <autostart_destination>
[----] I, [2018-03-07T08:57:35.881236 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#autostart_destination) Starting VM id: [8], name: [vparekh-test001]
[----] I, [2018-03-07T08:57:35.937407 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue.put) Message id: [38534],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Kubevirt::InfraManager::Vm", :object_id=>8, :attrs=>{:event_type=>:request_vm_start, "VmOrTemplate::vm"=>8, :vm_id=>8, "ExtManagementSystem::ext_management_system"=>20, :ext_management_system_id=>20, "MiqEvent::miq_event"=>7066, :miq_event_id=>7066, "EventStream::event_stream"=>7066, :event_stream_id=>7066}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2018-03-07T08:57:35.937493 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <post_create_destination>
[----] I, [2018-03-07T08:57:35.947910 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#post_create_destination) Destination Vm ID=8, Name=vparekh-test001
[----] I, [2018-03-07T08:57:35.949112 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#set_description) Setting Vm description to nil
[----] I, [2018-03-07T08:57:35.968858 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#set_ownership) Setting Owning User to Name=Administrator, ID=1
[----] I, [2018-03-07T08:57:35.969014 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#set_ownership) Setting Owning Group to Name=EvmGroup-super_administrator, ID=2
[----] I, [2018-03-07T08:57:35.969230 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#set_genealogy) Setting Genealogy Parent to MiqTemplate Name=linux-vm-template, ID=3
[----] I, [2018-03-07T08:57:35.992912 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <mark_as_completed>
[----] I, [2018-03-07T08:57:36.013848 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue.put) Message id: [38536],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::Kubevirt::InfraManager::Vm", :object_id=>8, :attrs=>{:event_type=>"vm_provisioned", "VmOrTemplate::vm"=>8, :vm_id=>8, :host=>nil, "MiqEvent::miq_event"=>7067, :miq_event_id=>7067, "EventStream::event_stream"=>7067, :event_stream_id=>7067}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2018-03-07T08:57:36.036117 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) Starting Phase <finish>
[----] I, [2018-03-07T08:57:36.043732 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#finish) Executing provision request: [Provision from [linux-vm-template] to [vparekh-test001]], Pass: 1 of 10... Complete
[----] I, [2018-03-07T08:57:36.043888 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#delivered) Message id: [38522], State: [ok], Delivered in [0.240268521] seconds
[----] I, [2018-03-07T08:57:36.045590 #902:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#m_callback) Message id: [38522], Invoking Callback with args: ["ok", "Message delivered successfully", "true"]
[----] I, [2018-03-07T08:57:40.148709 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#deliver) Message id: [38534], Delivering...
[----] I, [2018-03-07T08:57:40.152766 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAeEngine.deliver) Delivering {:event_type=>:request_vm_start, "VmOrTemplate::vm"=>8, :vm_id=>8, "ExtManagementSystem::ext_management_system"=>20, :ext_management_system_id=>20, "MiqEvent::miq_event"=>7066, :miq_event_id=>7066, "EventStream::event_stream"=>7066, :event_stream_id=>7066} for object [ManageIQ::Providers::Kubevirt::InfraManager::Vm.8] with state [] to Automate
[----] I, [2018-03-07T08:57:40.285125 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqEvent#process_evm_event) target = [#<ManageIQ::Providers::Kubevirt::InfraManager::Vm id: 8, vendor: "kubevirt", format: nil, version: nil, name: "vparekh-test001", description: nil, location: "unknown", config_xml: nil, autostart: nil, host_id: nil, last_sync_on: nil, created_on: "2018-03-07 08:57:24", updated_on: "2018-03-07 08:57:35", storage_id: 1, guid: "d7ecbabc-8265-4688-8ab9-9860a82bb529", ems_id: 20, last_scan_on: nil, last_scan_attempt_on: nil, uid_ems: "8ee20e50-21e5-11e8-b116-fa163ecafec3", retires_on: nil, retired: nil, boot_time: nil, tools_status: nil, standby_action: nil, power_state: "off", state_changed_on: "2018-03-07 08:57:24", previous_state: nil, connection_state: "connected", last_perf_capture_on: nil, registered: nil, busy: nil, smart: nil, memory_reserve: nil, memory_reserve_expand: nil, memory_limit: nil, memory_shares: nil, memory_shares_level: nil, cpu_reserve: nil, cpu_reserve_expand: nil, cpu_limit: nil, cpu_shares: nil, cpu_shares_level: nil, cpu_affinity: nil, ems_created_on: nil, template: false, evm_owner_id: 1, ems_ref_obj: "--- 8ee20e50-21e5-11e8-b116-fa163ecafec3\n...\n", miq_group_id: 2, linked_clone: nil, fault_tolerance: nil, type: "ManageIQ::Providers::Kubevirt::InfraManager::Vm", ems_ref: "8ee20e50-21e5-11e8-b116-fa163ecafec3", ems_cluster_id: nil, retirement_warn: nil, retirement_last_warn: nil, vnc_port: nil, flavor_id: nil, availability_zone_id: nil, cloud: false, retirement_state: nil, cloud_network_id: nil, cloud_subnet_id: nil, cloud_tenant_id: nil, raw_power_state: "off", publicly_available: nil, orchestration_stack_id: nil, retirement_requester: nil, tenant_id: 1, resource_group_id: nil, deprecated: nil, storage_profile_id: nil, cpu_hot_add_enabled: nil, cpu_hot_remove_enabled: nil, memory_hot_add_enabled: nil, memory_hot_add_limit: nil, memory_hot_add_increment: nil, hostname: nil>]
[----] I, [2018-03-07T08:57:40.285341 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqEvent#process_evm_event) Event Raised [request_vm_start]
[----] I, [2018-03-07T08:57:40.302376 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqEvent#process_evm_event) Alert for Event [request_vm_start]
[----] I, [2018-03-07T08:57:40.302489 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAlert.evaluate_alerts) [request_vm_start] Target: ManageIQ::Providers::Kubevirt::InfraManager::Vm Name: [vparekh-test001], Id: [8]
[----] I, [2018-03-07T08:57:40.313371 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#delivered) Message id: [38534], State: [ok], Delivered in [0.164645623] seconds
[----] I, [2018-03-07T08:57:40.359642 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#m_callback) Message id: [38534], Invoking Callback with args: [:raw_start, "ok", "Message delivered successfully", "#<MiqAeEngine::MiqAeWorkspaceRuntime:0x0000555773890ad8 @readonly=false, @nodes=[#<MiqAeEngine::MiqAeObject:0x0000555773a1db30 @workspace=#<MiqAeEngine::MiqAeWorkspaceRuntime:0x0000555773890ad8 ...>, @namespace=\"ManageIQ/System\", @klass=\"Process\", @instance=\"Event\", @attributes={\"event_stream_id\"=>\"7066\", \"event_type\"=>\"request_vm_start\", \"ext_management_system_id\"=>\"20\", \"miq_event_id\"=>\"7066\", \"object_name\"=>\"Event\", \"vm_id\"=>\"8\", \"vmdb_object_type\"=>\"vm\", \"event_stream\"=>#<MiqAeServiceMiqEven..."]
[----] I, [2018-03-07T08:57:40.362039 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager#with_provider_connection) Connecting through ManageIQ::Providers::Kubevirt::InfraManager: [k6t-ocp Virtualization Manager]
[----] I, [2018-03-07T08:57:40.417453 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#deliver) Message id: [38536], Delivering...
[----] I, [2018-03-07T08:57:40.420376 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"vm_provisioned", "VmOrTemplate::vm"=>8, :vm_id=>8, :host=>nil, "MiqEvent::miq_event"=>7067, :miq_event_id=>7067, "EventStream::event_stream"=>7067, :event_stream_id=>7067} for object [ManageIQ::Providers::Kubevirt::InfraManager::Vm.8] with state [] to Automate
[----] I, [2018-03-07T08:57:40.538339 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqEvent#process_evm_event) target = [#<ManageIQ::Providers::Kubevirt::InfraManager::Vm id: 8, vendor: "kubevirt", format: nil, version: nil, name: "vparekh-test001", description: nil, location: "unknown", config_xml: nil, autostart: nil, host_id: nil, last_sync_on: nil, created_on: "2018-03-07 08:57:24", updated_on: "2018-03-07 08:57:40", storage_id: 1, guid: "d7ecbabc-8265-4688-8ab9-9860a82bb529", ems_id: 20, last_scan_on: nil, last_scan_attempt_on: nil, uid_ems: "8ee20e50-21e5-11e8-b116-fa163ecafec3", retires_on: nil, retired: nil, boot_time: nil, tools_status: nil, standby_action: nil, power_state: "on", state_changed_on: "2018-03-07 08:57:40", previous_state: "off", connection_state: "connected", last_perf_capture_on: nil, registered: nil, busy: nil, smart: nil, memory_reserve: nil, memory_reserve_expand: nil, memory_limit: nil, memory_shares: nil, memory_shares_level: nil, cpu_reserve: nil, cpu_reserve_expand: nil, cpu_limit: nil, cpu_shares: nil, cpu_shares_level: nil, cpu_affinity: nil, ems_created_on: nil, template: false, evm_owner_id: 1, ems_ref_obj: "--- 8ee20e50-21e5-11e8-b116-fa163ecafec3\n...\n", miq_group_id: 2, linked_clone: nil, fault_tolerance: nil, type: "ManageIQ::Providers::Kubevirt::InfraManager::Vm", ems_ref: "8ee20e50-21e5-11e8-b116-fa163ecafec3", ems_cluster_id: nil, retirement_warn: nil, retirement_last_warn: nil, vnc_port: nil, flavor_id: nil, availability_zone_id: nil, cloud: false, retirement_state: nil, cloud_network_id: nil, cloud_subnet_id: nil, cloud_tenant_id: nil, raw_power_state: "on", publicly_available: nil, orchestration_stack_id: nil, retirement_requester: nil, tenant_id: 1, resource_group_id: nil, deprecated: nil, storage_profile_id: nil, cpu_hot_add_enabled: nil, cpu_hot_remove_enabled: nil, memory_hot_add_enabled: nil, memory_hot_add_limit: nil, memory_hot_add_increment: nil, hostname: nil>]
[----] I, [2018-03-07T08:57:40.538470 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqEvent#process_evm_event) Event Raised [vm_provisioned]
[----] I, [2018-03-07T08:57:40.549882 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqEvent#process_evm_event) Alert for Event [vm_provisioned]
[----] I, [2018-03-07T08:57:40.549991 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAlert.evaluate_alerts) [vm_provisioned] Target: ManageIQ::Providers::Kubevirt::InfraManager::Vm Name: [vparekh-test001], Id: [8]
[----] I, [2018-03-07T08:57:40.556690 #911:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#delivered) Message id: [38536], State: [ok], Delivered in [0.139245632] seconds
[----] I, [2018-03-07T08:58:42.182203 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#deliver) Message id: [38532], Delivering...
[----] I, [2018-03-07T08:58:42.184648 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqAeEngine.deliver) Delivering {"request"=>"vm_provision"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.3] with state [CheckProvisioned] to Automate
[----] I, [2018-03-07T08:58:50.432292 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#after_ae_delivery) ae_result="ok"
[----] I, [2018-03-07T08:58:50.461754 #893:2aabaed24f54]  INFO -- : Q-task_id([miq_provision_3]) MIQ(MiqQueue#delivered) Message id: [38532], State: [ok], Delivered in [8.27954346] seconds
 pg_toast_3592                                      |                  0 |           0 |                   |                         |                         |                  |         0 |            0 |                0 |             0 |         0 |            0 |                    0 |           0
 pg_toast_3596                                      |                  0 |           0 |                   |                         |                         |                  |         0 |            0 |                0 |             0 |         0 |            0 |                    0 |           0
[----] I, [2018-03-07T10:44:01.432043 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(MiqQueue#deliver) Message id: [39123], Delivering...
[----] I, [2018-03-07T10:44:01.433656 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(ServiceTemplateProvisionRequest#create_request_tasks) Creating request task instances for: <Provisioning Service [test] from [test]>...
[----] I, [2018-03-07T10:44:01.433717 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(ServiceTemplateProvisionRequest#call_automate_event) Raising event [request_starting] to Automate synchronously
[----] I, [2018-03-07T10:44:01.440313 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"request_starting", "EventStream::event_stream"=>7187, :event_stream_id=>7187} for object [ServiceTemplateProvisionRequest.3] with state [] to Automate
[----] I, [2018-03-07T10:44:02.752773 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(ServiceTemplateProvisionRequest#call_automate_event) Raised event [request_starting] to Automate
[----] I, [2018-03-07T10:44:02.821843 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(ServiceTemplateProvisionTask#create_child_tasks) - creating service tasks for service <ServiceTemplateProvisionTask:13> with parent service <none>
[----] I, [2018-03-07T10:44:03.039271 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(ServiceTemplateContainerTemplate.automate_result_include_service_template?) Include Service Template <test> : <true>
[----] I, [2018-03-07T10:44:03.190936 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) Setting Service Owning User to Name=Administrator, ID=1, Group to Name=EvmGroup-super_administrator, ID=2
[----] I, [2018-03-07T10:44:03.195764 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(ServiceTemplateProvisionTask#create_child_tasks) - created <0> service tasks for service <ServiceTemplateProvisionTask:13> with parent service <none>
[----] I, [2018-03-07T10:44:03.202692 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(ServiceTemplateProvisionTask#deliver_to_automate) Queuing Service_Template_Provisioning: [Provisioning [test] for Service [test]]...
[----] I, [2018-03-07T10:44:03.212669 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(MiqQueue.put) Message id: [39125],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ServiceTemplateProvisionTask", :object_id=>13, :namespace=>"Service/Generic/StateMachines", :class_name=>"GenericLifecycle", :instance_name=>"provision", :automate_message=>"create", :attrs=>{"dialog_option_0_number_of_vms"=>"5", "request"=>"clone_to_service", :service_action=>"Provision", "Service::Service"=>1}, :user_id=>1, :miq_group_id=>2, :tenant_id=>1}]
[----] I, [2018-03-07T10:44:03.234010 #893:2aabaed24f54]  INFO -- : Q-task_id([service_template_provision_request_3]) MIQ(MiqQueue#delivered) Message id: [39123], State: [ok], Delivered in [1.80196688] seconds

Gap in Power state of a VM

Unlike the traditional providers, Kubevirt has VM scheduling like Kubernetes way, means VMs would have phases like Scheduling, Scheduled, Pending, or Failed in some cases.
The gap here is, even if the VM scheduling is failed, but it stays in vms, so in miq we see it as Powered On but that's not powered on actually. Or even Scheduling is like booting up for traditional vm, but here we just see it as Powered on, which is actually not the actual state.

Targeted refresh for VMs created on Openshift shows error

When doing a targeted refresh for a VM that was created directly on OpenShift and not via miq, shows the error in the Last refresh pane

Error - Less Than A Minute Ago
--
HTTP status code 404, offlinevirtualmachines.kubevirt.io "testvm-sata" not found

CrashLoopBackOff on kubevirt-infra-refresh pod - keeping restarting

On cloudforms infrastructure provider provider, I put in the kubeadmin creds and the validation is successful. However, the vm template that I have is not listed. Checking the kubevirt-infra-resfresh pods and they are in CrashLoopBackOff status. Here are a portion of the entries of the log:

{"@timestamp":"2020-09-18T18:20:11.070781 ","hostname":"1-kubevirt-infra-refresh-8-79b58f46d6-jnm7s","pid":7,"tid":"2b101062d964","level":"info","message":"MIQ(ManageIQ::Providers::Kubevirt::InfraManager::RefreshWorker::Runner#sync_config) ID [88], PID [7], GUID [3f6a0b93-8897-44b0-9430-c459ea515ede], Zone [default], Active Roles [automate,database_operations,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,remote_console,reporting,scheduler,smartproxy,smartstate,user_interface,web_services], Assigned Roles [automate,database_operations,database_owner,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,remote_console,reporting,scheduler,smartproxy,smartstate,user_interface,web_services], Configuration:"}
{"@timestamp":"2020-09-18T18:20:11.071360 ","hostname":"1-kubevirt-infra-refresh-8-79b58f46d6-jnm7s","pid":7,"tid":"2b101062d964","level":"info","message":"\n---\n:count: 1\n:cpu_threshold_percent: 50\n:gc_interval: 900\n:heartbeat_freq: 10\n:heartbeat_timeout: 120\n:memory_threshold: 2147483648\n:nice_delta: 7\n:parent_time_threshold: 180\n:poll: 10\n:poll_escalate_max: 30\n:poll_method: :normal\n:starting_timeout: 600\n:stopping_timeout: 600\n:systemd_enabled: false\n:dequeue_method: :sql\n:queue_timeout: 7200"}
{"@timestamp":"2020-09-18T18:20:11.071465 ","hostname":"1-kubevirt-infra-refresh-8-79b58f46d6-jnm7s","pid":7,"tid":"2b101062d964","level":"info","message":"---"}
{"@timestamp":"2020-09-18T18:20:11.071792 ","hostname":"1-kubevirt-infra-refresh-8-79b58f46d6-jnm7s","pid":7,"tid":"2b101062d964","level":"info","message":"\n---\n:ems_id: '8'\n:guid: 3f6a0b93-8897-44b0-9430-c459ea515ede"}
{"@timestamp":"2020-09-18T18:20:15.162093 ","hostname":"1-kubevirt-infra-refresh-8-79b58f46d6-jnm7s","pid":7,"tid":"2b101062d964","level":"info","message":"MIQ(ManageIQ::Providers::Kubernetes::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::Kubernetes::ContainerManager: [b-ocp-plus-7w-3.cp.fyre.ibm.com kubernetes provider]"}
/opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:419:in `rescue in detect_version': 404 Not Found (Fog::Kubevirt::Errors::ClientError)
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:416:in `detect_version'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:360:in `create_client_from_token'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:345:in `create_client'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:435:in `openshift_client'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:288:in `watch_templates'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/connection.rb:108:in `watch_templates'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/refresh_worker/runner.rb:208:in `block in start_watches'
        from /var/www/miq/vmdb/app/models/ext_management_system.rb:524:in `with_provider_connection'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/refresh_worker/runner.rb:204:in `start_watches'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/refresh_worker/runner.rb:56:in `do_before_work_loop'
        from /var/www/miq/vmdb/app/models/miq_worker/runner.rb:108:in `prepare'
        from /var/www/miq/vmdb/app/models/miq_worker/runner.rb:94:in `start'
        from /var/www/miq/vmdb/lib/workers/bin/run_single_worker.rb:113:in `<main>'
/opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:223:in `exception_with_response': 404 Not Found (RestClient::NotFound)
        from /opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:103:in `return!'
        from /opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/request.rb:809:in `process_result'
        from /opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/request.rb:725:in `block in transmit'
        from /usr/share/ruby/net/http.rb:920:in `start'
        from /opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/request.rb:715:in `transmit'
        from /opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/request.rb:145:in `execute'
        from /opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/request.rb:52:in `execute'
        from /opt/IBM/infrastructure-management-gemset/gems/rest-client-2.0.2/lib/restclient/resource.rb:51:in `get'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:417:in `detect_version'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:360:in `create_client_from_token'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:345:in `create_client'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:435:in `openshift_client'
        from /opt/IBM/infrastructure-management-gemset/gems/fog-kubevirt-1.3.4/lib/fog/kubevirt/compute/compute.rb:288:in `watch_templates'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/connection.rb:108:in `watch_templates'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/refresh_worker/runner.rb:208:in `block in start_watches'
        from /var/www/miq/vmdb/app/models/ext_management_system.rb:524:in `with_provider_connection'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/refresh_worker/runner.rb:204:in `start_watches'
        from /opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-providers-kubevirt-45d4b13928e9/app/models/manageiq/providers/kubevirt/infra_manager/refresh_worker/runner.rb:56:in `do_before_work_loop'
        from /var/www/miq/vmdb/app/models/miq_worker/runner.rb:108:in `prepare'
        from /var/www/miq/vmdb/app/models/miq_worker/runner.rb:94:in `start'
        from /var/www/miq/vmdb/lib/workers/bin/run_single_worker.rb:113:in `<main>'
{"@timestamp":"2020-09-18T18:20:15.766110 ","hostname":"1-kubevirt-infra-refresh-8-79b58f46d6-jnm7s","pid":7,"tid":"2b101062d964","level":"info","message":"MIQ(AuthToken#validation_successful) [ExtManagementSystem] [5], previously valid/invalid on: [2020-09-18 18:13:19 UTC]/[], previous status: [Valid]"}

Using the management-admin creds does not work either.

OCP version is 4.5.6.

[Tracker] Providr Refresh fails

This issue tracks [1]

[1] https://bugzilla.redhat.com/1593571

Infra provider not getting updated

After adding the Openshift provider with kubevirt for virtualization, I was able to see the infra provider, but that provider does not get refreshed like the container provider does. I've to manually do the refresh for the provider to fetch the data.

Creating a VM errors 'validation failure`

Creating a VM of the working-template from miq shows the below error

[EVM] VM [testing002] Step [CheckProvisioned] Status [Error Creating VM] Message [[KubeException]: OfflineVirtualMachine.kubevirt.io "testing002" is invalid: []: Invalid value: map[string]interface {}{"apiVersion":"kubevirt.io/v1alpha1", "kind":"Offlin...

evm.log for the same

[root@dhcp-8-58-212 log]# grep E, evm.log
[----] E, [2018-04-16T04:27:34.846219 #13123:34b138] ERROR -- : MIQ(MiqScheduleWorker::Runner) ID [19] PID [13123] GUID [faacd61c-4551-45f7-8a9e-dd6e68d2eb2c] Error in update_worker_record_at_exit: PG::ConnectionBad: PQsocket() can't get socket descriptor: SELECT  "miq_workers".* FROM "miq_workers" WHERE "miq_workers"."type" IN ('MiqScheduleWorker') AND "miq_workers"."id" = $1 LIMIT $2
[----] E, [2018-04-16T04:27:34.846632 #13123:34b138] ERROR -- : MIQ(MiqScheduleWorker::Runner) ID [19] PID [13123] GUID [faacd61c-4551-45f7-8a9e-dd6e68d2eb2c] An error has occurred during work processing: PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
[----] E, [2018-04-16T04:27:38.656738 #10909:34b138] ERROR -- : MIQ(MiqServer#monitor) PG::AdminShutdown: FATAL:  terminating connection due to administrator command
[----] E, [2018-04-16T04:27:38.656918 #10909:34b138] ERROR -- : [ActiveRecord::StatementInvalid]: PG::AdminShutdown: FATAL:  terminating connection due to administrator command
[----] E, [2018-04-16T04:27:38.657036 #10909:34b138] ERROR -- : /usr/local/lib/ruby/gems/2.3.0/gems/activerecord-5.0.7/lib/active_record/connection_adapters/postgresql_adapter.rb:608:in `exec_prepared'
[----] E, [2018-04-16T04:27:38.659115 #10909:34b138] ERROR -- : MIQ(MiqServer#monitor) invalid encoding name: utf8, during reconnect!
[----] E, [2018-04-16T04:27:43.946014 #13085:34b138] ERROR -- : MIQ(MiqPriorityWorker::Runner) ID [15] PID [13085] GUID [acabdf31-5807-4d67-9926-1519c5c954b5] Error in update_worker_record_at_exit: PG::ConnectionBad: PQconsumeInput() SSL connection has been closed unexpectedly
[----] E, [2018-04-16T04:27:43.953660 #13093:34b138] ERROR -- : MIQ(MiqPriorityWorker::Runner) ID [16] PID [13093] GUID [28c93bc3-deb5-46bc-b1d2-8ef4dccea230] Error in update_worker_record_at_exit: PG::ConnectionBad: PQconsumeInput() SSL connection has been closed unexpectedly
[----] E, [2018-04-16T04:27:43.953922 #13075:34b138] ERROR -- : MIQ(MiqGenericWorker::Runner) ID [14] PID [13075] GUID [e95ffd63-3e71-4c57-88fa-26f0d990b52b] Error in update_worker_record_at_exit: PG::ConnectionBad: PQconsumeInput() SSL connection has been closed unexpectedly
[----] E, [2018-04-16T04:27:43.967235 #13112:34b138] ERROR -- : MIQ(MiqReportingWorker::Runner) ID [18] PID [13112] GUID [f0237cc3-0f70-4f84-ba6c-ecf43910cd33] Error in update_worker_record_at_exit: PG::ConnectionBad: PQconsumeInput() SSL connection has been closed unexpectedly
[----] E, [2018-04-16T04:27:43.974303 #13058:34b138] ERROR -- : MIQ(MiqEventHandler::Runner) ID [12] PID [13058] GUID [23f048a3-973f-480c-bf4a-3eb5131c04a7] Error in update_worker_record_at_exit: PG::ConnectionBad: PQconsumeInput() SSL connection has been closed unexpectedly
[----] E, [2018-04-16T04:27:44.023267 #13104:34b138] ERROR -- : MIQ(MiqReportingWorker::Runner) ID [17] PID [13104] GUID [45d21138-4e79-4bed-8b58-a141b9259bab] Error in update_worker_record_at_exit: PG::ConnectionBad: PQconsumeInput() SSL connection has been closed unexpectedly
[----] E, [2018-04-16T04:27:44.038791 #13067:34b138] ERROR -- : MIQ(MiqGenericWorker::Runner) ID [13] PID [13067] GUID [87e0e702-6f9c-4084-961c-1a5bce603952] Error in update_worker_record_at_exit: PG::ConnectionBad: PQconsumeInput() SSL connection has been closed unexpectedly
[----] E, [2018-04-16T04:53:01.746137 #2028:1199140] ERROR -- : Q-task_id([r1_miq_provision_1]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#provision_error) [[KubeException]: OfflineVirtualMachine.kubevirt.io "vparekh.test" is invalid: []: Invalid value: map[string]interface {}{"spec":map[string]interface {}{"template":map[string]interface {}{"spec":map[string]interface {}{"domain":map[string]interface {}{"cpu":map[string]interface {}{"cores":4}, "devices":map[string]interface {}{"disks":[]interface {}{map[string]interface {}{"volumeName":"registryvolume", "disk":map[string]interface {}{"dev":"vda"}, "name":"registrydisk"}, map[string]interface {}{"disk":map[string]interface {}{"dev":"vdb"}, "name":"cloudinitdisk", "volumeName":"cloudinitvolume"}}}, "machine":map[string]interface {}{"type":"q35"}, "resources":map[string]interface {}{"requests":map[string]interface {}{"memory":"4096Mi"}}}, "volumes":[]interface {}{map[string]interface {}{"name":"registryvolume", "registryDisk":map[string]interface {}{"image":"kubevirt/fedora-cloud-registry-disk-demo:latest"}}, map[string]interface {}{"cloudInitNoCloud":map[string]interface {}{"userDataBase64":"I2Nsb3VkLWNvbmZpZwpwYXNzd29yZDogYXRvbWljCnNzaF9wd2F1dGg6IFRydWUKY2hwYXNzd2Q6IHsgZXhwaXJlOiBGYWxzZSB9Cg=="}, "name":"cloudinitvolume"}}}}}, "apiVersion":"kubevirt.io/v1alpha1", "kind":"OfflineVirtualMachine", "metadata":map[string]interface {}{"name":"vparekh.test", "namespace":"default", "labels":map[string]interface {}{"kubevirt.io/os":"rhel-7"}, "creationTimestamp":"2018-04-16T08:53:00Z", "uid":"9136fe1b-4153-11e8-baee-fa163e82a9bc", "selfLink":"", "clusterName":""}}: validation failure list:
[----] E, [2018-04-16T04:53:01.746289 #2028:1199140] ERROR -- : Q-task_id([r1_miq_provision_1]) /usr/local/lib/ruby/gems/2.3.0/gems/kubeclient-2.5.2/lib/kubeclient/common.rb:117:in `rescue in handle_exception'
[----] E, [2018-04-16T04:54:09.855204 #2036:1199140] ERROR -- : Q-task_id([r1_miq_provision_1]) MIQ(MiqAeEngine.deliver) Error delivering {"request"=>"vm_provision"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.1] with state [CheckProvisioned] to Automate: 
[----] E, [2018-04-16T05:02:28.031102 #2036:1199140] ERROR -- : MIQ(MiqAeEngine.deliver) Error delivering {:event_type=>"request_created", "EventStream::event_stream"=>118, :event_stream_id=>118} for object [MiqProvisionRequest.2] with state [] to Automate: 
[----] E, [2018-04-16T05:03:41.283041 #2036:1199140] ERROR -- : Q-task_id([r2_miq_provision_2]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#provision_error) [[KubeException]: OfflineVirtualMachine.kubevirt.io "testing001" is invalid: []: Invalid value: map[string]interface {}{"apiVersion":"kubevirt.io/v1alpha1", "kind":"OfflineVirtualMachine", "metadata":map[string]interface {}{"uid":"0e6b59e1-4155-11e8-baee-fa163e82a9bc", "selfLink":"", "clusterName":"", "name":"testing001", "namespace":"default", "labels":map[string]interface {}{"kubevirt.io/os":"rhel-7"}, "creationTimestamp":"2018-04-16T09:03:40Z"}, "spec":map[string]interface {}{"template":map[string]interface {}{"spec":map[string]interface {}{"domain":map[string]interface {}{"cpu":map[string]interface {}{"cores":4}, "devices":map[string]interface {}{"disks":[]interface {}{map[string]interface {}{"disk":map[string]interface {}{"dev":"vda"}, "name":"registrydisk", "volumeName":"registryvolume"}, map[string]interface {}{"name":"cloudinitdisk", "volumeName":"cloudinitvolume", "disk":map[string]interface {}{"dev":"vdb"}}}}, "machine":map[string]interface {}{"type":"q35"}, "resources":map[string]interface {}{"requests":map[string]interface {}{"memory":"1024Mi"}}}, "volumes":[]interface {}{map[string]interface {}{"name":"registryvolume", "registryDisk":map[string]interface {}{"image":"kubevirt/fedora-cloud-registry-disk-demo:latest"}}, map[string]interface {}{"cloudInitNoCloud":map[string]interface {}{"userDataBase64":"I2Nsb3VkLWNvbmZpZwpwYXNzd29yZDogYXRvbWljCnNzaF9wd2F1dGg6IFRydWUKY2hwYXNzd2Q6IHsgZXhwaXJlOiBGYWxzZSB9Cg=="}, "name":"cloudinitvolume"}}}}}}: validation failure list:
[----] E, [2018-04-16T05:03:41.283194 #2036:1199140] ERROR -- : Q-task_id([r2_miq_provision_2]) /usr/local/lib/ruby/gems/2.3.0/gems/kubeclient-2.5.2/lib/kubeclient/common.rb:117:in `rescue in handle_exception'
[----] E, [2018-04-16T05:03:47.165339 #2028:1199140] ERROR -- : Q-task_id([r2_miq_provision_3]) MIQ(ManageIQ::Providers::Kubevirt::InfraManager::Provision#provision_error) [[KubeException]: OfflineVirtualMachine.kubevirt.io "testing002" is invalid: []: Invalid value: map[string]interface {}{"apiVersion":"kubevirt.io/v1alpha1", "kind":"OfflineVirtualMachine", "metadata":map[string]interface {}{"creationTimestamp":"2018-04-16T09:03:46Z", "uid":"11ecff7c-4155-11e8-baee-fa163e82a9bc", "selfLink":"", "clusterName":"", "name":"testing002", "namespace":"default", "labels":map[string]interface {}{"kubevirt.io/os":"rhel-7"}}, "spec":map[string]interface {}{"template":map[string]interface {}{"spec":map[string]interface {}{"domain":map[string]interface {}{"cpu":map[string]interface {}{"cores":4}, "devices":map[string]interface {}{"disks":[]interface {}{map[string]interface {}{"disk":map[string]interface {}{"dev":"vda"}, "name":"registrydisk", "volumeName":"registryvolume"}, map[string]interface {}{"disk":map[string]interface {}{"dev":"vdb"}, "name":"cloudinitdisk", "volumeName":"cloudinitvolume"}}}, "machine":map[string]interface {}{"type":"q35"}, "resources":map[string]interface {}{"requests":map[string]interface {}{"memory":"1024Mi"}}}, "volumes":[]interface {}{map[string]interface {}{"name":"registryvolume", "registryDisk":map[string]interface {}{"image":"kubevirt/fedora-cloud-registry-disk-demo:latest"}}, map[string]interface {}{"cloudInitNoCloud":map[string]interface {}{"userDataBase64":"I2Nsb3VkLWNvbmZpZwpwYXNzd29yZDogYXRvbWljCnNzaF9wd2F1dGg6IFRydWUKY2hwYXNzd2Q6IHsgZXhwaXJlOiBGYWxzZSB9Cg=="}, "name":"cloudinitvolume"}}}}}}: validation failure list:
[----] E, [2018-04-16T05:03:47.165483 #2028:1199140] ERROR -- : Q-task_id([r2_miq_provision_3]) /usr/local/lib/ruby/gems/2.3.0/gems/kubeclient-2.5.2/lib/kubeclient/common.rb:117:in `rescue in handle_exception'
[----] E, [2018-04-16T05:04:47.525291 #2028:1199140] ERROR -- : Q-task_id([r2_miq_provision_2]) MIQ(MiqAeEngine.deliver) Error delivering {"request"=>"vm_provision"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.2] with state [CheckProvisioned] to Automate: 
[----] E, [2018-04-16T05:04:53.487052 #2036:1199140] ERROR -- : Q-task_id([r2_miq_provision_3]) MIQ(MiqAeEngine.deliver) Error delivering {"request"=>"vm_provision"} for object [ManageIQ::Providers::Kubevirt::InfraManager::Provision.3] with state [CheckProvisioned] to Automate: 
[----] E, [2018-04-16T05:21:28.860134 #2046:1199140] ERROR -- : MIQ(MiqAeEngine.deliver) Error delivering {:event_id=>128, :event_stream_id=>128, :event_type=>"POD_UNHEALTHY"} for object [EmsEvent.128] with state [] to Automate: Empty Workspace

working-template used for this

[fedora@vparekh-automation-provider ~]$ oc get template working -n default -o yaml
apiVersion: template.openshift.io/v1
kind: Template
metadata:
  annotations:
    description: OCP kubevirt linux, template
    tags: kubevirt,ocp,template,linux
  creationTimestamp: 2018-04-16T08:47:27Z
  labels:
    kubevirt.io/os: rhel-7
    miq.github.io/kubevirt-is-vm-template: "true"
  name: working
  namespace: default
  resourceVersion: "1821"
  selfLink: /apis/template.openshift.io/v1/namespaces/default/templates/working
  uid: caac5cce-4152-11e8-baee-fa163e82a9bc
objects:
- apiVersion: kubevirt.io/v1alpha1
  kind: OfflineVirtualMachine
  metadata:
    name: ${NAME}
  spec:
    template:
      spec:
        domain:
          cpu:
            cores: ${CPU_CORES}
          devices:
            disks:
            - disk:
                dev: vda
              name: registrydisk
              volumeName: registryvolume
            - disk:
                dev: vdb
              name: cloudinitdisk
              volumeName: cloudinitvolume
          machine:
            type: q35
          resources:
            requests:
              memory: ${MEMORY}
        volumes:
        - name: registryvolume
          registryDisk:
            image: kubevirt/fedora-cloud-registry-disk-demo:latest
        - cloudInitNoCloud:
            userDataBase64: I2Nsb3VkLWNvbmZpZwpwYXNzd29yZDogYXRvbWljCnNzaF9wd2F1dGg6IFRydWUKY2hwYXNzd2Q6IHsgZXhwaXJlOiBGYWxzZSB9Cg==
          name: cloudinitvolume
parameters:
- description: Name for the new VM
  name: NAME
- description: Amount of memory in MB
  name: MEMORY
  value: 512Mi
- description: Amount of cores
  name: CPU_CORES
  value: "4"

Provisioning VM via service catalog fails

Unlike #43 , just provisioning a service catalog with a dummy dialog also gives error
Generic Service Error: Server [EVM] Service [test] Provision Step [pre4] Status [Error Processing Preprocess]
automation.log for the request

[----] I, [2018-05-22T09:49:51.528716 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2018-05-22T09:49:52.005635 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Instantiating [/Service/Generic/StateMachines/GenericLifecycle/provision?MiqServer%3A%3Amiq_server=1&Service%3A%3AService=1&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=1&User%3A%3Auser=1&dialog_text_box_1=test&object_name=provision&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task]
[----] I, [2018-05-22T09:49:52.289946 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [/Service/Generic/StateMachines/GenericLifecycle/provision?MiqServer%3A%3Amiq_server=1&Service%3A%3AService=1&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=1&User%3A%3Auser=1&dialog_text_box_1=test&object_name=provision&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task  ManageIQ/Service/Generic/StateMachines]
[----] I, [2018-05-22T09:49:53.141345 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) In State=[start], invoking [on_entry] method=[update_status(status => 'Processing Start')]
[----] I, [2018-05-22T09:49:53.145665 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [Service/Generic/StateMachines/GenericLifecycle/update_status  ManageIQ/Service/Generic/StateMachines]
[----] I, [2018-05-22T09:49:53.165663 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Invoking [inline] method [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status] with inputs [{"status"=>"Processing Start"}]
[----] I, [2018-05-22T09:49:53.167552 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Starting 
[----] I, [2018-05-22T09:49:54.536970 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Ending
[----] I, [2018-05-22T09:49:54.537132 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Method exited with rc=MIQ_OK
[----] I, [2018-05-22T09:49:54.537633 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processing State=[start]
[----] I, [2018-05-22T09:49:54.542771 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [Service/Generic/StateMachines/GenericLifecycle/start  ManageIQ/Service/Generic/StateMachines]
[----] I, [2018-05-22T09:49:54.553579 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Invoking [inline] method [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/start] with inputs [{}]
[----] I, [2018-05-22T09:49:54.554832 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/start]> Starting 
[----] I, [2018-05-22T09:49:55.339474 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/start]> Ending
[----] I, [2018-05-22T09:49:55.339756 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Method exited with rc=MIQ_OK
[----] I, [2018-05-22T09:49:55.340319 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processed State=[start] with Result=[ok]
[----] I, [2018-05-22T09:49:55.340507 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processed State=[start]
[----] I, [2018-05-22T09:49:55.340777 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) In State=[start], invoking [on_exit] method=[update_status(status => 'Processed Start')]
[----] I, [2018-05-22T09:49:55.346813 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [Service/Generic/StateMachines/GenericLifecycle/update_status  ManageIQ/Service/Generic/StateMachines]
[----] I, [2018-05-22T09:49:55.352094 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Invoking [inline] method [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status] with inputs [{"status"=>"Processed Start"}]
[----] I, [2018-05-22T09:49:55.354445 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Starting 
[----] I, [2018-05-22T09:49:56.278794 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Ending
[----] I, [2018-05-22T09:49:56.279061 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Method exited with rc=MIQ_OK
[----] I, [2018-05-22T09:49:56.280061 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Next State=[pre0]
[----] I, [2018-05-22T09:49:56.280611 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processed State=[pre0]
[----] I, [2018-05-22T09:49:56.280973 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Next State=[pre1]
[----] I, [2018-05-22T09:49:56.281402 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processed State=[pre1]
[----] I, [2018-05-22T09:49:56.281778 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Next State=[pre2]
[----] I, [2018-05-22T09:49:56.282159 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processed State=[pre2]
[----] I, [2018-05-22T09:49:56.282522 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Next State=[pre3]
[----] I, [2018-05-22T09:49:56.282914 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processed State=[pre3]
[----] I, [2018-05-22T09:49:56.283271 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Next State=[pre4]
[----] I, [2018-05-22T09:49:56.283709 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) In State=[pre4], invoking [on_entry] method=[update_status(status => 'Processing Preprocess')]
[----] I, [2018-05-22T09:49:56.289912 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [Service/Generic/StateMachines/GenericLifecycle/update_status  ManageIQ/Service/Generic/StateMachines]
[----] I, [2018-05-22T09:49:56.295299 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Invoking [inline] method [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status] with inputs [{"status"=>"Processing Preprocess"}]
[----] I, [2018-05-22T09:49:56.297296 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Starting 
[----] I, [2018-05-22T09:49:57.256280 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Ending
[----] I, [2018-05-22T09:49:57.256541 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Method exited with rc=MIQ_OK
[----] I, [2018-05-22T09:49:57.257148 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processing State=[pre4]
[----] I, [2018-05-22T09:49:57.263732 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [Service/Generic/StateMachines/GenericLifecycle/preprocess  ManageIQ/Service/Generic/StateMachines]
[----] I, [2018-05-22T09:49:57.283547 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Invoking [inline] method [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/preprocess] with inputs [{}]
[----] I, [2018-05-22T09:49:57.285849 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/preprocess]> Starting 
[----] I, [2018-05-22T09:49:58.251138 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/preprocess]> Ending
[----] I, [2018-05-22T09:49:58.251409 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Method exited with rc=MIQ_OK
[----] I, [2018-05-22T09:49:58.251975 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Processed State=[pre4] with Result=[error]
[----] W, [2018-05-22T09:49:58.252152 #11924:813134]  WARN -- : Q-task_id([r1_service_template_provision_task_1]) Error in State=[pre4]
[----] I, [2018-05-22T09:49:58.252442 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) In State=[pre4], invoking [on_error] method=[update_status(status => 'Error Processing Preprocess')]
[----] I, [2018-05-22T09:49:58.259419 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [Service/Generic/StateMachines/GenericLifecycle/update_status  ManageIQ/Service/Generic/StateMachines]
[----] I, [2018-05-22T09:49:58.265893 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Invoking [inline] method [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status] with inputs [{"status"=>"Error Processing Preprocess"}]
[----] I, [2018-05-22T09:49:58.268480 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Starting 
[----] I, [2018-05-22T09:49:59.251671 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) <AEMethod [/ManageIQ/Service/Generic/StateMachines/GenericLifecycle/update_status]> Ending
[----] I, [2018-05-22T09:49:59.251835 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Method exited with rc=MIQ_OK
[----] I, [2018-05-22T09:49:59.414198 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MiqAeEvent.build_evm_event >> event=<:service_provisioned> inputs=<{"MiqEvent::miq_event"=>1081, :miq_event_id=>1081, "EventStream::event_stream"=>1081, :event_stream_id=>1081}>
[----] I, [2018-05-22T09:50:01.414074 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2018-05-22T09:50:02.008517 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=1081&MiqEvent%3A%3Amiq_event=1081&MiqServer%3A%3Amiq_server=1&Service%3A%3Aservice=1&User%3A%3Auser=1&event_stream_id=1081&event_type=service_provisioned&miq_event_id=1081&object_name=Event&vmdb_object_type=service]
[----] I, [2018-05-22T09:50:02.056896 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=1081&MiqEvent%3A%3Amiq_event=1081&MiqServer%3A%3Amiq_server=1&Service%3A%3Aservice=1&User%3A%3Auser=1&event_stream_id=1081&event_type=service_provisioned&miq_event_id=1081&object_name=Event&vmdb_object_type=service  ManageIQ/System]
[----] I, [2018-05-22T09:50:02.206740 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/service_provisioned#create]
[----] I, [2018-05-22T09:50:02.230156 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/service_provisioned#create  ManageIQ/System/Event/MiqEvent]
[----] I, [2018-05-22T09:50:02.254103 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Instance [/ManageIQ/System/Event/MiqEvent/POLICY/service_provisioned] not found in MiqAeDatastore - trying [.missing]
[----] I, [2018-05-22T09:50:02.265095 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2018-05-22T09:50:02.270292 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create  ManageIQ/System]
[----] I, [2018-05-22T09:50:02.278904 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Updated namespace [System/event_handlers/event_enforce_policy  ManageIQ/System]
[----] I, [2018-05-22T09:50:02.286125 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2018-05-22T09:50:02.295165 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Followed  Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2018-05-22T09:50:02.296318 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) Followed  Relationship [miqaedb:/System/Event/MiqEvent/POLICY/service_provisioned#create]

evm.log for the same

[----] I, [2018-05-22T09:49:51.523161 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqQueue#deliver) Message id: [19949], Delivering...
[----] I, [2018-05-22T09:49:51.528919 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqAeEngine.deliver) Delivering {"dialog_text_box_1"=>"test", "request"=>"clone_to_service", :service_action=>"Provision", "Service::Service"=>1} for object [ServiceTemplateProvisionTask.1] with state [] to Automate
[----] I, [2018-05-22T09:49:51.711571 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(ServiceTemplateProvisionTask#before_ae_starts) Executing Service_Template_Provisioning request: [Provisioning [test] for Service [test]]
[----] E, [2018-05-22T09:49:59.253265 #11924:813134] ERROR -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqAeEngine.deliver) Error delivering {"dialog_text_box_1"=>"test", "request"=>"clone_to_service", :service_action=>"Provision", "Service::Service"=>1} for object [ServiceTemplateProvisionTask.1] with state [] to Automate: 
[----] I, [2018-05-22T09:49:59.253490 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(ServiceTemplateProvisionTask#after_ae_delivery) ae_result="error"
[----] I, [2018-05-22T09:49:59.466621 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqQueue.put) Message id: [19951],  id: [], Zone: [default], Role: [automate], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ServiceContainerTemplate", :object_id=>1, :attrs=>{:event_type=>:service_provisioned, "MiqEvent::miq_event"=>1081, :miq_event_id=>1081, "EventStream::event_stream"=>1081, :event_stream_id=>1081}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2018-05-22T09:49:59.467143 #11924:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqQueue#delivered) Message id: [19949], State: [ok], Delivered in [7.944003384] seconds
[----] I, [2018-05-22T09:50:01.402585 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqQueue#deliver) Message id: [19951], Delivering...
[----] I, [2018-05-22T09:50:01.414428 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqAeEngine.deliver) Delivering {:event_type=>:service_provisioned, "MiqEvent::miq_event"=>1081, :miq_event_id=>1081, "EventStream::event_stream"=>1081, :event_stream_id=>1081} for object [ServiceContainerTemplate.1] with state [] to Automate
[----] I, [2018-05-22T09:50:02.294572 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqEvent#process_evm_event) target = [#<ServiceContainerTemplate id: 1, name: "test", description: "test", guid: "0e4005dc-e06b-42c3-a160-8fca76f3cb0e", type: "ServiceContainerTemplate", service_template_id: 1, options: {:config_info=>{:provision=>{:container_template_id=>"24", :dialog_id=>"2", :fqname=>"/Service/Generic/StateMachines/GenericLifecycle/provision"}}, :dialog=>{"dialog_text_box_1"=>"test"}}, display: true, created_at: "2018-05-22 13:49:46", updated_at: "2018-05-22 13:49:46", evm_owner_id: 1, miq_group_id: 2, retired: false, retires_on: nil, retirement_warn: nil, retirement_last_warn: nil, retirement_state: nil, retirement_requester: nil, tenant_id: 1, ancestry: nil, initiator: "user">]
[----] I, [2018-05-22T09:50:02.297827 #11933:813134]  INFO -- : Q-task_id([r1_service_template_provision_task_1]) MIQ(MiqQueue#delivered) Message id: [19951], State: [ok], Delivered in [0.895261785] seconds

issue

Unknown OS

When creating VMs from the working-template, the VMs are showing unknown in Operating System, but the template has rhel-7 in the Operating System.
Shouldn't it get the same?

Targeted refresh for VM created via Miq shows error

Doing targeted refresh for VMs created via Miq (lifecycle) on KubeVirt results in error in Last refresh pane


Error - Less Than A Minute Ago
--
HTTP status code 404, templates "vparekh-test-linux" not found

[Tracker] Cannot power off a VM in phase: failed

This issue was created to track kubevirt/kubevirt#1052

validating Virtualization token gives 401 error

When editing the container provider, if the default was invalid, and it was validated in this change, validating virtualization with correct token would give 401 error

Duplicate templates in service catalog

There's just one template on provider, and seeing the same one in Infra->VM, but when making a service catalog it shows 2 template of the same name

Manual refresh of the infra provider doesn't update anything

When doing the manual refresh for the infra provider added from KubeVirt virtualization on OpenShift container provider, the refresh gives no error but the data is not updated in the miq.
@pkliczewski found that this could be due to the missing cpu spec in the testvm that was created on openshift side.
So we need to be more flexible in parsing the specs

issue pulling image

I see that on downstream cluster, registry:5000 doesn't have this image, and fails to resolve for docker hub as well

manageiq-providers-kubevirt/manifests/working-template.yml

Line 53 in be32cb5

image: registry:5000/kubevirt/fedora-cloud-registry-disk-demo:devel

@pkliczewski @masayag should we just keep it to kubevirt/fedora-cloud-registry-disk-demo?

Extra buttons

On Add new Provider and Edit Provider, these 2 extra buttons are there

Dependency Dashboard

This issue lists Renovate updates and detected dependencies. Read the Dependency Dashboard docs to learn more.

This repository currently has no open or pending branches.

Detected dependencies

github-actions

.github/workflows/ci.yaml

actions/checkout v4

ruby/setup-ruby v1

paambaati/codeclimate-action v6

manageiq/postgresql 13

Check this box to trigger a request for Renovate to run again on this repository

[RFE] Should give option to select storageclass

Though there are no option at the moment to select anything related to storage, but when implemented, it should have option to select the storageclass as well available on the cluster

[Regression] Cannot retire VM

Retiring one or multiple VMs goes to requests but fails with last message : Server [EVM] Step [StartRetirement] Status [Error Starting Retirement] Cannot continue because VM is .

Automation log for the same request

[----] I, [2018-05-16T04:03:38.438533 #2157:12578d4]  INFO -- : <AEMethod miqprovision_complete> VM Owner: #<MiqAeServiceUser:0x187b88c @object=#<User id: 1, name: "Administrator", email: nil, icon: nil, created_on: "2018-05-12 17:22:49", updated_on: "2018-05-16 07:46:53", userid: "admin", settings: {}, lastlogon: "2018-05-16 07:46:53", lastlogoff: "2018-05-15 11:12:11", current_group_id: 2, first_name: nil, last_name: nil, password_digest: "$2a$10$5AS2pdyFH5gvfLtPlZJq8e3KBY.cdmceBWSSWm0Zrl4...">, @virtual_columns=["allocated_memory", "allocated_storage", "allocated_vcpu", "custom_1", "custom_2", "custom_3", "custom_4", "custom_5", "custom_6", "custom_7", "custom_8", "custom_9", "href_slug", "ldap_group", "miq_group_description", "miq_user_role_name", "provisioned_storage", "region_description", "region_number"], @associations=["current_group", "current_tenant", "miq_groups", "miq_requests", "vms"]>
[----] I, [2018-05-16T04:07:18.999252 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) MiqAeEvent.build_evm_event >> event=<"request_starting"> inputs=<{"EventStream::event_stream"=>10479, :event_stream_id=>10479}>
[----] I, [2018-05-16T04:07:19.003707 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2018-05-16T04:07:19.011001 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=10479&MiqRequest%3A%3Amiq_request=5&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmRetireRequest%3A%3Avm_retire_request=5&event_stream_id=10479&event_type=request_starting&object_name=Event&vmdb_object_type=vm_retire_request]
[----] I, [2018-05-16T04:07:19.041650 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=10479&MiqRequest%3A%3Amiq_request=5&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmRetireRequest%3A%3Avm_retire_request=5&event_stream_id=10479&event_type=request_starting&object_name=Event&vmdb_object_type=vm_retire_request  ManageIQ/System]
[----] I, [2018-05-16T04:07:19.179082 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Following Relationship [miqaedb:/System/Event/RequestEvent/Request/request_starting#create]
[----] I, [2018-05-16T04:07:19.191898 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [miqaedb:/System/Event/RequestEvent/Request/request_starting#create  ManageIQ/System/Event/RequestEvent]
[----] I, [2018-05-16T04:07:19.214072 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Following Relationship [miqaedb:/System/Policy/request_starting#create]
[----] I, [2018-05-16T04:07:19.218441 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [miqaedb:/System/Policy/request_starting#create  ManageIQ/System]
[----] I, [2018-05-16T04:07:19.227929 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [System/Policy/get_request_type  ManageIQ/System]
[----] I, [2018-05-16T04:07:19.232986 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Invoking [inline] method [/ManageIQ/System/Policy/get_request_type] with inputs [{}]
[----] I, [2018-05-16T04:07:19.234344 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) <AEMethod [/ManageIQ/System/Policy/get_request_type]> Starting 
[----] I, [2018-05-16T04:07:19.994332 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) <AEMethod [/ManageIQ/System/Policy/get_request_type]> Ending
[----] I, [2018-05-16T04:07:19.994498 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Method exited with rc=MIQ_OK
[----] I, [2018-05-16T04:07:19.995340 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Following Relationship [miqaedb:/System/Process/parse_provider_category#create]
[----] I, [2018-05-16T04:07:19.998918 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [miqaedb:/System/Process/parse_provider_category#create  ManageIQ/System]
[----] I, [2018-05-16T04:07:20.007916 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [System/Process/parse_provider_category  ManageIQ/System]
[----] I, [2018-05-16T04:07:20.015611 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Invoking [builtin] method [/ManageIQ/System/Process/parse_provider_category] with inputs [{}]
[----] I, [2018-05-16T04:07:20.017148 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Setting provider_category to: 
[----] I, [2018-05-16T04:07:20.018273 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Followed  Relationship [miqaedb:/System/Process/parse_provider_category#create]
[----] I, [2018-05-16T04:07:20.018670 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Following Relationship [miqaedb:/System/Policy/VmRetireRequest_starting#create]
[----] I, [2018-05-16T04:07:20.021231 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [miqaedb:/System/Policy/VmRetireRequest_starting#create  ManageIQ/System]
[----] I, [2018-05-16T04:07:20.028164 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Following Relationship [miqaedb:/System/Process/parse_provider_category#create]
[----] I, [2018-05-16T04:07:20.029694 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [miqaedb:/System/Process/parse_provider_category#create  ManageIQ/System]
[----] I, [2018-05-16T04:07:20.037079 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Updated namespace [System/Process/parse_provider_category  ManageIQ/System]
[----] I, [2018-05-16T04:07:20.037237 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Invoking [builtin] method [/ManageIQ/System/Process/parse_provider_category] with inputs [{}]
[----] I, [2018-05-16T04:07:20.038562 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Setting provider_category to: 
[----] I, [2018-05-16T04:07:20.039475 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Followed  Relationship [miqaedb:/System/Process/parse_provider_category#create]
[----] I, [2018-05-16T04:07:20.039904 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Following Relationship [miqaedb:/unknown/VM/Lifecycle/Retirement?vm_id=#create]
[----] E, [2018-05-16T04:07:20.082834 #2165:124d140] ERROR -- : Q-task_id([r5_vm_retire_request_5]) Class [unknown/VM/Lifecycle] not found in MiqAeDatastore
[----] I, [2018-05-16T04:07:20.083023 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Followed  Relationship [miqaedb:/unknown/VM/Lifecycle/Retirement?vm_id=#create]
[----] I, [2018-05-16T04:07:20.083577 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Followed  Relationship [miqaedb:/System/Policy/VmRetireRequest_starting#create]
[----] I, [2018-05-16T04:07:20.083978 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Followed  Relationship [miqaedb:/System/Policy/request_starting#create]
[----] I, [2018-05-16T04:07:20.084386 #2165:124d140]  INFO -- : Q-task_id([r5_vm_retire_request_5]) Followed  Relationship [miqaedb:/System/Event/RequestEvent/Request/request_starting#create]

evm.log

[----] E, [2018-05-16T04:14:55.349906 #2157:124d140] ERROR -- : Q-task_id([r7_vm_retire_task_9]) MIQ(MiqAeEngine.deliver) Error delivering {"request"=>"vm_retire", "VmOrTemplate::Vm"=>126} for object [VmRetireTask.9] with state [] to Automate: