Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CompletionException: Duplicate Key Exists in SQL webpermissionspatch #3543

Closed
smhcnshn opened this issue Mar 29, 2024 · 4 comments
Closed

CompletionException: Duplicate Key Exists in SQL webpermissionspatch #3543

smhcnshn opened this issue Mar 29, 2024 · 4 comments
Labels
Bug Issues that contain unintended behavior

Comments

@smhcnshn
Copy link

Describe the issue

Running plan on a velocity proxy and a backend gameserver, completed the proxy setup, however running plan jar and updating its config on the gameserver lead to the issue

Exceptions & Other Logs

[02:02:04] [Plan MySQLDB-transaction-thread-1/INFO]: [Plan] Applying Patch: UpdateWebPermissionsPatch..
[02:02:04] [Plan MySQLDB-transaction-thread-1/ERROR]: [Plan] Database failed to open, com.djrapitops.plan.storage.database.transactions.patches.UpdateWebPermissionsPatch failed to be executed.
[02:02:04] [Plan MySQLDB-transaction-thread-1/ERROR]: [Plan] What to do: Report this, duplicate key exists in SQL.
[02:02:04] [Plan MySQLDB-transaction-thread-1/ERROR]: [Plan] Ran into CompletionException - logged to plugins\Plan\logs\CompletionException-6d69bff306.txt
[02:02:04] [Plan MySQLDB-transaction-thread-1/ERROR]: [Plan] (INCLUDE CONTENTS OF THE FILE IN ANY REPORTS)
[02:02:04] [Plan MySQLDB-transaction-thread-1/ERROR]: [Plan] What to do: Report this, duplicate key exists in SQL.
[02:02:04] [Plan MySQLDB-transaction-thread-1/ERROR]: [Plan] CRITICAL error triggered a plugin shutdown.
[02:02:04] [Plan MySQLDB-transaction-thread-1/INFO]: [Plan] Processing complete.
[02:02:04] [Plan MySQLDB-transaction-thread-1/INFO]: [Plan] Waiting for unfinished transactions to avoid data loss..
[02:02:04] [Craft Scheduler Thread - 24 - Plan/INFO]: [Plan] You're using the latest version.
[02:02:24] [Plan MySQLDB-transaction-thread-1/INFO]: [Plan] Player Analytics Disabled.
[02:02:24] [Plan Reload Thread/ERROR]: [Plan] ----------------------------------------
[02:02:24] [Plan Reload Thread/ERROR]: [Plan] Error: Failed to read Server information from Database: SQL Failure: HikariDataSource HikariDataSource (Plan Connection Pool-2) has been closed.
[02:02:24] [Plan Reload Thread/ERROR]: [Plan] ----------------------------------------
[02:02:24] [Plan Reload Thread/ERROR]: [Plan] Plugin Failed to Initialize Correctly. If this issue is caused by config settings you can use /plan reload

6d69bff306 - Last occurred: 2024-03-30 Occurrences: 2
---- Context 2 ----
Plan v5.6 build 2820
Pufferfish git-Pufferfish-32 (MC: 1.20.2)
Server v1.20.2-R0.1-SNAPSHOT

Report this, duplicate key exists in SQL.
Transaction: class com.djrapitops.plan.storage.database.transactions.patches.UpdateWebPermissionsPatch
DB State: CLOSED - fatal: true
Error code: 1062
INSERT INTO plan_web_permission (permission) VALUES (?)
Duplicate key

---- Context 1 ----
Plan v5.6 build 2820
Pufferfish git-Pufferfish-32 (MC: 1.20.2)
Server v1.20.2-R0.1-SNAPSHOT

Report this, duplicate key exists in SQL.
Transaction: class com.djrapitops.plan.storage.database.transactions.patches.UpdateWebPermissionsPatch
DB State: CLOSED - fatal: true
Error code: 1062
INSERT INTO plan_web_permission (permission) VALUES (?)
Duplicate key

---- Stacktrace ----
java.util.concurrent.CompletionException: com.djrapitops.plan.exceptions.database.FatalDBException: com.djrapitops.plan.storage.database.transactions.patches.UpdateWebPermissionsPatch failed to execute and database could not be opened: SQL Failure: Duplicate entry 'page.network.overview' for key 'permission'
   java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:315)
   java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:320)
   java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1770)
   java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
   java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
   java.base/java.lang.Thread.run(Thread.java:842)
Caused by:
com.djrapitops.plan.exceptions.database.FatalDBException: com.djrapitops.plan.storage.database.transactions.patches.UpdateWebPermissionsPatch failed to execute and database could not be opened: SQL Failure: Duplicate entry 'page.network.overview' for key 'permission'
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.init.OperationCriticalTransaction.executeTransaction(OperationCriticalTransaction.java:41)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.lambda$executeTransaction$4(SQLDB.java:373)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.DBAccessLock.performDatabaseOperation(DBAccessLock.java:61)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.DBAccessLock.performDatabaseOperation(DBAccessLock.java:56)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.lambda$executeTransaction$5(SQLDB.java:372)
   java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
   java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
   java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
   java.base/java.lang.Thread.run(Thread.java:842)
Caused by:
java.sql.BatchUpdateException: Duplicate entry 'page.network.overview' for key 'permission'
   com.mysql.cj.jdbc.exceptions.SQLError.createBatchUpdateException(SQLError.java:224)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchWithMultiValuesClause(ClientPreparedStatement.java:718)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchInternal(ClientPreparedStatement.java:409)
   com.mysql.cj.jdbc.StatementImpl.executeBatch(StatementImpl.java:795)
   Plan-5.6-build-2820.jar//plan.com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:127)
   Plan-5.6-build-2820.jar//plan.com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch(HikariProxyPreparedStatement.java)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.ExecBatchStatement.callExecute(ExecBatchStatement.java:35)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.ExecStatement.execute(ExecStatement.java:64)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.ExecStatement.execute(ExecStatement.java:55)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.Transaction.execute(Transaction.java:223)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.patches.UpdateWebPermissionsPatch.applyPatch(UpdateWebPermissionsPatch.java:58)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.patches.Patch.performOperations(Patch.java:62)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.Transaction.executeTransaction(Transaction.java:89)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.init.OperationCriticalTransaction.executeTransaction(OperationCriticalTransaction.java:36)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.lambda$executeTransaction$4(SQLDB.java:373)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.DBAccessLock.performDatabaseOperation(DBAccessLock.java:61)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.DBAccessLock.performDatabaseOperation(DBAccessLock.java:56)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.lambda$executeTransaction$5(SQLDB.java:372)
   java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
   java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
   java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
   java.base/java.lang.Thread.run(Thread.java:842)
Caused by:
java.sql.SQLIntegrityConstraintViolationException: Duplicate entry 'page.network.overview' for key 'permission'
   com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:118)
   com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:916)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1061)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1009)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1320)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchWithMultiValuesClause(ClientPreparedStatement.java:679)
   com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchInternal(ClientPreparedStatement.java:409)
   com.mysql.cj.jdbc.StatementImpl.executeBatch(StatementImpl.java:795)
   Plan-5.6-build-2820.jar//plan.com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:127)
   Plan-5.6-build-2820.jar//plan.com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch(HikariProxyPreparedStatement.java)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.ExecBatchStatement.callExecute(ExecBatchStatement.java:35)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.ExecStatement.execute(ExecStatement.java:64)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.ExecStatement.execute(ExecStatement.java:55)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.Transaction.execute(Transaction.java:223)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.patches.UpdateWebPermissionsPatch.applyPatch(UpdateWebPermissionsPatch.java:58)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.patches.Patch.performOperations(Patch.java:62)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.Transaction.executeTransaction(Transaction.java:89)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.transactions.init.OperationCriticalTransaction.executeTransaction(OperationCriticalTransaction.java:36)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.lambda$executeTransaction$4(SQLDB.java:373)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.DBAccessLock.performDatabaseOperation(DBAccessLock.java:61)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.DBAccessLock.performDatabaseOperation(DBAccessLock.java:56)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.lambda$executeTransaction$5(SQLDB.java:372)
   java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
   java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
   java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
   java.base/java.lang.Thread.run(Thread.java:842)
   java.base/java.lang.Thread.getStackTrace(Thread.java:1621)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.executeTransaction(SQLDB.java:359)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.setupDatabase(SQLDB.java:264)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.SQLDB.init(SQLDB.java:162)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.DBSystem.enable(DBSystem.java:103)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.storage.database.BukkitDBSystem.enable(BukkitDBSystem.java:54)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.PlanSystem.enableSystems(PlanSystem.java:181)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.PlanSystem.enableOtherThanCommands(PlanSystem.java:138)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.PlanSystem.enable(PlanSystem.java:176)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.Plan.onEnable(Plan.java:82)
   Plan-5.6-build-2820.jar//com.djrapitops.plan.commands.subcommands.PluginStatusCommands.lambda$onReload$0(PluginStatusCommands.java:76)
   java.base/java.lang.Thread.run(Thread.java:842)

Plugin versions

Plan version 5.6 build 2820

Additional information
@smhcnshn smhcnshn added the Bug Issues that contain unintended behavior label Mar 29, 2024
@AuroraLS3
Copy link
Collaborator

Does this occur every time? It sounds like two servers might have tried to do the same patch at the same time

@smhcnshn
Copy link
Author

yeah it happens everytime, i just set up a velocity instance and a gameserver right after and this popped up inside gameserver

AuroraLS3 added a commit that referenced this issue Mar 30, 2024
@AuroraLS3
Attempt to fix duplicate key issue in UpdateWebPermissionsPatch
49269d3 
Affects issues:
- #3543
@AuroraLS3
Copy link
Collaborator

A build with an attempted fix should appear here in 10 minutes https://github.com/plan-player-analytics/Plan/actions/runs/8489325894

It's a bit odd bug since there's some logic in there that should prevent this sort of thing from happening, so I think there's two transactions trying to modify the same table and one fails.

I added some code to check the list again for missing permissions before insert if it fails with duplicate key error, but it might be due to the configured isolation level in the mysql leading to reading out of date table contents

@AuroraLS3
Copy link
Collaborator

If that build doesn't fix it, this definitely does since it will ignore duplicate inserts on the database level (for this particular patch) rather than figuring it out in Java https://github.com/plan-player-analytics/Plan/actions/runs/8489430769

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug Issues that contain unintended behavior
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@AuroraLS3 @smhcnshn