Redundant calls to entrypoint in plugins

[yankovs]

Environment information

• MWDB version (from /about):
• Installation method:
  • mwdb.cert.pl service
  • From PyPi (pip install mwdb-core)
  • From docker-compose
  • Other (please explain)
• Plugins installed: explained below

Behaviour the bug (what happened?)

In latest mwdb commit, using a modified hello_world plugin from the official docs:

import logging
import random

from mwdb.core.plugins import PluginAppContext

__author__ = "just me"
__version__ = "1.0.0"
__doc__ = "Simple hello world plugin"


logger = logging.getLogger("mwdb.plugin.hello_world")


def entrypoint(app_context: PluginAppContext):
    logger.info("Random: %s", random.randint(0, 20))


__plugin_entrypoint__ = entrypoint

it seems like there are redundant calls to the logic inside the entrypoint:

2023-05-06 17:07:54 Waiting for DB to become operational
2023-05-06 17:07:54 Configuring mwdb-core instance
2023-05-06 17:07:57 
2023-05-06 17:07:57 MWDB configured successfully!
2023-05-06 17:07:57 
2023-05-06 17:07:57 Use 'mwdb-core run' to run the server.
2023-05-06 17:07:57 
2023-05-06 17:07:54 INFO  [mwdb.configure] Configuration already initialized... skipping
2023-05-06 17:07:56 INFO  [mwdb.plugin.hello_world] Random: 18
2023-05-06 17:07:56 INFO  [mwdb.application] Loaded plugin 'hello_world'
2023-05-06 17:07:56 INFO  [alembic.runtime.migration] Context impl PostgresqlImpl.
2023-05-06 17:07:56 INFO  [alembic.runtime.migration] Will assume transactional DDL.
2023-05-06 17:07:57 INFO  [mwdb.configure] Database already initialized... skipping
2023-05-06 17:07:57 INFO  [mwdb.application] Configured plugin 'hello_world'
2023-05-06 17:07:57 [2023-05-06 14:07:57 +0000] [1] [INFO] Starting gunicorn 20.1.0
2023-05-06 17:07:57 [2023-05-06 14:07:57 +0000] [1] [INFO] Listening at: http://0.0.0.0:8080 (1)
2023-05-06 17:07:57 [2023-05-06 14:07:57 +0000] [1] [INFO] Using worker: sync
2023-05-06 17:07:57 [2023-05-06 14:07:57 +0000] [21] [INFO] Booting worker with pid: 21
2023-05-06 17:07:57 [2023-05-06 14:07:57 +0000] [22] [INFO] Booting worker with pid: 22
2023-05-06 17:07:57 [2023-05-06 14:07:57 +0000] [23] [INFO] Booting worker with pid: 23
2023-05-06 17:07:57 [2023-05-06 14:07:57 +0000] [24] [INFO] Booting worker with pid: 24
2023-05-06 17:07:58 [INFO] MainThread - __init__.entrypoint:15 - Random: 16
2023-05-06 17:07:58 [INFO] MainThread - plugins.load_plugins:263 - Loaded plugin 'hello_world'
2023-05-06 17:07:58 [INFO] MainThread - __init__.entrypoint:15 - Random: 10
2023-05-06 17:07:58 [INFO] MainThread - plugins.load_plugins:263 - Loaded plugin 'hello_world'
2023-05-06 17:07:58 [INFO] MainThread - __init__.entrypoint:15 - Random: 5
2023-05-06 17:07:58 [INFO] MainThread - plugins.load_plugins:263 - Loaded plugin 'hello_world'
2023-05-06 17:07:59 [INFO] MainThread - __init__.entrypoint:15 - Random: 16
2023-05-06 17:07:59 [INFO] MainThread - plugins.load_plugins:263 - Loaded plugin 'hello_world'

Expected behaviour

I'd expect that the plugin code would be called once and logged once

Reproduction Steps

Use the plugin above in the same way mentioned in docs

I'd also want to add that in v2.8.2 of mwdb this did not happen, it would consistently log:

2023-05-06 17:07:59 [INFO] MainThread - __init__.entrypoint:15 - Random: <number>
2023-05-06 17:07:59 [INFO] MainThread - plugins.load_plugins:263 - Loaded plugin 'hello_world'

only once

[psrok1]

That's a side-effect caused by transition from uWSGI to Gunicorn and different configuration defaults set. uWSGI was configured to preload application before forking into worker processes. Gunicorn on the other hand loads application individually in each worker, so these log lines come from different processes.

The same behavior as in uWSGI can be turned on in Gunicorn by enabling preload_app option (https://docs.gunicorn.org/en/stable/settings.html#preload-app). On the other hand, reload is not compatible with preload_app in Gunicorn so even if we change the defaults, this behavior will persist in development environment.