Description of problem: A race condition sometimes causes an application to fail to deploy in cases of multiple deployments using JBossWeb authenticators (FORM, DIGEST, BASIC,...) Version-Release number of selected component (if applicable): EAP 6.0.1 How reproducible: Reproduced 3 failures out of about 20 startup attempts Steps to Reproduce: 1. Add two applications that both use a form authenticator to deployments dir(they can be the same application duplicated to different contexts) 2. Start JBoss (./standalone.sh is fine) 3. If the error/deployment failure is not seen, stop and start again. Actual results: Deployment of one of the applications fails sometimes randomly at startup: ERROR [org.apache.catalina.startup.ContextConfig] (MSC service thread 1-8) Cannot configure an authenticator for method FORM Expected results: Both deployments always succeed
This looks like a JBossWeb bug resulting from handling multiple threads/deployments at once through org.apache.catalina.startup.ContextConfig where the authenticators Properties are instantiated. I think TRACE module logging helps confirm the race condition hit here. The authenticators Property set will be instantiated and read from the "org/apache/catalina/startup/Authenticators.properties" resource stream just once by the first thread accessing the code block below. The thread doing this is thread 14: 04:42:59,782 TRACE [org.jboss.modules] (MSC service thread 1-14) Attempting to find resource org/apache/catalina/startup/Authenticators.properties in Module "org.jboss.as.web:main" from local module loader @767e557b (roots: /server/test/JBoss6-E/modules,/server/test/JBoss6-E/modules_custom) 04:42:59,859 TRACE [org.jboss.modules] (MSC service thread 1-14) Finding class org.apache.catalina.authenticator.FormAuthenticator from Module "org.jboss.as.web:main" from local module loader @767e557b (roots: /server/test/JBoss6-E/modules,/server/test/JBoss6-E/modules_custom) Thread 14 didn't finish loading the authenticators properties until sometime in between 04:42:59,782 and 04:42:59,859. Thread 28 is handling another application using a FORM authenticator at the same time and it bombs in ContextConfig.authenticatorConfig around the same time: 04:42:59,837 ERROR [org.apache.catalina.startup.ContextConfig] (MSC service thread 1-28) Cannot configure an authenticator for method FORM So that exception is thrown because no FORM value was found in the authenticators property. 28 didn't try to instantiate those properties though; that should have been done by Thread 14. We know thread 14 did instantiate those properties though since it succeeded where 28 failed. The problem is thread 28 passes past "authenticators == null" after 14 has called "authenticators = new Properties();" but before 14 has finished calling "authenticators.load(is);". Thus 28 reaches a point where it has not fleshed out the authenticators and nor has 14 and so it finds no value for FORM in the property set. 28's timestamp helps confirm that (04:42:59,837) since it logs that error right in the middle of when thread 14 would be loading the properties file. 280 if (authenticators == null) { 281 try { 282 InputStream is=this.getClass().getClassLoader().getResourceAsStream("org/apache/catalina/startup/Authenticators.properties"); 283 if( is!=null ) { 284 authenticators = new Properties(); 285 authenticators.load(is); 286 } else { 287 log.error(sm.getString( 288 "contextConfig.authenticatorResources")); 289 ok=false; 290 return; 291 } 292 } catch (IOException e) { 293 log.error(sm.getString( 294 "contextConfig.authenticatorResources"), e); 295 ok = false; 296 return; 297 } 298 } 299 300 // Identify the class name of the Valve we should configure 301 String authenticatorName = null; 302 authenticatorName = 303 authenticators.getProperty(loginConfig.getAuthMethod()); 304 if (authenticatorName == null) { 305 log.error(sm.getString("contextConfig.authenticatorMissing", 306 loginConfig.getAuthMethod())); 307 ok = false; 308 return; 309 } 310 311 // Instantiate and install an Authenticator of the requested class 312 try { 313 Class authenticatorClass = Class.forName(authenticatorName); 314 authenticator = (Valve) authenticatorClass.newInstance(); 315 } catch (Throwable t) { 316 log.error(sm.getString( 317 "contextConfig.authenticatorInstantiate", 318 authenticatorName), 319 t); 320 ok = false; 321 }
Reproduced on 6.0.1 with 2 duplicate deployments each using a FORM authenticator. 3 attempts out of ~20 failed and hit the issue. Added extra trace logging around the suspect race condition and it shows how the second fails as it checks the authenticators Property set before it was fully initialized with the data from the Authenticators.properties data: 12:18:09,014 TRACE [org.apache.catalina.startup.ContextConfig] (MSC service thread 1-3) Starting to load Authenticators.properties 12:18:09,014 TRACE [org.apache.catalina.startup.ContextConfig] (MSC service thread 1-3) Finished loading Authenticators.properties 12:18:09,014 ERROR [org.apache.catalina.startup.ContextConfig] (MSC service thread 1-8) Cannot configure an authenticator for method FORM
It's a bit less likely to be reproduced without additional logging overhead in my debug jar that wraps trace logging around "authenticators.load(is)". But I am no longer able to reproduce with the class patched with the attached diff. Just simple synchronization around the authenticators Property initialization and inputstream loading should avoid the issue. (In reply to comment #2) > Reproduced on 6.0.1 with 2 duplicate deployments each using a FORM > authenticator. 3 attempts out of ~20 failed and hit the issue. Added extra > trace logging around the suspect race condition and it shows how the second > fails as it checks the authenticators Property set before it was fully > initialized with the data from the Authenticators.properties data: > > 12:18:09,014 TRACE [org.apache.catalina.startup.ContextConfig] (MSC service > thread 1-3) Starting to load Authenticators.properties > 12:18:09,014 TRACE [org.apache.catalina.startup.ContextConfig] (MSC service > thread 1-3) Finished loading Authenticators.properties > 12:18:09,014 ERROR [org.apache.catalina.startup.ContextConfig] (MSC service > thread 1-8) Cannot configure an authenticator for method FORM
Created attachment 710736 [details] JBWEB7.0.17.GA patch diff
Can workaround this by staggering deployments/scripting them one by one through CLI.
Tomcat uses a static initializer to do this. This should work.
What static initializer are you referring to? I don't see any static initialization within ContextConfig.java where the race condition occurs so I guess somewhere else? If there is a static initializer that should be used for this, then it isn't currently by default. Multiple threads will invoke ContextConfig.authenticatorConfig() at once at start up when you have multiple deployments, allowing for this race condition if they all use a JBossWeb authenticator.
The code that initializes the authenticator map can probably be moved inside a static initializer. That's what Tomcat is doing, so I'll try it (r2181).
Web 7.2.1.Final is tagged and in Nexus.
Verified on EAP 6.1.1.ER4
Added a rough release note draft to the Docs Text field above. Setting NEEDINFO to request a technical verification of the note from the assignee, however feedback from anyone able to provide it at this last stage will be appreciated. If the draft is found to be inaccurate, please return the 'requires_doc_text' flag to '?" and add a comment with the corrections.