Comment 11 for bug 1316761

Revision history for this message
Vladimir Sharshov (vsharshov) wrote :

Most interesting details here. Astute try to report about a progress using RabbitMQ, but in RMQ log we have info about heartbeats on 06:46:27 and new message about error on 10:28:25. No messages between this two events. Also as we can see no report really was received to Nailgun.

Nailgun:
2014-05-15 10:33:27.873 INFO [7f6c59846700] (receiver) RPC method provision_resp received: {"status": "error", "progress": 100, "task_uuid": "0d094871-2b3a-4766-aa3b-64449f983756", "error": "Nodes failed to reboot: [\"node-1\", \"node-2\", \"node-3\", \"node-4\", \"node-5\", \"node-6\"]"}

Astute:
2014-05-15T06:38:18 debug: [397] Process message from worker queue: "[{\"args\": {\"task_uuid\": \"0d094871-2b3a-4766-aa3b-64449f983756\"...
2014-05-15T10:28:22 debug: [397] Data received by DeploymentProxyReporter to report it up: {"nodes"=>[{"uid"=>"1", "progress"=>100, "status"=>"provisioned"}, {"uid"=>"2", "progress"=>100, "status"=>"provisioned"}, {"uid"=>"3", "progress"=>100, "status"=>"provisioned"}, {"uid"=>"4", "progress"=>100, "status"=>"provisioning"}, {"uid"=>"5", "progress"=>100, "status"=>"provisioned"}, {"uid"=>"6", "progress"=>100, "status"=>"provisioning"}]}

2014-05-15T10:28:25 warning: [397] Trying to reconnect to message broker...
2014-05-15T10:28:25 warning: [412] Trying to reconnect to message broker...
2014-05-15T10:28:25 warning: [417] Trying to reconnect to message broker...
2014-05-15T10:28:25 warning: [403] Trying to reconnect to message broker...
2014-05-15T10:28:25 warning: [420] Trying to reconnect to message broker...
2014-05-15T10:28:25 warning: [408] Trying to reconnect to message broker...
2014-05-15T10:28:25 warning: [399] Trying to reconnect to message broker...

2014-05-15T10:28:25 debug: [397] Process message from worker queue: "[{\"args\": {\"task_uuid\": \"0d094871-2b3a-4766-aa3b-64449f983756\",

RabbitMQ:

=INFO REPORT==== 15-May-2014::06:46:27 ===
closing STOMP connection <0.977.0> (172.17.42.1:50879 -> 172.17.0.3:61613)

=INFO REPORT==== 15-May-2014::06:46:27 ===
accepting STOMP connection <0.1188.0> (172.17.42.1:50881 -> 172.17.0.3:61613)

=ERROR REPORT==== 15-May-2014::10:28:25 ===
closing AMQP connection <0.349.0> (172.17.42.1:35980 -> 172.17.0.3:5672):
{heartbeat_timeout,running}

=ERROR REPORT==== 15-May-2014::10:28:25 ===
closing AMQP connection <0.346.0> (172.17.42.1:35979 -> 172.17.0.3:5672):
{heartbeat_timeout,running}

=ERROR REPORT==== 15-May-2014::10:28:25 ===
closing AMQP connection <0.299.0> (172.17.42.1:35975 -> 172.17.0.3:5672):
{heartbeat_timeout,running}

=ERROR REPORT==== 15-May-2014::10:28:25 ===
closing AMQP connection <0.337.0> (172.17.42.1:35976 -> 172.17.0.3:5672):
{heartbeat_timeout,running}

=ERROR REPORT==== 15-May-2014::10:28:25 ===
closing AMQP connection <0.352.0> (172.17.42.1:35981 -> 172.17.0.3:5672):
{heartbeat_timeout,running}

=ERROR REPORT==== 15-May-2014::10:28:25 ===
closing AMQP connection <0.340.0> (172.17.42.1:35977 -> 172.17.0.3:5672):
{heartbeat_timeout,running}

=ERROR REPORT==== 15-May-2014::10:28:25 ===
closing AMQP connection <0.343.0> (172.17.42.1:35978 -> 172.17.0.3:5672):
{heartbeat_timeout,running}