Mix phx.server gives: Could not create schema.migrations table

Terbium-135 · October 9, 2023, 5:57am

When I am restarting a backend application with mix phx.serverthe following errors are emitted (3 of them):

2023-10-06T14:17:37.686454+02:00 error: Could not create schema migrations table. This error [...]
2023-10-06T14:17:37.687061+02:00 error: Could not create schema migrations table. [...]
[...]
2023-10-06T14:17:37.930492+02:00 error: GenServer #PID<0.2226.0> terminating, ** (Postgrex.Error) ERROR 40P01 (deadlock_detected) deadlock detected, [...]
2023-10-06T14:17:37.938410+02:00 error: GenServer #PID<0.2364.0> terminating, ** (Postgrex.Error) ERROR 40P01 (deadlock_detected) deadlock detected,  [...] lib/phoenix_ecto/check_repo_status.ex:99: Phoenix.Ecto.CheckRepoStatus.migration...
2023-10-06T14:17:38.663907+02:00 error: Could not create schema migrations table.  [...]
2023-10-06T14:17:38.761540+02:00 error: GenServer #PID<0.2308.0> terminating, ** (Postgrex.Error) ERROR 40P01 (deadlock_detected) deadlock detected,  [...]```

Increasing the verbosity of the postresql server (to narrow down further what’s going on) makes these errors disappear. But I guess they are still there.

Why there are 3 processes running at all? I have 3 tabs opened in the browser, pointing to different routes
The DB has an event trigger added - which is excluding schema.migrationthough
Got the feeling it has something to do with checking for the schema.migration table

2023-10-08 06:31:59.294 CEST [116650] phoenix@p1 DETAIL:  Process 116650 waits for AccessExclusiveLock on object 60892 of class 2620 of database 16389; blocked by process 116647.
	Process 116647 waits for AccessExclusiveLock on relation 25408 of database 16389; blocked by process 116650.
	Process 116650: CREATE TABLE IF NOT EXISTS "schema_migrations" ("version" bigint, "inserted_at" timestamp(0), PRIMARY KEY ("version"))
	Process 116647: CREATE TABLE IF NOT EXISTS "schema_migrations" ("version" bigint, "inserted_at" timestamp(0), PRIMARY KEY ("version"))

Where and how to investigate further?

Any help appreciated

Hermanverschooten · October 9, 2023, 8:09am

How do you start/stop/restart the app?

Terbium-135 · October 19, 2023, 6:59am

Starting the app with mix phx.server and in case the application gets recompiled during a source code change I see this deadlock popping up in the log and in the open browser windows (which I have to manually reload)

I guess that the mentioned 3 open windows are reconnecting then and getting data almost simultaneously from the db.

I don’t know why the CREATE TABLE IF NOT EXISTS schema_migrations command is even issued 3 times at all. Thought there would we something like a singleton to handle that check.

Not sure if there is any relation to:

github.com/phoenixframework/phoenix_ecto

Phoenix.Endpoint.SyncCodeReloadPlug issues CREATE TABLE even though repo is read-only

opened 11:10AM - 04 Sep 23 UTC

closed 06:47PM - 14 Sep 23 UTC

IwoHerka

### Environment * Elixir version (elixir -v): ```bash Erlang/OTP 26 [erts…-14.0.2] [source] [64-bit] [smp:24:24] [ds:24:24:10] [async-threads:1] [jit:ns] Elixir 1.15.4 (compiled with Erlang/OTP 26) ``` * Phoenix version (mix deps): ```elixir {:phoenix, "~> 1.7.2"}, {:phoenix_ecto, "~> 4.4"}, {:ecto_sql, "~> 3.10"}, {:myxql, ">= 0.6.0"}, ``` * Operating system: Windows/Ubuntu 22.04.2 LTS (WSL2) ### Actual behavior When sending request to my controller, `Phoenix.Endpoint.SyncCodeReloadPlug` issues `CREATE TABLE IF NOT EXISTS schema_migrations` query which fails, because my database connection is read-only (my database user has no rights to issue `CREATE`). My Ecto repo is configured as follows: ```elixir use Ecto.Repo, otp_app: :foo adapter: Ecto.Adapters.MyXQL, read_only: true ``` Stacktrace: ```bash [error] Could not create schema migrations table. This error usually happens due to the following: * The database does not exist * The "schema_migrations" table, which Ecto uses for managing migrations, was defined by another library * There is a deadlock while migrating (such as using concurrent indexes with a migration_lock) To fix the first issue, run "mix ecto.create" for the desired MIX_ENV. To address the second, you can run "mix ecto.drop" followed by "mix ecto.create", both for the desired MIX_ENV. Alternatively you may configure Ecto to use another table and/or repository for managing migrations: config :foo, Foo.Repo, migration_source: "some_other_table_for_schema_migrations", migration_repo: AnotherRepoForSchemaMigrations The full error report is shown below. [error] #PID<0.1200.0> running Phoenix.Endpoint.SyncCodeReloadPlug (connection #PID<0.1199.0>, stream id 1) terminated Server: localhost:4000 (http) Request: GET /foo ** (exit) an exception was raised: ** (MyXQL.Error) (1142) CREATE command denied to user 'foo_api_ro'@'<ip>' for table 'schema_migrations' query: CREATE TABLE IF NOT EXISTS `schema_migrations` (`version` bigint, `inserted_at` datetime, PRIMARY KEY (`version`)) ENGINE = INNODB (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:1047: Ecto.Adapters.SQL.raise_sql_call_error/1 (elixir 1.15.4) lib/enum.ex:1693: Enum."-map/2-lists^map/1-1-"/2 (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:1154: Ecto.Adapters.SQL.execute_ddl/4 (ecto_sql 3.10.2) lib/ecto/migrator.ex:756: Ecto.Migrator.verbose_schema_migration/3 (ecto_sql 3.10.2) lib/ecto/migrator.ex:564: Ecto.Migrator.lock_for_migrations/4 (ecto_sql 3.10.2) lib/ecto/migrator.ex:486: Ecto.Migrator.migrations/3 (phoenix_ecto 4.4.2) lib/phoenix_ecto/check_repo_status.ex:99: Phoenix.Ecto.CheckRepoStatus.migrations/3 (phoenix_ecto 4.4.2) lib/phoenix_ecto/check_repo_status.ex:57: Phoenix.Ecto.CheckRepoStatus.check_pending_migrations!/2 (phoenix_ecto 4.4.2) lib/phoenix_ecto/check_repo_status.ex:31: anonymous fn/3 in Phoenix.Ecto.CheckRepoStatus.call/2 (elixir 1.15.4) lib/enum.ex:2510: Enum."-reduce/3-lists^foldl/2-0-"/3 (phoenix_ecto 4.4.2) lib/phoenix_ecto/check_repo_status.ex:30: Phoenix.Ecto.CheckRepoStatus.call/2 (foo 0.1.0) lib/foo _web/endpoint.ex:1: FooWeb.Endpoint.plug_builder_call/2 (foo 0.1.0) deps/plug/lib/plug/debugger.ex:136: FooWeb.Endpoint."call (overridable 3)"/2 (foo 0.1.0) lib/foo _web/endpoint.ex:1: FooWeb.Endpoint.call/2 (phoenix 1.7.7) lib/phoenix/endpoint/sync_code_reload_plug.ex:22: Phoenix.Endpoint.SyncCodeReloadPlug.do_call/4 (plug_cowboy 2.6.1) lib/plug/cowboy/handler.ex:11: Plug.Cowboy.Handler.init/2 (cowboy 2.10.0) /home/poly/P/foo -api/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2 (cowboy 2.10.0) /home/poly/P/foo -api/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3 (cowboy 2.10.0) /home/poly/P/foo -api/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3 (stdlib 5.0.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3 ``` ### Expected behavior I would expect for Phoenix to respect `read_only: true` on my repository and check if `schema_migrations` table exist (in my case it does exist) without issuing `CREATE` statement. Ideally, it would work without `read_only: true`, to support read-only users on the database level.

Hermanverschooten · October 19, 2023, 7:50am

Have you tried commenting out the Phoenix.Ecto.CheckRepoStatus? Does it still happen then?

Terbium-135 · October 19, 2023, 8:17am

Not yet.
I give it a try and let you know.
Thank you for the guidance

Terbium-135 · October 19, 2023, 10:49am

Looks like commenting out CheckRepoStatus solved the problem.
Are there any drawbacks if I keep it like this?

(Still asking myself why I’m the only one facing this deadlock but that’s for another day)

Hermanverschooten · October 20, 2023, 9:28am

Can you check if it still trying to do the migrations with this commented out.

Terbium-135 · October 20, 2023, 9:48am

From that timestamp on I modified the endpoint.ex file there are no such events logged.

Is it trying to run (any) migrations at all - or is it just checking for the existence of schema.migrations ? I did not check the source code involved in this

Hermanverschooten · October 20, 2023, 9:55am

According to the docs

Checks if the storage is up (database is created) or if there are any pending migrations. Both checks can raise an error if the conditions are not met.

Terbium-135 · October 20, 2023, 9:59am

I will have a look at the source if I find the time.

I don’t understand why it is trying to create the migration table at all
In any case. Thank you for the help. Appreciated it!

Hermanverschooten · October 20, 2023, 10:11am

The migration table is a hard requirement when using a database. So by using the create if not exists they can ensure it exists, without having to check for its existance.

Terbium-135 · October 20, 2023, 10:15am

And I guess that’s the reason for a deadlock at my end.
I don’t know enough about postgresql. But I take it that it does a lock if creating a table.
I will have a look the upcoming weekend and try to figure out what is going on

Hermanverschooten · October 20, 2023, 10:23am

Yes, but unless you are starting more than 1 endpoint or more than once, you shouldn’t have that problem.

Terbium-135 · October 20, 2023, 1:19pm

Looks like I have more than one endpoint running.
Don’t know why and what is going on at all.
Because I also see tripled messages from live_reload in my console log:

[2023-10-20 14:50:20.812] [debug] Live reload: lib/backend_web/live/components/navbar.ex
[2023-10-20 14:50:20.813] [debug] Live reload: lib/backend_web/live/components/navbar.ex
[2023-10-20 14:50:20.847] [debug] Live reload: lib/backend_web/live/components/navbar.ex

Hermanverschooten · October 20, 2023, 1:30pm

I’d start with looking in application.ex, what is started there?