Logging Suggestion

[Sam-Kruglov]

I propose that out-of-the-box, all messages are logged like this:

• Command payloads at DEBUG
• User-friendly events at INFO
• Event payloads at DEBUG
• Query payloads at TRACE
• Query
• return values at TRACE

I think that would be in-line with "convention over configuration".

I think a well placed LoggingInterceptor, potentially adjusted to chance logging levels, covers this point already.

(c) @smcvb AxonFramework/extension-tracing#15

Here is how I'm doing it here:

@Bean
fun eventLogger(tracer: Tracer): MessageDispatchInterceptor<EventMessage<*>> {
    return MessageDispatchInterceptor {
        BiFunction { _, event ->
            try {
                val description = (event.payload as Describable).description()
                log.info("[${tracer.id()}]: $description")
                if (log.isDebugEnabled) {
                    log.debug("[${tracer.id()}]: ${event.payload}")
                }
            } catch (e: ClassCastException) {
                log.error("[${tracer.id()}]: ${event.name()} " +
                        "does not implement ${Describable::class.simpleName}")
                log.info("[${tracer.id()}]: ${event.payload}")
            }
            event
        }
    }
}

@Bean
fun commandLogger(tracer: Tracer): MessageDispatchInterceptor<CommandMessage<*>> {
    return MessageDispatchInterceptor {
        BiFunction { _, command ->
            if (log.isDebugEnabled) {
                log.debug("[${tracer.id()}]: ${command.payload}")
            }
            command
        }
    }
}

@Bean
fun queryLogger(tracer: Tracer): MessageDispatchInterceptor<QueryMessage<*, *>> {
    return MessageDispatchInterceptor {
        BiFunction { _, query ->
            if (log.isTraceEnabled) {
                val payload = query.payload.toString()
                log.trace("[${tracer.id()}]: $payload")
            }
            query
        }
    }
}

@Bean
fun queryLoggerReturnValue(tracer: Tracer): MessageHandlerInterceptor<QueryMessage<*, *>> {
    return MessageHandlerInterceptor { unitOfWork, chain ->
        if (!log.isTraceEnabled) {
            return@MessageHandlerInterceptor chain.proceed()
        }
        val span = tracer.activeSpan()!!
        val traceId = span.context().toTraceId()
        val logAction: (Any?) -> Unit = {
            //fixme sometimes we can't see payload in the ui, maybe span is finished earlier then the future?
            span.setTag("axon.return.message.payload", it.toString())
            log.trace("[$traceId]: ${unitOfWork.message.payloadType.simpleName} returned: $it")
        }
        val returnValue: Any? = chain.proceed()
        if (returnValue == null) {
            logAction(null)
            return@MessageHandlerInterceptor returnValue
        }
        if (returnValue is CompletableFuture<*>) {
            returnValue.thenAccept(logAction)
        } else {
            logAction(returnValue)
        }
        return@MessageHandlerInterceptor returnValue
    }
}

[smcvb]

What's your feel with enhancing the LoggingInterceptor to specify these levels per type of message, making it configurable through a builder to provide more flexibility, and to configure this interceptor by default, @Sam-Kruglov?

[Sam-Kruglov]

Sorry for the late response.
I see, so you want to have a single big MessageHandlerInterceptor with a bunch of instanceOf to see what type of message it is and to be able to configure the logging levels of each thing I mentioned here. I see no problem with that, we would only need to make sure to check logger.is[Debug/Trace/Info]Enabled somehow to avoid calling toString() and other expensive methods for no reason.

[smcvb]

Moving issue to release 4.8.0 in favor of time we need to spent on releasing 4.7.0

[smcvb]

We do not envision having sufficient time to work on this before our intended release of 4.8.0.
Added, we aim to direct our attention to the following major release.
Due to this, it is unclear at this stage when the issue will be resolved.