Instrument EventListener-annotated methods for observability

[vpavic]

This is analogous to #29883, just for @EventListener.

[kubehe]

Would it be also possible to support propagating trace from ApplicationEventPublisher?

For example by extending PayloadApplicationEvent with "headers" field.

[bclozel]

I'm not sure we should implement this actually.

For me a consistent observability instrumentation makes sense if:

• the operation has a high chance of consuming CPU time and I/O
• there are high-level semantics that we can use to extract meaningful KeyValues
• the recorded observations do not clutter the traces nor the metrics dashboards
• this effort does not go into the java profiler territory

@EventListener is really a method that is notified of an event, that's it. There is no other meaning attached to it.

It can be used for a lot of cases where their execution is really quick, does not involve I/O, does not switch threads. Also, besides the method name and the event type there's nothing much we can extract as metadata. In the case of @Scheduled observability, those methods are not likely to fire many times per second at runtime and it's common to use those to do CPU and I/O intensive work (also: thread pools). For @EventListener, many methods can listen to the same event and will be executed serially on the same thread. They can fire up multiple times per second, depending on the event.

I think this issue is very close to #30832 (@Async observability): while observability can be useful there, instrumenting at the framework level might not be worth it. Custom observations with Observation.create*** or @Observed sound more appealing: we can selectively instrument things and use application-level concepts.

In the case of ApplicationEventPublisher, I think it would make even more sense to create an observation around it with the application semantics. Am I missing something here?

[vpavic]

Thanks for the feedback. I think I should've put more context in the description when I opened this issue.

To me, this is analogous to #30335 in terms of the high-level flow and observability expectations - the difference being that the event isn't being transmitted over some external entity (message broker), but rather simply over the application context's event publishing facilities.

By default, as listener is invoked in the same thread, everything should work out of the box, however if the listener is async then whatever work it does it won't be a part of the same trace.

Additionally, I sometimes work with 3rd libraries that involve some kind of event-driven integration, requiring the developer to implement listener for certain event type - in this case the observation is not started in the 3rd party code, so Spring should probably take care of that when the event is published using ApplicationEventPublisher. I guess that scenario shoud be covered by this:

In the case of ApplicationEventPublisher, I think it would make even more sense to create an observation around it with the application semantics.

[vpavic]

By default, as listener is invoked in the same thread, everything should work out of the box, however if the listener is async then whatever work it does it won't be a part of the same trace.

Potentially, in the above scenario there's some overlap between what's requested in this issue and #29977 (or #30832).

[bclozel]

I think you've lost me.

Could you share concretely what observation are you expecting for @EventListener annotated methods? A concrete example of an observation would be nice: the observation name, what time is measured and the key values attached to the observation.

[vpavic]

Sorry for not being clear enough. I'll try with a very simple example:

spring.application.name=sample
logging.pattern.level=%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]

@SpringBootApplication
@RestController
public class SampleApplication {

    private static final Logger logger = LoggerFactory.getLogger(SampleApplication.class);

    public static void main(String[] args) {
        SpringApplication.run(SampleApplication.class, args);
    }

    @Autowired
    private ApplicationEventPublisher eventPublisher;

    @GetMapping(path = "/")
    String home() {
        logger.info("home handler invoked");
        this.eventPublisher.publishEvent(new SampleEvent("sample"));
        return "Hello World!";
    }

    @EventListener(SampleEvent.class)
    void handleGreetEvent(SampleEvent event) {
        logger.info("handled event: {}", event);
    }

    record SampleEvent(String name) {

    }

}

By default, observation context will get propagated and if I hit the endpoint, the following will be logged:

2023-07-11T23:33:45.677+02:00  INFO [sample,d9fb5f1950b4fc4012544f88830487e6,6356a9c4b84c2475] 3472159 --- [nio-8080-exec-1] sample.SampleApplication                 : home handler invoked
2023-07-11T23:33:45.677+02:00  INFO [sample,d9fb5f1950b4fc4012544f88830487e6,6356a9c4b84c2475] 3472159 --- [nio-8080-exec-1] sample.SampleApplication                 : handled event: SampleEvent[name=sample]

However, if I opt into running listener in a different thread using this:

@Bean(name = "applicationEventMulticaster")
public SimpleApplicationEventMulticaster simpleApplicationEventMulticaster() {
    SimpleApplicationEventMulticaster eventMulticaster = new SimpleApplicationEventMulticaster();
    eventMulticaster.setTaskExecutor(new SimpleAsyncTaskExecutor());
    return eventMulticaster;
}

Then obviously from observability perspective things don't work as before:

2023-07-11T23:38:54.509+02:00  INFO [sample,f1c5a03a4c6f1e3daaf1456e3d552c5c,f3840ab08a79ac04] 3473417 --- [nio-8080-exec-1] sample.SampleApplication                 : home handler invoked
2023-07-11T23:38:54.510+02:00  INFO [sample,,] 3473417 --- [TaskExecutor-22] sample.SampleApplication                 : handled event: SampleEvent[name=sample]

The same effect is also present if I don't provide custom ApplicationEventMulticaster but rather simply annotate the listener with @Async - in that case there some overlap with what we're discussing in #29977.

Other example is listening for events where publishing side is not a part of an existing observation. In this case I'd like to see a new observation started with the @EventListener method that is being invoked.

Hopefully this makes things a bit clearer.

Forgot to note, when I'm mentioning @EventListener I'm also referring to @TransactionalEventListener. These two have always been a nice mechanism to decouple different logical units in the codebase, but I'm expecting their usage will only go up now that Spring Modulith has been promoted to official Spring project.