{"comment":{"url":"https://api.github.com/repos/ministryofjustice/atet/comments/14962953","html_url":"https://github.com/ministryofjustice/atet/commit/89cab747eac5ae18a1af115e5ed16b530bd48ace#commitcomment-14962953","id":14962953,"user":{"login":"filipposc5","id":2116658,"avatar_url":"https://avatars.githubusercontent.com/u/2116658?v=3","gravatar_id":"","url":"https://api.github.com/users/filipposc5","html_url":"https://github.com/filipposc5","followers_url":"https://api.github.com/users/filipposc5/followers","following_url":"https://api.github.com/users/filipposc5/following{/other_user}","gists_url":"https://api.github.com/users/filipposc5/gists{/gist_id}","starred_url":"https://api.github.com/users/filipposc5/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/filipposc5/subscriptions","organizations_url":"https://api.github.com/users/filipposc5/orgs","repos_url":"https://api.github.com/users/filipposc5/repos","events_url":"https://api.github.com/users/filipposc5/events{/privacy}","received_events_url":"https://api.github.com/users/filipposc5/received_events","type":"User","site_admin":false},"position":null,"line":null,"path":"","commit_id":"89cab747eac5ae18a1af115e5ed16b530bd48ace","created_at":"2015-12-14T16:13:54Z","updated_at":"2015-12-14T16:13:54Z","body":"During a heartbeat definition of 28 seconds, two heartbeats will be sent in the total of 28 seconds and the responses must have been retrieved. This number is configurable on both server side and client side, and during the connection handshake this is negotiated on both sides so that a common value can be agreed upon. Eg:\r\n```\r\n2015-12-14T13:47:39Z p-23595 t-oxq11jlp0 DEBUG: Heartbeat interval negotiation: client = 30, server = 30, result = 30\r\n2015-12-14T13:47:39Z p-23595 t-oxq11jlp0 INFO: Heartbeat interval used (in seconds): 30\r\n2015-12-14T13:47:39Z p-23595 t-oxq11jlp0 DEBUG: Sent connection.tune-ok with heartbeat interval = 30, frame_max = 131072, channel_max = 65535\r\n```\r\n\r\nHowever the sneakers hardcoded default is 2 seconds (presumably set with low latency non-cloud machines in mind) which caused the previous negotiations to send heartbeats at 0.4 second intervals:\r\n`2015-09-09T18:09:05Z p-68 t-oujpb78qk DEBUG: Sending a heartbeat, last activity time: 2015-09-09 18:08:57 +0000, interval (s): 0.4`\r\nThere might be an issue in sneakers as well whereby it miscalculates the value too. Here's a sample negotiation with 2 seconds: \r\n```\r\n2015-12-03T14:57:15Z p-68 t-oujonbc7k DEBUG: Heartbeat interval negotiation: client = 2, server = 30, result = 2\r\n2015-12-03T14:57:15Z p-68 t-oujonbc7k INFO: Heartbeat interval used (in seconds): 2\r\n```\r\n\r\nAlso while this is configured in amqp.rb and does get applied to sneakers workers (eventually), it appears that perhaps the connections are opened before this configuration has taken place, so by that time the connections have already negotiated a very low heartbeat, which caused also the workers to behave unexpectedly. Also this is a mutual agreement so I believe both the server and the client can reset the connection. In practice I was seeing connections being reset every 6 seconds in rabbitmq log. \r\n\r\nThe root cause why we were seeing this only sometimes instead of all the time is simply because sometimes these connections were taking *slightly* longer (remember they have to make it all the way to ELB and back into rabbitmq as they are elb-balanced) whereas other times the performance was fast enough to not hit the issue.\r\n"}}