RDM-cas-overlay を起動しようとすると、たまに例外が発生し起動しない

[hiroyuki-sato]

概要

docker compose up cas で RDM-cas-overlay を起動しようとすると、たまに例外が発生し起動しないことがある。

環境

docker: 27.1.2, build d01f264
OS: Ubuntu 22.04
cas-overlay: 7c97d3b2ce5a4e32252ff61967ccd07cd07c7823

再現手順

git clone https://github.com/RCOSDP/RDM-osf.io
git clone https://github.com/RCOSDP/RDM-cas-overlay.git

( cd RDM-cas-overlay ; docker build -t rdm-cas-overlay . )
cd RDM-osf.io

docker-compose.override.yamlに以下の記述をする。

  #################
  # cas #
  #################
  cas:
    image: rdm-cas-overlay

#525 の不具合で、etc/cas.properties に以下の行を追加する。

osf.api.institutions.login.availability.url=http://localhost:8000/api/v2/institutions/login_availability/

docker compose up cas

期待する動作

例外を出力せずサービスが起動する。(ok.txt)

実際の動作

5回に3回ぐらい、以下の例外を出力して起動に失敗する場合がある
(ng.txt)

cas-1  | SLF4J: See also http://www.slf4j.org/codes.html#substituteLogger
cas-1  | SLF4J: org.reflections.Reflections
cas-1  | [INFO] No Spring WebApplicationInitializer types detected on classpath
cas-1  | [INFO] Initializing Spring root WebApplicationContext
cas-1  | log4j:WARN No appenders could be found for logger (org.jboss.logging).
cas-1  | log4j:WARN Please initialize the log4j system properly.
cas-1  | log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
cas-1  | Hibernate: select openscienc0_.id as id1_2_, openscienc0_.callback_url as callback2_2_, openscienc0_.client_id as client_i3_2_, openscienc0_.client_secret as client_s4_2_, openscienc0_.description as descript5_2_, openscienc0_.is_active as is_activ6_2_, openscienc0_.name as name7_2_, openscienc0_._id as _id8_2_ from osf_apioauth2application openscienc0_ where openscienc0_.is_active=true
cas-1  | 04:50:09.117 [main] ERROR org.springframework.web.context.ContextLoader - Context initialization failed
cas-1  | org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'log4jInitialization' defined in ServletContext resource [/WEB-INF/spring-configuration/log4jConfiguration.xml]: Initialization of bean failed; nested exception is java.lang.RuntimeException: java.lang.IllegalStateException: Context did not contain required Log4jWebLifeCycle in the org.apache.logging.log4j.web.Log4jWebSupport.INSTANCE attribute.
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:547)
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476)
cas-1  |        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:303)
cas-1  |        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
cas-1  |        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299)
cas-1  |        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
cas-1  |        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:755)
cas-1  |        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:759)
cas-1  |        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:480)
cas-1  |        at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:434)
cas-1  |        at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
cas-1  |        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:106)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:794)
cas-1  |        at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:522)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:785)
cas-1  |        at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:341)
cas-1  |        at org.eclipse.jetty.webapp.WebAppContext.startWebapp(WebAppContext.java:1357)
cas-1  |        at org.eclipse.jetty.maven.plugin.JettyWebAppContext.startWebapp(JettyWebAppContext.java:297)
cas-1  |        at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1350)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:734)
cas-1  |        at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:258)
cas-1  |        at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:512)
cas-1  |        at org.eclipse.jetty.maven.plugin.JettyWebAppContext.doStart(JettyWebAppContext.java:369)
cas-1  |        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114)
cas-1  |        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandlerCollection.doStart(ContextHandlerCollection.java:161)
cas-1  |        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114)
cas-1  |        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61)
cas-1  |        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132)
cas-1  |        at org.eclipse.jetty.server.Server.start(Server.java:405)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114)
cas-1  |        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61)
cas-1  |        at org.eclipse.jetty.server.Server.doStart(Server.java:372)
cas-1  |        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
cas-1  |        at org.eclipse.jetty.maven.plugin.AbstractJettyMojo.startJetty(AbstractJettyMojo.java:467)
cas-1  |        at org.eclipse.jetty.maven.plugin.AbstractJettyMojo.execute(AbstractJettyMojo.java:338)
cas-1  |        at org.eclipse.jetty.maven.plugin.JettyRunMojo.execute(JettyRunMojo.java:161)
cas-1  |        at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
cas-1  |        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
cas-1  |        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
cas-1  |        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
cas-1  |        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
cas-1  |        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
cas-1  |        at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
cas-1  |        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)

cas-1  |        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
cas-1  |        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
cas-1  |        at java.lang.reflect.Method.invoke(Method.java:498)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
cas-1  | Caused by: java.lang.RuntimeException: java.lang.IllegalStateException: Context did not contain required Log4jWebLifeCycle in the org.apache.logging.log4j.web.Log4jWebSupport.INSTANCE attribute.
cas-1  |        at org.jasig.cas.util.CasLoggerContextInitializer.initialize(CasLoggerContextInitializer.java:108)
cas-1  |        at org.jasig.cas.util.CasLoggerContextInitializer.setServletContext(CasLoggerContextInitializer.java:163)
cas-1  |        at org.springframework.web.context.support.ServletContextAwareProcessor.postProcessBeforeInitialization(ServletContextAwareProcessor.java:103)
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:408)
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1564)
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:539)
cas-1  |        ... 63 more
cas-1  | Caused by: java.lang.IllegalStateException: Context did not contain required Log4jWebLifeCycle in the org.apache.logging.log4j.web.Log4jWebSupport.INSTANCE attribute.
cas-1  |        at org.apache.logging.log4j.web.Log4jShutdownOnContextDestroyedListener.contextInitialized(Log4jShutdownOnContextDestroyedListener.java:50)
cas-1  |        at org.jasig.cas.util.CasLoggerContextInitializer.initialize(CasLoggerContextInitializer.java:101)
cas-1  |        ... 68 more
cas-1  |

cas-1  |        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299)
cas-1  |        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
cas-1  |        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:755)
cas-1  |        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:759)
cas-1  |        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:480)
cas-1  |        at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:434)
cas-1  |        at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
cas-1  |        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:106)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:794)
cas-1  |        at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:522)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:785)
cas-1  |        at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:341)
cas-1  |        at org.eclipse.jetty.webapp.WebAppContext.startWebapp(WebAppContext.java:1357)
cas-1  |        at org.eclipse.jetty.maven.plugin.JettyWebAppContext.startWebapp(JettyWebAppContext.java:297)
cas-1  |        at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1350)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:734)
cas-1  |        at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:258)
cas-1  |        at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:512)
cas-1  |        at org.eclipse.jetty.maven.plugin.JettyWebAppContext.doStart(JettyWebAppContext.java:369)
cas-1  |        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132)
cas-1  |        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114)
cas-1  |        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61)
cas-1  |        at org.eclipse.jetty.server.handler.ContextHandlerCol
cas-1  |        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
cas-1  |        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
cas-1  |        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
cas-1  |        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
cas-1  |        at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
cas-1  |        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
cas-1  |        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
cas-1  |        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
cas-1  |        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
cas-1  |        at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
cas-1  |        at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
cas-1  |        at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
cas-1  |        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
cas-1  |        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
cas-1  |        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
cas-1  |        at java.lang.reflect.Method.invoke(Method.java:498)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
cas-1  |        at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
cas-1  | Caused by: java.lang.RuntimeException: java.lang.IllegalStateException: Context did not contain required Log4jWebLifeCycle in the org.apache.logging.log4j.web.Log4jWebSupport.INSTANCE attribute.
cas-1  |        at org.jasig.cas.util.CasLoggerContextInitializer.initialize(CasLoggerContextInitializer.java:108)
cas-1  |        at org.jasig.cas.util.CasLoggerContextInitializer.setServletContext(CasLoggerContextInitializer.java:163)
cas-1  |        at org.springframework.web.context.support.ServletContextAwareProcessor.postProcessBeforeInitialization(ServletContextAwareProcessor.java:103)
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:408)
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1564)
cas-1  |        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:539)
cas-1  |        ... 63 more
cas-1  | Caused by: java.lang.IllegalStateException: Context did not contain required Log4jWebLifeCycle in the org.apache.logging.log4j.web.Log4jWebSupport.INSTANCE attribute.
cas-1  |        at org.apache.logging.log4j.web.Log4jShutdownOnContextDestroyedListener.contextInitialized(Log4jShutdownOnContextDestroyedListener.java:50)
cas-1  |        at org.jasig.cas.util.CasLoggerContextInitializer.initialize(CasLoggerContextInitializer.java:101)
cas-1  |        ... 68 more
cas-1  | [INFO] Started ServerConnector@1f6c03df{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
cas-1  | [INFO] Started @16364ms
cas-1  | [INFO] Started Jetty Server

その他

(CVEの問題がでるかもしれないが)断言はできないが、この修正を消すと、安定して動くように見える。(無関係かもしれない)
https://github.com/RCOSDP/RDM-cas-overlay/pull/6/files

ng.txt
ok.txt