951558 - buildapi-web2 RabbitMQ queue is high

Status: RESOLVED FIXED

(Infrastructure & Operations Graveyard :: CIDuty, task)

Description

[Ashish Vijayaram [:ashish]]

00:14:13 < nagios-scl3> | (IRC) Wed 00:14:13 PST [5397] rabbit1.releng.webapp.scl3.mozilla.com:Rabbit Unread Messages is CRITICAL: RABBITMQ_OVERVIEW CRITICAL - messages CRITICAL (982) messages_ready CRITICAL (982), messages_unacknowledged OK (0) (http://m.allizom.org/Rabbit+Unread+Messages)
00:08:24 < nagios-scl3> | (IRC) Wed 00:08:24 PST [5395] rabbit2.releng.webapp.scl3.mozilla.com:Rabbit Unread Messages is CRITICAL: RABBITMQ_OVERVIEW CRITICAL - messages CRITICAL (965) messages_ready CRITICAL (965), messages_unacknowledged OK (0) (http://m.allizom.org/Rabbit+Unread+Messages)

Opening a bug as per alert documentation. Unsure of severity, please adjust accordingly.

Comment 1

[Ashish Vijayaram [:ashish]]

I was unable to find the build duty personnel but I shall mention this bug in #buildduty for better visibility.

Comment 2

[Nick Thomas [:nthomas] (UTC+12)]

Looks like fallout from bug 946334 to me. From buildbot-master{61,62,65,66,81}:/builds/selfserve-agent/agent.log the self-serve messages are still getting through, and it worked for me too, so downgrading this to major.

Dustin and catlee (in SF this week) would know more about this.

Comment 3

[John Hopkins (:jhopkins)]

Dustin said yesterday: in the old arrangement, we were using a single rabbit server.  In the new, there are two behind a load balancer.  As far as I can tell, Buildapi does all of the right things to make this work (durable messages, queues, and exchanges)

Comment 4

[Dustin J. Mitchell [:dustin] (he/him)]

There were no connections to the buildapi-web2 queue, which is what buildapi (not self-serve) consumes from.  I restarted the buildapi daemon.  Unfortunately, due to bug 806777, there's no logging that might indicate why it stopped.

Comment 5

[Nick Thomas [:nthomas] (UTC+12)]

This started happening again:

(IRC) Wed 15:58:39 PST [5543] rabbit1.releng.webapp.scl3.mozilla.com:Rabbit Unread Messages is WARNING: RABBITMQ_OVERVIEW WARNING - messages WARNING (306) messages_ready WARNING (306), messages_unacknowledged OK (0) (http://m.allizom.org/Rabbit+Unread+Messages)

Comment 6

[Nick Thomas [:nthomas] (UTC+12)]

We do have buildapi logs this time, but nothing obviously wrong. This is the last message back from self-serve that gets processed:

2013-12-18 08:09:41,251 INFO  [buildapi.lib.mq] [Dummy-1] Got {u'body': {u'msg': u'Ok', u'errors': False}, u'request_id': 426451}

The next message out to self-serve is:
2013-12-18 08:42:51,599 INFO  [buildapi.lib.mq] [worker 18] Sending {'action': 'rebuild_build', 'body': {'priority': 0, 'bid': 34405899, 'when': 1387384971.5606539, 'request_id': 426452}, 'who': '[e-mail]'}

Maybe a 30min TCP timeout ? It's the first gap of that size size the restart in comment #4.

Comment 7

[Dustin J. Mitchell [:dustin] (he/him)]

Indeed - nice find!

[root@buildapi01 ~]# netstat -ap | grep rabbit
tcp        0      0 buildapi01.build.scl1:56297 releng-rabbitmq-zlb.we:amqp ESTABLISHED 28855/python

but

[[e-mail]3 dmitchell]# netstat -ap | grep buildapi01 | grep -v mysql
[[e-mail]3 dmitchell]#


RabbitMQ should fix this by suggesting heartbeats every 580s to the client.  I have no idea why that (9 minutes 40 seconds) is the default, but there you are.  At any rate, amqplib ignores this value, even in the latest version, so that doesn't help.  Hooray for crappy tools.

I changed the idle connection timeout in zeus to 300s, which should initiate a regular TCP FIN sequence at 300s, well before any firewalls in the way decide to expire the state.

Comment 8

[Dustin J. Mitchell [:dustin] (he/him)]

Maybe we should switch to py-amqp or librabbitmq.. I'll file a bug.

I restarted buildapi again, so let's hope this is solved this time.

Comment 9

[Dustin J. Mitchell [:dustin] (he/him)]

..and it's back..

Comment 10

[Dustin J. Mitchell [:dustin] (he/him)]

Same symptoms: no connection on the zlb, but a connection present on buildapi01.

In the logs:

Unhandled exception in thread started by <bound method LoggingJobRequestDoneConsumer.wait of <buildapi.lib.mq.LoggingJobRequestDoneConsumer object at 0x6572310>>
Traceback (most recent call last):
  File "/home/buildapi/src/buildapi/lib/mq.py", line 105, in wait
    consumer.wait(limit)
  File "/home/buildapi/lib/python2.6/site-packages/carrot/messaging.py", line 446, in wait
    it.next()
  File "/home/buildapi/lib/python2.6/site-packages/carrot/backends/pyamqplib.py", line 300, in consume
    self.channel.wait()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/abstract_channel.py", line 89, in wait
    self.channel_id, allowed_methods)
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/connection.py", line 198, in _wait_method
    self.method_reader.read_method()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
    raise m
IOError: Socket closed

So, yeah, amqplib.. you are NOT PRODUCTION READY.

Comment 11

[Dustin J. Mitchell [:dustin] (he/him)]

The connection timeout is still 28800s.  I'm not sure if my change didn't "take", or if it got changed back, but either way that's where it should be, lest the socket be closed after only 5m of idle.

Comment 12

[Nick Thomas [:nthomas] (UTC+12)]

Restarted buildapi in response to nagios alerting again.

Comment 13

[Dustin J. Mitchell [:dustin] (he/him)]

Thanks!  I suspect that 952266 is the fix here.

Comment 15

[Dustin J. Mitchell [:dustin] (he/him)]

Restarted again.  Sigh.

Comment 16

[Dustin J. Mitchell [:dustin] (he/him)]

Ah, I think there's a fairly simple fix here - ReconnectingConsumer needs to handle IOError.  I still hate amqplib and carrot :)

Comment 17

[Dustin J. Mitchell [:dustin] (he/him)]

Attachment: bug951558.patch

In my testing at home (without a rabbitmq server), I get IOError.  With this patch, it keeps trying.

Comment 18

[Dustin J. Mitchell [:dustin] (he/him)]

That helped, but now:

Unhandled exception in thread started by <bound method LoggingJobRequestDoneConsumer.wait of <buildapi.lib.mq.LoggingJobRequestDoneConsumer object at 0x351c290>>
Traceback (most recent call last):
  File "/home/buildapi/src/buildapi/lib/mq.py", line 108, in wait
    self.disconnect()
  File "/home/buildapi/src/buildapi/lib/mq.py", line 88, in disconnect
    self.connection.close()
  File "/home/buildapi/lib/python2.6/site-packages/carrot/connection.py", line 180, in close
    backend.close_connection(self._connection)
  File "/home/buildapi/lib/python2.6/site-packages/carrot/backends/pyamqplib.py", line 212, in close_connection
    connection.close()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/connection.py", line 301, in close
    (10, 61),    # Connection.close_ok
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/abstract_channel.py", line 89, in wait
    self.channel_id, allowed_methods)
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/connection.py", line 198, in _wait_method
    self.method_reader.read_method()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
    raise m
IOError: Socket closed

Comment 19

[Dustin J. Mitchell [:dustin] (he/him)]

Attachment: bug951558-p2.patch

Comment 20

[Dustin J. Mitchell [:dustin] (he/him)]

Comment on attachment 8350664 [details] [diff] [review]
bug951558-p2.patch

from jhopkins in irc.

This seems more durable.  I'm also going to bring the ZLB timeout back down to 5m, so we can avoid firewall TCP session timeouts.

Comment 21

[Dustin J. Mitchell [:dustin] (he/him)]

2013-12-20 09:17:11,005 INFO  [buildapi.lib.mq] [Dummy-1] Lost connection, trying again in 1s
Traceback (most recent call last):
  File "/home/buildapi/src/buildapi/lib/mq.py", line 108, in wait
    consumer.wait(limit)
  File "/home/buildapi/lib/python2.6/site-packages/carrot/messaging.py", line 446, in wait
    it.next()
  File "/home/buildapi/lib/python2.6/site-packages/carrot/backends/pyamqplib.py", line 300, in consume
    self.channel.wait()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/abstract_channel.py", line 89, in wait
    self.channel_id, allowed_methods)
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/connection.py", line 198, in _wait_method
    self.method_reader.read_method()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
    raise m
IOError: Socket closed
2013-12-20 09:17:11,006 INFO  [buildapi.lib.mq] [Dummy-1] error while disconnecting; ignored
Traceback (most recent call last):
  File "/home/buildapi/src/buildapi/lib/mq.py", line 89, in disconnect
    self.connection.close()
  File "/home/buildapi/lib/python2.6/site-packages/carrot/connection.py", line 180, in close
    backend.close_connection(self._connection)
  File "/home/buildapi/lib/python2.6/site-packages/carrot/backends/pyamqplib.py", line 212, in close_connection
    connection.close()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/connection.py", line 301, in close
    (10, 61),    # Connection.close_ok
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/abstract_channel.py", line 89, in wait
    self.channel_id, allowed_methods)
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/connection.py", line 198, in _wait_method
    self.method_reader.read_method()
  File "/home/buildapi/lib/python2.6/site-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
    raise m
IOError: Socket closed


.. promising!

Comment 22

[Dustin J. Mitchell [:dustin] (he/him)]

Attachment: bug951558-p3.patch

..deploy to selfserve

Comment 23

[Dustin J. Mitchell [:dustin] (he/him)]

This is causing selfserve to exit every 5m, since it doesn't use the ReconnectingConsumer class (?).  However, it seems stable this way, so let's leave well enough alone.