Worker timeout after v9 upgrade

scleriot · April 10, 2021, 8:36pm

Issue Summary

I have upgraded from Redash V8 to V9 beta, and workers timeout on server start, and I’m not able to load the web application (timeout also)

Here is my docker-compose.yml

version: "2"
x-redash-service: &redash-service
  image: redash/redash:9.0.0-beta.b42121
  depends_on:
    - postgres
    - redis
  env_file: /opt/redash/env
  restart: always
services:
  server:
    <<: *redash-service
    command: server
    ports:
      - "5000:5000"
    environment:
      REDASH_WEB_WORKERS: 4
  scheduler:
    <<: *redash-service
    command: scheduler
  scheduled_worker:
    <<: *redash-service
    command: worker
    environment:
      QUEUES: "scheduled_queries schemas"
      WORKERS_COUNT: 1
  adhoc_worker:
    <<: *redash-service
    command: worker
    environment:
      QUEUES: "queries"
      WORKERS_COUNT: 2
  worker:
    <<: *redash-service
    command: worker
    environment:
      QUEUES: "periodic emails default"
      WORKERS_COUNT: 1
  redis:
    image: redis:5.0-alpine
    restart: always
  postgres:
    image: postgres:9.6-alpine
    env_file: /opt/redash/env
    volumes:
      - /opt/redash/postgres-data:/var/lib/postgresql/data
    restart: always
  nginx:
    image: redash/nginx:latest
    ports:
      - "80:80"
    depends_on:
      - server
    links:
      - server:redash
    restart: always

Here is the output when running docker-compose up

postgres_1          | LOG:  database system was shut down at 2021-04-08 12:08:06 UTC
postgres_1          | LOG:  MultiXact member wraparound protections are now enabled
postgres_1          | LOG:  database system is ready to accept connections
postgres_1          | LOG:  autovacuum launcher started
redis_1             | 1:C 08 Apr 2021 12:09:16.103 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
redis_1             | 1:C 08 Apr 2021 12:09:16.104 # Redis version=5.0.6, bits=64, commit=00000000, modified=0, pid=1, just started
redis_1             | 1:C 08 Apr 2021 12:09:16.104 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
redis_1             | 1:M 08 Apr 2021 12:09:16.108 * Running mode=standalone, port=6379.
redis_1             | 1:M 08 Apr 2021 12:09:16.109 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
redis_1             | 1:M 08 Apr 2021 12:09:16.109 # Server initialized
redis_1             | 1:M 08 Apr 2021 12:09:16.110 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
redis_1             | 1:M 08 Apr 2021 12:09:16.110 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.
redis_1             | 1:M 08 Apr 2021 12:09:16.110 * Ready to accept connections
server_1            | [2021-04-08 12:09:19 +0000] [1] [INFO] Starting gunicorn 19.9.0
server_1            | [2021-04-08 12:09:19 +0000] [1] [INFO] Listening at: http://0.0.0.0:5000 (1)
server_1            | [2021-04-08 12:09:19 +0000] [1] [INFO] Using worker: sync
server_1            | [2021-04-08 12:09:19 +0000] [9] [INFO] Booting worker with pid: 9
server_1            | [2021-04-08 12:09:19 +0000] [10] [INFO] Booting worker with pid: 10
server_1            | [2021-04-08 12:09:19 +0000] [12] [INFO] Booting worker with pid: 12
server_1            | [2021-04-08 12:09:19 +0000] [11] [INFO] Booting worker with pid: 11
scheduled_worker_1  | Starting RQ worker...
scheduled_worker_1  | 2021-04-08 12:09:20,780 INFO RPC interface 'supervisor' initialized
scheduled_worker_1  | 2021-04-08 12:09:20,781 CRIT Server 'unix_http_server' running without any HTTP authentication checking
scheduled_worker_1  | 2021-04-08 12:09:20,785 INFO supervisord started with pid 7
worker_1            | Starting RQ worker...
adhoc_worker_1      | Starting RQ worker...
scheduler_1         | Starting RQ scheduler...
worker_1            | 2021-04-08 12:09:21,467 INFO RPC interface 'supervisor' initialized
worker_1            | 2021-04-08 12:09:21,473 CRIT Server 'unix_http_server' running without any HTTP authentication checking
worker_1            | 2021-04-08 12:09:21,475 INFO supervisord started with pid 7
adhoc_worker_1      | 2021-04-08 12:09:21,488 INFO RPC interface 'supervisor' initialized
adhoc_worker_1      | 2021-04-08 12:09:21,489 CRIT Server 'unix_http_server' running without any HTTP authentication checking
adhoc_worker_1      | 2021-04-08 12:09:21,493 INFO supervisord started with pid 7
scheduled_worker_1  | 2021-04-08 12:09:21,792 INFO spawned: 'worker_healthcheck' with pid 10
scheduled_worker_1  | 2021-04-08 12:09:21,796 INFO spawned: 'worker-0' with pid 11
worker_1            | 2021-04-08 12:09:22,479 INFO spawned: 'worker_healthcheck' with pid 10
worker_1            | 2021-04-08 12:09:22,488 INFO spawned: 'worker-0' with pid 11
adhoc_worker_1      | 2021-04-08 12:09:22,497 INFO spawned: 'worker_healthcheck' with pid 10
adhoc_worker_1      | 2021-04-08 12:09:22,520 INFO spawned: 'worker-0' with pid 11
adhoc_worker_1      | 2021-04-08 12:09:22,551 INFO spawned: 'worker-1' with pid 12
scheduled_worker_1  | 2021-04-08 12:09:22,838 INFO success: worker_healthcheck entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
scheduled_worker_1  | 2021-04-08 12:09:22,841 INFO success: worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
worker_1            | 2021-04-08 12:09:23,535 INFO success: worker_healthcheck entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
worker_1            | 2021-04-08 12:09:23,537 INFO success: worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
adhoc_worker_1      | 2021-04-08 12:09:23,603 INFO success: worker_healthcheck entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
adhoc_worker_1      | 2021-04-08 12:09:23,605 INFO success: worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
adhoc_worker_1      | 2021-04-08 12:09:23,606 INFO success: worker-1 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
scheduler_1         | [2021-04-08 12:09:45,558][PID:1][INFO][redash.tasks.schedule] Scheduling 372a63e24ac68e3028079685c6c1e8e1a38b9420 (refresh_queries) with interval 30.
scheduler_1         | [2021-04-08 12:09:45,561][PID:1][INFO][redash.tasks.schedule] Scheduling 75540cdf868e7873f5eec072177423b13b98dece (empty_schedules) with interval 3600.
scheduler_1         | [2021-04-08 12:09:45,569][PID:1][INFO][redash.tasks.schedule] Scheduling 52bcd40c254552539398db3cdb15055d4a9a536a (refresh_schemas) with interval 1800.
scheduler_1         | [2021-04-08 12:09:45,574][PID:1][INFO][redash.tasks.schedule] Scheduling c33b2b69cac2aa765fa2d2eb42301a0fc1ae774c (sync_user_details) with interval 60.
scheduler_1         | [2021-04-08 12:09:45,578][PID:1][INFO][redash.tasks.schedule] Scheduling d22541b0ed0835f429e15959feab5899a72cacea (purge_failed_jobs) with interval 86400.
scheduler_1         | [2021-04-08 12:09:45,579][PID:1][INFO][redash.tasks.schedule] Scheduling 797f4f959c6c96c738efd445b17db75742db80a9 (send_aggregated_errors) with interval 3600.
scheduler_1         | [2021-04-08 12:09:45,581][PID:1][INFO][redash.tasks.schedule] Scheduling 526f2c7f55dfe92457914cd7df02cfffe4dec877 (version_check) with interval 86400.
scheduler_1         | [2021-04-08 12:09:45,585][PID:1][INFO][redash.tasks.schedule] Scheduling e27209059575fcc17c527c47d0957cb21756e551 (cleanup_query_results) with interval 300.
scheduler_1         | [2021-04-08 12:09:45,595][PID:1][INFO][rq_scheduler.scheduler] Registering birth
server_1            | [2021-04-08 12:09:50 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:9)
server_1            | [2021-04-08 12:09:50 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:10)
server_1            | [2021-04-08 12:09:50 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:11)
server_1            | [2021-04-08 12:09:50 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:12)
server_1            | [2021-04-08 12:09:50 +0000] [11] [INFO] Worker exiting (pid: 11)
server_1            | [2021-04-08 12:09:50 +0000] [9] [INFO] Worker exiting (pid: 9)
server_1            | [2021-04-08 12:09:50 +0000] [10] [INFO] Worker exiting (pid: 10)
server_1            | [2021-04-08 12:09:50 +0000] [12] [INFO] Worker exiting (pid: 12)
server_1            | [2021-04-08 12:09:51 +0000] [13] [INFO] Booting worker with pid: 13
server_1            | [2021-04-08 12:09:51 +0000] [14] [INFO] Booting worker with pid: 14
server_1            | [2021-04-08 12:09:51 +0000] [15] [INFO] Booting worker with pid: 15
server_1            | [2021-04-08 12:09:51 +0000] [16] [INFO] Booting worker with pid: 16
worker_1            | 2021/04/08 12:10:03 [worker_healthcheck] Starting the health check for worker process Checks config: [(<class 'redash.cli.rq.WorkerHealthcheck'>, {})]
worker_1            | 2021/04/08 12:10:03 [worker_healthcheck] Installing signal handlers.
worker_1            | READY
worker_1            | 2021/04/08 12:10:03 [worker_healthcheck] Received TICK_60 event from supervisor
scheduled_worker_1  | 2021/04/08 12:10:03 [worker_healthcheck] Starting the health check for worker process Checks config: [(<class 'redash.cli.rq.WorkerHealthcheck'>, {})]
scheduled_worker_1  | 2021/04/08 12:10:03 [worker_healthcheck] Installing signal handlers.
scheduled_worker_1  | READY
scheduled_worker_1  | 2021/04/08 12:10:03 [worker_healthcheck] Received TICK_60 event from supervisor
scheduled_worker_1  | RESULT 2
scheduled_worker_1  | OKREADY
scheduled_worker_1  | 2021/04/08 12:10:03 [worker_healthcheck] Performing `RQ Worker Healthcheck` check for process name worker-0
scheduled_worker_1  | 2021/04/08 12:10:03 [worker_healthcheck] `RQ Worker Healthcheck` check succeeded for process worker-0
worker_1            | RESULT 2
worker_1            | OKREADY
worker_1            | 2021/04/08 12:10:03 [worker_healthcheck] Performing `RQ Worker Healthcheck` check for process name worker-0
worker_1            | 2021/04/08 12:10:03 [worker_healthcheck] `RQ Worker Healthcheck` check succeeded for process worker-0
worker_1            | [2021-04-08 12:10:04,377][PID:11][INFO][rq.worker] Worker rq:worker:0d6285cc67274769b6c1454fe97df75f: started, version 1.1.0
worker_1            | [2021-04-08 12:10:04,379][PID:11][INFO][rq.worker] *** Listening on periodic, emails, default...
worker_1            | [2021-04-08 12:10:04,382][PID:11][INFO][rq.worker] Cleaning registries for queue: periodic
worker_1            | [2021-04-08 12:10:04,402][PID:11][INFO][rq.worker] Cleaning registries for queue: emails
worker_1            | [2021-04-08 12:10:04,416][PID:11][INFO][rq.worker] Cleaning registries for queue: default
worker_1            | [2021-04-08 12:10:04,457][PID:11][INFO][rq.worker] periodic: 372a63e24ac68e3028079685c6c1e8e1a38b9420
scheduled_worker_1  | [2021-04-08 12:10:04,485][PID:11][INFO][rq.worker] Worker rq:worker:2f851ea80fb9427f9c46084c3d3c9a52: started, version 1.1.0
scheduled_worker_1  | [2021-04-08 12:10:04,493][PID:11][INFO][rq.worker] *** Listening on scheduled_queries, schemas...
scheduled_worker_1  | [2021-04-08 12:10:04,497][PID:11][INFO][rq.worker] Cleaning registries for queue: scheduled_queries
scheduled_worker_1  | [2021-04-08 12:10:04,502][PID:11][INFO][rq.worker] Cleaning registries for queue: schemas
worker_1            | [2021-04-08 12:10:04,506][PID:20][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_queries job.id=372a63e24ac68e3028079685c6c1e8e1a38b9420 Refreshing queries...
worker_1            | [2021-04-08 12:10:04,709][PID:20][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_queries job.id=372a63e24ac68e3028079685c6c1e8e1a38b9420 Done refreshing queries: {'outdated_queries_count': 0, 'last_refresh_at': 1617883804.6975257, 'query_ids': '[]'}
worker_1            | [2021-04-08 12:10:04,722][PID:20][INFO][rq.worker] periodic: Job OK (372a63e24ac68e3028079685c6c1e8e1a38b9420)
worker_1            | [2021-04-08 12:10:04,723][PID:20][INFO][rq.worker] Result is kept for 600 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
worker_1            | [2021-04-08 12:10:04,754][PID:11][INFO][rq.worker] periodic: 526f2c7f55dfe92457914cd7df02cfffe4dec877
worker_1            | [2021-04-08 12:10:04,790][PID:21][INFO][root] Performing version check.
worker_1            | [2021-04-08 12:10:04,791][PID:21][INFO][root] Current version: 9.0.0-beta
worker_1            | [2021-04-08 12:10:05,771][PID:21][INFO][root] Latest version: 8.0.0 (newer: False)
worker_1            | [2021-04-08 12:10:05,789][PID:21][INFO][rq.worker] periodic: Job OK (526f2c7f55dfe92457914cd7df02cfffe4dec877)
worker_1            | [2021-04-08 12:10:05,791][PID:21][INFO][rq.worker] Result is kept for 172800 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
worker_1            | [2021-04-08 12:10:05,826][PID:11][INFO][rq.worker] periodic: 52bcd40c254552539398db3cdb15055d4a9a536a
worker_1            | [2021-04-08 12:10:05,869][PID:24][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schemas job.id=52bcd40c254552539398db3cdb15055d4a9a536a task=refresh_schemas state=start
scheduled_worker_1  | [2021-04-08 12:10:05,972][PID:11][INFO][rq.worker] schemas: b5c1eafd-d484-4d66-b683-fc5cc9b093f2
worker_1            | [2021-04-08 12:10:05,997][PID:24][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schemas job.id=52bcd40c254552539398db3cdb15055d4a9a536a task=refresh_schemas state=finish total_runtime=0.13
worker_1            | [2021-04-08 12:10:06,006][PID:24][INFO][rq.worker] periodic: Job OK (52bcd40c254552539398db3cdb15055d4a9a536a)
worker_1            | [2021-04-08 12:10:06,008][PID:24][INFO][rq.worker] Result is kept for 3600 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
worker_1            | [2021-04-08 12:10:06,051][PID:11][INFO][rq.worker] periodic: 75540cdf868e7873f5eec072177423b13b98dece
worker_1            | [2021-04-08 12:10:06,099][PID:25][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.empty_schedules job.id=75540cdf868e7873f5eec072177423b13b98dece Deleting schedules of past scheduled queries...
scheduled_worker_1  | [2021-04-08 12:10:06,124][PID:20][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=b5c1eafd-d484-4d66-b683-fc5cc9b093f2 task=refresh_schema state=start ds_id=2
worker_1            | [2021-04-08 12:10:06,253][PID:25][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.empty_schedules job.id=75540cdf868e7873f5eec072177423b13b98dece Deleted 0 schedules.
worker_1            | [2021-04-08 12:10:06,265][PID:25][INFO][rq.worker] periodic: Job OK (75540cdf868e7873f5eec072177423b13b98dece)
worker_1            | [2021-04-08 12:10:06,267][PID:25][INFO][rq.worker] Result is kept for 7200 seconds
worker_1            | [2021-04-08 12:10:06,298][PID:11][INFO][rq.worker] periodic: 797f4f959c6c96c738efd445b17db75742db80a9
worker_1            | [2021-04-08 12:10:06,346][PID:26][INFO][rq.worker] periodic: Job OK (797f4f959c6c96c738efd445b17db75742db80a9)
worker_1            | [2021-04-08 12:10:06,347][PID:26][INFO][rq.worker] Result is kept for 7200 seconds
worker_1            | [2021-04-08 12:10:06,372][PID:11][INFO][rq.worker] periodic: c33b2b69cac2aa765fa2d2eb42301a0fc1ae774c
worker_1            | [2021-04-08 12:10:06,435][PID:27][INFO][rq.worker] periodic: Job OK (c33b2b69cac2aa765fa2d2eb42301a0fc1ae774c)
worker_1            | [2021-04-08 12:10:06,437][PID:27][INFO][rq.worker] Result is kept for 120 seconds
worker_1            | [2021-04-08 12:10:06,465][PID:11][INFO][rq.worker] periodic: d22541b0ed0835f429e15959feab5899a72cacea
worker_1            | [2021-04-08 12:10:06,522][PID:28][INFO][rq.worker] periodic: Job OK (d22541b0ed0835f429e15959feab5899a72cacea)
worker_1            | [2021-04-08 12:10:06,525][PID:28][INFO][rq.worker] Result is kept for 172800 seconds
scheduled_worker_1  | [2021-04-08 12:10:06,570][PID:20][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=b5c1eafd-d484-4d66-b683-fc5cc9b093f2 task=refresh_schema state=finished ds_id=2 runtime=0.43
worker_1            | [2021-04-08 12:10:06,569][PID:11][INFO][rq.worker] periodic: e27209059575fcc17c527c47d0957cb21756e551
scheduled_worker_1  | [2021-04-08 12:10:06,583][PID:20][INFO][rq.worker] schemas: Job OK (b5c1eafd-d484-4d66-b683-fc5cc9b093f2)
scheduled_worker_1  | [2021-04-08 12:10:06,585][PID:20][INFO][rq.worker] Result is kept for 500 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
worker_1            | [2021-04-08 12:10:06,618][PID:29][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.cleanup_query_results job.id=e27209059575fcc17c527c47d0957cb21756e551 Running query results clean up (removing maximum of 100 unused results, that are 7 days old or more)
scheduled_worker_1  | [2021-04-08 12:10:06,631][PID:11][INFO][rq.worker] schemas: cbe24446-d956-4b7f-aa54-1676fe28d322
worker_1            | [2021-04-08 12:10:06,764][PID:29][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.cleanup_query_results job.id=e27209059575fcc17c527c47d0957cb21756e551 Deleted 0 unused query results.
worker_1            | [2021-04-08 12:10:06,768][PID:29][INFO][rq.worker] periodic: Job OK (e27209059575fcc17c527c47d0957cb21756e551)
worker_1            | [2021-04-08 12:10:06,769][PID:29][INFO][rq.worker] Result is kept for 600 seconds
scheduled_worker_1  | [2021-04-08 12:10:06,809][PID:22][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=cbe24446-d956-4b7f-aa54-1676fe28d322 task=refresh_schema state=start ds_id=3
scheduled_worker_1  | [2021-04-08 12:10:06,822][PID:22][WARNING][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=cbe24446-d956-4b7f-aa54-1676fe28d322 Failed refreshing schema for the data source: Google Sheets DS
scheduled_worker_1  | Traceback (most recent call last):
scheduled_worker_1  |   File "/app/redash/tasks/queries/maintenance.py", line 143, in refresh_schema
scheduled_worker_1  |     ds.get_schema(refresh=True)
scheduled_worker_1  |   File "/app/redash/models/__init__.py", line 196, in get_schema
scheduled_worker_1  |     schema = query_runner.get_schema(get_stats=refresh)
scheduled_worker_1  |   File "/app/redash/query_runner/__init__.py", line 175, in get_schema
scheduled_worker_1  |     raise NotSupported()
scheduled_worker_1  | redash.query_runner.NotSupported
scheduled_worker_1  | [2021-04-08 12:10:06,844][PID:22][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=cbe24446-d956-4b7f-aa54-1676fe28d322 task=refresh_schema state=failed ds_id=3 runtime=0.02
scheduled_worker_1  | [2021-04-08 12:10:06,849][PID:22][INFO][rq.worker] schemas: Job OK (cbe24446-d956-4b7f-aa54-1676fe28d322)
scheduled_worker_1  | [2021-04-08 12:10:06,852][PID:22][INFO][rq.worker] Result is kept for 500 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
scheduled_worker_1  | [2021-04-08 12:10:06,882][PID:11][INFO][rq.worker] schemas: f3bf0030-7926-4a89-a45f-77193468fb32
scheduled_worker_1  | [2021-04-08 12:10:07,000][PID:23][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=f3bf0030-7926-4a89-a45f-77193468fb32 task=refresh_schema state=start ds_id=4
scheduled_worker_1  | [2021-04-08 12:10:07,002][PID:23][WARNING][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=f3bf0030-7926-4a89-a45f-77193468fb32 Failed refreshing schema for the data source: Licenses
scheduled_worker_1  | Traceback (most recent call last):
scheduled_worker_1  |   File "/app/redash/tasks/queries/maintenance.py", line 143, in refresh_schema
scheduled_worker_1  |     ds.get_schema(refresh=True)
scheduled_worker_1  |   File "/app/redash/models/__init__.py", line 196, in get_schema
scheduled_worker_1  |     schema = query_runner.get_schema(get_stats=refresh)
scheduled_worker_1  |   File "/app/redash/query_runner/__init__.py", line 175, in get_schema
scheduled_worker_1  |     raise NotSupported()
scheduled_worker_1  | redash.query_runner.NotSupported
scheduled_worker_1  | [2021-04-08 12:10:07,009][PID:23][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=f3bf0030-7926-4a89-a45f-77193468fb32 task=refresh_schema state=failed ds_id=4 runtime=0.01
scheduled_worker_1  | [2021-04-08 12:10:07,016][PID:23][INFO][rq.worker] schemas: Job OK (f3bf0030-7926-4a89-a45f-77193468fb32)
scheduled_worker_1  | [2021-04-08 12:10:07,018][PID:23][INFO][rq.worker] Result is kept for 500 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
scheduled_worker_1  | [2021-04-08 12:10:07,046][PID:11][INFO][rq.worker] schemas: 2c2013c4-00b7-4e5c-a3ed-d83db6695a22
scheduled_worker_1  | [2021-04-08 12:10:07,167][PID:24][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=2c2013c4-00b7-4e5c-a3ed-d83db6695a22 task=refresh_schema state=start ds_id=1
scheduled_worker_1  | [2021-04-08 12:10:07,399][PID:24][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=2c2013c4-00b7-4e5c-a3ed-d83db6695a22 task=refresh_schema state=finished ds_id=1 runtime=0.23
scheduled_worker_1  | [2021-04-08 12:10:07,409][PID:24][INFO][rq.worker] schemas: Job OK (2c2013c4-00b7-4e5c-a3ed-d83db6695a22)
scheduled_worker_1  | [2021-04-08 12:10:07,411][PID:24][INFO][rq.worker] Result is kept for 500 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
scheduled_worker_1  | [2021-04-08 12:10:07,442][PID:11][INFO][rq.worker] schemas: c68a6414-ca6d-49c4-9842-84e3bd75caab
scheduled_worker_1  | [2021-04-08 12:10:07,558][PID:26][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=c68a6414-ca6d-49c4-9842-84e3bd75caab task=refresh_schema state=start ds_id=5
scheduled_worker_1  | [2021-04-08 12:10:07,579][PID:26][WARNING][googleapiclient.discovery_cache] file_cache is unavailable when using oauth2client >= 4.0.0 or google-auth
scheduled_worker_1  | Traceback (most recent call last):
scheduled_worker_1  |   File "/usr/local/lib/python3.7/site-packages/googleapiclient/discovery_cache/__init__.py", line 36, in autodetect
scheduled_worker_1  |     from google.appengine.api import memcache
scheduled_worker_1  | ModuleNotFoundError: No module named 'google.appengine'
scheduled_worker_1  | 
scheduled_worker_1  | During handling of the above exception, another exception occurred:
scheduled_worker_1  | 
scheduled_worker_1  | Traceback (most recent call last):
scheduled_worker_1  |   File "/usr/local/lib/python3.7/site-packages/googleapiclient/discovery_cache/file_cache.py", line 33, in <module>
scheduled_worker_1  |     from oauth2client.contrib.locked_file import LockedFile
scheduled_worker_1  | ModuleNotFoundError: No module named 'oauth2client.contrib.locked_file'
scheduled_worker_1  | 
scheduled_worker_1  | During handling of the above exception, another exception occurred:
scheduled_worker_1  | 
scheduled_worker_1  | Traceback (most recent call last):
scheduled_worker_1  |   File "/usr/local/lib/python3.7/site-packages/googleapiclient/discovery_cache/file_cache.py", line 37, in <module>
scheduled_worker_1  |     from oauth2client.locked_file import LockedFile
scheduled_worker_1  | ModuleNotFoundError: No module named 'oauth2client.locked_file'
scheduled_worker_1  | 
scheduled_worker_1  | During handling of the above exception, another exception occurred:
scheduled_worker_1  | 
scheduled_worker_1  | Traceback (most recent call last):
scheduled_worker_1  |   File "/usr/local/lib/python3.7/site-packages/googleapiclient/discovery_cache/__init__.py", line 41, in autodetect
scheduled_worker_1  |     from . import file_cache
scheduled_worker_1  |   File "/usr/local/lib/python3.7/site-packages/googleapiclient/discovery_cache/file_cache.py", line 41, in <module>
scheduled_worker_1  |     'file_cache is unavailable when using oauth2client >= 4.0.0 or google-auth')
scheduled_worker_1  | ImportError: file_cache is unavailable when using oauth2client >= 4.0.0 or google-auth
scheduled_worker_1  | [2021-04-08 12:10:07,586][PID:26][INFO][googleapiclient.discovery] URL being requested: GET https://www.googleapis.com/discovery/v1/apis/bigquery/v2/rest
scheduled_worker_1  | [2021-04-08 12:10:07,587][PID:26][INFO][oauth2client.transport] Attempting refresh to obtain initial access_token
scheduled_worker_1  | [2021-04-08 12:10:07,600][PID:26][INFO][oauth2client.client] Refreshing access_token
scheduled_worker_1  | [2021-04-08 12:10:08,005][PID:26][INFO][googleapiclient.discovery] URL being requested: GET https://bigquery.googleapis.com/bigquery/v2/projects/finance-analytics-305218/datasets?alt=json
scheduled_worker_1  | [2021-04-08 12:10:08,386][PID:26][INFO][googleapiclient.discovery] URL being requested: GET https://bigquery.googleapis.com/bigquery/v2/projects/finance-analytics-305218/datasets/chargebee/tables?alt=json
scheduled_worker_1  | [2021-04-08 12:10:08,543][PID:26][INFO][googleapiclient.discovery] URL being requested: GET https://bigquery.googleapis.com/bigquery/v2/projects/finance-analytics-305218/datasets/chargebee/tables/invoices?alt=json
scheduled_worker_1  | [2021-04-08 12:10:08,737][PID:26][INFO][googleapiclient.discovery] URL being requested: GET https://bigquery.googleapis.com/bigquery/v2/projects/finance-analytics-305218/datasets/chargebee/tables/subscriptions?alt=json
scheduled_worker_1  | [2021-04-08 12:10:08,908][PID:26][INFO][googleapiclient.discovery] URL being requested: GET https://bigquery.googleapis.com/bigquery/v2/projects/finance-analytics-305218/datasets/chargebee_test/tables?alt=json
scheduled_worker_1  | [2021-04-08 12:10:09,075][PID:26][INFO][googleapiclient.discovery] URL being requested: GET https://bigquery.googleapis.com/bigquery/v2/projects/finance-analytics-305218/datasets/chargebee_test/tables/invoices?alt=json
scheduled_worker_1  | [2021-04-08 12:10:09,274][PID:26][INFO][rq.job.redash.tasks.queries.maintenance] job.func_name=redash.tasks.queries.maintenance.refresh_schema job.id=c68a6414-ca6d-49c4-9842-84e3bd75caab task=refresh_schema state=finished ds_id=5 runtime=1.71
scheduled_worker_1  | [2021-04-08 12:10:09,294][PID:26][INFO][rq.worker] schemas: Job OK (c68a6414-ca6d-49c4-9842-84e3bd75caab)
scheduled_worker_1  | [2021-04-08 12:10:09,298][PID:26][INFO][rq.worker] Result is kept for 500 seconds
postgres_1          | LOG:  unexpected EOF on client connection with an open transaction
worker_1            | 2021-04-08 12:10:15,377 INFO exited: worker-0 (terminated by SIGKILL; not expected)
worker_1            | 2021-04-08 12:10:15,391 INFO spawned: 'worker-0' with pid 30
worker_1            | 2021-04-08 12:10:16,397 INFO success: worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
server_1            | [2021-04-08 12:10:21 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:13)
server_1            | [2021-04-08 12:10:21 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:14)
server_1            | [2021-04-08 12:10:21 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:15)
server_1            | [2021-04-08 12:10:21 +0000] [1] [CRITICAL] WORKER TIMEOUT (pid:16)

Steps to Reproduce

Setup a Redash V8 server
Server works great
Upgrade to V9
Web pages are not loading and workers timeout

Reproduced with a fresh install (but existing database)

Technical details:

Redash Version: 9.0.0-beta.b42121
Browser/OS: Chrome / Linux
How did you install Redash: Docker

k4s1m · April 10, 2021, 8:43pm

What kind of data sources have you connected to Redash? I see two errors here:

Some data source doesn’t have a refresh_schema() method definition. So it raises an exception when the application boots because Redash kicks off a schema refresh job whenever the application starts.
Some dependency for connecting with Google AppEngine was not installed properly which causes a separate error when trying to refresh the schema here.

scleriot · April 11, 2021, 7:29am

The following datasources were enabled in V8:

MySQL
Google Big Query
Google Sheet

▼Categories

▼Tags

Worker timeout after v9 upgrade

Issue Summary

Steps to Reproduce

Technical details: