(0.16.3) Using knexSnakeCaseMappers() with sqlite3 dropColumn() breaks tables

[elunic]

Environment

Knex version: 0.16.3
Database + version: sqlite3 4.0.6
OS: Windows 7 x64

Bug

1. Explain what kind of behaviour you are getting and how you think it should do

When using Objection's knexSnakeCaseMappers(), if dropColumn() is used, the original table is not deleted/modified, the temporary table _knex_temp_alter3 is not deleted, and subsequent migrations that manipulate the table error out.

Dropping columns should not break the database schema when using knexSnakeCaseMappers

2. Error message

Varies. If the table is not manipulated after the dropColumn/dropColumns call, no error is produced, but a bogus/incorrect database structure is left behind.

If the table is manipulated in subsequent migrations (or knex.schema promises), various errors are thrown, mostly of type Unhandled rejection Error: SQLITE_ERROR: table _knex_temp_alter3 has no column named column_five

3. Reduced test code, for example in https://npm.runkit.com/knex or if it needs real
   database connection to mysql or postgresql, then single file example which initializes
   needed data and demonstrates the problem.

Files required to reproduce (using sqlite3):

knexfile.js

const { knexSnakeCaseMappers } = require('objection');

module.exports = {
  development: {
    client: 'sqlite3',
    connection: {
      filename: './data/development.sqlite3',
    },
    useNullAsDefault: true,
    ...knexSnakeCaseMappers(),
  },
};

migrations/1_one.js

exports.up = function(knex, Promise) {
  return knex.schema.createTable('table_one', table => {
    table.string('column_one');
    table.float('column_two');
  });
};

exports.down = function(knex, Promise) {};

migrations/2_two.js

exports.up = function(knex, Promise) {
  return knex.schema.alterTable('table_one', table => {
    table.dropColumn('column_two');
  });
};

exports.down = function(knex, Promise) {};

migrations/3_three.js

  return knex.schema
    .createTable('table_two', table => {
      table.integer('column_one');
    })
    .table('table_one', table => {
      table.integer('column_three');
    })
};

exports.down = function(knex, Promise) {};

/wh

[elhigu]

Does your code work without snakeCaseMappers? Please add generated queries so that we can see where stuff goes wrong. Also try if you can reproduce this with single file, it will be easier to test. I would rather debug something that I can verify in 2 minutes instead of 10.

[elunic]

Hi, thanks your reply. Yes, the code works without the snakeCaseMappers.

When I reduce this to a single file, the outcome a random variant of (so far as I can tell):

• table_one is deleted and _knex_temp_alter3 is left over
• table_one is NOT deleted and _knex_temp_alter3 is left over

My bad about the single file, here it is. Note that running this without DEBUG=* does not produce a rejected promise (the output is "migrate finished"), but an uncaught Promise rejection error is output nonetheless.

const Knex = require("knex");
const { knexSnakeCaseMappers } = require("objection");

const knex = Knex({
  client: "sqlite3",
  connection: {
    filename: "./test.sqlite3"
  },
  useNullAsDefault: true,
  ...knexSnakeCaseMappers()
});

class MyMigrationSource {
  getMigrations() {
    return Promise.resolve(["migration1", "migration2", "migration3"]);
  }

  getMigrationName(migration) {
    return migration;
  }

  getMigration(migration) {
    switch (migration) {
      case "migration1":
        return {
          up(knex) {
            return knex.schema.createTable("table_one", table => {
              table.string("column_one");
              table.float("column_two");
            });
          },

          down(knex) {}
        };

      case "migration2":
        return {
          up(knex) {
            return knex.schema.alterTable("table_one", table => {
              table.dropColumn("column_two");
            });
          },

          down(knex) {}
        };

      case "migration3":
        return {
          up(knex) {
            return knex.schema
              .createTable("table_two", table => {
                table.integer("column_one");
              })
              .table("table_one", table => {
                table.integer("column_three");
              });
          },

          down(knex) {}
        };
    }
  }
}

knex.migrate.latest({ debug: true, migrationSource: new MyMigrationSource() }).then(
  () => {
    console.log("migrate finished");
    process.exit(0);
  },
  err => {
    console.error("migrate error: ", err);
    process.exit(1);
  }
);

Here's the output of running it:

$ DEBUG=* node index.js
  knex:client acquired connection from pool: __knexUid1 +0ms
  knex:query select * from sqlite_master where type = 'table' and name = ? undefined +0ms
  knex:bindings [ 'knex_migrations' ] undefined +0ms
  knex:client releasing connection to pool: __knexUid1 +12ms
  knex:client acquired connection from pool: __knexUid1 +1ms
  knex:query create table `knex_migrations` (`id` integer not null primary key autoincrement, `name` varchar(255), `batch` integer, `migration_time` datetime) undefined +13ms
  knex:bindings [] undefined +14ms
  knex:client releasing connection to pool: __knexUid1 +20ms
  knex:client acquired connection from pool: __knexUid1 +1ms
  knex:query select * from sqlite_master where type = 'table' and name = ? undefined +17ms
  knex:bindings [ 'knex_migrations_lock' ] undefined +16ms
  knex:client releasing connection to pool: __knexUid1 +2ms
  knex:client acquired connection from pool: __knexUid1 +1ms
  knex:query create table `knex_migrations_lock` (`index` integer not null primary key autoincrement, `is_locked` integer) undefined +3ms
  knex:bindings [] undefined +4ms
  knex:client releasing connection to pool: __knexUid1 +15ms
  knex:client acquired connection from pool: __knexUid1 +1ms
  knex:query select * from `knex_migrations_lock` undefined +17ms
  knex:bindings [] undefined +17ms
  knex:client releasing connection to pool: __knexUid1 +4ms
  knex:client acquired connection from pool: __knexUid1 +1ms
  knex:query insert into `knex_migrations_lock` (`is_locked`) values (?) undefined +4ms
  knex:bindings [ 0 ] undefined +4ms
  knex:client releasing connection to pool: __knexUid1 +16ms
  knex:client acquired connection from pool: __knexUid1 +1ms
  knex:query select `name` from `knex_migrations` order by `id` asc undefined +18ms
  knex:bindings [] undefined +17ms
  knex:client releasing connection to pool: __knexUid1 +3ms
  knex:tx trx2: Starting top level transaction +0ms
  knex:client acquired connection from pool: __knexUid1 +4ms
  knex:query BEGIN; trx2 +6ms
  knex:bindings undefined trx2 +6ms
  knex:query select * from `knex_migrations_lock` trx2 +4ms
  knex:bindings [] trx2 +4ms
  knex:query update `knex_migrations_lock` set `is_locked` = ? trx2 +3ms
  knex:bindings [ 1 ] trx2 +3ms
  knex:query select * from sqlite_master where type = 'table' and name = ? trx2 +3ms
  knex:bindings [ 'knex_migrations' ] trx2 +4ms
  knex:query select * from sqlite_master where type = 'table' and name = ? trx2 +2ms
  knex:bindings [ 'knex_migrations_lock' ] trx2 +2ms
  knex:query select * from `knex_migrations_lock` trx2 +3ms
  knex:bindings [] trx2 +3ms
  knex:query select `name` from `knex_migrations` order by `id` asc trx2 +2ms
  knex:bindings [] trx2 +2ms
  knex:query select max(`batch`) as `max_batch` from `knex_migrations` trx2 +3ms
  knex:bindings [] trx2 +3ms
  knex:query create table `table_one` (`column_one` varchar(255), `column_two` float) trx2 +4ms
  knex:bindings [] trx2 +4ms
  knex:query insert into `knex_migrations` (`batch`, `migration_time`, `name`) values (?, ?, ?) trx2 +3ms
  knex:bindings [ 1, 2019-02-06T08:54:35.474Z, 'migration1' ] trx2 +2ms
  knex:query PRAGMA table_info(`table_one`) trx2 +4ms
  knex:bindings [] trx2 +5ms
  knex:tx trx4: Starting top level transaction +35ms
  knex:query SAVEPOINT trx4; trx4 +4ms
  knex:bindings undefined trx4 +3ms
  knex:query insert into `knex_migrations` (`batch`, `migration_time`, `name`) values (?, ?, ?) trx4 +2ms
  knex:bindings [ 1, 2019-02-06T08:54:35.484Z, 'migration2' ] trx4 +3ms
  knex:query SELECT name, sql FROM sqlite_master WHERE type="table" AND name="table_one" trx4 +4ms
  knex:bindings [] trx4 +4ms
  knex:query create table `table_two` (`column_one` integer) trx4 +3ms
  knex:bindings [] trx4 +2ms
  knex:query CREATE TABLE `_knex_temp_alter3` (`column_one` varchar(255), `column_two` float) trx4 +3ms
  knex:bindings [] trx4 +4ms
  knex:query alter table `table_one` add column `column_three` integer trx4 +3ms
  knex:bindings [] trx4 +2ms
  knex:query SELECT * FROM "table_one" trx4 +2ms
  knex:bindings [] trx4 +3ms
  knex:query insert into `knex_migrations` (`batch`, `migration_time`, `name`) values (?, ?, ?) trx4 +2ms
  knex:bindings [ 1, 2019-02-06T08:54:35.501Z, 'migration3' ] trx4 +2ms
  knex:query DROP TABLE "table_one" trx4 +3ms
  knex:bindings [] trx4 +3ms
  knex:query update `knex_migrations_lock` set `is_locked` = ? trx4 +2ms
  knex:bindings [ 0 ] trx4 +2ms
  knex:query COMMIT; trx4 +3ms
  knex:bindings undefined trx4 +2ms
  knex:query CREATE TABLE `table_one` (`column_one` varchar(255)) trx4 +1ms
  knex:bindings [] trx4 +2ms
  knex:tx trx2: releasing connection +59ms
  knex:client releasing connection to pool: __knexUid1 +94ms
migrate finished

[elunic]

I've uploaded all this to a Git repo: https://gitlab.elunic.software/whefter/knex-snakecasemappers-demo

[elhigu]

From queries, looks like some sqlite3 schema methods are still not using wrapIdentifiers for quoting identifiers correctly.

[elunic]

@elhigu I managed to track it down, I believe. The runner, when querying, doesn't await the return value of client.processResponse(). Together with the special structure returned by TableCompiler_SQLite3.prototype.dropColumn and renameColumn - an object with the special output property which returns a Promise, this resulted in the Promise itself being handed to client.postProcessResponse(), instead of the awaited value.

The knexSnakeCaseMappers then mangled the Promise object's property names. I'm assuming that meant the Promise was not recognized as such.

The proposed solution (see PR) is to simply await the return value of client.processResponse(). This should be a risk-free change, since any non-promise value will simply be returned.

Let me know what you think! We're looking forward to having this in production very soon, as we currently have some projects that depend on ugly fixes to work around this.

[elhigu]

In theory change indeed did seem harmless, but I'm not sure if that postprocess response is meant to allow to return promise or not. If not, then the real problem is elsewhere. If yes, we need to check other dialects too if they have the same bug.

[elunic]

After getting more errors, I dug deeper and indeed found that that dropColumn and renameColumn have an identifier mapping problem. These:

• https://github.com/tgriesser/knex/blob/master/src/dialects/sqlite3/schema/ddl.js#L229
• https://github.com/tgriesser/knex/blob/master/src/dialects/sqlite3/schema/ddl.js#L264

use the unmapped identifier (in this case, snake_case), whereas the rows returned and passed to the iterator in reinsertData (row) have been processed by postProcessResponse, and might be camelCase.
I've added code to make sure the modifications to row are done with the correctly processed keys.

It does look like it was originally not meant to return a promise, and then the whole output() thing was added afterwards. Regardless, it works for both cases and does fix this issue. Other dialects would have the same bug if they use the same construct with output() returning a process (I didn't check).

[kibertoad]

Fixed in 0.16.4-next2