I had tried to send this earlier with devstack output attached without
thinking about the large size of the text. Sorry :(

On Thu Jun 16 2022 16:56:21 GMT-0700 (Pacific Daylight Time), Dan Smith
<dms@danplanet.com> wrote:
>> It looks like copies of this may be getting repeatedly concatenated
>> into the plugin variable:
>>
>> https://opendev.org/openstack/devstack/src/commit/44d07f300150f7297773a215031ea85cb1f5e205/lib/databases/mysql#L231
>
> I don't think that's actually happening. If it was, restarting glance
> wouldn't help (as Melanie indicated) and it also should never really
> work. I was thinking that was more likely an artifact of the error
> message or something. Looking at the config files, they seem right. For
> example:
>
> https://zuul.opendev.org/t/openstack/build/ff5a7a6fc87840579b102b244f28200f/log/controller/logs/etc/glance/glance-api_conf.txt#21

I didn't notice this before but before things error with glance, other
projects had no problem loading the dbcounter plugin, keystone-manage:

> +lib/keystone:init_keystone:484            /usr/local/bin/keystone-manage --config-file /etc/keystone/keystone.conf db_sync
> INFO dbcounter [-] Registered counter for database keystone
> DEBUG oslo_db.sqlalchemy.engines [-] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_ENGINE_SUBSTITUTION {{(pid=371448) _check_effective_sql_mode /usr/local/lib/python3.8/dist-packages/oslo_db/sqlalchemy/engines.py:314}}
> DEBUG dbcounter [-] [371448] Writer thread running {{(pid=371448) stat_writer /usr/local/lib/python3.8/dist-packages/dbcounter.py:99}}

Yet glance fails to load it during two separate glance-manage calls:

> +lib/glance:init_glance:489                /usr/local/bin/glance-manage --config-file /etc/glance/glance-api.conf db_sync
> CRITICAL glance [-] Unhandled error: sqlalchemy.exc.NoSuchModuleError: Can't load plugin: sqlalchemy.plugins:dbcounterplugin=dbcounterplugin=dbcounter
[...]
> +lib/glance:init_glance:492                /usr/local/bin/glance-manage --config-file /etc/glance/glance-api.conf db_load_metadefs
> CRITICAL glance [-] Unhandled error: sqlalchemy.exc.NoSuchModuleError: Can't load plugin: sqlalchemy.plugins:dbcounterplugin=dbcounterplugin=dbcounter

Then cinder-manage loads it fine:

> +lib/cinder:init_cinder:440                /usr/local/bin/cinder-manage --config-file /etc/cinder/cinder.conf db sync
> INFO dbcounter [-] Registered counter for database cinder
> DEBUG oslo_db.sqlalchemy.engines [-] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_ENGINE_SUBSTITUTION {{(pid=391785) _check_effective_sql_mode /usr/local/lib/python3.8/dist-packages/oslo_db/sqlalchemy/engines.py:314}}
> DEBUG dbcounter [-] [391785] Writer thread running {{(pid=391785) stat_writer /usr/local/lib/python3.8/dist-packages/dbcounter.py:99}}

Then nova-manage:

> +lib/nova:init_nova:843                    /usr/local/bin/nova-manage --config-file /etc/nova/nova.conf api_db sync
> Modules with known eventlet monkey patching issues were imported prior to eventlet monkey patching: urllib3. This warning can usually be ignored if the caller is only importing and not executing nova code.
> INFO dbcounter [-] Registered counter for database nova_api
> DEBUG dbcounter [-] [394510] Writer thread running {{(pid=394510) stat_writer /usr/local/lib/python3.8/dist-packages/dbcounter.py:99}}
[...]
> INFO dbcounter [-] Registered counter for database nova_cell0
> DEBUG dbcounter [-] [394520] Writer thread running {{(pid=394520) stat_writer /usr/local/lib/python3.8/dist-packages/dbcounter.py:99}}
[...]
> INFO dbcounter [-] Registered counter for database nova_cell1
> DEBUG dbcounter [-] [394531] Writer thread running {{(pid=394531) stat_writer /usr/local/lib/python3.8/dist-packages/dbcounter.py:99}}

Finally glance fails to load the plugin in the g-api service when an
image upload is requested:

> +functions:_upload_image:121               openstack --os-cloud=devstack-admin --os-region-name=RegionOne image create cirros-0.5.2-x86_64-disk --public --container-format bare --disk-format qcow2 --property hw_rng_model=virtio
> /usr/lib/python3/dist-packages/secretstorage/dhcrypto.py:15: CryptographyDeprecationWarning: int_from_bytes is deprecated, use int.from_bytes instead
>   from cryptography.utils import int_from_bytes
> /usr/lib/python3/dist-packages/secretstorage/util.py:19: CryptographyDeprecationWarning: int_from_bytes is deprecated, use int.from_bytes instead
>   from cryptography.utils import int_from_bytes
> HttpException: 500: Server Error for url: http://192.168.42.11/image/v2/images, The server has either erred or is incapable of performing the requested operation.: 500 Internal Server Error

With this ^ I realized that restarting g-api might not have been a good
indicator of anything resolving because in this example the plugin load
failure occurs while checking quota for an inbound request. I'm not sure
whether services load the dbcounter passively when they start or if it's
only when database accesses are initiated.

I also don't understand how or why one project can't load the plugin but
the rest can. And I wonder whether it's a coincidence that it was glance
in the two examples we have so far.

-melwitt