Optimize logging at different levels with WebSocket/Messaging [SPR-11943]

[spring-projects-issues]

Prashant Deva opened SPR-11943 and commented

the info level logging seems to log every single 'connect' event and results in a very verbose log.
i know websocket connections are longer lived than http, but on a mostly websocket site this is akin to logging every http request. This kind of info is only needed during a debugging session and the logging level should reflect that.

please move these messages to a lower logging level (eg 'fine'/'debug') so as not to clutter logs

---

Affects: 4.1 RC1

0 votes, 5 watchers

[spring-projects-issues]

Rossen Stoyanchev commented

Changing the "Affects version" (and consequently the "Fix version") since I'm pretty sure this is with a 4.1 snasphot (that's where the logging improvements were made).

[spring-projects-issues]

Rossen Stoyanchev commented

Indeed, tricky to get the right balance in a messaging application. The recent logging improvements (targeting 4.1) were meant to provide additional options in between error/warning (prod) and debug (dev). I do think connect/disconnect events are important and not quite the same as every HTTP request (I'd say closer login and logout) but agree that the overall amount of data adds up (e.g. logging the full message) and we need to further optimize it. That said you could run at ERROR level in production if you want only that to appear or to ask this differently what would you like to see at INFO?

I think a good strategy would be to log as follows:

• INFO: minimal data for connect/disconnect and subscribe/unsubscribe events
• DEBUG: incoming messages (i.e. STOMP SEND frame) including their processing as well as messages sent to the broker
• TRACE: outgoing messages to clients as well as all other messages (heartbeats, acks)

Incoming messages are less likely to flood the logs. They represent requests to the application to do something. Outgoing messages (broadcasts) on the other hand reach a high volume very quickly and so do things like heartbeats. To make that practically usable we'd probably need to add some kind of additional filtering that logs messages from specific clients or sessions.

Comments?

[spring-projects-issues]

Prashant Deva commented

i believe the connect messages were logged in 4.0.5 too, not just 4.1.

as for incoming vs outgoing, that depends on the application.
our application is a broadcaster so it mostly does outgoing, thus your assumption holds true in this case.
But any application where the user is constantly sending data, the opposite can very easily hold true.

[spring-projects-issues]

Rossen Stoyanchev commented

i believe the connect messages were logged in 4.0.5 too, not just 4.1.

No, I just double checked in the 4.0.x branch with git grep logger\.info spring-messaging and git grep logger\.info spring-websocket to make sure of that.

But any application where the user is constantly sending data, the opposite can very easily hold true.

Still this is at DEBUG level. That's the level at which I am most likely to run in development. Indeed in production that can add up quite a bit but I don't expect anyone at DEBUG in production for long. It does point out that some filters (dynamically set via JMX for example) may be useful there as well for actually debugging specific issues in production.

I'll let you know when something is available to see if it looks more manageable.

[spring-projects-issues]

Rossen Stoyanchev commented

This should now be resolved in the latest 4.1 snapshot with the following commit. You will find almost nothing logged at INFO but at DEBUG level the logs should still be manageable (and more compact than before). Also note that #16361 is now also resolved (and therefore also #16547). Please do give these a try, thanks.

[spring-projects-issues]

Prashant Deva commented

thanks rossen!