[DRBD-user] Proxmox 6 - Linstor controller service no longer restarts

Thu Jan 16 11:29:20 CET 2020

Hello, 

I have just performed moving, resizing, snapshot tests on a Proxmox 6 / drbd / Linstor / Thin storage model. 
The last test carried out consisted in restoring a snapshot with memory of a vm after having increased the size of its disk by the web interface proxmox. 
The operation was carried out correctly except that the size of the Linstor volume definition corresponding to the disk did not drop back to its original size but without impacting the system or the vm ... 
So it's just for the context but I'm not sure the following problem is related: 
Some time later, I simply wanted to restart the Linstor controller service but without success since. 

------------------------------------------------------------- 

Jan 15 16:03:30 vpx4-1 systemd[1]: Stopping LINSTOR Controller Service... 
Jan 15 16:03:30 vpx4-1 Controller[837]: 16:03:30.093 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutdown in progress 
Jan 15 16:03:30 vpx4-1 Controller[837]: 16:03:30.105 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'DatabaseService' of type DatabaseService 
Jan 15 16:03:30 vpx4-1 Controller[837]: 16:03:30.119 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'DatabaseService' to complete shutdown 
Jan 15 16:03:30 vpx4-1 Controller[837]: 16:03:30.119 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'GrizzlyHttpServer' of type Grizzly-HTTP-Server 
Jan 15 16:03:30 vpx4-1 Controller[837]: 16:03:30.230 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'GrizzlyHttpServer' to complete shutdown 
Jan 15 16:03:30 vpx4-1 Controller[837]: 16:03:30.243 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'PlainConnector' of type NetComService 
Jan 15 16:03:30 vpx4-1 Controller[837]: 16:03:30.243 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'PlainConnector' to complete shutdown 
Jan 15 16:03:30 vpx4-1 pvestatd[1165]: Could not get storage-pool information, because:#012Can't connect to 192.168.104.181:3370 (Connection refused)#012#012Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.#012 
Jan 15 16:03:31 vpx4-1 pvestatd[1165]: Could not get storage-pool information, because:#012Can't connect to 192.168.104.181:3370 (Connection refused)#012#012Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.#012 
Jan 15 16:03:33 vpx4-1 Controller[837]: 16:03:33.244 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'TaskScheduleService' of type TaskScheduleService 
Jan 15 16:03:33 vpx4-1 Controller[837]: 16:03:33.245 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'TaskScheduleService' to complete shutdown 
Jan 15 16:03:33 vpx4-1 Controller[837]: 16:03:33.245 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'TimerEventService' of type TimerEventService 
Jan 15 16:03:33 vpx4-1 Controller[837]: 16:03:33.245 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'TimerEventService' to complete shutdown 
Jan 15 16:03:40 vpx4-1 pvestatd[1165]: Could not get storage-pool information, because:#012Can't connect to 192.168.104.181:3370 (Connection refused)#012#012Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.#012 
Jan 15 16:03:40 vpx4-1 pvestatd[1165]: Could not get storage-pool information, because:#012Can't connect to 192.168.104.181:3370 (Connection refused)#012#012Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.#012 
Jan 15 16:03:43 vpx4-1 Controller[837]: 16:03:43.246 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutdown complete 
Jan 15 16:03:43 vpx4-1 systemd[1]: linstor-controller.service: Succeeded. 
Jan 15 16:03:43 vpx4-1 systemd[1]: Stopped LINSTOR Controller Service. 
Jan 15 16:03:48 vpx4-1 systemd[1]: Started LINSTOR Controller Service. 
Jan 15 16:03:50 vpx4-1 Controller[9029]: LINSTOR, Module Controller 
Jan 15 16:03:50 vpx4-1 Controller[9029]: Version: 1.4.0 (7e49d9935043ec8528406360acac188fdff9fafb) 
Jan 15 16:03:50 vpx4-1 Controller[9029]: Build time: 2020-01-14T13:27:00+00:00 
Jan 15 16:03:50 vpx4-1 Controller[9029]: Java Version: 11 
Jan 15 16:03:50 vpx4-1 Controller[9029]: Java VM: Debian, Version 11.0.5+10-post-Debian-1deb10u1 
Jan 15 16:03:50 vpx4-1 Controller[9029]: Operating system: Linux, Version 5.3.13-1-pve 
Jan 15 16:03:50 vpx4-1 Controller[9029]: Environment: amd64, 2 processors, 498 MiB memory reserved for allocations 
Jan 15 16:03:50 vpx4-1 Controller[9029]: System components initialization in progress 
Jan 15 16:03:50 vpx4-1 pvestatd[1165]: Could not get storage-pool information, because:#012Can't connect to 192.168.104.181:3370 (Connection refused)#012#012Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.#012 
Jan 15 16:03:50 vpx4-1 pvestatd[1165]: Could not get storage-pool information, because:#012Can't connect to 192.168.104.181:3370 (Connection refused)#012#012Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.#012 
Jan 15 16:03:51 vpx4-1 Controller[9029]: 16:03:51.531 [main] INFO LINSTOR/Controller - SYSTEM - Log directory set to: '/var/log/linstor-controller' 
Jan 15 16:03:51 vpx4-1 Controller[9029]: 16:03:51.699 [main] INFO LINSTOR/Controller - SYSTEM - Linstor configuration file loaded from '/etc/linstor/linstor.toml'. 
Jan 15 16:03:51 vpx4-1 Controller[9029]: 16:03:51.702 [Main] INFO LINSTOR/Controller - SYSTEM - Loading API classes started. 
Jan 15 16:03:52 vpx4-1 Controller[9029]: 16:03:52.709 [Main] INFO LINSTOR/Controller - SYSTEM - API classes loading finished: 1005ms 
Jan 15 16:03:52 vpx4-1 Controller[9029]: 16:03:52.712 [Main] INFO LINSTOR/Controller - SYSTEM - Dependency injection started. 
Jan 15 16:03:53 vpx4-1 Controller[9029]: WARNING: An illegal reflective access operation has occurred 
Jan 15 16:03:53 vpx4-1 Controller[9029]: WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/usr/share/linstor-server/lib/guice-4.2.2.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain) 
Jan 15 16:03:53 vpx4-1 Controller[9029]: WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1 
Jan 15 16:03:53 vpx4-1 Controller[9029]: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations 
Jan 15 16:03:53 vpx4-1 Controller[9029]: WARNING: All illegal access operations will be denied in a future release 
Jan 15 16:03:55 vpx4-1 Controller[9029]: 16:03:55.517 [Main] INFO LINSTOR/Controller - SYSTEM - Dependency injection finished: 2805ms 
Jan 15 16:03:56 vpx4-1 Controller[9029]: 16:03:56.280 [Main] INFO LINSTOR/Controller - SYSTEM - Initializing authentication subsystem 
Jan 15 16:03:57 vpx4-1 Controller[9029]: 16:03:57.022 [Main] INFO LINSTOR/Controller - SYSTEM - Initializing the database connection pool 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.347 [Main] INFO org.flywaydb.core.internal.license.VersionPrinter - Flyway Community Edition 5.2.4 by Boxfuse 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.364 [Main] INFO org.flywaydb.core.internal.database.DatabaseFactory - Database: jdbc:h2:/var/lib/linstor/linstordb (H2 1.4) 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.535 [Main] INFO org.flywaydb.core.internal.command.DbValidate - Successfully validated 35 migrations (execution time 00:00.069s) 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.621 [Main] INFO org.flywaydb.core.internal.command.DbMigrate - Current version of schema "LINSTOR": 2019.12.11.01.01 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.621 [Main] WARN org.flywaydb.core.internal.command.DbMigrate - outOfOrder mode is active. Migration of schema "LINSTOR" may not be reproducible. 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.641 [Main] INFO org.flywaydb.core.internal.command.DbMigrate - Schema "LINSTOR" is up to date. No migration necessary. 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.654 [Main] INFO LINSTOR/Controller - SYSTEM - Loading security objects 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.691 [Main] INFO LINSTOR/Controller - SYSTEM - Current security level is NO_SECURITY 
Jan 15 16:03:58 vpx4-1 Controller[9029]: 16:03:58.754 [Main] INFO LINSTOR/Controller - SYSTEM - Core objects load from database is in progress 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.225 [Main] INFO LINSTOR/Controller - SYSTEM - Core objects load from database completed 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.259 [Main] ERROR LINSTOR/Controller - SYSTEM - An ValueInUseException exception was generated during number allocation cache initialization [Report number 5E1F29D6-00000-000000] 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.260 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutdown in progress 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.263 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'DatabaseService' of type DatabaseService 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.270 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'DatabaseService' to complete shutdown 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.270 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'TaskScheduleService' of type TaskScheduleService 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.271 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'TaskScheduleService' to complete shutdown 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.271 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutting down service instance 'TimerEventService' of type TimerEventService 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.272 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Waiting for service instance 'TimerEventService' to complete shutdown 
Jan 15 16:03:59 vpx4-1 Controller[9029]: 16:03:59.272 [Thread-0] INFO LINSTOR/Controller - SYSTEM - Shutdown complete 
Jan 15 16:03:59 vpx4-1 systemd[1]: linstor-controller.service: Main process exited, code=exited, status=199/n/a 
Jan 15 16:03:59 vpx4-1 systemd[1]: linstor-controller.service: Failed with result 'exit-code'. 
Jan 15 16:04:00 vpx4-1 systemd[1]: Starting Proxmox VE replication runner... 
Jan 15 16:04:00 vpx4-1 pvestatd[1165]: Could not get storage-pool information, because:#012Can't connect to 192.168.104.181:3370 (Connection refused)#012#012Connection refused at /usr/share/perl5/LWP/Protocol/http.pm line 50.#012 
... 

ERROR REPORT 5E1F29D6-00000-000000 

============================================================ 

Application: LINBIT® LINSTOR 
Module: Controller 
Version: 1.4.0 
Build ID: 7e49d9935043ec8528406360acac188fdff9fafb 
Build time: 2020-01-14T13:27:00+00:00 
Error time: 2020-01-15 16:03:59 
Node: vpx4-1 

============================================================ 

Reported error: 
=============== 

Category: Error 
Class name: ImplementationError 
Class canonical name: com.linbit.ImplementationError 
Generated at: Method 'initializeLayerRscIdPool', Source file 'DbNumberPoolInitializer.java', Line #101 

Error message: An ValueInUseException exception was generated during number allocation cache initialization 

Call backtrace: 

Method Native Class:Line number 
initializeLayerRscIdPool N com.linbit.linstor.numberpool.DbNumberPoolInitializer:101 
initialize N com.linbit.linstor.numberpool.DbNumberPoolInitializer:58 
start N com.linbit.linstor.core.Controller:240 
main N com.linbit.linstor.core.Controller:594 

Caused by: 
========== 

Category: Exception 
Class name: ValueInUseException 
Class canonical name: com.linbit.ValueInUseException 
Generated at: Method 'allocate', Source file 'DynamicNumberPoolImpl.java', Line #113 

Error message: Layer Resource Id 16 is already in use 

Call backtrace: 

Method Native Class:Line number 
allocate N com.linbit.linstor.numberpool.DynamicNumberPoolImpl:113 
allocate N com.linbit.linstor.numberpool.DbNumberPoolInitializer:110 
initializeLayerRscIdPool N com.linbit.linstor.numberpool.DbNumberPoolInitializer:93 
initialize N com.linbit.linstor.numberpool.DbNumberPoolInitializer:58 
start N com.linbit.linstor.core.Controller:240 
main N com.linbit.linstor.core.Controller:594 

END OF ERROR REPORT. 

------------------------------------------------------------- 

Do you have any idea ? 

Should we worry about warnings? 
" WARNING: An illegal reflective access operation has occurred ..." 

Just another question, is it normal that drbdtop is not present in the Linbit / Proxmox 6 repository ? 

Thank you, 

pve-manager / 6.1-5 / 9bf06119 (running kernel: 5.3.13-1-pve) 

linstor-client 1.0.10-1 
linstor-common 1.4.0-1 
linstor-controller 1.4.0-1 
linstor-proxmox 4.1.1-1 
linstor-satellite 1.4.0-1 
python-linstor 1.0.10-1 
drbd-dkms 9.0.21-1 
drbd-utils 9.11.0-1 

modinfo drbd 
filename: /lib/modules/5.3.13-1-pve/updates/dkms/drbd.ko 
version: 9.0.21-1 

global_filter = ["r | /dev/zd.* |", "r | / dev / mapper / pve -. * |" "r | / dev / mapper /.*- (vm | base) - [0-9] + - disk - [0-9] + |", "r | /dev/drbd.* |" ] 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linbit.com/pipermail/drbd-user/attachments/20200116/9650187a/attachment-0001.htm>