Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stuck in trying to register forever #3179

Closed
lenovouser opened this issue Jan 6, 2016 · 44 comments
Closed

Stuck in trying to register forever #3179

lenovouser opened this issue Jan 6, 2016 · 44 comments
Labels
area/agent Issues that deal with the Rancher Agent kind/bug Issues that are defects reported by users or that we know have reached a real release

Comments

@lenovouser
Copy link

Like stated above, don't know what is causing this. Registered another host and it worked perfectly fine.

Logs:

time="2016-01-06T23:24:04Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
I0107 00:24:05.005421 13647 cadvisor.go:90] Starting cAdvisor version: "0.12.0" on port 9344
time="2016-01-06T23:24:06Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:07Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:08Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:09Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:10Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=5 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:11Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=6 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:12Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=7 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:13Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=8 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:14Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=9 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:15Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=10 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:16Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=11 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:17Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=12 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:18Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=13 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:19Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=14 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:20Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=15 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:21Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=16 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:22Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=17 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:23Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=18 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:24Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=19 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:25Z" level="fatal" msg="Reached max retry attempts for getting token."
time="2016-01-06T23:24:26Z" level="info" msg="Starting event router."
time="2016-01-06T23:24:26Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-01-06T23:24:26Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"d6258e80fad698557f613f75b2fab7148bdd1b4fb05087393f55bab415d16b3e\", From:\"-simulated-\", Time:0}"
time="2016-01-06T23:24:26Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:27Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:28Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:29Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:30Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:31Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=5 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:32Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=6 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:33Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=7 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:34Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=8 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:35Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=9 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:36Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=10 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:37Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=11 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:38Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=12 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:39Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=13 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:40Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=14 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:42Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=15 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:43Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=16 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:44Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=17 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:45Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=18 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:46Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=19 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:47Z" level="fatal" msg="Reached max retry attempts for getting token."
time="2016-01-06T23:24:48Z" level="info" msg="Starting event router."
time="2016-01-06T23:24:48Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-01-06T23:24:48Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"d6258e80fad698557f613f75b2fab7148bdd1b4fb05087393f55bab415d16b3e\", From:\"-simulated-\", Time:0}"
time="2016-01-06T23:24:49Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:50Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:51Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:52Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:53Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:54Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=5 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:55Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=6 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:56Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=7 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:57Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=8 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:58Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=9 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:24:59Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=10 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:00Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=11 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:01Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=12 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:02Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=13 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:03Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=14 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:04Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=15 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:05Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=16 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:06Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=17 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:07Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=18 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:08Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=19 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:09Z" level="fatal" msg="Reached max retry attempts for getting token."
time="2016-01-06T23:25:10Z" level="info" msg="Starting event router."
time="2016-01-06T23:25:10Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-01-06T23:25:10Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"d6258e80fad698557f613f75b2fab7148bdd1b4fb05087393f55bab415d16b3e\", From:\"-simulated-\", Time:0}"
time="2016-01-06T23:25:10Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:11Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:12Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:13Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:14Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:15Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=5 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:16Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=6 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:17Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=7 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:18Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=8 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:19Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=9 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:21Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=10 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:22Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=11 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:23Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=12 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:24Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=13 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:25Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=14 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:26Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=15 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:27Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=16 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:28Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=17 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:29Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=18 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:30Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=19 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:31Z" level="fatal" msg="Reached max retry attempts for getting token."
time="2016-01-06T23:25:32Z" level="info" msg="Starting event router."
time="2016-01-06T23:25:32Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-01-06T23:25:32Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"d6258e80fad698557f613f75b2fab7148bdd1b4fb05087393f55bab415d16b3e\", From:\"-simulated-\", Time:0}"
time="2016-01-06T23:25:32Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:33Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:34Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:35Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:36Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-06T23:25:37Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=5 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
@will-chan will-chan added the kind/question Issues that just require an answer. No code change needd label Jan 7, 2016
@lenovouser
Copy link
Author

Any updates? How do I fix the Reached max retry attempts for getting token error and why does it even show up? Other hosts register just fine 😞

@phenomax
Copy link

+1

@deniseschannon
Copy link

Can you provide more details on the host that's failing? If other hosts are registering fine, then it must be unique to this host?

Is this host also running rancher server? How are you adding this host?

What version of Rancher server are you running? How are you running it (locally, on a VM (GCE, AWS, DO), etc?) Is this a standalone container or a HA set up?

@lenovouser
Copy link
Author

@deniseschannon

Some more info:

  • We even fully disabled our firewall, that didn't do the trick either.
  • The host where it works and the host where it doesn't are both not running rancher-server.
  • I am adding both hosts manual over add/custom.
  • All hosts are running Debian 8 'Jessie' and Docker version 1.9.1, build a34a1d5.
  • Rancher version 0.30.0, locally on a bare metal machine and running in standalone mode.

Host Information:

Host 1 / Master | agent + server (running fine):

docker -v:
Docker version 1.9.1, build a34a1d5

uname -a:
Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt11-1+deb8u3 (2015-08-04) x86_64 GNU/Linux

Host 2 / Slave | agent (running fine):

docker -v:
Docker version 1.9.1, build a34a1d5

uname -a:
Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u2 (2016-01-02) x86_64 GNU/Linux

Host 3 / Slave | agent (failing):

docker -v:
Docker version 1.9.1, build a34a1d5

uname -a:
Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u2 (2016-01-02) x86_64 GNU/Linux

@deniseschannon
Copy link

I just want to confirm that you're running Rancher v0.30.0? I'm not sure that version would support Docker 1.9.1. Would you be willing to upgrade? We're at v0.51.0.

It's strange that 1 host would be able to register and not the other...

@lenovouser
Copy link
Author

@deniseschannon sorry for the late reply. We updated rancher now to v0.5.1.0

Error still persists and is the same as before.

which then ends with

@phenomax
Copy link

+1

@lenovouser
Copy link
Author

Is there any way I can debug this? Pinging the rancher server from this host works just fine. Also curling the site works.

@phenomax
Copy link

Same question here: We re stucking in coming ahead by rancher agent not wanting to connect :/

@cjellick
Copy link

@lenovouser is the host showing up in the Rancher UI? If so, can you click its drop down menu, click 'view and api' and share its api output here? Please scrub it of any sensitive information such as domains/ips that you dont wish to share.

Also, can you check the logs inside the rancher-agent container at /var/log/rancher/agent.log to see if there are any other errors there?

@lenovouser
Copy link
Author

@cjellick thanks for the reply. No, it is not showing up in the host view, that is our problem. The problem is in fact that it is not connecting and we don't really know why. The logs are very big, I had to .zip them:

rancher-agent.log.zip

@cjellick
Copy link

Thanks @lenovouser. That "Host not registered yet" error you're seeing is actually a symptom, same as the host not showing up in the UI yet.

There is either some connectivity problem between your host and rancehr-server or rancher-server is erroring out when trying to process the host.

Would you be able to also send over the logs for rancher-agent container? You can limit the output in case it is really long via `docker logs rancher-agent --tail 3000.

Also, in the Rancher UI, go to the admin tab, then processes and let me know if there are any long running processes there. Finally, have a look at the rancher-server logs and see if their any recurring errors.

@lenovouser
Copy link
Author

Okay, here are the container logs (I just created a fresh one to be sure):

INFO: Starting agent for xxxxxxxxxxxxxxxxxxxxxxxxxxxxx
INFO: Access Key: xxxxxxxxxxxxxxxxxxxxxxxxxxxxx
INFO: Config URL: https://rancher.domain.tld/v1
INFO: Storage URL: https://rancher.domain.tld/v1
INFO: API URL: https://rancher.domain.tld/v1
INFO: IP: xxx.xxx.xxx.xxx
INFO: Port:
INFO: Required Image: rancher/agent:v0.8.2
INFO: Current Image: rancher/agent:v0.8.2
INFO: Using image rancher/agent:v0.8.2
INFO: Downloading agent https://rancher.domain.tld/v1/configcontent/configscripts
INFO: Updating configscripts
INFO: Downloading https://rancher.domain.tld/v1//configcontent//configscripts current=
INFO: Running /var/lib/cattle/download/configscripts/configscripts-1-f0f3fb2e1110b5ada7c441705981f93a480313a324294321cff467f0c3e12319/apply.sh
INFO: Sending configscripts applied 1-f0f3fb2e1110b5ada7c441705981f93a480313a324294321cff467f0c3e12319
INFO: Updating pyagent
INFO: Downloading https://rancher.domain.tld/v1//configcontent//pyagent current=
INFO: Running /var/lib/cattle/download/pyagent/pyagent-1-9e3dcab12585149a65d818082279708965cd826df1937a55b24f48428f8f0c06069547103e24f5f4562a2db5d4805d60/apply.sh
INFO: Updating host-api
INFO: Downloading https://rancher.domain.tld/v1//configcontent//host-api current=
INFO: Running /var/lib/cattle/download/host-api/1-1dcc85d77415faddc4d6d204d2bd622d835de4b5ee4b472651419b58189c474a/apply.sh
INFO: Sending host-api applied 1-1dcc85d77415faddc4d6d204d2bd622d835de4b5ee4b472651419b58189c474a
INFO: Updating agent-binaries
INFO: Downloading https://rancher.domain.tld/v1//configcontent//agent-binaries current=
INFO: Running /var/lib/cattle/download/agent-binaries/1-4200f9b686342da8e941359211b1d8c5f98877ae293d0ead231d43507f1c9eae/apply.sh
INFO: Sending agent-binaries applied 1-4200f9b686342da8e941359211b1d8c5f98877ae293d0ead231d43507f1c9eae
INFO: Updating python-agent
INFO: Downloading https://rancher.domain.tld/v1//configcontent//python-agent current=
INFO: Running /var/lib/cattle/download/python-agent/1-5fa9b53964d8b1335257916f7b4687aec2e17c9516e578f5406f29160eec1cd1/apply.sh
INFO: Sending python-agent applied 1-5fa9b53964d8b1335257916f7b4687aec2e17c9516e578f5406f29160eec1cd1
INFO: Updating cadvisor
INFO: Downloading https://rancher.domain.tld/v1//configcontent//cadvisor current=
INFO: Running /var/lib/cattle/download/cadvisor/1-4d2b4356ab14bc1fa7ec7cd83f35b7e975a16cea01634683b577c9498c98de25/apply.sh
INFO: HOME -> ./
INFO: HOME -> ./bin/
INFO: HOME -> ./bin/cadvisor.sh
INFO: HOME -> ./bin/cadvisor
INFO: Sending cadvisor applied 1-4d2b4356ab14bc1fa7ec7cd83f35b7e975a16cea01634683b577c9498c98de25
INFO: Updating volmgr
INFO: Downloading https://rancher.domain.tld/v1//configcontent//volmgr current=
INFO: Running /var/lib/cattle/download/volmgr/1-c813690c24ae9a12f0792378c78a48f447b243517233d7969b99baefbea5af15/apply.sh
INFO: Sending volmgr applied 1-c813690c24ae9a12f0792378c78a48f447b243517233d7969b99baefbea5af15
INFO: Sending pyagent applied 1-9e3dcab12585149a65d818082279708965cd826df1937a55b24f48428f8f0c06069547103e24f5f4562a2db5d4805d60
INFO: Starting agent /var/lib/cattle/pyagent/apply.sh
INFO: Executing /var/lib/cattle/pyagent/main.py
INFO: Updating host-config
INFO: Downloading https://rancher.domain.tld/v1//configcontent//host-config current=
INFO: Running /var/lib/cattle/download/host-config/host-config-1-48d1f8f4fedaa44e237395b9443aa13b03be6b382e27bf394340d07b3365175f/apply.sh
INFO: HOME -> ./
INFO: HOME -> ./etc/
INFO: HOME -> ./etc/cattle/
INFO: HOME -> ./etc/cattle/api.crt
INFO: Sending host-config applied 1-48d1f8f4fedaa44e237395b9443aa13b03be6b382e27bf394340d07b3365175f
I0120 18:19:08.728550 29555 storagedriver.go:132] No backend storage selected
I0120 18:19:08.728604 29555 storagedriver.go:134] Caching stats in memory for 2m0s
I0120 18:19:08.728647 29555 manager.go:128] cAdvisor running in container: "/system.slice/docker-49a2e6712d4afc54f8543faa05e41678bcc900058d16b765a9627aa5ed7a8e0c.scope"
time="2016-01-20T17:19:08Z" level="info" msg="Starting event router."
time="2016-01-20T17:19:08Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
I0120 18:19:08.806402 29555 fs.go:108] Filesystem partitions: map[/dev/md1:{mountpoint:/ major:9 minor:1 fsType: blockSize:0}]
I0120 18:19:08.809066 29555 manager.go:163] Machine: {NumCores:8 CpuFrequency:3800000 MemoryCapacity:33712635904 MachineID:575489e0268f48c39be50f8d8fddf616 SystemUUID:1242199A-4C92-E011-8D76-00E04CB27049 BootID:4832a60f-c31c-4b03-b577-8a0927c337d7 Filesystems:[{Device:/dev/md1 Capacity:111668994048}] DiskMap:map[9:1:{Name:md1 Major:9 Minor:1 Size:113586929664 Scheduler:none} 8:0:{Name:sda Major:8 Minor:0 Size:120034123776 Scheduler:cfq} 8:16:{Name:sdb Major:8 Minor:16 Size:120034123776 Scheduler:cfq} 8:32:{Name:sdc Major:8 Minor:32 Size:120034123776 Scheduler:cfq}] NetworkDevices:[{Name:eth0 MacAddress:e0:69:95:c8:70:90 Speed:1000 Mtu:1500}] Topology:[{Id:0 Memory:33712635904 Cores:[{Id:0 Threads:[0 4] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]} {Id:1 Threads:[1 5] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]} {Id:2 Threads:[2 6] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]} {Id:3 Threads:[3 7] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:8388608 Type:Unified Level:3}]}] CloudProvider:Unknown InstanceType:Unknown}
I0120 18:19:08.824417 29555 manager.go:169] Version: {KernelVersion:3.16.0-4-amd64 ContainerOsVersion:Debian GNU/Linux 8 (jessie) DockerVersion:1.9.1 CadvisorVersion: CadvisorRevision:}
I0120 18:19:08.824791 29555 factory.go:194] System is using systemd
time="2016-01-20T17:19:08Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"49a2e6712d4afc54f8543faa05e41678bcc900058d16b765a9627aa5ed7a8e0c\", From:\"-simulated-\", Time:0}"
time="2016-01-20T17:19:08Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
I0120 18:19:08.969231 29555 factory.go:236] Registering Docker factory
I0120 18:19:08.969589 29555 factory.go:93] Registering Raw factory
I0120 18:19:09.068836 29555 manager.go:1006] Started watching for new ooms in manager
I0120 18:19:09.068860 29555 oomparser.go:199] OOM parser using kernel log file: "/var/log/kern.log"
I0120 18:19:09.069321 29555 manager.go:250] Starting recovery of all containers
I0120 18:19:09.093907 29555 manager.go:255] Recovery completed
I0120 18:19:09.116477 29555 cadvisor.go:96] Starting cAdvisor version: - on port 9344
time="2016-01-20T17:19:09Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:10Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:11Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:12Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:13Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=5 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:14Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=6 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:15Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=7 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:16Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=8 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:17Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=9 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:18Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=10 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:19Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=11 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:20Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=12 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:21Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=13 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:22Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=14 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:23Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=15 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:24Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=16 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:26Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=17 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:27Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=18 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:28Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=19 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:29Z" level="fatal" msg="Reached max retry attempts for getting token."
time="2016-01-20T17:19:30Z" level="info" msg="Starting event router."
time="2016-01-20T17:19:30Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-01-20T17:19:30Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"49a2e6712d4afc54f8543faa05e41678bcc900058d16b765a9627aa5ed7a8e0c\", From:\"-simulated-\", Time:0}"
time="2016-01-20T17:19:30Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:31Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:32Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:33Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:34Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:35Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=5 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:36Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=6 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:37Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=7 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:38Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=8 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:39Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=9 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:40Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=10 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:41Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=11 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:42Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=12 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:43Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=13 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:44Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=14 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:45Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=15 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:46Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=16 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:47Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=17 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:48Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=18 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:49Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=19 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:50Z" level="fatal" msg="Reached max retry attempts for getting token."
time="2016-01-20T17:19:52Z" level="info" msg="Starting event router."
time="2016-01-20T17:19:52Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-01-20T17:19:52Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"49a2e6712d4afc54f8543faa05e41678bcc900058d16b765a9627aa5ed7a8e0c\", From:\"-simulated-\", Time:0}"
time="2016-01-20T17:19:52Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=0 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:53Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=1 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:54Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=2 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:55Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=3 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"
time="2016-01-20T17:19:56Z" level="info" msg="Host not registered yet. Sleeping 1 second and trying again." Attempt=4 reportedUuid="c2d67194-b81a-42a1-9bf1-50765811f069"

this just repeats itself indefinitely.

I am not really sure if it is a connectivity issue because I was able to ping and curl the rancher-server from the host machine and rancher-agent container.

There also indeed is a reconnect process running for a very long time in the admin panel:

If I click on that it takes forever to load and ends with this screen:

Which finally seems to give some information, even though I still don't get why it is failing.

And last: where can I find the rancher-server logs? There are none in /var/log/rancher. Or do you mean the container ones? Thanks for your help!

@lenovouser
Copy link
Author

In case you wanted the rancher-server container logs, here you go:

time="2016-01-16T18:45:37Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-16T18:45:48Z" level=info msg="Exiting go-machine-service..."
time="2016-01-16T18:45:48Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
160116 18:46:00 [Note] /usr/sbin/mysqld (mysqld 5.5.46-0ubuntu0.14.04.2-log) starting as process 23 ...
Uptime: 2  Threads: 1  Questions: 2  Slow queries: 0  Opens: 34  Flush tables: 1  Open tables: 26  Queries per second avg: 1.000
Setting up database
CATTLE_AGENT_PACKAGE_AGENT_BINARIES_URL=/usr/share/cattle/artifacts/agent-binaries.tar.gz
CATTLE_AGENT_PACKAGE_CADVISOR_URL=/usr/share/cattle/artifacts/cadvisor.tar.gz
CATTLE_AGENT_PACKAGE_HOST_API_URL=/usr/share/cattle/artifacts/host-api.tar.gz
CATTLE_AGENT_PACKAGE_NODE_AGENT_URL=/usr/share/cattle/artifacts/node-agent.tar.gz
CATTLE_AGENT_PACKAGE_PYTHON_AGENT_URL=/usr/share/cattle/artifacts/python-agent.tar.gz
CATTLE_AGENT_PACKAGE_RANCHER_DNS_URL=/usr/share/cattle/artifacts/rancher-dns.tar.gz
CATTLE_AGENT_PACKAGE_RANCHER_METADATA_URL=/usr/share/cattle/artifacts/rancher-metadata.tar.gz
CATTLE_AGENT_PACKAGE_VOLMGR_URL=/usr/share/cattle/artifacts/volmgr.tar.gz
CATTLE_CATTLE_VERSION=v0.130.0
CATTLE_DB_CATTLE_DATABASE=mysql
CATTLE_DB_CATTLE_MYSQL_HOST=localhost
CATTLE_DB_CATTLE_MYSQL_NAME=cattle
CATTLE_DB_CATTLE_MYSQL_PORT=3306
CATTLE_DB_CATTLE_USERNAME=cattle
CATTLE_GRAPHITE_HOST=
CATTLE_GRAPHITE_PORT=
CATTLE_HOME=/var/lib/cattle
CATTLE_HOST_API_PROXY_MODE=embedded
CATTLE_LOGBACK_OUTPUT_GELF_HOST=
CATTLE_LOGBACK_OUTPUT_GELF_PORT=
CATTLE_RANCHER_COMPOSE_VERSION=v0.7.0
CATTLE_RANCHER_SERVER_IMAGE=v0.51.0
CATTLE_USE_LOCAL_ARTIFACTS=true
DEFAULT_CATTLE_API_UI_INDEX=//releases.rancher.com/ui/0.78.0
DEFAULT_CATTLE_CATALOG_EXECUTE=true
DEFAULT_CATTLE_COMPOSE_EXECUTOR_EXECUTE=true
DEFAULT_CATTLE_MACHINE_EXECUTE=true
DEFAULT_CATTLE_RANCHER_COMPOSE_DARWIN_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-darwin-amd64-v0.7.0.tar.gz
DEFAULT_CATTLE_RANCHER_COMPOSE_LINUX_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-linux-amd64-v0.7.0.tar.gz
DEFAULT_CATTLE_RANCHER_COMPOSE_WINDOWS_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-windows-386-v0.7.0.zip
18:46:03.622 [main] WARN  o.e.jetty.security.SecurityHandler - ServletContext@o.e.j.w.WebAppContext@6c521576{/,file:/usr/share/cattle/b10c392870b9f40c15fbff8d3e16135c/,STARTING}{file:/usr/share/cattle/b10c392870b9f40c15fbff8d3e16135c/} has uncovered http methods for path: /
18:46:04.538 [main] INFO  ConsoleStatus - [1/6] [0ms] [0ms] Loading config-bootstrap
18:46:04.675 [main] INFO  ConsoleStatus - [2/6] [138ms] [135ms] Loading base-config
18:46:04.867 [main] INFO  ConsoleStatus - [3/6] [330ms] [192ms] Loading config
18:46:04.871 [main] INFO  ConsoleStatus - [4/6] [334ms] [4ms] Starting config-bootstrap
18:46:04.995 [main] INFO  ConsoleStatus - [5/6] [458ms] [124ms] Starting base-config
18:46:04.995 [main] INFO  ConsoleStatus - [6/6] [458ms] [0ms] Starting config
2016-01-16 18:46:05,174 INFO    [main] [ConsoleStatus] [1/36] [0ms] [0ms] Loading bootstrap
2016-01-16 18:46:05,225 INFO    [main] [ConsoleStatus] [2/36] [51ms] [51ms] Loading config-defaults
2016-01-16 18:46:08,596 INFO    [main] [ConsoleStatus] [3/36] [3422ms] [3371ms] Loading system
2016-01-16 18:46:08,626 INFO    [main] [ConsoleStatus] [4/36] [3452ms] [30ms] Loading defaults
2016-01-16 18:46:08,746 INFO    [main] [ConsoleStatus] [5/36] [3572ms] [120ms] Loading types
2016-01-16 18:46:10,953 INFO    [main] [ConsoleStatus] [6/36] [5779ms] [2207ms] Loading system-services
2016-01-16 18:46:11,127 INFO    [main] [ConsoleStatus] [7/36] [5953ms] [174ms] Loading agent-server
2016-01-16 18:46:11,308 INFO    [main] [ConsoleStatus] [8/36] [6134ms] [181ms] Loading allocator-server
2016-01-16 18:46:12,206 INFO    [main] [ConsoleStatus] [9/36] [7032ms] [898ms] Loading api-server
2016-01-16 18:46:13,106 INFO    [main] [ConsoleStatus] [10/36] [7932ms] [900ms] Loading iaas-api
2016-01-16 18:46:13,136 INFO    [main] [ConsoleStatus] [11/36] [7962ms] [30ms] Loading archaius
2016-01-16 18:46:13,265 INFO    [main] [ConsoleStatus] [12/36] [8091ms] [129ms] Loading core-model
2016-01-16 18:46:13,289 INFO    [main] [ConsoleStatus] [13/36] [8115ms] [24ms] Loading core-object-defaults
2016-01-16 18:46:13,311 INFO    [main] [ConsoleStatus] [14/36] [8137ms] [22ms] Loading encryption
2016-01-16 18:46:14,852 INFO    [main] [ConsoleStatus] [15/36] [9678ms] [1541ms] Loading process
2016-01-16 18:46:15,093 INFO    [main] [ConsoleStatus] [16/36] [9919ms] [241ms] Loading process-server
2016-01-16 18:46:15,113 INFO    [main] [ConsoleStatus] [17/36] [9939ms] [20ms] Loading redis
2016-01-16 18:46:15,146 INFO    [main] [ConsoleStatus] [18/36] [9972ms] [33ms] Loading storage-simulator
2016-01-16 18:46:15,172 INFO    [main] [ConsoleStatus] [19/36] [9998ms] [26ms] Starting bootstrap
2016-01-16 18:46:15,172 INFO    [main] [ConsoleStatus] [20/36] [9998ms] [0ms] Starting config-defaults
2016-01-16 18:46:15,172 INFO    [main] [ConsoleStatus] [21/36] [9998ms] [0ms] Starting system
2016-01-16 18:46:15,172 INFO    [main] [ConsoleStatus] [22/36] [9998ms] [0ms] Starting defaults
2016-01-16 18:46:15,172 INFO    [main] [ConsoleStatus] [23/36] [9998ms] [0ms] Starting types
2016-01-16 18:46:16,187 INFO    [main] [ConsoleStatus] [24/36] [11013ms] [1015ms] Starting system-services
2016-01-16 18:46:16,187 INFO    [main] [ConsoleStatus] [25/36] [11013ms] [0ms] Starting agent-server
2016-01-16 18:46:16,187 INFO    [main] [ConsoleStatus] [26/36] [11013ms] [0ms] Starting allocator-server
2016-01-16 18:46:16,396 INFO    [main] [ConsoleStatus] [27/36] [11222ms] [209ms] Starting api-server
2016-01-16 18:46:17,280 INFO    [main] [ConsoleStatus] [28/36] [12106ms] [884ms] Starting iaas-api
2016-01-16 18:46:17,280 INFO    [main] [ConsoleStatus] [29/36] [12106ms] [0ms] Starting archaius
2016-01-16 18:46:17,280 INFO    [main] [ConsoleStatus] [30/36] [12106ms] [0ms] Starting core-model
2016-01-16 18:46:17,280 INFO    [main] [ConsoleStatus] [31/36] [12106ms] [0ms] Starting core-object-defaults
2016-01-16 18:46:17,280 INFO    [main] [ConsoleStatus] [32/36] [12106ms] [0ms] Starting encryption
2016-01-16 18:46:17,282 INFO    [main] [ConsoleStatus] [33/36] [12108ms] [2ms] Starting process
2016-01-16 18:46:17,284 INFO    [main] [ConsoleStatus] [34/36] [12110ms] [2ms] Starting process-server
2016-01-16 18:46:17,284 INFO    [main] [ConsoleStatus] [35/36] [12110ms] [0ms] Starting redis
2016-01-16 18:46:17,284 INFO    [main] [ConsoleStatus] [36/36] [12110ms] [0ms] Starting storage-simulator
18:46:17.348 [main] INFO  ConsoleStatus - [DONE ] [14509ms] Startup Succeeded, Listening on port 8081
time="2016-01-16T18:46:18Z" level=info msg="Starting websocket proxy. Listening on [:8080], Proxying to cattle API at [localhost:8081], Monitoring parent pid [8]."
time="2016-01-16T18:46:19Z" level=info msg="Starting Rancher Catalog service"
time="2016-01-16T18:46:19Z" level=info msg="Using catalog library=https://github.com/rancher/rancher-catalog.git"
time="2016-01-16T18:46:19Z" level=info msg="Cloning the catalog from git url https://github.com/rancher/rancher-catalog.git"
Cloning into './DATA/library'...
time="2016-01-16T18:46:19Z" level=info msg="Setting log level" logLevel=info
time="2016-01-16T18:46:19Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-16T18:46:19Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-16T18:46:19Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-16T18:46:20Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-16T18:46:20Z" level=info msg="Connection established"
time="2016-01-16T18:46:20Z" level=info msg="Connection established"
time="2016-01-16T18:46:23Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
160116 18:46:50 [Note] /usr/sbin/mysqld (mysqld 5.5.46-0ubuntu0.14.04.2-log) starting as process 24 ...
Uptime: 2  Threads: 1  Questions: 2  Slow queries: 0  Opens: 34  Flush tables: 1  Open tables: 26  Queries per second avg: 1.000
Setting up database
CATTLE_AGENT_PACKAGE_AGENT_BINARIES_URL=/usr/share/cattle/artifacts/agent-binaries.tar.gz
CATTLE_AGENT_PACKAGE_CADVISOR_URL=/usr/share/cattle/artifacts/cadvisor.tar.gz
CATTLE_AGENT_PACKAGE_HOST_API_URL=/usr/share/cattle/artifacts/host-api.tar.gz
CATTLE_AGENT_PACKAGE_NODE_AGENT_URL=/usr/share/cattle/artifacts/node-agent.tar.gz
CATTLE_AGENT_PACKAGE_PYTHON_AGENT_URL=/usr/share/cattle/artifacts/python-agent.tar.gz
CATTLE_AGENT_PACKAGE_RANCHER_DNS_URL=/usr/share/cattle/artifacts/rancher-dns.tar.gz
CATTLE_AGENT_PACKAGE_RANCHER_METADATA_URL=/usr/share/cattle/artifacts/rancher-metadata.tar.gz
CATTLE_AGENT_PACKAGE_VOLMGR_URL=/usr/share/cattle/artifacts/volmgr.tar.gz
CATTLE_CATTLE_VERSION=v0.130.0
CATTLE_DB_CATTLE_DATABASE=mysql
CATTLE_DB_CATTLE_MYSQL_HOST=localhost
CATTLE_DB_CATTLE_MYSQL_NAME=cattle
CATTLE_DB_CATTLE_MYSQL_PORT=3306
CATTLE_DB_CATTLE_USERNAME=cattle
CATTLE_GRAPHITE_HOST=
CATTLE_GRAPHITE_PORT=
CATTLE_HOME=/var/lib/cattle
CATTLE_HOST_API_PROXY_MODE=embedded
CATTLE_LOGBACK_OUTPUT_GELF_HOST=
CATTLE_LOGBACK_OUTPUT_GELF_PORT=
CATTLE_RANCHER_COMPOSE_VERSION=v0.7.0
CATTLE_RANCHER_SERVER_IMAGE=v0.51.0
CATTLE_USE_LOCAL_ARTIFACTS=true
DEFAULT_CATTLE_API_UI_INDEX=//releases.rancher.com/ui/0.78.0
DEFAULT_CATTLE_CATALOG_EXECUTE=true
DEFAULT_CATTLE_COMPOSE_EXECUTOR_EXECUTE=true
DEFAULT_CATTLE_MACHINE_EXECUTE=true
DEFAULT_CATTLE_RANCHER_COMPOSE_DARWIN_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-darwin-amd64-v0.7.0.tar.gz
DEFAULT_CATTLE_RANCHER_COMPOSE_LINUX_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-linux-amd64-v0.7.0.tar.gz
DEFAULT_CATTLE_RANCHER_COMPOSE_WINDOWS_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-windows-386-v0.7.0.zip
18:46:53.545 [main] WARN  o.e.jetty.security.SecurityHandler - ServletContext@o.e.j.w.WebAppContext@ff2d89{/,file:/usr/share/cattle/b10c392870b9f40c15fbff8d3e16135c/,STARTING}{file:/usr/share/cattle/b10c392870b9f40c15fbff8d3e16135c/} has uncovered http methods for path: /
18:46:54.431 [main] INFO  ConsoleStatus - [1/6] [0ms] [0ms] Loading config-bootstrap
18:46:54.541 [main] INFO  ConsoleStatus - [2/6] [112ms] [109ms] Loading base-config
18:46:54.723 [main] INFO  ConsoleStatus - [3/6] [294ms] [182ms] Loading config
18:46:54.727 [main] INFO  ConsoleStatus - [4/6] [298ms] [3ms] Starting config-bootstrap
18:46:54.913 [main] INFO  ConsoleStatus - [5/6] [484ms] [185ms] Starting base-config
18:46:54.913 [main] INFO  ConsoleStatus - [6/6] [484ms] [0ms] Starting config
2016-01-16 18:46:55,080 INFO    [main] [ConsoleStatus] [1/36] [0ms] [0ms] Loading bootstrap
2016-01-16 18:46:55,156 INFO    [main] [ConsoleStatus] [2/36] [76ms] [76ms] Loading config-defaults
2016-01-16 18:46:58,386 INFO    [main] [ConsoleStatus] [3/36] [3306ms] [3230ms] Loading system
2016-01-16 18:46:58,431 INFO    [main] [ConsoleStatus] [4/36] [3351ms] [45ms] Loading defaults
2016-01-16 18:46:58,584 INFO    [main] [ConsoleStatus] [5/36] [3504ms] [153ms] Loading types
2016-01-16 18:47:00,800 INFO    [main] [ConsoleStatus] [6/36] [5720ms] [2215ms] Loading system-services
2016-01-16 18:47:00,932 INFO    [main] [ConsoleStatus] [7/36] [5852ms] [132ms] Loading agent-server
2016-01-16 18:47:01,058 INFO    [main] [ConsoleStatus] [8/36] [5978ms] [126ms] Loading allocator-server
2016-01-16 18:47:01,933 INFO    [main] [ConsoleStatus] [9/36] [6853ms] [875ms] Loading api-server
2016-01-16 18:47:02,804 INFO    [main] [ConsoleStatus] [10/36] [7724ms] [871ms] Loading iaas-api
2016-01-16 18:47:02,834 INFO    [main] [ConsoleStatus] [11/36] [7754ms] [30ms] Loading archaius
2016-01-16 18:47:02,983 INFO    [main] [ConsoleStatus] [12/36] [7903ms] [149ms] Loading core-model
2016-01-16 18:47:03,007 INFO    [main] [ConsoleStatus] [13/36] [7927ms] [24ms] Loading core-object-defaults
2016-01-16 18:47:03,030 INFO    [main] [ConsoleStatus] [14/36] [7950ms] [23ms] Loading encryption
2016-01-16 18:47:04,360 INFO    [main] [ConsoleStatus] [15/36] [9280ms] [1330ms] Loading process
2016-01-16 18:47:04,603 INFO    [main] [ConsoleStatus] [16/36] [9523ms] [243ms] Loading process-server
2016-01-16 18:47:04,634 INFO    [main] [ConsoleStatus] [17/36] [9554ms] [30ms] Loading redis
2016-01-16 18:47:04,689 INFO    [main] [ConsoleStatus] [18/36] [9609ms] [54ms] Loading storage-simulator
2016-01-16 18:47:04,729 INFO    [main] [ConsoleStatus] [19/36] [9649ms] [40ms] Starting bootstrap
2016-01-16 18:47:04,729 INFO    [main] [ConsoleStatus] [20/36] [9649ms] [0ms] Starting config-defaults
2016-01-16 18:47:04,729 INFO    [main] [ConsoleStatus] [21/36] [9649ms] [0ms] Starting system
2016-01-16 18:47:04,730 INFO    [main] [ConsoleStatus] [22/36] [9650ms] [0ms] Starting defaults
2016-01-16 18:47:04,730 INFO    [main] [ConsoleStatus] [23/36] [9650ms] [0ms] Starting types
2016-01-16 18:47:05,913 INFO    [main] [ConsoleStatus] [24/36] [10833ms] [1183ms] Starting system-services
2016-01-16 18:47:05,913 INFO    [main] [ConsoleStatus] [25/36] [10833ms] [0ms] Starting agent-server
2016-01-16 18:47:05,913 INFO    [main] [ConsoleStatus] [26/36] [10833ms] [0ms] Starting allocator-server
2016-01-16 18:47:06,226 INFO    [main] [ConsoleStatus] [27/36] [11146ms] [313ms] Starting api-server
2016-01-16 18:47:07,142 INFO    [main] [ConsoleStatus] [28/36] [12062ms] [916ms] Starting iaas-api
2016-01-16 18:47:07,142 INFO    [main] [ConsoleStatus] [29/36] [12062ms] [0ms] Starting archaius
2016-01-16 18:47:07,142 INFO    [main] [ConsoleStatus] [30/36] [12062ms] [0ms] Starting core-model
2016-01-16 18:47:07,142 INFO    [main] [ConsoleStatus] [31/36] [12062ms] [0ms] Starting core-object-defaults
2016-01-16 18:47:07,142 INFO    [main] [ConsoleStatus] [32/36] [12062ms] [0ms] Starting encryption
2016-01-16 18:47:07,144 INFO    [main] [ConsoleStatus] [33/36] [12064ms] [2ms] Starting process
2016-01-16 18:47:07,146 INFO    [main] [ConsoleStatus] [34/36] [12066ms] [2ms] Starting process-server
2016-01-16 18:47:07,147 INFO    [main] [ConsoleStatus] [35/36] [12067ms] [0ms] Starting redis
2016-01-16 18:47:07,147 INFO    [main] [ConsoleStatus] [36/36] [12067ms] [0ms] Starting storage-simulator
18:47:07.210 [main] INFO  ConsoleStatus - [DONE ] [14497ms] Startup Succeeded, Listening on port 8081
time="2016-01-16T18:47:08Z" level=info msg="Starting websocket proxy. Listening on [:8080], Proxying to cattle API at [localhost:8081], Monitoring parent pid [8]."
time="2016-01-16T18:47:09Z" level=info msg="Starting Rancher Catalog service"
time="2016-01-16T18:47:09Z" level=info msg="Using catalog library=https://github.com/rancher/rancher-catalog.git"
time="2016-01-16T18:47:09Z" level=info msg="Cloning the catalog from git url https://github.com/rancher/rancher-catalog.git"
Cloning into './DATA/library'...
time="2016-01-16T18:47:09Z" level=info msg="Setting log level" logLevel=info
time="2016-01-16T18:47:09Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-16T18:47:09Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-16T18:47:10Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-16T18:47:10Z" level=info msg="Connection established"
time="2016-01-16T18:47:13Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
time="2016-01-16T18:47:14Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-16T18:47:15Z" level=info msg="Connection established"
2016/01/16 18:50:57 http: proxy error: net/http: request canceled
time="2016-01-16T18:52:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-16T18:57:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-16T19:02:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-16T19:02:21Z" level=info msg="Creating Machine" eventId="622f9de4-a93b-4ee2-a31c-92923761052f" resourceId=1ph4
time="2016-01-16T19:02:21Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
time="2016-01-16T19:02:21Z" level=info msg="Activating Machine" eventId="1d4666b8-325e-4641-9189-4d89308ad2f8" resourceId=1ph4
2016-01-16 19:02:26,277 ERROR [:] [] [] [] [ecutorService-7] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
2016-01-16 19:02:31,277 ERROR [:] [] [] [] [cutorService-10] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
time="2016-01-16T19:07:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T06:47:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T06:47:19Z" level=info msg="Exiting go-machine-service..."
time="2016-01-17T06:47:20Z" level=info msg="Setting log level" logLevel=info
time="2016-01-17T06:47:20Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-17T06:47:21Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-17T06:47:21Z" level=info msg="Connection established"
time="2016-01-17T06:47:23Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
time="2016-01-17T06:47:24Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-17T06:47:24Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-17T06:47:25Z" level=info msg="Connection established"
time="2016-01-17T06:47:27Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
2016-01-17 06:47:37,535 ERROR [:] [] [] [] [ecutorService-7] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
2016-01-17 06:47:42,536 ERROR [:] [] [] [] [ecutorService-5] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
time="2016-01-17T06:52:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T07:02:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T07:02:32Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
2016-01-17 07:02:42,650 ERROR [:] [] [] [] [ecutorService-3] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
2016-01-17 07:02:47,650 ERROR [:] [] [] [] [ecutorService-5] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
time="2016-01-17T07:07:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T18:47:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T18:47:26Z" level=info msg="Exiting go-machine-service..."
time="2016-01-17T18:47:27Z" level=info msg="Setting log level" logLevel=info
time="2016-01-17T18:47:27Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-17T18:47:28Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-17T18:47:28Z" level=info msg="Connection established"
time="2016-01-17T18:47:31Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
time="2016-01-17T18:47:33Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-17T18:47:33Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-17T18:47:34Z" level=info msg="Connection established"
time="2016-01-17T18:47:40Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
2016-01-17 18:47:52,559 ERROR [:] [] [] [] [ecutorService-7] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
time="2016-01-17T18:52:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T18:57:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T19:02:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-17T19:02:46Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
2016-01-17 19:02:57,663 ERROR [:] [] [] [] [ecutorService-3] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
time="2016-01-17T19:07:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T06:47:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T06:47:35Z" level=info msg="Exiting go-machine-service..."
time="2016-01-18T06:47:36Z" level=info msg="Setting log level" logLevel=info
time="2016-01-18T06:47:36Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-18T06:47:37Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-18T06:47:37Z" level=info msg="Connection established"
time="2016-01-18T06:47:40Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
time="2016-01-18T06:47:42Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-18T06:47:42Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-18T06:47:43Z" level=info msg="Connection established"
time="2016-01-18T06:47:55Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
2016-01-18 06:48:08,486 ERROR [:] [] [] [] [ecutorService-2] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
time="2016-01-18T06:52:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T06:57:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T07:02:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T07:03:02Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
2016-01-18 07:03:13,590 ERROR [:] [] [] [] [cutorService-10] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
time="2016-01-18T07:07:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T17:52:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
2016-01-18 17:55:53,066 ERROR [0b2ddbb6-ebb6-4a81-9799-a14f27760d7e:1690] [instance:89->instanceHostMap:89] [instance.stop->(InstanceStop)->instancehostmap.deactivate] [] [cutorService-25] [c.p.e.p.i.DefaultProcessInstanceImpl] Unknown exception io.cattle.platform.eventing.exception.EventExecutionException: b8130ee9-7dd3-4d36-bc0f-5bbc871f8d68 : 404 Client Error: Not Found ("no such id: a9ac8a5b91bd67452ec023d7708f2833a9d452efa653a83b641d4c2c940cd364")
        at io.cattle.platform.eventing.exception.EventExecutionException.fromEvent(EventExecutionException.java:53) ~[cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:72) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:158) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.callSync(AgentBasedProcessHandler.java:170) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.IgnoreReconnectionAgentHandler.callSync(IgnoreReconnectionAgentHandler.java:18) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handleEvent(AgentBasedProcessHandler.java:156) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handle(AgentBasedProcessHandler.java:101) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.object.process.impl.DefaultObjectProcessManager.executeStandardProcess(DefaultObjectProcessManager.java:29) [cattle-framework-object-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AbstractObjectProcessLogic.deactivate(AbstractObjectProcessLogic.java:35) [cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.InstanceStop.compute(InstanceStop.java:95) [cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.InstanceStop.handle(InstanceStop.java:38) [cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.eventing.impl.ProcessEventListenerImpl.processExecute(ProcessEventListenerImpl.java:66) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at sun.reflect.GeneratedMethodAccessor512.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_91]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_91]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener$1.doWithLockNoResult(MethodInvokingListener.java:76) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener.onEvent(MethodInvokingListener.java:72) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.impl.AbstractThreadPoolingEventService$2.doRun(AbstractThreadPoolingEventService.java:135) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.NoExceptionRunnable.runInContext(NoExceptionRunnable.java:13) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:108) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_91]

2016-01-18 17:55:53,068 ERROR [0b2ddbb6-ebb6-4a81-9799-a14f27760d7e:1690] [instance:89] [instance.stop] [] [cutorService-25] [c.p.e.p.i.DefaultProcessInstanceImpl] Unknown exception io.cattle.platform.eventing.exception.EventExecutionException: b8130ee9-7dd3-4d36-bc0f-5bbc871f8d68 : 404 Client Error: Not Found ("no such id: a9ac8a5b91bd67452ec023d7708f2833a9d452efa653a83b641d4c2c940cd364")
        at io.cattle.platform.eventing.exception.EventExecutionException.fromEvent(EventExecutionException.java:53) ~[cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:72) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:158) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.callSync(AgentBasedProcessHandler.java:170) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.IgnoreReconnectionAgentHandler.callSync(IgnoreReconnectionAgentHandler.java:18) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handleEvent(AgentBasedProcessHandler.java:156) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handle(AgentBasedProcessHandler.java:101) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.object.process.impl.DefaultObjectProcessManager.executeStandardProcess(DefaultObjectProcessManager.java:29) ~[cattle-framework-object-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AbstractObjectProcessLogic.deactivate(AbstractObjectProcessLogic.java:35) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.InstanceStop.compute(InstanceStop.java:95) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.InstanceStop.handle(InstanceStop.java:38) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.eventing.impl.ProcessEventListenerImpl.processExecute(ProcessEventListenerImpl.java:66) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at sun.reflect.GeneratedMethodAccessor512.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_91]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_91]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener$1.doWithLockNoResult(MethodInvokingListener.java:76) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener.onEvent(MethodInvokingListener.java:72) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.impl.AbstractThreadPoolingEventService$2.doRun(AbstractThreadPoolingEventService.java:135) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.NoExceptionRunnable.runInContext(NoExceptionRunnable.java:13) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:108) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_91]

2016-01-18 17:55:53,109 ERROR [:] [] [] [] [cutorService-25] [i.c.p.e.e.i.ProcessEventListenerImpl] Unknown exception running process [instance.stop:1690] on [89] io.cattle.platform.eventing.exception.EventExecutionException: b8130ee9-7dd3-4d36-bc0f-5bbc871f8d68 : 404 Client Error: Not Found ("no such id: a9ac8a5b91bd67452ec023d7708f2833a9d452efa653a83b641d4c2c940cd364")
        at io.cattle.platform.eventing.exception.EventExecutionException.fromEvent(EventExecutionException.java:53) ~[cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:72) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:158) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.callSync(AgentBasedProcessHandler.java:170) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.IgnoreReconnectionAgentHandler.callSync(IgnoreReconnectionAgentHandler.java:18) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handleEvent(AgentBasedProcessHandler.java:156) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handle(AgentBasedProcessHandler.java:101) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.object.process.impl.DefaultObjectProcessManager.executeStandardProcess(DefaultObjectProcessManager.java:29) ~[cattle-framework-object-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AbstractObjectProcessLogic.deactivate(AbstractObjectProcessLogic.java:35) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.InstanceStop.compute(InstanceStop.java:95) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.InstanceStop.handle(InstanceStop.java:38) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.eventing.impl.ProcessEventListenerImpl.processExecute(ProcessEventListenerImpl.java:66) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at sun.reflect.GeneratedMethodAccessor512.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_91]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_91]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener$1.doWithLockNoResult(MethodInvokingListener.java:76) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener.onEvent(MethodInvokingListener.java:72) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.impl.AbstractThreadPoolingEventService$2.doRun(AbstractThreadPoolingEventService.java:135) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.NoExceptionRunnable.runInContext(NoExceptionRunnable.java:13) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:108) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_91]

time="2016-01-18T17:57:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T18:27:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
2016-01-18 18:30:03,930 ERROR [:] [] [] [] [ecutorService-8] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
time="2016-01-18T18:32:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T18:47:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T18:47:42Z" level=info msg="Exiting go-machine-service..."
time="2016-01-18T18:47:43Z" level=info msg="Setting log level" logLevel=info
time="2016-01-18T18:47:43Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-18T18:47:44Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-18T18:47:44Z" level=info msg="Connection established"
time="2016-01-18T18:47:48Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
time="2016-01-18T18:47:49Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-18T18:47:49Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-18T18:47:50Z" level=info msg="Connection established"
time="2016-01-18T18:48:08Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
2016-01-18 18:48:19,469 ERROR [:] [] [] [] [ecutorService-2] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
time="2016-01-18T18:52:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-18T18:57:10Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
160118 18:57:52 [Note] /usr/sbin/mysqld (mysqld 5.5.46-0ubuntu0.14.04.2-log) starting as process 23 ...
Uptime: 2  Threads: 1  Questions: 2  Slow queries: 0  Opens: 34  Flush tables: 1  Open tables: 26  Queries per second avg: 1.000
Setting up database
CATTLE_AGENT_PACKAGE_AGENT_BINARIES_URL=/usr/share/cattle/artifacts/agent-binaries.tar.gz
CATTLE_AGENT_PACKAGE_CADVISOR_URL=/usr/share/cattle/artifacts/cadvisor.tar.gz
CATTLE_AGENT_PACKAGE_HOST_API_URL=/usr/share/cattle/artifacts/host-api.tar.gz
CATTLE_AGENT_PACKAGE_NODE_AGENT_URL=/usr/share/cattle/artifacts/node-agent.tar.gz
CATTLE_AGENT_PACKAGE_PYTHON_AGENT_URL=/usr/share/cattle/artifacts/python-agent.tar.gz
CATTLE_AGENT_PACKAGE_RANCHER_DNS_URL=/usr/share/cattle/artifacts/rancher-dns.tar.gz
CATTLE_AGENT_PACKAGE_RANCHER_METADATA_URL=/usr/share/cattle/artifacts/rancher-metadata.tar.gz
CATTLE_AGENT_PACKAGE_VOLMGR_URL=/usr/share/cattle/artifacts/volmgr.tar.gz
CATTLE_CATTLE_VERSION=v0.130.0
CATTLE_DB_CATTLE_DATABASE=mysql
CATTLE_DB_CATTLE_MYSQL_HOST=localhost
CATTLE_DB_CATTLE_MYSQL_NAME=cattle
CATTLE_DB_CATTLE_MYSQL_PORT=3306
CATTLE_DB_CATTLE_USERNAME=cattle
CATTLE_GRAPHITE_HOST=
CATTLE_GRAPHITE_PORT=
CATTLE_HOME=/var/lib/cattle
CATTLE_HOST_API_PROXY_MODE=embedded
CATTLE_LOGBACK_OUTPUT_GELF_HOST=
CATTLE_LOGBACK_OUTPUT_GELF_PORT=
CATTLE_RANCHER_COMPOSE_VERSION=v0.7.0
CATTLE_RANCHER_SERVER_IMAGE=v0.51.0
CATTLE_USE_LOCAL_ARTIFACTS=true
DEFAULT_CATTLE_API_UI_INDEX=//releases.rancher.com/ui/0.78.0
DEFAULT_CATTLE_CATALOG_EXECUTE=true
DEFAULT_CATTLE_COMPOSE_EXECUTOR_EXECUTE=true
DEFAULT_CATTLE_MACHINE_EXECUTE=true
DEFAULT_CATTLE_RANCHER_COMPOSE_DARWIN_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-darwin-amd64-v0.7.0.tar.gz
DEFAULT_CATTLE_RANCHER_COMPOSE_LINUX_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-linux-amd64-v0.7.0.tar.gz
DEFAULT_CATTLE_RANCHER_COMPOSE_WINDOWS_URL=https://releases.rancher.com/compose/beta/v0.7.0/rancher-compose-windows-386-v0.7.0.zip
18:57:56.049 [main] WARN  o.e.jetty.security.SecurityHandler - ServletContext@o.e.j.w.WebAppContext@71067de1{/,file:/usr/share/cattle/b10c392870b9f40c15fbff8d3e16135c/,STARTING}{file:/usr/share/cattle/b10c392870b9f40c15fbff8d3e16135c/} has uncovered http methods for path: /
18:57:56.957 [main] INFO  ConsoleStatus - [1/6] [0ms] [0ms] Loading config-bootstrap
18:57:57.084 [main] INFO  ConsoleStatus - [2/6] [129ms] [126ms] Loading base-config
18:57:57.325 [main] INFO  ConsoleStatus - [3/6] [370ms] [240ms] Loading config
18:57:57.331 [main] INFO  ConsoleStatus - [4/6] [376ms] [6ms] Starting config-bootstrap
18:57:57.500 [main] INFO  ConsoleStatus - [5/6] [545ms] [169ms] Starting base-config
18:57:57.500 [main] INFO  ConsoleStatus - [6/6] [545ms] [0ms] Starting config
2016-01-18 18:57:57,660 INFO    [main] [ConsoleStatus] [1/36] [0ms] [0ms] Loading bootstrap
2016-01-18 18:57:57,722 INFO    [main] [ConsoleStatus] [2/36] [62ms] [62ms] Loading config-defaults
2016-01-18 18:58:00,827 INFO    [main] [ConsoleStatus] [3/36] [3167ms] [3105ms] Loading system
2016-01-18 18:58:00,872 INFO    [main] [ConsoleStatus] [4/36] [3212ms] [45ms] Loading defaults
2016-01-18 18:58:01,015 INFO    [main] [ConsoleStatus] [5/36] [3355ms] [143ms] Loading types
2016-01-18 18:58:02,989 INFO    [main] [ConsoleStatus] [6/36] [5329ms] [1974ms] Loading system-services
2016-01-18 18:58:03,103 INFO    [main] [ConsoleStatus] [7/36] [5443ms] [114ms] Loading agent-server
2016-01-18 18:58:03,216 INFO    [main] [ConsoleStatus] [8/36] [5556ms] [113ms] Loading allocator-server
2016-01-18 18:58:03,872 INFO    [main] [ConsoleStatus] [9/36] [6212ms] [656ms] Loading api-server
2016-01-18 18:58:04,685 INFO    [main] [ConsoleStatus] [10/36] [7025ms] [813ms] Loading iaas-api
2016-01-18 18:58:04,712 INFO    [main] [ConsoleStatus] [11/36] [7052ms] [27ms] Loading archaius
2016-01-18 18:58:04,828 INFO    [main] [ConsoleStatus] [12/36] [7168ms] [116ms] Loading core-model
2016-01-18 18:58:04,848 INFO    [main] [ConsoleStatus] [13/36] [7188ms] [20ms] Loading core-object-defaults
2016-01-18 18:58:04,868 INFO    [main] [ConsoleStatus] [14/36] [7208ms] [20ms] Loading encryption
2016-01-18 18:58:05,994 INFO    [main] [ConsoleStatus] [15/36] [8334ms] [1126ms] Loading process
2016-01-18 18:58:06,149 INFO    [main] [ConsoleStatus] [16/36] [8489ms] [155ms] Loading process-server
2016-01-18 18:58:06,168 INFO    [main] [ConsoleStatus] [17/36] [8508ms] [19ms] Loading redis
2016-01-18 18:58:06,199 INFO    [main] [ConsoleStatus] [18/36] [8539ms] [31ms] Loading storage-simulator
2016-01-18 18:58:06,225 INFO    [main] [ConsoleStatus] [19/36] [8565ms] [26ms] Starting bootstrap
2016-01-18 18:58:06,225 INFO    [main] [ConsoleStatus] [20/36] [8565ms] [0ms] Starting config-defaults
2016-01-18 18:58:06,225 INFO    [main] [ConsoleStatus] [21/36] [8565ms] [0ms] Starting system
2016-01-18 18:58:06,225 INFO    [main] [ConsoleStatus] [22/36] [8565ms] [0ms] Starting defaults
2016-01-18 18:58:06,225 INFO    [main] [ConsoleStatus] [23/36] [8565ms] [0ms] Starting types
2016-01-18 18:58:06,956 INFO    [main] [ConsoleStatus] [24/36] [9296ms] [731ms] Starting system-services
2016-01-18 18:58:06,956 INFO    [main] [ConsoleStatus] [25/36] [9296ms] [0ms] Starting agent-server
2016-01-18 18:58:06,956 INFO    [main] [ConsoleStatus] [26/36] [9296ms] [0ms] Starting allocator-server
2016-01-18 18:58:07,220 INFO    [main] [ConsoleStatus] [27/36] [9560ms] [264ms] Starting api-server
2016-01-18 18:58:07,948 INFO    [main] [ConsoleStatus] [28/36] [10288ms] [728ms] Starting iaas-api
2016-01-18 18:58:07,948 INFO    [main] [ConsoleStatus] [29/36] [10288ms] [0ms] Starting archaius
2016-01-18 18:58:07,948 INFO    [main] [ConsoleStatus] [30/36] [10288ms] [0ms] Starting core-model
2016-01-18 18:58:07,948 INFO    [main] [ConsoleStatus] [31/36] [10288ms] [0ms] Starting core-object-defaults
2016-01-18 18:58:07,948 INFO    [main] [ConsoleStatus] [32/36] [10288ms] [0ms] Starting encryption
2016-01-18 18:58:07,950 INFO    [main] [ConsoleStatus] [33/36] [10290ms] [2ms] Starting process
2016-01-18 18:58:07,952 INFO    [main] [ConsoleStatus] [34/36] [10292ms] [2ms] Starting process-server
2016-01-18 18:58:07,952 INFO    [main] [ConsoleStatus] [35/36] [10292ms] [0ms] Starting redis
2016-01-18 18:58:07,952 INFO    [main] [ConsoleStatus] [36/36] [10292ms] [0ms] Starting storage-simulator
18:58:08.012 [main] INFO  ConsoleStatus - [DONE ] [12748ms] Startup Succeeded, Listening on port 8081
time="2016-01-18T18:58:09Z" level=info msg="Starting websocket proxy. Listening on [:8080], Proxying to cattle API at [localhost:8081], Monitoring parent pid [8]."
time="2016-01-18T18:58:09Z" level=info msg="Starting Rancher Catalog service"
time="2016-01-18T18:58:09Z" level=info msg="Using catalog library=https://github.com/rancher/rancher-catalog.git"
time="2016-01-18T18:58:09Z" level=info msg="Cloning the catalog from git url https://github.com/rancher/rancher-catalog.git"
Cloning into './DATA/library'...
time="2016-01-18T18:58:09Z" level=info msg="Setting log level" logLevel=info
time="2016-01-18T18:58:09Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-18T18:58:09Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-18T18:58:10Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-18T18:58:10Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-18T18:58:11Z" level=info msg="Connection established"
time="2016-01-18T18:58:11Z" level=info msg="Connection established"
time="2016-01-18T18:58:15Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
time="2016-01-18T18:58:17Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
2016-01-18 18:58:32,000 ERROR [:] [] [] [] [ecutorService-7] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
time="2016-01-18T19:03:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-19T05:58:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
2016/01/19 06:00:10 http: proxy error: net/http: request canceled
time="2016-01-19T06:03:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-19T06:58:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-19T06:58:17Z" level=info msg="Exiting go-machine-service..."
time="2016-01-19T06:58:19Z" level=info msg="Setting log level" logLevel=info
time="2016-01-19T06:58:19Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-19T06:58:19Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-19T06:58:19Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
time="2016-01-19T06:58:19Z" level=info msg="Connection established"
time="2016-01-19T06:58:21Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-19T06:58:21Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-19T06:58:21Z" level=info msg="Connection established"
time="2016-01-19T06:58:28Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
time="2016-01-19T06:58:32Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
2016-01-19 06:58:37,769 ERROR [:] [] [] [] [ecutorService-2] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
2016-01-19 06:58:42,770 ERROR [:] [] [] [] [ecutorService-5] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
2016-01-19 06:58:42,770 ERROR [:] [] [] [] [ecutorService-3] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
time="2016-01-19T07:03:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-19T18:58:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-19T18:58:25Z" level=info msg="Exiting go-machine-service..."
time="2016-01-19T18:58:26Z" level=info msg="Setting log level" logLevel=info
time="2016-01-19T18:58:26Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-19T18:58:26Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-19T18:58:26Z" level=info msg="Connection established"
time="2016-01-19T18:58:27Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
time="2016-01-19T18:58:28Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-19T18:58:28Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-19T18:58:28Z" level=info msg="Connection established"
time="2016-01-19T18:58:41Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
time="2016-01-19T18:58:48Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
2016-01-19 18:58:53,707 ERROR [:] [] [] [] [ecutorService-3] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
2016-01-19 18:58:58,707 ERROR [:] [] [] [] [ecutorService-2] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
time="2016-01-19T19:03:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-20T06:58:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-20T06:58:33Z" level=info msg="Exiting go-machine-service..."
time="2016-01-20T06:58:35Z" level=info msg="Setting log level" logLevel=info
time="2016-01-20T06:58:35Z" level=info msg="Starting go-machine-service..." gitcommit=5023ae4
time="2016-01-20T06:58:35Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-20T06:58:35Z" level=info msg="Connection established"
time="2016-01-20T06:58:35Z" level=info msg="Exiting rancher-compose-executor" version=v0.7.0
time="2016-01-20T06:58:37Z" level=info msg="Starting rancher-compose-executor" version=v0.7.0
time="2016-01-20T06:58:37Z" level=info msg="Initializing event router" workerCount=10
time="2016-01-20T06:58:37Z" level=info msg="Connection established"
time="2016-01-20T06:58:53Z" level=info msg="Registering backend for host [45136ee6-b7f3-4bba-97ec-6db6d5ef659b]"
2016-01-20 06:59:03,843 ERROR [:] [] [] [] [ecutorService-1] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
time="2016-01-20T06:59:04Z" level=info msg="Registering backend for host [7474c498-10a2-4b69-ad58-00b094b8b7fe]"
2016-01-20 06:59:08,843 ERROR [:] [] [] [] [cutorService-10] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [4] count [1]
2016-01-20 06:59:13,844 ERROR [:] [] [] [] [ecutorService-3] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
2016-01-20 06:59:18,845 ERROR [:] [] [] [] [ecutorService-9] [i.c.p.a.s.ping.impl.PingMonitorImpl ] Failed to get ping from agent [5] count [1]
time="2016-01-20T07:03:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
time="2016-01-20T07:48:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
2016-01-20 07:49:40,026 ERROR [a2912105-1068-40d2-87f0-28c3ba9bfc82:2369] [instance:35] [instance.purge] [] [ecutorService-2] [c.p.e.p.i.DefaultProcessInstanceImpl] Unknown exception io.cattle.platform.eventing.exception.EventExecutionException: 72996af2-ea56-4b02-a2c0-a41d2a094584 : 500 Server Error: Internal Server Error ("Driver aufs failed to remove root filesystem 0e4bc24698b751772ff2e688826a2c11d395a3f31e7f49484b0602753d130a13: rename /var/lib/docker/aufs/mnt/0e4bc24698b751772ff2e688826a2c11d395a3f31e7f49484b0602753d130a13 /var/lib/docker/aufs/mnt/0e4bc24698b751772ff2e688826a2c11d395a3f31e7f49484b0602753d130a13-removing: device or resource busy")
        at io.cattle.platform.eventing.exception.EventExecutionException.fromEvent(EventExecutionException.java:53) ~[cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:72) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:158) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.callSync(AgentBasedProcessHandler.java:170) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handleEvent(AgentBasedProcessHandler.java:156) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.PostInstancePurge.handle(PostInstancePurge.java:38) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.eventing.impl.ProcessEventListenerImpl.processExecute(ProcessEventListenerImpl.java:66) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at sun.reflect.GeneratedMethodAccessor680.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_91]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_91]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener$1.doWithLockNoResult(MethodInvokingListener.java:76) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener.onEvent(MethodInvokingListener.java:72) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.impl.AbstractThreadPoolingEventService$2.doRun(AbstractThreadPoolingEventService.java:135) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.NoExceptionRunnable.runInContext(NoExceptionRunnable.java:13) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:108) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_91]

2016-01-20 07:49:40,039 ERROR [:] [] [] [] [ecutorService-2] [i.c.p.e.e.i.ProcessEventListenerImpl] Unknown exception running process [instance.purge:2369] on [35] io.cattle.platform.eventing.exception.EventExecutionException: 72996af2-ea56-4b02-a2c0-a41d2a094584 : 500 Server Error: Internal Server Error ("Driver aufs failed to remove root filesystem 0e4bc24698b751772ff2e688826a2c11d395a3f31e7f49484b0602753d130a13: rename /var/lib/docker/aufs/mnt/0e4bc24698b751772ff2e688826a2c11d395a3f31e7f49484b0602753d130a13 /var/lib/docker/aufs/mnt/0e4bc24698b751772ff2e688826a2c11d395a3f31e7f49484b0602753d130a13-removing: device or resource busy")
        at io.cattle.platform.eventing.exception.EventExecutionException.fromEvent(EventExecutionException.java:53) ~[cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:72) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:158) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.callSync(AgentBasedProcessHandler.java:170) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handleEvent(AgentBasedProcessHandler.java:156) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.PostInstancePurge.handle(PostInstancePurge.java:38) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:456) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:396) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:390) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:520) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:323) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:259) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:256) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.eventing.impl.ProcessEventListenerImpl.processExecute(ProcessEventListenerImpl.java:66) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at sun.reflect.GeneratedMethodAccessor680.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_91]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_91]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener$1.doWithLockNoResult(MethodInvokingListener.java:76) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener.onEvent(MethodInvokingListener.java:72) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.eventing.impl.AbstractThreadPoolingEventService$2.doRun(AbstractThreadPoolingEventService.java:135) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.NoExceptionRunnable.runInContext(NoExceptionRunnable.java:13) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:108) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) [cattle-framework-managed-context-0.5.0-SNAPSHOT.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_91]

time="2016-01-20T07:53:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
2016/01/20 07:55:52 http: proxy error: net/http: request canceled
time="2016-01-20T07:58:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"
2016/01/20 17:27:30 http: proxy error: net/http: request canceled
2016/01/20 17:27:30 http: proxy error: net/http: request canceled
time="2016-01-20T17:28:11Z" level=info msg="Pulling the catalog library from the repo to sync any new changes to ./DATA/library"

@lenovouser
Copy link
Author

I was searching the issues a bit deeper, and it seems like it is related but not similar to #2196 and #2335

@lenovouser
Copy link
Author

Any idea?

@lenovouser
Copy link
Author

Hello? 😄 How can I fix / kill the reconnect process?

@j4ndev
Copy link

j4ndev commented Jan 22, 2016

+1

@phenomax
Copy link

Sorry for possible spamming but I d also like to +1 the issue.

@lenovouser
Copy link
Author

Hello? Is this a known bug? Or did we do something wrong? Can I fix it somehow?

@lenovouser
Copy link
Author

We have now done a few things because we hoped it might be our fault:

  • Disabled firewall on all servers
  • Purged and re-installed docker on all servers
  • Purged and re-installed rancher-agent on all servers
  • Purged and moved rancher-server to different servers to test if it is a network issue

Nothing helps. It is always the one host who doesn't want to connect. Even if the server is e.g. running on the same host. It still may be our fault, I know. But is there at least any way I can find out why it is not connecting? Any logs containing more information than that it is not connecting and more like why it doesn't want to. Something which is also very weird is that it definitely is connecting somehow and then disconnecting because this reconnect process is starting on rancher-server.

@cjellick
Copy link

@lenovouser this error shows up 6k times in your rancher-agent logs:

('Received websocket error: [%s]', timeout('timed out',)) 

It appears about every 70 seconds, which is inline with the 60 second timeout we have on the websocket connection (plus 10 for the agent to restart and get to the point where it is trying to connect again).
I think that that is as good as we're going to get for error messages.

I'm trying to think of what scenario could cause one host to work perfectly fine and another to consistently fail. rancher-agent is attempting to make an outbound websocket connection to rancher-server.

One typical cause of this not working is a proxy or other network device that does not like websocket connections sitting between the agent and server. Is that possible? Assuming that your two agent nodes are "next to each other" and their traffic is going through all the same devices, that seems unlikely, but do you have any proxies, load balancers, or other known devices between the two?

Can you exec into the rancher-server container and do ping/curl from there?

@demarant
Copy link

@lenovouser i had similar websockets issues, and enabling SSL for Rancher server helped us:
http://docs.rancher.com/rancher/installing-rancher/installing-server/basic-ssl-config/

In the UI you would need to configure your Host Registration for SSL.
You need also to re-register your hosts and use the https url as rancher server.

This will make sure proxies or whatever is in the middle does not block websockets and let ngnix/apachr upgrade the protocol properly.
Give it a try, it may help.

@demarant
Copy link

@lenovouser i just realised you seem to already have https setup https://rancher.domain.tld/v1
In any case you could test to establish a websocket to that server from the host with issue...

@lenovouser
Copy link
Author

@cjellick I can ping the rancher-agent host system from the rancher-server container with about ~0.200 ms. How do I curl the agent? As far as I know there is no port open for the agent, right?

@cjellick
Copy link

I meant the other way around @lenovouser: exec into the rancher-agent container and curl from it to rancher-server.

@lenovouser
Copy link
Author

@cjellick

curl https://rancher.domain.tld
{"id":"56a7391e-4324-4e8c-93f9-5fcac7c49e01","type":"error","links":{},"actions":{},"status":401,"code":"Unauthorized","message":"Unauthorized","detail":null}

and

curl https://rancher.domain.tld/login
<!DOCTYPE html>
<html>
  <head>
    <meta charset="utf-8">
    <meta http-equiv="X-UA-Compatible" content="IE=edge">
    <link rel="icon" href="favicon.ico">
    <title>Rancher</title>
    <!-- 0.78.0 -->
    <meta name="description" content="">
    <meta name="viewport" content="width=694">
    <base href="/" />
    <link rel="stylesheet" href="assets/vendor-2a3919e4a821c50aa1a44cc3e855e8c6.css" integrity="sha256-EC+be4F9BnpepBY4/ZigMVwA9ARSwz7f6qpNFbt6jE4= sha512-ZqbpTkdjN346mA+kXqq3ofe2cdLRY+8V3YvnkkgEiWMAyzxEibtffp+aPWk9p7iYQh4WFO8LJ9dwGMVM7EagZA==" >
    <link rel="stylesheet" href="assets/ui-aeb0f651c97c215c3766fbaedecf9de6.css">
    <style type="text/css" title="dynamic-css"></style>

  </head>
  <body>

    <script src="assets/vendor-af98fd6665a863e6306d14cbb34e54ae.js"></script>
    <script src="assets/ui-612b4d37d375a2618002f60bf83d9852.js"></script>
    <div id="ember-basic-dropdown-wormhole"></div>
  </body>
</html>

@cjellick
Copy link

@lenovouser i dont think you mentioned whether or not you had any LBs, proxies, or other network devices between rnacher-server and this node.

Also, what do you iptables look like on this node?
iptables --line-numbers -L -n -t nat

@cjellick
Copy link

@lenovouser also are you in a cloud-like environment where you have the ability to add new hosts to this cluster relatively easily? You mentioned that another host you provisioned works just fine, so just wondering if you do that again to see if the success or failure is the anomaly.

@lenovouser
Copy link
Author

Well. No. There is nothing really between it except for the NGINX in front of rancher-server, but that should not be the problem because the other hosts work well.

iptables --line-numbers -L -n -t nat
Chain PREROUTING (policy ACCEPT)
num  target     prot opt source               destination
1    DOCKER     all  --  0.0.0.0/0            0.0.0.0/0            ADDRTYPE match dst-type LOCAL

Chain INPUT (policy ACCEPT)
num  target     prot opt source               destination

Chain OUTPUT (policy ACCEPT)
num  target     prot opt source               destination
1    DOCKER     all  --  0.0.0.0/0           !127.0.0.0/8          ADDRTYPE match dst-type LOCAL

Chain POSTROUTING (policy ACCEPT)
num  target     prot opt source               destination
1    MASQUERADE  all  --  172.17.0.0/16        0.0.0.0/0

Chain DOCKER (2 references)
num  target     prot opt source               destination

and yes, failure is the anomaly. I just tried to manually add a DO test droplet and it worked. (The other hosts were added manually too, therefore I chose to do it with the droplet too)

@cjellick
Copy link

@lenovouser jsut want to confirm: this host is not the same node on which rancher-server is running right? I believe you stated this previously, but wanted to confirm again explicitly.

Next, is the host that is failing and the ones that are succeeding similar in that they are in the same cloud provider and are part of all the security groups, private networks, etc?

Finally, you could try the nuclear option:

  1. Purge all containers from the host, including and especially all rancher containers.
  2. Do rm -rf /var/lib/rancher/ on the node. This step purges some state.
  3. Get the docker run ...rancher/agent command from the UI and rerun
  4. See if the host shows up in the UI.

@lenovouser
Copy link
Author

@cjellick Yes this is not the same node and yes they are at the same provider, same firewall and network groups, just different physical servers in different datacenters.

Okay, I just did it and it is not connecting again, even though I want to mention that the reconnect process was still running on the master. I am going to purge the master now again and do a fresh install to see if that helps.

EDIT:

Okay, I just deleted the server and all agents. Then I ran rm -rf /var/lib/rancher/ on all 4 roots (Still have the droplet for testing). Anything else I can purge to make sure I am starting clean?

@lenovouser
Copy link
Author

Any updates?

@lenovouser
Copy link
Author

"Okay, I just deleted the server and all agents. Then I ran rm -rf /var/lib/rancher/ on all 4 roots (Still have the droplet for testing). Anything else I can purge to make sure I am starting clean?"

@lenovouser
Copy link
Author

Any updates?

@deniseschannon
Copy link

That's all you should need to do to purge the droplet before being added to the server.

When you do a fresh install of the server, are you still using v0.51.0 or are you doing v0.56.1?

@lenovouser
Copy link
Author

@deniseschannon I now did the fresh install and pulled from docker hub before that, so we are running v0.56.1.

There is a completely different error now which is very weird...

It just spams the console with this when I do docker logs -f rancher-agent:

time="2016-02-04T17:46:15Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-02-04T17:46:15Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"2a337794b2eeb3551b668489c788cd78949fe1a9a9545d11649c494b524e7623\", From:\"-simulated-\", Time:0}"
time="2016-02-04T17:46:15Z" level="fatal" msg="invalid character '<' looking for beginning of value"

This also happens on my verification DO droplet, but only once and then it connects. On the problematic host it just keeps spamming that

@lenovouser
Copy link
Author

This kind of seems related to #2901, #3148 and #3455

@lenovouser
Copy link
Author

Tried

service docker stop
apt-get purge docker-engine
rm -rf /var/lib/docker/
rm -rf /var/lib/rancher/
apt-get autoremove
apt-get install docker-engine
sudo docker run <agent stuff>
  • doesn't work either. Still the same error:
time="2016-02-04T18:22:15Z" level="info" msg="Starting event router."
time="2016-02-04T18:22:15Z" level="info" msg="Watching state directory: /var/lib/rancher/state/containers"
time="2016-02-04T18:22:15Z" level="info" msg="Processing event: &docker.APIEvents{Status:\"start\", ID:\"44bfb7e095cafe3b5a0a1d96aa6f8a5f7ea9969d016c905e5da274763399bc68\", From:\"-simulated-\", Time:0}"
time="2016-02-04T18:22:15Z" level="fatal" msg="invalid character '<' looking for beginning of value"

even though all the files were purged and it even pulled the image new. So I absolutely do not get where the invalid character '<' looking for beginning of value error comes from.

@lenovouser
Copy link
Author

tail -f /var/log/rancher/agent.log spams this here:

2016-02-05 11:05:11,071 INFO process-manager [139852073218128] [process_manager.py:65] Launching ['host-api', '-cadvisor-url', 'http://127.0.0.1:9344', '-logtostderr=true', '-ip', '0.0.0.0', '-port', '9345', '-auth=true', '-host-uuid', '138150a6-b8a6-4ca9-8a75-583eedb9c7fd', '-public-key', '/var/lib/cattle/etc/cattle/api.crt', '-cattle-url', 'https://rancher.domain.tld/v1', '-cattle-state-dir', '/var/lib/rancher/state/containers']
2016-02-05 11:05:11,074 INFO process-manager [139852073218128] [process_manager.py:68] Launched ['host-api', '-cadvisor-url', 'http://127.0.0.1:9344', '-logtostderr=true', '-ip', '0.0.0.0', '-port', '9345', '-auth=true', '-host-uuid', '138150a6-b8a6-4ca9-8a75-583eedb9c7fd', '-public-key', '/var/lib/cattle/etc/cattle/api.crt', '-cattle-url', 'https://rancher.domain.tld/v1', '-cattle-state-dir', '/var/lib/rancher/state/containers'] as pid 26717
2016-02-05 11:05:13,075 INFO process-manager [139852073218128] [process_manager.py:79] Process 26717 is dead, return code 1

@lenovouser
Copy link
Author

Any updates?

@deniseschannon deniseschannon added kind/bug Issues that are defects reported by users or that we know have reached a real release area/agent Issues that deal with the Rancher Agent and removed kind/question Issues that just require an answer. No code change needd labels Feb 10, 2016
@deniseschannon
Copy link

It's still just the single problematic host, correct? We're working hard on finishing up the last couple of features that will be in GA before we'll have time to concentrate on fixing as many bugs. We'll try to look at as soon as possible.

@lenovouser
Copy link
Author

Okay, cool. Yes, just the single host.

@lenovouser
Copy link
Author

This is now fixed in v0.59.1 for some reason. Closing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/agent Issues that deal with the Rancher Agent kind/bug Issues that are defects reported by users or that we know have reached a real release
Projects
None yet
Development

No branches or pull requests

7 participants