The electric proxy hangs when LOG_LEVEL: "debug" is NOT set

[gorbak25]

I'm using the new migration proxy. When pushing migrations via it using yarn prisma migrate deploy --schema prisma/electric-proxy/schema.prisma the tool hangs and never ends. When connecting to the proxy via netcat the proxy accepts the connection but never sends anything back.

The logs of the electric server don't indicate anything was wrong. I then added LOG_LEVEL: "debug" to it to see what is going on. Turns out the prisma migration tool started working! I then proceeded to disable debug mode again and the proxy hanged again .-. Did that a few more times and I get the same result everytime:

• With LOG_LEVEL: "debug" the migration proxy works
• Without LOG_LEVEL: "debug" the migration proxy hangs forever .-.

In debug mode when i'm running migrations the logs are littered with 18:23:24.440 pid=<0.3431.0> proxy_session_id=6 [debug] unrecognised from_clause object

For example:

18:23:24.440 pid=<0.3431.0> proxy_session_id=6 [debug] unrecognised from_clause object %PgQuery.Node{node: {:join_expr, %PgQuery.JoinExpr{jointype: :JOIN_INNER, is_natural: false, larg: %PgQuery.Node{node: {:join_expr, %PgQuery.JoinExpr{jointype: :JOIN_INNER, is_natural: false, larg: %PgQuery.Node{node: {:range_var, %PgQuery.RangeVar{catalogname: "", schemaname: "", relname: "pg_type", inh: true, relpersistence: "p", alias: %PgQuery.Alias{aliasname: "t", colnames: []}, location: 215}}}, rarg: %PgQuery.Node{node: {:range_var, %PgQuery.RangeVar{catalogname: "", schemaname: "", relname: "pg_enum", inh: true, relpersistence: "p", alias: %PgQuery.Alias{aliasname: "e", colnames: []}, location: 242}}}, using_clause: [], join_using_alias: nil, quals: %PgQuery.Node{node: {:a_expr, %PgQuery.A_Expr{kind: :AEXPR_OP, name: [%PgQuery.Node{node: {:string, %PgQuery.String{sval: "="}}}], lexpr: %PgQuery.Node{node: {:column_ref, %PgQuery.ColumnRef{fields: [%PgQuery.Node{node: {:string, %PgQuery.String{sval: "t"}}}, %PgQuery.Node{node: {:string, %PgQuery.String{sval: "oid"}}}], location: 255}}}, rexpr: %PgQuery.Node{node: {:column_ref, %PgQuery.ColumnRef{fields: [%PgQuery.Node{node: {:string, %PgQuery.String{sval: "e"}}}, %PgQuery.Node{node: {:string, %PgQuery.String{sval: "enumtypid"}}}], location: 263}}}, location: 261}}}, alias: nil, rtindex: 0}}}, rarg: %PgQuery.Node{node: {:range_var, %PgQuery.RangeVar{catalogname: "", schemaname: "pg_catalog", relname: "pg_namespace", inh: true, relpersistence: "p", alias: %PgQuery.Alias{aliasname: "n", colnames: []}, location: 292}}}, using_clause: [], join_using_alias: nil, quals: %PgQuery.Node{node: {:a_expr, %PgQuery.A_Expr{kind: :AEXPR_OP, name: [%PgQuery.Node{node: {:string, %PgQuery.String{sval: "="}}}], lexpr: %PgQuery.Node{node: {:column_ref, %PgQuery.ColumnRef{fields: [%PgQuery.Node{node: {:string, %PgQuery.String{sval: "n"}}}, %PgQuery.Node{node: {:string, %PgQuery.String{sval: "oid"}}}], location: 321}}}, rexpr: %PgQuery.Node{node: {:column_ref, %PgQuery.ColumnRef{fields: [%PgQuery.Node{node: {:string, %PgQuery.String{sval: "t"}}}, %PgQuery.Node{node: {:string, %PgQuery.String{sval: "typnamespace"}}}], location: 329}}}, location: 327}}}, alias: nil, rtindex: 0}}}

[gorbak25]

Here's the PCAP of when the hang occurs https://drive.google.com/file/d/19lzfrUFxXbc9p_R4CAjBFCELWwG9uqH3/view?usp=sharing

In the pcap first graphile-worker installs itself which succeeds

then when prisma connects the migrations hang forever

[alco]

Hey @gorbak25. Thanks for the detailed report!

I take it you're using Prisma to manage your app's migrations? What username does it use to connect to the Proxy?

And if possible, please include the full Electric log, both with LOG_LEVEL set to debug and without it. If you can also provide Postgres logs to correlate with, that'd be superhelpful.

[magnetised]

@gorbak25 if you could also provide the content of the migration that's failing that'd also be extremely helpful. Thanks

[balegas]

@gorbak25 is this still an issue?

[andrezimpel]

For me it is still an issue. I tried it with log level debug but got the same result. The migrations just hang and never finish without any error.

[linear]

VAX-1501 The electric proxy hangs when LOG_LEVEL: "debug" is NOT set

[alco]

@andrezimpel Thanks for letting us know! We'll look into this.

[alco]

I cannot reproduce this using the latest version Electric. Here's what I did:

Create a file named schema.prisma with the following contents:

datasource db {
  provider = "postgresql"
  url      = "postgresql://postgres:proxy_password@localhost:65432/postgres"
}

model Item {
  value String @id

  @@map("items")
}

Start Electric sync service with LOG_LEVEL=debug, connected to an empty DB.

Execute prisma migrate dev --name init --schema schema.prisma and check the output:

Environment variables loaded from .env
Prisma schema loaded from schema.prisma
Datasource "db": PostgreSQL database "postgres", schema "public" at "localhost:65432"

Applying migration `20240514104020_init`

The following migration(s) have been created and applied from new schema changes:

migrations/
  └─ 20240514104020_init/
    └─ migration.sql

Your database is now in sync with your schema.

Execute prisma migrate deploy --schema schema.prisma:

Environment variables loaded from .env
Prisma schema loaded from schema.prisma
Datasource "db": PostgreSQL database "postgres", schema "public" at "localhost:65432"

1 migration found in prisma/migrations


No pending migrations to apply.

Reset the database, restart the sync service with LOG_LEVEL=info and execute prisma migrate deploy --schema schema.prisma once again:

Environment variables loaded from .env
Prisma schema loaded from schema.prisma
Datasource "db": PostgreSQL database "postgres", schema "public" at "localhost:65432"

1 migration found in prisma/migrations

Applying migration `20240514104020_init`

The following migration have been applied:

migrations/
  └─ 20240514104020_init/
    └─ migration.sql
      
All migrations have been successfully applied.

This may have been another symptom of the problem fixed in #998.