Mysql: insert: got an insertId, but actually no data inserted

[yangqiang]

My service works OK and all MySQL queries work fine after started. As time passes, 1 day to 1 week or so, an operation fails. The main reason is: it fails to insert a record to MySQL, and all the following MySQL queries(read/write) will fail untill the service is restarted. The related codes are:

self.conn.query(sql, function(err, res, fields){
    if(err){
        callback && callback(ERRCODE.MYSQL.code, err);
    }else{
        if (!res.insertId) {
            logger.error('activity.insertActivitySpeaker: insertId undefined');
        } else {
            logger.info('success: activity.insertActivitySpeaker: insertId %s', res.insertId);
        }
        callback && callback(0, res);
    }
});

When the insert error occurs, line

logger.info('success: activity.insertActivitySpeaker: insertId %s', res.insertId);

will still be executed and print an id. But there are no related operation logs in MySQL binlog and no record with the id printed in the database. MySQL read queries will always return empty result.

versions:
node: 6.9.5
mysqld Ver 5.5.47-0ubuntu0.14.04.1-log for debian-linux-gnu on x86_64 ((Ubuntu))
node-mysql: 2.10.0

Hope for some tips, thanks.

[sqlbot]

Log also the value of conn.threadId. This value will match the value of TRX_MYSQL_THREAD_ID in the information_schema.innodb_trx table if the current connection has an active transaction.

If you see transactions lingering in that table longer than expected, you almost certainly have a case where another part of your code is starting a transaction and inadvertently leaving it running, or disabling autocommit for that connection on the server and leaving it disabled... then you come along and happen to get that same connection object, and your insert is done in a transaction that is never committed.

The insertId comes from the server, which seems to indicate that the above is the only possible explanation -- you did insert the row, but due to mishandling of transaction state elsewhere in your code, that insert ultimately rolls back.

Transactions should not generally appear in the binlog until committed, so that is consistent with this diagnosis.

[yangqiang]

I added the extra log for conn.threadId. It takes an unexpected period of time to regenerate the error. I'm wonderring if

you did insert the row, but due to mishandling of transaction state elsewhere in your code, that insert ultimately rolls back.

How to explain

and all the following MySQL queries(read/write) will fail untill the service is restarted

Does it mean the connection became unusable after the insert error occured? If so, why no exception throws?

[sqlbot]

Does it mean the connection became unusable after the insert error occured?

No, the connection is not unusable, but it won't behave as expected, if it is getting into this state.

Also, please clarify what you mean about read queries failing. In what way to read queries fail?

[yangqiang]

A read query:

self.conn.query(sql, function(err, res, fields){
        if(err){
            callback && callback(ERRCODE.MYSQL.code, ERRCODE.MYSQL.hint);
        }else{
            // When insert error occurs, the following codes will always return callback(0, undefined);
            if(res === undefined) {
                callback && callback(0, res);
            } else if (res[0] === undefined){
                callback && callback(0, undefined);
            }else{
                callback && callback(0, res[0]);
            }
        }
    });

[sqlbot]

In what specific way does the read query fail?

[yangqiang]

Before insert error occurs, the return data res is exactly as expected.
When insert error occurs, the return data res will be undefined or null.

[yangqiang]

The error is reproduced and the log is as follows:

2018-06-04T13:14:56.664Z - error: debug conn.threadId: 7796202
2018-06-04T13:14:56.664Z - error: debug activity.insertActivitySpeaker insert ret: {"fieldCount":0,"affectedRows":1,"insertId":1215,"serverStatus":2,"warningCount":0,"message":"","protocol41":true,"changedRows":0}

2018-06-05T06:32:59.598Z - error: debug conn.threadId: 7829985
2018-06-05T06:32:59.600Z - error: debug activity.insertActivitySpeaker insert ret: {"fieldCount":0,"affectedRows":1,"insertId":1216,"serverStatus":3,"warningCount":0,"message":"","protocol41":true,"changedRows":0}

conn.threadId changed from 7796202 to 7829985, and serverStatus changed from 2 to 3.

This issue may be same as #1089

[sqlbot]

There it is. serverStatus is a bitmap, and the lsb set to 1 indicates that you are indeed in a transaction. Elsewhere, your code is doing something with this connection that is leaving a transaction running. The changes are getting written to the database but not committed, so they remain invisible.

[yangqiang]

Thank you very much!
The error is caused by missing rollbacks or commits in a transaction. It can be reproduced with following codes:

let mysql = require("mysql");

function createConn() {
    return mysql.createConnection({
        host     : '192.168.1.100',
        user     : 'yangqiang',
        password : '123456',
        database : 'node_mysql_demo'
    });
}

function transactionWithoutCommit(conn) {
    conn.beginTransaction(function (err) {
        if (err) {
            throw err;
        }
        conn.query('SELECT * from user where name="jonny"', function (error, results, fields) {
            if (error) {
                return conn.rollback(function () {
                    throw error;
                })
            } else {
                // no commit, causes the error
            }
        });
    });
}

function transactionWithCommit(conn) {
    conn.beginTransaction(function (err) {
        if (err) {
            throw err;
        }
        conn.query('SELECT * from user where name="jonny"', function (error, results, fields) {
            if (error) {
                return conn.rollback(function () {
                    throw error;
                })
            } else {
                conn.commit(function (err) {
                    if (err) {
                        return conn.rollback(function(){ throw err;})
                    } else {
                        console.log('transaction committed');
                    }
                });
            }
        });
    });
}

function write(conn) {
    conn.query('INSERT INTO user (name) VALUES ("Mei");', function (error, results, fields) {
        if (error) throw error;
        console.log(JSON.stringify(results));
    });
}


var connection = createConn();
connection.connect();

transactionWithoutCommit(connection); // block the following write
// transactionWithCommit(connection); // this is OK
write(connection);

[kai-koch]

As I read this, the error is in your code, and not mysqljs. Therefore I close the issue.
If I was mistaken, feel free to re-open this issue with further information..