Opened 6 years ago

Closed 6 years ago

#1787 closed defect (fixed)

liquibase lock issue on petascopedb

Reported by: Dimitar Misev Owned by: Bang Pham Huu
Priority: critical Milestone: 9.7
Component: petascope Version: development
Keywords: Cc: Vlad Merticariu
Complexity: Medium

Description

This seems to be a random problem that happens for unknown (?) reason at petascope startup; to fix it some lock needs to be manually cleared in petascopedb (how?) and Tomcat restarted.

Below is the whole petascope.log:

  INFO [2018-06-07 13:06:19] ConfigManager@396: ------------------------------------
  INFO [2018-06-07 13:06:19] ConfigManager@398: -- PETASCOPE
  INFO [2018-06-07 13:06:19] ConfigManager@399: Version: 9.6.0
  INFO [2018-06-07 13:06:19] ConfigManager@400: DB URL: jdbc:postgresql://localhost:5432/petascopedb
  INFO [2018-06-07 13:06:19] ConfigManager@401: DB User: petauser
  INFO [2018-06-07 13:06:19] ConfigManager@402: 
  INFO [2018-06-07 13:06:19] ConfigManager@404: -- RASDAMAN
  INFO [2018-06-07 13:06:19] ConfigManager@405: Version: 9.6.0
  INFO [2018-06-07 13:06:19] ConfigManager@406: URL: http://localhost:7001
  INFO [2018-06-07 13:06:19] ConfigManager@407: DB: RASBASE
  INFO [2018-06-07 13:06:19] ConfigManager@408: User: rasguest
  INFO [2018-06-07 13:06:19] ConfigManager@409: 
  INFO [2018-06-07 13:06:19] ConfigManager@411: -- SECORE
  INFO [2018-06-07 13:06:19] ConfigManager@412: Version: 0.1.0
  INFO [2018-06-07 13:06:19] ConfigManager@413: URL: [http://localhost:8080/def]
  INFO [2018-06-07 13:06:19] ConfigManager@414: 
  INFO [2018-06-07 13:06:19] ConfigManager@416: -- OGC STANDARDS
  INFO [2018-06-07 13:06:19] ConfigManager@417: CIS: 1.1
  INFO [2018-06-07 13:06:19] ConfigManager@418: WCS: 2.0.1
  INFO [2018-06-07 13:06:19] ConfigManager@419: WCS-T: 2.0.0
  INFO [2018-06-07 13:06:19] ConfigManager@420: WCPS: 1.0.0
  INFO [2018-06-07 13:06:19] ConfigManager@421: WMS: 1.3.0
  INFO [2018-06-07 13:06:19] ConfigManager@423: ------------------------------------
 TRACE [2018-06-07 13:06:19] TypeRegistry@200: Initializing the type registry
 DEBUG [2018-06-07 13:06:19] RasUtil@92: Executing rasql query: SELECT a FROM RAS_STRUCT_TYPES a
 DEBUG [2018-06-07 13:06:19] RasUtil@227: rasql query executed in 155 ms.
 DEBUG [2018-06-07 13:06:19] RasUtil@92: Executing rasql query: SELECT a FROM RAS_MARRAY_TYPES a
 DEBUG [2018-06-07 13:06:19] RasUtil@227: rasql query executed in 137 ms.
 DEBUG [2018-06-07 13:06:19] RasUtil@92: Executing rasql query: SELECT a FROM RAS_SET_TYPES a
 DEBUG [2018-06-07 13:06:20] RasUtil@227: rasql query executed in 156 ms.
  INFO [2018-06-07 13:06:20] TypeRegistry@205: Succesfully initialized the type registry.
 DEBUG [2018-06-07 13:06:20] TypeRegistry@206: Contents: {FloatSet3=TypeRegistryEntry{cellType='float', mdArrayType='float,3', nilValues='[]'}, UShortSet3=TypeRegistryEntry{cellType='unsigned short', mdArrayType='unsigned short,3', nilValues='[]'}, FloatSet4=TypeRegistryEntry{cellType='float', mdArrayType='float,4', nilValues='[]'}, LongSet1=TypeRegistryEntry{cellType='long', mdArrayType='long,1', nilValues='[]'}, LongSet3=TypeRegistryEntry{cellType='long', mdArrayType='long,3', nilValues='[]'}, FloatSet1=TypeRegistryEntry{cellType='float', mdArrayType='float,1', nilValues='[]'}, Gauss1Set=TypeRegistryEntry{cellType='complex', mdArrayType='complex,2', nilValues='[]'}, FloatSet=TypeRegistryEntry{cellType='float', mdArrayType='float,2', nilValues='[]'}, OctetSet3=TypeRegistryEntry{cellType='octet', mdArrayType='octet,3', nilValues='[]'}, UShortSet1=TypeRegistryEntry{cellType='unsigned short', mdArrayType='unsigned short,1', nilValues='[]'}, RGBSet=TypeRegistryEntry{cellType='struct {red char green char blue char}', mdArrayType='struct {red char, green char, blue char},2', nilValues='[]'}, RGBSet1=TypeRegistryEntry{cellType='struct {red char green char blue char}', mdArrayType='struct {red char, green char, blue char},1', nilValues='[]'}, RGBSet3=TypeRegistryEntry{cellType='struct {red char green char blue char}', mdArrayType='struct {red char, green char, blue char},3', nilValues='[]'}, Gauss2Set=TypeRegistryEntry{cellType='complexd', mdArrayType='complexd,2', nilValues='[]'}, ShortSet=TypeRegistryEntry{cellType='short', mdArrayType='short,2', nilValues='[]'}, GreySet3=TypeRegistryEntry{cellType='char', mdArrayType='char,3', nilValues='[]'}, BoolSet=TypeRegistryEntry{cellType='bool', mdArrayType='bool,2', nilValues='[]'}, LongSet=TypeRegistryEntry{cellType='long', mdArrayType='long,2', nilValues='[]'}, ULongSet1=TypeRegistryEntry{cellType='ulong', mdArrayType='ulong,1', nilValues='[]'}, ULongSet3=TypeRegistryEntry{cellType='ulong', mdArrayType='ulong,3', nilValues='[]'}, BoolSet1=TypeRegistryEntry{cellType='bool', mdArrayType='bool,1', nilValues='[]'}, BoolSet3=TypeRegistryEntry{cellType='bool', mdArrayType='bool,3', nilValues='[]'}, OctetSet=TypeRegistryEntry{cellType='octet', mdArrayType='octet,2', nilValues='[]'}, DoubleSet=TypeRegistryEntry{cellType='double', mdArrayType='double,2', nilValues='[]'}, DoubleSet1=TypeRegistryEntry{cellType='double', mdArrayType='double,1', nilValues='[]'}, DoubleSet3=TypeRegistryEntry{cellType='double', mdArrayType='double,3', nilValues='[]'}, OctetSet1=TypeRegistryEntry{cellType='octet', mdArrayType='octet,1', nilValues='[]'}, ULongSet=TypeRegistryEntry{cellType='ulong', mdArrayType='ulong,2', nilValues='[]'}, UShortSet=TypeRegistryEntry{cellType='unsigned short', mdArrayType='unsigned short,2', nilValues='[]'}, ShortSet1=TypeRegistryEntry{cellType='short', mdArrayType='short,1', nilValues='[]'}, GreySet=TypeRegistryEntry{cellType='char', mdArrayType='char,2', nilValues='[]'}, GaussSet1=TypeRegistryEntry{cellType='complex', mdArrayType='complex,1', nilValues='[]'}, ShortSet3=TypeRegistryEntry{cellType='short', mdArrayType='short,3', nilValues='[]'}, GaussSet2=TypeRegistryEntry{cellType='complexd', mdArrayType='complexd,1', nilValues='[]'}, GreySet1=TypeRegistryEntry{cellType='char', mdArrayType='char,1', nilValues='[]'}}
  INFO [2018-06-07 13:06:27] DatabaseUtil@296: Postgresql database 'petascopedb' has successfully been created.
 DEBUG [2018-06-07 13:07:31] RasUtil@92: Executing rasql query: select version()
 DEBUG [2018-06-07 13:07:35] RasUtil@227: rasql query executed in 3835 ms.
 DEBUG [2018-06-07 13:07:35] RasUtil@271: Read rasdaman version: "9.6.0"
 DEBUG [2018-06-07 13:07:35] RasUtil@275: rasql query executed in 3850 ms.
  INFO [2018-06-07 13:07:35] ConfigManager@396: ------------------------------------
  INFO [2018-06-07 13:07:35] ConfigManager@398: -- PETASCOPE
  INFO [2018-06-07 13:07:35] ConfigManager@399: Version: 9.6.0
  INFO [2018-06-07 13:07:35] ConfigManager@400: DB URL: jdbc:postgresql://localhost:5432/petascopedb
  INFO [2018-06-07 13:07:35] ConfigManager@401: DB User: petauser
  INFO [2018-06-07 13:07:35] ConfigManager@402: 
  INFO [2018-06-07 13:07:35] ConfigManager@404: -- RASDAMAN
  INFO [2018-06-07 13:07:35] ConfigManager@405: Version: 9.6.0
  INFO [2018-06-07 13:07:35] ConfigManager@406: URL: http://localhost:7001
  INFO [2018-06-07 13:07:35] ConfigManager@407: DB: RASBASE
  INFO [2018-06-07 13:07:35] ConfigManager@408: User: rasguest
  INFO [2018-06-07 13:07:35] ConfigManager@409: 
  INFO [2018-06-07 13:07:35] ConfigManager@411: -- SECORE
  INFO [2018-06-07 13:07:35] ConfigManager@412: Version: 0.1.0
  INFO [2018-06-07 13:07:35] ConfigManager@413: URL: [http://localhost:8080/def]
  INFO [2018-06-07 13:07:35] ConfigManager@414: 
  INFO [2018-06-07 13:07:35] ConfigManager@416: -- OGC STANDARDS
  INFO [2018-06-07 13:07:35] ConfigManager@417: CIS: 1.1
  INFO [2018-06-07 13:07:35] ConfigManager@418: WCS: 2.0.1
  INFO [2018-06-07 13:07:35] ConfigManager@419: WCS-T: 2.0.0
  INFO [2018-06-07 13:07:35] ConfigManager@420: WCPS: 1.0.0
  INFO [2018-06-07 13:07:35] ConfigManager@421: WMS: 1.3.0
  INFO [2018-06-07 13:07:35] ConfigManager@423: ------------------------------------
 TRACE [2018-06-07 13:07:35] TypeRegistry@200: Initializing the type registry
 DEBUG [2018-06-07 13:07:35] RasUtil@92: Executing rasql query: SELECT a FROM RAS_STRUCT_TYPES a
 DEBUG [2018-06-07 13:07:35] RasUtil@227: rasql query executed in 167 ms.
 DEBUG [2018-06-07 13:07:35] RasUtil@92: Executing rasql query: SELECT a FROM RAS_MARRAY_TYPES a
 DEBUG [2018-06-07 13:07:35] RasUtil@227: rasql query executed in 170 ms.
 DEBUG [2018-06-07 13:07:35] RasUtil@92: Executing rasql query: SELECT a FROM RAS_SET_TYPES a
 DEBUG [2018-06-07 13:07:36] RasUtil@227: rasql query executed in 175 ms.
  INFO [2018-06-07 13:07:36] TypeRegistry@205: Succesfully initialized the type registry.
 DEBUG [2018-06-07 13:07:36] TypeRegistry@206: Contents: {FloatSet3=TypeRegistryEntry{cellType='float', mdArrayType='float,3', nilValues='[]'}, UShortSet3=TypeRegistryEntry{cellType='unsigned short', mdArrayType='unsigned short,3', nilValues='[]'}, FloatSet4=TypeRegistryEntry{cellType='float', mdArrayType='float,4', nilValues='[]'}, LongSet1=TypeRegistryEntry{cellType='long', mdArrayType='long,1', nilValues='[]'}, LongSet3=TypeRegistryEntry{cellType='long', mdArrayType='long,3', nilValues='[]'}, FloatSet1=TypeRegistryEntry{cellType='float', mdArrayType='float,1', nilValues='[]'}, Gauss1Set=TypeRegistryEntry{cellType='complex', mdArrayType='complex,2', nilValues='[]'}, FloatSet=TypeRegistryEntry{cellType='float', mdArrayType='float,2', nilValues='[]'}, UShortSet1=TypeRegistryEntry{cellType='unsigned short', mdArrayType='unsigned short,1', nilValues='[]'}, OctetSet3=TypeRegistryEntry{cellType='octet', mdArrayType='octet,3', nilValues='[]'}, RGBSet=TypeRegistryEntry{cellType='struct {red char green char blue char}', mdArrayType='struct {red char, green char, blue char},2', nilValues='[]'}, RGBSet1=TypeRegistryEntry{cellType='struct {red char green char blue char}', mdArrayType='struct {red char, green char, blue char},1', nilValues='[]'}, RGBSet3=TypeRegistryEntry{cellType='struct {red char green char blue char}', mdArrayType='struct {red char, green char, blue char},3', nilValues='[]'}, Gauss2Set=TypeRegistryEntry{cellType='complexd', mdArrayType='complexd,2', nilValues='[]'}, ShortSet=TypeRegistryEntry{cellType='short', mdArrayType='short,2', nilValues='[]'}, GreySet3=TypeRegistryEntry{cellType='char', mdArrayType='char,3', nilValues='[]'}, BoolSet=TypeRegistryEntry{cellType='bool', mdArrayType='bool,2', nilValues='[]'}, LongSet=TypeRegistryEntry{cellType='long', mdArrayType='long,2', nilValues='[]'}, ULongSet1=TypeRegistryEntry{cellType='ulong', mdArrayType='ulong,1', nilValues='[]'}, ULongSet3=TypeRegistryEntry{cellType='ulong', mdArrayType='ulong,3', nilValues='[]'}, BoolSet1=TypeRegistryEntry{cellType='bool', mdArrayType='bool,1', nilValues='[]'}, BoolSet3=TypeRegistryEntry{cellType='bool', mdArrayType='bool,3', nilValues='[]'}, OctetSet=TypeRegistryEntry{cellType='octet', mdArrayType='octet,2', nilValues='[]'}, DoubleSet=TypeRegistryEntry{cellType='double', mdArrayType='double,2', nilValues='[]'}, DoubleSet1=TypeRegistryEntry{cellType='double', mdArrayType='double,1', nilValues='[]'}, DoubleSet3=TypeRegistryEntry{cellType='double', mdArrayType='double,3', nilValues='[]'}, OctetSet1=TypeRegistryEntry{cellType='octet', mdArrayType='octet,1', nilValues='[]'}, ULongSet=TypeRegistryEntry{cellType='ulong', mdArrayType='ulong,2', nilValues='[]'}, UShortSet=TypeRegistryEntry{cellType='unsigned short', mdArrayType='unsigned short,2', nilValues='[]'}, ShortSet1=TypeRegistryEntry{cellType='short', mdArrayType='short,1', nilValues='[]'}, GreySet=TypeRegistryEntry{cellType='char', mdArrayType='char,2', nilValues='[]'}, GaussSet1=TypeRegistryEntry{cellType='complex', mdArrayType='complex,1', nilValues='[]'}, ShortSet3=TypeRegistryEntry{cellType='short', mdArrayType='short,3', nilValues='[]'}, GaussSet2=TypeRegistryEntry{cellType='complexd', mdArrayType='complexd,1', nilValues='[]'}, GreySet1=TypeRegistryEntry{cellType='char', mdArrayType='char,1', nilValues='[]'}}
  WARN [2018-06-07 13:12:43] AnnotationConfigEmbeddedWebApplicationContext@550: Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'liquibase' defined in class path resource [org/rasdaman/BeanApplicationConfiguration.class]: Invocation of init method failed; nested exception is liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by 10.0.2.15 (10.0.2.15) since 6/7/18 1:06 PM
 ERROR [2018-06-07 13:12:43] SpringApplication@815: Application startup failed
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'liquibase' defined in class path resource [org/rasdaman/BeanApplicationConfiguration.class]: Invocation of init method failed; nested exception is liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by 10.0.2.15 (10.0.2.15) since 6/7/18 1:06 PM
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1628)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:555)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483)
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:296)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
	at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1081)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:856)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:542)
	at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:122)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:737)
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:370)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314)
	at org.springframework.boot.web.support.SpringBootServletInitializer.run(SpringBootServletInitializer.java:151)
	at org.springframework.boot.web.support.SpringBootServletInitializer.createRootApplicationContext(SpringBootServletInitializer.java:131)
	at org.springframework.boot.web.support.SpringBootServletInitializer.onStartup(SpringBootServletInitializer.java:86)
	at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:169)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5502)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:632)
	at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1073)
	at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1857)
	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: liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by 10.0.2.15 (10.0.2.15) since 6/7/18 1:06 PM
	at liquibase.lockservice.StandardLockService.waitForLock(StandardLockService.java:190)
	at liquibase.Liquibase.update(Liquibase.java:196)
	at liquibase.Liquibase.update(Liquibase.java:192)
	at liquibase.integration.spring.SpringLiquibase.performUpdate(SpringLiquibase.java:431)
	at liquibase.integration.spring.SpringLiquibase.afterPropertiesSet(SpringLiquibase.java:388)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1687)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1624)
	... 31 more

Change History (1)

comment:1 by Bang Pham Huu, 6 years ago

Resolution: fixed
Status: newclosed
Note: See TracTickets for help on using tickets.