Failed upgrade from 5.0 to 5.3

Nebula3 years ago

Hey all,
I've traccar running in docker and its using MSSQL as DB. Tried to perform the update from 5.0 to 5.3 as server failed to start with following error:

2022-08-14 23:40:18  INFO: Shutting down server...
2022-08-14 23:58:57  INFO: Operating system name: Linux version: 5.15.41-0-virt architecture: amd64
2022-08-14 23:58:57  INFO: Java runtime name: OpenJDK 64-Bit Server VM vendor: Alpine version: 11.0.16+8-alpine-r0
2022-08-14 23:58:57  INFO: Memory limit heap: 494mb non-heap: 0mb
2022-08-14 23:58:57  INFO: Character encoding: UTF-8 charset: UTF-8
2022-08-14 23:58:57  INFO: Version: 5.3
2022-08-14 23:58:57  INFO: Starting server...
2022-08-14 23:58:58  INFO: HikariPool-1 - Starting...
2022-08-14 23:58:59  INFO: HikariPool-1 - Added connection ConnectionID:1 ClientConnectionId: 3014b448-85c4-4b28-9689-8a352a0a851a
2022-08-14 23:58:59  INFO: HikariPool-1 - Start completed.
2022-08-14 23:59:00  INFO: Set default schema name to dbo
2022-08-14 23:59:00  INFO: Clearing database change log checksums
2022-08-14 23:59:00  INFO: Successfully acquired change log lock
2022-08-14 23:59:02  INFO: Successfully released change log lock
2022-08-14 23:59:02  INFO: Successfully acquired change log lock
2022-08-14 23:59:02  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.json.JsonChangeLogParser Unable to get public no-arg constructor
2022-08-14 23:59:02  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.yaml.YamlChangeLogParser Unable to get public no-arg constructor
2022-08-14 23:59:05  INFO: Reading from DATABASECHANGELOG
2022-08-14 23:59:06  INFO: Reading from DATABASECHANGELOG
2022-08-14 23:59:06  INFO: Cannot load service: liquibase.hub.HubService: Provider liquibase.hub.core.StandardHubService could not be instantiated
2022-08-14 23:59:06  INFO: Index idx_drivers_uniqueid created
2022-08-14 23:59:06  INFO: Index idx_devices_uniqueid created
2022-08-14 23:59:06  INFO: Index idx_users_email created
2022-08-14 23:59:06  INFO: Index idx_users_login created
2022-08-14 23:59:06  INFO: Index idx_users_token created
2022-08-14 23:59:06  INFO: Columns overlayurl(VARCHAR(512)) added to tc_servers
2022-08-14 23:59:06  INFO: ChangeSet changelog-5.1::changelog-5.1::author ran successfully in 200ms
2022-08-14 23:59:06  INFO: Columns status(CHAR(8)) added to tc_devices
2022-08-14 23:59:06  INFO: Columns geofenceIds(VARCHAR(128)) added to tc_devices
2022-08-14 23:59:06  INFO: ChangeSet changelog-5.2::changelog-5.2::author ran successfully in 18ms
2022-08-14 23:59:07  INFO: Columns fixedemail(BOOLEAN) added to tc_servers
2022-08-14 23:59:07  INFO: Columns fixedemail(BOOLEAN) added to tc_users
2022-08-14 23:59:07  INFO: Columns expirationtime(TIMESTAMP) added to tc_devices
2022-08-14 23:59:07  INFO: Table tc_keystore created
2022-08-14 23:59:07  INFO: Successfully released change log lock
2022-08-14 23:59:07 ERROR: Main method error - The index 'idx_users_token' is dependent on column 'token'. - SQLServerException (... < DatabaseModule:96 < <gener:-1 < *:-1 < ... < Main:126 < ...)
2022-08-14 23:59:14  INFO: Operating system name: Linux version: 5.15.41-0-virt architecture: amd64
2022-08-14 23:59:14  INFO: Java runtime name: OpenJDK 64-Bit Server VM vendor: Alpine version: 11.0.16+8-alpine-r0
2022-08-14 23:59:14  INFO: Memory limit heap: 494mb non-heap: 0mb
2022-08-14 23:59:14  INFO: Character encoding: UTF-8 charset: UTF-8
2022-08-14 23:59:14  INFO: Version: 5.3
2022-08-14 23:59:14  INFO: Starting server...
2022-08-14 23:59:15  INFO: HikariPool-1 - Starting...
2022-08-14 23:59:16  INFO: HikariPool-1 - Added connection ConnectionID:1 ClientConnectionId: a9fa4ec3-6020-487c-8031-1ae4df4b1ec6
2022-08-14 23:59:16  INFO: HikariPool-1 - Start completed.
2022-08-14 23:59:17  INFO: Set default schema name to dbo
2022-08-14 23:59:17  INFO: Clearing database change log checksums
2022-08-14 23:59:17  INFO: Successfully acquired change log lock
2022-08-14 23:59:18  INFO: Successfully released change log lock
2022-08-14 23:59:18  INFO: Successfully acquired change log lock
2022-08-14 23:59:18  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.json.JsonChangeLogParser Unable to get public no-arg constructor
2022-08-14 23:59:18  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.yaml.YamlChangeLogParser Unable to get public no-arg constructor
2022-08-14 23:59:21  INFO: Reading from DATABASECHANGELOG
2022-08-14 23:59:22  INFO: Reading from DATABASECHANGELOG
2022-08-14 23:59:23  INFO: Cannot load service: liquibase.hub.HubService: Provider liquibase.hub.core.StandardHubService could not be instantiated
2022-08-14 23:59:23  INFO: Columns fixedemail(BOOLEAN) added to tc_servers
2022-08-14 23:59:23  INFO: Columns fixedemail(BOOLEAN) added to tc_users
2022-08-14 23:59:23  INFO: Columns expirationtime(TIMESTAMP) added to tc_devices
2022-08-14 23:59:23  INFO: Table tc_keystore created
2022-08-14 23:59:23  INFO: Successfully released change log lock
2022-08-14 23:59:23 ERROR: Main method error - The index 'idx_users_token' is dependent on column 'token'. - SQLServerException (... < DatabaseModule:96 < <gener:-1 < *:-1 < ... < Main:126 < ...)

Digging into it I came across this and it looks like this was already merged into 5.3.

As a desperate attempt to get my server back online, I tried reverting back to 5.2 then 5.1 and then finally to 5.0. When trying 5.0 image I was getting following error:

traccar    | Exception in thread "main" java.lang.RuntimeException: liquibase.exception.LockException: liquibase.exception.DatabaseException: Expected single row from liquibase.statement.core.SelectFromDatabaseChangeLogLockStatement@58f174d9 but got 0
traccar    | 	at org.traccar.Main.run(Main.java:147)
traccar    | 	at org.traccar.Main.main(Main.java:106)
traccar    | Caused by: liquibase.exception.LockException: liquibase.exception.DatabaseException: Expected single row from liquibase.statement.core.SelectFromDatabaseChangeLogLockStatement@58f174d9 but got 0

Thought this might be due to downgrade to 5.2 and 5.1 that I attempted so I removed last two rows from DATABASECHANGELOG that were about 5.2 and 5.1. I'm still getting:

traccar    | Exception in thread "main" java.lang.RuntimeException: liquibase.exception.LockException: liquibase.exception.DatabaseException: Expected single row from liquibase.statement.core.SelectFromDatabaseChangeLogLockStatement@7ff2b8d2 but got 0
traccar    | 	at org.traccar.Main.run(Main.java:145)
traccar    | 	at org.traccar.Main.main(Main.java:107)
traccar    | Caused by: liquibase.exception.LockException: liquibase.exception.DatabaseException: Expected single row from liquibase.statement.core.SelectFromDatabaseChangeLogLockStatement@7ff2b8d2 but got 0

Can anyone please guide me on how to fix this. Thank you

Joystick3 years ago

Have you tried to drop it with sql query directly in your database?

DROP INDEX idx_users_token ON tc_users;
Nebula3 years ago

Did that but still getting this error:

traccar    | Exception in thread "main" java.lang.RuntimeException: com.google.inject.ProvisionException: Unable to provision, see the following errors:
traccar    |
traccar    | 1) [Guice/ErrorInCustomProvider]: LockException: DatabaseException: Expected single row from SelectFromDatabaseChangeLogLockStatement@149c3204 but got 0
traccar    |   at DatabaseModule.provideDataSource(DatabaseModule.java:46)
traccar    |   at DatabaseStorage.<init>(DatabaseStorage.java:48)
traccar    |       \_ for 2nd parameter
traccar    |   while locating DatabaseStorage
traccar    |   while locating Storage
traccar    |
traccar    | Learn more:
traccar    |   https://github.com/google/guice/wiki/ERROR_IN_CUSTOM_PROVIDER
traccar    |
traccar    | 1 error
traccar    |
traccar    | ======================
traccar    | Full classname legend:
traccar    | ======================
traccar    | DatabaseException:                        "liquibase.exception.DatabaseException"
traccar    | DatabaseModule:                           "org.traccar.storage.DatabaseModule"
traccar    | DatabaseStorage:                          "org.traccar.storage.DatabaseStorage"
traccar    | LockException:                            "liquibase.exception.LockException"
traccar    | SelectFromDatabaseChangeLogLockStatement: "liquibase.statement.core.SelectFromDatabaseChangeLogLockStatement"
traccar    | Storage:                                  "org.traccar.storage.Storage"
traccar    | ========================
traccar    | End of classname legend:
traccar    | ========================
traccar    |
traccar    | 	at org.traccar.Main.run(Main.java:154)
traccar    | 	at org.traccar.Main.main(Main.java:114)
traccar    | Caused by: com.google.inject.ProvisionException: Unable to provision, see the following errors:

I'm guessing 149c3204 is the deploymentID or something but since I've deleted two rows from DATABASECHANGELOG its not matching. Do you know where this 149c3204 is coming from? I dont see anything else in traccar's data directory.

Anton Tananaev3 years ago

Why did you remove stuff from DATABASECHANGELOG? You should just reset the lock status.

Nebula3 years ago

That was my bad, I wrongly assumed when downgrading to 5 from 5.3 that it'll need those rows removed.

Anton Tananaev3 years ago

I think the easiest way is to restore the database from a backup and run the upgrade again.

Nebula3 years ago

I'll give it a try, thank you

Nebula3 years ago

Alright, so I restored db from backup, and then tried running 5.3. As expected, it was complaining about idx_users_token which I dropped manually using DROP INDEX idx_users_token ON tc_users;

But its still failing to start with following error:

2022-08-15 22:11:48  INFO: Operating system name: Linux version: 5.15.41-0-virt architecture: amd64
2022-08-15 22:11:48  INFO: Java runtime name: OpenJDK 64-Bit Server VM vendor: Alpine version: 11.0.16+8-alpine-r0
2022-08-15 22:11:48  INFO: Memory limit heap: 494mb non-heap: 0mb
2022-08-15 22:11:48  INFO: Character encoding: UTF-8 charset: UTF-8
2022-08-15 22:11:48  INFO: Version: 5.3
2022-08-15 22:11:48  INFO: Starting server...
2022-08-15 22:11:48  INFO: HikariPool-1 - Starting...
2022-08-15 22:11:49  INFO: HikariPool-1 - Added connection ConnectionID:1 ClientConnectionId: 2633325e-42e5-4ac5-8c37-7ecb9fc91979
2022-08-15 22:11:49  INFO: HikariPool-1 - Start completed.
2022-08-15 22:11:50  INFO: Set default schema name to dbo
2022-08-15 22:11:50  INFO: Clearing database change log checksums
2022-08-15 22:11:50  INFO: Successfully acquired change log lock
2022-08-15 22:11:51  INFO: Successfully released change log lock
2022-08-15 22:11:51  INFO: Successfully acquired change log lock
2022-08-15 22:11:51  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.json.JsonChangeLogParser Unable to get public no-arg constructor
2022-08-15 22:11:51  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.yaml.YamlChangeLogParser Unable to get public no-arg constructor
2022-08-15 22:11:54  INFO: Reading from DATABASECHANGELOG
2022-08-15 22:11:55  INFO: Reading from DATABASECHANGELOG
2022-08-15 22:11:55  INFO: Cannot load service: liquibase.hub.HubService: Provider liquibase.hub.core.StandardHubService could not be instantiated
2022-08-15 22:11:55  INFO: Successfully released change log lock

The service keeps restarting with following in logs:

2022-08-15 22:16:46  INFO: jetty-10.0.7; built: 2021-10-06T19:34:02.766Z; git: da8a4553af9dd84080931fa0f8c678cd2d60f3d9; jvm 11.0.16+8-alpine-r0
2022-08-15 22:16:48  INFO: Started o.t.w.@52cb52bd{/,null,AVAILABLE}
2022-08-15 22:16:49  INFO: Session workerName=node0
2022-08-15 22:16:58  INFO: Operating system name: Linux version: 5.15.41-0-virt architecture: amd64
2022-08-15 22:16:58  INFO: Java runtime name: OpenJDK 64-Bit Server VM vendor: Alpine version: 11.0.16+8-alpine-r0
2022-08-15 22:16:58  INFO: Memory limit heap: 494mb non-heap: 0mb
2022-08-15 22:16:58  INFO: Character encoding: UTF-8 charset: UTF-8
2022-08-15 22:16:58  INFO: Version: 5.3
2022-08-15 22:16:58  INFO: Starting server...
2022-08-15 22:16:59  INFO: HikariPool-1 - Starting...
2022-08-15 22:17:00  INFO: HikariPool-1 - Added connection ConnectionID:1 ClientConnectionId: 9f5370f6-11bc-4e3e-aa27-c54516e43266
2022-08-15 22:17:00  INFO: HikariPool-1 - Start completed.
2022-08-15 22:17:01  INFO: Set default schema name to dbo
2022-08-15 22:17:01  INFO: Clearing database change log checksums
2022-08-15 22:17:01  INFO: Successfully acquired change log lock
2022-08-15 22:17:02  INFO: Successfully released change log lock
2022-08-15 22:17:02  INFO: Successfully acquired change log lock
2022-08-15 22:17:02  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.json.JsonChangeLogParser Unable to get public no-arg constructor
2022-08-15 22:17:02  INFO: Cannot load service: liquibase.parser.ChangeLogParser: liquibase.parser.core.yaml.YamlChangeLogParser Unable to get public no-arg constructor
2022-08-15 22:17:05  INFO: Reading from DATABASECHANGELOG
2022-08-15 22:17:06  INFO: Reading from DATABASECHANGELOG
2022-08-15 22:17:06  INFO: Cannot load service: liquibase.hub.HubService: Provider liquibase.hub.core.StandardHubService could not be instantiated
2022-08-15 22:17:06  INFO: Successfully released change log lock
2022-08-15 22:17:24  INFO: jetty-10.0.7; built: 2021-10-06T19:34:02.766Z; git: da8a4553af9dd84080931fa0f8c678cd2d60f3d9; jvm 11.0.16+8-alpine-r0
2022-08-15 22:17:25  INFO: Started o.t.w.@63553e9f{/,null,AVAILABLE}
2022-08-15 22:17:26  INFO: Session workerName=node0
2022-08-15 22:17:36  INFO: Operating system name: Linux version: 5.15.41-0-virt architecture: amd64
2022-08-15 22:17:36  INFO: Java runtime name: OpenJDK 64-Bit Server VM vendor: Alpine version: 11.0.16+8-alpine-r0
2022-08-15 22:17:36  INFO: Memory limit heap: 494mb non-heap: 0mb

and in docker-compose up i eventually get traccar exited with code 137. Also no log is printed on stdout of docker-compose up the above is from traccar-server.log file.

Anton Tananaev3 years ago

I'm not a docker-compose expert, but doesn't error code 137 mean out of memory?

Nebula3 years ago

Ahh, yeah I had memory limit of 150MiB in my docker compose. Upped it to 500MiB and its golden now.
Thank you very much for your help and quick responses, appreciate it :)

Nebula3 years ago

Just noticed that with v5.3 RAM usage is slightly more than double (~ 380-400MiB) compared to v5 (~ 130-150MiB). Is this somewhat expected?

Anton Tananaev3 years ago

As long as it doesn't leak memory, it shouldn't be double.

Nebula3 years ago

I'll keep an eye out and see. Thank you for quick response