Skip to content

Instantly share code, notes, and snippets.

@sononix

sononix/gist:de7e27da721448c715fe

Created February 19, 2016 17:31
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save sononix/de7e27da721448c715fe to your computer and use it in GitHub Desktop.
Save sononix/de7e27da721448c715fe to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gistfile1.txt
2016-02-19 17:22:36,944 DEBUG [19f9410d-bdf0-4aaa-8ecc-1b8f3d0061cc:65] [service:5] [service.create] [] [tp882902200-124] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:36,953 DEBUG [:] [] [] [] [tp882902200-124] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [service.create:65] on resource [5]
2016-02-19 17:22:37,074 DEBUG [:] [] [] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.create:64] on resource [4]
2016-02-19 17:22:37,192 DEBUG [:] [] [] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.create:65] on resource [5]
2016-02-19 17:22:37,264 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(ServiceCreate)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceCreate]
2016-02-19 17:22:37,358 INFO [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(ServiceCreate)] [] [ecutorService-1] [i.c.p.r.p.i.ResourcePoolManagerImpl ] Assigning [169.254.64.201] from pool [subnet:2] to owner [service:4]
2016-02-19 17:22:37,377 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(ServiceCreate)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceCreate]
2016-02-19 17:22:37,471 INFO [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(ServiceCreate)] [] [ecutorService-6] [i.c.p.r.p.i.ResourcePoolManagerImpl ] Assigning [169.254.118.31] from pool [subnet:2] to owner [service:5]
2016-02-19 17:22:37,544 DEBUG [:] [] [] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:66] on resource [3]
2016-02-19 17:22:37,551 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(ServiceCreate)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ServiceCreate]
2016-02-19 17:22:37,554 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(ServiceCreatePostListener)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ServiceCreatePostListener]
2016-02-19 17:22:37,555 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(ServiceCreatePostListener)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ServiceCreatePostListener]
2016-02-19 17:22:37,556 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(ActivateByDefault)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:37,556 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(ActivateByDefault)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:37,566 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(SelectorServiceCreatePostListener)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [SelectorServiceCreatePostListener]
2016-02-19 17:22:37,575 INFO [b75e8c97-419b-4506-976f-37599776dd8a:66] [serviceConsumeMap:3] [serviceconsumemap.create] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceConsumeMap:3]
2016-02-19 17:22:37,581 DEBUG [b75e8c97-419b-4506-976f-37599776dd8a:66] [serviceConsumeMap:3] [serviceconsumemap.create] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:37,588 DEBUG [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create->(SelectorServiceCreatePostListener)] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [SelectorServiceCreatePostListener]
2016-02-19 17:22:37,592 DEBUG [:] [] [] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceconsumemap.create:66] on resource [3]
2016-02-19 17:22:37,602 DEBUG [:] [] [] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:67] on resource [4]
2016-02-19 17:22:37,612 INFO [a89244c5-567a-46e5-8cbd-719a4a78f606:67] [serviceConsumeMap:4] [serviceconsumemap.create] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceConsumeMap:4]
2016-02-19 17:22:37,615 DEBUG [a89244c5-567a-46e5-8cbd-719a4a78f606:67] [serviceConsumeMap:4] [serviceconsumemap.create] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:37,623 DEBUG [:] [] [] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceconsumemap.create:67] on resource [4]
2016-02-19 17:22:37,624 DEBUG [:] [] [] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:68] on resource [5]
2016-02-19 17:22:37,632 INFO [7489835b-6cd2-4b5f-9560-b53caf137ba3:68] [serviceConsumeMap:5] [serviceconsumemap.create] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceConsumeMap:5]
2016-02-19 17:22:37,636 DEBUG [7489835b-6cd2-4b5f-9560-b53caf137ba3:68] [serviceConsumeMap:5] [serviceconsumemap.create] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:37,640 DEBUG [:] [] [] [] [tp882902200-125] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceconsumemap.create:68] on resource [5]
2016-02-19 17:22:37,641 DEBUG [:] [] [] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:69] on resource [6]
2016-02-19 17:22:37,659 INFO [0b25bfb4-a619-4d54-8b85-4c9510bd315f:69] [serviceConsumeMap:6] [serviceconsumemap.create] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceConsumeMap:6]
2016-02-19 17:22:37,660 DEBUG [0b25bfb4-a619-4d54-8b85-4c9510bd315f:69] [serviceConsumeMap:6] [serviceconsumemap.create] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:37,667 DEBUG [:] [] [] [] [qtp882902200-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceconsumemap.create:69] on resource [6]
2016-02-19 17:22:37,747 INFO [c0513928-b54b-44bb-b7c4-8567030b263f:64] [service:4] [service.create] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [service:4]
2016-02-19 17:22:37,763 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(ServiceCreate)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ServiceCreate]
2016-02-19 17:22:37,767 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(ServiceCreatePostListener)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ServiceCreatePostListener]
2016-02-19 17:22:37,767 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(ServiceCreatePostListener)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ServiceCreatePostListener]
2016-02-19 17:22:37,771 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(ActivateByDefault)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:37,771 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(ActivateByDefault)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:37,771 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(SelectorServiceCreatePostListener)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [SelectorServiceCreatePostListener]
2016-02-19 17:22:37,774 DEBUG [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create->(SelectorServiceCreatePostListener)] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [SelectorServiceCreatePostListener]
2016-02-19 17:22:37,823 INFO [bb4dea97-45e3-446c-a324-662fa98577d2:65] [service:5] [service.create] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [service:5]
2016-02-19 17:22:37,837 DEBUG [:] [] [] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:68] on resource [5]
2016-02-19 17:22:37,842 DEBUG [:] [] [] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:66] on resource [3]
2016-02-19 17:22:37,866 DEBUG [:] [] [] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:67] on resource [4]
2016-02-19 17:22:37,898 DEBUG [:] [] [] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceconsumemap.create:69] on resource [6]
2016-02-19 17:22:37,971 DEBUG [:] [] [] [] [ecutorService-1] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [service.create:64] on resource [4]
2016-02-19 17:22:37,986 DEBUG [:] [] [] [] [ecutorService-6] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [service.create:65] on resource [5]
2016-02-19 17:22:38,090 DEBUG [12201675-0df9-4912-887e-32403ba7442b:68] [serviceConsumeMap:5] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,092 DEBUG [213b24e8-88cb-4729-8c5f-b34be56963ed:67] [serviceConsumeMap:4] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,096 DEBUG [12201675-0df9-4912-887e-32403ba7442b:68] [serviceConsumeMap:5] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,097 DEBUG [12201675-0df9-4912-887e-32403ba7442b:68] [serviceConsumeMap:5] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:38,097 DEBUG [12201675-0df9-4912-887e-32403ba7442b:68] [serviceConsumeMap:5] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:38,098 DEBUG [12201675-0df9-4912-887e-32403ba7442b:68] [serviceConsumeMap:5] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,100 DEBUG [213b24e8-88cb-4729-8c5f-b34be56963ed:67] [serviceConsumeMap:4] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,102 DEBUG [213b24e8-88cb-4729-8c5f-b34be56963ed:67] [serviceConsumeMap:4] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:38,102 DEBUG [213b24e8-88cb-4729-8c5f-b34be56963ed:67] [serviceConsumeMap:4] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:38,103 DEBUG [213b24e8-88cb-4729-8c5f-b34be56963ed:67] [serviceConsumeMap:4] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,108 DEBUG [12201675-0df9-4912-887e-32403ba7442b:68] [serviceConsumeMap:5] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,112 DEBUG [213b24e8-88cb-4729-8c5f-b34be56963ed:67] [serviceConsumeMap:4] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,150 DEBUG [449fa2b8-9742-4c2b-83ef-6dc1533ed7cf:66] [serviceConsumeMap:3] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,150 DEBUG [84710569-987f-4245-94d8-fe80aa4477c9:69] [serviceConsumeMap:6] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,159 DEBUG [449fa2b8-9742-4c2b-83ef-6dc1533ed7cf:66] [serviceConsumeMap:3] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,159 DEBUG [84710569-987f-4245-94d8-fe80aa4477c9:69] [serviceConsumeMap:6] [serviceconsumemap.create->(AgentInstanceApplyItems)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems]
2016-02-19 17:22:38,159 DEBUG [84710569-987f-4245-94d8-fe80aa4477c9:69] [serviceConsumeMap:6] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:38,160 DEBUG [449fa2b8-9742-4c2b-83ef-6dc1533ed7cf:66] [serviceConsumeMap:3] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:38,160 DEBUG [84710569-987f-4245-94d8-fe80aa4477c9:69] [serviceConsumeMap:6] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:38,160 DEBUG [84710569-987f-4245-94d8-fe80aa4477c9:69] [serviceConsumeMap:6] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,160 DEBUG [449fa2b8-9742-4c2b-83ef-6dc1533ed7cf:66] [serviceConsumeMap:3] [serviceconsumemap.create->(ActivateByDefault)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:38,161 DEBUG [449fa2b8-9742-4c2b-83ef-6dc1533ed7cf:66] [serviceConsumeMap:3] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,169 DEBUG [84710569-987f-4245-94d8-fe80aa4477c9:69] [serviceConsumeMap:6] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,170 DEBUG [449fa2b8-9742-4c2b-83ef-6dc1533ed7cf:66] [serviceConsumeMap:3] [serviceconsumemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:38,180 INFO [12201675-0df9-4912-887e-32403ba7442b:68] [serviceConsumeMap:5] [serviceconsumemap.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [serviceConsumeMap:5]
2016-02-19 17:22:38,234 INFO [449fa2b8-9742-4c2b-83ef-6dc1533ed7cf:66] [serviceConsumeMap:3] [serviceconsumemap.create] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [serviceConsumeMap:3]
2016-02-19 17:22:38,235 INFO [213b24e8-88cb-4729-8c5f-b34be56963ed:67] [serviceConsumeMap:4] [serviceconsumemap.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [serviceConsumeMap:4]
2016-02-19 17:22:38,315 DEBUG [:] [] [] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [serviceconsumemap.create:68] on resource [5]
2016-02-19 17:22:38,315 INFO [84710569-987f-4245-94d8-fe80aa4477c9:69] [serviceConsumeMap:6] [serviceconsumemap.create] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [serviceConsumeMap:6]
2016-02-19 17:22:38,414 DEBUG [:] [] [] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [serviceconsumemap.create:66] on resource [3]
2016-02-19 17:22:38,428 DEBUG [:] [] [] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [serviceconsumemap.create:67] on resource [4]
2016-02-19 17:22:38,477 DEBUG [:] [] [] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [serviceconsumemap.create:69] on resource [6]
2016-02-19 17:22:38,817 DEBUG [:] [] [] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:22:38,819 INFO [f7d328e0-6935-4e18-a9e8-04de9b35da1f:70] [service:1] [service.activate] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [service:1]
2016-02-19 17:22:38,820 DEBUG [f7d328e0-6935-4e18-a9e8-04de9b35da1f:70] [service:1] [service.activate] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:38,822 DEBUG [:] [] [] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [service.activate:70] on resource [1]
2016-02-19 17:22:38,942 DEBUG [:] [] [] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:22:39,112 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceUpdateActivate]
2016-02-19 17:22:39,441 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive, instanceTriggeredStop=stop}] to [InstanceRecord:null]
2016-02-19 17:22:39,557 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:22:39,606 INFO [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1->instance:2] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->creating] on [instance:2]
2016-02-19 17:22:39,607 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1->instance:2] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:39,655 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [instance.create:71] on resource [2]
2016-02-19 17:22:39,664 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:22:39,708 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:72] on resource [1]
2016-02-19 17:22:39,774 INFO [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1->serviceExposeMap:1] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceExposeMap:1]
2016-02-19 17:22:39,775 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1->serviceExposeMap:1] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:39,793 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstancePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [InstancePreCreate]
2016-02-19 17:22:39,793 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstancePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [InstancePreCreate]
2016-02-19 17:22:39,793 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(VirtualMachinePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [VirtualMachinePreCreate]
2016-02-19 17:22:39,793 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(VirtualMachinePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [VirtualMachinePreCreate]
2016-02-19 17:22:39,794 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(AgentInstanceInstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [AgentInstanceInstanceCreate]
2016-02-19 17:22:39,794 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(AgentInstanceInstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [AgentInstanceInstanceCreate]
2016-02-19 17:22:39,794 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(DockerInstancePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [DockerInstancePreCreate]
2016-02-19 17:22:39,808 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(DockerInstancePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [image.create:73] on resource [2]
2016-02-19 17:22:39,812 INFO [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->image:2] [instance.create->(DockerInstancePreCreate)->image.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [image:2]
2016-02-19 17:22:39,816 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->image:2] [instance.create->(DockerInstancePreCreate)->image.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:39,819 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(DockerInstancePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [image.create:73] on resource [2]
2016-02-19 17:22:39,840 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceexposemap.create:72] on resource [1]
2016-02-19 17:22:39,852 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:72] on resource [1]
2016-02-19 17:22:39,890 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(DockerInstancePreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [DockerInstancePreCreate]
2016-02-19 17:22:39,906 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:74] on resource [1]
2016-02-19 17:22:39,908 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1->serviceExposeMap:1] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:22:39,972 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceVolumeLookupPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [InstanceVolumeLookupPreCreate]
2016-02-19 17:22:39,974 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceexposemap.create:74] on resource [1]
2016-02-19 17:22:39,982 DEBUG [e61d34fa-7b6e-402c-a442-e9a3e91f538f:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:74] on resource [1]
2016-02-19 17:22:39,985 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceVolumeLookupPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [InstanceVolumeLookupPreCreate]
2016-02-19 17:22:40,049 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(ServiceExposeMapCreate)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceExposeMapCreate]
2016-02-19 17:22:40,052 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(ServiceExposeMapCreate)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ServiceExposeMapCreate]
2016-02-19 17:22:40,061 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(AgentInstanceApplyItems)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems]
2016-02-19 17:22:40,072 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [InstanceCreate]
2016-02-19 17:22:40,075 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceCreate)] [] [ecutorService-4] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive}] to [VolumeRecord:null]
2016-02-19 17:22:40,076 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(AgentInstanceApplyItems)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems]
2016-02-19 17:22:40,081 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(ActivateByDefault)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:40,082 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(ActivateByDefault)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:40,084 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:40,098 DEBUG [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create->(LoadBalancerServiceUpdateConfig)] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [LoadBalancerServiceUpdateConfig]
2016-02-19 17:22:40,135 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.create:null] on resource [5]
2016-02-19 17:22:40,161 INFO [60722cc5-b539-4d92-b8f2-5638bc6bc557:72] [serviceExposeMap:1] [serviceexposemap.create] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [serviceExposeMap:1]
2016-02-19 17:22:40,223 INFO [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->volume:5] [instance.create->(InstanceCreate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [volume:5]
2016-02-19 17:22:40,230 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->volume:5] [instance.create->(InstanceCreate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:22:40,230 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->volume:5] [instance.create->(InstanceCreate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:22:40,235 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->volume:5] [instance.create->(InstanceCreate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:40,235 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->volume:5] [instance.create->(InstanceCreate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:40,309 DEBUG [:] [] [] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [ALREADY_DONE] process [serviceexposemap.create:74] on resource [1]
2016-02-19 17:22:40,309 DEBUG [:] [] [] [] [ecutorService-5] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [serviceexposemap.create:72] on resource [1]
2016-02-19 17:22:40,327 INFO [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->volume:5] [instance.create->(InstanceCreate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [volume:5]
2016-02-19 17:22:40,328 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volume.create:null] on resource [5]
2016-02-19 17:22:40,386 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [nic.create:null] on resource [2]
2016-02-19 17:22:40,436 INFO [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->nic:2] [instance.create->(InstanceCreate)->nic.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [nic:2]
2016-02-19 17:22:40,445 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->nic:2] [instance.create->(InstanceCreate)->nic.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:40,445 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->nic:2] [instance.create->(InstanceCreate)->nic.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:40,489 INFO [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2->nic:2] [instance.create->(InstanceCreate)->nic.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [nic:2]
2016-02-19 17:22:40,490 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [nic.create:null] on resource [2]
2016-02-19 17:22:41,486 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [InstanceCreate]
2016-02-19 17:22:41,545 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(DockerInstancePostCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [DockerInstancePostCreate]
2016-02-19 17:22:41,550 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(DockerInstancePostCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [DockerInstancePostCreate]
2016-02-19 17:22:41,551 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:41,551 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:41,552 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceInstanceLinkCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [InstanceInstanceLinkCreate]
2016-02-19 17:22:41,554 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstanceInstanceLinkCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [InstanceInstanceLinkCreate]
2016-02-19 17:22:41,554 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstancePortCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [InstancePortCreate]
2016-02-19 17:22:41,555 DEBUG [87a50dd9-961c-4349-b789-ec7c8eb0093b:71] [instance:2] [instance.create->(InstancePortCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [InstancePortCreate]
2016-02-19 17:22:41,609 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [creating->starting] on [instance:2]
2016-02-19 17:22:41,614 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStartToken)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [InstanceStartToken]
2016-02-19 17:22:41,615 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStartToken)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [InstanceStartToken]
2016-02-19 17:22:41,728 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(AgentInstanceInstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [AgentInstanceInstanceStart]
2016-02-19 17:22:41,728 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(AgentInstanceInstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [AgentInstanceInstanceStart]
2016-02-19 17:22:41,729 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(LoadBalancerInstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [LoadBalancerInstanceStart]
2016-02-19 17:22:41,730 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(LoadBalancerInstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [LoadBalancerInstanceStart]
2016-02-19 17:22:41,736 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(ServiceLinkPreInstanceStateHandler)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [ServiceLinkPreInstanceStateHandler]
2016-02-19 17:22:41,777 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(ServiceLinkPreInstanceStateHandler)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [ServiceLinkPreInstanceStateHandler]
2016-02-19 17:22:41,777 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStartRegisterAsNspProvider)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [InstanceStartRegisterAsNspProvider]
2016-02-19 17:22:41,778 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStartRegisterAsNspProvider)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [InstanceStartRegisterAsNspProvider]
2016-02-19 17:22:41,799 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(ServiceLinkPreInstanceStateHandler)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [ServiceLinkPreInstanceStateHandler]
2016-02-19 17:22:41,823 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(ServiceLinkPreInstanceStateHandler)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [ServiceLinkPreInstanceStateHandler]
2016-02-19 17:22:41,824 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [InstanceStart]
2016-02-19 17:22:41,891 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.allocate:null] on resource [2]
2016-02-19 17:22:41,942 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [instance:2]
2016-02-19 17:22:41,946 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [InstanceAllocate]
2016-02-19 17:22:41,949 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [c.p.a.e.i.AllocatorEventListenerImpl] Allocating [instance:2]
2016-02-19 17:22:42,040 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] Attemping allocation for:
2016-02-19 17:22:42,040 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] instance [2]
2016-02-19 17:22:42,041 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] volume [5]
2016-02-19 17:22:42,041 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] constraints:
2016-02-19 17:22:42,041 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] is valid
2016-02-19 17:22:42,041 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,041 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,041 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] account id must be 5
2016-02-19 17:22:42,041 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,042 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] host needs 1 compute free
2016-02-19 17:22:42,042 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,042 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@51eebc93
2016-02-19 17:22:42,042 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@109e80eb
2016-02-19 17:22:42,042 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@1621ccd3
2016-02-19 17:22:42,046 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [1] pools [1]
2016-02-19 17:22:42,046 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] Checking candidate:
2016-02-19 17:22:42,046 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] host [1]
2016-02-19 17:22:42,046 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] volume [5]
2016-02-19 17:22:42,046 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] pool [1]
2016-02-19 17:22:42,046 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [true] : is valid
2016-02-19 17:22:42,051 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,051 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,056 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [true] : account id must be 5
2016-02-19 17:22:42,060 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [true] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,062 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [true] : host needs 1 compute free
2016-02-19 17:22:42,063 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [true] : nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,068 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [false] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@51eebc93
2016-02-19 17:22:42,077 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [false] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@109e80eb
2016-02-19 17:22:42,079 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] checking candidate [false] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@1621ccd3
2016-02-19 17:22:42,079 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][3ac0473a-4fcf-4b0c-9e82-cfe27311359a] candidates result [false]
2016-02-19 17:22:42,079 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [null] pools []
2016-02-19 17:22:42,081 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] Attemping allocation for:
2016-02-19 17:22:42,082 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] instance [2]
2016-02-19 17:22:42,082 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] volume [5]
2016-02-19 17:22:42,082 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] constraints:
2016-02-19 17:22:42,082 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] is valid
2016-02-19 17:22:42,082 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,082 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,083 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] account id must be 5
2016-02-19 17:22:42,084 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,084 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] host needs 1 compute free
2016-02-19 17:22:42,084 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,084 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@51eebc93
2016-02-19 17:22:42,084 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@109e80eb
2016-02-19 17:22:42,090 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [1] pools [1]
2016-02-19 17:22:42,090 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] Checking candidate:
2016-02-19 17:22:42,090 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] host [1]
2016-02-19 17:22:42,090 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] volume [5]
2016-02-19 17:22:42,090 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] pool [1]
2016-02-19 17:22:42,090 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [true] : is valid
2016-02-19 17:22:42,091 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,091 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,092 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [true] : account id must be 5
2016-02-19 17:22:42,094 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [true] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,096 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [true] : host needs 1 compute free
2016-02-19 17:22:42,096 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [true] : nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,098 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [false] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@51eebc93
2016-02-19 17:22:42,102 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] checking candidate [false] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@109e80eb
2016-02-19 17:22:42,102 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][323c3567-9314-4a82-9a75-4cec3ae5dd2e] candidates result [false]
2016-02-19 17:22:42,102 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [null] pools []
2016-02-19 17:22:42,102 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] Attemping allocation for:
2016-02-19 17:22:42,102 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] instance [2]
2016-02-19 17:22:42,102 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] volume [5]
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] constraints:
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] is valid
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] account id must be 5
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] host needs 1 compute free
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,103 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@51eebc93
2016-02-19 17:22:42,106 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [1] pools [1]
2016-02-19 17:22:42,106 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] Checking candidate:
2016-02-19 17:22:42,106 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] host [1]
2016-02-19 17:22:42,106 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] volume [5]
2016-02-19 17:22:42,106 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] pool [1]
2016-02-19 17:22:42,106 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [true] : is valid
2016-02-19 17:22:42,107 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,108 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,108 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [true] : account id must be 5
2016-02-19 17:22:42,109 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [true] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,110 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [true] : host needs 1 compute free
2016-02-19 17:22:42,110 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [true] : nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,112 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] checking candidate [false] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@51eebc93
2016-02-19 17:22:42,112 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][0c62618f-213e-4343-b151-2d7852b62685] candidates result [false]
2016-02-19 17:22:42,112 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [null] pools []
2016-02-19 17:22:42,112 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] Attemping allocation for:
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] instance [2]
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] volume [5]
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] constraints:
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] is valid
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] account id must be 5
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,113 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] host needs 1 compute free
2016-02-19 17:22:42,114 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d] nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,119 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [1] pools [1]
2016-02-19 17:22:42,119 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] Checking candidate:
2016-02-19 17:22:42,120 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] host [1]
2016-02-19 17:22:42,120 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] volume [5]
2016-02-19 17:22:42,120 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] pool [1]
2016-02-19 17:22:42,120 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] checking candidate [true] : is valid
2016-02-19 17:22:42,121 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,121 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,121 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] checking candidate [true] : account id must be 5
2016-02-19 17:22:42,123 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] checking candidate [true] : io.cattle.platform.allocator.constraint.ContainerLabelAffinityConstraint@6278739e
2016-02-19 17:22:42,124 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] checking candidate [true] : host needs 1 compute free
2016-02-19 17:22:42,124 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] checking candidate [true] : nic [2] subnet's matches host and vnet [null]
2016-02-19 17:22:42,124 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.service.AbstractAllocator ] [fc4501fb-84f2-447f-88b3-f7623c1f271d][cbc5759a-7dab-4bd1-8f9b-d514993b56dd] candidates result [true]
2016-02-19 17:22:42,125 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.dao.impl.AllocatorDaoImpl ] Associating instance [2] to host [1]
2016-02-19 17:22:42,128 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.dao.impl.AllocatorDaoImpl ] Modifying computeFree on host [1], 999999 - 1 = 999998
2016-02-19 17:22:42,129 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [i.c.p.a.dao.impl.AllocatorDaoImpl ] Associating volume [5] to storage pool [1]
2016-02-19 17:22:42,175 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [cutorService-49] [c.p.a.e.i.AllocatorEventListenerImpl] Allocator [SimpleAllocator] handled request [AllocationRequest [type=INSTANCE, resource=2]]
2016-02-19 17:22:42,178 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instancehostmap.create:null] on resource [2]
2016-02-19 17:22:42,228 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->instancehostmap.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [instanceHostMap:2]
2016-02-19 17:22:42,236 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->instancehostmap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:42,237 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->instancehostmap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:42,282 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->instancehostmap.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [instanceHostMap:2]
2016-02-19 17:22:42,284 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [instancehostmap.create:null] on resource [2]
2016-02-19 17:22:42,287 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.allocate:null] on resource [5]
2016-02-19 17:22:42,332 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [volume:5]
2016-02-19 17:22:42,337 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [VolumeAllocate]
2016-02-19 17:22:42,338 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [c.p.a.e.i.AllocatorEventListenerImpl] Allocating [volume:5]
2016-02-19 17:22:42,355 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] Attemping allocation for:
2016-02-19 17:22:42,358 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] volume [5]
2016-02-19 17:22:42,358 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] pool [1]
2016-02-19 17:22:42,358 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] constraints:
2016-02-19 17:22:42,358 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] is valid
2016-02-19 17:22:42,358 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] valid host(s) [1]
2016-02-19 17:22:42,358 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] volume [5] have exactly these pool(s): [1]
2016-02-19 17:22:42,359 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,359 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050] account id must be 5
2016-02-19 17:22:42,362 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [.s.a.d.i.AllocationCandidateIterator] Enumerating canditates hostId [1] pools [1]
2016-02-19 17:22:42,362 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] Checking candidate:
2016-02-19 17:22:42,363 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] volume [5]
2016-02-19 17:22:42,363 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] pool [1]
2016-02-19 17:22:42,363 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] checking candidate [true] : is valid
2016-02-19 17:22:42,363 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] checking candidate [true] : valid host(s) [1]
2016-02-19 17:22:42,365 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] checking candidate [true] : volume [5] have exactly these pool(s): [1]
2016-02-19 17:22:42,371 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] checking candidate [true] : storage pool for volume 5 must be one of kind [docker, sim]
2016-02-19 17:22:42,372 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] checking candidate [true] : account id must be 5
2016-02-19 17:22:42,372 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [i.c.p.a.service.AbstractAllocator ] [d05f99a1-753a-48e2-9b05-e4cb365b4050][01139a69-3bc6-4455-aa87-c9e4e063a92f] candidates result [true]
2016-02-19 17:22:42,374 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [cutorService-16] [c.p.a.e.i.AllocatorEventListenerImpl] Allocator [SimpleAllocator] handled request [AllocationRequest [type=VOLUME, resource=5]]
2016-02-19 17:22:42,379 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volumestoragepoolmap.create:null] on resource [5]
2016-02-19 17:22:42,435 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)->volumestoragepoolmap.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [volumeStoragePoolMap:5]
2016-02-19 17:22:42,455 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)->volumestoragepoolmap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:42,455 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)->volumestoragepoolmap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:42,501 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)->volumestoragepoolmap.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [volumeStoragePoolMap:5]
2016-02-19 17:22:42,502 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volumestoragepoolmap.create:null] on resource [5]
2016-02-19 17:22:42,502 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate->(VolumeAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [VolumeAllocate]
2016-02-19 17:22:42,552 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)->volume.allocate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [volume:5]
2016-02-19 17:22:42,552 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volume.allocate:null] on resource [5]
2016-02-19 17:22:42,558 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volumestoragepoolmap.create:null] on resource [5]
2016-02-19 17:22:42,559 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [ALREADY_DONE] process [volumestoragepoolmap.create:null] on resource [5]
2016-02-19 17:22:42,561 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate->(InstanceAllocate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [InstanceAllocate]
2016-02-19 17:22:42,617 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)->instance.allocate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [instance:2]
2016-02-19 17:22:42,618 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [instance.allocate:null] on resource [2]
2016-02-19 17:22:42,672 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [nic.activate:null] on resource [2]
2016-02-19 17:22:42,716 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [nic:2]
2016-02-19 17:22:42,720 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstanceNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [AgentInstanceNicActivate]
2016-02-19 17:22:42,720 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstanceNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [AgentInstanceNicActivate]
2016-02-19 17:22:42,720 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstanceIpsecNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [AgentInstanceIpsecNicActivate]
2016-02-19 17:22:42,722 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstanceIpsecNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [AgentInstanceIpsecNicActivate]
2016-02-19 17:22:42,723 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(HostOnlyNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [HostOnlyNicActivate]
2016-02-19 17:22:42,727 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(HostOnlyNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [HostOnlyNicActivate]
2016-02-19 17:22:42,728 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(InstanceHealthcheckRegister)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [InstanceHealthcheckRegister]
2016-02-19 17:22:42,770 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(InstanceHealthcheckRegister)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [InstanceHealthcheckRegister]
2016-02-19 17:22:42,774 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(NicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [NicActivate]
2016-02-19 17:22:42,783 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(NicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [network.activate:null] on resource [2]
2016-02-19 17:22:42,783 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(NicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [ALREADY_DONE] process [network.activate:null] on resource [2]
2016-02-19 17:22:42,835 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(NicActivate)] [] [ecutorService-4] [i.c.p.r.p.i.ResourcePoolManagerImpl ] Assigning [02:4f:91:89:5e:08] from pool [network:2] to owner [nic:2]
2016-02-19 17:22:42,835 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(NicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [NicActivate]
2016-02-19 17:22:42,887 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(CreateInstanceAssociatePublicIpAddress)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [CreateInstanceAssociatePublicIpAddress]
2016-02-19 17:22:42,890 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(CreateInstanceAssociatePublicIpAddress)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [CreateInstanceAssociatePublicIpAddress]
2016-02-19 17:22:42,891 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(VirtualMachineMetadata)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [VirtualMachineMetadata]
2016-02-19 17:22:42,894 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(VirtualMachineMetadata)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [VirtualMachineMetadata]
2016-02-19 17:22:42,894 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstanceApplyItems)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems]
2016-02-19 17:22:42,894 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstanceApplyItems)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems]
2016-02-19 17:22:42,894 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstancePostNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstancePostNicActivate]
2016-02-19 17:22:42,894 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate->(AgentInstancePostNicActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstancePostNicActivate]
2016-02-19 17:22:42,938 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->nic:2] [instance.start->(InstanceStart)->nic.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [nic:2]
2016-02-19 17:22:42,939 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [nic.activate:null] on resource [2]
2016-02-19 17:22:42,990 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.activate:null] on resource [5]
2016-02-19 17:22:43,037 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [volume:5]
2016-02-19 17:22:43,052 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [VolumeActivate]
2016-02-19 17:22:43,065 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [image.activate:null] on resource [2]
2016-02-19 17:22:43,115 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->image:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->image.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->activating] on [image:2]
2016-02-19 17:22:43,164 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->image:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->image.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [image:2]
2016-02-19 17:22:43,165 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [image.activate:null] on resource [2]
2016-02-19 17:22:43,217 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [imagestoragepoolmap.create:null] on resource [2]
2016-02-19 17:22:43,261 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [imageStoragePoolMap:2]
2016-02-19 17:22:43,272 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:22:43,273 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:22:43,321 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [imageStoragePoolMap:2]
2016-02-19 17:22:43,322 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [imagestoragepoolmap.create:null] on resource [2]
2016-02-19 17:22:43,323 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [imagestoragepoolmap.activate:null] on resource [2]
2016-02-19 17:22:43,370 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [imageStoragePoolMap:2]
2016-02-19 17:22:43,380 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.activate->(ImageStoragePoolMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ImageStoragePoolMapActivate]
2016-02-19 17:22:49,224 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:22:49,226 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [service.activate:70] on resource [1]
2016-02-19 17:22:49,239 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [environment.create:57] on resource [2]
2016-02-19 17:22:49,240 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [environment.create:57] on resource [2]
2016-02-19 17:22:49,274 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [image.create:73] on resource [2]
2016-02-19 17:22:49,275 INFO [1ab1532f-3440-4215-bb62-0ddf84e99430:73] [image:2] [image.create] [] [erviceReplay-15] [i.c.p.e.p.i.ResourceStatesDefinition] State [active] is not a valid state
2016-02-19 17:22:49,282 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:22:49,288 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [instance.create:71] on resource [2]
2016-02-19 17:22:49,443 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [ALREADY_DONE] process [image.activate:73] on resource [2]
2016-02-19 17:22:55,168 DEBUG [:] [] [] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [service.activate:70] on resource [1]
2016-02-19 17:22:55,169 INFO [:] [] [] [] [ecutorService-7] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [service.activate:70] on [1] : Object [instance:2] failed to satisfy predicate [15000] millis
2016-02-19 17:23:03,092 DEBUG [:] [] [] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [environment.create:57] on resource [2]
2016-02-19 17:23:03,093 INFO [:] [] [] [] [ecutorService-2] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [environment.create:57] on [2] : null
2016-02-19 17:23:04,457 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:23:04,474 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [environment.create:57] on resource [2]
2016-02-19 17:23:04,552 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:23:04,558 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [instance.create:71] on resource [2]
2016-02-19 17:23:04,621 DEBUG [4c8db302-811b-4ff3-989c-49bcb16e405d:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceUpdateActivate]
2016-02-19 17:23:04,634 DEBUG [2d722e1f-9db0-41ec-81af-2fe7c9a0930f:57] [environment:2] [environment.create->(rancher-compose-executor)] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [rancher-compose-executor]
2016-02-19 17:23:19,513 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [environment.create:57] on resource [2]
2016-02-19 17:23:19,518 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [environment.create:57] on resource [2]
2016-02-19 17:23:19,528 DEBUG [:] [] [] [] [erviceReplay-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:23:19,529 DEBUG [:] [] [] [] [erviceReplay-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [service.activate:70] on resource [1]
2016-02-19 17:23:19,529 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:23:19,530 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [instance.create:71] on resource [2]
2016-02-19 17:23:20,283 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [environment.create:57] on resource [2]
2016-02-19 17:23:20,290 INFO [:] [] [] [] [erviceReplay-15] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [environment.create:57] on [2] : null
2016-02-19 17:23:20,573 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [service.activate:70] on resource [1]
2016-02-19 17:23:20,573 INFO [:] [] [] [] [erviceReplay-16] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [service.activate:70] on [1] : Object [instance:2] failed to satisfy predicate [15000] millis
2016-02-19 17:23:34,788 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:23:34,790 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [environment.create:57] on resource [2]
2016-02-19 17:23:34,791 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [instance.create:71] on resource [2]
2016-02-19 17:23:34,801 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:23:34,953 DEBUG [30094719-3de6-4e20-b3d8-74ee3ca09532:57] [environment:2] [environment.create->(rancher-compose-executor)] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [rancher-compose-executor]
2016-02-19 17:23:34,975 DEBUG [3da03a8f-5a05-4f0b-b86f-a80ea642b010:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceUpdateActivate]
2016-02-19 17:23:49,895 DEBUG [:] [] [] [] [erviceReplay-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:23:49,898 DEBUG [:] [] [] [] [erviceReplay-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [service.activate:70] on resource [1]
2016-02-19 17:23:49,903 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [environment.create:57] on resource [2]
2016-02-19 17:23:49,906 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:23:49,906 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [environment.create:57] on resource [2]
2016-02-19 17:23:49,908 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [instance.create:71] on resource [2]
2016-02-19 17:23:50,269 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [environment.create:57] on resource [2]
2016-02-19 17:23:50,269 INFO [:] [] [] [] [erviceReplay-16] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [environment.create:57] on [2] : null
2016-02-19 17:23:50,349 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [service.activate:70] on resource [1]
2016-02-19 17:23:50,350 INFO [:] [] [] [] [erviceReplay-15] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [service.activate:70] on [1] : Object [instance:2] failed to satisfy predicate [15000] millis
2016-02-19 17:24:05,009 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:24:05,010 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [instance.create:71] on resource [2]
2016-02-19 17:24:05,016 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:24:05,024 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [environment.create:57] on resource [2]
2016-02-19 17:24:05,041 DEBUG [1eecfe48-c7ef-478a-81f5-7ff1c5ff7fb3:70] [service:1] [service.activate->(ServiceUpdateActivate)] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceUpdateActivate]
2016-02-19 17:24:05,047 DEBUG [0d059b3b-f5b3-42f4-a356-7066b9dd1c78:57] [environment:2] [environment.create->(rancher-compose-executor)] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [rancher-compose-executor]
2016-02-19 17:24:13,327 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.activate->(ImageStoragePoolMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ImageStoragePoolMapActivate]
2016-02-19 17:24:13,377 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->imageStoragePoolMap:2] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->imagestoragepoolmap.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [imageStoragePoolMap:2]
2016-02-19 17:24:13,386 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [imagestoragepoolmap.activate:null] on resource [2]
2016-02-19 17:24:13,387 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volumestoragepoolmap.create:null] on resource [5]
2016-02-19 17:24:13,388 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [ALREADY_DONE] process [volumestoragepoolmap.create:null] on resource [5]
2016-02-19 17:24:13,389 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volumestoragepoolmap.activate:null] on resource [5]
2016-02-19 17:24:13,435 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->volumestoragepoolmap.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [volumeStoragePoolMap:5]
2016-02-19 17:24:13,439 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->volumestoragepoolmap.activate->(VolumeStoragePoolMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [VolumeStoragePoolMapActivate]
2016-02-19 17:24:13,458 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->volumestoragepoolmap.activate->(VolumeStoragePoolMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [VolumeStoragePoolMapActivate]
2016-02-19 17:24:13,556 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volumeStoragePoolMap:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)->volumestoragepoolmap.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [volumeStoragePoolMap:5]
2016-02-19 17:24:13,557 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volumestoragepoolmap.activate:null] on resource [5]
2016-02-19 17:24:13,559 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate->(VolumeActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [VolumeActivate]
2016-02-19 17:24:13,606 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:5] [instance.start->(InstanceStart)->volume.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [volume:5]
2016-02-19 17:24:13,607 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volume.activate:null] on resource [5]
2016-02-19 17:24:13,659 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2] [instance.start->(InstanceStart)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instancehostmap.activate:null] on resource [2]
2016-02-19 17:24:13,706 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [instanceHostMap:2]
2016-02-19 17:24:13,709 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(MetadataAttachProcessHandler)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [MetadataAttachProcessHandler]
2016-02-19 17:24:13,711 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(MetadataAttachProcessHandler)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [MetadataAttachProcessHandler]
2016-02-19 17:24:13,711 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(AgentInstancePreInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [AgentInstancePreInstanceHostMapActivate]
2016-02-19 17:24:13,711 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(AgentInstancePreInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [AgentInstancePreInstanceHostMapActivate]
2016-02-19 17:24:13,713 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(InstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [InstanceHostMapActivate]
2016-02-19 17:24:20,304 DEBUG [:] [] [] [] [erviceReplay-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:71] on resource [2]
2016-02-19 17:24:20,310 DEBUG [:] [] [] [] [erviceReplay-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [instance.create:71] on resource [2]
2016-02-19 17:24:20,311 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [service.activate:70] on resource [1]
2016-02-19 17:24:20,311 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [environment.create:57] on resource [2]
2016-02-19 17:24:20,311 DEBUG [:] [] [] [] [erviceReplay-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [service.activate:70] on resource [1]
2016-02-19 17:24:20,312 DEBUG [:] [] [] [] [erviceReplay-14] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [PROCESS_ALREADY_IN_PROGRESS] process [environment.create:57] on resource [2]
2016-02-19 17:24:20,485 DEBUG [:] [] [] [] [erviceReplay-16] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [service.activate:70] on resource [1]
2016-02-19 17:24:20,486 INFO [:] [] [] [] [erviceReplay-16] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [service.activate:70] on [1] : Object [instance:2] failed to satisfy predicate [15000] millis
2016-02-19 17:24:20,493 DEBUG [:] [] [] [] [erviceReplay-15] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [TIMEOUT] process [environment.create:57] on resource [2]
2016-02-19 17:24:20,493 INFO [:] [] [] [] [erviceReplay-15] [i.c.p.e.e.i.ProcessEventListenerImpl] Communication timeout on process [environment.create:57] on [2] : null
2016-02-19 17:24:20,862 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(InstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [InstanceHostMapActivate]
2016-02-19 17:24:20,909 DEBUG [:] [] [] [] [tp882902200-128] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [containerevent.create:75] on resource [2]
2016-02-19 17:24:20,910 INFO [92126175-46d7-4ecf-b417-7b0a57d25252:75] [containerEvent:2] [containerevent.create] [] [tp882902200-128] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->creating] on [containerEvent:2]
2016-02-19 17:24:20,911 DEBUG [92126175-46d7-4ecf-b417-7b0a57d25252:75] [containerEvent:2] [containerevent.create] [] [tp882902200-128] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:24:20,931 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(AgentInstanceHostServicesApplyItems)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceHostServicesApplyItems]
2016-02-19 17:24:20,935 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(AgentInstanceHostServicesApplyItems)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceHostServicesApplyItems]
2016-02-19 17:24:20,937 DEBUG [:] [] [] [] [tp882902200-128] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [containerevent.create:75] on resource [2]
2016-02-19 17:24:20,943 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [DockerPostInstanceHostMapActivate]
2016-02-19 17:24:20,978 DEBUG [:] [] [] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [containerevent.create:76] on resource [3]
2016-02-19 17:24:20,985 INFO [b71cd7c6-ae4d-411f-9bf0-68fc202fede4:76] [containerEvent:3] [containerevent.create] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->creating] on [containerEvent:3]
2016-02-19 17:24:20,986 DEBUG [b71cd7c6-ae4d-411f-9bf0-68fc202fede4:76] [containerEvent:3] [containerevent.create] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:24:20,994 DEBUG [:] [] [] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [containerevent.create:75] on resource [2]
2016-02-19 17:24:20,997 DEBUG [:] [] [] [] [qtp882902200-18] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [containerevent.create:76] on resource [3]
2016-02-19 17:24:21,046 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [ipaddress.create:null] on resource [3]
2016-02-19 17:24:21,055 DEBUG [:] [] [] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [containerevent.create:76] on resource [3]
2016-02-19 17:24:21,125 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->ipAddress:3] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->ipaddress.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [ipAddress:3]
2016-02-19 17:24:21,130 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->ipAddress:3] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->ipaddress.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:24:21,131 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->ipAddress:3] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->ipaddress.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:24:21,145 DEBUG [5bbc85ca-abba-4b7b-97f5-9175cd697122:75] [containerEvent:2] [containerevent.create->(ContainerEventPreCreate)] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [ContainerEventPreCreate]
2016-02-19 17:24:21,147 DEBUG [5bbc85ca-abba-4b7b-97f5-9175cd697122:75] [containerEvent:2] [containerevent.create->(ContainerEventPreCreate)] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [ContainerEventPreCreate]
2016-02-19 17:24:21,192 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->ipAddress:3] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->ipaddress.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->activating] on [ipAddress:3]
2016-02-19 17:24:21,196 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->ipAddress:3] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->ipaddress.activate->(IpAddressActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [IpAddressActivate]
2016-02-19 17:24:21,196 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->ipAddress:3] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->ipaddress.activate->(IpAddressActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [IpAddressActivate]
2016-02-19 17:24:21,209 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ContainerEventPreCreate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [ContainerEventPreCreate]
2016-02-19 17:24:21,211 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ContainerEventPreCreate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [ContainerEventPreCreate]
2016-02-19 17:24:21,228 DEBUG [5bbc85ca-abba-4b7b-97f5-9175cd697122:75] [containerEvent:2] [containerevent.create->(ContainerEventCreate)] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ContainerEventCreate]
2016-02-19 17:24:21,230 DEBUG [5bbc85ca-abba-4b7b-97f5-9175cd697122:75] [containerEvent:2] [containerevent.create->(ContainerEventCreate)] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ContainerEventCreate]
2016-02-19 17:24:21,232 DEBUG [5bbc85ca-abba-4b7b-97f5-9175cd697122:75] [containerEvent:2] [containerevent.create->(ActivateByDefault)] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:24:21,232 DEBUG [5bbc85ca-abba-4b7b-97f5-9175cd697122:75] [containerEvent:2] [containerevent.create->(ActivateByDefault)] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:24:21,276 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->ipAddress:3] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->ipaddress.activate] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [ipAddress:3]
2016-02-19 17:24:21,276 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [ipaddress.activate:null] on resource [3]
2016-02-19 17:24:21,279 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [ipaddress.activate:null] on resource [3]
2016-02-19 17:24:21,279 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [ALREADY_DONE] process [ipaddress.activate:null] on resource [3]
2016-02-19 17:24:21,280 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ContainerEventCreate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ContainerEventCreate]
2016-02-19 17:24:21,289 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive}] to [VolumeRecord:null]
2016-02-19 17:24:21,292 INFO [5bbc85ca-abba-4b7b-97f5-9175cd697122:75] [containerEvent:2] [containerevent.create] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [creating->created] on [containerEvent:2]
2016-02-19 17:24:21,360 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ContainerEventCreate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.stop:77] on resource [2]
2016-02-19 17:24:21,376 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.create:null] on resource [6]
2016-02-19 17:24:21,442 DEBUG [:] [] [] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [containerevent.create:75] on resource [2]
2016-02-19 17:24:21,442 INFO [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3->instance:2] [containerevent.create->(ContainerEventCreate)->instance.stop] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [starting->stopping] on [instance:2]
2016-02-19 17:24:21,442 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3->instance:2] [containerevent.create->(ContainerEventCreate)->instance.stop] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:24:21,459 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [volume:6]
2016-02-19 17:24:21,461 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:21,461 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:21,510 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ContainerEventCreate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [instance.stop:77] on resource [2]
2016-02-19 17:24:21,510 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ContainerEventCreate)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ContainerEventCreate]
2016-02-19 17:24:21,522 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ActivateByDefault)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:24:21,524 DEBUG [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create->(ActivateByDefault)] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:24:21,531 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:24:21,531 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:24:21,564 INFO [0cc59884-d7e3-4469-bca3-bc90624ba464:76] [containerEvent:3] [containerevent.create] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [creating->created] on [containerEvent:3]
2016-02-19 17:24:21,580 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [volume:6]
2016-02-19 17:24:21,580 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volume.create:null] on resource [6]
2016-02-19 17:24:21,580 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Created volume [6] in storage pool [1].
2016-02-19 17:24:21,644 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Volme mount created. Volume id [6], instance id [2], mount id [4]
2016-02-19 17:24:21,697 DEBUG [:] [] [] [] [ecutorService-7] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [containerevent.create:76] on resource [3]
2016-02-19 17:24:21,703 DEBUG [:] [] [] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.stop:77] on resource [2]
2016-02-19 17:24:21,715 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [mount.create:78] on resource [4]
2016-02-19 17:24:21,762 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:4] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [mount:4]
2016-02-19 17:24:21,762 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:4] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:24:21,814 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [mount.create:78] on resource [4]
2016-02-19 17:24:21,817 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive}] to [VolumeRecord:null]
2016-02-19 17:24:21,866 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.create:null] on resource [7]
2016-02-19 17:24:21,915 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [volume:7]
2016-02-19 17:24:21,919 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:21,920 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:21,968 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:24:21,968 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:24:22,016 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [volume:7]
2016-02-19 17:24:22,017 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volume.create:null] on resource [7]
2016-02-19 17:24:22,017 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Created volume [7] in storage pool [1].
2016-02-19 17:24:22,070 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Volme mount created. Volume id [7], instance id [2], mount id [5]
2016-02-19 17:24:22,120 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [mount.create:79] on resource [5]
2016-02-19 17:24:22,169 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:5] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [mount:5]
2016-02-19 17:24:22,169 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:5] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:24:22,221 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [mount.create:79] on resource [5]
2016-02-19 17:24:22,225 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive}] to [VolumeRecord:null]
2016-02-19 17:24:22,274 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.create:null] on resource [8]
2016-02-19 17:24:22,321 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:8] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [volume:8]
2016-02-19 17:24:22,322 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:8] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:22,323 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:8] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:22,377 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:8] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:24:22,377 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:8] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:24:22,417 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:8] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [volume:8]
2016-02-19 17:24:22,418 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volume.create:null] on resource [8]
2016-02-19 17:24:22,418 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Created volume [8] in storage pool [1].
2016-02-19 17:24:22,466 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Volme mount created. Volume id [8], instance id [2], mount id [6]
2016-02-19 17:24:22,534 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [mount.create:80] on resource [6]
2016-02-19 17:24:22,578 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [mount:6]
2016-02-19 17:24:22,578 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:6] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:24:22,628 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [mount.create:80] on resource [6]
2016-02-19 17:24:22,631 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive}] to [VolumeRecord:null]
2016-02-19 17:24:22,678 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.create:null] on resource [9]
2016-02-19 17:24:22,726 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:9] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [volume:9]
2016-02-19 17:24:22,728 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:9] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:22,729 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:9] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(VolumeExternalIdPreCreate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [VolumeExternalIdPreCreate]
2016-02-19 17:24:22,777 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:9] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault]
2016-02-19 17:24:22,777 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:9] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create->(ActivateByDefault)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault]
2016-02-19 17:24:22,825 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->volume:9] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->volume.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [volume:9]
2016-02-19 17:24:22,826 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [volume.create:null] on resource [9]
2016-02-19 17:24:22,826 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Created volume [9] in storage pool [1].
2016-02-19 17:24:22,878 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [.i.DockerPostInstanceHostMapActivate] Volme mount created. Volume id [9], instance id [2], mount id [7]
2016-02-19 17:24:22,936 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [mount.create:81] on resource [7]
2016-02-19 17:24:23,012 INFO [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [mount:7]
2016-02-19 17:24:23,013 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->mount:7] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)->mount.create] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED
2016-02-19 17:24:23,056 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [mount.create:81] on resource [7]
2016-02-19 17:24:23,065 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive}] to [VolumeRecord:null]
2016-02-19 17:24:23,118 DEBUG [66ba011f-6a4b-4862-b34e-d6532daf23b5:71] [instance:2->instanceHostMap:2] [instance.start->(InstanceStart)->instancehostmap.activate->(DockerPostInstanceHostMapActivate)] [] [ecutorService-4] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [volume.create:null] on resource [10]
root@6d8d11858d86:/var/lib/cattle/logs#
root@6d8d11858d86:/var/lib/cattle/logs#
root@6d8d11858d86:/var/lib/cattle/logs# ls
cattle-debug.log cattle-error.log
root@6d8d11858d86:/var/lib/cattle/logs# ls -a
. .. cattle-debug.log cattle-error.log
root@6d8d11858d86:/var/lib/cattle/logs# ls -l
total 1036
-rw-r--r-- 1 root root 1053507 Feb 19 17:25 cattle-debug.log
-rw-r--r-- 1 root root 145 Feb 19 17:21 cattle-error.log
root@6d8d11858d86:/var/lib/cattle/logs# nano cattle-error.log
bash: nano: command not found
root@6d8d11858d86:/var/lib/cattle/logs# vi cattle-debug.log
2016-02-19 17:18:31,062 INFO [:] [] [] [] [main ] [i.c.platform.logback.LogbackStartup ] Logback configured with [jar:file:/usr/share/cattle/b2d529b20e9c5001f1ff765945f4b940/WEB-INF/lib/cattle-framework-logback-0.5.0-SNAPS
HOT.jar!/logback/logback.xml]
2016-02-19 17:18:31,083 DEBUG [:] [] [] [] [main ] [a.c.s.m.c.ResourceApplicationContext] Unable to locate LifecycleProcessor with name 'lifecycleProcessor': using default [org.springframework.context.support.DefaultLifecyc
leProcessor@72488c90]
2016-02-19 17:18:31,089 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Loaded module context [bootstrap] in 3834 ms
2016-02-19 17:18:31,089 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: bootstrap
2016-02-19 17:18:31,089 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: config-defaults
2016-02-19 17:18:31,090 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: system
2016-02-19 17:18:31,090 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: defaults
2016-02-19 17:18:31,090 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: types
2016-02-19 17:18:31,090 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: system-services
2016-02-19 17:18:31,091 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: agent-server
2016-02-19 17:18:31,091 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: allocator-server
2016-02-19 17:18:31,091 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: api-server
2016-02-19 17:18:31,091 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: iaas-api
2016-02-19 17:18:31,091 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: archaius
2016-02-19 17:18:31,092 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: core-model
2016-02-19 17:18:31,092 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: core-object-defaults
2016-02-19 17:18:31,092 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: encryption
2016-02-19 17:18:31,092 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: process
2016-02-19 17:18:31,092 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: redis
2016-02-19 17:18:31,093 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Module Hierarchy: storage-simulator
2016-02-19 17:18:31,095 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Loading module context [config-defaults] from URL [jar:file:/usr/share/cattle/b2d529b20e9c5001f1ff765945f4b940/WEB-INF/lib/cattle-app
-config-0.5.0-SNAPSHOT.jar!/META-INF/cattle/bootstrap/spring-bootstrap-context-inheritable.xml]
2016-02-19 17:18:31,095 INFO [:] [] [] [] [main ] [c.s.m.m.i.DefaultModuleDefinitionSet] Loading module context [config-defaults] from URL [jar:file:/usr/share/cattle/b2d529b20e9c5001f1ff765945f4b940/WEB-INF/lib/cattle-app
-config-0.5.0-SNAPSHOT.jar!/META-INF/cattle/bootstrap/spring-metrics-context-inheritable.xml]
2016-02-19 17:18:31,095 INFO [:] [] [] [] [main ] [a.c.s.m.c.ResourceApplicationContext] Refreshing ResourceApplicationContext [applicationName=/config-defaults, configResources=[URL [jar:file:/usr/share/cattle/b2d529b20e9
c5001f1ff765945f4b940/WEB-INF/lib/cattle-app-config-0.5.0-SNAPSHOT.jar!/META-INF/cattle/bootstrap/spring-bootstrap-context-inheritable.xml], URL [jar:file:/usr/share/cattle/b2d529b20e9c5001f1ff765945f4b940/WEB-INF/lib/cattle-app-conf
ig-0.5.0-SNAPSHOT.jar!/META-INF/cattle/bootstrap/spring-metrics-context-inheritable.xml]]]
"cattle-debug.log" 6190 lines, 1690298 characters
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment