** Description changed: + [Impact] + + On Jammy, nova-api running under Apache mod_wsgi can lose its RabbitMQ + reply listener connection even with heartbeat_in_pthread=True. + + Eventlet monkey-patching still affects the threading and queue modules + used by AMQPDriverBase, so the listener remains a green thread and can + miss heartbeats when its Eventlet hub is not scheduled. + + RabbitMQ then closes the connection with "missed heartbeats from + client", and the API logs "Server unexpectedly closed connection". + + [Test Plan] + + Before patch + + The WSGI helper blocks the Eventlet hub for 18 seconds with a 6-second + heartbeat timeout. + + lxc launch ubuntu:22.04 lp2009138-test + lxc file push reproduce_wsgi.py lp2009138-test/tmp/ + lxc exec lp2009138-test -- bash + + Inside the container + + apt-get update + apt-get install -y apache2 libapache2-mod-wsgi-py3 rabbitmq-server python3-eventlet python3-oslo.messaging curl + useradd --system --create-home --user-group nova + install -d -m 755 /etc/nova /var/lib/lp2009138 + printf '[DEFAULT]\ntransport_url = rabbit://guest:[email protected]:5672//\n' > /etc/nova/nova.conf + install -m 644 /tmp/reproduce_wsgi.py /var/lib/lp2009138/reproduce_wsgi.py + cat > /etc/apache2/sites-available/lp2009138-reproducer.conf <<'EOF' + Listen 127.0.0.1:18080 + <VirtualHost 127.0.0.1:18080> + ServerName lp2009138-reproducer + WSGIDaemonProcess lp2009138-reproducer user=nova group=nova processes=1 threads=1 + WSGIProcessGroup lp2009138-reproducer + WSGIApplicationGroup %{GLOBAL} + WSGIScriptAlias / /var/lib/lp2009138/reproduce_wsgi.py + <Directory /var/lib/lp2009138> + Require all granted + </Directory> + ErrorLog /var/log/apache2/lp2009138-reproducer-error.log + CustomLog /var/log/apache2/lp2009138-reproducer-access.log combined + </VirtualHost> + EOF + a2ensite lp2009138-reproducer + apache2ctl configtest + service rabbitmq-server start + rabbitmqctl await_startup + + Set heartbeat_in_pthread=False + + sed -i 's/"heartbeat_in_pthread", True/"heartbeat_in_pthread", + False/' /var/lib/lp2009138/reproduce_wsgi.py + + Run after each package or option change: + + apache2ctl restart + curl -fsS --max-time 45 http://127.0.0.1:18080/ + rabbitmqctl list_connections name client_properties state timeout + tail -n 40 /var/log/rabbitmq/*.log + + Set True, then repeat the test block + + sed -i 's/"heartbeat_in_pthread", False/"heartbeat_in_pthread", + True/' /var/lib/lp2009138/reproduce_wsgi.py + + Expected listener_thread_native=false and "missed heartbeats from client, timeout: 6s". + Check this run's timestamp and lp2009138-mod-wsgi connection name. A reconnection is not a pass. + + After patch + + Install the patched python3-oslo.messaging package and repeat the test + block with True. + + Expected listener_thread_native=true and the original connection stays + open without missed heartbeats. + + Repeat with False using the earlier sed command: expect + listener_thread_native=false and a missed-heartbeat disconnect. + + [Where problems could occur] + + Mixing native threads with Eventlet-patched queues could cause cross-thread greenlet errors, hangs, or lost RPC replies. + The threading and queue references are module-level, so transports with different heartbeat_in_pthread settings in the same process could affect one another. + If the change unintentionally affects non-WSGI services using heartbeat_in_pthread=False, it could disrupt Eventlet-based RPC processing and instance builds. + + [Original Description] + Context ======= OpenStack Yoga Nova API behind apache2 with mod_wsgi RabbitMQ 3.9.12 Explanation =========== When using nova with apache2/mod_wsgi, we need to set 'heartbeat_in_pthread=True' to avoid using green threads (eventlet monkey patched threads). The python thread is mandatory to keep sending heartbeats so rabbit will not close the connection. One other option is to completely disable the heartbeats, so the connection will only rely on tcp keepalive. But more is better. The problem with the current heartbeat_in_pthread implementation is that some threads are still greenthreads. The result is that, some connections are correctly sending heartbeats, some others are not (and are still killed by rabbitmq after the heartbeat timeout). We identified that oslo_messaging is connecting to rabbit for two different purpose: - send - listen The current heartbeat_in_pthread=True parameter is switching heartbeat from greenthread to python thread *only for send* purpose (done in impl_rabbit.py). For listen purpose, the thread is created by the mother class (in amqpdriver.py), which is still using greenthreads. As a result, for listen purpose, rabbit connections are killed. We can see in rabbit logs: missed heartbeats from client, timeout: 60s We can see in nova-api logs: Server unexpectedly closed connection. - How to reproduce ================ Start nova-api with apache mod_wsgi and set heartbeat_in_pthread=True Monitor the current rabbitmq connection from nova: $ ss -tnep |grep 5672 (this can be empty if nova did nothing yet) Do an nova API call that needs rabbit, e.g. ask for a console url: $ openstack console url show 5700ecbc-adff-41d3-88a4-f24e0b885b2e - This will create two connecitons: - ESTAB 0 0 10.42.1.165:58206 10.43.216.243:5672 timer:(keepalive,46sec,0) uid:42436 ino:422570487 sk:1a cgroup:/ <-> - ESTAB 0 0 10.42.1.165:58204 10.43.216.243:5672 timer:(keepalive,46sec,0) uid:42436 ino:422570486 sk:1b cgroup:/ <-> + ESTAB 0 0 10.42.1.165:58206 10.43.216.243:5672 timer:(keepalive,46sec,0) uid:42436 ino:422570487 sk:1a cgroup:/ <-> + ESTAB 0 0 10.42.1.165:58204 10.43.216.243:5672 timer:(keepalive,46sec,0) uid:42436 ino:422570486 sk:1b cgroup:/ <-> One is for "send" purpose, second is for "listen" purpose. You can also see them in rabbit logs: connection <0.21408.594> (10.42.1.165:58206 -> 10.42.0.21:5672 - mod_wsgi:88239:41e4b74d-c3be-47f5-8b8f-d3bd99871f46): user 'openstack' authenticated and granted access to vhost '/' connection <0.21390.594> (10.42.1.165:58204 -> 10.42.0.21:5672 - mod_wsgi:88239:2b8345ca-fc75-442f-9271-1448352bb2d2): user 'openstack' authenticated and granted access to vhost '/' You can also monitor the heartbeats going from/to rabbit: $ tcpdump -i eth0 -nn port 5672 ... You will see that both connection are receiving heartbeats every 30sec, but *only one* is sending heartbeats (the one in pthread). - After few minutes, rabbit is killing the "listen" connection, as seen in rabbit logs: 2023-03-03 09:54:27.932885+00:00 [erro] <0.21390.594> closing AMQP connection <0.21390.594> (10.42.1.165:58204 -> 10.42.0.21:5672 - mod_wsgi:88239:2b8345ca-fc75-442f-9271-1448352bb2d2): 2023-03-03 09:54:27.932885+00:00 [erro] <0.21390.594> missed heartbeats from client, timeout: 60s
** Attachment added: "reproduce_wsgi.py" https://bugs.launchpad.net/ubuntu/+source/oslo.messaging/+bug/2009138/+attachment/6004742/+files/reproduce_wsgi.py ** Description changed: [Impact] On Jammy, nova-api running under Apache mod_wsgi can lose its RabbitMQ reply listener connection even with heartbeat_in_pthread=True. Eventlet monkey-patching still affects the threading and queue modules used by AMQPDriverBase, so the listener remains a green thread and can miss heartbeats when its Eventlet hub is not scheduled. RabbitMQ then closes the connection with "missed heartbeats from client", and the API logs "Server unexpectedly closed connection". [Test Plan] Before patch The WSGI helper blocks the Eventlet hub for 18 seconds with a 6-second heartbeat timeout. - lxc launch ubuntu:22.04 lp2009138-test - lxc file push reproduce_wsgi.py lp2009138-test/tmp/ - lxc exec lp2009138-test -- bash + // Please download attached python file. + lxc launch ubuntu:22.04 lp2009138-test + lxc file push reproduce_wsgi.py lp2009138-test/tmp/ + lxc exec lp2009138-test -- bash Inside the container - apt-get update - apt-get install -y apache2 libapache2-mod-wsgi-py3 rabbitmq-server python3-eventlet python3-oslo.messaging curl - useradd --system --create-home --user-group nova - install -d -m 755 /etc/nova /var/lib/lp2009138 - printf '[DEFAULT]\ntransport_url = rabbit://guest:[email protected]:5672//\n' > /etc/nova/nova.conf - install -m 644 /tmp/reproduce_wsgi.py /var/lib/lp2009138/reproduce_wsgi.py - cat > /etc/apache2/sites-available/lp2009138-reproducer.conf <<'EOF' + apt-get update + apt-get install -y apache2 libapache2-mod-wsgi-py3 rabbitmq-server python3-eventlet python3-oslo.messaging curl + useradd --system --create-home --user-group nova + install -d -m 755 /etc/nova /var/lib/lp2009138 + printf '[DEFAULT]\ntransport_url = rabbit://guest:[email protected]:5672//\n' > /etc/nova/nova.conf + install -m 644 /tmp/reproduce_wsgi.py /var/lib/lp2009138/reproduce_wsgi.py + cat > /etc/apache2/sites-available/lp2009138-reproducer.conf <<'EOF' Listen 127.0.0.1:18080 <VirtualHost 127.0.0.1:18080> - ServerName lp2009138-reproducer - WSGIDaemonProcess lp2009138-reproducer user=nova group=nova processes=1 threads=1 - WSGIProcessGroup lp2009138-reproducer - WSGIApplicationGroup %{GLOBAL} - WSGIScriptAlias / /var/lib/lp2009138/reproduce_wsgi.py - <Directory /var/lib/lp2009138> - Require all granted - </Directory> - ErrorLog /var/log/apache2/lp2009138-reproducer-error.log - CustomLog /var/log/apache2/lp2009138-reproducer-access.log combined + ServerName lp2009138-reproducer + WSGIDaemonProcess lp2009138-reproducer user=nova group=nova processes=1 threads=1 + WSGIProcessGroup lp2009138-reproducer + WSGIApplicationGroup %{GLOBAL} + WSGIScriptAlias / /var/lib/lp2009138/reproduce_wsgi.py + <Directory /var/lib/lp2009138> + Require all granted + </Directory> + ErrorLog /var/log/apache2/lp2009138-reproducer-error.log + CustomLog /var/log/apache2/lp2009138-reproducer-access.log combined </VirtualHost> EOF - a2ensite lp2009138-reproducer - apache2ctl configtest - service rabbitmq-server start - rabbitmqctl await_startup + a2ensite lp2009138-reproducer + apache2ctl configtest + service rabbitmq-server start + rabbitmqctl await_startup Set heartbeat_in_pthread=False - sed -i 's/"heartbeat_in_pthread", True/"heartbeat_in_pthread", + sed -i 's/"heartbeat_in_pthread", True/"heartbeat_in_pthread", False/' /var/lib/lp2009138/reproduce_wsgi.py Run after each package or option change: - apache2ctl restart - curl -fsS --max-time 45 http://127.0.0.1:18080/ - rabbitmqctl list_connections name client_properties state timeout - tail -n 40 /var/log/rabbitmq/*.log + apache2ctl restart + curl -fsS --max-time 45 http://127.0.0.1:18080/ + rabbitmqctl list_connections name client_properties state timeout + tail -n 40 /var/log/rabbitmq/*.log Set True, then repeat the test block - sed -i 's/"heartbeat_in_pthread", False/"heartbeat_in_pthread", + sed -i 's/"heartbeat_in_pthread", False/"heartbeat_in_pthread", True/' /var/lib/lp2009138/reproduce_wsgi.py Expected listener_thread_native=false and "missed heartbeats from client, timeout: 6s". Check this run's timestamp and lp2009138-mod-wsgi connection name. A reconnection is not a pass. After patch Install the patched python3-oslo.messaging package and repeat the test block with True. Expected listener_thread_native=true and the original connection stays open without missed heartbeats. Repeat with False using the earlier sed command: expect listener_thread_native=false and a missed-heartbeat disconnect. [Where problems could occur] Mixing native threads with Eventlet-patched queues could cause cross-thread greenlet errors, hangs, or lost RPC replies. The threading and queue references are module-level, so transports with different heartbeat_in_pthread settings in the same process could affect one another. If the change unintentionally affects non-WSGI services using heartbeat_in_pthread=False, it could disrupt Eventlet-based RPC processing and instance builds. [Original Description] Context ======= OpenStack Yoga Nova API behind apache2 with mod_wsgi RabbitMQ 3.9.12 Explanation =========== When using nova with apache2/mod_wsgi, we need to set 'heartbeat_in_pthread=True' to avoid using green threads (eventlet monkey patched threads). The python thread is mandatory to keep sending heartbeats so rabbit will not close the connection. One other option is to completely disable the heartbeats, so the connection will only rely on tcp keepalive. But more is better. The problem with the current heartbeat_in_pthread implementation is that some threads are still greenthreads. The result is that, some connections are correctly sending heartbeats, some others are not (and are still killed by rabbitmq after the heartbeat timeout). We identified that oslo_messaging is connecting to rabbit for two different purpose: - send - listen The current heartbeat_in_pthread=True parameter is switching heartbeat from greenthread to python thread *only for send* purpose (done in impl_rabbit.py). For listen purpose, the thread is created by the mother class (in amqpdriver.py), which is still using greenthreads. As a result, for listen purpose, rabbit connections are killed. We can see in rabbit logs: missed heartbeats from client, timeout: 60s We can see in nova-api logs: Server unexpectedly closed connection. How to reproduce ================ Start nova-api with apache mod_wsgi and set heartbeat_in_pthread=True Monitor the current rabbitmq connection from nova: $ ss -tnep |grep 5672 (this can be empty if nova did nothing yet) Do an nova API call that needs rabbit, e.g. ask for a console url: $ openstack console url show 5700ecbc-adff-41d3-88a4-f24e0b885b2e This will create two connecitons: ESTAB 0 0 10.42.1.165:58206 10.43.216.243:5672 timer:(keepalive,46sec,0) uid:42436 ino:422570487 sk:1a cgroup:/ <-> ESTAB 0 0 10.42.1.165:58204 10.43.216.243:5672 timer:(keepalive,46sec,0) uid:42436 ino:422570486 sk:1b cgroup:/ <-> One is for "send" purpose, second is for "listen" purpose. You can also see them in rabbit logs: connection <0.21408.594> (10.42.1.165:58206 -> 10.42.0.21:5672 - mod_wsgi:88239:41e4b74d-c3be-47f5-8b8f-d3bd99871f46): user 'openstack' authenticated and granted access to vhost '/' connection <0.21390.594> (10.42.1.165:58204 -> 10.42.0.21:5672 - mod_wsgi:88239:2b8345ca-fc75-442f-9271-1448352bb2d2): user 'openstack' authenticated and granted access to vhost '/' You can also monitor the heartbeats going from/to rabbit: $ tcpdump -i eth0 -nn port 5672 ... You will see that both connection are receiving heartbeats every 30sec, but *only one* is sending heartbeats (the one in pthread). After few minutes, rabbit is killing the "listen" connection, as seen in rabbit logs: 2023-03-03 09:54:27.932885+00:00 [erro] <0.21390.594> closing AMQP connection <0.21390.594> (10.42.1.165:58204 -> 10.42.0.21:5672 - mod_wsgi:88239:2b8345ca-fc75-442f-9271-1448352bb2d2): 2023-03-03 09:54:27.932885+00:00 [erro] <0.21390.594> missed heartbeats from client, timeout: 60s -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/2009138 Title: Heartbeat in pthreads still using greenthreads To manage notifications about this bug go to: https://bugs.launchpad.net/cloud-archive/+bug/2009138/+subscriptions -- ubuntu-bugs mailing list [email protected] https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
