search

knex / knex

A query builder for PostgreSQL, MySQL, CockroachDB, SQL Server, SQLite3 and Oracle, designed to be flexible, portable, and fun to use.
https://knexjs.org/
MIT License
19.16k stars 2.11k forks source link

Migrations lock index sequence already exists #3457

Open johnmaia opened 4 years ago

johnmaia commented 4 years ago

Environment

Knex version: 0.19.3 Database + version: PostgreSQL 10.6 OS: alpine (docker image)

Bug

We have an application that on every request it connects to a certain database. After the connection is established the migrations are executed before performing the request related queries.

Recently we came across the following error when the migrations were performed for the first time on a certain database:

{ 
  error: duplicate key value violates unique constraint "pg_type_typname_nsp_index"      
  at Connection.parseE (/home/node/app/node_modules/pg/lib/connection.js:555:11) 
  at Connection.parseMessage (/home/node/app/node_modules/pg/lib/connection.js:380:19)       
  at Socket.<anonymous> (/home/node/app/node_modules/pg/lib/connection.js:120:22) 
  at Socket.emit (events.js:198:13)\n       at Socket.EventEmitter.emit (domain.js:448:20)
  at addChunk (_stream_readable.js:288:12) 
  at readableAddChunk (_stream_readable.js:269:11)
  at Socket.Readable.push (_stream_readable.js:224:10)
  at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
  name: 'error',
  length: 266,
  severity: 'ERROR',
  code: '23505',
  detail: 'Key (typname, typnamespace)=(migrations_lock_index_seq, 38364) already exists.',
  hint: undefined,
  position: undefined,
  internalPosition: undefined,
  internalQuery: undefined,
  where: undefined,
  schema: 'pg_catalog',
  table: 'pg_type',
  column: undefined,
  dataType: undefined,
  constraint: 'pg_type_typname_nsp_index',
  file: 'nbtinsert.c',
  line: '434', 
  routine: '_bt_check_unique' 
}

Sadly the migrations were not performed. After this, on every new request he following error was thrown:

{ 
  MigrationLocked: Migration table is already locked 
  name: 'MigrationLocked',
  message: 'Migration table is already locked' 
}

Our solution was to manual delete all the rows that were stored in the migrations_lock table and rerun the migrations.

We suspect that two requests were executed concurrently and during the creation of the migrations table one of the requests failed throwing the first error, showed above, locking the table and therefore making it impossible to run the migrations.

elhigu commented 4 years ago

Please add reproduction code for this. There is pretty much nothing we can do without way to reproduce the problem (shooting in dark would take too long and we don't know yet if library has been used correctly or not).

johnmaia commented 4 years ago

We can't easily reproduce this error given that this error only occurred once after executing thousands of other similar requests. We tried to reproduce this by running a stack of knex.migrate.latest() on a clean database using promise.all. Something like this:

await Promise.all([
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest(),
  knex.migrate.latest()
]);

And we did had the following error:

(node:71102) UnhandledPromiseRejectionWarning: error: duplicate key value violates unique constraint "pg_type_typname_nsp_index"
    at Connection.parseE (node_modules/pg/lib/connection.js:555:11)
    at Connection.parseMessage (node_modules/pg/lib/connection.js:380:19)
    at Socket.<anonymous> (node_modules/pg/lib/connection.js:120:22)
    at Socket.emit (events.js:189:13)
    at addChunk (_stream_readable.js:284:12)
    at readableAddChunk (_stream_readable.js:265:11)
    at Socket.Readable.push (_stream_readable.js:220:10)
    at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
(node:71102) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:71102) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

But it doesn't look like the same issue we had in production. In this case the migrations were performed without any problem.

elhigu commented 4 years ago

you could try to get that error to happen when DEBUG=knex:* is set and try to spot if there is something fishy going on how queries are ran...

johnmaia commented 4 years ago

Ok, I've just executed the previous script with DEBUG=knex* and got the following output:

knex:client acquired connection from pool: __knexUid3 +0ms
knex:client acquired connection from pool: __knexUid2 +0ms
knex:client acquired connection from pool: __knexUid1 +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +2ms
knex:bindings [ 'migrations', 'schema' ] undefined +2ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:client acquired connection from pool: __knexUid10 +5ms
knex:client acquired connection from pool: __knexUid9 +0ms
knex:client acquired connection from pool: __knexUid8 +0ms
knex:client acquired connection from pool: __knexUid7 +0ms
knex:client acquired connection from pool: __knexUid6 +0ms
knex:client acquired connection from pool: __knexUid5 +0ms
knex:client acquired connection from pool: __knexUid4 +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +1ms
knex:bindings [ 'migrations', 'schema' ] undefined +1ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +1ms
knex:bindings [ 'migrations', 'schema' ] undefined +1ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +1ms
knex:bindings [ 'migrations', 'schema' ] undefined +1ms
knex:client releasing connection to pool: __knexUid3 +7ms
knex:client releasing connection to pool: __knexUid6 +1ms
knex:client releasing connection to pool: __knexUid10 +0ms
knex:client acquired connection from pool: __knexUid3 +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +6ms
knex:bindings [ 'migrations', 'schema' ] undefined +7ms
knex:client releasing connection to pool: __knexUid2 +1ms
knex:client releasing connection to pool: __knexUid1 +0ms
knex:client releasing connection to pool: __knexUid5 +0ms
knex:client acquired connection from pool: __knexUid6 +0ms
knex:client acquired connection from pool: __knexUid10 +0ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +3ms
knex:bindings [] undefined +2ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +1ms
knex:bindings [] undefined +1ms
knex:client releasing connection to pool: __knexUid4 +3ms
knex:client acquired connection from pool: __knexUid2 +0ms
knex:client acquired connection from pool: __knexUid5 +0ms
knex:client acquired connection from pool: __knexUid1 +1ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +1ms
knex:bindings [] undefined +1ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +0ms
knex:bindings [] undefined +0ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +0ms
knex:bindings [] undefined +0ms
knex:client releasing connection to pool: __knexUid7 +0ms
knex:client releasing connection to pool: __knexUid8 +1ms
knex:client releasing connection to pool: __knexUid9 +0ms
knex:client acquired connection from pool: __knexUid4 +0ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +1ms
knex:bindings [] undefined +1ms
knex:client releasing connection to pool: __knexUid3 +0ms
knex:client acquired connection from pool: __knexUid7 +0ms
knex:client acquired connection from pool: __knexUid9 +9ms
knex:client acquired connection from pool: __knexUid8 +0ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +9ms
knex:bindings [] undefined +9ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +0ms
knex:bindings [] undefined +0ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +1ms
knex:bindings [] undefined +1ms
knex:client acquired connection from pool: __knexUid3 +5ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +6ms
knex:bindings [] undefined +6ms
knex:client releasing connection to pool: __knexUid6 +6ms
knex:client releasing connection to pool: __knexUid4 +1ms
knex:client releasing connection to pool: __knexUid1 +0ms
knex:client releasing connection to pool: __knexUid2 +0ms
knex:client releasing connection to pool: __knexUid10 +0ms
knex:client releasing connection to pool: __knexUid5 +0ms
(node:77807) UnhandledPromiseRejectionWarning: error: duplicate key value violates unique constraint "pg_type_typname_nsp_index"
  at Connection.parseE (node_modules/pg/lib/connection.js:555:11)
  at Connection.parseMessage (node_modules/pg/lib/connection.js:380:19)
  at Socket.<anonymous> (node_modules/pg/lib/connection.js:120:22)
  at Socket.emit (events.js:189:13)
  at addChunk (_stream_readable.js:284:12)
  at readableAddChunk (_stream_readable.js:265:11)
  at Socket.Readable.push (_stream_readable.js:220:10)
  at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
(node:77807) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error fooated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:77807) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
knex:client releasing connection to pool: __knexUid7 +29ms
knex:client releasing connection to pool: __knexUid8 +1ms
knex:client releasing connection to pool: __knexUid9 +0ms
knex:client acquired connection from pool: __knexUid6 +0ms
knex:client acquired connection from pool: __knexUid5 +0ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +35ms
knex:bindings [] undefined +35ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations_lock', 'schema' ] undefined +0ms
knex:client releasing connection to pool: __knexUid3 +1ms
knex:client releasing connection to pool: __knexUid6 +2ms
knex:client releasing connection to pool: __knexUid5 +16ms
knex:client acquired connection from pool: __knexUid5 +0ms
knex:query create table "schema"."migrations_lock" ("index" serial primary key, "is_locked" integer) undefined +19ms
knex:bindings [] undefined +19ms
knex:client releasing connection to pool: __knexUid5 +7ms
knex:client acquired connection from pool: __knexUid5 +1ms
knex:query select * from "schema"."migrations_lock" undefined +10ms
knex:bindings [] undefined +10ms
knex:client releasing connection to pool: __knexUid5 +6ms
knex:client acquired connection from pool: __knexUid5 +1ms
knex:query insert into "schema"."migrations_lock" ("is_locked") values (?) undefined +6ms
knex:bindings [ 0 ] undefined +6ms
knex:client releasing connection to pool: __knexUid5 +5ms
knex:client acquired connection from pool: __knexUid5 +0ms
knex:query select "name" from "schema"."migrations" order by "id" asc undefined +4ms
knex:bindings [] undefined +5ms
knex:client releasing connection to pool: __knexUid5 +2ms
knex:tx trx11: Starting top level transaction +0ms
knex:client acquired connection from pool: __knexUid5 +15ms
...
bri3d commented 4 years ago

@johnmaia - I think we are experiencing the same issue. I filed #3538. It can be more easily reproduced with process-level concurrency rather than IO concurrency - that is, by executing that same promise chain in many Node processes concurrently. However, a reading of the code shows that the issue is clearly possible, as outlined in my comment. Please let me know if this helps or you can reproduce and follow along.

johnmaia commented 4 years ago

@bri3d, yes it seems to be the same issue. I've followed your suggestions and I was able to recreate the same problem with process-level concurrency. I've ran the following node script:

import knex from 'knex';

(async () => {
  const knexConnection = knex( {
    client: 'postgres',
    connection: {
      database: 'foobar',
      host: '127.0.0.1',
      user: 'postgres'
    }
  });

  await knexConnection.migrate.latest();
})();

On 5 concurrent processes with the following bash script:

DEBUG=knex* babel-node src/foobar.js &
DEBUG=knex* babel-node src/foobar.js &
DEBUG=knex* babel-node src/foobar.js &
DEBUG=knex* babel-node src/foobar.js &
DEBUG=knex* babel-node src/foobar.js &

And got the following output:

knex:client acquired connection from pool: __knexUid1 +0ms
knex:client acquired connection from pool: __knexUid1 +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:client acquired connection from pool: __knexUid1 +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:client acquired connection from pool: __knexUid1 +0ms
knex:client acquired connection from pool: __knexUid1 +0ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:client releasing connection to pool: __knexUid1 +26ms
knex:client releasing connection to pool: __knexUid1 +27ms
knex:client acquired connection from pool: __knexUid1 +2ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +0ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:client acquired connection from pool: __knexUid1 +2ms
knex:bindings [ 'migrations', 'schema' ] undefined +0ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +29ms
knex:bindings [] undefined +30ms
knex:client releasing connection to pool: __knexUid1 +30ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +31ms
knex:bindings [] undefined +31ms
knex:client acquired connection from pool: __knexUid1 +1ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +34ms
knex:bindings [] undefined +35ms
knex:client releasing connection to pool: __knexUid1 +28ms
knex:client releasing connection to pool: __knexUid1 +19ms
knex:client acquired connection from pool: __knexUid1 +2ms
knex:client acquired connection from pool: __knexUid1 +1ms
knex:query select * from information_schema.tables where table_name = ? and table_schema = ? undefined +15ms
knex:bindings [ 'migrations_lock', 'schema' ] undefined +14ms
knex:client releasing connection to pool: __knexUid1 +28ms
knex:client releasing connection to pool: __knexUid1 +22ms
knex:client acquired connection from pool: __knexUid1 +1ms
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" timestamptz) undefined +28ms
knex:client releasing connection to pool: __knexUid1 +5ms
knex:client releasing connection to pool: __knexUid1 +17ms
knex:bindings [] undefined +29ms
(node:23440) Unhandle  knex:client acquired connection from pool: __knexUid1 +0ms
dPromiseRejectionWarning: error: duplicate key value violates unique constraint "pg_type_typname_nsp_index"
  at Connection.parseE (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:604:11)
  at Connection.parseMessage (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:401:19)
  at Socket.<anonymous> (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:121:22)
  at Socket.emit (events.js:189:13)
  at Socket.EventEmitter.emit (domain.js:441:20)
  at addChunk (_stream_readable.js:284:12)
  at readableAddChunk (_stream_readable.js:265:11)
  at Socket.Readable.push (_stream_readable.js:220:10)
  at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
knex:query create table "schema"."migrations" ("id" serial primary key, "name" varchar(255), "batch" integer, "migration_time" tim(node:23441) UnhandledPromiseRejectionWarning: error: relation "migrations" already exists
  at Connection.parseE (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:604:11)
  at Connection.parseMessage (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:401:19)
  at Socket.<anonymous> (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:121:22)
  at Socket.emit (events.js:189:13)
  at Socket.EventEmitter.emit (domain.js:441:20)
  at addChunk (_stream_readable.js:284:12)
  at readableAddChunk (_stream_readable.js:265:11)
  at Socket.Readable.push (_stream_readable.js:220:10)
  at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
estamptz) undefined +28ms
(node:23441) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:23440) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
knex:bindings [] undefined +29ms
knex:query create table "schema"."migrations_lock" ("index" serial primary key, "is_locked" integer) undefined +10ms
(node:23440) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
(node:23441) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
knex:bindings [] undefined +10ms
knex:client releasing connection to pool: __knexUid1 +15ms
(node:23439) UnhandledPromiseRejectionWarning: error: relation "migrations" already exists
  at Connection.parseE (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:604:11)
  at Connection.parseMessage (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:401:19)
  at Socket.<anonymous> (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:121:22)
  at Socket.emit (events.js:189:13)
  at Socket.EventEmitter.emit (domain.js:441:20)
  at addChunk (_stream_readable.js:284:12)
  at readableAddChunk (_stream_readable.js:265:11)
  at Socket.Readable.push (_stream_readable.js:220:10)
  at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
(node:23439) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:23439) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
knex:client releasing connection to pool: __knexUid1 +17ms
knex:client acquired connection from pool: __knexUid1 +1ms
knex:client releasing connection to pool: __knexUid1 +20ms
knex:query select * from "schema"."migrations_lock" undefined +16ms
knex:bindings [] undefined +16ms
(node:23438) UnhandledPromiseRejectionWarning: error: relation "migrations" already exists
  at Connection.parseE (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:604:11)
  at Connection.parseMessage (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:401:19)
  at Socket.<anonymous> (/Users/johnmaia/Projects/foobar/node_modules/pg/lib/connection.js:121:22)
  at Socket.emit (events.js:189:13)
  at Socket.EventEmitter.emit (domain.js:441:20)
  at addChunk (_stream_readable.js:284:12)
  at readableAddChunk (_stream_readable.js:265:11)
  at Socket.Readable.push (_stream_readable.js:220:10)
  at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
(node:23438) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:23438) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
...

Thanks for referring my issue!

jasonhao518 commented 1 year ago

seems the same issue is still there. knex 2.3.0, postgresql: 14.5.0 pg: 8.8.0

[2022-12-12 08:04:49] ERROR alter table "migrations_lock" add constraint "migrations_lock_pkey" primary key ("lock_key") - multiple primary keys for table "migrations_lock" are not allowed

alter table "migrations_lock" add constraint "migrations_lock_pkey" primary key ("lock_key") - multiple primary keys for table "migrations_lock" are not allowed

Error ID: a66ba640-79f3-11ed-b39d-f948464e4b01

Error Code: 42P16