通过ApiId关联log
zhangxin edited this page Mar 8, 2017
·
2 revisions
目录
作为全异步程序，一个API会引发大量的异步消息、工作流，很难将它们产生的log跟API对应起来。为了方便大家查看log，我们将API消息的ID嵌入log中，方便大家快速搜索一个API引发的log。例如：
2017-03-08 08:08:47,276 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully completed上面例子中，{api=1630fa0b94134d5990c910b4f8fdc7fb}表示该log是由ID为1630fa0b94134d5990c910b4f8fdc7fb的API引发的。
无论用何种方式调用ZStack的API，最终都会转化成消息总线上的API消息。查看log调试时第一步是找到对应API的ID，这个可以通过grep命令获得。例如我们要找到创建名为vm云主机的API的ID，可以直接通过下面命令grep log：
grep "APICreateVmInstanceMsg" management-server.log | grep vm
2017-03-08 08:08:44,816 TRACE [CloudBusImpl2] {api=e5bebb05fe1d4a93b788b0e7b0834976} [msg send]: {"org.zstack.header.vm.APICreateVmInstanceMsg":{"name":"vm","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","imageUuid":"c728428146b9423ab858ebc60a0a7828","l3NetworkUuids":["feec0979bc244854b3f37c16613afdf8"],"type":"UserVm","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","strategy":"InstantStart","resourceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","session":{"uuid":"4b43648d19dc4d5cb1044c820110e966","accountUuid":"36c27e8ff05c4780bf6d2fa65700f22e","userUuid":"36c27e8ff05c4780bf6d2fa65700f22e","expiredDate":"Mar 8, 2017 10:08:39 AM","createDate":"Mar 8, 2017 8:08:39 AM"},"timeout":1800000,"headers":{"correlationId":"e5bebb05fe1d4a93b788b0e7b0834976","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{}},"id":"e5bebb05fe1d4a93b788b0e7b0834976","serviceId":"vmInstance.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978524779}}输出JSON格式数据中的id字段包含的即是API的id。
能够调试log，我们假设试着者熟悉ZStack的API消息名称
拿到API消息ID后，我们就可以搜索log找到该API引发的log了，搜索方式是通过api=API ID去grep log，例如：
2017-03-08 08:08:47,105 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.header.vm.APIStopVmInstanceMsg":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","type":"grace","session":{"uuid":"4b43648d19dc4d5cb1044c820110e966"},"timeout":-1,"headers":{"correlationId":"1630fa0b94134d5990c910b4f8fdc7fb","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{}},"id":"1630fa0b94134d5990c910b4f8fdc7fb","serviceId":"api.portal","createdTime":1488978527099}}
2017-03-08 08:08:47,113 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} called class org.zstack.testlib.Test$2 for message[class org.zstack.header.vm.APIStopVmInstanceMsg]
2017-03-08 08:08:47,114 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.header.vm.APIStopVmInstanceMsg":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","type":"grace","session":{"uuid":"4b43648d19dc4d5cb1044c820110e966","accountUuid":"36c27e8ff05c4780bf6d2fa65700f22e","userUuid":"36c27e8ff05c4780bf6d2fa65700f22e","expiredDate":"Mar 8, 2017 10:08:39 AM","createDate":"Mar 8, 2017 8:08:39 AM"},"timeout":1800000,"headers":{"correlationId":"1630fa0b94134d5990c910b4f8fdc7fb","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{}},"id":"1630fa0b94134d5990c910b4f8fdc7fb","serviceId":"vmInstance.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527099}}
2017-03-08 08:08:47,115 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.header.vm.APIStopVmInstanceMsg":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","type":"grace","session":{"uuid":"4b43648d19dc4d5cb1044c820110e966","accountUuid":"36c27e8ff05c4780bf6d2fa65700f22e","userUuid":"36c27e8ff05c4780bf6d2fa65700f22e","expiredDate":"Mar 8, 2017 10:08:39 AM","createDate":"Mar 8, 2017 8:08:39 AM"},"timeout":1800000,"headers":{"correlationId":"1630fa0b94134d5990c910b4f8fdc7fb","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"1630fa0b94134d5990c910b4f8fdc7fb","serviceId":"vmInstance.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527099}}
2017-03-08 08:08:47,150 DEBUG [VmInstanceBase] {api=1630fa0b94134d5990c910b4f8fdc7fb} vm[uuid:29c3f4dfb00e421f92a145ed17cce7c5] changed state from Running to Stopping in db
2017-03-08 08:08:47,150 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [event publish]: {"org.zstack.core.cloudbus.CanonicalEvent":{"path":"/vm/state/change","content":{"vmUuid":"29c3f4dfb00e421f92a145ed17cce7c5","oldState":"Running","newState":"Stopping","inventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","hostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:47 AM","state":"Stopping","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"date":"Mar 8, 2017 8:08:47 AM"},"managementNodeId":"fb5bed855fa244a29737faa6c2f720cc","headers":{"schema":{"org.zstack.header.vm.VmCanonicalEvents$VmStateChangedData":["content"],"org.zstack.header.vm.VmInstanceInventory":["content.inventory"],"org.zstack.header.vm.VmNicInventory":["content.inventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["content.inventory.allVolumes[0]"]},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"016fd43c462f4037b4a4e89736a81117","createdTime":1488978527150}}
2017-03-08 08:08:47,152 DEBUG [SchedulerFacadeImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} vm 29c3f4dfb00e421f92a145ed17cce7c5 not set any scheduler
2017-03-08 08:08:47,155 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] starts
2017-03-08 08:08:47,155 TRACE [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} execution path:
2017-03-08 08:08:47,155 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] start executing flow[VmStopOnHypervisorFlow.java:VmStopOnHypervisorFlow]
2017-03-08 08:08:47,157 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} called class org.zstack.testlib.Test$2 for message[class org.zstack.header.vm.StopVmOnHypervisorMsg]
2017-03-08 08:08:47,158 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.header.vm.StopVmOnHypervisorMsg":{"vmInventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","hostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:46 AM","state":"Running","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"type":"grace","timeout":1800000,"headers":{"correlationId":"254bc774d9b9497e9751c36e14d8b3bc","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{"org.zstack.header.vm.VmInstanceInventory":["vmInventory"],"org.zstack.header.vm.VmNicInventory":["vmInventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["vmInventory.allVolumes[0]"]}},"id":"254bc774d9b9497e9751c36e14d8b3bc","serviceId":"host.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527155}}
2017-03-08 08:08:47,166 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.header.vm.StopVmOnHypervisorMsg":{"vmInventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","hostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:46 AM","state":"Running","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"type":"grace","timeout":1800000,"headers":{"correlationId":"254bc774d9b9497e9751c36e14d8b3bc","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{"org.zstack.header.vm.VmInstanceInventory":["vmInventory"],"org.zstack.header.vm.VmNicInventory":["vmInventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["vmInventory.allVolumes[0]"]},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"254bc774d9b9497e9751c36e14d8b3bc","serviceId":"host.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527155}}
2017-03-08 08:08:47,174 DEBUG [EncryptRSA] {api=1630fa0b94134d5990c910b4f8fdc7fb} Input length must be multiple of 16 when decrypting with padded cipher
2017-03-08 08:08:47,177 DEBUG [EncryptRSA] {api=1630fa0b94134d5990c910b4f8fdc7fb} Input length must be multiple of 16 when decrypting with padded cipher
2017-03-08 08:08:47,179 TRACE [RESTFacadeImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} json post[http://localhost:8989/vm/stop], <{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","type":"grace","timeout":120},{Content-Type=[application/json], Content-Length=[72], taskuuid=[5ed5fd1c9ff141acbce0c5565de23b3a], callbackurl=[http://localhost:8989/asyncrest/callback], X-Resource-UUID=[4f90592b3cb34a6fa8ca25df06e66a62]}>
2017-03-08 08:08:47,184 DEBUG [EncryptRSA] {api=1630fa0b94134d5990c910b4f8fdc7fb} Input length must be multiple of 16 when decrypting with padded cipher
2017-03-08 08:08:47,185 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.header.vm.StopVmOnHypervisorReply":{"success":true,"headers":{"isReply":"true","correlationId":"254bc774d9b9497e9751c36e14d8b3bc","schema":{}},"id":"f8ef03e88db8471496288dabd956a497","serviceId":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527184}}
2017-03-08 08:08:47,187 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.header.vm.StopVmOnHypervisorReply":{"success":true,"headers":{"isReply":"true","correlationId":"254bc774d9b9497e9751c36e14d8b3bc","schema":{},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"f8ef03e88db8471496288dabd956a497","serviceId":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527184}}
2017-03-08 08:08:47,187 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully executed flow[VmStopOnHypervisorFlow.java:VmStopOnHypervisorFlow]
2017-03-08 08:08:47,187 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] start executing flow[VmReturnHostFlow.java:VmReturnHostFlow]
2017-03-08 08:08:47,189 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} called class org.zstack.testlib.Test$2 for message[class org.zstack.header.allocator.ReturnHostCapacityMsg]
2017-03-08 08:08:47,189 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.header.allocator.ReturnHostCapacityMsg":{"cpuCapacity":4,"memoryCapacity":8589934592,"hostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","headers":{"correlationId":"aac892b10e1f40c48413ad07238f8648","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","schema":{}},"id":"aac892b10e1f40c48413ad07238f8648","serviceId":"host.allocator.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527188}}
2017-03-08 08:08:47,190 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully executed flow[VmReturnHostFlow.java:VmReturnHostFlow]
2017-03-08 08:08:47,190 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] start executing flow[VmReleaseResourceFlow.java:VmReleaseResourceFlow]
2017-03-08 08:08:47,194 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.header.allocator.ReturnHostCapacityMsg":{"cpuCapacity":4,"memoryCapacity":8589934592,"hostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","headers":{"correlationId":"aac892b10e1f40c48413ad07238f8648","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","schema":{},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"aac892b10e1f40c48413ad07238f8648","serviceId":"host.allocator.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527188}}
2017-03-08 08:08:47,194 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] starts
2017-03-08 08:08:47,194 TRACE [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} execution path:
2017-03-08 08:08:47,194 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] start executing flow[NetworkServiceManagerImpl.java:release-network-service-DHCP]
2017-03-08 08:08:47,194 DEBUG [NetworkServiceManagerImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} NetworkServiceExtensionPoint[org.zstack.network.service.DhcpExtension] is asking back ends to release network service[DHCP] if needed
2017-03-08 08:08:47,198 DEBUG [DhcpExtension] {api=1630fa0b94134d5990c910b4f8fdc7fb} org.zstack.network.service.virtualrouter.dhcp.VirtualRouterDhcpBackend is releasing DHCP service
2017-03-08 08:08:47,199 TRACE [HostCapacityUpdater] {api=1630fa0b94134d5990c910b4f8fdc7fb} [Host Capacity] HostAllocatorManagerImpl.java:returnComputeResourceCapacity:495 changed the capacity of the host[uuid:4f90592b3cb34a6fa8ca25df06e66a62] as:
2017-03-08 08:08:47,218 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} called class org.zstack.testlib.Test$2 for message[class org.zstack.network.service.virtualrouter.VirtualRouterAsyncHttpCallMsg]
2017-03-08 08:08:47,218 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.network.service.virtualrouter.VirtualRouterAsyncHttpCallMsg":{"vmInstanceUuid":"2932e43d271144f497051fa16f9a15be","path":"/removedhcp","command":"{\"dhcpEntries\":[{\"ip\":\"192.168.100.97\",\"mac\":\"fa:f9:c7:04:1f:00\",\"netmask\":\"255.255.255.0\",\"gateway\":\"192.168.100.1\",\"vrNicMac\":\"fa:97:72:71:1b:01\",\"isDefaultL3Network\":true}]}","commandTimeout":1800000,"checkStatus":true,"commandClassName":"org.zstack.network.service.virtualrouter.VirtualRouterCommands$RemoveDhcpEntryCmd","timeout":1830000,"headers":{"correlationId":"85013b7fc15c4d0fafe14ac5fe6c80aa","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{}},"id":"85013b7fc15c4d0fafe14ac5fe6c80aa","serviceId":"vmInstance.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527217}}
2017-03-08 08:08:47,219 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.network.service.virtualrouter.VirtualRouterAsyncHttpCallMsg":{"vmInstanceUuid":"2932e43d271144f497051fa16f9a15be","path":"/removedhcp","command":"{\"dhcpEntries\":[{\"ip\":\"192.168.100.97\",\"mac\":\"fa:f9:c7:04:1f:00\",\"netmask\":\"255.255.255.0\",\"gateway\":\"192.168.100.1\",\"vrNicMac\":\"fa:97:72:71:1b:01\",\"isDefaultL3Network\":true}]}","commandTimeout":1800000,"checkStatus":true,"commandClassName":"org.zstack.network.service.virtualrouter.VirtualRouterCommands$RemoveDhcpEntryCmd","timeout":1830000,"headers":{"correlationId":"85013b7fc15c4d0fafe14ac5fe6c80aa","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"85013b7fc15c4d0fafe14ac5fe6c80aa","serviceId":"vmInstance.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527217}}
2017-03-08 08:08:47,235 TRACE [RESTFacadeImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} json post[http://localhost:8989/removedhcp], <{"dhcpEntries":[{"ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","vrNicMac":"fa:97:72:71:1b:01","isDefaultL3Network":true}]},{Content-Type=[application/json], Content-Length=[176], taskuuid=[64ffc35e6e3c47e4babaec8ef559f851], callbackurl=[http://localhost:8989/asyncrest/callback]}>
2017-03-08 08:08:47,243 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.network.service.virtualrouter.VirtualRouterAsyncHttpCallReply":{"response":{"success":true},"success":true,"headers":{"isReply":"true","correlationId":"85013b7fc15c4d0fafe14ac5fe6c80aa","schema":{}},"id":"aec88c3d5703480c818b3c769bf54e88","serviceId":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527235}}
2017-03-08 08:08:47,246 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.network.service.virtualrouter.VirtualRouterAsyncHttpCallReply":{"response":{"success":true},"success":true,"headers":{"isReply":"true","correlationId":"85013b7fc15c4d0fafe14ac5fe6c80aa","schema":{},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"aec88c3d5703480c818b3c769bf54e88","serviceId":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527235}}
2017-03-08 08:08:47,246 DEBUG [VirtualRouterDhcpBackend] {api=1630fa0b94134d5990c910b4f8fdc7fb} successfully removed dhcp entry[[ip: 192.168.100.97,mac: fa:f9:c7:04:1f:00,netmask: 255.255.255.0,gateway: 192.168.100.1,hostname: null,l3NetworkUuid: feec0979bc244854b3f37c16613afdf8,dnsDomain: nullisDefaultL3Network: true]] from virtual router vm[uuid:2932e43d271144f497051fa16f9a15be, ip:12.16.10.90]
2017-03-08 08:08:47,246 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully executed flow[NetworkServiceManagerImpl.java:release-network-service-DHCP]
2017-03-08 08:08:47,247 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] start executing flow[NetworkServiceManagerImpl.java:release-network-service-DNS]
2017-03-08 08:08:47,247 DEBUG [NetworkServiceManagerImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} NetworkServiceExtensionPoint[org.zstack.network.service.DnsExtension] is asking back ends to release network service[DNS] if needed
2017-03-08 08:08:47,247 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully executed flow[NetworkServiceManagerImpl.java:release-network-service-DNS]
2017-03-08 08:08:47,247 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] start executing flow[NetworkServiceManagerImpl.java:release-network-service-SecurityGroup]
2017-03-08 08:08:47,247 DEBUG [NetworkServiceManagerImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} NetworkServiceExtensionPoint[org.zstack.network.securitygroup.SecurityGroupNetworkServiceExtension] is asking back ends to release network service[SecurityGroup] if needed
2017-03-08 08:08:47,248 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} called class org.zstack.testlib.Test$2 for message[class org.zstack.network.securitygroup.RefreshSecurityGroupRulesOnVmMsg]
2017-03-08 08:08:47,248 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.network.securitygroup.RefreshSecurityGroupRulesOnVmMsg":{"vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","hostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","deleteAllRules":true,"timeout":1800000,"headers":{"correlationId":"02cd84505cd34aaebe35b62a4bfb0ed8","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{}},"id":"02cd84505cd34aaebe35b62a4bfb0ed8","serviceId":"securityGroup.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527247}}
2017-03-08 08:08:47,251 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.network.securitygroup.RefreshSecurityGroupRulesOnVmMsg":{"vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","hostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","deleteAllRules":true,"timeout":1800000,"headers":{"correlationId":"02cd84505cd34aaebe35b62a4bfb0ed8","replyTo":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","noReply":"false","schema":{},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"02cd84505cd34aaebe35b62a4bfb0ed8","serviceId":"securityGroup.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527247}}
2017-03-08 08:08:47,252 DEBUG [SecurityGroupManagerImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} no nic of vm[uuid:29c3f4dfb00e421f92a145ed17cce7c5] needs to refresh security group rule
2017-03-08 08:08:47,252 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg send]: {"org.zstack.network.securitygroup.RefreshSecurityGroupRulesOnVmReply":{"success":true,"headers":{"isReply":"true","correlationId":"02cd84505cd34aaebe35b62a4bfb0ed8","schema":{}},"id":"5c8e13d5ecab4fe4abaf594b989702c9","serviceId":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527251}}
2017-03-08 08:08:47,254 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [msg received]: {"org.zstack.network.securitygroup.RefreshSecurityGroupRulesOnVmReply":{"success":true,"headers":{"isReply":"true","correlationId":"02cd84505cd34aaebe35b62a4bfb0ed8","schema":{},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"5c8e13d5ecab4fe4abaf594b989702c9","serviceId":"zstack.message.cloudbus.fb5bed855fa244a29737faa6c2f720cc","createdTime":1488978527251}}
2017-03-08 08:08:47,257 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully executed flow[NetworkServiceManagerImpl.java:release-network-service-SecurityGroup]
2017-03-08 08:08:47,257 DEBUG [NetworkServiceManagerImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} successfully released network services for vm[uuid:29c3f4dfb00e421f92a145ed17cce7c5, name:vm]
2017-03-08 08:08:47,258 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully executed flow[VmReleaseResourceFlow.java:VmReleaseResourceFlow]
2017-03-08 08:08:47,267 DEBUG [VmInstanceBase] {api=1630fa0b94134d5990c910b4f8fdc7fb} vm[uuid:29c3f4dfb00e421f92a145ed17cce7c5] changed state from Stopping to Stopped in db
2017-03-08 08:08:47,267 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [event publish]: {"org.zstack.core.cloudbus.CanonicalEvent":{"path":"/vm/state/change","content":{"vmUuid":"29c3f4dfb00e421f92a145ed17cce7c5","oldState":"Stopping","newState":"Stopped","inventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:47 AM","state":"Stopped","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"date":"Mar 8, 2017 8:08:47 AM"},"managementNodeId":"fb5bed855fa244a29737faa6c2f720cc","headers":{"schema":{"org.zstack.header.vm.VmCanonicalEvents$VmStateChangedData":["content"],"org.zstack.header.vm.VmInstanceInventory":["content.inventory"],"org.zstack.header.vm.VmNicInventory":["content.inventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["content.inventory.allVolumes[0]"]},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"255f053cef194f2ea016b7d4cd85886b","createdTime":1488978527267}}
2017-03-08 08:08:47,271 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [event received]: {"org.zstack.core.cloudbus.CanonicalEvent":{"path":"/vm/state/change","content":{"vmUuid":"29c3f4dfb00e421f92a145ed17cce7c5","oldState":"Stopping","newState":"Stopped","inventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:47 AM","state":"Stopped","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"date":"Mar 8, 2017 8:08:47 AM"},"managementNodeId":"fb5bed855fa244a29737faa6c2f720cc","type":{"_name":"key.event.LOCAL.canonicalEvent"},"headers":{"schema":{"org.zstack.header.vm.VmCanonicalEvents$VmStateChangedData":["content"],"org.zstack.header.vm.VmInstanceInventory":["content.inventory"],"org.zstack.header.vm.VmNicInventory":["content.inventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["content.inventory.allVolumes[0]"]},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"255f053cef194f2ea016b7d4cd85886b","createdTime":1488978527267}}
2017-03-08 08:08:47,272 DEBUG [SchedulerFacadeImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} vm 29c3f4dfb00e421f92a145ed17cce7c5 not set any scheduler
2017-03-08 08:08:47,274 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [event publish]: {"org.zstack.header.vm.APIStopVmInstanceEvent":{"inventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:47 AM","state":"Stopped","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"apiId":"1630fa0b94134d5990c910b4f8fdc7fb","success":true,"headers":{"schema":{"org.zstack.header.vm.VmInstanceInventory":["inventory"],"org.zstack.header.vm.VmNicInventory":["inventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["inventory.allVolumes[0]"]},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"1b629eda49644ace84ec5089a0cb2307","createdTime":1488978527273}}
2017-03-08 08:08:47,276 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: stop-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully completed
2017-03-08 08:08:47,276 DEBUG [SimpleFlowChain] {api=1630fa0b94134d5990c910b4f8fdc7fb} [FlowChain: release-network-services-from-vm-29c3f4dfb00e421f92a145ed17cce7c5] successfully completed
2017-03-08 08:08:47,284 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [event received]: {"org.zstack.header.vm.APIStopVmInstanceEvent":{"inventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:47 AM","state":"Stopped","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"type":{"_name":"key.event.API.API_EVENT"},"apiId":"1630fa0b94134d5990c910b4f8fdc7fb","success":true,"headers":{"schema":{"org.zstack.header.vm.VmInstanceInventory":["inventory"],"org.zstack.header.vm.VmNicInventory":["inventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["inventory.allVolumes[0]"]},"api-id":"1630fa0b94134d5990c910b4f8fdc7fb"},"id":"1b629eda49644ace84ec5089a0cb2307","createdTime":1488978527273}}
2017-03-08 08:08:47,296 TRACE [request] {api=1630fa0b94134d5990c910b4f8fdc7fb} Call Web-Hook[http://127.0.0.1:8989/sdk/webook] (to 127.0.0.1/v1/vm-instances/29c3f4dfb00e421f92a145ed17cce7c5/actions) Body: {"schema":{"inventory.vmNics[0]":"org.zstack.header.vm.VmNicInventory","inventory.allVolumes[0]":"org.zstack.header.volume.VolumeInventory","inventory":"org.zstack.header.vm.VmInstanceInventory"},"inventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:47 AM","state":"Stopped","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]}}
2017-03-08 08:08:47,371 TRACE [CloudBusImpl2] {api=1630fa0b94134d5990c910b4f8fdc7fb} [event received]: {"org.zstack.core.cloudbus.CanonicalEvent":{"path":"/vm/state/change","content":{"vmUuid":"29c3f4dfb00e421f92a145ed17cce7c5","oldState":"Stopped","newState":"Starting","inventory":{"uuid":"29c3f4dfb00e421f92a145ed17cce7c5","name":"vm","zoneUuid":"788195871c884b81b7e5353c74ee5a07","clusterUuid":"faf504cd553b487485a8ef01598e970c","imageUuid":"c728428146b9423ab858ebc60a0a7828","lastHostUuid":"4f90592b3cb34a6fa8ca25df06e66a62","instanceOfferingUuid":"e80b4dc074cf4462b24222c796e4d00d","rootVolumeUuid":"cedcd1b846704e9daa13b657e27f23e3","platform":"Linux","defaultL3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","type":"UserVm","hypervisorType":"KVM","memorySize":8589934592,"cpuNum":4,"cpuSpeed":0,"allocatorStrategy":"LeastVmPreferredHostAllocatorStrategy","createDate":"Mar 8, 2017 8:08:44 AM","lastOpDate":"Mar 8, 2017 8:08:47 AM","state":"Starting","internalId":1,"vmNics":[{"uuid":"439a8d695d634fb9a0ab669c7ef30b08","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","usedIpUuid":"d7dfcc3bd63839f5be470375d5746274","l3NetworkUuid":"feec0979bc244854b3f37c16613afdf8","ip":"192.168.100.97","mac":"fa:f9:c7:04:1f:00","netmask":"255.255.255.0","gateway":"192.168.100.1","internalName":"vnic1.0","deviceId":0,"createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM"}],"allVolumes":[{"uuid":"cedcd1b846704e9daa13b657e27f23e3","name":"ROOT-for-vm","description":"Root volume for VM[uuid:29c3f4dfb00e421f92a145ed17cce7c5]","primaryStorageUuid":"c3d56df97f4b41919a9acbd3d442668a","vmInstanceUuid":"29c3f4dfb00e421f92a145ed17cce7c5","rootImageUuid":"c728428146b9423ab858ebc60a0a7828","installPath":"/local_ps/rootVolumes/acct-36c27e8ff05c4780bf6d2fa65700f22e/vol-cedcd1b846704e9daa13b657e27f23e3/cedcd1b846704e9daa13b657e27f23e3.qcow2","type":"Root","format":"qcow2","size":0,"actualSize":0,"deviceId":0,"state":"Enabled","status":"Ready","createDate":"Mar 8, 2017 8:08:45 AM","lastOpDate":"Mar 8, 2017 8:08:45 AM","isShareable":false}]},"date":"Mar 8, 2017 8:08:47 AM"},"managementNodeId":"fb5bed855fa244a29737faa6c2f720cc","type":{"_name":"key.event.LOCAL.canonicalEvent"},"headers":{"schema":{"org.zstack.header.vm.VmCanonicalEvents$VmStateChangedData":["content"],"org.zstack.header.vm.VmInstanceInventory":["content.inventory"],"org.zstack.header.vm.VmNicInventory":["content.inventory.vmNics[0]"],"org.zstack.header.volume.VolumeInventory":["content.inventory.allVolumes[0]"]},"api-id":"183ed9bdca0549f7b45e60f8e80ad16e"},"id":"d2535bdf8c944082af6b10fc4b4fea48","createdTime":1488978527368}}
2017-03-08 08:08:47,528 TRACE [RESTFacadeImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} [http response(url: http://localhost:8989/setdns, taskUuid: 85bc432f8a764456898321c23ea58c77)] {"success":true}
2017-03-08 08:08:47,770 TRACE [RESTFacadeImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} [http response(url: http://localhost:8989/adddhcp, taskUuid: 4ebbf8bf57ef4f319294118e505cecd8)] {"success":true}
2017-03-08 08:08:47,801 TRACE [RESTFacadeImpl] {api=1630fa0b94134d5990c910b4f8fdc7fb} [http response(url: http://localhost:8989/setdns, taskUuid: 7dc052a560414ea8a73f6e6f8d6ae4b8)] {"success":true}