Hello,
We are testing micrometer reactive tracing.
If we add @EnableReactiveMethodSecurity annotation to our configuration we're not able to see traceId and spanId in logs. If we comment out @EnableReactiveMethodSecurity context propogration works as expected but we're loosing method security.
If it helps, enabling reactive method security causes following additional logs
2023-02-24 12:44:22.530 [main] INFO o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.boot.actuate.autoconfigure.observation.ObservationAutoConfiguration' of type [org.springframework.boot.actuate.autoconfigure.observation.ObservationAutoConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying) {}
2023-02-24 12:44:22.546 [main] INFO o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'observationRegistry' of type [io.micrometer.observation.SimpleObservationRegistry] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying) {}
Thanks for your help.
Comment From: wilkinsona
It's hard to help based on what you've described thus far. I can see that something is causing a couple of observability-related beans to be created too early, but I can't tell what that cause is or if it's the reason for your problem. If you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.
Comment From: ugurlu
You can observe behaviour on the attached file. TraceId is visible when
curl -v http://localhost:8787/testmono1
is executed
2023-02-24T14:34:52.490+03:00 INFO [test-service,63f8a0dcced69e05a4af64c2068774bb,a4af64c2068774bb] 36100 --- [ parallel-1] com.example.demo.RestCtrl : dummy
2023-02-24T14:34:52.497+03:00 INFO [test-service,63f8a0dcced69e05a4af64c2068774bb,a4af64c2068774bb] 36100 --- [ parallel-1] com.example.demo.RestCtrl : dummy 2
When comment removed from line 17 of SecurityConfig.java log changes to
2023-02-24T14:34:17.028+03:00 INFO [test-service,NOIT,SSS] 40148 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.actuate.autoconfigure.observation.ObservationAutoConfiguration' of type [org.springframework.boot.actuate.autoconfigure.observation.ObservationAutoConfiguration] is not eligible for getting
processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2023-02-24T14:34:17.037+03:00 INFO [test-service,NOIT,SSS] 40148 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'observationRegistry' of type [io.micrometer.observation.SimpleObservationRegistry] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
..
..
..
2023-02-24T14:34:22.530+03:00 INFO [test-service,NOIT,SSS] 40148 --- [ parallel-1] com.example.demo.RestCtrl : dummy
2023-02-24T14:34:22.536+03:00 INFO [test-service,NOIT,SSS] 40148 --- [ parallel-1] com.example.demo.RestCtrl : dummy 2
EnableReactiveMethodSecurity.zip
Comment From: wilkinsona
Thanks for the sample.
This looks like a bug in Spring Security. The preAuthorizeInterceptor bean defined in ReactiveAuthorizationManagerMethodSecurityConfiguration is an Advisor so it's created very early by the AOP infrastructure. It injects an ObjectProvider<ObservationRegistry> which should delay the creation of the ObservationRegistry. Unfortunately, this provider is passed into ReactiveAuthorizationManagerMethodSecurityConfiguration#manager which immediately calls getIfAvailable(). As a result the ObservationRegistry is created very early as part of setting up the AOP infrastructure and this prevents it from being post-processed correctly.
I have opened https://github.com/spring-projects/spring-security/issues/12780 so that the Security team can investigate.
Comment From: ugurlu
Thank you for the effort.