Parsing CloudStack Management Server logs and tracing API command
Parsing CloudStack can be difficult sometimes since the API calls create asynchronous jobs. A new user might find it difficult to trace the logs from api to the actual end point(Host, SSVM, KVM agent, Direct agent etc.)
Here is an example on how you can parse the logs:
1. Look for api call and find logId:xxxxx from the logs.
$ cat vmops.log | grep "createSnapshot"
2018-03-20 17:26:13,968 DEBUG [c.c.a.ApiServlet] (qtp502458215-2586:ctx-625958a0) (logid:15907246) ===START=== 10.233.88.86 -- GET command=createSnapshot&response=json&volumeId=3128662b-b696-42a2-ba28-921ba330b430&quiescevm=false&asyncBackup=false&name=snap9&_=1521547911513
2018-03-20 17:26:14,229 DEBUG [c.c.a.ApiServlet] (qtp502458215-2586:ctx-625958a0 ctx-d4cd9ea2) (logid:15907246) ===END=== 10.233.88.86 -- GET command=createSnapshot&response=json&volumeId=3128662b-b696-42a2-ba28-921ba330b430&quiescevm=false&asyncBackup=false&name=snap9&_=1521547911513
2. Find job id using logid
$ cat vmops.log | grep "logid:15907246"
2018-03-20 17:26:13,968 DEBUG [c.c.a.ApiServlet] (qtp502458215-2586:ctx-625958a0) (logid:15907246) ===START=== 10.233.88.86 -- GET command=createSnapshot&response=json&volumeId=3128662b-b696-42a2-ba28-921ba330b430&quiescevm=false&asyncBackup=false&name=snap9&_=1521547911513
2018-03-20 17:26:14,229 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp502458215-2586:ctx-625958a0 ctx-d4cd9ea2) (logid:15907246) submit async job-171, details: AsyncJobVO {id:171, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 20, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo: {"quiescevm":"false","httpmethod":"GET","ctxAccountId":"2","uuid":"aea78296-660b-4a33-8df4-0fdba0b739b8","cmdEventType":"SNAPSHOT.CREATE","asyncBackup":"false","response":"json","ctxUserId":"2","volumeId":"3128662b-b696-42a2-ba28-921ba330b430","name":"snap9","ctxStartEventId":"373","id":"20","ctxDetails":"{\"interface com.cloud.storage.Volume\":\"3128662b-b696-42a2-ba28-921ba330b430\",\"interface com.cloud.storage.Snapshot\":\"aea78296-660b-4a33-8df4-0fdba0b739b8\"}","_":"1521547911513"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 244605868339236, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2018-03-20 17:26:14,229 DEBUG [c.c.a.ApiServlet] (qtp502458215-2586:ctx-625958a0 ctx-d4cd9ea2) (logid:15907246) ===END=== 10.233.88.86 -- GET command=createSnapshot&response=json&volumeId=3128662b-b696-42a2-ba28-921ba330b430&quiescevm=false&asyncBackup=false&name=snap9&_=1521547911513
3. Grep by job-id to get all the relevant logs for the job
$ cat vmops.log | grep "job-171"
This will give you ALL the logs for the job.
4. grep by Request to get all the relevant end point logs
$ cat vmops.log | grep "job-171" | grep 'Request'
2018-03-20 17:26:20,134 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 7-7004504795444676123: Sending { Cmd , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3128662b-b696-42a2-ba28-921ba330b430","volumeType":"ROOT","volumeState":"Snapshotting","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"name":"ROOT-22","size":52428800,"path":"ROOT-22-000002","volumeId":22,"vmName":"i-2-22-VM","vmState":"Running","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[0a838fb091a1363c819486528236cb3d] i-2-22-VM/ROOT-22.vmdk\",\"[0a838fb091a1363c819486528236cb3d] ba6dc938a27b3ed0979f719788fc0c8b/ba6dc938a27b3ed0979f719788fc0c8b.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":22,"deviceId":0,"hypervisorType":"VMware","storagePolicy":""},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"vmName":"i-2-22-VM","name":"snap9","hypervisorType":"VMware","id":20,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2018-03-20 17:26:20,134 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 7-7004504795444676123: Executing: { Cmd , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3128662b-b696-42a2-ba28-921ba330b430","volumeType":"ROOT","volumeState":"Snapshotting","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"name":"ROOT-22","size":52428800,"path":"ROOT-22-000002","volumeId":22,"vmName":"i-2-22-VM","vmState":"Running","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[0a838fb091a1363c819486528236cb3d] i-2-22-VM/ROOT-22.vmdk\",\"[0a838fb091a1363c819486528236cb3d] ba6dc938a27b3ed0979f719788fc0c8b/ba6dc938a27b3ed0979f719788fc0c8b.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":22,"deviceId":0,"hypervisorType":"VMware","storagePolicy":""},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"vmName":"i-2-22-VM","name":"snap9","hypervisorType":"VMware","id":20,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2018-03-20 17:26:21,533 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 7-7004504795444676123: Received: { Ans: , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver: v1, Flags: 10, { CreateObjectAnswer } }
2018-03-20 17:26:30,207 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 11-6711207869712171133: Sending { Cmd , MgmtId: 244605868339236, via: 11(s-18-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"4d481647-3325-4d90-bd61-3838aa7d09c3","volume":{"uuid":"3128662b-b696-42a2-ba28-921ba330b430","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"name":"ROOT-22","size":52428800,"path":"ROOT-22-000002","volumeId":22,"vmName":"i-2-22-VM","vmState":"Running","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[0a838fb091a1363c819486528236cb3d] i-2-22-VM/ROOT-22.vmdk\",\"[0a838fb091a1363c819486528236cb3d] ba6dc938a27b3ed0979f719788fc0c8b/ba6dc938a27b3ed0979f719788fc0c8b.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":22,"deviceId":0,"hypervisorType":"VMware","storagePolicy":""},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"vmName":"i-2-22-VM","name":"snap9","hypervisorType":"VMware","id":20,"quiescevm":false,"physicalSize":0}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/22/b4f12a50-5954-4d67-9306-b76dc65c101e","volume":{"uuid":"3128662b-b696-42a2-ba28-921ba330b430","volumeType":"ROOT","volumeState":"Ready","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"name":"ROOT-22","size":52428800,"path":"ROOT-22-000002","volumeId":22,"vmName":"i-2-22-VM","vmState":"Running","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[0a838fb091a1363c819486528236cb3d] i-2-22-VM/ROOT-22.vmdk\",\"[0a838fb091a1363c819486528236cb3d] ba6dc938a27b3ed0979f719788fc0c8b/ba6dc938a27b3ed0979f719788fc0c8b.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":22,"deviceId":0,"hypervisorType":"VMware","storagePolicy":""},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://nfs.ip.addr.here/export/home/rajani/vmware/secondary","_role":"Image"}},"vmName":"i-2-22-VM","name":"snap9","hypervisorType":"VMware","id":20,"quiescevm":false,"physicalSize":0}},"executeInSequence":false,"options":{"fullSnapshot":"true"},"options2":{},"wait":21600}}] }
2018-03-20 17:27:38,331 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 11-6711207869712171133: Received: { Ans: , MgmtId: 244605868339236, via: 11(s-18-VM), Ver: v1, Flags: 10, { CopyCmdAnswer } }
5. Grep by seq to find the request response of each request
$ cat vmops.log | grep "Seq 7-7004504795444676123"
2018-03-20 17:26:20,134 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 7-7004504795444676123: Sending { Cmd , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3128662b-b696-42a2-ba28-921ba330b430","volumeType":"ROOT","volumeState":"Snapshotting","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"name":"ROOT-22","size":52428800,"path":"ROOT-22-000002","volumeId":22,"vmName":"i-2-22-VM","vmState":"Running","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[0a838fb091a1363c819486528236cb3d] i-2-22-VM/ROOT-22.vmdk\",\"[0a838fb091a1363c819486528236cb3d] ba6dc938a27b3ed0979f719788fc0c8b/ba6dc938a27b3ed0979f719788fc0c8b.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":22,"deviceId":0,"hypervisorType":"VMware","storagePolicy":""},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"vmName":"i-2-22-VM","name":"snap9","hypervisorType":"VMware","id":20,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2018-03-20 17:26:20,134 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 7-7004504795444676123: Executing: { Cmd , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3128662b-b696-42a2-ba28-921ba330b430","volumeType":"ROOT","volumeState":"Snapshotting","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"name":"ROOT-22","size":52428800,"path":"ROOT-22-000002","volumeId":22,"vmName":"i-2-22-VM","vmState":"Running","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[0a838fb091a1363c819486528236cb3d] i-2-22-VM/ROOT-22.vmdk\",\"[0a838fb091a1363c819486528236cb3d] ba6dc938a27b3ed0979f719788fc0c8b/ba6dc938a27b3ed0979f719788fc0c8b.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":22,"deviceId":0,"hypervisorType":"VMware","storagePolicy":""},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0a838fb0-91a1-363c-8194-86528236cb3d","name":"vmware-primary1","id":2,"poolType":"NetworkFilesystem","host":"nfs.ip.addr.here","path":"/export/home/rajani/vmware/primary","port":2049,"url":"NetworkFilesystem://nfs.ip.addr.here/export/home/rajani/vmware/primary/?ROLE=Primary&STOREUUID=0a838fb0-91a1-363c-8194-86528236cb3d","isManaged":false}},"vmName":"i-2-22-VM","name":"snap9","hypervisorType":"VMware","id":20,"quiescevm":false,"physicalSize":0}},"wait":0}}] }
2018-03-20 17:26:20,134 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-451:ctx-dbdb38c2) (logid:45c3cc5f) Seq 7-7004504795444676123: Executing request
2018-03-20 17:26:21,532 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-451:ctx-dbdb38c2) (logid:8aa78257) Seq 7-7004504795444676123: Response Received:
2018-03-20 17:26:21,532 DEBUG [c.c.a.t.Request] (DirectAgent-451:ctx-dbdb38c2) (logid:8aa78257) Seq 7-7004504795444676123: Processing: { Ans: , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"4d481647-3325-4d90-bd61-3838aa7d09c3","id":0,"quiescevm":false,"physicalSize":0}},"result":true,"wait":0}}] }
2018-03-20 17:26:21,533 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 7-7004504795444676123: Received: { Ans: , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver: v1, Flags: 10, { CreateObjectAnswer } }
Each of the entities created/failed above will have events/alerts wherever applicable.
6. In the above logs, Request Sending.. will have via information. That is the were the command is actually send.
For example, observe the below logs:
The below command is being sent to host with IP host.ip.addr.here
2018-03-20 17:26:20,134 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 7-7004504795444676123: Sending { Cmd , MgmtId: 244605868339236, via: 7(host.ip.addr.here), Ver......
The below command is being sent to SSVM with id s-18-VM. For further information, you could look for logs on SSVM
2018-03-20 17:26:30,207 DEBUG [c.c.a.t.Request] (Work-Job-Executor-19:ctx-acbc62c8 job-171/job-172 ctx-9cd448c6) (logid:8aa78257) Seq 11-6711207869712171133: Sending { Cmd , MgmtId: 244605868339236, via: 11(s-18-VM), Ver:
Comments