"UNIQUE constraint failed" crashes

[OgelGames]

Recently I've noticed a number of these crashes, and I'm not sure if it needs looking into...

2020-02-23 09:42:42: ERROR[Main]: Failed to finalize m_stmt_create: UNIQUE constraint failed: auth.name
2020-02-23 09:42:42: ERROR[Main]: Failed to finalize m_stmt_begin: cannot start a transaction within a transaction
2020-02-23 09:42:55: ERROR[Main]: ServerError: AsyncErr: ServerThread::run Lua: Runtime error from mod '' in callback createAuth(): : UNIQUE constraint failed: auth.name
2020-02-23 09:42:55: ERROR[Main]: stack traceback:
2020-02-23 09:42:55: ERROR[Main]:   [C]: at 0x558210fbf980

2020-02-23 11:16:39: ERROR[Main]: Failed to finalize m_stmt_create: UNIQUE constraint failed: auth.name
2020-02-23 11:16:41: ERROR[Main]: ServerError: AsyncErr: ServerThread::run Lua: Runtime error from mod '' in callback createAuth(): : UNIQUE constraint failed: auth.name
2020-02-23 11:16:41: ERROR[Main]: stack traceback:
2020-02-23 11:16:41: ERROR[Main]:   [C]: at 0x5614a5849980

2020-02-24 14:42:01: ERROR[Main]: Failed to finalize m_stmt_create: UNIQUE constraint failed: auth.name
2020-02-24 14:42:01: ERROR[Main]: Failed to finalize m_stmt_begin: cannot start a transaction within a transaction
2020-02-24 14:42:13: ERROR[Main]: ServerError: AsyncErr: ServerThread::run Lua: Runtime error from mod '' in callback createAuth(): : UNIQUE constraint failed: auth.name
2020-02-24 14:42:13: ERROR[Main]: stack traceback:
2020-02-24 14:42:13: ERROR[Main]:   [C]: at 0x560207bab980

2020-02-25 12:48:31: ERROR[ConnectionReceive]: Peer not found (possible timeout)
2020-02-25 12:48:36: ERROR[Main]: Failed to finalize m_stmt_create: UNIQUE constraint failed: auth.name
2020-02-25 12:48:44: ERROR[Main]: ServerError: AsyncErr: ServerThread::run Lua: Runtime error from mod '' in callback createAuth(): : UNIQUE constraint failed: auth.name
2020-02-25 12:48:44: ERROR[Main]: stack traceback:
2020-02-25 12:48:44: ERROR[Main]:   [C]: at 0x55d15c406980

2020-03-01 22:07:27: ERROR[Main]: Failed to finalize m_stmt_create: UNIQUE constraint failed: auth.name
2020-03-01 22:07:27: ERROR[Main]: Failed to finalize m_stmt_begin: cannot start a transaction within a transaction
2020-03-01 22:07:33: ERROR[Main]: ServerError: AsyncErr: ServerThread::run Lua: Runtime error from mod '' in callback createAuth(): : UNIQUE constraint failed: auth.name
2020-03-01 22:07:33: ERROR[Main]: stack traceback:
2020-03-01 22:07:33: ERROR[Main]:   [C]: at 0x56142b1f6980

2020-03-02 21:14:59: ERROR[Main]: Failed to finalize m_stmt_create: UNIQUE constraint failed: auth.name
2020-03-02 21:15:11: ERROR[Main]: ServerError: AsyncErr: ServerThread::run Lua: Runtime error from mod '' in callback createAuth(): : UNIQUE constraint failed: auth.name
2020-03-02 21:15:11: ERROR[Main]: stack traceback:
2020-03-02 21:15:11: ERROR[Main]:   [C]: at 0x55d1cb802980

2020-03-03 10:06:16: ERROR[Main]: Failed to finalize m_stmt_create: UNIQUE constraint failed: auth.name
2020-03-03 10:06:16: ERROR[Main]: Failed to finalize m_stmt_begin: cannot start a transaction within a transaction
2020-03-03 10:06:21: ERROR[Main]: ServerError: AsyncErr: ServerThread::run Lua: Runtime error from mod '' in callback createAuth(): : UNIQUE constraint failed: auth.name
2020-03-03 10:06:21: ERROR[Main]: stack traceback:
2020-03-03 10:06:21: ERROR[Main]:   [C]: at 0x561802da3980

[S-S-X]

UNIQUE constraint failed tells us that something is wrong with database. It could be bug in database handlers but can also be caused by interrupted transaction and and partial recovery (crash committing stuff to db) or by not using transactions while adding or deleting data and failure during that.

It seems to be auth.name in all cases and therefore it would be good to check all linked tables. DB model can be seen here: https://github.com/minetest/minetest/blob/master/src/database/database-postgresql.cpp or of course better to extract that from actual database.

Whatever it is someone with direct access to database should check what exactly is broken, maybe fix that and then we might (or not) be able to find what actually caused it.

It might be also caused by attempt to add invalid data into database but whatever it is it would be good to check if there's any hints inside database.

[BuckarooBanzay]

UNIQUE constraint failed tells us that something is wrong with database. It could be bug in database handlers but can also be caused by interrupted transaction and and partial recovery (crash committing stuff to db) or by not using transactions while adding or deleting data and failure during that.

This looks like the auth-database, it is still an sqlite3-based database as postgres is not yet implemented for the auth data.

I try to see if i can find something in the log-files but i have the feeling it does not hit the logs at this point...

[S-S-X]

it is still an sqlite3-based database

Same thing different engine, sqlite3 also uses foreign keys. So difference here is that it is not postgres database that has to be checked but sqlite3 database.

Foreign key constraints should hold whatever db engine is used and checks are similar. Therefore I would still recommend checking integrity of data stored in database.

edit. It seems that sqlite3 browser has integrity check function: https://sqlitebrowser.org/ if that works then you don't have to write script for data integrity check. If it find problems then it comes down to either deleting invalid data or fixing it manually by adding missing data to db.

But then looking at https://www.sqlite.org/pragma.html#pragma_integrity_check

PRAGMA integrity_check does not find FOREIGN KEY errors. Use the PRAGMA foreign_key_check command for to find errors in FOREIGN KEY constraints.

So actually these are builtin things \o/ very nice. You should try those and see what you get. I do not have much experience with sqlite so can't tell how well those actually work.

[BuckarooBanzay]

Proper stacktrace:

src/script/lua_api/l_auth.cpp:153

// auth_create(table)
int ModApiAuth::l_auth_create(lua_State *L)
{
        NO_MAP_LOCK_REQUIRED;
        AuthDatabase *auth_db = getAuthDb(L);
        if (!auth_db)
                return 0;
        luaL_checktype(L, 1, LUA_TTABLE);
        int table = 1;
        AuthEntry authEntry;
        bool success;
        // no meaningful id field, we assume
        success = getstringfield(L, table, "name", authEntry.name);
        success = success && getstringfield(L, table, "password", authEntry.password);
        lua_getfield(L, table, "privileges");
        if (lua_istable(L, -1)) {
                lua_pushnil(L);
                while (lua_next(L, -2)) {
                        authEntry.privileges.emplace_back(
                                        lua_tostring(L, -2)); // the key, not the value
                        lua_pop(L, 1);
                }
        } else {
                success = false;
        }
        lua_pop(L, 1); // the table
        success = success && getintfield(L, table, "last_login", authEntry.last_login);

        if (!success)
                return 0;

        if (auth_db->createAuth(authEntry)) { //XXX <-- Crash here
                pushAuthEntry(L, authEntry);
                return 1;
        }

        return 0;
}

Prepared statement:

INSERT INTO auth (name, password, last_login) VALUES (?, ?, ?)

Database code:

bool AuthDatabaseSQLite3::createAuth(AuthEntry &authEntry)
{
        beginSave();

        // id autoincrements
        str_to_sqlite(m_stmt_create, 1, authEntry.name); // XXX <--- duplicate entry here
        str_to_sqlite(m_stmt_create, 2, authEntry.password);
        int64_to_sqlite(m_stmt_create, 3, authEntry.last_login);
        sqlite3_vrfy(sqlite3_step(m_stmt_create), SQLITE_DONE);
        sqlite3_reset(m_stmt_create);

        // obtain id and write back to original authEntry
        sqlite3_step(m_stmt_last_insert_rowid);
        authEntry.id = sqlite_to_uint(m_stmt_last_insert_rowid, 0);
        sqlite3_reset(m_stmt_last_insert_rowid);

        writePrivileges(authEntry);

        endSave();
        return true;
}

Call sources for createAuth():

./serverenvironment.cpp:2235:           success = success && dstdb->createAuth(authEntry);
./network/serverpackethandler.cpp:1573:     m_script->createAuth(playername, initial_ver_key);
./network/serverpackethandler.cpp:1776:     m_script->createAuth(playername, client->enc_pwd);
./script/lua_api/l_auth.cpp:153:    if (auth_db->createAuth(authEntry)) {

TODO

• [x] log queries from createAuth (patch in https://github.com/pandorabox-io/minetest_docker)

[BuckarooBanzay]

fixed with https://github.com/pandorabox-io/minetest_docker/commit/0f01a8cf4fcc11c776f1208a8f3d16776d860d5b

TODO

• [x] Deploy new image
• [x] Bring issue upstream with repro...

[BuckarooBanzay]

Upstream issue: https://github.com/minetest/minetest/issues/9498