Lazily initialize Environment in GenericFilterBean (aligned with HttpServletBean) [SPR-15469]

[spring-projects-issues]

Caleb Cushing opened SPR-15469 and commented

We noticed there were a lot of these logs

[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletConfigInitParams] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletContextInitParams] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [jndiProperties] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemProperties] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemEnvironment] PropertySource with lowest search precedence
[DEBUG] [10:15:23] [localhost-startStop-1] env.AbstractEnvironment:124 - Initialized StandardServletEnvironment with PropertySources [servletConfigInitParams,servletContextInitParams,jndiProperties,systemProperties,systemEnvironment]
[DEBUG] [10:15:23] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletConfigInitParams] PropertySource with lowest search precedence
[DEBUG] [10:15:23] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletContextInitParams] PropertySource with lowest search precedence
[DEBUG] [10:15:23] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [jndiProperties] PropertySource with lowest search precedence
[DEBUG] [10:15:23] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemProperties] PropertySource with lowest search precedence
[DEBUG] [10:15:23] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemEnvironment] PropertySource with lowest search precedence
[DEBUG] [10:16:10] [localhost-startStop-1] env.AbstractEnvironment:124 - Initialized StandardServletEnvironment with PropertySources [servletConfigInitParams,servletContextInitParams,jndiProperties,systemProperties,systemEnvironment]
[DEBUG] [10:16:10] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletConfigInitParams] PropertySource with lowest search precedence
[DEBUG] [10:16:10] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletContextInitParams] PropertySource with lowest search precedence
[DEBUG] [10:16:10] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [jndiProperties] PropertySource with lowest search precedence
[DEBUG] [10:16:10] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemProperties] PropertySource with lowest search precedence
[DEBUG] [10:16:10] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemEnvironment] PropertySource with lowest search precedence
... truncated for brevity

Stephane Nichol told me in a gitter conversation that this shouldn't happen.

I've finally had time to dig into this, to see why it's happening in our system. Turns out it's because of line 94 in GenericFilterBean every time we create a new filter we create a new StandardServletEnvironment.

So this leave's me with 2 questions on improvements.

1. is there a way to provide what the environment is created for in the log?
2. maybe lazily instantiate the environment in GenericFilterBean (normally I'd be against this, but not sure if most of the time, whether the global environment is auto passed or not)

not sure fixing this is a major win for me, but it was confusing, and required using the debugger to navigate the stack to figure out why this was happening.

---

Affects: 4.3.8

Referenced from: commits dab56db, 1ea54eb

[spring-projects-issues]

Juergen Hoeller commented

I'm rather surprised that you're watching the debug-level log so closely but you nevertheless got a point :-)

Are you defining those filter beans within a Spring application context or in web.xml? The context's Environment will only be provided in the former case; in the latter, each bean will indeed use its own default StandardServletEnvironment... which we can (and should) lazily initialize in GenericFilterBean.init indeed, in particular for the case where an external Environment is being provided anyway.

[spring-projects-issues]

Caleb Cushing commented

I'm rather surprised that you're watching the debug-level log so closely but you nevertheless got a point

well... I replaced our reliance on commons-configuration, with property sources, and our PropertySourcesMerger does this thing where it writes the merged results back to System.properties, probably for a hand full of templated xml's that only know how to use that as the property source. At the end of all that, looked at it and wondered why we have half a dozen repeating logs. I'm not sure when they were turned on, and guessing now that they existed before this migration, we just didn't notice them, but also couldn't explain them.

Are you defining those filter beans within a Spring application context or in web.xml?

looks like we're defining them as @Component, and we probably aren't actually setting Environment to be provided in anyway. Though that makes me wonder why setEnvironment doesn't have @Autowired, regardless we could add that in our subclasses.

I also got to thinking that maybe the bean constructor/init could/should also log itself so that the log would look more like

[DEBUG] [10:07:54] [localhost-startStop-1] dex.TimeoutFilter:109 - initializing environment
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletConfigInitParams] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [servletContextInitParams] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [jndiProperties] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemProperties] PropertySource with lowest search precedence
[DEBUG] [10:07:54] [localhost-startStop-1] env.MutablePropertySources:109 - Adding [systemEnvironment] PropertySource with lowest search precedence

in this way the logs would come after a log that tells you what's creating them.

[spring-projects-issues]

Juergen Hoeller commented

When running in a Spring application context, setEnvironment is being populated through the EnvironmentAware callback interface, so doesn't need an @Autowired annotation. So if we initialize the default Environment lazily, those log entries should disappear completely in such a scenario.

[spring-projects-issues]

Caleb Cushing commented

ah, ok, I thought that was true, but then second guessed myself. Cool.

[spring-projects-issues]

Caleb Cushing commented

#1405 basic implementation based on 4.3 branch

not sure if EnvironmentCapable should be applied, or if these should be public/protected, didn't write tests yet either.

[spring-projects-issues]

Juergen Hoeller commented

HttpServletBean makes some compromises for DispatcherServlet that we don't necessarily have to follow in GenericFilterBean. I'll make up my mind on how far to take the alignment there.

Your PR generally goes in the right direction but I'm afraid we'll have to start with the master branch towards 5.0. I'll backport it to 4.3.x from there, possibly in a limited fashion. Being at it, I can also take care of the actual changes in master for 5.0 RC1; I'd also like to review all other Environment initialization spots still.

[spring-projects-issues]

Juergen Hoeller commented

I've done a somewhat larger revision in the meantime, also addressing the GenericFilterBean issue. I'll backport this to 4.3.9 tomorrow.