Windows server installation error

ivolonte · September 16, 2020, 9:29pm

Hi everyone! I am running a windows server 2019 machine. I tried to follow all the steps shown on this video, but when I go to the Tomcat Web Application Manager, openboxes appears stopped. I tried to start openboxes from the App Manager, it takes some time, but finally appears the message “FAIL - Application at context path [/openboxes] could not be started”.

I tried looking the logs stderr and stdout and searching other topics with the same problem, but I could not found it. Here I attach the logs if anyone can help. Thanks in advance!

tomcat7-stderr.2020-09-16.log


2020-09-16 16:51:10 Apache Commons Daemon procrun stderr initialized.

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Nombre de la versión del servidor: Apache Tomcat/7.0.105

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Server built: Jul 2 2020 12:25:26 UTC

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Número de versión de servidor: 7.0.105.0

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: OS Name: Windows Server 2019

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Versión de Systema Operativo: 10.0

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Arquitectura: amd64

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Java Home: C:\Program Files\Zulu\zulu-7\jre

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: JVM Version: 1.7.0_272-b10

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Vededor JVM: Azul Systems, Inc.

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: CATALINA_BASE: C:\Program Files\Apache Software Foundation\Tomcat 7.0

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: CATALINA_HOME: C:\Program Files\Apache Software Foundation\Tomcat 7.0

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -Dcatalina.home=C:\Program Files\Apache Software Foundation\Tomcat 7.0

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -Dcatalina.base=C:\Program Files\Apache Software Foundation\Tomcat 7.0

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -Djava.io.tmpdir=C:\Program Files\Apache Software Foundation\Tomcat 7.0\temp

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -Djava.util.logging.config.file=C:\Program Files\Apache Software Foundation\Tomcat 7.0\conf\logging.properties

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -XX:MaxPermSize=512m

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: exit

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: abort

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -Xms512m

sep 16, 2020 4:51:10 PM org.apache.catalina.startup.VersionLoggerListener log

INFORMACIÓN: Command line argument: -Xmx2048m

sep 16, 2020 4:51:10 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent

INFORMACIÓN: Cargada la biblioteca nativa APR de Apache Tomcat [1.2.24] con la versión APR [1.7.0].

sep 16, 2020 4:51:10 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent

INFORMACIÓN: Capacidades APR: IPv6 [true], enviar fichero [true], aceptar filtros [false], aleatorio [true].

sep 16, 2020 4:51:10 PM org.apache.catalina.core.AprLifecycleListener initializeSSL

INFORMACIÓN: OpenSSL inicializado correctamente [OpenSSL 1.1.1g 21 Apr 2020]

sep 16, 2020 4:51:11 PM org.apache.coyote.AbstractProtocol init

INFORMACIÓN: Inicializando el manejador de protocolo ["http-apr-8080"]

sep 16, 2020 4:51:11 PM org.apache.catalina.startup.Catalina load

INFORMACIÓN: Initialization processed in 522 ms

sep 16, 2020 4:51:11 PM org.apache.catalina.core.StandardService startInternal

INFORMACIÓN: Arrancando servicio [Catalina]

sep 16, 2020 4:51:11 PM org.apache.catalina.core.StandardEngine startInternal

INFORMACIÓN: Starting Servlet Engine: Apache Tomcat/7.0.105

sep 16, 2020 4:51:11 PM org.apache.catalina.startup.HostConfig deployWAR

INFORMACIÓN: Despliegue del archivo [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\openboxes.war] de la aplicación web

sep 16, 2020 4:51:30 PM org.apache.catalina.startup.TldConfig execute

INFORMACIÓN: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.

sep 16, 2020 4:58:18 PM org.apache.catalina.core.StandardContext startInternal

GRAVE: One or more listeners failed to start. Full details will be found in the appropriate container log file

sep 16, 2020 4:58:18 PM org.apache.catalina.core.StandardContext startInternal

GRAVE: Falló en arranque del Contexto [/openboxes] debido a errores previos

sep 16, 2020 4:58:18 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc

GRAVE: La aplicación web [/openboxes] registró el conductor JDBC [com.mysql.jdbc.Driver] pero falló al anular el registro mientras la aplicación web estaba parada. Para prevenir un fallo de memoria, se ha anulado el registro del conductor JDBC por la fuerza.

sep 16, 2020 4:58:18 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16b07km19tzo0t|301c3037]-HelperThread-#0] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 4:58:18 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16b07km19tzo0t|301c3037]-HelperThread-#1] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 4:58:18 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16b07km19tzo0t|301c3037]-HelperThread-#2] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 4:58:18 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16b07km19tzo0t|301c3037]-DeferredStatementDestroyerThread-#0] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 4:58:18 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Abandoned connection cleanup thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.HostConfig deployWAR

INFORMACIÓN: Deployment of web application archive [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\openboxes.war] has finished in [427.772] ms

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.HostConfig deployDirectory

INFORMACIÓN: Desplegando el directorio [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\docs] de la aplicación web

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.HostConfig deployDirectory

INFORMACIÓN: Deployment of web application directory [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\docs] has finished in [47] ms

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.HostConfig deployDirectory

INFORMACIÓN: Desplegando el directorio [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\manager] de la aplicación web

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.HostConfig deployDirectory

INFORMACIÓN: Deployment of web application directory [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\manager] has finished in [63] ms

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.HostConfig deployDirectory

INFORMACIÓN: Desplegando el directorio [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\ROOT] de la aplicación web

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.HostConfig deployDirectory

INFORMACIÓN: Deployment of web application directory [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\ROOT] has finished in [31] ms

sep 16, 2020 4:58:18 PM org.apache.coyote.AbstractProtocol start

INFORMACIÓN: Starting ProtocolHandler ["http-apr-8080"]

sep 16, 2020 4:58:18 PM org.apache.catalina.startup.Catalina start

INFORMACIÓN: Server startup in 427962 ms

sep 16, 2020 4:58:20 PM org.apache.catalina.loader.WebappClassLoaderBase findResourceInternal

INFORMACIÓN: Acceso ilegal: esta instancia de aplicación web ya ha sido parada. Could not load []. La eventual traza de pila que sigue ha sido motivada por un error lanzado con motivos de depuración así como para intentar terminar el hilo que motivó el acceso ilegal y no tiene impacto funcional.

sep 16, 2020 5:20:09 PM org.apache.catalina.startup.TldConfig execute

INFORMACIÓN: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.

sep 16, 2020 5:27:03 PM org.apache.catalina.core.StandardContext startInternal

GRAVE: One or more listeners failed to start. Full details will be found in the appropriate container log file

sep 16, 2020 5:27:03 PM org.apache.catalina.core.StandardContext startInternal

GRAVE: Falló en arranque del Contexto [/openboxes] debido a errores previos

sep 16, 2020 5:27:03 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc

GRAVE: La aplicación web [/openboxes] registró el conductor JDBC [com.mysql.jdbc.Driver] pero falló al anular el registro mientras la aplicación web estaba parada. Para prevenir un fallo de memoria, se ha anulado el registro del conductor JDBC por la fuerza.

sep 16, 2020 5:27:03 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16c112prm9rar|635260]-HelperThread-#0] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 5:27:03 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16c112prm9rar|635260]-HelperThread-#1] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 5:27:03 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16c112prm9rar|635260]-HelperThread-#2] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 5:27:03 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16c112prm9rar|635260]-DeferredStatementDestroyerThread-#0] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 5:27:03 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads

GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Abandoned connection cleanup thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.

sep 16, 2020 5:27:07 PM org.apache.catalina.loader.WebappClassLoaderBase findResourceInternal

INFORMACIÓN: Acceso ilegal: esta instancia de aplicación web ya ha sido parada. Could not load []. La eventual traza de pila que sigue ha sido motivada por un error lanzado con motivos de depuración así como para intentar terminar el hilo que motivó el acceso ilegal y no tiene impacto funcional.

+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

Wed Sep 16 16:52:00 ART 2020 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

Wed Sep 16 16:52:00 ART 2020 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

-- (the same paragraph a lot of times) --

Wed Sep 16 16:58:18 ART 2020 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

log4j:WARN No appenders could be found for logger (com.mchange.v2.async.ThreadPoolAsynchronousRunner).

log4j:WARN Please initialize the log4j system properly.

log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

log4j:WARN No appenders could be found for logger (com.mchange.v2.async.ThreadPoolAsynchronousRunner).

log4j:WARN Please initialize the log4j system properly.

log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

log4j:WARN No appenders could be found for logger (com.mchange.v2.async.ThreadPoolAsynchronousRunner).

log4j:WARN Please initialize the log4j system properly.

log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

Unable to load specified config location classpath:openboxes-config.properties : class path resource [openboxes-config.properties] cannot be opened because it does not exist

Unable to load specified config location classpath:openboxes-config.groovy : class path resource [openboxes-config.groovy] cannot be opened because it does not exist

Unable to load specified config location file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.groovy : C:\Windows\ServiceProfiles\LocalService\.grails\openboxes-config.groovy (El sistema no puede encontrar el archivo especificado)

Wed Sep 16 17:20:17 ART 2020 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

-- (the same paragraph a lot of times) --

Wed Sep 16 17:27:03 ART 2020 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

Wed Sep 16 17:27:03 ART 2020 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

log4j:WARN No appenders could be found for logger (com.mchange.v2.async.ThreadPoolAsynchronousRunner).

log4j:WARN Please initialize the log4j system properly.

log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

log4j:WARN No appenders could be found for logger (com.mchange.v2.async.ThreadPoolAsynchronousRunner).

log4j:WARN Please initialize the log4j system properly.

log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

jmiranda · September 17, 2020, 2:47am

Can you zip up and send all of the Tomcat logs to support@openboxes.com? I have a feeling we’re missing something in the stderr so I assume its in the stdout log (or one of the other logs).

ivolonte · September 17, 2020, 11:30am

Hi!, Ok, I’ll send all the logs by e-mails. Thnaks!

jmiranda · September 17, 2020, 3:29pm

The stdout log contains the error that

2020-09-16 17:41:55,477 [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac16ckdhg1ra4xbv|2b801215]-HelperThread-#1] WARN  resourcepool.BasicResourcePool  - com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6e71cdbb -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: 
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Could not create connection to database server. Attempted reconnect 3 times. Giving up.

Later in the stacktrace we see the cause

Access denied for user 'root'@'localhost' (using password: YES)

There are a few possible reasons for this error:

The openboxes-config.properties file has not been created (or Tomcat is not able to read it) which causes the application to use the default dataSource.username and dataSource.password defined in Config.groovy.
The openboxes-config.properties file has been created but is not readable by Tomcat.

The cause suggests that the file is not being found so we’re going to look at the rest of the log to see if we’re correct. If I splice the stdout and stderro together I see the following.

Using configuration locations [classpath:openboxes-config.properties, classpath:openboxes-config.groovy, file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.properties, file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.groovy] [production]
Unable to load specified config location classpath:openboxes-config.properties : class path resource [openboxes-config.properties] cannot be opened because it does not exist
Unable to load specified config location classpath:openboxes-config.groovy : class path resource [openboxes-config.groovy] cannot be opened because it does not exist
Unable to load specified config location file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.groovy : C:\Windows\ServiceProfiles\LocalService\.grails\openboxes-config.groovy (El sistema no puede encontrar el archivo especificado)

This is good. As part of the installation instructions we usually only create openboxes-config.properties in the user’s home directory so the first line is saying “we have four possible config locations” and the next three lines are telling us that 3 out of the 4 were not found (implying that 1 was found). So we’re good.

~~classpath:openboxes-config.properties~~
~~classpath:openboxes-config.groovy~~
file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.properties
~~file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.groovy~~

Ok, so it’s finding the openboxes-config.properties at the above location. So we now have two possible problems

You have set the dataSource.username to root and dataSource.password to some invalid password. This is less likely since the instructions suggest that you use openboxes as the dataSource.username. But if you find yourself in this situation, then you probably just need to figure out the root password and set it in openboxes-config.properties.
You have set the username / password to something else but the file is not being read properly by Tomcat. This one is harder to deal with on Windows then on Ubuntu. I have tried time and again to change permissions of files on Windows with no luck.

So hopefully you have better luck than I have with this. Can you maybe explain how (exactly) you created that file and the .grails directory? I think I’ve had trouble when I created the .grails directory from a command line. So perhaps create it using Windows Explorer (or whatever the GUI file manager is for Windows). Or play around with the read, write permissions and ownership of the .grails directory

In Ubuntu I would do something like this and it would usually work.

sudo chown tomcat:tomcat /opt/tomcat/.grails
sudo chmod +r /opt/tomcat/.grails

So keep playing around with the permissions, restart Tomcat, and check stdout to see if you get past the database connection phase of the startup process.

ivolonte · September 18, 2020, 7:22pm

Justin, thank you for your help!

First of all, my file openboxes-config.properties has this content, I double check and I think it is ok.

dataSource.url=jdbc:mysql://localhost:3306/openboxes?useSSL=false
dataSource.username=openboxes
dataSource.password=openboxes

I’ve created the folder .grails and the file from PowerShell following the video.
The folder can’t be created from the Windows GUI (Windows Explorer) because it does not allow a name with dots. So I tried to create the folder from the command prompt and created a new openboxes-config.properties directly from Notepad.

I restarted Tomcat and the line “Access denied for user ‘root’@‘localhost’ (using password: YES)” does not appear in the stdout log file.

I don’t know if openboxes can connect now to SQL database. Taking a look on the stdout log file, I found this line:

2020-09-18 15:56:37,672 [localhost-startStop-1] ERROR context.ContextLoader  - Context initialization failed
org.springframework.beans.factory.access.BootstrapException: Error executing bootstraps; nested exception is org.codehaus.groovy.runtime.InvokerInvocationException: liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by SERVER (192.168.56.1) since 10/09/20 17:10

I serch files created on that date and time, and I found files on the folder C:\ProgramData\MySQL\MySQL Server 5.7\Data\openboxes that matches. So I guess there is a problem accessing the database.

I tried to use this commands on database command line as root user, but there is no changes.

GRANT ALL PRIVILEGES ON 'openboxes'.* TO 'openboxes'@'%';
FLUSH PRIVILEGES;

Here you have the full stdout log:


2020-09-18 15:51:06 Apache Commons Daemon procrun stdout initialized.
Using configuration locations [classpath:openboxes-config.properties, classpath:openboxes-config.groovy, file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.properties, file:C:\Windows\ServiceProfiles\LocalService/.grails/openboxes-config.groovy] [production]
2020-09-18 15:51:14,997 [localhost-startStop-1] INFO  context.ContextLoader  - Root WebApplicationContext: initialization started
2020-09-18 15:51:15,012 [localhost-startStop-1] INFO  support.XmlWebApplicationContext  - Refreshing Root WebApplicationContext: startup date [Fri Sep 18 15:51:15 ART 2020]; root of context hierarchy
2020-09-18 15:51:15,044 [localhost-startStop-1] INFO  xml.XmlBeanDefinitionReader  - Loading XML bean definitions from ServletContext resource [/WEB-INF/applicationContext.xml]
2020-09-18 15:51:15,122 [localhost-startStop-1] INFO  support.DefaultListableBeanFactory  - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@68ce4f11: defining beans [grailsApplication,pluginManager,grailsConfigurator,grailsResourceLoader,grailsResourceHolder,characterEncodingFilter]; root of factory hierarchy
2020-09-18 15:51:16,215 [localhost-startStop-1] WARN  commons.GrailsApplicationFactoryBean  - Class with name [org.pih.warehouse.putaway.PutawayService] was not found, and hence not loaded. Possible empty class or script definition?
2020-09-18 15:51:18,012 [localhost-startStop-1] INFO  cfg.Environment  - Hibernate 3.3.1.GA
2020-09-18 15:51:18,028 [localhost-startStop-1] INFO  cfg.Environment  - hibernate.properties not found
2020-09-18 15:51:18,028 [localhost-startStop-1] INFO  cfg.Environment  - Bytecode provider name : javassist
2020-09-18 15:51:18,028 [localhost-startStop-1] INFO  cfg.Environment  - using JDK 1.4 java.sql.Timestamp handling
2020-09-18 15:51:20,637 [localhost-startStop-1] INFO  annotation.ClassPathBeanDefinitionScanner  - JSR-250 'javax.annotation.ManagedBean' found and supported for component scanning
2020-09-18 15:51:21,200 [MLog-Init-Reporter] INFO  log.MLog  - MLog clients using slf4j logging.
2020-09-18 15:51:22,371 [localhost-startStop-1] INFO  c3p0.C3P0Registry  - Initializing c3p0-0.9.5.3 [built 27-January-2019 00:11:37 -0800; debug? true; trace: 10]
2020-09-18 15:51:22,700 [localhost-startStop-1] INFO  impl.AbstractPoolBackedDataSource  - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 5, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, dataSourceName -> 1hgeby9ac193qe4mdr0j95|6ed95e60, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.mysql.jdbc.Driver, extensions -> {}, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, forceUseNamedDriverClass -> false, identityToken -> 1hgeby9ac193qe4mdr0j95|6ed95e60, idleConnectionTestPeriod -> 7200, initialPoolSize -> 10, jdbcUrl -> jdbc:mysql://localhost:3306/openboxes?useSSL=false, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 14400, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 1800, maxPoolSize -> 100, maxStatements -> 180, maxStatementsPerConnection -> 0, minPoolSize -> 5, numHelperThreads -> 3, preferredTestQuery -> SELECT 1, privilegeSpawnedThreads -> false, properties -> {user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 1, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ]
2020-09-18 15:51:22,981 [localhost-startStop-1] INFO  annotations.Version  - Hibernate Annotations 3.4.0.GA
2020-09-18 15:51:23,012 [localhost-startStop-1] INFO  common.Version  - Hibernate Commons Annotations 3.1.0.GA
2020-09-18 15:51:23,356 [localhost-startStop-1] WARN  commons.GrailsDomainConfigurationUtil  - Derived properties may not be constrained. Property [shipmentItemCount] of domain class org.pih.warehouse.shipping.Shipment will not be checked during validation.
2020-09-18 15:51:23,434 [localhost-startStop-1] WARN  commons.GrailsDomainConfigurationUtil  - Derived properties may not be constrained. Property [monthRequested] of domain class org.pih.warehouse.requisition.Requisition will not be checked during validation.
2020-09-18 15:51:23,512 [localhost-startStop-1] INFO  validator.Version  - Hibernate Validator 3.1.0.GA
2020-09-18 15:51:23,575 [localhost-startStop-1] INFO  search.HibernateSearchEventListenerRegister  - Unable to find org.hibernate.search.event.FullTextIndexEventListener on the classpath. Hibernate Search is not enabled.
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  connection.ConnectionProviderFactory  - Initializing connection provider: org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - RDBMS: MySQL, version: 5.7.31-log
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - JDBC driver: MySQL Connector Java, version: mysql-connector-java-5.1.47 ( Revision: fe1903b1ecb4a96a917f7ed3190d80c049b1de29 )
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  dialect.Dialect  - Using dialect: org.hibernate.dialect.MySQL5InnoDBDialect
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  transaction.TransactionFactoryFactory  - Transaction strategy: org.springframework.orm.hibernate3.SpringTransactionFactory
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  transaction.TransactionManagerLookupFactory  - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Automatic flush during beforeCompletion(): disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Automatic session close at end of transaction: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - JDBC batch size: 15
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - JDBC batch updates for versioned data: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Scrollable result sets: enabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - JDBC3 getGeneratedKeys(): enabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - JDBC result set fetch size: 25
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Connection release mode: auto
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Maximum outer join fetch depth: 2
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Default batch fetch size: 25
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Generate SQL with comments: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Order SQL updates by primary key: enabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Order SQL inserts for batching: enabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  ast.ASTQueryTranslatorFactory  - Using ASTQueryTranslatorFactory
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Query language substitutions: {}
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - JPA-QL strict compliance: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Second-level cache: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Query cache: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Cache region factory : org.hibernate.cache.impl.NoCachingRegionFactory
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Optimize cache for minimal puts: enabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Structured second-level cache entries: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Statistics: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Deleted entity synthetic identifier rollback: disabled
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Default entity-mode: pojo
2020-09-18 15:51:23,684 [localhost-startStop-1] INFO  cfg.SettingsFactory  - Named query checking : enabled
2020-09-18 15:51:23,715 [localhost-startStop-1] INFO  impl.SessionFactoryImpl  - building session factory
2020-09-18 15:51:24,996 [localhost-startStop-1] INFO  util.NamingHelper  - JNDI InitialContext properties:{}
2020-09-18 15:51:25,934 [localhost-startStop-1] INFO  config.PropertiesFactoryBean  - Loading properties file from class path resource [gsp/views.properties]
2020-09-18 15:51:26,637 [localhost-startStop-1] INFO  ehcache.EhCacheManagerFactoryBean  - Initializing EHCache CacheManager
2020-09-18 15:51:26,793 [localhost-startStop-1] INFO  impl.StdSchedulerFactory  - Using default implementation for ThreadExecutor
2020-09-18 15:51:26,793 [localhost-startStop-1] INFO  simpl.SimpleThreadPool  - Job execution threads will use class loader of thread: localhost-startStop-1
2020-09-18 15:51:26,793 [localhost-startStop-1] INFO  core.SchedulerSignalerImpl  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2020-09-18 15:51:26,793 [localhost-startStop-1] INFO  core.QuartzScheduler  - Quartz Scheduler v.2.1.6 created.
2020-09-18 15:51:26,809 [localhost-startStop-1] INFO  simpl.RAMJobStore  - RAMJobStore initialized.
2020-09-18 15:51:26,809 [localhost-startStop-1] INFO  core.QuartzScheduler  - Scheduler meta-data: Quartz Scheduler (v2.1.6) 'DefaultPluginScheduler' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

2020-09-18 15:51:26,809 [localhost-startStop-1] INFO  impl.StdSchedulerFactory  - Quartz scheduler 'DefaultPluginScheduler' initialized from an externally provided properties instance.
2020-09-18 15:51:26,809 [localhost-startStop-1] INFO  impl.StdSchedulerFactory  - Quartz scheduler version: 2.1.6
2020-09-18 15:51:26,809 [localhost-startStop-1] INFO  core.QuartzScheduler  - JobFactory set to: grails.plugin.quartz2.GrailsJobFactory@746ffd84
2020-09-18 15:51:28,215 [localhost-startStop-1] INFO  support.DefaultLifecycleProcessor  - Starting beans in phase 2147483647
Starting Quartz Scheduler in QuartzFactoryBean
2020-09-18 15:51:28,215 [localhost-startStop-1] INFO  core.QuartzScheduler  - Scheduler DefaultPluginScheduler_$_NON_CLUSTERED started.
2020-09-18 15:51:28,403 [localhost-startStop-1] INFO  support.DefaultListableBeanFactory  - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7f715ade: defining beans [org.grails.plugin.zippedresources.ZipResourceMapper,org.grails.plugin.resource.CSSRewriterResourceMapper,org.grails.plugin.cachedresources.HashAndCacheResourceMapper,org.grails.plugin.resource.BundleResourceMapperInstance,org.grails.plugin.resource.CSSRewriterResourceMapperInstance,org.grails.plugin.resource.BundleResourceMapper,org.grails.plugin.cachedresources.HashAndCacheResourceMapperInstance,org.grails.plugin.zippedresources.ZipResourceMapperInstance,org.grails.plugin.resource.CSSPreprocessorResourceMapperInstance,org.grails.plugin.resource.CSSPreprocessorResourceMapper]; parent: org.codehaus.groovy.grails.commons.spring.ReloadAwareAutowireCapableBeanFactory@7ad9275a
2020-09-18 15:51:37,027 [localhost-startStop-1] WARN  commons.GrailsDomainConfigurationUtil  - Derived properties may not be constrained. Property [shipmentItemCount] of domain class org.pih.warehouse.shipping.Shipment will not be checked during validation.
2020-09-18 15:51:37,043 [localhost-startStop-1] WARN  commons.GrailsDomainConfigurationUtil  - Derived properties may not be constrained. Property [monthRequested] of domain class org.pih.warehouse.requisition.Requisition will not be checked during validation.
2020-09-18 15:51:37,184 [localhost-startStop-1] INFO  bootstrap.BootStrap  - Running liquibase changelog(s) ...
2020-09-18 15:51:37,262 [localhost-startStop-1] INFO  bootstrap.BootStrap  - Liquibase running: true
2020-09-18 15:51:37,262 [localhost-startStop-1] INFO  bootstrap.BootStrap  - Setting default schema to openboxes
2020-09-18 15:51:37,262 [localhost-startStop-1] INFO  bootstrap.BootStrap  - Product Version: 5.7.31-log
2020-09-18 15:51:37,262 [localhost-startStop-1] INFO  bootstrap.BootStrap  - Database Version: 5.7
2020-09-18 15:51:37,277 [localhost-startStop-1] INFO  liquibase  - Reading from `DATABASECHANGELOG`
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
2020-09-18 15:52:00,058 [DefaultPluginScheduler_Worker-1] INFO  jobs.AssignIdentifierJob  - Postponing job execution until liquibase migrations are complete
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
2020-09-18 15:53:00,013 [DefaultPluginScheduler_Worker-2] INFO  jobs.AssignIdentifierJob  - Postponing job execution until liquibase migrations are complete
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
2020-09-18 15:54:00,011 [DefaultPluginScheduler_Worker-3] INFO  jobs.AssignIdentifierJob  - Postponing job execution until liquibase migrations are complete
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
2020-09-18 15:55:00,011 [DefaultPluginScheduler_Worker-4] INFO  jobs.AssignIdentifierJob  - Postponing job execution until liquibase migrations are complete
2020-09-18 15:55:00,042 [DefaultPluginScheduler_Worker-5] INFO  jobs.DataCleaningJob  - Postponing job execution until liquibase migrations are complete
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
2020-09-18 15:56:00,000 [DefaultPluginScheduler_Worker-6] INFO  jobs.AssignIdentifierJob  - Postponing job execution until liquibase migrations are complete
Waiting for changelog lock....
Waiting for changelog lock....
Waiting for changelog lock....
2020-09-18 15:56:37,672 [localhost-startStop-1] ERROR context.ContextLoader  - Context initialization failed
org.springframework.beans.factory.access.BootstrapException: Error executing bootstraps; nested exception is org.codehaus.groovy.runtime.InvokerInvocationException: liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by SERVER (192.168.56.1) since 10/09/20 17:10
	at org.codehaus.groovy.grails.web.context.GrailsContextLoader.createWebApplicationContext(GrailsContextLoader.java:87)
	at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:197)
	at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:47)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5128)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5653)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1007)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:983)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:639)
	at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1127)
	at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:2019)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.codehaus.groovy.runtime.InvokerInvocationException: liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by SERVER (192.168.56.1) since 10/09/20 17:10
	at grails.util.Environment.evaluateEnvironmentSpecificBlock(Environment.java:251)
	at grails.util.Environment.executeForEnvironment(Environment.java:244)
	at grails.util.Environment.executeForCurrentEnvironment(Environment.java:220)
	... 5 more
Caused by: liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by SERVER (192.168.56.1) since 10/09/20 17:10
	at liquibase.lock.LockHandler.waitForLock(LockHandler.java:170)
	at liquibase.Liquibase.update(Liquibase.java:100)
	at liquibase.Liquibase$update.call(Unknown Source)
	at BootStrap$_closure1.doCall(BootStrap.groovy:447)
	... 8 more

ivolonte · September 18, 2020, 7:23pm

And the stderr log:


2020-09-18 15:51:06 Apache Commons Daemon procrun stderr initialized.
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Nombre de la versión del servidor:   Apache Tomcat/7.0.105

sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Server built:          Jul 2 2020 12:25:26 UTC
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Número de versión de servidor:         7.0.105.0
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: OS Name:               Windows Server 2019
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Versión de Systema Operativo:      10.0

sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Arquitectura:          amd64

sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Java Home:             C:\Program Files\Zulu\zulu-7\jre
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: JVM Version:           1.7.0_272-b10
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Vededor JVM:     Azul Systems, Inc.
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: CATALINA_BASE:         C:\Program Files\Apache Software Foundation\Tomcat 7.0
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: CATALINA_HOME:         C:\Program Files\Apache Software Foundation\Tomcat 7.0
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -Dcatalina.home=C:\Program Files\Apache Software Foundation\Tomcat 7.0
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -Dcatalina.base=C:\Program Files\Apache Software Foundation\Tomcat 7.0
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -Djava.io.tmpdir=C:\Program Files\Apache Software Foundation\Tomcat 7.0\temp
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -Djava.util.logging.config.file=C:\Program Files\Apache Software Foundation\Tomcat 7.0\conf\logging.properties
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -XX:MaxPermSize=512m
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: exit
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: abort
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -Xms512m
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.VersionLoggerListener log
INFORMACIÓN: Command line argument: -Xmx2048m
sep 18, 2020 3:51:07 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFORMACIÓN: Cargada la biblioteca nativa APR de Apache Tomcat [1.2.24] con la versión APR [1.7.0].
sep 18, 2020 3:51:07 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFORMACIÓN: Capacidades APR: IPv6 [true], enviar fichero [true], aceptar filtros [false], aleatorio [true].
sep 18, 2020 3:51:07 PM org.apache.catalina.core.AprLifecycleListener initializeSSL
INFORMACIÓN: OpenSSL inicializado correctamente [OpenSSL 1.1.1g  21 Apr 2020]
sep 18, 2020 3:51:07 PM org.apache.coyote.AbstractProtocol init
INFORMACIÓN: Inicializando el manejador de protocolo ["http-apr-8080"]

sep 18, 2020 3:51:07 PM org.apache.catalina.startup.Catalina load
INFORMACIÓN: Initialization processed in 521 ms
sep 18, 2020 3:51:07 PM org.apache.catalina.core.StandardService startInternal
INFORMACIÓN: Arrancando servicio [Catalina]
sep 18, 2020 3:51:07 PM org.apache.catalina.core.StandardEngine startInternal
INFORMACIÓN: Starting Servlet Engine: Apache Tomcat/7.0.105
sep 18, 2020 3:51:07 PM org.apache.catalina.startup.HostConfig deployWAR
INFORMACIÓN: Despliegue del archivo [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\openboxes.war] de la aplicación web
sep 18, 2020 3:51:14 PM org.apache.catalina.startup.TldConfig execute
INFORMACIÓN: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
sep 18, 2020 3:56:37 PM org.apache.catalina.core.StandardContext startInternal
GRAVE: One or more listeners failed to start. Full details will be found in the appropriate container log file
sep 18, 2020 3:56:37 PM org.apache.catalina.core.StandardContext startInternal
GRAVE: Falló en arranque del Contexto [/openboxes] debido a errores previos
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc
GRAVE: La aplicación web [/openboxes] registró el conductor JDBC [com.mysql.jdbc.Driver] pero falló al anular el registro mientras la aplicación web estaba parada. Para prevenir un fallo de memoria, se ha anulado el registro del conductor JDBC por la fuerza.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac193qe4mdr0j95|6ed95e60]-AdminTaskTimer] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac193qe4mdr0j95|6ed95e60]-HelperThread-#0] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac193qe4mdr0j95|6ed95e60]-HelperThread-#1] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac193qe4mdr0j95|6ed95e60]-HelperThread-#2] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [C3P0PooledConnectionPoolManager[identityToken->1hgeby9ac193qe4mdr0j95|6ed95e60]-DeferredStatementDestroyerThread-#0] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Abandoned connection cleanup thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [net.sf.ehcache.CacheManager@78a3964] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store inventorySnapshotCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store dashboardCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store messageCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store dashboardTotalStockValueCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store megamenuCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store selectTagsCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-1] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-2] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-3] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-4] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-5] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-6] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-7] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-8] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-9] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_Worker-10] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store binLocationReportCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store selectCatalogsCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store inventoryBrowserCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store dashboardProductSummaryCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store fastMoversCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store quantityOnHandCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store selectTagCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store binLocationSummaryCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store selectCategoryCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Store dashboardGenericProductSummaryCache Spool Thread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [Timer-0] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
GRAVE: La aplicación web [/openboxes] parece haber arrancado un hilo llamado [DefaultPluginScheduler_QuartzSchedulerThread] pero no ha podido pararlo. Esto tiene todas las papeletas de convertirse en un fallo de memoria.
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.HostConfig deployWAR
INFORMACIÓN: Deployment of web application archive [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\openboxes.war] has finished in [330.221] ms
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.HostConfig deployDirectory
INFORMACIÓN: Desplegando el directorio [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\docs] de la aplicación web
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.HostConfig deployDirectory
INFORMACIÓN: Deployment of web application directory [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\docs] has finished in [47] ms
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.HostConfig deployDirectory
INFORMACIÓN: Desplegando el directorio [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\manager] de la aplicación web
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.HostConfig deployDirectory
INFORMACIÓN: Deployment of web application directory [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\manager] has finished in [31] ms
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.HostConfig deployDirectory
INFORMACIÓN: Desplegando el directorio [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\ROOT] de la aplicación web
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.HostConfig deployDirectory
INFORMACIÓN: Deployment of web application directory [C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\ROOT] has finished in [16] ms
sep 18, 2020 3:56:37 PM org.apache.coyote.AbstractProtocol start
INFORMACIÓN: Starting ProtocolHandler ["http-apr-8080"]
sep 18, 2020 3:56:37 PM org.apache.catalina.startup.Catalina start
INFORMACIÓN: Server startup in 330385 ms
sep 18, 2020 3:56:38 PM org.apache.catalina.loader.WebappClassLoaderBase findResourceInternal
INFORMACIÓN: Acceso ilegal: esta instancia de aplicación web ya ha sido parada.  Could not load [].  La eventual traza de pila que sigue ha sido motivada por un error lanzado con motivos de depuración así como para intentar terminar el hilo que motivó el acceso ilegal y no tiene impacto funcional.
sep 18, 2020 4:00:00 PM org.apache.catalina.loader.WebappClassLoaderBase findResourceInternal
INFORMACIÓN: Acceso ilegal: esta instancia de aplicación web ya ha sido parada.  Could not load [org/pih/warehouse/jobs/CalculateQuantityJob.class].  La eventual traza de pila que sigue ha sido motivada por un error lanzado con motivos de depuración así como para intentar terminar el hilo que motivó el acceso ilegal y no tiene impacto funcional.
sep 18, 2020 4:00:00 PM org.apache.catalina.loader.WebappClassLoaderBase findResourceInternal
INFORMACIÓN: Acceso ilegal: esta instancia de aplicación web ya ha sido parada.  Could not load [org/pih/warehouse/core/ApiClientService.class].  La eventual traza de pila que sigue ha sido motivada por un error lanzado con motivos de depuración así como para intentar terminar el hilo que motivó el acceso ilegal y no tiene impacto funcional.

jmiranda · September 18, 2020, 8:31pm

Yay! So thankfully, this is a pretty straightforward error.

OpenBoxes uses Liquibase to create the database schema. There are 100s of changelogs (database migrations) that need to be executed in order to create the latest version of the database schema. This process takes a long time (sometimes 20-30 minutes). In your case, the database migration process must have been interrupted. In other words, you stopped Tomcat while the database migrations were being executed, which leaves the application in an invalid state as evidenced by the following error message.

2020-09-18 15:51:37,277 [localhost-startStop-1] INFO  liquibase  - Reading from `DATABASECHANGELOG`
Waiting for changelog lock....

The fix is fairly straightforward as well.

Stop Tomcat

Delete the DATABASE_CHANGELOGLOCK record

$ mysql -u openboxes -p openboxes -e 'delete from DATABASECHANGELOGLOCK;'

Start Tomcat
Then wait for all database migrations to be executed which can be achieved on Linux with the following . On Windows, Microsoft makes it infinitely harder to tail a log file, but I was able to get it working with PowerShell on Windows 10 doing something like this https://www.howtogeek.com/tips/how-to-get-tail-like-functionality-on-windows-with-powershell/.
```
$ tail -f /opt/tomcat/logs/catalina.out
```

ivolonte · September 19, 2020, 8:59pm

Justin, thank you so much!

On Windows, I used this command to delete the table:

DROP TABLE DATABASECHANGELOGLOCK;

Finally the CHANGESET appears on stdout log!

Regarding the tail, I Windows PowerShell ISE and the tail works great!

I wait some time and finally the OpenBoxes started!

Thank you so much agian for your help!

jmiranda · September 21, 2020, 2:20am

Glad you got it working. But be careful. I said to do a “DELETE FROM DATABASECHANGELOGLOCK” which just deletes any records in the table. You dropped the table. Which could lead to some issues later on. So make sure that the DATABASECHANGELOGLOCK table is recreated by Liquibase on startup.

You can check to see if the table exists and has the right columns by running the following command:

$ mysql -u openboxes -p openboxes -e 'DESCRIBE DATABASECHANGELOGLOCK;'
+-------------+--------------+------+-----+---------+-------+
| Field       | Type         | Null | Key | Default | Extra |
+-------------+--------------+------+-----+---------+-------+
| ID          | int(11)      | NO   | PRI | NULL    |       |
| LOCKED      | tinyint(1)   | NO   |     | NULL    |       |
| LOCKGRANTED | datetime     | YES  |     | NULL    |       |
| LOCKEDBY    | varchar(255) | YES  |     | NULL    |       |
+-------------+--------------+------+-----+---------+-------+

ivolonte · September 21, 2020, 1:36pm

Justin, I’ve just verified and the table was recreated and the structure is as you described.

Thank you for your support!

jmiranda · July 5, 2021, 3:51pm

3 posts were split to a new topic: Windows installation errors