Pika event broker connection breaks down

[wochinge]

Rasa Open Source stops sending events via the pika event broker. Note that it works in the beginning and then stops working.

More info in Slack Thread

Rasa Open Source version: 0.28.6

Stack Trace:

2020-09-17 08:24:57 ERROR    pika.adapters.utils.io_services_utils  - Wrapped func exited with exception. Caller's stack:
Traceback (most recent call last):
  File "/opt/venv/lib/python3.7/site-packages/pika/diagnostic_utils.py", line 53, in log_exception_func_wrap
    return func(*args, **kwargs)
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/utils/io_services_utils.py", line 1093, in _on_socket_writable
    'but _tx_buffers is empty.', self._state)
AssertionError: ('_AsyncPlaintextTransport._on_socket_writable() called, but _tx_buffers is empty.', 1)
Traceback (most recent call last):
  File "/opt/venv/lib/python3.7/site-packages/pika/diagnostic_utils.py", line 53, in log_exception_func_wrap
    return func(*args, **kwargs)
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/utils/io_services_utils.py", line 1093, in _on_socket_writable
    'but _tx_buffers is empty.', self._state)
AssertionError: ('_AsyncPlaintextTransport._on_socket_writable() called, but _tx_buffers is empty.', 1)
2020-09-17 08:24:57 DEBUG    pika.adapters.select_connection  - Deactivating poller
Exception in thread Thread-2:
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/opt/venv/lib/python3.7/site-packages/rasa/core/brokers/pika.py", line 439, in _run_pika_io_loop
    self._pika_connection.ioloop.start()
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/select_connection.py", line 543, in start
    self._poller.start()
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/select_connection.py", line 803, in start
    self.poll()
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/select_connection.py", line 1200, in poll
    self._dispatch_fd_events(fd_event_map)
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/select_connection.py", line 904, in _dispatch_fd_events
    handler(fileno, events)
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/utils/selector_ioloop_adapter.py", line 391, in _on_reader_writer_fd_events
    callbacks.writer()
  File "/opt/venv/lib/python3.7/site-packages/pika/diagnostic_utils.py", line 53, in log_exception_func_wrap
    return func(*args, **kwargs)
  File "/opt/venv/lib/python3.7/site-packages/pika/adapters/utils/io_services_utils.py", line 1093, in _on_socket_writable
    'but _tx_buffers is empty.', self._state)
AssertionError: ('_AsyncPlaintextTransport._on_socket_writable() called, but _tx_buffers is empty.', 1)

Investigation so far

• there is an issue Assert Exception from _AsyncPlaintextTransport::_on_socket_writable pika/pika#1219 which suggest that this is caused by multiple threads sending messages via the connection
• the io loop is indeed running in a separate thread since this change Pika timeout fix #4689

Open Question:

• Why does this break only for some users?

Solution Ideas

• the brute force way to fix this is isolating the event broker sending into a separate process and send messages via multiprocessing.queue to the broker process

[wochinge]

High Prio because this breaks Rasa X usage and involves customers.

[benos]

Hi Folks,

This fix seems to have had the opposite of the desired effect for me. I.e. after upgrading to 1.10.16 rasa stopped recording events on Rasa X and after reverting back to 1.10.15 it works fine again.

I'm running all the services in Docker. There are no error messages I could see when running 1.10.16.

Happy to jump on a call and show you if it can help you debug it.

Ben

[wochinge]

@benos Thanks for bringing this up!
@alwx Do you have time to have another look?

[indam23]

I also see an issue with 1.10.16 - rabbitmq reports

2020-10-21 10:47:05.535 [error] <0.917.0> closing AMQP connection <0.917.0> (10.1.251.31:41056 -> 10.1.251.33:5672):
missed heartbeats from client, timeout: 60s

and no events are recorded.

This PR: #7100
Would revert the changes in 1.10.16 and also add some handling for disconnection.