Uploaded image for project: 'Red Hat OpenStack Services on OpenShift'
  1. Red Hat OpenStack Services on OpenShift
  2. OSPRH-20106

Initialization error in Octavia amphora-agent

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Minor Minor
    • None
    • None
    • openstack-octavia
    • None
    • Bug Tracking
    • False
    • Hide

      None

      Show
      None
    • False
    • ?
    • None
    • Low

      Potential race condition in octavia amphora-agent startup leads to:

      • loadbalancer operating_status remains OFFLINE
      • VIP is not correctly plugged

      Logs of the amphora agent:

       

      Sep 17 16:13:56 amphora-749dfb94-706f-41d0-b444-65b0042750e4 systemd[1]: Starting OpenStack Octavia Amphora Agent service...
Sep 17 16:13:56 amphora-749dfb94-706f-41d0-b444-65b0042750e4 systemd[1]: Started OpenStack Octavia Amphora Agent service.
Sep 17 16:14:00 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: 2025-09-17 16:14:00.440 851 INFO octavia.common.config [-] Logging enabled!
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: 2025-09-17 16:14:00.440 851 INFO octavia.common.config [-] Logging enabled!
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: 2025-09-17 16:14:00.443 851 INFO octavia.common.config [-] /usr/bin/amphora-agent version 12.0.1.dev84
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: 2025-09-17 16:14:00.443 851 DEBUG octavia.common.config [-] command line: /usr/bin/amphora-agent --config-file /etc/octavia/amphora-agent.conf setup_logging /usr/lib/python3.9/site-packages/octavia/common/config.py:948
Sep 17 16:14:00 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: 2025-09-17 16:14:00.443 851 INFO octavia.common.config [-] /usr/bin/amphora-agent version 12.0.1.dev84
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[965]: 2025-09-17 16:14:00.876 965 INFO octavia.amphorae.backends.health_daemon.health_daemon [-] Health Manager Sender starting.
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[965]: 2025-09-17 16:14:00.908 965 ERROR octavia.amphorae.backends.health_daemon.health_daemon [-] Keepalived is configured but not running, skipping health heartbeat.: ProcessLookupError: [Errno 3] No such process
Sep 17 16:14:00 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: 2025-09-17 16:14:00.443 851 DEBUG octavia.common.config [-] command line: /usr/bin/amphora-agent --config-file /etc/octavia/amphora-agent.conf setup_logging /usr/lib/python3.9/site-packages/octavia/common/config.py:948
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: --- Logging error ---
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: Traceback (most recent call last):
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib64/python3.9/logging/handlers.py", line 978, in emit
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     self.socket.send(msg)
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: OSError: [Errno 9] Bad file descriptor
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: During handling of the above exception, another exception occurred:
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: Traceback (most recent call last):
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib64/python3.9/logging/handlers.py", line 981, in emit
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     self._connect_unixsocket(self.address)
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib64/python3.9/logging/handlers.py", line 899, in _connect_unixsocket
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     self.socket.connect(address)
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: FileNotFoundError: [Errno 2] No such file or directory
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]: Call stack:
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/bin/amphora-agent", line 10, in <module>
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     sys.exit(main())
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib/python3.9/site-packages/octavia/cmd/agent.py", line 89, in main
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     AmphoraAgent(server_instance.app, options).run()
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib/python3.9/site-packages/gunicorn/app/base.py", line 72, in run
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     Arbiter(self).run()
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib/python3.9/site-packages/gunicorn/arbiter.py", line 58, in __init__
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     self.setup(app)
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib/python3.9/site-packages/gunicorn/arbiter.py", line 105, in setup
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     self.log.debug('Current configuration:\n{0}'.format(
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:   File "/usr/lib/python3.9/site-packages/gunicorn/glogging.py", line 267, in debug
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[851]:     self.error_log.debug(msg, *args, **kwargs)
Sep 17 16:14:00 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[965]: 2025-09-17 16:14:00.876 965 INFO octavia.amphorae.backends.health_daemon.health_daemon [-] Health Manager Sender starting.
Sep 17 16:14:00 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[965]: 2025-09-17 16:14:00.908 965 ERROR octavia.amphorae.backends.health_daemon.health_daemon [-] Keepalived is configured but not running, skipping health heartbeat.: ProcessLookupError: [Errno 3] No such process

      "Bad file descriptor" and "No such file or directory" is related to the logging system.

       

      At the same timestamps, rsyslog was (re)started:

       

      Sep 17 16:14:02 amphora-749dfb94-706f-41d0-b444-65b0042750e4 systemd[1]: Starting System Logging Service...
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 rsyslogd[1115]: warning: ~ action is deprecated, consider using the 'stop' statement instead [v8.2310.0-4.el9 try https://www.rsyslog.com/e/2307 ]
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 rsyslogd[1115]: module 'imuxsock' already in this config, cannot be added  [v8.2310.0-4.el9 try https://www.rsyslog.com/e/2221 ]
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 rsyslogd[1115]: [origin software="rsyslogd" swVersion="8.2310.0-4.el9" x-pid="1115" x-info="https://www.rsyslog.com"] start
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 systemd[1]: Started System Logging Service.
Sep 17 16:14:03 amphora-749dfb94-706f-41d0-b444-65b0042750e4 rsyslogd[1115]: imjournal: journal files changed, reloading...  [v8.2310.0-4.el9 try https://www.rsyslog.com/e/0 ]
Sep 17 16:39:32 amphora-749dfb94-706f-41d0-b444-65b0042750e4 rsyslogd[1115]: imjournal: journal files changed, reloading...  [v8.2310.0-4.el9 try https://www.rsyslog.com/e/0 ]
Sep 17 18:23:49 amphora-749dfb94-706f-41d0-b444-65b0042750e4 rsyslogd[1115]: imjournal: journal files changed, reloading...  [v8.2310.0-4.el9 try https://www.rsyslog.com/e/0 ]
Sep 17 20:09:36 amphora-749dfb94-706f-41d0-b444-65b0042750e4 rsyslogd[1115]: imjournal: journal files changed, reloading...  [v8.2310.0-4.el9 try https://www.rsyslog.com/e/0 ]

      it also triggered other issues:

       

      eth1 (the vip port) was not moved to the right namespace

      [cloud-user@amphora-749dfb94-706f-41d0-b444-65b0042750e4 ~]$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1442 qdisc fq_codel state UP group default qlen 1000
    link/ether fa:16:3e:dd:4c:45 brd ff:ff:ff:ff:ff:ff
    altname enp3s0
    inet 172.24.2.83/16 brd 172.24.255.255 scope global dynamic noprefixroute eth0
       valid_lft 29185sec preferred_lft 29185sec
    inet6 fe80::f816:3eff:fedd:4c45/64 scope link 
       valid_lft forever preferred_lft forever
3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
    link/ether fa:16:3e:74:75:e2 brd ff:ff:ff:ff:ff:ff
    altname enp4s0
and
[cloud-user@amphora-749dfb94-706f-41d0-b444-65b0042750e4 ~]$ sudo ip -n amphora-haproxy a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
4: eth2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1442 qdisc fq_codel state UP group default qlen 1000
    link/ether fa:16:3e:86:b2:7b brd ff:ff:ff:ff:ff:ff
    altname enp5s0
    inet 10.100.0.63/24 scope global eth2
       valid_lft forever preferred_lft forever
    inet6 fc00::f816:3eff:fe86:b27b/64 scope global 
       valid_lft forever preferred_lft forever

      keepalived didn't start because it could not bind to the eth1 interface,

      Sep 18 08:03:28 amphora-749dfb94-706f-41d0-b444-65b0042750e4 Keepalived_vrrp[1985]: (/var/lib/octavia/vrrp/octavia-keepalived.conf: Line 10) WARNING - interface eth1 for vrrp_instance e7f165ff3b45495489ebb60c1532dc7f doesn't exist
Sep 18 08:03:28 amphora-749dfb94-706f-41d0-b444-65b0042750e4 Keepalived_vrrp[1985]: (/var/lib/octavia/vrrp/octavia-keepalived.conf: Line 36) WARNING - interface eth1 for VROUTE nexthop doesn't exist
Sep 18 08:03:28 amphora-749dfb94-706f-41d0-b444-65b0042750e4 Keepalived_vrrp[1985]: (/var/lib/octavia/vrrp/octavia-keepalived.conf: Line 37) WARNING - interface eth1 for VROUTE nexthop doesn't exist
Sep 18 08:03:28 amphora-749dfb94-706f-41d0-b444-65b0042750e4 Keepalived_vrrp[1985]: Non-existent interface specified in configuration
Sep 18 08:03:28 amphora-749dfb94-706f-41d0-b444-65b0042750e4 Keepalived_vrrp[1985]: Stopped

      and the heartbeat message could not be sent because the keepalived pid file didn't exist

      Sep 18 07:58:15 amphora-749dfb94-706f-41d0-b444-65b0042750e4 amphora-agent[965]: 2025-09-18 07:58:15.001 965 ERROR octavia.amphorae.backends.health_daemon.health_daemon [-] Missing keepalived PID file /var/lib/octavia/vrrp/octavia-keepalived.pid, skipping health heartbeat.: FileNotFoundError: [Errno 2] No such file or directory: '/var/lib/octavia/vrrp/octavia-keepalived.pid'

      thus LB stayed in OFFLINE operating_status

              rhn-support-gthiemon Gregory Thiemonge
              rhn-support-gthiemon Gregory Thiemonge
              rhos-dfg-networking-squad-vans
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated: