Hello,
Good Day!!!
Trying to get orchestration automation working with Openstack. Can someone highlight what happens from from the task.execute from CatalogInitalization to the API call using fog library? Last I see in log is service template provision task doing a put message. This is from debug logs. Dont have access to logs now. fog.log is not interesting. automation and evm logs has not much after that. How to trace? Any help with code pointers is appreciated.
Thanks,
SN
These are the last log entries:
Q-task_id([service_template_provision_task_11000000000123]) ===========================================
#12202:6e04f38] INFO – : Q-task_id([service_template_provision_task_11000000000123]) MIQ(MiqQueue.put) Message id: [11000103556134], id: [], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [11000000000123], Task id: [service_template_provision_task_11000000000123], Command: [ServiceTemplateProvisionTask.execute], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2017-10-02T13:16:24.461355 #12202:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/Methods/provision]> Ending
[----] I, [2017-10-02T13:16:24.461563 #12202:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) Method exited with rc=MIQ_OK
[----] I, [2017-10-02T13:16:24.462031 #12202:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) Followed Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/Provision#create]
[----] I, [2017-10-02T13:16:24.462166 #12202:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) Processed State=[provision] with Result=[ok]
[----] I, [2017-10-02T13:16:24.462273 #12202:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) Processed State =[provision]
[----] I, [2017-10-02T13:16:24.462439 #12202:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) In State=[provision], invoking [on_exit] method=[update_serviceprovision_status(status => ‘Creating Service’)]
Are you wishing to trace this for interest/understanding sake, or is there a particular problem that you’re trying to troubleshoot? If the latter, what’s the problem?
You can often get a better understanding of what’s happening behind the scenes by enabling debug-level logging, and then tracing things in evm.log. It can get quite verbose though!
In your case I’d search for the message ID 11000103556134 and see what dequeues it. It was queued for Role: [ems_operations], so it’ll be dequeued by a Generic worker on an appliance with the EMS Operations server role set.
pemcg
Peter,
As always, thank you for your response. The intent was to troubleshoot a specific and also gain a deeper understanding of the product. This kind of understanding helps to eliminate multiple support tickets opened with downstream vendor and move with our solutions at a faster pace. Its a win-win situation for us and the vendor. In this specific instance, the issue was I can pointing the catalog item to the wrong “CatalogItemInitialization” instance, the one in the /Service/Provisioning path rather than the correct one in /Cloud/Orchestration. Once I pointed the catalog item to the correct instance, the processing continued. For now, our environment is a single appliance test env.
Given the size and scope of the forthcoming product deployment, we would be much better off if we can find solutions from the code rather than rely on vendor support. And for that we are replying on this community.
I would like to know the code paths taken from the inline methods to the OpenStack API’s both for /Service/Provisioning and /Cloud/Orchestration
BTW, here is the log entries for that message id. Does that tell you anything? ( The issue is resolved)
[----] I, [2017-10-02T13:16:24.392908 #12202:6e04f38] INFO – : Q-task_id([service_template_provision_task_11000000000123]) MIQ(MiqQueue.put) Message id: [11000103556134], id: [], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [11000000000123], Task id: [service_template_provision_task_11000000000123], Command: [ServiceTemplateProvisionTask.execute], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2017-10-02T13:16:27.510899 #1626:106f134] INFO – : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [11000103556134], MiqWorker id: [11000000514210], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [11000000000123], Task id: [service_template_provision_task_11000000000123], Command: [ServiceTemplateProvisionTask.execute], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [3.122875483] seconds
[----] I, [2017-10-02T13:16:27.511048 #1626:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) MIQ(MiqQueue#deliver) Message id: [11000103556134], Delivering…
[----] I, [2017-10-02T13:16:27.609743 #1626:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) MIQ(MiqQueue#delivered) Message id: [11000103556134], State: [ok], Delivered in [0.098705016] seconds
[----] I, [2017-10-02T13:16:27.611510 #1626:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) MIQ(MiqQueue#m_callback) Message id: [11000103556134], Invoking Callback with args: [“ok”, “Message delivered successfully”, “nil”]
Thanks,
SN
I applaud your efforts to learn 
So a couple of useful tips regarding workers and messages: workers only ever process 1 message at a time, and while they are processing that message they don’t do anything else.
If you look at the line:
[----] I, [2017-10-02T13:16:27.510899 #1626:106f134] INFO – : MIQ(MiqGenericWorker::Runner#get_message_via_drb)
You’ll see that the worker with PID 1626 has just dequeued message ID 11000103556134, and will process it. If you now grep for ‘#1626:’ in evm.log you’ll see the log lines from the worker processing this message, up until the next ‘Delivered in’ line:
[----] I, [2017-10-02T13:16:27.609743 #1626:106f134] INFO – : Q-task_id([service_template_provision_task_11000000000123]) MIQ(MiqQueue#delivered) Message id: [11000103556134], State: [ok], Delivered in [0.098705016] seconds
So pairing up get_message_via_drb and MiqQueue#delivered log lines for a worker PID gives you a good idea of what each worker is doing. You can match up worker names to their PID using rake evm:status
The way that I trace code is probably horribly inefficient (I’m not a core developer and I welcome better suggestions), but I rsync /opt/rh/cfme-gemset/* and /var/www/miq/vmdb/* from a current appliance to a ‘sources’ directory on my laptop.
To follow ServiceTemplateProvisionTask.execute I’d then do something like:
grep -iR 'def execute' --include=*.rb *
to find out where a method called execute was defined.
We know from vmdb/app/models/service_template_provision_task.rb that a ServiceTemplateProvisionTask derives from a MiqRequestTask:
class ServiceTemplateProvisionTask < MiqRequestTask
and the grep shows this as a likely candidate:
vmdb/app/models/miq_request_task.rb: def execute
Looking at this file show that the execute method calls do_request, and another grep shows:
vmdb/app/models/service_template_provision_task.rb: def do_request
Now the do_request method runs:
miq_request_tasks.each(&:deliver_to_automate)
and the deliver_to_automate method (also in service_template_provision_task.rb) queues another message:
...
MiqQueue.put(
:class_name => 'MiqAeEngine',
:method_name => 'deliver',
...
so in evm.log you should be able to see a line corresponding to this MiqQueue.put.
It’s a relatively painful iterative process of grepping the code, grepping the logs, and cross-referencing, and I’d welcome better suggestions.
Hope this helps,
pemcg
Good Day!
Thanks Peter. Sorry for the delay in responding. What you shared matches with my understanding (almost-95%). Didn’t think about rake evm status. Also use the same code scouring methods.
Thanks a bunch,
SN