on_hbread_fail when using mcollective and activemq

asked 2015-05-31 06:02:03 -0600

peier0810 gravatar image

when I use mcollective to run puppet command such as mco puppet runonce, i find that it always takes about one minute to run the puppet command in some machines. I checked mcollective's debug log and it shows like this:

D, [2015-05-27T18:58:36.550481 #26213] DEBUG -- : pluginmanager.rb:83:in `[]' Returning cached plugin connector_plugin with class MCollective::Connector::Activemq

D, [2015-05-27T18:58:36.550782 #26213] DEBUG -- : activemq.rb:437:in `publish' Sending a broadcast message to ActiveMQ target '/queue/mcollective.reply.puppetmaster.glodon.com_32460.2' with headers '{"expires"=>"1432724386000", "timestamp"=>"1432724316000", "mc_sender"=>"test-account-110.web.test.glodon.com"}'

D, [2015-05-27T18:58:36.563189 #26213] DEBUG -- : runnerstats.rb:56:in `sent' Incrementing replies stat

D, [2015-05-27T18:58:53.000523 #26213] DEBUG -- : activemq.rb:188:in `on_hbfire' Received heartbeat from stomp://mcollective@test-activemq-206.mid.test.glodon.com:61613: receive_fire, curt1432724333.00008

D, [2015-05-27T18:58:54.000169 #26213] DEBUG -- : activemq.rb:190:in `on_hbfire' Publishing heartbeat to stomp://mcollective@test-activemq-206.mid.test.glodon.com:61613: send_fire, last_sleep30.5curt1432724333.99974

D, [2015-05-27T18:59:22.502314 #26213] DEBUG -- : activemq.rb:188:in `on_hbfire' Received heartbeat from stomp://mcollective@test-activemq-206.mid.test.glodon.com:61613: receive_fire, curt1432724362.50197

D, [2015-05-27T18:59:22.502807 #26213] DEBUG -- : activemq.rb:157:in `on_hbread_fail' Heartbeat failed to acquire readlock for 'stomp://mcollective@test-activemq-206.mid.test.glodon.com:61613': {"read_fail_count"=>0, "lock_fail"=>true, "ticker_interval"=>29.5, "lock_fail_count"=>1}

D, [2015-05-27T18:59:24.500427 #26213] DEBUG -- : activemq.rb:190:in `on_hbfire' Publishing heartbeat to stomp://mcollective@test-activemq-206.mid.test.glodon.com:61613: send_fire, last_sleep30.4992110729218curt1432724364.50003

D, [2015-05-27T18:59:52.003765 #26213] DEBUG -- : activemq.rb:188:in `on_hbfire' Received heartbeat from stomp://mcollective@test-activemq-206.mid.test.glodon.com:61613: receive_fire, curt1432724392.00326

D, [2015-05-27T18:59:55.000559 #26213] DEBUG -- : activemq.rb:190:in `on_hbfire' Publishing heartbeat to stomp://mcollective@test-activemq-206.mid.test.glodon.com:61613: send_fire, last_sleep30.4992220401764curt1432724395.00024

we can see that mcollective spend about one minute on "on_hbfire". This really makes me confused in the whole past month. Hope someone can help me, Thank you all!

edit retag flag offensive close merge delete