Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

WebAPI v2.11 fails to start with many sources configured #2031

Closed
anthonysena opened this issue May 10, 2022 · 7 comments
Closed

WebAPI v2.11 fails to start with many sources configured #2031

anthonysena opened this issue May 10, 2022 · 7 comments
Labels
Milestone

Comments

@anthonysena
Copy link
Collaborator

Expected behavior

WebAPI starts without error after installing v2.11

Actual behavior

WebAPI fails to start after installing v2.11

Steps to reproduce behavior

Installing this in our environment had the following error when starting up WebAPI:

Error starting ApplicationContext. To display the auto-configuration report re-run your application with 'debug' enabled.
2022-05-09 21:28:19.547 ERROR http-nio-8080-exec-4 org.springframework.boot.SpringApplication - [] - Application startup failed
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'CDMResultsService' defined in file [D:\apache-tomcat-8.5.63\webapps\WebAPI\WEB-INF\classes\org\ohdsi\webapi\service\CDMResultsService.class]: Invocation of init method failed; nested exception is javax.ws.rs.WebApplicationException: HTTP 500 Internal Server Error
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1630) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:553) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:481) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:312) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:308) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:756) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:867) ~[spring-context-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:542) ~[spring-context-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:123) ~[spring-boot-1.5.22.RELEASE.jar:1.5.22.RELEASE]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:666) [spring-boot-1.5.22.RELEASE.jar:1.5.22.RELEASE]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:353) [spring-boot-1.5.22.RELEASE.jar:1.5.22.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:300) [spring-boot-1.5.22.RELEASE.jar:1.5.22.RELEASE]
	at org.springframework.boot.web.support.SpringBootServletInitializer.run(SpringBootServletInitializer.java:151) [spring-boot-1.5.22.RELEASE.jar:1.5.22.RELEASE]
	at org.springframework.boot.web.support.SpringBootServletInitializer.createRootApplicationContext(SpringBootServletInitializer.java:131) [spring-boot-1.5.22.RELEASE.jar:1.5.22.RELEASE]
	at org.springframework.boot.web.support.SpringBootServletInitializer.onStartup(SpringBootServletInitializer.java:91) [spring-boot-1.5.22.RELEASE.jar:1.5.22.RELEASE]
	at org.springframework.web.SpringServletContainerInitializer.onStartup(SpringServletContainerInitializer.java:169) [spring-web-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5160) [catalina.jar:8.5.63]
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:743) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:719) [catalina.jar:8.5.63]
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:705) [catalina.jar:8.5.63]
	at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:938) [catalina.jar:8.5.63]
	at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:490) [catalina.jar:8.5.63]
	at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1579) [catalina.jar:8.5.63]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_181]
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_181]
	at org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:286) [tomcat-coyote.jar:8.5.63]
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source) [?:1.8.0_181]
	at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source) [?:1.8.0_181]
	at org.apache.catalina.manager.ManagerServlet.check(ManagerServlet.java:1567) [catalina.jar:8.5.63]
	at org.apache.catalina.manager.ManagerServlet.deploy(ManagerServlet.java:820) [catalina.jar:8.5.63]
	at org.apache.catalina.manager.ManagerServlet.doPut(ManagerServlet.java:448) [catalina.jar:8.5.63]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:655) [servlet-api.jar:?]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:733) [servlet-api.jar:?]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.63]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat-websocket.jar:8.5.63]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.63]
	at org.apache.catalina.filters.HttpHeaderSecurityFilter.doFilter(HttpHeaderSecurityFilter.java:126) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.63]
	at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:109) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.63]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.63]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) [catalina.jar:8.5.63]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) [catalina.jar:8.5.63]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:669) [catalina.jar:8.5.63]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) [catalina.jar:8.5.63]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) [catalina.jar:8.5.63]
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:698) [catalina.jar:8.5.63]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) [catalina.jar:8.5.63]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:353) [catalina.jar:8.5.63]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616) [tomcat-coyote.jar:8.5.63]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-coyote.jar:8.5.63]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831) [tomcat-coyote.jar:8.5.63]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1629) [tomcat-coyote.jar:8.5.63]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:8.5.63]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:1.8.0_181]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.5.63]
	at java.lang.Thread.run(Unknown Source) [?:1.8.0_181]
Caused by: javax.ws.rs.WebApplicationException: HTTP 500 Internal Server Error
	at org.ohdsi.webapi.job.JobTemplate.launch(JobTemplate.java:60) ~[classes/:?]
	at org.ohdsi.webapi.service.JobService.runJob(JobService.java:229) ~[classes/:?]
	at org.ohdsi.webapi.service.JobService$$FastClassBySpringCGLIB$$4fc5dc62.invoke(<generated>) ~[classes/:?]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.ohdsi.webapi.service.JobService$$EnhancerBySpringCGLIB$$c63ef499.runJob(<generated>) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.createJob(CDMResultsService.java:518) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.createJob(CDMResultsService.java:494) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.warmCaches(CDMResultsService.java:448) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.warmCaches(CDMResultsService.java:151) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.afterPropertiesSet(CDMResultsService.java:139) ~[classes/:?]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1688) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1626) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	... 65 more
Caused by: org.springframework.dao.DataIntegrityViolationException: PreparedStatementCallback; SQL [INSERT into webapi.BATCH_JOB_INSTANCE(JOB_INSTANCE_ID, JOB_NAME, JOB_KEY, VERSION) values (?, ?, ?, ?)]; ERROR: value too long for type character varying(100); nested exception is org.postgresql.util.PSQLException: ERROR: value too long for type character varying(100)
	at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:102) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:82) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:82) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:654) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:875) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:936) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:941) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.batch.core.repository.dao.JdbcJobInstanceDao.createJobInstance(JdbcJobInstanceDao.java:115) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at org.springframework.batch.core.repository.support.SimpleJobRepository.createJobExecution(SimpleJobRepository.java:135) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_181]
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_181]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:283) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at com.sun.proxy.$Proxy553.createJobExecution(Unknown Source) ~[?:?]
	at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:125) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_181]
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_181]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:127) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at com.sun.proxy.$Proxy563.run(Unknown Source) ~[?:?]
	at org.ohdsi.webapi.job.JobTemplate.launch(JobTemplate.java:53) ~[classes/:?]
	at org.ohdsi.webapi.service.JobService.runJob(JobService.java:229) ~[classes/:?]
	at org.ohdsi.webapi.service.JobService$$FastClassBySpringCGLIB$$4fc5dc62.invoke(<generated>) ~[classes/:?]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.ohdsi.webapi.service.JobService$$EnhancerBySpringCGLIB$$c63ef499.runJob(<generated>) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.createJob(CDMResultsService.java:518) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.createJob(CDMResultsService.java:494) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.warmCaches(CDMResultsService.java:448) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.warmCaches(CDMResultsService.java:151) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.afterPropertiesSet(CDMResultsService.java:139) ~[classes/:?]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1688) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1626) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	... 65 more
Caused by: org.postgresql.util.PSQLException: ERROR: value too long for type character varying(100)
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2675) ~[postgresql-42.3.3.jar:42.3.3]
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2365) ~[postgresql-42.3.3.jar:42.3.3]
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:355) ~[postgresql-42.3.3.jar:42.3.3]
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:490) ~[postgresql-42.3.3.jar:42.3.3]
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:408) ~[postgresql-42.3.3.jar:42.3.3]
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:166) ~[postgresql-42.3.3.jar:42.3.3]
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:134) ~[postgresql-42.3.3.jar:42.3.3]
	at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:882) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:875) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:638) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:875) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:936) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:941) ~[spring-jdbc-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.batch.core.repository.dao.JdbcJobInstanceDao.createJobInstance(JdbcJobInstanceDao.java:115) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at org.springframework.batch.core.repository.support.SimpleJobRepository.createJobExecution(SimpleJobRepository.java:135) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_181]
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_181]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:283) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at com.sun.proxy.$Proxy553.createJobExecution(Unknown Source) ~[?:?]
	at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:125) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_181]
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_181]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_181]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:127) ~[spring-batch-core-3.0.10.RELEASE.jar:3.0.10.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at com.sun.proxy.$Proxy563.run(Unknown Source) ~[?:?]
	at org.ohdsi.webapi.job.JobTemplate.launch(JobTemplate.java:53) ~[classes/:?]
	at org.ohdsi.webapi.service.JobService.runJob(JobService.java:229) ~[classes/:?]
	at org.ohdsi.webapi.service.JobService$$FastClassBySpringCGLIB$$4fc5dc62.invoke(<generated>) ~[classes/:?]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.ohdsi.webapi.service.JobService$$EnhancerBySpringCGLIB$$c63ef499.runJob(<generated>) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.createJob(CDMResultsService.java:518) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.createJob(CDMResultsService.java:494) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.warmCaches(CDMResultsService.java:448) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.warmCaches(CDMResultsService.java:151) ~[classes/:?]
	at org.ohdsi.webapi.service.CDMResultsService.afterPropertiesSet(CDMResultsService.java:139) ~[classes/:?]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1688) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1626) ~[spring-beans-4.3.25.RELEASE.jar:4.3.25.RELEASE]
	... 65 more

A bit more about our environment: we have a large number (> 10) of CDMs configured with vocabulary and results daimons. When reviewing the stack trace above, my first impression was that perhaps something about the source_key was problematic and causing a job name > 100 characters. This was not the case. I was then looking through the changes here: https://github.com/OHDSI/WebAPI/pull/1993/files#diff-45561d1ce808215d1229fd2a7d080664d05d70b47e13bfa830d9f400db258194L109-R147 and see that we're calling warmCaches() in multiple places in this service.

To try and debug, I set up my local WebAPI DB with 2 sources to see if I could reproduce the problem. When I did this, I found that WebAPI is starting multiple warming jobs, even when I manually set <cdm.cache.cron.warming.enable>false</cdm.cache.cron.warming.enable> in the pom.xml. See below:

image

Upon re-review of #1993, I'm unclear on a few items:

  • Can we disable the Achilles caching when we do not require it? My presumption was that setting <cdm.cache.cron.warming.enable>false</cdm.cache.cron.warming.enable> would do that while also allowing for the previous "results" cache controlled by <cdm.result.cache.warming.enable>true</cdm.result.cache.warming.enable> to work as before?
  • Why is warmCaches() invoked in 2 places? Place 1 and Place 2
  • I'm a bit confused on the code here:
    List<Integer> sourceIds = new ArrayList<>();
    List<String> sourceKeys = new ArrayList<>();
    List<Step> jobSteps = new ArrayList<>();
    for (Source source : vocabularySources) {
    sourceIds.add(source.getSourceId());
    sourceKeys.add(source.getSourceKey());
    String jobStepName = getWarmCacheJobName(source.getSourceKey());
    // Check whether cache job for current source already exists
    if (jobService.findJobByName(jobStepName, jobStepName) == null) {
    Step jobStep = getJobStep(source, jobStepName);
    // get priority of the results daimon
    int priority = getPriority(source);
    // if source has results daimon with high priority - put it at the beginning of the queue
    if (priority == 1) {
    jobSteps.add(0, jobStep);
    } else {
    jobSteps.add(jobStep);
    }
    }
    if (counter++ >= bucketSizes[bucketIndex] - 1) {
    createJob(sourceIds.stream().map(String::valueOf).collect(Collectors.joining(", ")),
    String.join(", ", sourceKeys),
    jobSteps);
    bucketIndex++;
    counter = 0;
    sourceKeys.clear();
    jobSteps.clear();
    }
    }
    }
    • I'm confused on why we're using List<> collections in this operation (i.e. sourceIds). The loop that starts on 429 adds each sourceId to a collection and then this collection is used on line 448 to call createJob but this collection is not purged like sourceKeys and jobSteps which I believe is where we're creating the duplication and potentially violating the length of the job name.
    • Can you clarify what buckets represents in this loop? It appears like you are trying to bucket the caching operations into a single job? I'm not sure if I'm interpreting this correctly.
    • It appears we lost the ability to control the cached based on daimon priority. Now it appears that any source with a vocabulary and results daimon will automatically qualify to have the Achilles results cached? If I have this correct, we'll need to restore this functionality.

I'm sorry I missed so much in the review of #1993 but we also need to better communicate desired functionality ahead of implementation moving forward. The brief description in #1978 is insufficient to support building new features without describing how they will work, how we plan to preserve backwards compatibility and so on.

@chrisknoll
Copy link
Collaborator

@anthonysena , i'm not sure it's the number of CDMs that is the problem but rather some value is longer than 100 chars (although not sure what that could have been). I'm basing it on this error:

Caused by: org.postgresql.util.PSQLException: ERROR: value too long for type character varying(100)

I wish it would output what the value was that was longer than 100 chars, that would have helped.

@anthonysena
Copy link
Collaborator Author

Linking this to #2007 as they are rooted in the same problem.

@anton-abushkevich
Copy link
Contributor

@anthonysena
You absolutely right about sourcesIds list. The main reason of the bug is that sourcesIds was not cleared. I created quick fix for this, see #2032.

I would address other questions to Sergei Suvorov @ssuvorov-fls - he is the author of the original code changes in #1993 (I only created the PR).

@anthonysena
Copy link
Collaborator Author

Thanks @anton-abushkevich for the update here and I'll tag @ssuvorov-fls on the PR as I have a few questions that are likely better for that thread.

@ssuvorov-fls
Copy link
Contributor

Hello @anthonysena

Can we disable the Achilles caching when we do not require it? My presumption was that setting <cdm.cache.cron.warming.enable>false</cdm.cache.cron.warming.enable> would do that while also allowing for the previous "results" cache controlled by <cdm.result.cache.warming.enable>true</cdm.result.cache.warming.enable> to work as before?

  • Yes, if "cdm.result.cache.warming.enable" is set to false then cache won't be updated, but still will be used

Why is warmCaches() invoked in 2 places? Place 1 and Place 2

  • Caching is started when application starts (1st place)
  • Caching is started when cron is triggered (2nd place)

Can you clarify what buckets represents in this loop? It appears like you are trying to bucket the caching operations into a single job? I'm not sure if I'm interpreting this correctly.

  • Buckets are used to group caching for runnning in parallel. If the number of buckets is small then caching will take more time

It appears we lost the ability to control the cached based on daimon priority. Now it appears that any source with a vocabulary and results daimon will automatically qualify to have the Achilles results cached? If I have this correct, we'll need to restore this functionality.

  • This functionality is still used (src/main/java/org/ohdsi/webapi/service/CDMResultsService.java:437)

@anthonysena
Copy link
Collaborator Author

Thanks @ssuvorov-fls - I also posted some questions on #2032 (comment) so I'm hoping we can keep the conversation going on that pull request.

A couple of follow up points to your notes here:

Yes, if "cdm.result.cache.warming.enable" is set to false then cache won't be updated, but still will be used

If cdm.result.cache.warming.enable is set to false, we then also lose the ability to cache record counts. In my opinion, we should be able to control both cache types: record counts and Achilles results as they support different features (vocabulary search/data source).

This functionality is still used (src/main/java/org/ohdsi/webapi/service/CDMResultsService.java:437)

Here is the code:

// get priority of the results daimon
int priority = getPriority(source);
// if source has results daimon with high priority - put it at the beginning of the queue
if (priority == 1) {
jobSteps.add(0, jobStep);
} else {
jobSteps.add(jobStep);
}
}

The original functionality skipped warming the record count cache if a source had a results daimon with priority == 0. The change in the code above now prioritizes the daimon to have its cache as one of the first steps in the List<> instead. The changes I started to make on #2032 aims to address this. If you could review, I'd appreciate it.

@anton-abushkevich anton-abushkevich added this to the V2.11.1 milestone May 18, 2022
anton-abushkevich added a commit that referenced this issue May 23, 2022
* fails to start with many sources configured #2031

* Starting to add back the ability to control caching based on daimon priority

Co-authored-by: Anthony Sena <[email protected]>
@anton-abushkevich
Copy link
Contributor

Fixed by #2032. Further questions moved to #2034.

anton-abushkevich added a commit that referenced this issue Jun 9, 2022
* fails to start with many sources configured #2031

* Starting to add back the ability to control caching based on daimon priority

Co-authored-by: Anthony Sena <[email protected]>
(cherry picked from commit fad3dab)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants