Exclude authorization messages from ERROR logging in StompSubProtocolHandler

[phil-applegate]

Affects: 5.3.17

---

As part of #26026 the logging in StompSubProtocolHandler was improved to prevent the logging of exceptions pertaining to failed authentication. More specifically, this suppression applies to STOMP CONNECT messages as per (bcd2b9a#diff-624b9c9ccd9db4e56263e34b3e865fdce34e9b1dd00a00f956f919ede789265fR337).

Given that Spring Security allows for access decisions to be made at the topic level when users Subscribe (using MessageSecurityMetaDataSourceRegistry.simpSubscribeDestMatchers(String... patterns)) should the logging suppression be enhanced to apply to both CONNECT and SUBSCRIBE messages? This will therefore suppress the error level logging when a user fails authorization when subscribing to a topic.

[rstoyanchev]

For #26026 the concern was that a user that is not even authenticated could filling up the logs with stacktraces, while for a subscription to be sent, the user must have been authenticated already. Did you run into this from a specific use case or concern, and if so could you please elaborate?

[rstoyanchev]

This will therefore suppress the error level logging when a user fails authentication when subscribing to a topic.

Just noticed this. Subscribing should trigger authorization, not authentication.

[phil-applegate]

Thanks for your response. Apologies - you are correct. I've updated the original post to refer to authorization rather than authentication.

In the use case I am referring to, access decisions are made on a per topic basis so it's likely there could be authenticated users who are not authorized to access a range of topics. Ultimately, the concern here was similar #26026 in that authenticated users who are not authorized for a given topic could cause unnecessary errors to be logged. Is the expectation within Spring Messaging/Spring Security that an error be explicitly logged when a user is denied access? I believe in other areas (REST), this is typically logged at DEBUG level.

[rstoyanchev]

Thanks for clarifying.

We typically do log unhandled errors, which is how this looks from the perspective of StompSubProtocolHandler, and if I'm not mistaken after that an ERROR frame is sent and the connection is closed. If we did not log this, I'm pretty sure it would cause the opposite issue of not seeing anything to explain the error.

Note that the interceptor can return true or false to skip the processing of the message but it chooses to reject it in a way that does not allow the user to use the connection further. I think that's justified since it's not clear why the user is trying to access subscriptions they're not allowed to access, and the logging of that exception at ERROR is in line with that.

Just to be clear you are not suggesting that authenticated users in your use case could be intentionally doing this. In other words, it's more about noise in the logs rather than intentionally filling them up?

[phil-applegate]

Yes, you are correct this is more about noise rather than the logs being intentionally filled up.

I understand your point where an explanation is required for what has caused the error. Perhaps the auth issues here are different to other types of exception as it's arguable if an error has actually occurred, rather the system is functioning as expected and denying unauthorized requests.

Would the ERROR frame back to the client/caller not provide sufficient details that an auth error has occurred? If more details were required on the server side, would it not be expected that DEBUG level logging be enabled to see why requests are being denied?

Perhaps I am mistaken, but I believe this is the pattern used in Spring Web (Security). If a REST endpoint is hit and a user is unauthorized an HTTP 403 would be returned but to see the details on the server side you'd need to enable DEBUG logging on org.springframework.security.