barbican-api fails in binary flavours (uwsgi logs: unavailable modifier requested: 0)

[Jie Li]

Now we use kolla-ansible deploy the Barbican in environment by uwsgi. We meet these problems:
1.When we use the cli: openstack secret list, then it tell me "unavailable modifier requested: 0".
2.It always report the "SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /v1/secrets/xxxxxxx".
Maybe there are other problems here we not found.
We can see all the OpenStack services in kolla-ansible are use wsgi to deploy the service except the Barbican service, so we should also use the wsgi to deploy the barbican service.

[Radosław Piliszek (yoctozepto)]

Interesting case. We see the move towards uwsgi in general so this is really worth investigating future-wise as well.

[Radosław Piliszek (yoctozepto)]

Please let us know which release of Kolla that was (e.g. Stein, Train).

[Radosław Piliszek (yoctozepto)]

side note: bline on IRC has a similar issue on Train - "unavailable modifier requested: 0" (point 1)

[Jie Li (ramboman)]

The release is Rocky, and it is the same as master. By the way, why we plan to move towards uwsgi in general? Is their any problem in wsgi?

[Radosław Piliszek (yoctozepto)]

I guess because uWSGI is deemed to be a high-performance server for WSGI apps, not having mod_wsgi limitations and deployable with http server of choice in front of it (though probably still often with Apache). mod_wsgi makes the app live with apache daemon.

[Radosław Piliszek (yoctozepto)]

As for the problem at hand, where do these messages appear? Logs? Which ones?

[Jie Li (ramboman)]

yeah, it's appear in barbican.api logs.
and for the "SIGPIPE“，we can see the uwsgi community also don't know how to solve it clearly.
Re:
https://github.com/unbit/uwsgi/issues/1623
So we should think the uwsgi careful.

[Radosław Piliszek (yoctozepto)]

I forgot to ask - kolla images - distro: Ubuntu/Debian/CentOS? type: Binary/Source?

[Jie Li (ramboman)]

distro:Centos
type:Binary

[Jie Li (ramboman)]

so how can we deal with this issue?

[Radosław Piliszek (yoctozepto)]

I reproduced it on both binary, source flavours are fine. Testing: https://review.opendev.org/719037

[Radosław Piliszek (yoctozepto)]

As a workaround, if you don't require the binary flavour, you can use the following in globals.yml:

  barbican_install_type: "source"

[Radosław Piliszek (yoctozepto)]

I could not get the SIGPIPE error. When does it happen?

[Radosław Piliszek (yoctozepto)]

Some logs for reference:

binary failing:

*** Operational MODE: single process ***
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 22)
Fri Apr 10 16:01:29 2020 - [emperor] vassal barbican-api.ini has been spawned
spawned uWSGI worker 1 (pid: 23, cores: 1)
*** no app loaded. going in full dynamic mode ***
Fri Apr 10 16:01:29 2020 - [emperor] vassal barbican-api.ini is ready to accept requests
-- unavailable modifier requested: 0 --
announcing my loyalty to the Emperor...
Fri Apr 10 16:02:19 2020 - [emperor] vassal barbican-api.ini is now loyal
-- unavailable modifier requested: 0 --

source succeeding:

*** Operational MODE: single process ***
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 22)
Fri Apr 10 16:06:17 2020 - [emperor] vassal barbican-api.ini has been spawned
spawned uWSGI worker 1 (pid: 23, cores: 1)
Loading paste environment: config:/etc/barbican/barbican-api-paste.ini
WSGI app 0 (mountpoint='') ready in 3 seconds on interpreter 0x1e80a40 pid: 23
Fri Apr 10 16:06:20 2020 - [emperor] vassal barbican-api.ini is ready to accept requests
{address space usage: 247947264 bytes/236MB} {rss usage: 90808320 bytes/86MB} [pid: 23|app: 0|req: 1/1] 192.0.2.1 () {28 vars in 399 bytes} [Fri Apr 10 16:07:10 2020] GET / => generated 349 bytes in 3 msecs (HTTP/1.1 300) 3 headers in 105 bytes (1 switches on core 0)
announcing my loyalty to the Emperor...
Fri Apr 10 16:07:10 2020 - [emperor] vassal barbican-api.ini is now loyal
{address space usage: 251183104 bytes/239MB} {rss usage: 94121984 bytes/89MB} [pid: 23|app: 0|req: 2/2] 192.0.2.1 () {30 vars in 658 bytes} [Fri Apr 10 16:07:10 2020] GET /v1/secrets?limit=10&offset=0 => generated 27 bytes in 746 msecs (HTTP/1.1 200) 4 headers in 156 bytes (1 switches on core 0)
{address space usage: 251183104 bytes/239MB} {rss usage: 94326784 bytes/89MB} [pid: 23|app: 0|req: 3/3] 192.0.2.1 () {28 vars in 399 bytes} [Fri Apr 10 16:07:13 2020] GET / => generated 349 bytes in 2 msecs (HTTP/1.1 300) 3 headers in 105 bytes (1 switches on core 0)
{address space usage: 251842560 bytes/240MB} {rss usage: 94642176 bytes/90MB} [pid: 23|app: 0|req: 4/4] 192.0.2.1 () {34 vars in 666 bytes} [Fri Apr 10 16:07:13 2020] POST /v1/secrets/ => generated 88 bytes in 140 msecs (HTTP/1.1 201) 5 headers in 243 bytes (1 switches on core 0)
{address space usage: 252010496 bytes/240MB} {rss usage: 94908416 bytes/90MB} [pid: 23|app: 0|req: 5/5] 192.0.2.1 () {28 vars in 399 bytes} [Fri Apr 10 16:07:15 2020] GET / => generated 349 bytes in 2 msecs (HTTP/1.1 300) 3 headers in 105 bytes (1 switches on core 0)
{address space usage: 252272640 bytes/240MB} {rss usage: 95088640 bytes/90MB} [pid: 23|app: 0|req: 6/6] 192.0.2.1 () {30 vars in 697 bytes} [Fri Apr 10 16:07:15 2020] GET /v1/secrets/b264c188-6719-4335-96b8-3c854df2cac9 => generated 396 bytes in 100 msecs (HTTP/1.1 200) 4 headers in 157 bytes (1 switches on core 0)

[Radosław Piliszek (yoctozepto)]

OTOH, source flavours log this:

*** Python threads support is disabled. You can enable it with --enable-threads ***

[Radosław Piliszek (yoctozepto)]

All flavours log this:

open("/usr/lib/uwsgi/plugins/python_plugin.so"): No such file or directory [core/utils.c line 3691]
!!! UNABLE to load uWSGI plugin: /usr/lib/uwsgi/plugins/python_plugin.so: cannot open shared object file: No such file or directory !!!

^ looks like wrong library path. Nowadays it should be python3 I guess (but surely this does not apply to Rocky!).

[Radosław Piliszek (yoctozepto)]

But since source installs uwsgi from pip, we get native python support. In case of distro's it is modular. The module is installed seemingly properly but this is not the right one for Ussuri (py3, not 2).

[Radosław Piliszek (yoctozepto)]

Ussuri was fixed by switching to python3 in config. Now it also logs this:

*** Python threads support is disabled. You can enable it with --enable-threads ***

[Radosław Piliszek (yoctozepto)]

As for your issue, please attach full barbican-api logs. There must be something else missing there.

[Nick Jones (yankcrime)]

I've just hit this in Train and can confirm that switching the config to specify python3 fixed the issue.

[Radosław Piliszek (yoctozepto)]

@Jie - I don't see the invalid modifier case in there and it properly loaded python interpreter, so as I said this is likely a different issue. That SIGPIPE looks quite legit, considering the fact that silent disconnect from client (and/or haproxy) can raise it. Barbican also seems to handle other requests properly. Is it happening persistently? Maybe there is some timeout in place (e.g. SQL being slow)?

@Nick - ack, thanks.

We really need to trace the python version in images to fix this case. Just based on distro if binary is used.

[Pierre Riteau (priteau)]

Is this bug exactly the same as https://bugs.launchpad.net/kolla-ansible/+bug/1881784
Note there is a fix proposed: https://review.opendev.org/#/c/733805/