`superset_app` timeout error when running locally

rudokemper commented 2 months ago

I'm encountering an issue where my superset_app container is terminated due to a timeout error when running locally (using docker-compose -f docker-compose-non-dev.yml up). It does not seem related to recent changes like 16e90704a8e6fba31e0b4032aae176b96a162342 or a2e4c7dc3997a148e4984f33a1e3abd032592e25, as the same error occurs when running using the codebase from prior commits.

Logs:

superset_init         | 
superset_init         | [notice] A new release of pip is available: 23.0.1 -> 24.2
superset_init         | [notice] To update, run: pip install --upgrade pip
superset_init         | 
superset_init         | ######################################################################
superset_init         | 
superset_init         | 
superset_init         | Init Step 1/3 [Starting] -- Applying DB migrations
superset_init         | 
superset_init         | 
superset_init         | ######################################################################
superset_init         | 
superset_worker_beat  | 
superset_worker_beat  | [notice] A new release of pip is available: 23.0.1 -> 24.2
superset_worker_beat  | [notice] To update, run: pip install --upgrade pip
superset_worker       | 
superset_worker       | [notice] A new release of pip is available: 23.0.1 -> 24.2
superset_worker       | [notice] To update, run: pip install --upgrade pip
superset_app          | 
superset_app          | [notice] A new release of pip is available: 23.0.1 -> 24.2
superset_app          | [notice] To update, run: pip install --upgrade pip
superset_worker_beat  | Starting Celery beat...
superset_worker       | Starting Celery worker...
superset_app          | Starting web app...
superset_app          | [2024-08-22 20:18:07 +0000] [12] [INFO] Starting gunicorn 20.1.0
superset_app          | [2024-08-22 20:18:07 +0000] [12] [INFO] Listening at: http://0.0.0.0:8088 (12)
superset_app          | [2024-08-22 20:18:07 +0000] [12] [INFO] Using worker: gthread
superset_app          | [2024-08-22 20:18:07 +0000] [13] [INFO] Booting worker with pid: 13
superset_worker_beat  | 2024-08-22 20:18:09,420:INFO:superset.utils.logging_configurator:logging was configured successfully
superset_worker_beat  | 2024-08-22 20:18:09,423:INFO:root:Configured event logger of type <class 'superset.utils.log.DBEventLogger'>
superset_worker_beat  | /usr/local/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
superset_worker_beat  |   warnings.warn(
superset_app          | 2024-08-22 20:18:09,451:INFO:superset.utils.logging_configurator:logging was configured successfully
superset_app          | 2024-08-22 20:18:09,457:INFO:root:Configured event logger of type <class 'superset.utils.log.DBEventLogger'>
superset_app          | /usr/local/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
superset_app          |   warnings.warn(
superset_worker       | 2024-08-22 20:18:09,721:INFO:superset.utils.logging_configurator:logging was configured successfully
superset_worker       | 2024-08-22 20:18:09,723:INFO:root:Configured event logger of type <class 'superset.utils.log.DBEventLogger'>
superset_worker       | /usr/local/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
superset_worker       |   warnings.warn(
superset_init         | 2024-08-22 20:18:09,915:INFO:superset.utils.logging_configurator:logging was configured successfully
superset_init         | 2024-08-22 20:18:09,921:INFO:root:Configured event logger of type <class 'superset.utils.log.DBEventLogger'>
superset_init         | /usr/local/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
superset_init         |   warnings.warn(
superset_app          | [2024-08-22 20:19:08 +0000] [12] [CRITICAL] WORKER TIMEOUT (pid:13)
superset_app          | [2024-08-22 20:19:09 +0000] [12] [WARNING] Worker with pid 13 was terminated due to signal 9
superset_app          | [2024-08-22 20:19:09 +0000] [36] [INFO] Booting worker with pid: 36
superset_app          | 2024-08-22 20:19:10,378:INFO:superset.utils.logging_configurator:logging was configured successfully
superset_app          | 2024-08-22 20:19:10,381:INFO:root:Configured event logger of type <class 'superset.utils.log.DBEventLogger'>
superset_app          | /usr/local/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
superset_app          |   warnings.warn(
superset_app          | [2024-08-22 20:20:09 +0000] [12] [CRITICAL] WORKER TIMEOUT (pid:36)
superset_app          | [2024-08-22 20:20:10 +0000] [12] [WARNING] Worker with pid 36 was terminated due to signal 9
superset_app          | [2024-08-22 20:20:10 +0000] [58] [INFO] Booting worker with pid: 58
superset_app          | 2024-08-22 20:20:11,784:INFO:superset.utils.logging_configurator:logging was configured successfully
superset_app          | 2024-08-22 20:20:11,787:INFO:root:Configured event logger of type <class 'superset.utils.log.DBEventLogger'>
superset_app          | /usr/local/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
superset_app          |   warnings.warn(
superset_app          | [2024-08-22 20:21:11 +0000] [12] [CRITICAL] WORKER TIMEOUT (pid:58)
superset_app          | [2024-08-22 20:21:12 +0000] [12] [WARNING] Worker with pid 58 was terminated due to signal 9
superset_app          | [2024-08-22 20:21:12 +0000] [81] [INFO] Booting worker with pid: 81
superset_app          | 2024-08-22 20:21:13,076:INFO:superset.utils.logging_configurator:logging was configured successfully
superset_app          | 2024-08-22 20:21:13,080:INFO:root:Configured event logger of type <class 'superset.utils.log.DBEventLogger'>
superset_app          | /usr/local/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.

Signal 9 termination is a SIGKILL, so it seems like the worker is being terminated because of reaching a memory storage limit.

I experimented with increasing memory limits and reservations in the docker compose config like this:

services:
  superset:
    env_file: docker/.env-non-dev
    image: *superset-image
    container_name: superset_app
    command: ["/app/docker/docker-bootstrap.sh", "app-gunicorn"]
    user: "root"
    restart: unless-stopped
    ports:
      - "8080:8088"
    depends_on: *superset-depends-on
    deploy:
      resources:
        limits:
          memory: 4g
        reservations:
          memory: 2g

A bit unsure on next steps so logging this for now. It is blocking me from testing changes to our Superset deployment locally before deploying to production.

IamJeffG commented 2 months ago

FWIW I do not see this when I run locally from main branch, with the following changes to docker-compose-non-dev.yml:

x-superset-image: &superset-image guardiancr.azurecr.io/superset-docker:3.0.3_20240822-1541
and uncomment the db service and volumes

I do see the "UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified." one time only, from the superset_init service of all places, but that init does finish.

IamJeffG commented 2 months ago

As far as memory usage when I run locally, I've got 40GB and superset_app uses 0.5% of that and superset_worker uses 2% of that (on first start, without me using the app)

rudokemper commented 2 months ago

Thanks, that's helpful. I have also seen the UserWarning in the prod server logs (but similarly, it finishes).

I have made the same changes, but nevertheless get this error. But at least now I know it's a local issue on my end. I'll try to figure it out, and leave a solution in documentation if it's relevant enough.

rudokemper commented 2 months ago

Well! I tried to run again today in the interest of diagnosing any memory limits on my local Docker setup, and this time it worked just fine. Maybe my RAM was being exhausted by other processes running yesterday? No idea as of yet. But I'm now unblocked and it's sufficiently clear that it's just a local problem on my computer to close this issue here :shrug:

ConservationMetrics / superset-deployment

`superset_app` timeout error when running locally #32