loggingmanageiq

Cloudforms/manageiq log format explanation logs in of automation log


ManageIQ creates logs in automation.log in the following form:

[----] I, [2018-03-15T08:26:22.292771 #29399:3a99874]  INFO -- : Q-task_id([service_template_provision_request_1000000023798]) <AEMethod limits> Getting Tenant Quota Values for: {}
[----] I, [2018-03-15T08:26:23.335038 #29399:44d130]  INFO -- : Q-task_id([service_template_provision_request_1000000023798]) Followed  Relationship [miqaedb:/System/Request/SERVICE_PROVISION_INFO#create]
[----] I, [2018-03-15T08:26:27.058401 #29409:44d130]  INFO -- : Q-task_id([service_template_provision_task_1000000021859]) User [myuser] with current group ID [1000000000027] name [Domain mydomain (admin)]

We can see that there are some links between the log lines. The first 2 have the same service_template_provision_request identifier and also have the same number in the identifier after the hashtag at the start (29399). The last 2 logs have the same identifier after the colon in the hashtag at the start (44d130). I'm wondering what all of these mean.

I know the service_template_provision_request corresponds to the request number that I get assigned when ordering a service. But the meaning of the identifier with the hashtag eludes me.

My end goal is to be able to figure out with certainty which logs go with which request and with which task and which task is caused by which request. Ideally using the logs as is.

I think I could change the code so that at the start of each task we log the task id with the request id, but I was wondering if I could avoid having to do this.


Solution

  • The first 2 have the same service_template_provision_request identifier and also have the same number in the identifier after the hashtag at the start (29399). The last 2 logs have the same identifier after the colon in the hashtag at the start (44d130). I'm wondering what all of these mean.

    The first part of #29409:44d130 (the 29409) is the process id as you would see in top or ps. The second part (the 44d130) is the Ruby thread id, within that process. In your case, you have multiple processes with the same apparent thread id, but that is complelely coincidental.