time="2020-11-18T19:13:48Z" level=info msg="running k8s-await-election" version=refs/tags/v0.2.0
I1118 19:13:48.722244 1 leaderelection.go:242] attempting to acquire leader lease piraeus-operator/piraeus-cs...
time="2020-11-18T19:13:51Z" level=info msg="long live our new leader: 'piraeus-cs-controller-5f998d764b-btsjm'!"
I1120 12:17:59.154742 1 leaderelection.go:252] successfully acquired lease piraeus-operator/piraeus-cs
time="2020-11-20T12:17:59Z" level=info msg="long live our new leader: 'piraeus-cs-controller-5f998d764b-zz46s'!"
time="2020-11-20T12:17:59Z" level=info msg="starting command '/usr/bin/piraeus-entry.sh' with arguments: '[startController]'"
LINSTOR, Module Controller
Version: 1.9.0 (678acd24a8b9b73a735407cd79ca33a5e95eb2e2)
Build time: 2020-09-23T09:33:23+00:00
Java Version: 11
Java VM: Debian, Version 11.0.8+10-post-Debian-1deb10u1
Operating system: Linux, Version 5.6.19-300.fc32.x86_64
Environment: amd64, 1 processors, 29694 MiB memory reserved for allocations
System components initialization in progress
12:17:59,493 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
12:17:59,494 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
12:17:59,494 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/usr/share/linstor-server/lib/conf/logback.xml]
12:17:59,549 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
12:17:59,551 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
12:17:59,553 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
12:17:59,556 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
12:17:59,568 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
12:17:59,569 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
12:17:59,573 |-INFO in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@2de23121 - Will use zip compression
12:17:59,575 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /var/log/linstor-controller/linstor-Controller.log
12:17:59,575 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/var/log/linstor-controller/linstor-Controller.log]
12:17:59,576 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Failed to create parent directories for [/var/log/linstor-controller/linstor-Controller.log]
12:17:59,576 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - openFile(/var/log/linstor-controller/linstor-Controller.log,true) call failed. java.io.FileNotFoundException: /var/log/linstor-controller/linstor-Controller.log (No such file or directory)
at java.io.FileNotFoundException: /var/log/linstor-controller/linstor-Controller.log (No such file or directory)
at at java.base/java.io.FileOutputStream.open0(Native Method)
at at java.base/java.io.FileOutputStream.open(FileOutputStream.java:298)
at at java.base/java.io.FileOutputStream.<init>(FileOutputStream.java:237)
at at ch.qos.logback.core.recovery.ResilientFileOutputStream.<init>(ResilientFileOutputStream.java:26)
at at ch.qos.logback.core.FileAppender.openFile(FileAppender.java:204)
at at ch.qos.logback.core.FileAppender.start(FileAppender.java:127)
at at ch.qos.logback.core.rolling.RollingFileAppender.start(RollingFileAppender.java:100)
at at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:90)
at at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
at at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:165)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:152)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
at at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
at at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
at at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
at at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
at at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
at at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
at at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:417)
at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:362)
at at com.linbit.linstor.logging.StdErrorReporter.<init>(StdErrorReporter.java:75)
at at com.linbit.linstor.core.Controller.main(Controller.java:450)
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [LINSTOR/Controller] to INFO
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [LINSTOR/Controller] to false
12:17:59,576 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[LINSTOR/Controller]
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [LINSTOR/Satellite] to INFO
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [LINSTOR/Satellite] to false
12:17:59,576 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[LINSTOR/Satellite]
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [LINSTOR/TESTS] to OFF
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [LINSTOR/TESTS] to false
12:17:59,576 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[LINSTOR/TESTS]
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
12:17:59,576 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
12:17:59,576 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
12:17:59,577 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@6913c1fb - Registering current configuration as safe fallback point
12:17:59.580 [main] ERROR LINSTOR/Controller - SYSTEM - Unable to create log directory: /var/log/linstor-controller
org.h2.message.DbException: Log file error: "/var/log/linstor-controller/error-report.trace.db", cause: "org.h2.message.DbException: Error while creating file ""/var/log/linstor-controller"" [90062-197]" [90034-197]
org.h2.message.DbException: Log file error: "/var/log/linstor-controller/error-report.trace.db", cause: "org.h2.message.DbException: Error while creating file ""/var/log/linstor-controller"" [90062-197]" [90034-197]
at org.h2.message.DbException.get(DbException.java:168)
at org.h2.message.TraceSystem.logWritingError(TraceSystem.java:289)
at org.h2.message.TraceSystem.openWriter(TraceSystem.java:310)
at org.h2.message.TraceSystem.writeFile(TraceSystem.java:258)
at org.h2.message.TraceSystem.write(TraceSystem.java:242)
at org.h2.message.Trace.error(Trace.java:196)
at org.h2.engine.Database.openDatabase(Database.java:314)
at org.h2.engine.Database.<init>(Database.java:280)
at org.h2.engine.Engine.openSession(Engine.java:66)
at org.h2.engine.Engine.openSession(Engine.java:179)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:157)
at org.h2.engine.Engine.createSession(Engine.java:140)
at org.h2.engine.Engine.createSession(Engine.java:28)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:351)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
at org.h2.Driver.connect(Driver.java:69)
at org.apache.commons.dbcp2.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:55)
at org.apache.commons.dbcp2.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:355)
at org.apache.commons.dbcp2.BasicDataSource.validateConnectionFactory(BasicDataSource.java:115)
at org.apache.commons.dbcp2.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:665)
at org.apache.commons.dbcp2.BasicDataSource.createDataSource(BasicDataSource.java:544)
at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:753)
at com.linbit.linstor.logging.H2ErrorReporter.setupErrorDB(H2ErrorReporter.java:66)
at com.linbit.linstor.logging.H2ErrorReporter.<init>(H2ErrorReporter.java:61)
at com.linbit.linstor.logging.StdErrorReporter.<init>(StdErrorReporter.java:107)
at com.linbit.linstor.core.Controller.main(Controller.java:450)
Caused by: org.h2.jdbc.JdbcSQLException: Log file error: "/var/log/linstor-controller/error-report.trace.db", cause: "org.h2.message.DbException: Error while creating file ""/var/log/linstor-controller"" [90062-197]" [90034-197]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)
... 27 more
Caused by: org.h2.message.DbException: Error while creating file "/var/log/linstor-controller" [90062-197]
at org.h2.message.DbException.get(DbException.java:179)
at org.h2.message.DbException.get(DbException.java:155)
at org.h2.store.fs.FilePathDisk.createDirectory(FilePathDisk.java:271)
at org.h2.store.fs.FileUtils.createDirectory(FileUtils.java:42)
at org.h2.store.fs.FileUtils.createDirectories(FileUtils.java:312)
at org.h2.message.TraceSystem.openWriter(TraceSystem.java:300)
... 24 more
Caused by: org.h2.jdbc.JdbcSQLException: Error while creating file "/var/log/linstor-controller" [90062-197]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)
... 30 more
12:18:02.218 [main] ERROR LINSTOR/Controller - SYSTEM - Unable to operate the error-reports database: java.sql.SQLException: Cannot create PoolableConnectionFactory (Error while creating file "/var/log/linstor-controller" [90062-197])
12:18:02.218 [main] INFO LINSTOR/Controller - SYSTEM - Log directory set to: '/var/log/linstor-controller'
12:18:02.242 [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/ ***
12:18:02.250 [Main] INFO LINSTOR/Controller - SYSTEM - Loading API classes started.
12:18:02.486 [Main] INFO LINSTOR/Controller - SYSTEM - API classes loading finished: 236ms
12:18:02.486 [Main] INFO LINSTOR/Controller - SYSTEM - Dependency injection started.
12:18:02.501 [Main] INFO LINSTOR/Controller - SYSTEM - Attempting dynamic load of extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule"
12:18:02.501 [Main] INFO LINSTOR/Controller - SYSTEM - Extension module "com.linbit.linstor.spacetracking.ControllerSpaceTrackingModule" is not installed
WARNING: An illegal reflective access operation has occurred
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)
WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
12:18:03.175 [Main] INFO LINSTOR/Controller - SYSTEM - Dependency injection finished: 689ms
12:18:03.375 [Main] INFO LINSTOR/Controller - SYSTEM - Initializing authentication subsystem
12:18:03.459 [Main] INFO LINSTOR/Controller - SYSTEM - Starting service instance 'TimerEventService' of type TimerEventService
12:18:03.460 [Main] INFO LINSTOR/Controller - SYSTEM - Initializing the etcd database
12:18:04.008 [Main] INFO LINSTOR/Controller - SYSTEM - Starting service instance 'ETCDDatabaseService' of type ETCDDatabaseService
12:18:04.009 [Main] INFO LINSTOR/Controller - SYSTEM - Loading security objects
12:18:04.090 [Main] INFO LINSTOR/Controller - SYSTEM - Current security level is NO_SECURITY
12:18:04.144 [Main] INFO LINSTOR/Controller - SYSTEM - Core objects load from database is in progress
12:18:06.684 [Main] INFO LINSTOR/Controller - SYSTEM - Core objects load from database completed
12:18:06.703 [Main] INFO LINSTOR/Controller - SYSTEM - Starting service instance 'TaskScheduleService' of type TaskScheduleService
12:18:06.704 [Main] INFO LINSTOR/Controller - SYSTEM - Initializing network communications services
12:18:06.704 [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
Unable to create error report file for error report 5FB7B3F7-00000-000000:
/var/log/linstor-controller/ErrorReport-5FB7B3F7-00000-000000.log (No such file or directory)
The error report will be written to the standard error stream instead.
ERROR REPORT 5FB7B3F7-00000-000000
============================================================
Application: LINBIT? LINSTOR
Module: Controller
Version: 1.9.0
Build ID: 678acd24a8b9b73a735407cd79ca33a5e95eb2e2
Build time: 2020-09-23T09:33:23+00:00
Error time: 2020-11-20 12:18:06
Node: piraeus-cs-controller-5f998d764b-zz46s
============================================================
Reported error:
===============
Category: Error
Class name: ImplementationError
Class canonical name: com.linbit.ImplementationError
Generated at: Method 'execute', Source file 'TaskScheduleService.java', Line #289
Error message: Unhandled exception caught in com.linbit.linstor.tasks.TaskScheduleService
Error context:
This exception was generated in the service thread of the service 'TaskScheduleService'
Call backtrace:
Method Native Class:Line number
execute N com.linbit.linstor.tasks.TaskScheduleService:289
run N com.linbit.linstor.tasks.TaskScheduleService:196
run N java.lang.Thread:834
Caused by:
==========
Category: RuntimeException
Class name: LinStorRuntimeException
Class canonical name: com.linbit.linstor.LinStorRuntimeException
Generated at: Method 'archiveLogDirectory', Source file 'StdErrorReporter.java', Line #730
Error message: Unable to list log directory
Call backtrace:
Method Native Class:Line number
archiveLogDirectory N com.linbit.linstor.logging.StdErrorReporter:730
run 12:18:06.709 [Main] INFO LINSTOR/Controller - SYSTEM - Created network communication service 'PlainConnector'
N 12:18:06.709 [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
com.linbit.linstor.tasks.LogArchiveTask:49
12:18:06.709 [Main] INFO LINSTOR/Controller - SYSTEM - Created network communication service 'SslConnector'
execute N com.linbit.linstor.tasks.TaskScheduleService:282
run N com.linbit.linstor.tasks.TaskScheduleService:196
run N java.lang.Thread:834
Caused by:
==========
Category: Exception
Class name: NoSuchFileException
Class canonical name: java.nio.file.NoSuchFileException
Generated at: Method 'translateToIOException', Source file 'UnixException.java', Line #92
Error message: /var/log/linstor-controller
Call backtrace:
Method Native Class:Line number
translateToIOException N sun.nio.fs.UnixException:92
rethrowAsIOException N sun.nio.fs.UnixException:111
rethrowAsIOException N sun.nio.fs.UnixException:116
newDirectoryStream N sun.nio.fs.UnixFileSystemProvider:432
newDirectoryStream N java.nio.file.Files:471
list N java.nio.file.Files:3698
archiveLogDirectory N com.linbit.linstor.logging.StdErrorReporter:652
run N com.linbit.linstor.tasks.LogArchiveTask:49
12:18:06.711 [Main] INFO LINSTOR/Controller - SYSTEM - Reconnecting to previously known nodes
execute N com.linbit.linstor.tasks.TaskScheduleService:282
run N com.linbit.linstor.tasks.TaskScheduleService:196
run N java.lang.Thread:834
END OF ERROR REPORT.
12:18:06.730 [Main] INFO LINSTOR/Controller - SYSTEM - Reconnect requests sent
Nov 20, 2020 12:18:07 PM org.glassfish.grizzly.http.server.NetworkListener start
INFO: Started listener bound to [[::]:3370]
Nov 20, 2020 12:18:07 PM org.glassfish.grizzly.http.server.HttpServer start
INFO: [HttpServer] Started.
12:18:07.656 [Main] INFO LINSTOR/Controller - SYSTEM - Controller initialized
org.h2.message.DbException: Log file error: "/var/log/linstor-controller/error-report.trace.db", cause: "org.h2.message.DbException: Error while creating file ""/var/log/linstor-controller"" [90062-197]" [90034-197]
org.h2.message.DbException: Log file error: "/var/log/linstor-controller/error-report.trace.db", cause: "org.h2.message.DbException: Error while creating file ""/var/log/linstor-controller"" [90062-197]" [90034-197]
at org.h2.message.DbException.get(DbException.java:168)
at org.h2.message.TraceSystem.logWritingError(TraceSystem.java:289)
at org.h2.message.TraceSystem.openWriter(TraceSystem.java:310)
at org.h2.message.TraceSystem.writeFile(TraceSystem.java:258)
at org.h2.message.TraceSystem.write(TraceSystem.java:242)
at org.h2.message.Trace.error(Trace.java:196)
at org.h2.engine.Database.openDatabase(Database.java:314)
at org.h2.engine.Database.<init>(Database.java:280)
at org.h2.engine.Engine.openSession(Engine.java:66)
at org.h2.engine.Engine.openSession(Engine.java:179)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:157)
at org.h2.engine.Engine.createSession(Engine.java:140)
at org.h2.engine.Engine.createSession(Engine.java:28)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:351)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
at org.h2.Driver.connect(Driver.java:69)
at org.apache.commons.dbcp2.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:55)
at org.apache.commons.dbcp2.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:355)
at org.apache.commons.dbcp2.BasicDataSource.validateConnectionFactory(BasicDataSource.java:115)
at org.apache.commons.dbcp2.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:665)
at org.apache.commons.dbcp2.BasicDataSource.createDataSource(BasicDataSource.java:544)
at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:753)
at com.linbit.linstor.logging.H2ErrorReporter.writeErrorReportToDB(H2ErrorReporter.java:105)
at com.linbit.linstor.logging.StdErrorReporter.reportErrorImpl(StdErrorReporter.java:301)
at com.linbit.linstor.logging.StdErrorReporter.reportError(StdErrorReporter.java:271)
at com.linbit.linstor.tasks.TaskScheduleService.execute(TaskScheduleService.java:286)
at com.linbit.linstor.tasks.TaskScheduleService.run(TaskScheduleService.java:196)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.h2.jdbc.JdbcSQLException: Log file error: "/var/log/linstor-controller/error-report.trace.db", cause: "org.h2.message.DbException: Error while creating file ""/var/log/linstor-controller"" [90062-197]" [90034-197]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)
... 29 more
Caused by: org.h2.message.DbException: Error while creating file "/var/log/linstor-controller" [90062-197]
at org.h2.message.DbException.get(DbException.java:179)
at org.h2.message.DbException.get(DbException.java:155)
at org.h2.store.fs.FilePathDisk.createDirectory(FilePathDisk.java:271)
at org.h2.store.fs.FileUtils.createDirectory(FileUtils.java:42)
at org.h2.store.fs.FileUtils.createDirectories(FileUtils.java:312)
at org.h2.message.TraceSystem.openWriter(TraceSystem.java:300)
... 26 more
Caused by: org.h2.jdbc.JdbcSQLException: Error while creating file "/var/log/linstor-controller" [90062-197]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)
... 32 more
12:18:09.291 [TaskScheduleService] ERROR LINSTOR/Controller - SYSTEM - Unable to write error report to DB: Cannot create PoolableConnectionFactory (Error while creating file "/var/log/linstor-controller" [90062-197])
12:18:09.291 [TaskScheduleService] ERROR LINSTOR/Controller - SYSTEM - Unhandled exception caught in com.linbit.linstor.tasks.TaskScheduleService [Report number 5FB7B3F7-00000-000000]