We did have fusionauth up and running in our automated test environment. However now it is failing to start. In our other environments we have the exact same setup running. Usually my go-to is the fusionauthapp_stdout logs. Whats strange however is that the logs seem to stop being emitted at an early startup stage.
In the environment(s) that are working correctly the logs look like I expect for a normal startup as shown in the first example:
Using CATALINA_BASE: "C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat"
Using CATALINA_HOME: "C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat"
Using CATALINA_TMPDIR: "C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat\temp"
Using JRE_HOME: "C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat\..\..\java\jre1.8.0_171"
Using CLASSPATH: "C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat\bin\bootstrap.jar;C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat\bin\tomcat-juli.jar"
Jul 10, 2019 10:41:11.414 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Loading FusionAuth configuration file [C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat\..\..\config\fusionauth.properties]
Jul 10, 2019 10:41:11.478 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Dynamically set property [fusionauth-app.public-url] set to [http://192.168.XX.XX:XXXX]
Jul 10, 2019 10:41:11.479 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - FusionAuth Runtime Mode [Production]
Jul 10, 2019 10:41:11.599 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Loading FusionAuth configuration file [C:\Users\administrator\fusionauth\fusionauth-app\apache-tomcat\..\..\config\fusionauth.properties]
Jul 10, 2019 10:41:11.664 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Dynamically set property [fusionauth-app.public-url] set to [http://192.168.XX.XX:XXXX
Jul 10, 2019 10:41:11.665 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - FusionAuth Runtime Mode [Production]
Jul 10, 2019 10:41:11.925 AM INFO com.inversoft.maintenance.db.JDBCMaintenanceModeDatabaseService - Database Version [1.3.1]
Jul 10, 2019 10:41:11.927 AM INFO com.inversoft.maintenance.db.JDBCMaintenanceModeDatabaseService - Latest Migration Version [1.1.0]
Jul 10, 2019 10:41:11.929 AM INFO io.fusionauth.app.maintenance.FusionAuthMaintenanceModeWorkflow - Determine database status : ACTIVE
Jul 10, 2019 10:41:12.113 AM INFO io.fusionauth.app.maintenance.FusionAuthMaintenanceModeWorkflow - Determine search status : ACTIVE]
Jul 10, 2019 10:41:12.115 AM INFO org.primeframework.mvc.servlet.PrimeServletContextListener - Initializing Prime
Jul 10, 2019 10:41:12.118 AM INFO io.fusionauth.app.guice.FusionAuthModule -
--------- Starting FusionAuth version [1.3.1] -------
logs continue
Using CATALINA_BASE: "C:\fusionauth\fusionauth-app\apache-tomcat"
Using CATALINA_HOME: "C:\fusionauth\fusionauth-app\apache-tomcat"
Using CATALINA_TMPDIR: "C:\fusionauth\fusionauth-app\apache-tomcat\temp"
Using JRE_HOME: "C:\fusionauth\fusionauth-app\apache-tomcat\..\..\java\jre1.8.0_171"
Using CLASSPATH: "C:\fusionauth\fusionauth-app\apache-tomcat\bin\bootstrap.jar;C:\fusionauth\fusionauth-app\apache-tomcat\bin\tomcat-juli.jar"
Jul 10, 2019 10:57:41.944 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Loading FusionAuth configuration file [C:\fusionauth\fusionauth-app\apache-tomcat\..\..\config\fusionauth.properties]
Jul 10, 2019 10:57:41.993 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Dynamically set property [fusionauth-app.public-url] set to [http://192.168.XX.XX:XXXX]
Jul 10, 2019 10:57:41.994 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - FusionAuth Runtime Mode [Production]
Jul 10, 2019 10:57:42.164 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Loading FusionAuth configuration file [C:\fusionauth\fusionauth-app\apache-tomcat\..\..\config\fusionauth.properties]
Jul 10, 2019 10:57:42.208 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Dynamically set property [fusionauth-app.public-url] set to [http://192.168.XX.XX:XXXX]
Jul 10, 2019 10:57:42.209 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - FusionAuth Runtime Mode [Production]
The logs stop abruptly after the properties configuration...
I appreciate this is probably an issue with out environment however without the logs I am pretty stumped.
Currently the log level is INFO. Is there anyway to set the log level lower, for example to DEBUG so I can understand further whats happening?
I have already tried restarting the server.
Restarted both the fusion auth app and fusion auth search services
Tried running the fusion auth app and fusion auth search manually i.e. not as a service
Using CATALINA_BASE: "C:\fusionauth\fusionauth-app\apache-tomcat"
Using CATALINA_HOME: "C:\fusionauth\fusionauth-app\apache-tomcat"
Using CATALINA_TMPDIR: "C:\fusionauth\fusionauth-app\apache-tomcat\temp"
Using JRE_HOME: "C:\fusionauth\fusionauth-app\apache-tomcat\..\..\java\jre1.8.0_171"
Using CLASSPATH: "C:\fusionauth\fusionauth-app\apache-tomcat\bin\bootstrap.jar;C:\fusionauth\fusionauth-app\apache-tomcat\bin\tomcat-juli.jar"
08:03:37,104 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
08:03:37,104 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
08:03:37,105 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/fusionauth/fusionauth-app/web/WEB-INF/classes/logback.xml]
08:03:37,105 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath.
08:03:37,105 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/C:/fusionauth/fusionauth-app/web/WEB-INF/lib/fusionauth-app-1.3.1.jar!/logback.xml]
08:03:37,105 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/C:/fusionauth/fusionauth-app/web/WEB-INF/classes/logback.xml]
08:03:37,140 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
08:03:37,147 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 1 minutes
08:03:37,147 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[C:\fusionauth\fusionauth-app\web\WEB-INF\classes\logback.xml]] every 60 seconds.
08:03:37,147 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
08:03:37,152 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
08:03:37,155 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
08:03:37,170 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
08:03:37,204 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [io.fusionauth] to DEBUG
08:03:37,204 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [io.fusionauth] to false
08:03:37,204 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[io.fusionauth]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.primeframework] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.primeframework] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.primeframework]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.inversoft.migration] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [com.inversoft.migration] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[com.inversoft.migration]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.inversoft.maintenance] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [com.inversoft.maintenance] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[com.inversoft.maintenance]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka.common.utils.AppInfoParser] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.apache.kafka.common.utils.AppInfoParser] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.apache.kafka.common.utils.AppInfoParser]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka.clients.consumer.ConsumerConfig] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.apache.kafka.clients.consumer.ConsumerConfig] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.apache.kafka.clients.consumer.ConsumerConfig]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka.clients.producer.ProducerConfig] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.apache.kafka.clients.producer.ProducerConfig] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.apache.kafka.clients.producer.ProducerConfig]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka.clients.producer.KafkaProducer] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.apache.kafka.clients.producer.KafkaProducer] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.apache.kafka.clients.producer.KafkaProducer]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.kafka.clients.NetworkClient] to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.apache.kafka.clients.NetworkClient] to false
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[org.apache.kafka.clients.NetworkClient]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
08:03:37,205 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
08:03:37,205 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
08:03:37,206 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@18a29fef - Registering current configuration as safe fallback point
Jul 12, 2019 8:03:37.218 AM DEBUG org.primeframework.mvc.guice.GuiceBootstrap - Initializing Guice
Jul 12, 2019 8:03:37.800 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Loading FusionAuth configuration file [C:\fusionauth\fusionauth-app\apache-tomcat\..\..\config\fusionauth.properties]
Jul 12, 2019 8:03:37.840 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Dynamically set property [fusionauth-app.public-url] set to [http://192.168.XX.XX:XXXX]
Jul 12, 2019 8:03:37.841 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - FusionAuth Runtime Mode [Production]
Jul 12, 2019 8:03:37.965 AM DEBUG org.primeframework.mvc.guice.GuiceBootstrap - Initializing Guice
Jul 12, 2019 8:03:37.969 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Loading FusionAuth configuration file [C:\fusionauth\fusionauth-app\apache-tomcat\..\..\config\fusionauth.properties]
Jul 12, 2019 8:03:38.008 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - Dynamically set property [fusionauth-app.public-url] set to [http://192.168.XX.XX:XXXX]
Jul 12, 2019 8:03:38.009 AM INFO io.fusionauth.api.configuration.PropertiesFileFusionAuthConfiguration - FusionAuth Runtime Mode [Production]
Jul 12, 2019 8:03:38.061 AM DEBUG com.inversoft.maintenance.db.JDBCMaintenanceModeDatabaseService - Connection established to [192.168.XX.XX:XXXX]
To increase the log level during startup, you can perform the following steps:
Place a logback.xml file in fusionauth\fusionauth-app\web\WEB-INF\classes and then restart the service.
Here is an example configuration with DEBUG enabled.
<configuration scan="true" scanPeriod="60 seconds">
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<!-- encoders are assigned the type
ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
<encoder>
<pattern>%d{"MMM dd, yyyy h:mm:ss.SSS a"} %-5level %logger{75} - %msg%n</pattern>
</encoder>
</appender>
<!-- DEBUG enabled -->
<logger name="io.fusionauth" level="DEBUG" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.primeframework" level="INFO" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="com.inversoft.migration" level="INFO" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="com.inversoft.maintenance" level="INFO" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<!-- Kafka logging is chatty -->
<logger name="org.apache.kafka.common.utils.AppInfoParser" level="ERROR" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.apache.kafka.clients.consumer.ConsumerConfig" level="ERROR" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.apache.kafka.clients.producer.ProducerConfig" level="ERROR" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.apache.kafka.clients.producer.KafkaProducer" level="ERROR" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.apache.kafka.clients.NetworkClient" level="ERROR" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
https://gist.github.com/robotdan/422904ddf9381233b0ac73654fd8d243