TRACE level logging of traffic

[atsu85]

Add logging sent and received AMQP messages (with TRACE level via SLF4j for debugging)

Current situation

Currently even if i have configured com.rabbitmq logger with level TRACE, then neither request nor responses are logged. Sample logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>%d{HH:mm:ss.SSS} [%thread{10}][%-5level][%file:%line]%logger{15} - %msg%n%rEx</pattern>
		</encoder>
	</appender>

	<logger name="com.rabbitmq" level="TRACE"/><!-- XXX -->
	<root>
		<level value="WARN"/>
		<appender-ref ref="CONSOLE"/>
	</root>
</configuration>

Proposal

Improve java client library, so that with TRACE level (for debugging) request and response messages would be logged.

Additional details

• Client library version: com.rabbitmq:amqp-client:5.4.3 (latest right now)

[acogoluegnes]

@atsu85 I think that's a fair request. What do you think would be useful to log?

• sent: exchange, routing key, flags (mandatory and immediate), properties, channel number, connection info (toString method).
• received: consumer tag, channel number, connection info, envelope toString, properties.

I'm just a bit concerned about logging properties that could contain sensitive information.

[lukebakken]

I'm just a bit concerned about logging properties that could contain sensitive information.

I think that someone enables trace-level logging, they should expect that everything will be shown, even if it might be sensitive.

[michaelklishin]

How about we trace what/s coming in and going out on the wire instead? That's what Bunny does.

[atsu85]

Sensitive information

@acogoluegnes:

I'm just a bit concerned about logging properties that could contain sensitive information.

@lukebakken:

I think that someone enables trace-level logging, they should expect that everything will be shown, even if it might be sensitive.

I agree. As i proposed, this additional information should be added with TRACE level, and i guess nobody should have it accidentally enabled (or if they have it accidentally enabled for this project, then it isn't the only one and they probably have bigger problems. Also, if i remember correctly, i didn't see any TRACE level logging in this project, but i might have forgotten smth).

What to log

@atsu85 I think that's a fair request. What do you think would be useful to log?

Log levels

I think what is logged could depend on the logger level (most relevant details with DEBUG, more with TRACE). I guess You could consider adding logging with INFO level as well, but IMHO that would be kind of breaking change - some projects may have INFO level turned on either globally or for only this project and then they'd get additional log entries for each AMQP message. Not difficult to change log level of specific logger, but it may still be a bad surprise.

My use-case

Personally i'm interested in seeing where the message is/was sent (exchange, routing key) and what it contains (headers and body as text if it contains textual content like json, xml or perhaps even plain text) to get an overview of what has been published/consumed. I'd use this feature to make sure that my Gatling load tests script does what i expect (running it with single user to make sure it takes some inputs from previous message and passes them to next message). My Gatling load-test publish/consume messages directly to/from Rabbit (as for production we have custom solution already in place).

Other thoughts

Regarding connection info and channel numbers - they are not so interesting for me personally. Perhaps i'm wrong but i'd guess they shouldn't matter unless there is a bug in in either server or client implementation and in that case remote debugger might be used to find out more.

@michaelklishin, @lukebakken, I trust You as authors&maintainers of this library have quite good idea of what could be logged with specific levels.

[acogoluegnes]

@atsu85 Logging the body of the message as a string implies we check properties for content-type. Not sure if we want to add this kind of logic in logging, especially if this logic is prone to errors.

@michaelklishin Thanks for the tips, we could log writes here and reads here.

Introducing an interface to log write and read AMQCommands seems an appropriate solution here. The default would be a no-op, we could provide an implementation that logs everything at trace level, and a custom one could be provided for specific stuff (logging the content of messages when possible).

[atsu85]

Proposal sounds good.

Logging the body of the message as a string implies we check properties for content-type.

Yes, i knew that, but i admit detecting if it is textual could be prone to errors

[acogoluegnes]

@atsu85 5.5.0.RC1 has shipped with the new feature. You can do as in this test to log only outbound and inbound messages.