Numerous logs mentioning a failed JNDI lookup when using Jetty

[filpano]

Affects: 5.2.7.RELEASE

After migrating to Spring Boot 2.3.1.RELEASE / Spring 5.2.7.RELEASE, I am seeing the following DEBUG logs upon application startup (in fact, they are the very first log messages printed out):

2020-07-07 09:16:12.407 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [java:comp/env/logging.group]
2020-07-07 09:16:12.413 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.413 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@2fba3fc4
2020-07-07 09:16:12.414 DEBUG 12015 --- [           main] o.e.j.jndi.java.javaURLContextFactory    : >>> new root context requested 
2020-07-07 09:16:12.414 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="comp/env/logging.group"
2020-07-07 09:16:12.415 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.ContextFactory    : Trying thread context classloader
2020-07-07 09:16:12.419 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="env/logging.group"
2020-07-07 09:16:12.419 DEBUG 12015 --- [           main] o.s.jndi.JndiLocatorDelegate             : Converted JNDI name [java:comp/env/logging.group] not found - trying original name [logging.group]. javax.naming.NameNotFoundException: env is not bound; remaining name 'env/logging.group'
2020-07-07 09:16:12.419 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [logging.group]
2020-07-07 09:16:12.419 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.419 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@4bf48f6
2020-07-07 09:16:12.419 DEBUG 12015 --- [           main] o.e.jetty.jndi.local.localContextRoot    : Looking up name="logging.group"
2020-07-07 09:16:12.420 DEBUG 12015 --- [           main] o.s.jndi.JndiPropertySource              : JNDI lookup for name [logging.group] threw NamingException with message: null. Returning null.
2020-07-07 09:16:12.422 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [java:comp/env/logging.group]
2020-07-07 09:16:12.422 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.422 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@1c852c0f
2020-07-07 09:16:12.423 DEBUG 12015 --- [           main] o.e.j.jndi.java.javaURLContextFactory    : >>> new root context requested 
2020-07-07 09:16:12.423 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="comp/env/logging.group"
2020-07-07 09:16:12.423 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.ContextFactory    : Trying thread context classloader
2020-07-07 09:16:12.423 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="env/logging.group"
2020-07-07 09:16:12.423 DEBUG 12015 --- [           main] o.s.jndi.JndiLocatorDelegate             : Converted JNDI name [java:comp/env/logging.group] not found - trying original name [logging.group]. javax.naming.NameNotFoundException: env is not bound; remaining name 'env/logging.group'
2020-07-07 09:16:12.423 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [logging.group]
2020-07-07 09:16:12.423 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.424 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@a37aefe
2020-07-07 09:16:12.424 DEBUG 12015 --- [           main] o.e.jetty.jndi.local.localContextRoot    : Looking up name="logging.group"
2020-07-07 09:16:12.424 DEBUG 12015 --- [           main] o.s.jndi.JndiPropertySource              : JNDI lookup for name [logging.group] threw NamingException with message: null. Returning null.
2020-07-07 09:16:12.426 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [java:comp/env/logging.level]
2020-07-07 09:16:12.426 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.426 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@24c4ddae
2020-07-07 09:16:12.426 DEBUG 12015 --- [           main] o.e.j.jndi.java.javaURLContextFactory    : >>> new root context requested 
2020-07-07 09:16:12.426 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="comp/env/logging.level"
2020-07-07 09:16:12.427 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.ContextFactory    : Trying thread context classloader
2020-07-07 09:16:12.427 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="env/logging.level"
2020-07-07 09:16:12.427 DEBUG 12015 --- [           main] o.s.jndi.JndiLocatorDelegate             : Converted JNDI name [java:comp/env/logging.level] not found - trying original name [logging.level]. javax.naming.NameNotFoundException: env is not bound; remaining name 'env/logging.level'
2020-07-07 09:16:12.427 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [logging.level]
2020-07-07 09:16:12.427 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.427 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@37fb0bed
2020-07-07 09:16:12.427 DEBUG 12015 --- [           main] o.e.jetty.jndi.local.localContextRoot    : Looking up name="logging.level"
2020-07-07 09:16:12.428 DEBUG 12015 --- [           main] o.s.jndi.JndiPropertySource              : JNDI lookup for name [logging.level] threw NamingException with message: null. Returning null.
2020-07-07 09:16:12.428 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [java:comp/env/logging.level]
2020-07-07 09:16:12.429 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.429 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@a82c5f1
2020-07-07 09:16:12.429 DEBUG 12015 --- [           main] o.e.j.jndi.java.javaURLContextFactory    : >>> new root context requested 
2020-07-07 09:16:12.429 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="comp/env/logging.level"
2020-07-07 09:16:12.429 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.ContextFactory    : Trying thread context classloader
2020-07-07 09:16:12.429 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="env/logging.level"
2020-07-07 09:16:12.430 DEBUG 12015 --- [           main] o.s.jndi.JndiLocatorDelegate             : Converted JNDI name [java:comp/env/logging.level] not found - trying original name [logging.level]. javax.naming.NameNotFoundException: env is not bound; remaining name 'env/logging.level'
2020-07-07 09:16:12.430 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [logging.level]
2020-07-07 09:16:12.430 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.430 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@7b7fdc8
2020-07-07 09:16:12.430 DEBUG 12015 --- [           main] o.e.jetty.jndi.local.localContextRoot    : Looking up name="logging.level"
2020-07-07 09:16:12.430 DEBUG 12015 --- [           main] o.s.jndi.JndiPropertySource              : JNDI lookup for name [logging.level] threw NamingException with message: null. Returning null.
2020-07-07 09:16:12.433 DEBUG 12015 --- [           main] org.springframework.jndi.JndiTemplate    : Looking up JNDI object with name [java:comp/env/logging.level.org.company]
2020-07-07 09:16:12.433 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : InitialContextFactory.getInitialContext()
2020-07-07 09:16:12.433 DEBUG 12015 --- [           main] o.e.jetty.jndi.InitialContextFactory     : Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@7fc4780b
2020-07-07 09:16:12.433 DEBUG 12015 --- [           main] o.e.j.jndi.java.javaURLContextFactory    : >>> new root context requested 
2020-07-07 09:16:12.433 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="comp/env/logging.level.org.company"
2020-07-07 09:16:12.434 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.ContextFactory    : Trying thread context classloader
2020-07-07 09:16:12.434 DEBUG 12015 --- [           main] org.eclipse.jetty.jndi.NamingContext     : Looking up name="env/logging.level.org.company"
2020-07-07 09:16:12.434 DEBUG 12015 --- [           main] o.s.jndi.JndiLocatorDelegate             : Converted JNDI name [java:comp/env/logging.level.org.company] not found - trying original name [logging.level.org.company]. javax.naming.NameNotFoundException: env is not bound; remaining name 'env/logging.level.org.company'
... some more

In my bootstrap.yaml I have the following:

logging:
  pattern:
    console: ${pattern.json}
  level:
    org.company: DEBUG
    root: INFO

This does not seem to affect my application at all, seeing how we do not use JNDI. However, I have been unable to turn these messages off and I am even surprised that they are logged at all (seeing how the root logger is set to INFO). The fact that it is trying to do a JNDI lookup for logging.level makes me think that this is some standard logging that is enabled in Spring itself, before Logback configuration has even been picked up.

[snicoll]

This does not seem to be related to the core framework so I've moved this issue to Spring Boot. It sounds like you're reporting an upgrade problem but you didn't mention the version of Spring Boot that you were using previously that didn't have the problem. If you revert to this version without changing anything else (including the Spring Cloud version), are those logs going away?

[filpano]

Thanks for the reply. I had initially created the issue in the main Spring tracker as the org.sprinfgramework.jndi.JndiTemplate that produces said logs is a spring-context component.

We migrated from Spring Boot 2.1.3.RELEASE / Spring 5.1.5.RELEASE. Unfortunately, I cannot run the application without changing anything else as there are incompatible Class changes between the versions.

Edit: FWIW, we also updated from Spring Cloud Stream Greenwich.SR2 to Hoxton.SR6. However, I don't think this has any bearing on the issue - our services which do not use Spring Cloud Stream are also showing this issue.

[silh]

There was an issue with Jetty JNDI being enabled by default in Spring Boot 1.X and it was fixed here - #4710.
Looks like the transitive dependency was reintroduced.
As a temporary fix you could exclude it in your pom, as it most like not used in Spring Boot application.

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-jetty</artifactId>
            <exclusions>
                <exclusion>
                    <groupId>org.eclipse.jetty</groupId>
                    <artifactId>jetty-jndi</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

The issue is not present in Spring Boot 2.1.0.RELEASE and is present in 2.3.1.RELEASE (I know the distance between the versions is long...).
The relevant part of dependency tree in 2.1.0:

[INFO] |  +- org.eclipse.jetty.websocket:javax-websocket-server-impl:jar:9.4.10.v20180503:compile
[INFO] |  |  +- org.eclipse.jetty:jetty-annotations:jar:9.4.10.v20180503:compile
[INFO] |  |  |  +- org.eclipse.jetty:jetty-plus:jar:9.4.10.v20180503:compile
[INFO] |  |  |  +- org.ow2.asm:asm:jar:6.1.1:compile
[INFO] |  |  |  \- org.ow2.asm:asm-commons:jar:6.1.1:compile
[INFO] |  |  |     +- org.ow2.asm:asm-tree:jar:6.1.1:compile
[INFO] |  |  |     \- org.ow2.asm:asm-analysis:jar:6.1.1:compile

And in 2.3.1:

[INFO] |  +- org.eclipse.jetty.websocket:javax-websocket-server-impl:jar:9.4.29.v20200521:compile
[INFO] |  |  +- org.eclipse.jetty:jetty-annotations:jar:9.4.29.v20200521:compile
[INFO] |  |  |  +- org.eclipse.jetty:jetty-plus:jar:9.4.29.v20200521:compile
[INFO] |  |  |  |  \- org.eclipse.jetty:jetty-jndi:jar:9.4.29.v20200521:compile
[INFO] |  |  |  +- org.ow2.asm:asm:jar:7.3.1:compile
[INFO] |  |  |  \- org.ow2.asm:asm-commons:jar:7.3.1:compile
[INFO] |  |  |     +- org.ow2.asm:asm-tree:jar:7.3.1:compile
[INFO] |  |  |     \- org.ow2.asm:asm-analysis:jar:7.3.1:compile

[snicoll]

@silh thank you very much for the great detective work. We'll review dependency management and see what we can do to avoid that in the future.

[snicoll]

From a quick look, it looks like a regression of us moving to Gradle.