search

pwm-project / pwm

pwm
Other
911 stars 250 forks source link

[PWM 1.9.1] 'saveConfigOnStart' prevents ContextManager from being added to the ServletContext. #557

Open marcus-bcl opened 4 years ago

marcus-bcl commented 4 years ago

Description When enabling the 'saveConfigOnStart' option in PwmConfiguration.xml, the application intermittently fails to start after deploying to Tomcat. The error message displayed is:

5053 ERROR_APP_UNAVAILABLE (unable to load the context manager from servlet context)

To Reproduce Steps to reproduce the behavior:

  1. Create a simple PwmConfiguration.xml:

    <?xml version="1.0" encoding="UTF-8"?>
<PwmConfiguration pwmVersion="1.9.1" xmlVersion="4" createTime="1970-01-01T00:00:00Z">
<properties type="config">
<property key="saveConfigOnStart">true</property>
</properties>
<settings>
<setting key="pwm.securityKey" syntax="PASSWORD">
  <label>Security Key</label>
  <value plaintext="true">12345678901234567890123456789012</value>
</setting>
</settings>
</PwmConfiguration>

  2. Create a Dockerfile to deploy the app+config to Tomcat:

    FROM tomcat:9
EXPOSE 8080
RUN curl -f https://www.pwm-project.org/artifacts/pwm/release/v1.9.1/pwm-1.9.1.war -o "${CATALINA_HOME}/webapps/ROOT.war"
ENV PWM_APPLICATIONPATH /usr/local/pwm
RUN mkdir -p "${PWM_APPLICATIONPATH}"
COPY PwmConfiguration.xml "${PWM_APPLICATIONPATH}"

  3. Build and run the container docker run $(docker build -q .)

  4. Intermittently the following error occurs and PWM fails to start:

    2020-06-30T15:08:39Z, INFO , pwm.PwmApplication, PWM v1.9.1 b43093778 rdb1407912c86601068662b91caebd51f6266a0e3 open for bidness! (1295ms)
2020-06-30T15:08:39Z, WARN , http.ContextManager, {#,context} configuration file contains property "saveConfigOnStart"=true, will save configuration and set property to false.
2020-06-30T15:08:39Z, INFO , stored.ConfigurationReader, {#,context} beginning write to configuration file /usr/local/pwm/PwmConfiguration.xml.new
2020-06-30T15:08:40Z, INFO , stored.ConfigurationReader, saved configuration {"challenge.profile.list":{"default":{}},"deleteAccount.profile.list":{"default":{}},"email.profile.list":{"default":{}},"helpdesk.profile.list":{"default":{}},"ldap.profile.list":{"default":{}},"newUser.profile.list":{"default":{}},"otp.profile.list":{"default":{}},"password.profile.list":{"default":{}},"pwm.securityKey":"*hidden*","recovery.profile.list":{"default":{}},"updateAttributes.profile.list":{"default":{}}}
2020-06-30T15:08:40Z, INFO , http.ContextManager, {#,context} beginning application restart (0ms), restart count=1
2020-06-30T15:08:40Z, WARN , pwm.PwmApplication, shutting down
2020-06-30T15:08:40Z, FATAL, http.HttpEventManager, error initializing context: java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@5312940c[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@6924ff83[Wrapped task = password.pwm.http.ContextManager$SilentPropertiesFileWatcher@e19908e]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5ac168e3[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] (stacktrace follows)
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@5312940c[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@6924ff83[Wrapped task = password.pwm.http.ContextManager$SilentPropertiesFileWatcher@e19908e]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5ac168e3[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0]
at java.base/java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055)
at java.base/java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:340)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor.scheduleWithFixedDelay(ScheduledThreadPoolExecutor.java:680)
at java.base/java.util.concurrent.Executors$DelegatedScheduledExecutorService.scheduleWithFixedDelay(Executors.java:788)
at password.pwm.http.ContextManager.initialize(ContextManager.java:303)
at password.pwm.http.HttpEventManager.contextInitialized(HttpEventManager.java:129)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4678)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5139)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:717)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:690)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:705)
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:978)
at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1848)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118)
at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:773)
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:427)
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1576)
at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:309)
at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423)
at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:936)
at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:841)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1384)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1374)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:909)
at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:262)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:421)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:930)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.startup.Catalina.start(Catalina.java:633)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:343)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:474)
...
2020-06-30T15:08:40Z, INFO , event.AuditService, audit event: {"instance":"6B5C8F1322E71775","type":"SYSTEM","eventCode":"SHUTDOWN","guid":"d25e40a5-ec3b-417f-9659-30f583d50eed","timestamp":"2020-06-30T15:08:40Z","narrative":"PWM has been shutdown","xdasTaxonomy":"XDAS_AE_TERMINATE_SERVICE","xdasOutcome":"XDAS_OUT_SUCCESS"}
2020-06-30T15:08:40Z, WARN , filter.GZIPFilter, unable to load application configuration, defaulting to disabled
30-Jun-2020 15:08:40.953 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/usr/local/tomcat/webapps/ROOT.war] has finished in [11,018] ms
30-Jun-2020 15:08:40.959 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
2020-06-30T15:08:41Z, WARN , pwm.PwmApplication, configuration checksum does not match previously seen checksum, configuration has been modified since last startup
2020-06-30T15:08:41Z, INFO , event.AuditService, audit event: {"type":"USER","eventCode":"MODIFY_CONFIGURATION","guid":"e79a111f-46c4-4d02-a667-951ec688b20b","timestamp":"2020-06-30T15:08:41Z","message":"configuration was modified directly (not using ConfigEditor UI)","narrative":"Configuration has been modified, changes: configuration was modified directly (not using ConfigEditor UI)","xdasTaxonomy":"XDAS_AE_CONFUPDATE","xdasOutcome":"XDAS_OUT_SUCCESS"}
30-Jun-2020 15:08:41.094 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [11,258] milliseconds
2020-06-30T15:08:41Z, INFO , event.AuditService, audit event: {"instance":"6B5C8F1322E71775","type":"SYSTEM","eventCode":"STARTUP","guid":"ff848cd8-fd8e-41cd-ae4d-ce5efe775775","timestamp":"2020-06-30T15:08:41Z","narrative":"PWM has started up","xdasTaxonomy":"XDAS_AE_INVOKE_SERVICE","xdasOutcome":"XDAS_OUT_SUCCESS"}
2020-06-30T15:08:41Z, ERROR, filter.RequestInitializationFilter, error while trying to detect application status: 5053 ERROR_APP_UNAVAILABLE (unable to load the context manager from servlet context)
2020-06-30T15:08:41Z, ERROR, filter.RequestInitializationFilter, unable to satisfy incoming request, application is not available
2020-06-30T15:08:41Z, WARN , http.HttpEventManager, error during sessionCreated event: 5053 ERROR_APP_UNAVAILABLE (unable to load the context manager from servlet context)

Expected behavior The configuration should be saved with the encrypted security_key, and the application should startup successfully.

Additional context From having a quick look in the code, I believe this is a timing issue. Occasionally the application is restarted too quickly after saving the config, causing the scheduling of the SilentPropertiesFileWatcher to fail with a RejectedExecutionException - which in turn prevents the ContextManager from being stored in the ServletContext. If this is the case, then the relevant code is in password.pwm.http.ContextManager::initialize: https://github.com/pwm-project/pwm/blob/db1407912c86601068662b91caebd51f6266a0e3/server/src/main/java/password/pwm/http/ContextManager.java#L301-L304

I understand that the 'saveConfigOnStart' option is to be removed in 2.0.0, however the silent.properties method that replaces it does not fit our use case as it only allows configuration of a small subset of options. As v1.9.1 is the latest release version, I hope this can be fixed in a v1.9.2 release.

Let me know if you need any more information.

IyadKandalaft commented 4 years ago

I'm having the same issue when using saveConfigOnStart. PWM restarts itself 3 times and then starts looping on:

2020-07-14T18:00:35Z, ERROR, filter.RequestInitializationFilter, error while trying to detect application status: 5053 ERROR_APP_UNAVAILABLE (unable to load the context manager from servlet context)
2020-07-14T18:00:35Z, WARN , http.HttpEventManager, error during sessionCreated event: 5053 ERROR_APP_UNAVAILABLE (unable to load the context manager from servlet context)

Restarting tomcat seems to resolve the issue but that's a workaround that might not work in some contexts.