graphql-engine icon indicating copy to clipboard operation
graphql-engine copied to clipboard

Published 20 hours ago • verified publisher icon hasura

CLI: v2.10.1: error applying metadata - trigger already exists

Open andoks opened this issue 3 years ago • 8 comments

Version Information

Server Version: v2.10.1 (.cli-migrations-v2 from docker hub) CLI Version (for CLI related issue): N/A

Environment

OSS (hasura/graphql-engine:v2.10.1.cli-migrations-v2 docker image)

What is the current behaviour?

Spinning up a new container with pre-existing migration scripts causes fatal error and restart with the following error printed to the logs

error applying metadata 
{
    "code": "unexpected",
    "error": "database query error",
    "internal": {
        "arguments": [],
        "error": {
            "description": null,
            "exec_status": "FatalError",
            "hint": null,
            "message": "trigger \"notify_hasura_delete_triggers_when_deleting_monitoring_target_D\" for relation \"monitoring_target\" already exists",
            "status_code": "42710"
        },
        "prepared": false,
        "statement": "\n         CREATE TRIGGER \"notify_hasura_delete_triggers_when_deleting_monitoring_target_DELETE\" AFTER DELETE ON \"public\".\"monitoring_target\" FOR EACH ROW EXECUTE PROCEDURE hdb_catalog.\"notify_hasura_delete_triggers_when_deleting_monitoring_target_DELETE\"()\n      "
    },
   "path\: "$.args"
}

What is the expected behaviour?

Successful startup of container

How to reproduce the issue?

  1. Update docker-compose setup from v2.9.0 to v2.10.1
  2. Run docker-compose up -d --build --force-recreate
  3. During container startup the log entry above is printed and the container is restarted

Screenshots or Screencast

Please provide any traces or logs that could help here.

{"timestamp":"2022-08-19T10:33:35.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"database url for migrations is set by HASURA_GRAPHQL_DATABASE_URL"}}
{"timestamp":"2022-08-19T10:33:35.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"migrations server port env var is not set, defaulting to 9691"}}
{"timestamp":"2022-08-19T10:33:35.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"server timeout is not set, defaulting to 30 seconds"}}
{"timestamp":"2022-08-19T10:33:35.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"starting graphql engine temporarily on port 9691"}}
{"timestamp":"2022-08-19T10:33:35.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"waiting 30 for 9691 to be ready"}}
{"detail":{"info":{"admin_secret_set":true,"auth_hook":null,"auth_hook_mode":null,"console_assets_dir":"/srv/console-assets","cors_config":{"allowed_origins":{"fqdns":["http://localhost:9695","https://localhost","http://localhost:3000"],"wildcards":[]},"disabled":false,"ws_read_cookie":null},"enable_allowlist":false,"enable_console":true,"enable_maintenance_mode":false,"enable_metadata_query_logging":false,"enable_telemetry":false,"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_map":{"x-hasura-allowed-roles":{"path":"$.roles"},"x-hasura-default-role":{"path":"$.roles[0]"},"x-hasura-user-id":{"path":"$.email"}},"header":{"name":"access_token","type":"Cookie"},"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":null,"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-19T10:33:35.663+0000","type":"startup"}
{"detail":{"info":{"database_url":"postgres://postgres:...@insight-postgres:5432/postgres","retries":1},"kind":"postgres_connection"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"timestamp":"2022-08-19T10:33:36.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"port 9691 is ready"}}
{"timestamp":"2022-08-19T10:33:36.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"env var HASURA_GRAPHQL_MIGRATIONS_DIR is not set, defaulting to /hasura-migrations"}}
{"timestamp":"2022-08-19T10:33:36.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"env var HASURA_GRAPHQL_METADATA_DIR is not set, defaulting to /hasura-metadata"}}
{"timestamp":"2022-08-19T10:33:36.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-apply","info":"applying migrations from /hasura-migrations"}}
{"level":"info","msg":"nothing to apply on database ","time":"2022-08-19T10:33:36Z"}
{"timestamp":"2022-08-19T10:33:36.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-apply","info":"applying metadata from /hasura-metadata"}}
{"detail":{"info":"Already at the latest catalog version (47); nothing to do.","kind":"catalog_migrate"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"detail":{"info":"Schema sync enabled. Polling at Milliseconds {milliseconds = 1s}","kind":"schema-sync"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"detail":{"info":{"instance_id":"6969011b-ce8b-4809-9b17-35bd33f7e4ed","message":"listener thread started","thread_id":"ThreadId 91"},"kind":"schema-sync"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"detail":{"info":{"instance_id":"6969011b-ce8b-4809-9b17-35bd33f7e4ed","message":"processor thread started","thread_id":"ThreadId 107"},"kind":"schema-sync"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"detail":{"info":"starting workers","kind":"event_triggers"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"detail":{"info":"preparing data","kind":"scheduled_triggers"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"detail":{"info":{"message":"starting API server","time_taken":0.198670467},"kind":"server"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"startup"}
{"detail":"Thread SchemeUpdate.listener (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":"Thread ourIdleGC (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":"Thread processEventQueue (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":"Thread processScheduledTriggers (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":"Thread SchemeUpdate.processor (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":"Thread checkForUpdates (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":"Thread asyncActionsProcessor (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":{"http_info":{"content_encoding":null,"http_version":"HTTP/1.1","ip":"127.0.0.1","method":"GET","status":200,"url":"/v1/version"},"operation":{"request_id":"e4e30ce1-8396-456e-b96b-96295f7be3a0","request_mode":"non-graphql","response_size":16},"request_id":"e4e30ce1-8396-456e-b96b-96295f7be3a0"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":"Thread asyncActionSubscriptionsProcessor (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":{"http_info":{"content_encoding":null,"http_version":"HTTP/1.1","ip":"127.0.0.1","method":"GET","status":200,"url":"/v1/version"},"operation":{"request_id":"3ec09aa4-ce04-4b6c-b6a5-f3c13a9bc467","request_mode":"non-graphql","response_size":16},"request_id":"3ec09aa4-ce04-4b6c-b6a5-f3c13a9bc467"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":"Thread runCronEventsGenerator (re)started","level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"unstructured"}
{"detail":{"http_info":{"content_encoding":null,"http_version":"HTTP/1.1","ip":"127.0.0.1","method":"GET","status":404,"url":"/v1alpha1/config"},"operation":{"error":{"code":"not-found","error":"resource does not exist","path":"$"},"request_id":"747bf58c-5357-432e-992a-c36bfb8950ff","request_mode":"error","response_size":65},"request_id":"747bf58c-5357-432e-992a-c36bfb8950ff"},"level":"error","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":{"http_info":{"content_encoding":"gzip","http_version":"HTTP/1.1","ip":"127.0.0.1","method":"POST","status":200,"url":"/v1/query"},"operation":{"query_execution_time":3.604388e-3,"request_id":"9698880a-a979-41db-8f19-44ceb0f2847f","request_mode":"non-graphql","request_read_time":2.354e-6,"response_size":1844,"user_vars":{"x-hasura-role":"admin"}},"request_id":"9698880a-a979-41db-8f19-44ceb0f2847f"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":{"http_info":{"content_encoding":"gzip","http_version":"HTTP/1.1","ip":"127.0.0.1","method":"POST","status":200,"url":"/v1/metadata"},"operation":{"query_execution_time":2.352602e-3,"request_id":"14b6447a-20b1-442d-a315-d926a8dbc26f","request_mode":"non-graphql","request_read_time":1.613e-6,"response_size":89,"user_vars":{"x-hasura-role":"admin"}},"request_id":"14b6447a-20b1-442d-a315-d926a8dbc26f"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":{"http_info":{"content_encoding":"gzip","http_version":"HTTP/1.1","ip":"127.0.0.1","method":"POST","status":200,"url":"/v1/metadata"},"operation":{"query_execution_time":3.105306e-3,"request_id":"56559e67-d74d-406a-990b-f44d4a9ad00e","request_mode":"non-graphql","request_read_time":2.895e-6,"response_size":1844,"user_vars":{"x-hasura-role":"admin"}},"request_id":"56559e67-d74d-406a-990b-f44d4a9ad00e"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":{"http_info":{"content_encoding":"gzip","http_version":"HTTP/1.1","ip":"127.0.0.1","method":"POST","status":200,"url":"/v2/query"},"operation":{"query_execution_time":4.576112e-3,"request_id":"10aa5223-348b-4a33-8aa3-89583ecf58f7","request_mode":"non-graphql","request_read_time":1.332e-6,"response_size":68,"user_vars":{"x-hasura-role":"admin"}},"request_id":"10aa5223-348b-4a33-8aa3-89583ecf58f7"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":{"http_info":{"content_encoding":"gzip","http_version":"HTTP/1.1","ip":"127.0.0.1","method":"POST","status":200,"url":"/v2/query"},"operation":{"query_execution_time":4.113588e-3,"request_id":"b9d9cd46-0652-404f-9d76-42fa490f4028","request_mode":"non-graphql","request_read_time":1.152e-6,"response_size":68,"user_vars":{"x-hasura-role":"admin"}},"request_id":"b9d9cd46-0652-404f-9d76-42fa490f4028"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":{"http_info":{"content_encoding":"gzip","http_version":"HTTP/1.1","ip":"127.0.0.1","method":"POST","status":200,"url":"/v2/query"},"operation":{"query_execution_time":3.777972e-3,"request_id":"014bf8ae-13cb-4707-9813-616012658613","request_mode":"non-graphql","request_read_time":2.956e-6,"response_size":185,"user_vars":{"x-hasura-role":"admin"}},"request_id":"014bf8ae-13cb-4707-9813-616012658613"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"detail":{"http_info":{"content_encoding":"gzip","http_version":"HTTP/1.1","ip":"127.0.0.1","method":"POST","status":200,"url":"/v2/query"},"operation":{"query_execution_time":3.68567e-3,"request_id":"f1fc007d-ebcd-4701-933f-cb8b26a28bbd","request_mode":"non-graphql","request_read_time":2.966e-6,"response_size":68,"user_vars":{"x-hasura-role":"admin"}},"request_id":"f1fc007d-ebcd-4701-933f-cb8b26a28bbd"},"level":"info","timestamp":"2022-08-19T10:33:35.663+0000","type":"http-log"}
{"level":"info","msg":"Applying metadata...","time":"2022-08-19T10:33:37Z"}
time="2022-08-19T10:33:37Z" level=fatal msg="error applying metadata \n{\n  \"code\": \"unexpected\",\n  \"error\": \"database query error\",\n  \"internal\": {\n    \"arguments\": [],\n    \"error\": {\n      \"description\": null,\n      \"exec_status\": \"FatalError\",\n      \"hint\": null,\n      \"message\": \"trigger \\\"notify_hasura_delete_triggers_when_deleting_monitoring_target_D\\\" for relation \\\"monitoring_target\\\" already exists\",\n      \"status_code\": \"42710\"\n    },\n    \"prepared\": false,\n    \"statement\": \"\\n         CREATE TRIGGER \\\"notify_hasura_delete_triggers_when_deleting_monitoring_target_DELETE\\\" AFTER DELETE ON \\\"public\\\".\\\"monitoring_target\\\" FOR EACH ROW EXECUTE PROCEDURE hdb_catalog.\\\"notify_hasura_delete_triggers_when_deleting_monitoring_target_DELETE\\\"()\\n      \"\n  },\n  \"path\": \"$.args\"\n}"

Any possible solutions?

Downgrade to v2.9.0

Can you identify the location in the source code where the problem exists?

If the bug is confirmed, would you be willing to submit a PR?

Keywords

andoks avatar Aug 19 '22 11:08 andoks

possibly related to #8806

andoks avatar Aug 19 '22 11:08 andoks

Hi @andoks , thank you for bringing this issue to our attention. We are currently investigating this and would update soon with our findings.

manasag avatar Aug 20 '22 10:08 manasag

It seems to be a timing issue.

When I wait a few seconds and do hasura metadata reload afterwards, everything works again.

maaft avatar Aug 25 '22 16:08 maaft

The above "trigger ... already exists" error is also stopping me from adding and remove columns from existing tables in the database.

I did some testing on the various versions of hasura, and it seems like this bug (assuming it is a bug) does not happen with v2.6.2, but starts happening with v2.7.0. Due to this issue I have had to downgrade Hasura to v2.6.2 for now.

EDIT: this was a red herring, still got the trigger already exists error with v2.6.2

EDIT2: Testing a few times with v2.3.1, it seems like the issue is not present in that version.

andoks avatar Sep 06 '22 15:09 andoks

@manasag could you please update on this issue? I am also encountering this, and it's kind of a big deal. Presently on 2.10.1.

I can also confirm that I am not experiencing this issue with 2.7.0.

revelstoke-tim avatar Oct 05 '22 01:10 revelstoke-tim

@manasag Please could you reply with an update on this issue? It is impacting our ability to update Hasura to a more recent release which contains fixes to other issues we're encountering.

revelstoke-tim avatar Oct 10 '22 15:10 revelstoke-tim

@andoks one thing you should check is the length of your event / trigger names. Because Hasura adds both a prefix ('notify_hasura_') and a suffix ('_DELETE', etc), and also schema name (if the trigger is on a different schema), I've found that it can exceed the Postgres identifier limit of 63 bytes. To workaround I shortened my event names and that seems to have done the trick.

Judging by your logs, that's also your issue, so shorten your "delete_triggers_when_deleting_monitoring_target" name . YMMV.

revelstoke-tim avatar Oct 15 '22 17:10 revelstoke-tim

@manasag should you ever return to this issue, this seems to be a regression from the event trigger length fix from https://github.com/hasura/graphql-engine/issues/5786 / https://github.com/hasura/graphql-engine/pull/5826 . Would be great for it to be fixed again.

revelstoke-tim avatar Oct 15 '22 17:10 revelstoke-tim

@revelstoke-tim We are looking into this. Apologies for not responding sooner.

tirumaraiselvan avatar Nov 30 '22 12:11 tirumaraiselvan

@andoks one thing you should check is the length of your event / trigger names. Because Hasura adds both a prefix ('notify_hasura_') and a suffix ('_DELETE', etc), and also schema name (if the trigger is on a different schema), I've found that it can exceed the Postgres identifier limit of 63 bytes. To workaround I shortened my event names and that seems to have done the trick.

Judging by your logs, that's also your issue, so shorten your "delete_triggers_when_deleting_monitoring_target" name . YMMV.

@revelstoke-tim thanks for your input, indeed it was related to a named trigger, as hasura uses 21 of the 63 allowed bytes in identifier/names on a delete trigger ("notify_hasura_" + "_DELETE".

andoks avatar Jan 03 '23 16:01 andoks

Yes, the Event Trigger name should be less than 42 characters. This is also enforced in the create_event_trigger API and the console but isn't being enforced in the replace_metadata API. We are working on it but the complication there is to prevent any breaking changes.

tirumaraiselvan avatar Jan 17 '23 08:01 tirumaraiselvan