python3 - importlib fails to read first 5 chars from file

[Mihai Gheorghe]

A bit of context: we have an Openstack Ussuri deployment (HA) on Ubuntu Focal. Most Openstack services are running on LXD containers on 3 baremetals. There are also two OVN-dedicated-chassis which act as gateways and nova-compute nodes.
A couple of days ago we updated all the packages in the environment to the latest versions (baremetals and lxc containers).
After the updates, we started seeing problems with the Octavia API. The API would randomly give an internal server error. Octavia API is running under Apache2 WSGI on 3 LXD containers on 3 separate nodes.
Looking into one of the Octavia container under /var/log/apache2/octavia_error.log, we found the following error:

[Fri Apr 28 10:11:07.509268 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] mod_wsgi (pid=1312420): Failed to exec Python script file '/usr/bin/octavia-wsgi'.
[Fri Apr 28 10:11:07.509455 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] mod_wsgi (pid=1312420): Exception occurred processing WSGI script '/usr/bin/octavia-wsgi'.
[Fri Apr 28 10:11:07.511688 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] Traceback (most recent call last):
[Fri Apr 28 10:11:07.511884 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "/usr/bin/octavia-wsgi", line 52, in <module>
[Fri Apr 28 10:11:07.512260 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] application = setup_app()
[Fri Apr 28 10:11:07.512343 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "/usr/lib/python3/dist-packages/octavia/api/app.py", line 59, in setup_app
[Fri Apr 28 10:11:07.512435 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] pecan_config = get_pecan_config()
[Fri Apr 28 10:11:07.512513 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "/usr/lib/python3/dist-packages/octavia/api/app.py", line 40, in get_pecan_config
[Fri Apr 28 10:11:07.512529 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] return pecan_configuration.conf_from_file(filename)
[Fri Apr 28 10:11:07.512543 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "/usr/lib/python3/dist-packages/pecan/configuration.py", line 176, in conf_from_file
[Fri Apr 28 10:11:07.512553 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] SourceFileLoader(module_name, abspath).load_module(module_name)
[Fri Apr 28 10:11:07.512567 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap_external>", line 522, in _check_name_wrapper
[Fri Apr 28 10:11:07.512705 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap_external>", line 1027, in load_module
[Fri Apr 28 10:11:07.512725 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap_external>", line 852, in load_module
[Fri Apr 28 10:11:07.512737 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap>", line 265, in _load_module_shim
[Fri Apr 28 10:11:07.512750 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap>", line 702, in _load
[Fri Apr 28 10:11:07.512763 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap>", line 671, in _load_unlocked
[Fri Apr 28 10:11:07.512775 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap_external>", line 844, in exec_module
[Fri Apr 28 10:11:07.512788 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap_external>", line 981, in get_code
[Fri Apr 28 10:11:07.512800 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap_external>", line 911, in source_to_code
[Fri Apr 28 10:11:07.512839 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
[Fri Apr 28 10:11:07.512869 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] File "/usr/lib/python3/dist-packages/octavia/api/config.py", line 1
[Fri Apr 28 10:11:07.512893 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] Copyright 2014 Rackspace
[Fri Apr 28 10:11:07.512921 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] ^
[Fri Apr 28 10:11:07.512938 2023] [wsgi:error] [pid 1312420:tid 140012169602816] [remote 127.0.0.1:59914] IndentationError: unexpected indent

The original /usr/lib/python3/dist-packages/octavia/api/config.py file is added to the bug report.
As seen in the file, the first line starts with a comment, but python is trying to run it as code.
Removing the first 5 charactersin the file so that string above starts right after the comment yelds the following traceback:

[Wed Apr 26 17:08:22.609980 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] mod_wsgi (pid=330647): Failed to exec Python script file '/usr/bin/octavia-wsgi'.
[Wed Apr 26 17:08:22.610114 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] mod_wsgi (pid=330647): Exception occurred processing WSGI script '/usr/bin/octavia-wsgi'.
[Wed Apr 26 17:08:22.611039 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] Traceback (most recent call last):
[Wed Apr 26 17:08:22.611097 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] File "/usr/bin/octavia-wsgi", line 52, in <module>
[Wed Apr 26 17:08:22.611106 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] application = setup_app()
[Wed Apr 26 17:08:22.611125 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] File "/usr/lib/python3/dist-packages/octavia/api/app.py", line 59, in setup_app
[Wed Apr 26 17:08:22.611135 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] pecan_config = get_pecan_config()
[Wed Apr 26 17:08:22.611152 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] File "/usr/lib/python3/dist-packages/octavia/api/app.py", line 40, in get_pecan_config
[Wed Apr 26 17:08:22.611160 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] return pecan_configuration.conf_from_file(filename)
[Wed Apr 26 17:08:22.611178 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] File "/usr/lib/python3/dist-packages/pecan/configuration.py", line 168, in conf_from_file
[Wed Apr 26 17:08:22.611327 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] compiled = compile(f.read(), abspath, 'exec')
[Wed Apr 26 17:08:22.611355 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] File "/usr/lib/python3/dist-packages/octavia/api/config.py", line 1
[Wed Apr 26 17:08:22.611381 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] right 2014 Rackspace
[Wed Apr 26 17:08:22.611419 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] ^
[Wed Apr 26 17:08:22.611437 2023] [wsgi:error] [pid 330647:tid 140629468657408] [remote 127.0.0.1:55142] SyntaxError: invalid syntax

It seems that when the source file is read by python, the first 5 characters are skipped for some reason.
Digging deeper, I see no reason for importlib to trim those characters. Internally it uses _io.open_code().read() which should return the entire file without trimming anything

If adding the comment after the 5th char on the first line, the file is read as is should but the error moves to a different file:

[Fri Apr 28 10:20:24.730194 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] mod_wsgi (pid=1316806): Failed to exec Python script file '/usr/bin/octavia-wsgi'.
[Fri Apr 28 10:20:24.730379 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] mod_wsgi (pid=1316806): Exception occurred processing WSGI script '/usr/bin/octavia-wsgi'.
[Fri Apr 28 10:20:24.732137 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] Traceback (most recent call last):
[Fri Apr 28 10:20:24.732294 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/bin/octavia-wsgi", line 52, in <module>
[Fri Apr 28 10:20:24.732316 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] application = setup_app()
[Fri Apr 28 10:20:24.732340 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/octavia/api/app.py", line 62, in setup_app
[Fri Apr 28 10:20:24.732353 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] return pecan_make_app(
[Fri Apr 28 10:20:24.732381 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/pecan/__init__.py", line 86, in make_app
[Fri Apr 28 10:20:24.732400 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] app = Pecan(root, **kw)
[Fri Apr 28 10:20:24.732453 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/pecan/core.py", line 832, in __init__
[Fri Apr 28 10:20:24.732475 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] super(Pecan, self).__init__(*args, **kw)
[Fri Apr 28 10:20:24.732516 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/pecan/core.py", line 240, in __init__
[Fri Apr 28 10:20:24.732536 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] root = self.__translate_root__(root)
[Fri Apr 28 10:20:24.732582 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/pecan/core.py", line 275, in __translate_root__
[Fri Apr 28 10:20:24.732618 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] module = __import__(name, fromlist=fromlist)
[Fri Apr 28 10:20:24.732645 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/octavia/api/root_controller.py", line 24, in <module>
[Fri Apr 28 10:20:24.732716 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] from octavia.api.v2 import controllers as v2_controller
[Fri Apr 28 10:20:24.732760 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/octavia/api/v2/controllers/__init__.py", line 19, in <module>
[Fri Apr 28 10:20:24.732821 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] from octavia.api.v2.controllers import availability_zone_profiles
[Fri Apr 28 10:20:24.732908 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] File "/usr/lib/python3/dist-packages/octavia/api/v2/controllers/availability_zone_profiles.py", line 1
[Fri Apr 28 10:20:24.732952 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] Copyright 2019 Verizon Media
[Fri Apr 28 10:20:24.733024 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] ^
[Fri Apr 28 10:20:24.733107 2023] [wsgi:error] [pid 1316806:tid 140384699016960] [remote 127.0.0.1:41802] SyntaxError: invalid syntax

As far as we can tell, this problem appears when importlib reads the file and hands it over incomplete (missing the first 5 chars).
This issue only occurs on the Octavia containers and not on the other Openstack services.
The other thing is that the fault is not consistent. It happens at Apache2 reload or restart but not everytime. Once in a few restarts. When the problem occurs, Octavia API is down.

Env details:
OS: Ubuntu 20.04

Kernel:
5.4.0-147-generic

Openstack: Ussuri

Octavia:
ii octavia-api 6.2.2-0ubuntu1 all OpenStack Load Balancer as a Service - API frontend
ii octavia-common 6.2.2-0ubuntu1 all OpenStack Load Balancer as a Service - Common files
ii octavia-driver-agent 6.2.2-0ubuntu1 all OpenStack Load Balancer Service - Driver Agent
ii octavia-health-manager 6.2.2-0ubuntu1 all OpenStack Load Balancer Service - Health manager
ii octavia-housekeeping 6.2.2-0ubuntu1 all OpenStack Load Balancer Service - Housekeeping manager
ii octavia-worker 6.2.2-0ubuntu1 all OpenStack Load Balancer Service - Worker
ii python3-octavia 6.2.2-0ubuntu1 all OpenStack Load Balancer as a Service - Python libraries
ii python3-octavia-lib 2.0.0-0ubuntu1 all Library to support Octavia provider drivers
ii python3-ovn-octavia-provider 0.1.0-0ubuntu1 all OpenStack Octavia Integration with OVN - Python 3 library

Python: Python 3.8.10

LXD:
lxd 5.13-cea5ee2 24758 latest/stable canonical✓ -

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Gregory Thiemonge (gthiemonge)]

Marked as Invalid. It doesn't look like an Octavia bug.
Note: the official tested runtime for Ussuri was not Ubuntu 20.04 but it was Ubuntu 18.04

[Stefan Lupsa (stefanlupsacbsl)]

Hello, we've narrowed down the problem to the upgrade of the python3-openvswitch package out of the 42 total python packages that were changed during the routine upgrade.
During the upgrade it went from 2.13.3-0ubuntu0.20.04.2 -> 2.13.8-0ubuntu1.1

In the release history of the openvswitch package of which python3-openvswitch is a dependency and is versioned together, 2.13.5-0ubuntu1 is the first version available after the package we had in the Octavia containers before the upgrade. It presents the problematic behavior and in the latest available version 2.13.8-0ubuntu1.2, it is still there.

We were only specifically testing what package change was causing Octavia API to hang (not the full loadbalancer functionality) as we've installed one python package deb at a time without dependency through dpdk.

This behavior can be replicated by having at least one loadbalancer object created in the Octavia DB and running 2-3 openstack loadbalancer list watch screens to query the 4 API workers under apache wsgi while reloading the apache workers every 60 seconds to stress as this does not happen every time, but it should be visible behavior under these conditions after 1-2 hours.

deb packages taken from:
https://launchpad.net/ubuntu/focal/amd64/python3-openvswitch/2.13.3-0ubuntu0.20.04.2
https://launchpad.net/ubuntu/focal/amd64/python3-openvswitch/2.13.5-0ubuntu1

This behavior also does not happen if the Octavia OVN provider is disabled with all the latest packages but with the python3-openvswitch downgrade it does not appear even with the OVN driver enabled.

[api_settings]
#enabled_provider_drivers = amphora:The Octavia Amphora driver,ovn:Octavia OVN driver
enabled_provider_drivers = amphora:The Octavia Amphora driver

# Python version and libs installed
ubuntu@juju-7bae07-1-lxd-7:~$ dpkg -l | grep python3.8
ii libpython3.8:amd64 3.8.10-0ubuntu1~20.04.8 amd64 Shared Python runtime library (version 3.8)
ii libpython3.8-dev:amd64 3.8.10-0ubuntu1~20.04.8 amd64 Header files and a static library for Python (v3.8)
ii libpython3.8-minimal:amd64 3.8.10-0ubuntu1~20.04.8 amd64 Minimal subset of the Python language (version 3.8)
ii libpython3.8-stdlib:amd64 3.8.10-0ubuntu1~20.04.8 amd64 Interactive high-level object-oriented language (standard library, version 3.8)
ii python3.8 3.8.10-0ubuntu1~20.04.8 amd64 Interactive high-level object-oriented language (version 3.8)
ii python3.8-dev 3.8.10-0ubuntu1~20.04.8 amd64 Header files and a static library for Python (v3.8)
ii python3.8-minimal 3.8.10-0ubuntu1~20.04.8 amd64 Minimal subset of the Python language (version 3.8)

# Octavia, ovn and openvswitch installed packages
ubuntu@juju-7bae07-1-lxd-7:~$ dpkg -l | grep -e openvswitch -e ovn -e octavia
ii octavia-api 6.2.2-0ubuntu1 all OpenStack Load Balancer as a Service - API frontend
ii octavia-common 6.2.2-0ubuntu1 all OpenStack Load Balancer as a Service - Common f...

[Frode Nordahl (fnordahl)]

This all looks a bit strange to me and I'm not sure about the causality of the findings presented.

FWIW; in the OpenStack Charms project the Octavia OVN Provider driver is enabled from Victoria onwards, as we have found the Ussuri version to not work properly.

To confirm that it still works I just triggered a successful CI run [0] which deploys a OpenStack Victoria cloud, which includes the 2.13.8-0ubuntu1.2 openvswitch package, and performs an end to end test.

0: https://openstack-ci-reports.ubuntu.com/artifacts/673/887246/4/check/focal-victoria-no-amphora/6731e85/