QuiltServerTools / Ledger

A server-side logging mod for fabric 1.17+
https://www.quiltservertools.net/Ledger/latest/
GNU Lesser General Public License v3.0
190 stars 52 forks source link

Can't insert some actions to MySQL database, and search, rollback or restore and etc after fail #285

Open HyperPaint opened 4 months ago

HyperPaint commented 4 months ago

Expected behavior

Actions inserted as always

Observed/actual behavior

Log messages like this when mod tries insert actions

[11:52:04] [DefaultDispatcher-worker-2/WARN] (Exposed) Transaction attempt #7 failed: java.sql.BatchUpdateException: Data truncation: Data too long for column 'extra_data' at row 41. Statement(s): INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); INSERT INTO actions (action_id, block_state, extra_data, object_id, old_block_state, old_object_id, player_id, rolled_back, source, time, world_id, x, y, z) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) org.jetbrains.exposed.exceptions.ExposedSQLException: java.sql.BatchUpdateException: Data truncation: Data too long for column 'extra_data' at row 41 at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:94) ~[ledger.jar:?] at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:244) ~[ledger.jar:?] at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:221) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.Statement.execute(Statement.kt:55) ~[ledger.jar:?] at org.jetbrains.exposed.sql.QueriesKt.executeBatch(Queries.kt:302) ~[ledger.jar:?] at org.jetbrains.exposed.sql.QueriesKt.batchInsert(Queries.kt:201) ~[ledger.jar:?] at org.jetbrains.exposed.sql.QueriesKt.batchInsert(Queries.kt:176) ~[ledger.jar:?] at org.jetbrains.exposed.sql.QueriesKt.batchInsert$default(Queries.kt:171) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager.insertActions(DatabaseManager.kt:416) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager.access$insertActions(DatabaseManager.kt:68) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager$logActionBatch$2.invokeSuspend(DatabaseManager.kt:341) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager$logActionBatch$2.invoke(DatabaseManager.kt) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager$logActionBatch$2.invoke(DatabaseManager.kt) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager$execute$2.invokeSuspend(DatabaseManager.kt:382) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager$execute$2.invoke(DatabaseManager.kt) ~[ledger.jar:?] at com.github.quiltservertools.ledger.database.DatabaseManager$execute$2.invoke(DatabaseManager.kt) ~[ledger.jar:?] at org.jetbrains.exposed.sql.transactions.experimental.SuspendedKt$suspendedTransactionAsyncInternal$1.invokeSuspend(Suspended.kt:187) ~[ledger.jar:?] at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) ~[org_jetbrains_kotlin_kotlin-stdlib-2.0.0-e823d47a24b16be4.jar:?] at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104) ~[org_jetbrains_kotlinx_kotlinx-coe-jvm-1.8.1-682b081a811ff4e1.jar:?] at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:111) ~[org_jetbrains_kotlinx_kotlinx-coe-jvm-1.8.1-682b081a811ff4e1.jar:?] at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:99) ~[org_jetbrains_kotlinx_kotlinx-coe-jvm-1.8.1-682b081a811ff4e1.jar:?] at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584) ~[org_jetbrains_kotlinx_kotlinx-coe-jvm-1.8.1-682b081a811ff4e1.jar:?] at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:811) ~[org_jetbrains_kotlinx_kotlinx-coe-jvm-1.8.1-682b081a811ff4e1.jar:?] at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:715) ~[org_jetbrains_kotlinx_kotlinx-coe-jvm-1.8.1-682b081a811ff4e1.jar:?] at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:702) ~[org_jetbrains_kotlinx_kotlinx-coe-jvm-1.8.1-682b081a811ff4e1.jar:?] Caused by: java.sql.BatchUpdateException: Data truncation: Data too long for column 'extra_data' at row 41 at com.mysql.cj.jdbc.exceptions.SQLError.createBatchUpdateException(SQLError.java:223) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchWithMultiValuesClause(ClientPreparedStatement.java:716) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchInternal(ClientPreparedStatement.java:407) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.StatementImpl.executeBatch(StatementImpl.java:802) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:127) ~[com_zaxxer_hikaricp-5.1.0-a2ab78c3c3386cdb.jar:?] at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch(HikariProxyPreparedStatement.java) ~[com_zaxxer_hikaricp-5.1.0-a2ab78c3c3386cdb.jar:?] at org.jetbrains.exposed.sql.statements.jdbc.JdbcPreparedStatementImpl.executeBatch(JdbcPreparedStatementImpl.kt:91) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.InsertStatement.execInsertFunction(InsertStatement.kt:158) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:168) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:18) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:92) ~[ledger.jar:?] ... 24 more Caused by: com.mysql.cj.jdbc.exceptions.MysqlDataTruncation: Data truncation: Data too long for column 'extra_data' at row 41 at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:104) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:555) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:339) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1054) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1003) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1312) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchWithMultiValuesClause(ClientPreparedStatement.java:677) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchInternal(ClientPreparedStatement.java:407) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.mysql.cj.jdbc.StatementImpl.executeBatch(StatementImpl.java:802) ~[com_mysql_mysql-connector-j-8.3.0-ecd0628c956d655f.jar:?] at com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:127) ~[com_zaxxer_hikaricp-5.1.0-a2ab78c3c3386cdb.jar:?] at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch(HikariProxyPreparedStatement.java) ~[com_zaxxer_hikaricp-5.1.0-a2ab78c3c3386cdb.jar:?] at org.jetbrains.exposed.sql.statements.jdbc.JdbcPreparedStatementImpl.executeBatch(JdbcPreparedStatementImpl.kt:91) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.InsertStatement.execInsertFunction(InsertStatement.kt:158) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:168) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:18) ~[ledger.jar:?] at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:92) ~[ledger.jar:?] ... 24 more [11:52:04] [DefaultDispatcher-worker-2/WARN] (Exposed) Wait 979597 milliseconds before retrying

No logs, but message Text.translatable("error.ledger.command.no_results") when search after error. Maybe connection pool is busy

And queue in ledger status stacking up to 18 thousands and so on...

Steps/models to reproduce

idk, it seems like some action has very big extra data

What operating system are you running

Linux

Minecraft version

1.20.4

Ledger version

1.3.1

Logs

useful logs in Observed/actual behavior

Agreements

Other

Maybe changing column extra data from text to medium text will help

HyperPaint commented 4 months ago

its written book with 100 pages...

Text in book moves to extra_data field and then entry can't insert, because extra_data is TEXT type (64 KiB)

HyperPaint commented 4 months ago

Maybe ignore action like this? And it seems like that mod should check variable size before insert in database and trunc data

HyperPaint commented 4 months ago

Converted extra_data, block_state and old_block_state to MEDIUMTEXT and problem solved

ScorNinja commented 4 months ago

Also database collation is limited with the default chosen latin1_swedish_ci. I updated mine to use utf8mb4_general_ci which allows expanded characters in the utf range to be supported.

HyperPaint commented 2 weeks ago

Better to use utf8mb4_unicode_520_ci collation