JNDI lookup fails with keys ending ":" in IBM Liberty during application startup

[remesh22]

I am facing a weird issue with containers other than Tomcat(spring boot 1.3.5). The issue is with StandardServletEnvironment which includes JNDIDatasource as one of the property source.

@Override
protected void customizePropertySources(MutablePropertySources propertySources) {
    propertySources.addLast(new StubPropertySource(SERVLET_CONFIG_PROPERTY_SOURCE_NAME));
    propertySources.addLast(new StubPropertySource(SERVLET_CONTEXT_PROPERTY_SOURCE_NAME));
    if (JndiLocatorDelegate.isDefaultJndiEnvironmentAvailable()) {
        propertySources.addLast(new JndiPropertySource(JNDI_PROPERTY_SOURCE_NAME));
    }
    super.customizePropertySources(propertySources);
}

Spring is by default looking for some jndi properties ending with ":" at the end of the property. The lookup is failing for the following properties

spring.cloud.bootstrap.name:
SPRING_APPLICATION_JSON: 
spring.cloud.bootstrap.location: 

etc

Here is the sample application.
demo_ibm.zip

[wilkinsona]

The placeholder in SpringApplicationJsonEnvironmentPostProcessor looks to be wrong:

String json = environment.resolvePlaceholders(
        "${spring.application.json:${SPRING_APPLICATION_JSON:}}");

AFAICT, there's no need for the second :.

@remesh22 We can fix that one in Spring Boot, but the other two belong to Spring Cloud. Can you please open a separate issue for spring.cloud.bootstrap.name: and spring.cloud.bootstrap.location:? I think that https://github.com/spring-cloud/spring-cloud-commons is the correct repo for those.

[wilkinsona]

I was wrong above. The second colon is required in order to provide a default value for when the SPRING_APPLICATION_JSON environment variable has not been set.

An alternative would be "${spring.application.json:${SPRING_APPLICATION_JSON:{}}}" which will probably fix Liberty's weird behaviour. We'd then perform the following lookups:

• SPRING_APPLICATION_JSON:{}
• SPRING_APPLICATION_JSON
• spring.application.json:{}
• spring.application.json

[wilkinsona]

@remesh22 I can't reproduce the problem using your sample application. I've tried with both 8.5.5.3 and 16.0.0.2. Here's the log from 16.0.0.2:

objc[7944]: Class JavaLaunchHelper is implemented in both /Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/bin/java and /Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/libinstrument.dylib. One of the two will be used. Which one is undefined.
Launching my-server (WebSphere Application Server 16.0.0.2/wlp-1.0.13.cl160220160526-2258) on Java HotSpot(TM) 64-Bit Server VM, version 1.8.0_74-b02 (en_US)
[AUDIT   ] CWWKE0001I: The server my-server has been launched.
[AUDIT   ] CWWKE0100I: This product is licensed for development, and limited production use. The full license terms can be viewed here: https://public.dhe.ibm.com/ibmdl/export/pub/software/websphere/wasdev/license/base_ilan/ilan/16.0.0.2/lafiles/en.html
[AUDIT   ] CWWKZ0058I: Monitoring dropins for applications. 
[AUDIT   ] CWWKS4104A: LTPA keys created in 0.394 seconds. LTPA key file: /Users/awilkinson/dev/runtimes/websphere/wlp/16.0.0.2/usr/servers/my-server/resources/security/ltpa.keys
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/demo_ibm/
[AUDIT   ] CWWKZ0001I: Application demo-0.0.1-SNAPSHOT started in 5.671 seconds.
[AUDIT   ] CWWKF0012I: The server installed the following features: [jsp-2.3, ejbLite-3.2, managedBeans-1.0, jsf-2.2, beanValidation-1.1, servlet-3.1, ssl-1.0, jndi-1.0, jsonp-1.0, appSecurity-2.0, jdbc-4.1, jaxrs-2.0, jaxrsClient-2.0, el-3.0, json-1.0, cdi-1.2, distributedMap-1.0, webProfile-7.0, websocket-1.1, jpa-2.1].
[AUDIT   ] CWWKF0011I: The server my-server is ready to run a smarter planet.
[WARNING ] CWNEN0047W: Resource annotations on the fields of the org.springframework.web.servlet.view.tiles3.TilesConfigurer$CompositeELResolverImpl class will be ignored. The annotations could not be obtained because of the exception : java.lang.NoClassDefFoundError: org/apache/tiles/el/ScopeELResolver
[WARNING ] CWNEN0049W: Resource annotations on the methods of the org.springframework.web.servlet.view.tiles3.TilesConfigurer$CompositeELResolverImpl class will be ignored. The annotations could not be obtained because of the exception : java.lang.NoClassDefFoundError: org/apache/tiles/el/ScopeELResolver
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.3.5.RELEASE)
2016-07-26 16:30:44.521  INFO 7944 --- [ecutor-thread-3] com.example.DemoIbmApplication           : Starting DemoIbmApplication on aw-rmbp.home with PID 7944 (/Users/awilkinson/dev/runtimes/websphere/wlp/16.0.0.2/usr/servers/my-server/apps/expanded/demo-0.0.1-SNAPSHOT.war/WEB-INF/classes started by awilkinson in /Users/awilkinson/dev/runtimes/websphere/wlp/16.0.0.2/usr/servers/my-server)
2016-07-26 16:30:44.524  INFO 7944 --- [ecutor-thread-3] com.example.DemoIbmApplication           : No active profile set, falling back to default profiles: default
2016-07-26 16:30:44.552  INFO 7944 --- [ecutor-thread-3] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@3a96ff10: startup date [Tue Jul 26 16:30:44 BST 2016]; root of context hierarchy
2016-07-26 16:30:45.602  INFO 7944 --- [ecutor-thread-3] f.a.AutowiredAnnotationBeanPostProcessor : JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2016-07-26 16:30:45.625  INFO 7944 --- [ecutor-thread-3] com.ibm.ws.webcontainer.webapp           : SRVE0292I: Servlet Message - [demo-0.0.1-SNAPSHOT]:.Initializing Spring embedded WebApplicationContext
2016-07-26 16:30:45.625  INFO 7944 --- [ecutor-thread-3] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1073 ms
2016-07-26 16:30:46.456  INFO 7944 --- [ecutor-thread-3] o.s.b.c.e.ServletRegistrationBean        : Mapping servlet: 'dispatcherServlet' to [/]
2016-07-26 16:30:46.466  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'errorPageFilter' to: [/*]
2016-07-26 16:30:46.467  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'metricFilter' to: [/*]
2016-07-26 16:30:46.467  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'characterEncodingFilter' to: [/*]
2016-07-26 16:30:46.467  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2016-07-26 16:30:46.468  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'httpPutFormContentFilter' to: [/*]
2016-07-26 16:30:46.468  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'requestContextFilter' to: [/*]
2016-07-26 16:30:46.468  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'webRequestLoggingFilter' to: [/*]
2016-07-26 16:30:46.469  INFO 7944 --- [ecutor-thread-3] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'applicationContextIdFilter' to: [/*]
2016-07-26 16:30:46.554  INFO 7944 --- [ecutor-thread-3] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@3a96ff10: startup date [Tue Jul 26 16:30:44 BST 2016]; root of context hierarchy
2016-07-26 16:30:46.583  INFO 7944 --- [ecutor-thread-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/]}" onto public java.lang.String com.example.RESTController.hello()
2016-07-26 16:30:46.589  INFO 7944 --- [ecutor-thread-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2016-07-26 16:30:46.589  INFO 7944 --- [ecutor-thread-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2016-07-26 16:30:46.611  INFO 7944 --- [ecutor-thread-3] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-07-26 16:30:46.611  INFO 7944 --- [ecutor-thread-3] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-07-26 16:30:46.633  INFO 7944 --- [ecutor-thread-3] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-07-26 16:30:47.550  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/info || /info.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.551  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/metrics/{name:.*}],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.MetricsMvcEndpoint.value(java.lang.String)
2016-07-26 16:30:47.551  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/metrics || /metrics.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.552  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/mappings || /mappings.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.552  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/health || /health.json],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.HealthMvcEndpoint.invoke(java.security.Principal)
2016-07-26 16:30:47.553  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/autoconfig || /autoconfig.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.555  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/env/{name:.*}],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EnvironmentMvcEndpoint.value(java.lang.String)
2016-07-26 16:30:47.555  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/env || /env.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.556  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/beans || /beans.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.557  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/dump || /dump.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.557  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/configprops || /configprops.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.558  INFO 7944 --- [ecutor-thread-3] o.s.b.a.e.mvc.EndpointHandlerMapping     : Mapped "{[/trace || /trace.json],methods=[GET],produces=[application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2016-07-26 16:30:47.683  INFO 7944 --- [ecutor-thread-3] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2016-07-26 16:30:47.689  INFO 7944 --- [ecutor-thread-3] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 0
2016-07-26 16:30:47.755  INFO 7944 --- [ecutor-thread-3] com.example.DemoIbmApplication           : Started DemoIbmApplication in 3.86 seconds (JVM running for 45.857)
2016-07-26 16:30:47.838  WARN 7944 --- [ecutor-thread-3] com.ibm.ws.session.WASSessionCore        : Detected JSESSIONID with invalid length; expected length of 23, found 28, setting: 3DBA79ACB6477B7BA8187F71864D to null.
2016-07-26 16:30:47.839  WARN 7944 --- [cutor-thread-22] com.ibm.ws.session.WASSessionCore        : Detected JSESSIONID with invalid length; expected length of 23, found 28, setting: 3DBA79ACB6477B7BA8187F71864D to null.
2016-07-26 16:30:47.846  INFO 7944 --- [ecutor-thread-3] com.ibm.ws.webcontainer.webapp           : SRVE0292I: Servlet Message - [demo-0.0.1-SNAPSHOT]:.Initializing Spring FrameworkServlet 'dispatcherServlet'
2016-07-26 16:30:47.846  INFO 7944 --- [ecutor-thread-3] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization started
2016-07-26 16:30:47.855  INFO 7944 --- [ecutor-thread-3] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization completed in 8 ms
2016-07-26 16:30:47.855  INFO 7944 --- [ecutor-thread-3] com.ibm.ws.webcontainer.servlet          : SRVE0242I: [demo-0.0.1-SNAPSHOT] [/demo_ibm] [dispatcherServlet]: Initialization successful.

Can you please provide the precise steps and versions that are required to reproduce the problem?

[remesh22]

The application will start up even though we get lot of errors in ffdc location.Please check the log at servers/defaultserver/logs/ffdc. I am using version 8.5.5.9

[wilkinsona]

Thanks. There are more failures than you mention. I see a ClassNotFoundException for the following classes:

• com.sun.jndi.url.SPRING_APPLICATION_JSON.SPRING_APPLICATION_JSONURLContextFactory
• com.sun.jndi.url.spring.application.json.spring.application.jsonURLContextFactory
• com.sun.jndi.url.LOG_LEVEL_PATTERN.LOG_LEVEL_PATTERNURLContextFactory
• com.sun.jndi.url.logging.pattern.level.logging.pattern.levelURLContextFactory
• com.sun.jndi.url.spring.config.name.spring.config.nameURLContextFactory
• com.sun.jndi.url.vcap.application.name.vcap.application.nameURLContextFactory
• com.sun.jndi.url.spring.application.name.spring.application.nameURLContextFactory
• com.sun.jndi.url.PORT.PORTURLContextFactory
• com.sun.jndi.url.server.port.server.portURLContextFactory
• com.sun.jndi.url.spring.application.index.spring.application.indexURLContextFactory

Now that I can see the failures, I can also see that I was wrong (again) when I said that changing the look up would fix the error. For example, three of the errors above are produced while resolving ${spring.application.name:${vcap.application.name:${spring.config.name:application}}}. Liberty appears to fail on any JNDI lookup with a : in the name. Unfortunately, there's nothing we can do about this in Spring Boot as it's the standard Spring Framework syntax for a place holder with a default value. FWIW, Tomcat simply throws a NameNotFoundException in the same situation.

Spring Framework's JndiLocatorSupport.convertJndiName attempts to apply a scheme to any name that doesn't have one. It won't be doing so in this case due to the presence of the : in the name. I'm not sure if there's anything that can be done, but you might want to raise an SPR JIRA ticket to explore the possibility of it somehow adding the prefix in this case. That might stop the failure in Liberty. Failing that, you could get in touch with IBM and see if there's anything that can be done in Liberty. And, failing that, you could ignore the problem as it appears to be benign (other than the FFDCs).

[jhoeller]

As of Spring Framework 4.3, you can set a Spring property (system property or entry in a spring.properties file) "spring.jndi.ignore", e.g. spring.jndi.ignore=true to skip any default JNDI checks. This might be the easiest way out in such a scenario, and is available out of the box as of Boot 1.4 which includes Spring Framework 4.3.

[remesh22]

Thanks for the info jhoeller. I am using version 1.3.5 right now and i will migrate to 1.4 when it is released.

[snicoll]

@remesh22 can you please try now? You can use Spring Framework 4.3 with your current setup, just override the spring.version to 4.3.1.RELEASE if you're using the spring-boot-starter-parent pom. Alternatively you could give 1.4.0.RC1 a try.

[remesh22]

Tried with updating the spring version to 4.3.1and also tried with 1.4.0.RC1. Getting the same error and also application.properties complain that 'spring.jndi.ignore' is an unknown property.

[snicoll]

That must be in a file called spring.properties or via a system property. This is a spring framework override. Can you try that please?

[jhoeller]

FYI, I'm looking into this tonight for a potential quick fix in 4.3.2 still... Maybe there's a simple enough rule for the framework not to try clearly invalid JNDI names to begin with.

[jhoeller]

See https://jira.spring.io/browse/SPR-14518 for the above-mentioned effort towards ignoring invalid JNDI names to begin with.

[remesh22]

I tried with system property and it's working fine.
Tried both options. All good now.Thank you so much for the quick turnaround.

[jhoeller]

Thanks, that's great to know since it validates our assumptions. I've also finished SPR-14518 in the meantime, so those warnings on Liberty should not happen out of the box anymore either as of Spring Framework 4.3.2.