hasura / hasura/graphql-engine

Hasura docker app crashes on Heroku on deployment - graphql-engine serve commands binds port before ready

Open
#7,474 3 comments 0 reactions 0 assignees View on GitHub
Dominant language
TypeScript
Stars
32.1k
Forks
3k
PR merge metrics
PR metrics pending

Description

Whenever we do a new deploy of hasura, our app 'crashes' on heroku.

We believe this is due to the fact that the hasura image is binding to the dyno's port before hasura is ready to serve. Therefore Heroku will start redirecting traffic to the hasura even though hasura is still applying metadata and booting.

We've spoken to Heroku about this, and they said dynos will also start serve as soon as the port is binded.

Is there a command to start hasura and apply metadata, before it binds to the port / starts serving traffic? Or could the docker image be updated to only bind after hasura is ready to serve?

Here are our logs when booting - It basically just continues with the boot process but we get ` at=error code=H10 desc="App crashed"` repeatedly for about 2-3 minutes until it's ready.

```
26 Aug 2021 10:52:50.160134 <133>1 2021-08-25T22:52:49.414471+00:00 app api - - Release v343 created by user *****@*****
26 Aug 2021 10:52:50.185189 <133>1 2021-08-25T22:52:49.414471+00:00 app api - - Set COMMIT_SHA, COMMIT_0e6f61be92249855a26134e1867ae1d5e7584f36 config vars by user *****@*****
26 Aug 2021 10:52:50.904107 <134>1 2021-08-25T22:52:50.536149+00:00 heroku web.1 - - Restarting
26 Aug 2021 10:52:53.632192 <134>1 2021-08-25T22:52:53.248981+00:00 heroku web.1 - - Starting process with command `/bin/sh -c graphql-engine\ serve\ --server-port\ \"\$\{PORT\}\"`
26 Aug 2021 10:52:54.999331 <158>1 2021-08-25T22:52:54.630806+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=*******.herokuapp.com request_id=3fdba7d3-85b8-4802-9cc6-f92abb356172 fwd="122.58.94.185" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:55.162333 <158>1 2021-08-25T22:52:54.633517+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=*******.herokuapp.com request_id=b95abaf0-b107-4327-9c75-8acc44170351 fwd="101.100.129.151" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:55.598280 <190>1 2021-08-25T22:52:54.879801+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:54.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"migrations server port env var is not set, defaulting to 9691"}}
26 Aug 2021 10:52:55.598270 <190>1 2021-08-25T22:52:54.880569+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:54.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"server timeout is not set, defaulting to 30 seconds"}}
26 Aug 2021 10:52:55.598267 <190>1 2021-08-25T22:52:54.881394+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:54.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"starting graphql engine temporarily on port 9691"}}
26 Aug 2021 10:52:55.598250 <190>1 2021-08-25T22:52:54.882275+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:54.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"waiting 30 for 9691 to be ready"}}
26 Aug 2021 10:52:56.044333 <158>1 2021-08-25T22:52:55.462549+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=*******.herokuapp.com request_id=2eb50893-9e7e-46e1-ae5e-862a3bf496d6 fwd="158.140.247.176" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:56.0901402 <190>1 2021-08-25T22:52:55.687592+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:55.686+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","query-log"],"server_host":"HostAny","enable_allowlist":false,"remote_schema_permissions":false,"log_level":"info","auth_hook_mode":null,"use_prepared_statements":true,"unauth_role":null,"stringify_numeric_types":false,"v1-boolean-null-collapse":false,"graceful_shutdown_timeout":60,"enabled_apis":["metadata"],"enable_telemetry":false,"enable_console":true,"auth_hook":null,"infer_function_permissions":true,"experimental_features":[],"events_fetch_batch_size":100,"jwt_secret":{"audience":null,"claims_format":"json","claims_namespace":"https://hasura.io/jwt/claims","key":"","header":null,"type":"","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":9691,"websocket_keep_alive":"KeepAliveDelay {unKeepAliveDelay = Seconds {seconds = 5s}}"}}}
26 Aug 2021 10:52:56.090337 <190>1 2021-08-25T22:52:55.687608+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:55.686+0000","level":"info","detail":{"kind":"postgres_connection","info":{"retries":1,"database_url":"postgres://********:...@************.compute-1.amazonaws.com:5432/************"}}}
26 Aug 2021 10:52:56.317331 <158>1 2021-08-25T22:52:55.829049+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=************.herokuapp.com request_id=c1a88d49-14d3-4404-a257-79c6d1cf5d45 fwd="122.58.94.185" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:56.441192 <134>1 2021-08-25T22:52:56.018749+00:00 heroku web.1 - - Starting process with command `/bin/sh -c graphql-engine\ serve\ --server-port\ \"\$\{PORT\}\"`
26 Aug 2021 10:52:56.469333 <158>1 2021-08-25T22:52:55.856205+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=************.herokuapp.com request_id=1adb0d68-721e-47c5-8428-dc6b5b465ab7 fwd="101.100.129.151" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:57.882333 <158>1 2021-08-25T22:52:57.302547+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=************.herokuapp.com request_id=2ff7cbe4-7446-43a9-b940-5f4ee827e01b fwd="101.100.129.151" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:58.143331 <158>1 2021-08-25T22:52:57.626327+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=************.herokuapp.com request_id=2dbf2ce4-1eac-446a-9f20-ff9f837220bc fwd="122.58.94.185" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:58.320227 <190>1 2021-08-25T22:52:57.690652+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread asyncActionsProcessor (re)started"}
26 Aug 2021 10:52:58.320221 <190>1 2021-08-25T22:52:57.690655+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread checkForUpdates (re)started"}
26 Aug 2021 10:52:58.320274 <190>1 2021-08-25T22:52:57.690657+00:00 app web.1 - - {"type":"schema-sync-thread","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"thread_type":"processor","info":{"currentVersion":0,"latestResourceVersion":205}}}
26 Aug 2021 10:52:58.320239 <190>1 2021-08-25T22:52:57.690676+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread asyncActionSubscriptionsProcessor (re)started"}
26 Aug 2021 10:52:58.320228 <190>1 2021-08-25T22:52:57.691063+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread runCronEventsGenerator (re)started"}
26 Aug 2021 10:52:58.320274 <190>1 2021-08-25T22:52:57.691088+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"kind":"catalog_migrate","info":"Already at the latest catalog version (46); nothing to do."}}
26 Aug 2021 10:52:58.320276 <190>1 2021-08-25T22:52:57.691088+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"kind":"schema-sync","info":"Schema sync enabled. Polling at Milliseconds {milliseconds = 1s}"}}
26 Aug 2021 10:52:58.320326 <190>1 2021-08-25T22:52:57.691089+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"kind":"schema-sync","info":{"thread_id":"ThreadId 26","instance_id":"8bb8f3d1-cb66-40d5-9163-0f1d3cdea5c2","message":"listener thread started"}}}
26 Aug 2021 10:52:58.320327 <190>1 2021-08-25T22:52:57.691089+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"kind":"schema-sync","info":{"thread_id":"ThreadId 28","instance_id":"8bb8f3d1-cb66-40d5-9163-0f1d3cdea5c2","message":"processor thread started"}}}
26 Aug 2021 10:52:58.320231 <190>1 2021-08-25T22:52:57.691089+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"kind":"event_triggers","info":"starting workers"}}
26 Aug 2021 10:52:58.320232 <190>1 2021-08-25T22:52:57.69109+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"kind":"scheduled_triggers","info":"preparing data"}}
26 Aug 2021 10:52:58.320262 <190>1 2021-08-25T22:52:57.69109+00:00 app web.1 - - {"type":"startup","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":{"kind":"server","info":{"time_taken":1.296780243,"message":"starting API server"}}}
26 Aug 2021 10:52:58.320227 <190>1 2021-08-25T22:52:57.691104+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread SchemeUpdate.listener (re)started"}
26 Aug 2021 10:52:58.320215 <190>1 2021-08-25T22:52:57.691105+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread ourIdleGC (re)started"}
26 Aug 2021 10:52:58.320228 <190>1 2021-08-25T22:52:57.691105+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread SchemeUpdate.processor (re)started"}
26 Aug 2021 10:52:58.320223 <190>1 2021-08-25T22:52:57.691105+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread processEventQueue (re)started"}
26 Aug 2021 10:52:58.320230 <190>1 2021-08-25T22:52:57.691106+00:00 app web.1 - - {"type":"unstructured","timestamp":"2021-08-25T22:52:56.919+0000","level":"info","detail":"Thread processScheduledTriggers (re)started"}
26 Aug 2021 10:52:58.320237 <190>1 2021-08-25T22:52:57.894884+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:57.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"port 9691 is ready"}}
26 Aug 2021 10:52:58.320301 <190>1 2021-08-25T22:52:57.900469+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:57.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"env var HASURA_GRAPHQL_MIGRATIONS_DIR is not set, defaulting to /hasura-migrations"}}
26 Aug 2021 10:52:58.320297 <190>1 2021-08-25T22:52:57.907352+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:57.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"env var HASURA_GRAPHQL_METADATA_DIR is not set, defaulting to /hasura-metadata"}}
26 Aug 2021 10:52:58.320256 <190>1 2021-08-25T22:52:57.912438+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:57.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-apply","info":"applying metadata from /hasura-metadata"}}
26 Aug 2021 10:52:58.794333 <158>1 2021-08-25T22:52:58.296366+00:00 heroku router - - at=error code=H10 desc="App crashed" method=GET path="/v1/graphql" host=************.herokuapp.com request_id=67a64154-06c1-4b91-a377-954eeafdf8ab fwd="158.140.247.176" dyno= connect= service= status=503 bytes= protocol=https
26 Aug 2021 10:52:58.861280 <190>1 2021-08-25T22:52:58.177586+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:58.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"migrations server port env var is not set, defaulting to 9691"}}
26 Aug 2021 10:52:58.861270 <190>1 2021-08-25T22:52:58.178465+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:58.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"server timeout is not set, defaulting to 30 seconds"}}
26 Aug 2021 10:52:58.861267 <190>1 2021-08-25T22:52:58.179496+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:58.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"starting graphql engine temporarily on port 9691"}}
26 Aug 2021 10:52:58.861250 <190>1 2021-08-25T22:52:58.180424+00:00 app web.1 - - {"timestamp":"2021-08-25T22:52:58.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"waiting 30 for 9691 to be ready"}}
26 Aug 2021 10:52:59.002367 <190>1 2021-08-25T22:52:58.601517+00:00 app web.1 - - {"level":"info","msg":"Help us improve Hasura! The cli collects anonymized usage stats which\nallow us to keep improving Hasura at warp speed. To opt-out or read more,\nvisit https://hasura.io/docs/latest/graphql/core/guides/telemetry.html\n","time":"2021-08-25T22:52:58Z"}
26 Aug 2021 10:52:59.002281 <190>1 2021-08-25T22:52:58.692861+00:00 app web.1 - - {"type":"schema-sync-thread","timestamp":"2021-08-25T22:52:58.491+0000","level":"info","detail":{"thread_type":"processor","info":{"message":"Schema Version changed with notifications"}}}
26 Aug 2021 10:52:59.002543 <190>1 2021-08-25T22:52:58.692868+00:00 app web.1 - - {"type":"http-log","timestamp":"2021-08-25T22:52:58.491+0000","level":"error","detail":{"operation":{"error":{"path":"$","error":"resource does not exist","code":"not-found"},"request_id":"659327b7-acc9-4d86-9ec4-cb611f24dc39","response_size":65,"raw_query":""},"request_id":"659327b7-acc9-4d86-9ec4-cb611f24dc39","http_info":{"status":404,"http_version":"HTTP/1.1","url":"/v1alpha1/config","ip":"127.0.0.1","method":"GET","content_encoding":null}}}
26 Aug 2021 10:52:59.002448 <190>1 2021-08-25T22:52:58.692904+00:00 app web.1 - - {"type":"http-log","timestamp":"2021-08-25T22:52:58.491+0000","level":"info","detail":{"operation":{"request_id":"cfb81e03-9dee-47c7-875c-5f9898e86052","response_size":15},"request_id":"cfb81e03-9dee-47c7-875c-5f9898e86052","http_info":{"status":200,"http_version":"HTTP/1.1","url":"/v1/version","ip":"127.0.0.1","method":"GET","content_encoding":null}}}
26 Aug 2021 10:52:59.002602 <190>1 2021-08-25T22:52:58.692919+00:00 app web.1 - - {"type":"http-log","timestamp":"2021-08-25T22:52:58.491+0000","level":"info","detail":{"operation":{"query_execution_time":1.6697823e-2,"user_vars":{"x-hasura-role":"admin"},"request_id":"e85d4b97-ea9a-4c64-9e5e-e13bf1727a47","response_size":178,"query":{"args":{},"type":"get_catalog_state"},"request_read_time":4.94e-6},"request_id":"e85d4b97-ea9a-4c64-9e5e-e13bf1727a47","http_info":{"status":200,"http_version":"HTTP/1.1","url":"/v1/metadata","ip":"127.0.0.1","method":"POST","content_encoding":"gzip"}}}
26 Aug 2021 10:52:59.002598 <190>1 2021-08-25T22:52:58.692932+00:00 app web.1 - - {"type":"http-log","timestamp":"2021-08-25T22:52:58.491+0000","level":"info","detail":{"operation":{"query_execution_time":2.711089e-2,"user_vars":{"x-hasura-role":"admin"},"request_id":"e31fe220-2351-45c1-8b6b-22ac4739de37","response_size":7104,"query":{"args":{},"type":"export_metadata"},"request_read_time":4.41e-6},"request_id":"e31fe220-2351-45c1-8b6b-22ac4739de37","http_info":{"status":200,"http_version":"HTTP/1.1","url":"//v1/query","ip":"127.0.0.1","method":"POST","content_encoding":"gzip"}}}
26 Aug 2021 10:52:59.002169 <190>1 2021-08-25T22:52:58.692959+00:00 app web.1 - - {"level":"info","msg":"Applying metadata...","time":"2021-08-25T22:52:58Z"}
********** TRUNCATED ******************
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.