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

database seems empty after upgrade #208

Closed
ggzengel opened this issue Dec 30, 2020 · 4 comments
Closed

database seems empty after upgrade #208

ggzengel opened this issue Dec 30, 2020 · 4 comments
Labels
solved in next release next release should resolve this issue

Comments

@ggzengel
Copy link

After update from 1.7.3.-1 to 1.11.0-1 the database looks empty.

r l; v l; sp l; rd l; every table looks empty.

I replaced the new database with the last backup (linstordb.mv.db-2020-12-30T00:17+00:00.bak), but it still wont work.

The version from once before (linstordb.mv.db-2020-08-02T20:33+00:00.bak) worked.

This is the first start, after update without reboot.

Dec 30 00:20:38 px1 systemd[1]: Started LINSTOR Controller Service.
Dec 30 00:20:38 px1 Controller[30384]: LINSTOR, Module Controller
Dec 30 00:20:38 px1 Controller[30384]: Version:            1.11.0 (3367e32d0fa92515efe61f6963767700a8701d98)
Dec 30 00:20:38 px1 Controller[30384]: Build time:         2020-12-18T08:40:35+00:00
Dec 30 00:20:38 px1 Controller[30384]: Java Version:       11
Dec 30 00:20:38 px1 Controller[30384]: Java VM:            Debian, Version 11.0.9.1+1-post-Debian-1deb10u2
Dec 30 00:20:38 px1 Controller[30384]: Operating system:   Linux, Version 5.4.44-2-pve
Dec 30 00:20:38 px1 Controller[30384]: Environment:        amd64, 24 processors, 30688 MiB memory reserved for allocations
Dec 30 00:20:38 px1 Controller[30384]: System components initialization in progress
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.277 [main] INFO  LINSTOR/Controller - SYSTEM - ErrorReporter DB first time init.
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.279 [main] INFO  LINSTOR/Controller - SYSTEM - Log directory set to: '/var/log/linstor-controller'
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.307 [main] WARN  io.sentry.dsn.Dsn - *** Couldn't find a suitable DSN, Sentry operations will do nothing! See documentation: https://docs.sentry.io/clients/java/ ***
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.316 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading API classes started.
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.665 [Main] INFO  LINSTOR/Controller - SYSTEM - API classes loading finished: 348ms
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.666 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection started.
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.679 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule"
Dec 30 00:20:39 px1 Controller[30384]: 00:20:39.679 [Main] INFO  LINSTOR/Controller - SYSTEM - Dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule" was successful
Dec 30 00:20:39 px1 Controller[30384]: WARNING: An illegal reflective access operation has occurred
Dec 30 00:20:39 px1 Controller[30384]: WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/usr/share/linstor-server/lib/guice-4.2.3.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
Dec 30 00:20:39 px1 Controller[30384]: WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1
Dec 30 00:20:39 px1 Controller[30384]: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
Dec 30 00:20:39 px1 Controller[30384]: WARNING: All illegal access operations will be denied in a future release
Dec 30 00:20:40 px1 Controller[30384]: 00:20:40.652 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection finished: 986ms
Dec 30 00:20:40 px1 Controller[30384]: 00:20:40.897 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing authentication subsystem
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.001 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTracking using SQL driver
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.002 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTrackingService: Instance added as a system service
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.003 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TimerEventService' of type TimerEventService
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.004 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing the database connection pool
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.157 [Main] WARN  org.flywaydb.core.api.Location - Use of dots (.) as path separators will be deprecated in Flyway 7. Path: com.linbit.linstor.dbcp.migration
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.163 [Main] INFO  org.flywaydb.core.internal.license.VersionPrinter - Flyway Community Edition 6.5.7 by Redgate
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.207 [Main] INFO  org.flywaydb.core.internal.database.DatabaseFactory - Database: jdbc:h2:/var/lib/linstor/linstordb (H2 1.4)
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.273 [Main] INFO  org.flywaydb.core.internal.command.DbValidate - Successfully validated 48 migrations (execution time 00:00.040s)
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.295 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Current version of schema "LINSTOR": 2020.05.14.13.37
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.296 [Main] WARN  org.flywaydb.core.internal.command.DbMigrate - outOfOrder mode is active. Migration of schema "LINSTOR" may not be reproducible.
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.297 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.06.03.10.37 - Move all storage pool name properties into a simple single one
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.339 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.07.09.08.00 - Add create timestamp column to resources table
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.435 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.07.23.10.00 - Disable Plain and SSL Connector
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.457 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.08.20.10.00 - Enable auto-diskful-allow-cleanup
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.475 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.09.30.16.15 - Create tables required for SpaceTracking
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.500 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.12.03.10.00 - Enable auto-evict-allow-eviction
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.521 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Successfully applied 6 migrations to schema "LINSTOR" (execution time 00:00.236s)
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.531 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'DatabaseService' of type DatabaseService
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.531 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading security objects
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.544 [Main] INFO  LINSTOR/Controller - SYSTEM - Current security level is NO_SECURITY
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.557 [Main] INFO  LINSTOR/Controller - SYSTEM - Core objects load from database is in progress
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.719 [Main] ERROR LINSTOR/Controller - SYSTEM - No TCP/IP port number could be allocated for the resource [Report number 5FEBC7D6-00000-000000]
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.724 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TaskScheduleService' of type TaskScheduleService
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.724 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing network communications services
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.725 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'DebugSslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.725 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: Running log archive on directory: /var/log/linstor-controller
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.728 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: No logs to archive.
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.731 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'PlainConnector'
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.732 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'SslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.732 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'SslConnector'
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.736 [Main] ERROR LINSTOR/Controller - SYSTEM - The current scope has already been entered [Report number 5FEBC7D6-00000-000001]
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.736 [Main] INFO  LINSTOR/Controller - SYSTEM - No known nodes.
Dec 30 00:20:41 px1 Controller[30384]: 00:20:41.737 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'SpaceTrackingService' of type SpaceTrackingService
Dec 30 00:20:42 px1 Controller[30384]: Dec 30, 2020 12:20:42 AM org.glassfish.grizzly.http.server.NetworkListener start
Dec 30 00:20:42 px1 Controller[30384]: INFO: Started listener bound to [[::]:3370]
Dec 30 00:20:42 px1 Controller[30384]: Dec 30, 2020 12:20:42 AM org.glassfish.grizzly.http.server.HttpServer start
Dec 30 00:20:42 px1 Controller[30384]: INFO: [HttpServer] Started.
Dec 30 00:20:42 px1 Controller[30384]: 00:20:42.857 [Main] INFO  LINSTOR/Controller - SYSTEM - Controller initialized

The upgrade

Preparing to unpack .../072-python-linstor_1.6.0-1_all.deb ...
Unpacking python-linstor (1.6.0-1) over (1.1.2-1) ...
Preparing to unpack .../073-linstor-client_1.6.0-1_all.deb ...
Unpacking linstor-client (1.6.0-1) over (1.1.2-1) ...
Preparing to unpack .../074-drbd-utils_9.15.1-1_amd64.deb ...
Unpacking drbd-utils (9.15.1-1) over (9.13.1-1) ...
Preparing to unpack .../075-linstor-proxmox_5.1.4-1_all.deb ...
Leaving 'diversion of /usr/share/perl5/PVE/Storage/DRBDPlugin.pm to /usr/share/perl5/PVE/Storage/DRBDPlugin.pm.proxmox by linstor-proxmox'
Unpacking linstor-proxmox (5.1.4-1) over (5.1.2-1) ...

The databases

# ls -la /var/lib/linstor
total 4680
drwxr-xr-x  2 root root   4096 Dec 30 03:03 .
drwxr-xr-x 57 root root   4096 Apr 17  2020 ..
-rw-r--r--  1 root root 692224 Dec 30 03:03 linstordb.mv.db
-rw-r--r--  1 root root 589824 Apr 15  2020 linstordb.mv.db-2020-04-15T03:29+00:00.bak
-rw-r--r--  1 root root 692224 Jun 15  2020 linstordb.mv.db-2020-06-15T01:06+00:00.bak
-rw-r--r--  1 root root 692224 Aug  2 20:33 linstordb.mv.db-2020-08-02T20:33+00:00.bak
-rw-r--r--  1 root root 692224 Dec 30 00:17 linstordb.mv.db-2020-12-30T00:17+00:00.bak
-rw-r--r--  1 root root 692224 Dec 30 00:16 linstordb.mv.db.bak
-rw-r--r--  1 root root 692224 Dec 30 00:44 linstordb.mv.db.def
-rw-r--r--  1 root root  40582 Aug  2 20:31 linstordb.trace.db
-rw-r--r--  1 root root      0 Dec 30 03:03 loop_device_mapping

Last database backup (2020-12)

Dec 30 00:47:11 px1 systemd[1]: Started LINSTOR Controller Service.
Dec 30 00:47:12 px1 Controller[29584]: LINSTOR, Module Controller
Dec 30 00:47:12 px1 Controller[29584]: Version:            1.11.0 (3367e32d0fa92515efe61f6963767700a8701d98)
Dec 30 00:47:12 px1 Controller[29584]: Build time:         2020-12-18T08:40:35+00:00
Dec 30 00:47:12 px1 Controller[29584]: Java Version:       11
Dec 30 00:47:12 px1 Controller[29584]: Java VM:            Debian, Version 11.0.9.1+1-post-Debian-1deb10u2
Dec 30 00:47:12 px1 Controller[29584]: Operating system:   Linux, Version 5.4.78-2-pve
Dec 30 00:47:12 px1 Controller[29584]: Environment:        amd64, 24 processors, 30688 MiB memory reserved for allocations
Dec 30 00:47:12 px1 Controller[29584]: System components initialization in progress
Dec 30 00:47:12 px1 Controller[29584]: 00:47:12.742 [main] INFO  LINSTOR/Controller - SYSTEM - ErrorReporter DB version 1 found.
Dec 30 00:47:12 px1 Controller[29584]: 00:47:12.744 [main] INFO  LINSTOR/Controller - SYSTEM - Log directory set to: '/var/log/linstor-controller'
Dec 30 00:47:12 px1 Controller[29584]: 00:47:12.771 [main] WARN  io.sentry.dsn.Dsn - *** Couldn't find a suitable DSN, Sentry operations will do nothing! See documentation: https://docs.sentry.io/clients/java/ ***
Dec 30 00:47:12 px1 Controller[29584]: 00:47:12.780 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading API classes started.
Dec 30 00:47:13 px1 Controller[29584]: 00:47:13.091 [Main] INFO  LINSTOR/Controller - SYSTEM - API classes loading finished: 310ms
Dec 30 00:47:13 px1 Controller[29584]: 00:47:13.092 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection started.
Dec 30 00:47:13 px1 Controller[29584]: 00:47:13.104 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule"
Dec 30 00:47:13 px1 Controller[29584]: 00:47:13.105 [Main] INFO  LINSTOR/Controller - SYSTEM - Dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule" was successful
Dec 30 00:47:13 px1 Controller[29584]: WARNING: An illegal reflective access operation has occurred
Dec 30 00:47:13 px1 Controller[29584]: WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/usr/share/linstor-server/lib/guice-4.2.3.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
Dec 30 00:47:13 px1 Controller[29584]: WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1
Dec 30 00:47:13 px1 Controller[29584]: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
Dec 30 00:47:13 px1 Controller[29584]: WARNING: All illegal access operations will be denied in a future release
Dec 30 00:47:13 px1 Controller[29584]: 00:47:13.990 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection finished: 898ms
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.259 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing authentication subsystem
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.367 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTracking using SQL driver
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.369 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTrackingService: Instance added as a system service
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.370 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TimerEventService' of type TimerEventService
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.371 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing the database connection pool
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.490 [Main] WARN  org.flywaydb.core.api.Location - Use of dots (.) as path separators will be deprecated in Flyway 7. Path: com.linbit.linstor.dbcp.migration
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.494 [Main] INFO  org.flywaydb.core.internal.license.VersionPrinter - Flyway Community Edition 6.5.7 by Redgate
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.525 [Main] INFO  org.flywaydb.core.internal.database.DatabaseFactory - Database: jdbc:h2:/var/lib/linstor/linstordb (H2 1.4)
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.580 [Main] INFO  org.flywaydb.core.internal.command.DbValidate - Successfully validated 48 migrations (execution time 00:00.036s)
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.604 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Current version of schema "LINSTOR": 2020.05.14.13.37
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.604 [Main] WARN  org.flywaydb.core.internal.command.DbMigrate - outOfOrder mode is active. Migration of schema "LINSTOR" may not be reproducible.
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.605 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.06.03.10.37 - Move all storage pool name properties into a simple single one
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.678 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.07.09.08.00 - Add create timestamp column to resources table
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.792 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.07.23.10.00 - Disable Plain and SSL Connector
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.818 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.08.20.10.00 - Enable auto-diskful-allow-cleanup
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.840 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.09.30.16.15 - Create tables required for SpaceTracking
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.908 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.12.03.10.00 - Enable auto-evict-allow-eviction
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.954 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Successfully applied 6 migrations to schema "LINSTOR" (execution time 00:00.366s)
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.961 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'DatabaseService' of type DatabaseService
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.961 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading security objects
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.971 [Main] INFO  LINSTOR/Controller - SYSTEM - Current security level is NO_SECURITY
Dec 30 00:47:14 px1 Controller[29584]: 00:47:14.991 [Main] INFO  LINSTOR/Controller - SYSTEM - Core objects load from database is in progress
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.174 [Main] ERROR LINSTOR/Controller - SYSTEM - No TCP/IP port number could be allocated for the resource [Report number 5FEBCE10-00000-000000]
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.179 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TaskScheduleService' of type TaskScheduleService
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.179 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing network communications services
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.180 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'DebugSslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.181 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: Running log archive on directory: /var/log/linstor-controller
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.185 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: No logs to archive.
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.187 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'PlainConnector'
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.189 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'SslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.189 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'SslConnector'
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.195 [Main] ERROR LINSTOR/Controller - SYSTEM - The current scope has already been entered [Report number 5FEBCE10-00000-000001]
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.195 [Main] INFO  LINSTOR/Controller - SYSTEM - No known nodes.
Dec 30 00:47:15 px1 Controller[29584]: 00:47:15.196 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'SpaceTrackingService' of type SpaceTrackingService
Dec 30 00:47:16 px1 Controller[29584]: 00:47:16.113 [Main] ERROR LINSTOR/Controller - SYSTEM - Unable to start grizzly http server on [::]:3370.
Dec 30 00:47:16 px1 Controller[29584]: 00:47:16.114 [Main] INFO  LINSTOR/Controller - SYSTEM - Trying to start grizzly http server on fallback ipv4: 0.0.0.0
Dec 30 00:47:16 px1 Controller[29584]: Dec 30, 2020 12:47:16 AM org.glassfish.grizzly.http.server.NetworkListener start
Dec 30 00:47:16 px1 Controller[29584]: INFO: Started listener bound to [0.0.0.0:3370]
Dec 30 00:47:16 px1 Controller[29584]: Dec 30, 2020 12:47:16 AM org.glassfish.grizzly.http.server.HttpServer start
Dec 30 00:47:16 px1 Controller[29584]: INFO: [HttpServer-1] Started.
Dec 30 00:47:16 px1 Controller[29584]: 00:47:16.413 [Main] INFO  LINSTOR/Controller - SYSTEM - Controller initialized

Old Database (2020-08) but it works

Dec 30 00:50:15 px1 systemd[1]: Started LINSTOR Controller Service.
Dec 30 00:50:15 px1 Controller[20581]: LINSTOR, Module Controller
Dec 30 00:50:15 px1 Controller[20581]: Version:            1.11.0 (3367e32d0fa92515efe61f6963767700a8701d98)
Dec 30 00:50:15 px1 Controller[20581]: Build time:         2020-12-18T08:40:35+00:00
Dec 30 00:50:15 px1 Controller[20581]: Java Version:       11
Dec 30 00:50:15 px1 Controller[20581]: Java VM:            Debian, Version 11.0.9.1+1-post-Debian-1deb10u2
Dec 30 00:50:15 px1 Controller[20581]: Operating system:   Linux, Version 5.4.78-2-pve
Dec 30 00:50:15 px1 Controller[20581]: Environment:        amd64, 24 processors, 30688 MiB memory reserved for allocations
Dec 30 00:50:15 px1 Controller[20581]: System components initialization in progress
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.345 [main] INFO  LINSTOR/Controller - SYSTEM - ErrorReporter DB version 1 found.
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.347 [main] INFO  LINSTOR/Controller - SYSTEM - Log directory set to: '/var/log/linstor-controller'
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.383 [main] WARN  io.sentry.dsn.Dsn - *** Couldn't find a suitable DSN, Sentry operations will do nothing! See documentation: https://docs.sentry.io/clients/java/ ***
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.394 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading API classes started.
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.796 [Main] INFO  LINSTOR/Controller - SYSTEM - API classes loading finished: 401ms
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.796 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection started.
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.809 [Main] INFO  LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule"
Dec 30 00:50:16 px1 Controller[20581]: 00:50:16.809 [Main] INFO  LINSTOR/Controller - SYSTEM - Dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule" was successful
Dec 30 00:50:16 px1 Controller[20581]: WARNING: An illegal reflective access operation has occurred
Dec 30 00:50:16 px1 Controller[20581]: WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/usr/share/linstor-server/lib/guice-4.2.3.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
Dec 30 00:50:16 px1 Controller[20581]: WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1
Dec 30 00:50:16 px1 Controller[20581]: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
Dec 30 00:50:16 px1 Controller[20581]: WARNING: All illegal access operations will be denied in a future release
Dec 30 00:50:17 px1 Controller[20581]: 00:50:17.808 [Main] INFO  LINSTOR/Controller - SYSTEM - Dependency injection finished: 1012ms
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.113 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing authentication subsystem
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.228 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTracking using SQL driver
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.230 [Main] INFO  LINSTOR/Controller - SYSTEM - SpaceTrackingService: Instance added as a system service
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.231 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TimerEventService' of type TimerEventService
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.231 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing the database connection pool
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.373 [Main] WARN  org.flywaydb.core.api.Location - Use of dots (.) as path separators will be deprecated in Flyway 7. Path: com.linbit.linstor.dbcp.migration
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.377 [Main] INFO  org.flywaydb.core.internal.license.VersionPrinter - Flyway Community Edition 6.5.7 by Redgate
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.412 [Main] INFO  org.flywaydb.core.internal.database.DatabaseFactory - Database: jdbc:h2:/var/lib/linstor/linstordb (H2 1.4)
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.475 [Main] INFO  org.flywaydb.core.internal.command.DbValidate - Successfully validated 48 migrations (execution time 00:00.040s)
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.501 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Current version of schema "LINSTOR": 2020.05.14.13.37
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.501 [Main] WARN  org.flywaydb.core.internal.command.DbMigrate - outOfOrder mode is active. Migration of schema "LINSTOR" may not be reproducible.
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.503 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.06.03.10.37 - Move all storage pool name properties into a simple single one
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.553 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.07.09.08.00 - Add create timestamp column to resources table
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.645 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.07.23.10.00 - Disable Plain and SSL Connector
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.672 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.08.20.10.00 - Enable auto-diskful-allow-cleanup
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.693 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.09.30.16.15 - Create tables required for SpaceTracking
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.737 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Migrating schema "LINSTOR" to version 2020.12.03.10.00 - Enable auto-evict-allow-eviction
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.799 [Main] INFO  org.flywaydb.core.internal.command.DbMigrate - Successfully applied 6 migrations to schema "LINSTOR" (execution time 00:00.316s)
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.807 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'DatabaseService' of type DatabaseService
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.807 [Main] INFO  LINSTOR/Controller - SYSTEM - Loading security objects
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.819 [Main] INFO  LINSTOR/Controller - SYSTEM - Current security level is NO_SECURITY
Dec 30 00:50:18 px1 Controller[20581]: 00:50:18.830 [Main] INFO  LINSTOR/Controller - SYSTEM - Core objects load from database is in progress
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.035 [Main] INFO  LINSTOR/Controller - SYSTEM - Core objects load from database completed
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.037 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'TaskScheduleService' of type TaskScheduleService
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.038 [Main] INFO  LINSTOR/Controller - SYSTEM - Initializing network communications services
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.039 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'DebugSslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.040 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: Running log archive on directory: /var/log/linstor-controller
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.043 [TaskScheduleService] INFO  LINSTOR/Controller - SYSTEM - LogArchive: No logs to archive.
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.045 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'PlainConnector'
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.046 [Main] WARN  LINSTOR/Controller - SYSTEM - The SSL network communication service 'SslConnector' could not be started because the keyStore file (/etc/linstor/ssl/keystore.jks) is missing
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.046 [Main] INFO  LINSTOR/Controller - SYSTEM - Created network communication service 'SslConnector'
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.047 [Main] INFO  LINSTOR/Controller - SYSTEM - Reconnecting to previously known nodes
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.068 [Main] INFO  LINSTOR/Controller - SYSTEM - Reconnect requests sent
Dec 30 00:50:19 px1 Controller[20581]: 00:50:19.069 [Main] INFO  LINSTOR/Controller - SYSTEM - Starting service instance 'SpaceTrackingService' of type SpaceTrackingService
Dec 30 00:50:20 px1 Controller[20581]: 00:50:20.172 [Main] ERROR LINSTOR/Controller - SYSTEM - Unable to start grizzly http server on [::]:3370.
Dec 30 00:50:20 px1 Controller[20581]: 00:50:20.172 [Main] INFO  LINSTOR/Controller - SYSTEM - Trying to start grizzly http server on fallback ipv4: 0.0.0.0
Dec 30 00:50:20 px1 Controller[20581]: Dec 30, 2020 12:50:20 AM org.glassfish.grizzly.http.server.NetworkListener start
Dec 30 00:50:20 px1 Controller[20581]: INFO: Started listener bound to [0.0.0.0:3370]
Dec 30 00:50:20 px1 Controller[20581]: Dec 30, 2020 12:50:20 AM org.glassfish.grizzly.http.server.HttpServer start
Dec 30 00:50:20 px1 Controller[20581]: INFO: [HttpServer-1] Started.
Dec 30 00:50:20 px1 Controller[20581]: 00:50:20.457 [Main] INFO  LINSTOR/Controller - SYSTEM - Controller initialized
@rp-
Copy link
Contributor

rp- commented Dec 30, 2020

Can you send us the version of the database, where the upgrade didn't work?

@ggzengel
Copy link
Author

ggzengel commented Jan 4, 2021

This is the backup before/while upgrade:

linstordb.mv.db-2020-12-30T00:17+00:00.bak.zip

@ghernadi
Copy link
Contributor

Apparently there is an issue with the StorPoolNameDrbdMeta property.

After migrating your database, Linstor loads every internal resource layer-trees and runs their intializers. However, an initializer of a resource which was created with internal metadata still sees at this point the StorPoolNameDrbdMeta of your resource-group ZFS_12 (which indicates that this resource should have external metadata). But as there is no child data representing that external metadata, Linstor tries to create that data, but as Linstor is still during a quite fragile loading time (as not everything is loaded / initialized, etc...) creating completely new objects can break things... (as we see in this case)

I believe we have found and fixed the bug, which will be included in the next release. Until then, you should be able to temporarily remove the mentioned property and afterwards perform the upgrade.

This issue might occur after every controller-restart, so re-inserting the property after upgrading will only work until you restart the controller. Until we do the release, you might want to use the resource-definition as a target for this specific property instead of the resource-group to avoid this bug for now. After the bugfix-release you should be able to safely use this property on resource-group level again.

@ghernadi ghernadi added the solved in next release next release should resolve this issue label Jan 11, 2021
@ggzengel
Copy link
Author

Because of #128 (comment) and a new blocksize=16k on ZFS I migrated from internal to external metadata. But some weren't already migrated but now they are.
On other sites I had already migrated and didn't get the error.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
solved in next release next release should resolve this issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@rp- @ggzengel @ghernadi