How to debug timeout on Heroku deployment

[kurt-o-sys]

Hi all,

I had a working deployment of Hasura on Heroku. However, recently, when I startup the application, there's a timeout error, resulting in the app just not starting anymore (see logs below). The credentials, urls etc are correct, since the application has been working before.

I already had Heroku increase the timeout from 60 seconds to 120 seconds, but that doesn't help.
The postgres database is running fine (I can connect to it and read the schemas and tables)

This is my Dockerfile (updated Hasura to version 2.9.0):

$ cat Dockerfile
FROM hasura/graphql-engine:v2.9.0

# Enable the console
ENV HASURA_GRAPHQL_ENABLE_CONSOLE=true

# Enable debugging mode. It should be disabled in production.
ENV HASURA_GRAPHQL_DEV_MODE=true

# Heroku hobby tier PG has few limitations including 20 max connections
# https://devcenter.heroku.com/articles/heroku-postgres-plans#hobby-tier
ENV HASURA_GRAPHQL_PG_CONNECTIONS=15

# Change $DATABASE_URL to your heroku postgres URL if you're not using
# the primary postgres instance in your app
CMD graphql-engine \
    --database-url $DATABASE_URL \
    serve \
    --server-port $PORT

## Comment the command above and use the command below to
## enable an access-key and an auth-hook
## Recommended that you set the access-key as a environment variable in heroku
#CMD graphql-engine \
#    --database-url $DATABASE_URL \
#    serve \
#    --server-port $PORT \
#    --access-key XXXXX \
#    --auth-hook https://myapp.com/hasura-webhook
#
# Console can be enable/disabled by the env var HASURA_GRAPHQL_ENABLE_CONSOLE

Any ideas how I can find out the exact issue/how to debug it/how to solve it?

Thanks.

2022-08-07T07:36:56.535404+00:00 heroku[web.1]: Starting process with command `/bin/sh -c graphql-engine\ \ \ \ \ --database-url\ \postgres://(redacted)@ec2-108-128-201-166.eu-west-1.compute.amazonaws.com:5432/d25u4bqll5rg1a\ \ \ \ \ serve\ \ \ \ \ --server-port\ \54482`
2022-08-07T07:36:58.165375+00:00 app[web.1]: {"type":"startup","timestamp":"2022-08-07T07:36:58.164+0000","level":"info","detail":{"kind":"server_configuration","info":{"live_query_options":{"batch_size":100,"refetch_delay":1},"transaction_isolation":"ISOLATION LEVEL READ COMMITTED","plan_cache_options":{"plan_cache_size":4000},"enable_maintenance_mode":false,"enabled_log_types":["http-log","websocket-log","startup","webhook-log"],"server_host":"HostAny","enable_allowlist":false,"remote_schema_permissions":false,"log_level":"info","auth_hook_mode":null,"use_prepared_statements":true,"unauth_role":"public","stringify_numeric_types":false,"enabled_apis":["metadata","graphql","config","pgdump"],"enable_telemetry":true,"enable_console":true,"auth_hook":null,"infer_function_permissions":true,"experimental_features":[],"jwt_secret":{"audience":null,"claims_format":"json","claims_namespace":"https://hasura.io/jwt/claims","key":"<JWK REDACTED>","header":null,"type":"<TYPE REDACTED>","issuer":null},"cors_config":{"allowed_origins":"*","disabled":false,"ws_read_cookie":null},"websocket_compression_options":"NoCompression","console_assets_dir":null,"admin_secret_set":true,"port":54482,"websocket_keep_alive":"KeepAliveDelay {unKeepAliveDelay = Seconds {seconds = 5s}}"}}}
2022-08-07T07:36:58.165393+00:00 app[web.1]: {"type":"startup","timestamp":"2022-08-07T07:36:58.164+0000","level":"info","detail":{"kind":"postgres_connection","info":{"retries":1,"database_url":"postgres://(redacted)@ec2-108-128-201-166.eu-west-1.compute.amazonaws.com:5432/d25u4bqll5rg1a"}}}
2022-08-07T07:36:59.166452+00:00 app[web.1]: {"type":"startup","timestamp":"2022-08-07T07:36:58.164+0000","level":"info","detail":{"kind":"schema-sync","info":{"thread_id":"ThreadId 20","instance_id":"4d92014d-5145-4c41-8dbb-0fd24611de34","message":"listener thread started"}}}
2022-08-07T07:36:59.166471+00:00 app[web.1]: {"type":"unstructured","timestamp":"2022-08-07T07:36:58.164+0000","level":"info","detail":"Thread SchemeUpdate.listener (re)started"}
2022-08-07T07:38:57.126000+00:00 heroku[web.1]: Error R10 (Boot timeout) -> Web process failed to bind to $PORT within 120 seconds of launch
2022-08-07T07:38:57.286889+00:00 heroku[web.1]: Stopping process with SIGKILL
2022-08-07T07:38:57.444751+00:00 heroku[web.1]: Process exited with status 137
2022-08-07T07:38:58.148543+00:00 heroku[web.1]: State changed from starting to crashed

[stayradiated]

I'm currently having issues trying to get Hasura running on Heroku, this is due to the recent changes by Heroku to restrict PostgreSQL extensions to the heroku_ext schema. I haven't got a solution for this yet though...

[stayradiated]

I tried out that image, but I'm seeing the same issues unfortunately.

[stayradiated]

I finally got Hasura working with Heroku! The key changes I had to make are:

1. Need to use hasura/graphql-engine:v2.9.0-heroku.1.cli-migrations-v3 image with the HASURA_GRAPHQL_DEFAULT_EXTENSIONS_SCHEMA env var set to heroku_ext.
2. There is a bug with the Hasura v2.9.0 that was preventing Hasura from binding to the $PORT env var that Heroku injects. See issue #8770 for more details.

This is a simplified version of the Dockerfile I am using now:

FROM hasura/graphql-engine:v2.9.0-heroku.1.cli-migrations-v3

# temporary fix for https://github.com/hasura/graphql-engine/issues/8770
RUN sed -i 's/\(^\s\+\)PORT=/\1local PORT=/m'  /bin/docker-entrypoint.sh

# Heroku only allows to install extensions in the heroku_ext schema
ENV HASURA_GRAPHQL_DEFAULT_EXTENSIONS_SCHEMA=heroku_ext

# bundle metadata into Docker image (unrelated to issue with Heroku)
# https://hasura.io/docs/latest/migrations-metadata-seeds/auto-apply-migrations/
COPY ./metadata /hasura-metadata

CMD graphql-engine serve --server-port "${PORT}"

I'm not sure if that is the same issue you are experience @kurt-o-sys but maybe it might help you as well.

[kurt-o-sys]

Thanks!

I may be getting closer, but still get issues with the connection to the database. It seems --database-url is not used.
I tried different versions (with/without migrations, v2.9.0 and 2.10.0, with/without the local port fix)

2022-08-11T09:14:11.178671+00:00 heroku[web.1]: State changed from crashed to starting
2022-08-11T09:14:21.724554+00:00 heroku[web.1]: Starting process with command `/bin/sh -c graphql-engine\ \ \ \ \ --database-url\ \postgres://edxvzxubxqcanh:<REDACTED>@ec2-108-128-201-166.eu-west-1.compute.amazonaws.com:5432/d25u4bqll5rg1a\ \ \ \ \ serve\ \ \ \ \ --server-port\ \"\$\{PORT\}\"`
2022-08-11T09:14:22.567522+00:00 app[web.1]: {"timestamp":"2022-08-11T09:14:22.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"database url for migrations is set by HASURA_GRAPHQL_DATABASE_URL"}}
2022-08-11T09:14:22.569747+00:00 app[web.1]: {"timestamp":"2022-08-11T09:14:22.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"migrations server port env var is not set, defaulting to 9691"}}
2022-08-11T09:14:22.573005+00:00 app[web.1]: {"timestamp":"2022-08-11T09:14:22.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"server timeout is not set, defaulting to 30 seconds"}}
2022-08-11T09:14:22.575278+00:00 app[web.1]: {"timestamp":"2022-08-11T09:14:22.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"starting graphql engine temporarily on port 9691"}}
2022-08-11T09:14:22.581895+00:00 app[web.1]: {"timestamp":"2022-08-11T09:14:22.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"waiting 30 for 9691 to be ready"}}
2022-08-11T09:14:23.530181+00:00 app[web.1]: {"detail":{"info":{"admin_secret_set":true,"auth_hook":null,"auth_hook_mode":null,"console_assets_dir":null,"cors_config":{"allowed_origins":"*","disabled":false,"ws_read_cookie":null},"enable_allowlist":false,"enable_console":true,"enable_maintenance_mode":false,"enable_metadata_query_logging":false,"enable_telemetry":true,"enabled_apis":["metadata"],"enabled_log_types":["startup","webhook-log","http-log","websocket-log"],"events_fetch_batch_size":100,"experimental_features":[],"graceful_shutdown_timeout":60,"infer_function_permissions":true,"jwt_secret":[{"audience":null,"claims_format":"json","claims_namespace":"https://hasura.io/jwt/claims","header":null,"issuer":null,"key":"<JWK REDACTED>","type":"<TYPE REDACTED>"}],"live_query_options":{"batch_size":100,"refetch_delay":1},"log_level":"info","port":9691,"remote_schema_permissions":false,"server_host":"HostAny","stringify_numeric_types":false,"transaction_isolation":"ISOLATION LEVEL READ COMMITTED","unauth_role":"public","use_prepared_statements":true,"v1-boolean-null-collapse":false,"websocket_compression_options":"NoCompression","websocket_connection_init_timeout":"WSConnectionInitTimeout {unWSConnectionInitTimeout = Seconds {seconds = 3s}}","websocket_keep_alive":"KeepAliveDelay {unKeepAliveDelay = Seconds {seconds = 5s}}"},"kind":"server_configuration"},"level":"info","timestamp":"2022-08-11T09:14:23.529+0000","type":"startup"}
2022-08-11T09:14:23.654981+00:00 app[web.1]: {"detail":{"info":{"error":"parsing database url failed"},"kind":"postgres_connection"},"level":"info","timestamp":"2022-08-11T09:14:23.529+0000","type":"startup"}
2022-08-11T09:14:23.654983+00:00 app[web.1]: {"detail":{"message":"postgres connection failed, retrying(0)."},"level":"warn","timestamp":"2022-08-11T09:14:23.529+0000","type":"pg-client"}
2022-08-11T09:14:23.654983+00:00 app[web.1]: {"detail":{"message":"postgres connection failed, retrying(1)."},"level":"warn","timestamp":"2022-08-11T09:14:23.529+0000","type":"pg-client"}
2022-08-11T09:14:23.654984+00:00 app[web.1]: {"detail":{"info":{"code":"postgres-error","error":"connection error","internal":"connection to server on socket \"/var/run/postgresql/.s.PGSQL.5432\" failed: No such file or directory\n\tIs the server running locally and accepting connections on that socket?\n","path":"$"},"kind":"catalog_migrate"},"level":"error","timestamp":"2022-08-11T09:14:23.529+0000","type":"startup"}
2022-08-11T09:14:23.655065+00:00 app[web.1]: {"code":"postgres-error","error":"connection error","internal":"connection to server on socket \"/var/run/postgresql/.s.PGSQL.5432\" failed: No such file or directory\n\tIs the server running locally and accepting connections on that socket?\n","path":"$"}
2022-08-11T09:13:15.000000+00:00 app[api]: Build started by user ...
2022-08-11T09:14:52.931014+00:00 heroku[web.1]: Process exited with status 1
2022-08-11T09:14:52.989453+00:00 heroku[web.1]: State changed from starting to crashed
2022-08-11T09:14:52.810984+00:00 app[web.1]: {"timestamp":"2022-08-11T09:14:52.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"failed waiting for 9691, try increasing HASURA_GRAPHQL_MIGRATIONS_SERVER_TIMEOUT (default: 30)"}}

Dockerfile:

FROM hasura/graphql-engine:v2.10.0.cli-migrations-v2

# temporary fix for https://github.com/hasura/graphql-engine/issues/8770
RUN sed -i 's/\(^\s\+\)PORT=/\1local PORT=/m'  /bin/docker-entrypoint.sh

# Heroku only allows to install extensions in the heroku_ext schema
ENV HASURA_GRAPHQL_DEFAULT_EXTENSIONS_SCHEMA=heroku_ext

ENV HASURA_GRAPHQL_ENABLE_CONSOLE=true
ENV HASURA_GRAPHQL_DEV_MODE=true
ENV HASURA_GRAPHQL_PG_CONNECTIONS=15
CMD graphql-engine \
    --database-url $DATABASE_URL \
    serve \
    --server-port "${PORT}"

[kurt-o-sys]

With the normal (non-migrations) container:

2022-08-11T09:23:55.838428+00:00 app[web.1]: {"detail":{"info":{"database_url":"postgres://edxvzxubxqcanh:[email protected]:5432/d25u4bqll5rg1a","retries":1},"kind":"postgres_connection"},"level":"info","timestamp":"2022-08-11T09:23:54.836+0000","type":"startup"}
2022-08-11T09:26:02.212067+00:00 app[web.1]: {"detail":{"message":"postgres connection failed, retrying(0)."},"level":"warn","timestamp":"2022-08-11T09:26:02.211+0000","type":"pg-client"}

(When I connect to the same database_url from Hasura cloud, it does work fine)

[kurt-o-sys]

see follow-up in #8812