Azure Provisioning never completes

Open kTipSSIoYv opened this issue 3 years ago • 11 comments

@Fryguy @agrare With the following patch I still see a issue. The catalog request doesn't finish at all. I've applied only the 515 patch.

I see virtual machine end requests but as you can see it doesn't finish. Its kind of in a loop with publicIPAddresses_write_EndRequest and virtualMachines_write_EndRequest

[----] I, [2022-08-06T19:55:06.763592 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:06.852560 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:06.852963 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:06.862501 #312:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-06T19:55:06.864663 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28314&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28314&event_stream_id=28314&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream]
[----] I, [2022-08-06T19:55:06.877554 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28314&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28314&event_stream_id=28314&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-06T19:55:06.898868 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:06.902703 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-06T19:55:06.909855 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:06.913260 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-06T19:55:06.922350 #312:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-06T19:55:06.923740 #312:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-06T19:55:06.933732 #314:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-06T19:55:06.934922 #314:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28315&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28315&event_stream_id=28315&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream]
[----] I, [2022-08-06T19:55:06.939350 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:06.939569 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:06.941911 #314:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28315&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28315&event_stream_id=28315&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-06T19:55:06.954888 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:06.958501 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-06T19:55:06.965350 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:06.968875 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-06T19:55:06.977659 #314:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-06T19:55:06.978935 #314:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-06T19:55:06.985933 #312:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-06T19:55:06.987183 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28316&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28316&event_stream_id=28316&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream]
[----] I, [2022-08-06T19:55:06.993897 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28316&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28316&event_stream_id=28316&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-06T19:55:07.007698 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:07.011502 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-06T19:55:07.018629 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:07.022056 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-06T19:55:07.030499 #312:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-06T19:55:07.031854 #312:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-06T19:55:07.034503 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:07.034874 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:07.104359 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:07.104762 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:07.107190 #314:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-06T19:55:07.108756 #314:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28317&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28317&event_stream_id=28317&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream]
[----] I, [2022-08-06T19:55:07.116246 #314:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28317&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28317&event_stream_id=28317&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-06T19:55:07.130856 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:07.135105 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-06T19:55:07.142610 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:07.146480 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-06T19:55:07.157131 #314:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-06T19:55:07.158533 #314:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-06T19:55:07.219915 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:07.220143 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:36.320945 #312:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-06T19:55:36.322588 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28318&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1394&event_id=28318&event_stream_id=28318&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1394&vmdb_object_type=event_stream]
[----] I, [2022-08-06T19:55:36.332502 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28318&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1394&event_id=28318&event_stream_id=28318&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1394&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-06T19:55:36.351420 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:55:36.355930 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-06T19:55:36.365239 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:36.370014 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-06T19:55:36.380745 #312:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-06T19:55:36.382447 #312:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-06T19:55:36.416344 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:55:36.416587 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:56:11.681441 #312:95b0]  INFO -- automation: User [admin] with current group ID [1] name [Tenant My Company/1 access]
[----] I, [2022-08-06T19:56:11.683531 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28319&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28319&event_stream_id=28319&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream]
[----] I, [2022-08-06T19:56:11.695889 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28319&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28319&event_stream_id=28319&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-06T19:56:11.717938 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-06T19:56:11.724331 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-06T19:56:11.735116 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:56:11.739932 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-06T19:56:11.749807 #312:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-06T19:56:11.751241 #312:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-06T19:56:11.776193 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:56:11.776447 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-06T19:56:47.109870 #314:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-06T19:56:47.111181 #314:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28320&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28320&event_stream_id=28320&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream]
[----] I, [2022-08-06T19:56:47.119135 #314:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28320&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1393&event_id=28320&event_stream_id=28320&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1393&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-06T19:56:47.134659 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-06T19:56:47.139270 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-06T19:56:47.146837 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:56:47.150552 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-06T19:56:47.159555 #314:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-06T19:56:47.161002 #314:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-06T19:56:47.194057 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-06T19:56:47.194314 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]

Aug 08 '22 13:08 kTipSSIoYv

If you got to PostProvision then you made it past the issue that https://github.com/ManageIQ/manageiq-providers-azure/pull/515 fixed. Can you post the automation log snipped from the PostProvision section?

Here is mine for reference:

INFO -- automation: Q-task_id([r2_miq_provision_2]) Next State=[PostProvision]
INFO -- automation: Q-task_id([r2_miq_provision_2]) In State=[PostProvision], invoking [on_entry] method=[update_provision_status(status => 'Applying PostProvision Customizations')]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Updated namespace [Cloud/VM/Provisioning/StateMachines/VMProvision_vm/update_provision_status  ManageIQ/Cloud/VM/Provisioning/StateMachines]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Invoking [inline] method [/ManageIQ/Cloud/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status] with inputs [{"status"=>"Applying PostProvision Customizations"}]
INFO -- automation: Q-task_id([r2_miq_provision_2]) <AEMethod [/ManageIQ/Cloud/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status]> Starting
INFO -- automation: Q-task_id([r2_miq_provision_2]) <AEMethod [/ManageIQ/Cloud/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status]> Ending
INFO -- automation: Q-task_id([r2_miq_provision_2]) Method exited with rc=MIQ_OK
INFO -- automation: Q-task_id([r2_miq_provision_2]) Processing State=[PostProvision]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Following Relationship [miqaedb:/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision#azure]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Updated namespace [miqaedb:/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision#azure  ManageIQ/Cloud/VM/Provisioning/StateMachines]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Updated namespace [Cloud/VM/Provisioning/StateMachines/Methods/postprovision  ManageIQ/Cloud/VM/Provisioning/StateMachines]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Invoking [inline] method [/ManageIQ/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision] with inputs [{}]
INFO -- automation: Q-task_id([r2_miq_provision_2]) <AEMethod [/ManageIQ/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision]> Starting
INFO -- automation: Q-task_id([r2_miq_provision_2]) <AEMethod postprovision> Provisioning ID:<2> Provision Request ID:<2> Provision Type: <template>
INFO -- automation: Q-task_id([r2_miq_provision_2]) <AEMethod [/ManageIQ/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision]> Ending
INFO -- automation: Q-task_id([r2_miq_provision_2]) Method exited with rc=MIQ_OK
INFO -- automation: Q-task_id([r2_miq_provision_2]) Followed  Relationship [miqaedb:/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision#azure]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Processed State=[PostProvision] with Result=[ok]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Processed State=[PostProvision]
INFO -- automation: Q-task_id([r2_miq_provision_2]) In State=[PostProvision], invoking [on_exit] method=[update_provision_status(status => 'Applied PostProvision Customizations')]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Updated namespace [Cloud/VM/Provisioning/StateMachines/VMProvision_vm/update_provision_status  ManageIQ/Cloud/VM/Provisioning/StateMachines]
INFO -- automation: Q-task_id([r2_miq_provision_2]) Invoking [inline] method [/ManageIQ/Cloud/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status] with inputs [{"status"=>"Applied PostProvision Customizations"}]

Do you have any automate domain customizations?

Aug 08 '22 14:08 agrare

@agrare I'm running a method during postProvision to implement a security group. It's a method to run ansible Playbook during post provision.

[----] I, [2022-08-08T15:03:34.430503 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Next State=[PostProvision]
[----] I, [2022-08-08T15:03:34.434325 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) In State=[PostProvision], invoking [on_entry] method=[update_provision_status(status => 'Applying PostProvision Customizations')]
[----] I, [2022-08-08T15:03:34.457172 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Updated namespace [Cloud/VM/Provisioning/StateMachines/VMProvision_vm/update_provision_status  ManageIQ/Cloud/VM/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:34.466445 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Invoking [inline] method [/ManageIQ/Cloud/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status] with inputs [{"status"=>"Applying PostProvision Customizations"}]
[----] I, [2022-08-08T15:03:34.468996 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod [/ManageIQ/Cloud/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status]> Starting 
[----] I, [2022-08-08T15:03:34.934491 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod [/ManageIQ/Cloud/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status]> Ending
[----] I, [2022-08-08T15:03:34.936176 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:03:34.937925 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Processing State=[PostProvision]
[----] I, [2022-08-08T15:03:34.938264 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Following Relationship [miqaedb:/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision#azure]
[----] I, [2022-08-08T15:03:34.964813 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Updated namespace [miqaedb:/Cloud/VM/Provisioning/StateMachines/Methods/PostProvision#azure  ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:35.003638 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Updated namespace [Cloud/VM/Provisioning/StateMachines/Methods/ansible_azure_sg_provisioning  ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:35.011141 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Invoking [inline] method [/ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines/Methods/Ansible_azure_SG_Provisioning] with inputs [{}]
[----] I, [2022-08-08T15:03:35.012140 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod [/ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines/Methods/Ansible_azure_SG_Provisioning]> Starting 
[----] I, [2022-08-08T15:03:35.295081 #310:79a838]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> Found provider: Azure via default method
[----] I, [2022-08-08T15:03:35.297934 #310:79a838]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> vm_root value is: 1395 
[----] I, [2022-08-08T15:03:35.309480 #310:79a838]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> vm_target_name_1 value is: Ubuntu971 
[----] I, [2022-08-08T15:03:35.378659 #310:79a89c]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> VM ID is 1395
[----] I, [2022-08-08T15:03:35.380512 #310:79a89c]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> instance_name is Ubuntu971
[----] I, [2022-08-08T15:03:35.515193 #310:79a89c]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> TESTING
[----] I, [2022-08-08T15:03:35.517618 #310:79a89c]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> instance_rg is cloud-shell-storage-centralindia
[----] I, [2022-08-08T15:03:35.518997 #310:79a89c]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> TESTING
[----] I, [2022-08-08T15:03:35.520624 #310:79a89c]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> TESTING
[----] I, [2022-08-08T15:03:35.521885 #310:79a838]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> instance_name is: Ubuntu971
[----] I, [2022-08-08T15:03:35.522426 #310:79a838]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod ansible_azure_sg_provisioning> instance_rg is: cloud-shell-storage-centralindia
[----] I, [2022-08-08T15:03:36.061201 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) <AEMethod [/ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines/Methods/Ansible_azure_SG_Provisioning]> Ending
[----] I, [2022-08-08T15:03:36.061307 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:03:36.075576 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Updated namespace [Cloud/VM/Provisioning/StateMachines/Methods/ansible_azure_sg_playbook  ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:36.091787 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Invoking [playbook] method [/ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines/Methods/Ansible_azure_SG_Playbook] with inputs [{"vm_name"=>"Ubuntu971", "resource_group"=>"cloud-shell-storage-centralindia", "sg_name"=>"", "sg_ssh_cidr"=>"0.0.0.0/0", "sg_rules"=>"", "sg_create_new"=>"0", "sg_create_rules"=>"0"}]
[----] I, [2022-08-08T15:03:36.873936 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Playbook Method passing options:
[----] I, [2022-08-08T15:03:36.874632 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) 
---
:become_enabled: false
:execution_ttl: '15'
:extra_vars:
  vm_name: Ubuntu971
  resource_group: cloud-shell-storage-centralindia
  sg_name: ''
  sg_ssh_cidr: 0.0.0.0/0
  sg_rules: ''
  sg_create_new: '0'
  sg_create_rules: '0'
  :manageiq:
    automate_workspace: automate_workspaces/a33c36b6-dfa0-4319-99c0-3d82fec699b0
    api_url: https://172.17.0.2
    api_token: 23fa285e97d30d5a74d28d30e0191e91
    user: users/1
    group: groups/2
    X_MIQ_Group: EvmGroup-super_administrator
    request_task: requests/1088/request_tasks/2795
    request: requests/1088
  :manageiq_connection:
    url: https://172.17.0.2
    token: 23fa285e97d30d5a74d28d30e0191e91
    X_MIQ_Group: EvmGroup-super_administrator
:hosts:
- localhost
:verbosity: '3'
:credential: 1
:cloud_credential: 128
[----] I, [2022-08-08T15:03:37.982091 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Ansible job with ref 66694 was created.
[----] I, [2022-08-08T15:03:42.525152 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:03:42.536490 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Instantiating [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%203%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=3&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create]
[----] I, [2022-08-08T15:03:42.542743 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%203%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=3&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:42.559967 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processing State=[checkprovisioned]
[----] I, [2022-08-08T15:03:42.560142 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:03:42.568188 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:42.577961 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_provisioned  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:42.580347 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned] with inputs [{}]
[----] I, [2022-08-08T15:03:42.581341 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Starting 
[----] I, [2022-08-08T15:03:42.827019 #308:68ac18]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Listing Root Object Attributes:
[----] I, [2022-08-08T15:03:42.831040 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_next_state: 
[----] I, [2022-08-08T15:03:42.832210 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_result: ok
[----] I, [2022-08-08T15:03:42.833211 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_retry_server_affinity: false
[----] I, [2022-08-08T15:03:42.834281 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state: checkprovisioned
[----] I, [2022-08-08T15:03:42.835246 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_max_retries: 100
[----] I, [2022-08-08T15:03:42.836183 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_retries: 3
[----] I, [2022-08-08T15:03:42.837235 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_started: 2022-08-08 15:00:31 UTC
[----] I, [2022-08-08T15:03:42.838407 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_step: main
[----] I, [2022-08-08T15:03:42.839336 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_network: 17
[----] I, [2022-08-08T15:03:42.840297 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_subnet: 22
[----] I, [2022-08-08T15:03:42.841192 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_create_sg_rules: 0
[----] I, [2022-08-08T15:03:42.842217 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_instance_type: 959
[----] I, [2022-08-08T15:03:42.843179 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_number_of_vms: 1
[----] I, [2022-08-08T15:03:42.844183 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_placement_availability_zone: 5
[----] I, [2022-08-08T15:03:42.845202 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_resource_group: 6
[----] I, [2022-08-08T15:03:42.846325 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_security_groups: 206
[----] I, [2022-08-08T15:03:42.847558 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_create_new: 0
[----] I, [2022-08-08T15:03:42.848647 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_name: 
[----] I, [2022-08-08T15:03:42.849698 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_rules: 
[----] I, [2022-08-08T15:03:42.850847 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_ssh_cidr: 0.0.0.0/0
[----] I, [2022-08-08T15:03:42.851768 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_src_vm_id: 940
[----] I, [2022-08-08T15:03:42.852837 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_vm_name: Ubuntu
[----] I, [2022-08-08T15:03:42.854191 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x000055b87bdffc30>
[----] I, [2022-08-08T15:03:42.855887 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x000055b87c4c6618>
[----] I, [2022-08-08T15:03:42.856867 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server_id: 7
[----] I, [2022-08-08T15:03:42.857880 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	object_name: CatalogItemInitialization
[----] I, [2022-08-08T15:03:42.858969 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	request: clone_to_service
[----] I, [2022-08-08T15:03:42.860406 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service: #<MiqAeMethodService::MiqAeServiceService:0x000055b87c4c3120>
[----] I, [2022-08-08T15:03:42.861497 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_action: Provision
[----] I, [2022-08-08T15:03:42.862664 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_id: 1014
[----] I, [2022-08-08T15:03:42.864305 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task: #<MiqAeMethodService::MiqAeServiceServiceTemplateProvisionTask:0x000055b87c4bc398>
[----] I, [2022-08-08T15:03:42.865423 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task_id: 2793
[----] I, [2022-08-08T15:03:42.866962 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x000055b87c4b4120>
[----] I, [2022-08-08T15:03:42.868485 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user: #<MiqAeMethodService::MiqAeServiceUser:0x000055b87c4b4a58>
[----] I, [2022-08-08T15:03:42.869465 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user_id: 1
[----] I, [2022-08-08T15:03:42.870590 #308:68ac68]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	vmdb_object_type: service_template_provision_task
[----] I, [2022-08-08T15:03:42.871746 #308:68ac18]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> ===========================================
[----] I, [2022-08-08T15:03:42.875220 #308:68ac18]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Service ProvisionCheck returned <ok> for state <provisioned> and status <Ok>
[----] I, [2022-08-08T15:03:42.882331 #308:68ac18]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Child tasks not finished. Setting retry for task: 2793 
[----] I, [2022-08-08T15:03:42.897006 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Ending
[----] I, [2022-08-08T15:03:42.897120 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:03:42.897554 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Followed  Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:03:42.897707 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processed State=[checkprovisioned] with Result=[retry]
[----] I, [2022-08-08T15:03:42.897958 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) In State=[checkprovisioned], invoking [on_exit] method=[update_serviceprovision_status(status => 'Creating Service')]
[----] I, [2022-08-08T15:03:42.902955 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:42.907200 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{"status"=>"Creating Service"}]
[----] I, [2022-08-08T15:03:42.908546 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting 
[----] I, [2022-08-08T15:03:43.310279 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2022-08-08T15:03:43.310402 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:03:50.598774 #308:95b0]  INFO -- automation: User [admin] with current group ID [1] name [Tenant My Company/1 access]
[----] I, [2022-08-08T15:03:50.604279 #308:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28774&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28774&event_stream_id=28774&event_type=disks_write_BeginRequest&object_name=Event&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:03:50.621735 #308:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28774&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28774&event_stream_id=28774&event_type=disks_write_BeginRequest&object_name=Event&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:03:50.644687 #308:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/disks_write_BeginRequest#create]
[----] I, [2022-08-08T15:03:50.654600 #308:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/disks_write_BeginRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:03:50.657557 #308:95b0]  INFO -- automation: Instance [/ManageIQ/System/Event/EmsEvent/AZURE/disks_write_BeginRequest] not found in MiqAeDatastore - trying [.missing]
[----] I, [2022-08-08T15:03:50.663590 #308:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/disks_write_BeginRequest#create]
[----] I, [2022-08-08T15:03:50.677909 #312:95b0]  INFO -- automation: User [admin] with current group ID [1] name [Tenant My Company/1 access]
[----] I, [2022-08-08T15:03:50.679846 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28775&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28775&event_stream_id=28775&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:03:50.690073 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28775&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28775&event_stream_id=28775&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:03:50.703581 #314:95b0]  INFO -- automation: User [admin] with current group ID [1] name [Tenant My Company/1 access]
[----] I, [2022-08-08T15:03:50.716910 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-08T15:03:50.722000 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:03:50.733474 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:03:50.740196 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-08T15:03:50.754809 #312:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-08T15:03:50.757480 #312:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-08T15:03:50.798958 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:03:50.799514 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-08T15:03:50.812495 #314:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28776&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28776&event_stream_id=28776&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:03:50.820664 #314:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28776&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28776&event_stream_id=28776&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:03:50.836409 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-08T15:03:50.840795 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:03:50.848602 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:03:50.853011 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-08T15:03:50.862837 #314:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-08T15:03:50.864532 #314:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-08T15:03:50.941082 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:03:50.941442 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-08T15:04:08.351211 #312:95b0]  INFO -- automation: User [admin] with current group ID [1] name [Tenant My Company/1 access]
[----] I, [2022-08-08T15:04:08.352740 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28777&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28777&event_stream_id=28777&event_type=disks_write_EndRequest&object_name=Event&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:04:08.362359 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28777&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28777&event_stream_id=28777&event_type=disks_write_EndRequest&object_name=Event&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:04:08.382997 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/disks_write_EndRequest#create]
[----] I, [2022-08-08T15:04:08.396058 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/disks_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:04:08.399071 #312:95b0]  INFO -- automation: Instance [/ManageIQ/System/Event/EmsEvent/AZURE/disks_write_EndRequest] not found in MiqAeDatastore - trying [.missing]
[----] I, [2022-08-08T15:04:08.405490 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/disks_write_EndRequest#create]
[----] I, [2022-08-08T15:04:08.430832 #314:95b0]  INFO -- automation: User [admin] with current group ID [1] name [Tenant My Company/1 access]
[----] I, [2022-08-08T15:04:08.432502 #314:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28778&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28778&event_stream_id=28778&event_type=publicIPAddresses_write_BeginRequest&object_name=Event&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:04:08.441278 #314:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28778&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28778&event_stream_id=28778&event_type=publicIPAddresses_write_BeginRequest&object_name=Event&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:04:08.457906 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_BeginRequest#create]
[----] I, [2022-08-08T15:04:08.472596 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_BeginRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:04:08.475388 #314:95b0]  INFO -- automation: Instance [/ManageIQ/System/Event/EmsEvent/AZURE/publicIPAddresses_write_BeginRequest] not found in MiqAeDatastore - trying [.missing]
[----] I, [2022-08-08T15:04:08.481064 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_BeginRequest#create]
[----] I, [2022-08-08T15:04:09.359149 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:04:09.367481 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Instantiating [/Service/Provisioning/StateMachines/ServiceProvision_Template/clone_to_service?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2794&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2Fclone_to_service%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%203%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A56%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=3&ae_state_started=2022-08-08%2015%3A00%3A56%20UTC&object_name=clone_to_service&request=clone_to_service&vmdb_object_type=service_template_provision_task#create]
[----] I, [2022-08-08T15:04:09.374153 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/clone_to_service?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2794&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2Fclone_to_service%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%203%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A56%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=3&ae_state_started=2022-08-08%2015%3A00%3A56%20UTC&object_name=clone_to_service&request=clone_to_service&vmdb_object_type=service_template_provision_task#create  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:09.391936 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Processing State=[checkprovisioned]
[----] I, [2022-08-08T15:04:09.392117 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:04:09.399905 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:09.411179 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_provisioned  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:09.413573 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned] with inputs [{}]
[----] I, [2022-08-08T15:04:09.414599 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Starting 
[----] I, [2022-08-08T15:04:09.685257 #308:68c608]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Listing Root Object Attributes:
[----] I, [2022-08-08T15:04:09.690774 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_next_state: 
[----] I, [2022-08-08T15:04:09.692695 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_result: ok
[----] I, [2022-08-08T15:04:09.694873 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_retry_server_affinity: false
[----] I, [2022-08-08T15:04:09.696902 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state: checkprovisioned
[----] I, [2022-08-08T15:04:09.698753 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_max_retries: 100
[----] I, [2022-08-08T15:04:09.701372 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_retries: 3
[----] I, [2022-08-08T15:04:09.703621 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_started: 2022-08-08 15:00:56 UTC
[----] I, [2022-08-08T15:04:09.705912 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_step: main
[----] I, [2022-08-08T15:04:09.709520 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x000055b87597e428>
[----] I, [2022-08-08T15:04:09.711879 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x000055b87598caf0>
[----] I, [2022-08-08T15:04:09.714344 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_server_id: 7
[----] I, [2022-08-08T15:04:09.716427 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	object_name: clone_to_service
[----] I, [2022-08-08T15:04:09.718835 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	request: clone_to_service
[----] I, [2022-08-08T15:04:09.723284 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service: #<MiqAeMethodService::MiqAeServiceService:0x000055b875988748>
[----] I, [2022-08-08T15:04:09.725233 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_id: 1014
[----] I, [2022-08-08T15:04:09.728682 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_template_provision_task: #<MiqAeMethodService::MiqAeServiceServiceTemplateProvisionTask:0x000055b875983630>
[----] I, [2022-08-08T15:04:09.730608 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_template_provision_task_id: 2794
[----] I, [2022-08-08T15:04:09.733676 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x000055b87597ec20>
[----] I, [2022-08-08T15:04:09.736370 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	user: #<MiqAeMethodService::MiqAeServiceUser:0x000055b87597f468>
[----] I, [2022-08-08T15:04:09.738742 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	user_id: 1
[----] I, [2022-08-08T15:04:09.741014 #308:68c658]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	vmdb_object_type: service_template_provision_task
[----] I, [2022-08-08T15:04:09.742855 #308:68c608]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> ===========================================
[----] I, [2022-08-08T15:04:09.750518 #308:68c608]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Service ProvisionCheck returned <ok> for state <provisioned> and status <Ok>
[----] I, [2022-08-08T15:04:09.760702 #308:68c608]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Child tasks not finished. Setting retry for task: 2794 
[----] I, [2022-08-08T15:04:09.776913 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Ending
[----] I, [2022-08-08T15:04:09.777096 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:04:09.777439 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Followed  Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:04:09.777636 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Processed State=[checkprovisioned] with Result=[retry]
[----] I, [2022-08-08T15:04:09.777955 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) In State=[checkprovisioned], invoking [on_exit] method=[update_serviceprovision_status(status => 'Creating Service')]
[----] I, [2022-08-08T15:04:09.783943 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:09.789717 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Invoking [inline] method [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{"status"=>"Creating Service"}]
[----] I, [2022-08-08T15:04:09.790671 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting 
[----] I, [2022-08-08T15:04:10.190556 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2022-08-08T15:04:10.190724 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:04:51.022890 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:04:51.053329 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Instantiating [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%204%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=4&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create]
[----] I, [2022-08-08T15:04:51.065081 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%204%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=4&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:51.090843 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processing State=[checkprovisioned]
[----] I, [2022-08-08T15:04:51.091079 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:04:51.099555 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:51.110298 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_provisioned  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:51.112771 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned] with inputs [{}]
[----] I, [2022-08-08T15:04:51.113663 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Starting 
[----] I, [2022-08-08T15:04:51.380052 #308:68e5d4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Listing Root Object Attributes:
[----] I, [2022-08-08T15:04:51.384773 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_next_state: 
[----] I, [2022-08-08T15:04:51.385879 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_result: ok
[----] I, [2022-08-08T15:04:51.386935 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_retry_server_affinity: false
[----] I, [2022-08-08T15:04:51.388020 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state: checkprovisioned
[----] I, [2022-08-08T15:04:51.388980 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_max_retries: 100
[----] I, [2022-08-08T15:04:51.390174 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_retries: 4
[----] I, [2022-08-08T15:04:51.391285 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_started: 2022-08-08 15:00:31 UTC
[----] I, [2022-08-08T15:04:51.392265 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_step: main
[----] I, [2022-08-08T15:04:51.393424 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_network: 17
[----] I, [2022-08-08T15:04:51.394477 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_subnet: 22
[----] I, [2022-08-08T15:04:51.395556 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_create_sg_rules: 0
[----] I, [2022-08-08T15:04:51.396634 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_instance_type: 959
[----] I, [2022-08-08T15:04:51.397677 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_number_of_vms: 1
[----] I, [2022-08-08T15:04:51.398745 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_placement_availability_zone: 5
[----] I, [2022-08-08T15:04:51.399791 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_resource_group: 6
[----] I, [2022-08-08T15:04:51.400786 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_security_groups: 206
[----] I, [2022-08-08T15:04:51.401857 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_create_new: 0
[----] I, [2022-08-08T15:04:51.402786 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_name: 
[----] I, [2022-08-08T15:04:51.403853 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_rules: 
[----] I, [2022-08-08T15:04:51.404965 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_ssh_cidr: 0.0.0.0/0
[----] I, [2022-08-08T15:04:51.406015 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_src_vm_id: 940
[----] I, [2022-08-08T15:04:51.407035 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_vm_name: Ubuntu
[----] I, [2022-08-08T15:04:51.408785 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x000055b873d76410>
[----] I, [2022-08-08T15:04:51.410335 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x000055b873d861f8>
[----] I, [2022-08-08T15:04:51.411778 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server_id: 7
[----] I, [2022-08-08T15:04:51.413035 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	object_name: CatalogItemInitialization
[----] I, [2022-08-08T15:04:51.414179 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	request: clone_to_service
[----] I, [2022-08-08T15:04:51.415735 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service: #<MiqAeMethodService::MiqAeServiceService:0x000055b873d82c88>
[----] I, [2022-08-08T15:04:51.416820 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_action: Provision
[----] I, [2022-08-08T15:04:51.417894 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_id: 1014
[----] I, [2022-08-08T15:04:51.419488 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task: #<MiqAeMethodService::MiqAeServiceServiceTemplateProvisionTask:0x000055b873d7d328>
[----] I, [2022-08-08T15:04:51.420532 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task_id: 2793
[----] I, [2022-08-08T15:04:51.422067 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x000055b873d76be0>
[----] I, [2022-08-08T15:04:51.423850 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user: #<MiqAeMethodService::MiqAeServiceUser:0x000055b873d77400>
[----] I, [2022-08-08T15:04:51.425106 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user_id: 1
[----] I, [2022-08-08T15:04:51.426327 #308:68e624]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	vmdb_object_type: service_template_provision_task
[----] I, [2022-08-08T15:04:51.427612 #308:68e5d4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> ===========================================
[----] I, [2022-08-08T15:04:51.431263 #308:68e5d4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Service ProvisionCheck returned <ok> for state <provisioned> and status <Ok>
[----] I, [2022-08-08T15:04:51.438047 #308:68e5d4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Child tasks not finished. Setting retry for task: 2793 
[----] I, [2022-08-08T15:04:51.452878 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Ending
[----] I, [2022-08-08T15:04:51.452994 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:04:51.453323 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Followed  Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:04:51.453498 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processed State=[checkprovisioned] with Result=[retry]
[----] I, [2022-08-08T15:04:51.453707 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) In State=[checkprovisioned], invoking [on_exit] method=[update_serviceprovision_status(status => 'Creating Service')]
[----] I, [2022-08-08T15:04:51.459449 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:04:51.464361 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{"status"=>"Creating Service"}]
[----] I, [2022-08-08T15:04:51.465198 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting 
[----] I, [2022-08-08T15:04:51.877613 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2022-08-08T15:04:51.877735 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:05:10.316980 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:05:10.339674 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Instantiating [/Service/Provisioning/StateMachines/ServiceProvision_Template/clone_to_service?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2794&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2Fclone_to_service%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%204%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A56%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=4&ae_state_started=2022-08-08%2015%3A00%3A56%20UTC&object_name=clone_to_service&request=clone_to_service&vmdb_object_type=service_template_provision_task#create]
[----] I, [2022-08-08T15:05:10.352153 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/clone_to_service?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2794&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2Fclone_to_service%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%204%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A56%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=4&ae_state_started=2022-08-08%2015%3A00%3A56%20UTC&object_name=clone_to_service&request=clone_to_service&vmdb_object_type=service_template_provision_task#create  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:10.375137 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Processing State=[checkprovisioned]
[----] I, [2022-08-08T15:05:10.375375 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:05:10.392751 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:10.404459 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_provisioned  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:10.406813 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned] with inputs [{}]
[----] I, [2022-08-08T15:05:10.407590 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Starting 
[----] I, [2022-08-08T15:05:10.672340 #308:68f72c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Listing Root Object Attributes:
[----] I, [2022-08-08T15:05:10.748495 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_next_state: 
[----] I, [2022-08-08T15:05:10.750255 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_result: ok
[----] I, [2022-08-08T15:05:10.751784 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_retry_server_affinity: false
[----] I, [2022-08-08T15:05:10.753152 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state: checkprovisioned
[----] I, [2022-08-08T15:05:10.754450 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_max_retries: 100
[----] I, [2022-08-08T15:05:10.756344 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_retries: 4
[----] I, [2022-08-08T15:05:10.757843 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_started: 2022-08-08 15:00:56 UTC
[----] I, [2022-08-08T15:05:10.759017 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_step: main
[----] I, [2022-08-08T15:05:10.760537 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x000055b8736ca3f0>
[----] I, [2022-08-08T15:05:10.761979 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x000055b8736d8928>
[----] I, [2022-08-08T15:05:10.763207 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_server_id: 7
[----] I, [2022-08-08T15:05:10.764078 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	object_name: clone_to_service
[----] I, [2022-08-08T15:05:10.765288 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	request: clone_to_service
[----] I, [2022-08-08T15:05:10.766985 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service: #<MiqAeMethodService::MiqAeServiceService:0x000055b8736d52c8>
[----] I, [2022-08-08T15:05:10.767988 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_id: 1014
[----] I, [2022-08-08T15:05:10.769396 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_template_provision_task: #<MiqAeMethodService::MiqAeServiceServiceTemplateProvisionTask:0x000055b8736cfad0>
[----] I, [2022-08-08T15:05:10.770747 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_template_provision_task_id: 2794
[----] I, [2022-08-08T15:05:10.773585 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x000055b8736caf58>
[----] I, [2022-08-08T15:05:10.775910 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	user: #<MiqAeMethodService::MiqAeServiceUser:0x000055b8736cba70>
[----] I, [2022-08-08T15:05:10.777192 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	user_id: 1
[----] I, [2022-08-08T15:05:10.778253 #308:68f77c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	vmdb_object_type: service_template_provision_task
[----] I, [2022-08-08T15:05:10.779409 #308:68f72c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> ===========================================
[----] I, [2022-08-08T15:05:10.782881 #308:68f72c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Service ProvisionCheck returned <ok> for state <provisioned> and status <Ok>
[----] I, [2022-08-08T15:05:10.790646 #308:68f72c]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Child tasks not finished. Setting retry for task: 2794 
[----] I, [2022-08-08T15:05:10.810365 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Ending
[----] I, [2022-08-08T15:05:10.810524 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:05:10.810876 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Followed  Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:05:10.811026 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Processed State=[checkprovisioned] with Result=[retry]
[----] I, [2022-08-08T15:05:10.811413 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) In State=[checkprovisioned], invoking [on_exit] method=[update_serviceprovision_status(status => 'Creating Service')]
[----] I, [2022-08-08T15:05:10.817122 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:10.823301 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Invoking [inline] method [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{"status"=>"Creating Service"}]
[----] I, [2022-08-08T15:05:10.824386 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting 
[----] I, [2022-08-08T15:05:11.218944 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2022-08-08T15:05:11.219079 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:05:22.957063 #312:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:05:22.958526 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28779&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1395&event_id=28779&event_stream_id=28779&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1395&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:05:22.967082 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28779&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1395&event_id=28779&event_stream_id=28779&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1395&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:05:22.983351 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-08T15:05:22.988363 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:05:22.999348 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:05:23.004584 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-08T15:05:23.021018 #312:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-08T15:05:23.023538 #312:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-08T15:05:23.062682 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:05:23.063100 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-08T15:05:40.204633 #312:95b0]  INFO -- automation: User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:05:40.206524 #312:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28780&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1395&event_id=28780&event_stream_id=28780&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1395&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:05:40.214687 #312:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28780&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=1395&event_id=28780&event_stream_id=28780&event_type=virtualMachines_write_EndRequest&object_name=Event&vm_id=1395&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:05:40.231043 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-08T15:05:40.235473 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:05:40.243981 #312:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:05:40.248307 #312:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-08T15:05:40.258228 #312:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-08T15:05:40.278764 #312:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-08T15:05:40.280120 #314:95b0]  INFO -- automation: User [admin] with current group ID [1] name [Tenant My Company/1 access]
[----] I, [2022-08-08T15:05:40.281719 #314:95b0]  INFO -- automation: Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=28781&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28781&event_stream_id=28781&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream]
[----] I, [2022-08-08T15:05:40.289388 #314:95b0]  INFO -- automation: Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=28781&MiqServer%3A%3Amiq_server=7&User%3A%3Auser=1&event_id=28781&event_stream_id=28781&event_type=publicIPAddresses_write_EndRequest&object_name=Event&vmdb_object_type=event_stream  ManageIQ/System]
[----] I, [2022-08-08T15:05:40.302140 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:05:40.302474 #312:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/virtualMachines_write_EndRequest#create]
[----] I, [2022-08-08T15:05:40.302494 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-08T15:05:40.307154 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create  ManageIQ/System/Event/EmsEvent]
[----] I, [2022-08-08T15:05:40.314679 #314:95b0]  INFO -- automation: Following Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:05:40.319044 #314:95b0]  INFO -- automation: Updated namespace [miqaedb:/System/event_handlers/refresh#create  ManageIQ/System]
[----] I, [2022-08-08T15:05:40.328772 #314:95b0]  INFO -- automation: Updated namespace [System/event_handlers/refresh  ManageIQ/System]
[----] I, [2022-08-08T15:05:40.330361 #314:95b0]  INFO -- automation: Invoking [builtin] method [/ManageIQ/System/event_handlers/refresh] with inputs [{}]
[----] I, [2022-08-08T15:05:40.377462 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/event_handlers/refresh#create]
[----] I, [2022-08-08T15:05:40.377780 #314:95b0]  INFO -- automation: Followed  Relationship [miqaedb:/System/Event/EmsEvent/AZURE/publicIPAddresses_write_EndRequest#create]
[----] I, [2022-08-08T15:05:54.552947 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:05:54.563452 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Instantiating [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%205%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=5&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create]
[----] I, [2022-08-08T15:05:54.569736 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%205%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=5&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:54.586230 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processing State=[checkprovisioned]
[----] I, [2022-08-08T15:05:54.586402 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:05:54.593669 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:54.603512 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_provisioned  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:54.605484 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned] with inputs [{}]
[----] I, [2022-08-08T15:05:54.606531 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Starting 
[----] I, [2022-08-08T15:05:54.904500 #308:6915f4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Listing Root Object Attributes:
[----] I, [2022-08-08T15:05:54.908635 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_next_state: 
[----] I, [2022-08-08T15:05:54.909821 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_result: ok
[----] I, [2022-08-08T15:05:54.910931 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_retry_server_affinity: false
[----] I, [2022-08-08T15:05:54.912031 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state: checkprovisioned
[----] I, [2022-08-08T15:05:54.913155 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_max_retries: 100
[----] I, [2022-08-08T15:05:54.914253 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_retries: 5
[----] I, [2022-08-08T15:05:54.915199 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_started: 2022-08-08 15:00:31 UTC
[----] I, [2022-08-08T15:05:54.916280 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_step: main
[----] I, [2022-08-08T15:05:54.917246 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_network: 17
[----] I, [2022-08-08T15:05:54.918232 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_subnet: 22
[----] I, [2022-08-08T15:05:54.919244 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_create_sg_rules: 0
[----] I, [2022-08-08T15:05:54.920168 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_instance_type: 959
[----] I, [2022-08-08T15:05:54.921280 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_number_of_vms: 1
[----] I, [2022-08-08T15:05:54.922320 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_placement_availability_zone: 5
[----] I, [2022-08-08T15:05:54.923418 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_resource_group: 6
[----] I, [2022-08-08T15:05:54.924318 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_security_groups: 206
[----] I, [2022-08-08T15:05:54.925328 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_create_new: 0
[----] I, [2022-08-08T15:05:54.926511 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_name: 
[----] I, [2022-08-08T15:05:54.927747 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_rules: 
[----] I, [2022-08-08T15:05:54.928892 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_ssh_cidr: 0.0.0.0/0
[----] I, [2022-08-08T15:05:54.930038 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_src_vm_id: 940
[----] I, [2022-08-08T15:05:54.931034 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_vm_name: Ubuntu
[----] I, [2022-08-08T15:05:54.932441 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x000055b872976d48>
[----] I, [2022-08-08T15:05:54.934034 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x000055b872984218>
[----] I, [2022-08-08T15:05:54.935047 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server_id: 7
[----] I, [2022-08-08T15:05:54.936233 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	object_name: CatalogItemInitialization
[----] I, [2022-08-08T15:05:54.937411 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	request: clone_to_service
[----] I, [2022-08-08T15:05:54.939251 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service: #<MiqAeMethodService::MiqAeServiceService:0x000055b872981590>
[----] I, [2022-08-08T15:05:54.940433 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_action: Provision
[----] I, [2022-08-08T15:05:54.941518 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_id: 1014
[----] I, [2022-08-08T15:05:54.942930 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task: #<MiqAeMethodService::MiqAeServiceServiceTemplateProvisionTask:0x000055b87297b500>
[----] I, [2022-08-08T15:05:54.944186 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task_id: 2793
[----] I, [2022-08-08T15:05:54.945623 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x000055b872977978>
[----] I, [2022-08-08T15:05:54.947016 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user: #<MiqAeMethodService::MiqAeServiceUser:0x000055b872978328>
[----] I, [2022-08-08T15:05:54.948150 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user_id: 1
[----] I, [2022-08-08T15:05:54.949028 #308:691644]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	vmdb_object_type: service_template_provision_task
[----] I, [2022-08-08T15:05:54.949969 #308:6915f4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> ===========================================
[----] I, [2022-08-08T15:05:54.953491 #308:6915f4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Service ProvisionCheck returned <ok> for state <provisioned> and status <Ok>
[----] I, [2022-08-08T15:05:54.959780 #308:6915f4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Child tasks not finished. Setting retry for task: 2793 
[----] I, [2022-08-08T15:05:54.973720 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Ending
[----] I, [2022-08-08T15:05:54.973839 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:05:54.974158 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Followed  Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:05:54.974387 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processed State=[checkprovisioned] with Result=[retry]
[----] I, [2022-08-08T15:05:54.974607 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) In State=[checkprovisioned], invoking [on_exit] method=[update_serviceprovision_status(status => 'Creating Service')]
[----] I, [2022-08-08T15:05:54.979989 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:05:54.984563 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{"status"=>"Creating Service"}]
[----] I, [2022-08-08T15:05:54.985563 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting 
[----] I, [2022-08-08T15:05:55.400691 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2022-08-08T15:05:55.400907 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited wi
[----] I, [2022-08-08T15:06:17.006910 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:06:17.025275 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Instantiating [/Service/Provisioning/StateMachines/ServiceProvision_Template/clone_to_service?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2794&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2Fclone_to_service%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%205%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A56%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=5&ae_state_started=2022-08-08%2015%3A00%3A56%20UTC&object_name=clone_to_service&request=clone_to_service&vmdb_object_type=service_template_provision_task#create]
[----] I, [2022-08-08T15:06:17.043376 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/clone_to_service?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2794&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2Fclone_to_service%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%205%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A56%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=5&ae_state_started=2022-08-08%2015%3A00%3A56%20UTC&object_name=clone_to_service&request=clone_to_service&vmdb_object_type=service_template_provision_task#create  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:06:17.068604 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Processing State=[checkprovisioned]
[----] I, [2022-08-08T15:06:17.068942 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:06:17.078632 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:06:17.092185 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_provisioned  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:06:17.095047 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned] with inputs [{}]
[----] I, [2022-08-08T15:06:17.096179 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Starting 
[----] I, [2022-08-08T15:06:17.360786 #308:692774]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Listing Root Object Attributes:
[----] I, [2022-08-08T15:06:17.365030 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_next_state: 
[----] I, [2022-08-08T15:06:17.366549 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_result: ok
[----] I, [2022-08-08T15:06:17.367708 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_retry_server_affinity: false
[----] I, [2022-08-08T15:06:17.368867 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state: checkprovisioned
[----] I, [2022-08-08T15:06:17.369998 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_max_retries: 100
[----] I, [2022-08-08T15:06:17.371010 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_retries: 5
[----] I, [2022-08-08T15:06:17.372117 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_started: 2022-08-08 15:00:56 UTC
[----] I, [2022-08-08T15:06:17.373146 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	ae_state_step: main
[----] I, [2022-08-08T15:06:17.374667 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x000055b87253ce80>
[----] I, [2022-08-08T15:06:17.376067 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x000055b87254b610>
[----] I, [2022-08-08T15:06:17.377032 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	miq_server_id: 7
[----] I, [2022-08-08T15:06:17.378050 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	object_name: clone_to_service
[----] I, [2022-08-08T15:06:17.379069 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	request: clone_to_service
[----] I, [2022-08-08T15:06:17.380537 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service: #<MiqAeMethodService::MiqAeServiceService:0x000055b8725491f8>
[----] I, [2022-08-08T15:06:17.381665 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_id: 1014
[----] I, [2022-08-08T15:06:17.383235 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_template_provision_task: #<MiqAeMethodService::MiqAeServiceServiceTemplateProvisionTask:0x000055b872542f38>
[----] I, [2022-08-08T15:06:17.384437 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	service_template_provision_task_id: 2794
[----] I, [2022-08-08T15:06:17.386077 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x000055b87253dd58>
[----] I, [2022-08-08T15:06:17.387686 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	user: #<MiqAeMethodService::MiqAeServiceUser:0x000055b87253f1f8>
[----] I, [2022-08-08T15:06:17.388862 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	user_id: 1
[----] I, [2022-08-08T15:06:17.389973 #308:6927c4]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> 	vmdb_object_type: service_template_provision_task
[----] I, [2022-08-08T15:06:17.390966 #308:692774]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> ===========================================
[----] I, [2022-08-08T15:06:17.394476 #308:692774]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Service ProvisionCheck returned <ok> for state <provisioned> and status <Ok>
[----] I, [2022-08-08T15:06:17.401202 #308:692774]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod check_provisioned> Child tasks not finished. Setting retry for task: 2794 
[----] I, [2022-08-08T15:06:17.415840 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Ending
[----] I, [2022-08-08T15:06:17.415958 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:06:17.416322 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Followed  Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:06:17.416469 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Processed State=[checkprovisioned] with Result=[retry]
[----] I, [2022-08-08T15:06:17.416813 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) In State=[checkprovisioned], invoking [on_exit] method=[update_serviceprovision_status(status => 'Creating Service')]
[----] I, [2022-08-08T15:06:17.422208 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:06:17.427008 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Invoking [inline] method [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{"status"=>"Creating Service"}]
[----] I, [2022-08-08T15:06:17.428082 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting 
[----] I, [2022-08-08T15:06:17.792072 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2022-08-08T15:06:17.792324 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2794]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:07:04.529415 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) User [admin] with current group ID [2] name [EvmGroup-super_administrator]
[----] I, [2022-08-08T15:07:04.537686 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Instantiating [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%206%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=6&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create]
[----] I, [2022-08-08T15:07:04.543426 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/CatalogItemInitialization?MiqServer%3A%3Amiq_server=7&Service%3A%3AService=1014&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=2793&User%3A%3Auser=1&ae_state=checkprovisioned&ae_state_previous=---%0A%22%2FManageIQ_Custom%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2FCatalogItemInitialization%22%3A%0A%20%20ae_state%3A%20checkprovisioned%0A%20%20ae_state_retries%3A%206%0A%20%20ae_state_started%3A%202022-08-08%2015%3A00%3A31%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=6&ae_state_started=2022-08-08%2015%3A00%3A31%20UTC&dialog_cloud_network=17&dialog_cloud_subnet=22&dialog_create_sg_rules=0&dialog_instance_type=959&dialog_number_of_vms=1&dialog_placement_availability_zone=5&dialog_resource_group=6&dialog_security_groups=206&dialog_sg_create_new=0&dialog_sg_name=&dialog_sg_rules=&dialog_sg_ssh_cidr=0.0.0.0%2F0&dialog_src_vm_id=940&dialog_vm_name=Ubuntu&object_name=CatalogItemInitialization&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:07:04.557672 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processing State=[checkprovisioned]
[----] I, [2022-08-08T15:07:04.557881 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:07:04.565014 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:07:04.573634 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_provisioned  ManageIQ/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:07:04.575355 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned] with inputs [{}]
[----] I, [2022-08-08T15:07:04.576162 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Starting 
[----] I, [2022-08-08T15:07:04.836271 #308:694830]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Listing Root Object Attributes:
[----] I, [2022-08-08T15:07:04.841058 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_next_state: 
[----] I, [2022-08-08T15:07:04.842160 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_result: ok
[----] I, [2022-08-08T15:07:04.843256 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_retry_server_affinity: false
[----] I, [2022-08-08T15:07:04.844210 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state: checkprovisioned
[----] I, [2022-08-08T15:07:04.845215 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_max_retries: 100
[----] I, [2022-08-08T15:07:04.846245 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_retries: 6
[----] I, [2022-08-08T15:07:04.847281 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_started: 2022-08-08 15:00:31 UTC
[----] I, [2022-08-08T15:07:04.848429 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	ae_state_step: main
[----] I, [2022-08-08T15:07:04.849409 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_network: 17
[----] I, [2022-08-08T15:07:04.850449 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_cloud_subnet: 22
[----] I, [2022-08-08T15:07:04.851418 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_create_sg_rules: 0
[----] I, [2022-08-08T15:07:04.852460 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_instance_type: 959
[----] I, [2022-08-08T15:07:04.853594 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_number_of_vms: 1
[----] I, [2022-08-08T15:07:04.854597 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_placement_availability_zone: 5
[----] I, [2022-08-08T15:07:04.855723 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_resource_group: 6
[----] I, [2022-08-08T15:07:04.856660 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_security_groups: 206
[----] I, [2022-08-08T15:07:04.857914 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_create_new: 0
[----] I, [2022-08-08T15:07:04.859080 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_name: 
[----] I, [2022-08-08T15:07:04.860143 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_rules: 
[----] I, [2022-08-08T15:07:04.861157 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_sg_ssh_cidr: 0.0.0.0/0
[----] I, [2022-08-08T15:07:04.862255 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_src_vm_id: 940
[----] I, [2022-08-08T15:07:04.863311 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	dialog_vm_name: Ubuntu
[----] I, [2022-08-08T15:07:04.864771 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x000055b86c12e4c0>
[----] I, [2022-08-08T15:07:04.866307 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x000055b86c09c868>
[----] I, [2022-08-08T15:07:04.867289 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	miq_server_id: 7
[----] I, [2022-08-08T15:07:04.868323 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	object_name: CatalogItemInitialization
[----] I, [2022-08-08T15:07:04.869228 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	request: clone_to_service
[----] I, [2022-08-08T15:07:04.870622 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service: #<MiqAeMethodService::MiqAeServiceService:0x000055b86c0c90e8>
[----] I, [2022-08-08T15:07:04.871764 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_action: Provision
[----] I, [2022-08-08T15:07:04.872700 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_id: 1014
[----] I, [2022-08-08T15:07:04.874068 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task: #<MiqAeMethodService::MiqAeServiceServiceTemplateProvisionTask:0x000055b86c0f44f0>
[----] I, [2022-08-08T15:07:04.875059 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	service_template_provision_task_id: 2793
[----] I, [2022-08-08T15:07:04.876438 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x000055b86c120118>
[----] I, [2022-08-08T15:07:04.877966 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user: #<MiqAeMethodService::MiqAeServiceUser:0x000055b86c120258>
[----] I, [2022-08-08T15:07:04.878879 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	user_id: 1
[----] I, [2022-08-08T15:07:04.879862 #308:694880]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> 	vmdb_object_type: service_template_provision_task
[----] I, [2022-08-08T15:07:04.880948 #308:694830]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> ===========================================
[----] I, [2022-08-08T15:07:04.884529 #308:694830]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Service ProvisionCheck returned <ok> for state <provisioned> and status <Ok>
[----] I, [2022-08-08T15:07:04.890597 #308:694830]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod check_provisioned> Child tasks not finished. Setting retry for task: 2793 
[----] I, [2022-08-08T15:07:04.904942 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/check_provisioned]> Ending
[----] I, [2022-08-08T15:07:04.905091 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited with rc=MIQ_OK
[----] I, [2022-08-08T15:07:04.905402 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Followed  Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/CheckProvisioned#create]
[----] I, [2022-08-08T15:07:04.905553 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Processed State=[checkprovisioned] with Result=[retry]
[----] I, [2022-08-08T15:07:04.905822 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) In State=[checkprovisioned], invoking [on_exit] method=[update_serviceprovision_status(status => 'Creating Service')]
[----] I, [2022-08-08T15:07:04.910778 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status  ManageIQ_Custom/Service/Provisioning/StateMachines]
[----] I, [2022-08-08T15:07:04.915243 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Invoking [inline] method [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{"status"=>"Creating Service"}]
[----] I, [2022-08-08T15:07:04.916084 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting 
[----] I, [2022-08-08T15:07:05.291863 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) <AEMethod [/ManageIQ_Custom/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2022-08-08T15:07:05.291992 #308:95b0]  INFO -- automation: Q-task_id([r1088_service_template_provision_task_2793]) Method exited with rc=MIQ_OK

Aug 08 '22 15:08 kTipSSIoYv

@agrare Do you still need evm.log?

Aug 08 '22 15:08 kTipSSIoYv

@kTipSSIoYv it looks like an issue with invoking that playbook, there are no references to the r1088_miq_provision_2795 task after this:

[----] I, [2022-08-08T15:03:36.075576 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Updated namespace [Cloud/VM/Provisioning/StateMachines/Methods/ansible_azure_sg_playbook  ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines]
[----] I, [2022-08-08T15:03:36.091787 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Invoking [playbook] method [/ManageIQ_Custom/Cloud/VM/Provisioning/StateMachines/Methods/Ansible_azure_SG_Playbook] with inputs [{"vm_name"=>"Ubuntu971", "resource_group"=>"cloud-shell-storage-centralindia", "sg_name"=>"", "sg_ssh_cidr"=>"0.0.0.0/0", "sg_rules"=>"", "sg_create_new"=>"0", "sg_create_rules"=>"0"}]
[----] I, [2022-08-08T15:03:36.873936 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Playbook Method passing options:
[----] I, [2022-08-08T15:03:36.874632 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) 
[----] I, [2022-08-08T15:03:37.982091 #310:95b0]  INFO -- automation: Q-task_id([r1088_miq_provision_2795]) Ansible job with ref 66694 was created.

And at least as of these logs you never get out of the PostProvision state.

You can check on the playbook run by running:

cd /var/www/miq/vmdb
rails c
pp ManageIQ::Providers::EmbeddedAnsible::AutomationManager::Job.find_by(:ems_ref => "66694")

Aug 08 '22 15:08 agrare

Do you still need evm.log?

If there is any info from running the embedded ansible job that would be helpful

Aug 08 '22 16:08 agrare

@agrare I've sent you the evm.log. Can you let me know if you find anything from the last test?

When I'm re-testing it's sort of this issue . Its not launching the ansible job at all.

Aug 08 '22 18:08 kTipSSIoYv

I see a lot of authentication_check failures

[----] W, [2022-08-08T03:19:16.002959 #308:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T04:19:29.345683 #308:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T05:19:20.176887 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T06:19:29.059845 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T07:19:21.689963 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T08:19:26.920310 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T09:19:20.758946 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T10:19:15.749944 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T11:19:22.295561 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] I, [2022-08-08T12:18:03.499814 #286:95b0]  INFO -- evm: MIQ(MiqQueue.put) Message id: [2376848], Zone: [default], Role: [], Server: [], MiqTask id: [], Handler id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [ManageIQ::Providers::EmbeddedAnsible::AutomationManager.refresh_all_ems_timer], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2022-08-08T12:18:08.771226 #310:95b0]  INFO -- evm: MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [2376848], Zone: [default], Role: [], Server: [], MiqTask id: [], Handler id: [MiqWorker 4227], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [ManageIQ::Providers::EmbeddedAnsible::AutomationManager.refresh_all_ems_timer], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [5.3298625] seconds
[----] W, [2022-08-08T12:19:15.747432 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T13:19:24.669967 #310:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T14:19:26.079860 #308:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials
[----] W, [2022-08-08T15:19:43.178155 #308:95b0]  WARN -- evm: MIQ(ManageIQ::Providers::EmbeddedAnsible::AutomationManager#authentication_check_no_validation) type: [nil] for [1] [Embedded Ansible] Validation failed: incomplete, Missing credentials

Not sure why we're running auth check for EmbeddedAnsible or if that would cause anything to fail @jrafanie

Aug 08 '22 20:08 agrare

Not sure why we're running auth check for EmbeddedAnsible or if that would cause anything to fail @jrafanie

Unless I'm wrong, we queue an authentication_check on all ExtManagementSystem every hour. Based on that result, many of our providers will skip an Ems with invalid authentication.

Aug 08 '22 21:08 jrafanie

Unless I'm wrong, we queue an authentication_check on all ExtManagementSystem every hour. Based on that result, many of our providers will skip an Ems with invalid authentication.

Right but embedded ansible doesn't have or need any authentication (AFAIK) so this is needless work. Thinking we should have maybe some supports check to indicate if we need to run authentication_check

Aug 10 '22 17:08 agrare

Right but embedded ansible doesn't have or need any authentication (AFAIK) so this is needless work. Thinking we should have maybe some supports check to indicate if we need to run authentication_check

Yes, that makes sense to me. This is the first one to not need auth checks.

Aug 10 '22 20:08 jrafanie

@agrare Increasing the Generic Worker count fixed the issue.

Sep 11 '22 17:09 kTipSSIoYv

This issue has been automatically marked as stale because it has not been updated for at least 3 months.

If you can still reproduce this issue on the current release or on master, please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions! More information about the ManageIQ triage process can be found in the triage process documentation.

Feb 27 '23 00:02 miq-bot

This issue has been automatically closed because it has not been updated for at least 3 months.

Feel free to reopen this issue if this issue is still valid.

Thank you for all your contributions! More information about the ManageIQ triage process can be found in the triage process documentation.

May 29 '23 00:05 miq-bot