SL4J Loggers output not present in console when using LogstashEncoder

[bjeSSAdev]

I'm using the following revelant dependecies and versions:
Spring Boot:2.7.5,
logstash-logback-encoder:7.2,
logback-json-core:0.1.5,
logback-json-classic: 0.1.5,
slf4j-api:1.7.36,
log4j-to-slf4j: 2.17.2

Our library common-event-handling just recently switched to using the slf4j framework instead of directly using log4j2. The service is using the log4j2 api but logback as the implementation.
When included one of our microservices, logs from the library appear in the console except when the nonlocal profile is active. There's no output and no errors are shown.

Here's the output from the service when not using the appender:
`2023-02-01 15:13:58.597  INFO [IRS-INTAKE-ACL:0.0.33,,,] 9044 --- [nio-8080-exec-4] g.s.i.router.EAWUTFileUploadEndpoint     : Started uploading EawutFile  ...
2023-02-01 15:13:58.597  INFO [IRS-INTAKE-ACL:0.0.33,,,] 9044 --- [nio-8080-exec-4] g.s.i.router.EAWUTFileUploadEndpoint     : EAWUTFile size : 434
2023-02-01 15:13:58.597  INFO [IRS-INTAKE-ACL:0.0.33,,,] 9044 --- [nio-8080-exec-4] g.s.i.f.EawutRecordProcessor             : Processing  2 records. override url http://172.27.123.175:11580. 
2023-02-01 15:13:58.604  INFO [IRS-INTAKE-ACL:0.0.33,,,] 9044 --- [nio-8080-exec-4] g.s.i.f.EawutRecordProcessor             : Processing completed.
**2023-02-01 15:13:58.725  INFO [IRS-INTAKE-ACL:0.0.33,,,] 9044 --- [ad | producer-1] g.s.e.e.s.c.LoggingProducerListener      : Publishing to Kafka successful; topic=TP.PIL.IRS.EARNINGS.UNREPORTED.WAGES; key={"aggregateId": -1131251976}; headers=RecordHeaders(headers = [EventHeader [key=eventType, value=gov.ssa.irsrptg.avro.UnreportedWagesDelivered], RecordHeader(key = b3, value = [49, 51, 49, 50, 55, 57, 57, 102, 54, 51, 100, 51, 97, 102, 102, 101, 45, 49, 98, 102, 99, 54, 53, 51, 101, 102, 97, 53, 51, 52, 54, 55, 99, 45, 48])], isReadOnly = true); partition=0; offset=1171; timestamp=1675282438603`**

and here's the same scenario when the net.logstash.logback.encoder.LogstashEncoder is activated

{"@timestamp":"2023-02-01T15:33:28.711(EST)","@version":"1","message":"Started uploading EawutFile  ...","logger_name":"gov.ssa.irsrptg.router.EAWUTFileUploadEndpoint","thread_name":"http-nio-8080-exec-4","level":"INFO","level_value":20000,"traceId":"79181b80b092a0fa","spanId":"79181b80b092a0fa","reqMetaData":null,"appName":"IRS-INTAKE-ACL","appVersion":"0.0.33"}
{"@timestamp":"2023-02-01T15:33:28.712(EST)","@version":"1","message":"EAWUTFile size : 434","logger_name":"gov.ssa.irsrptg.router.EAWUTFileUploadEndpoint","thread_name":"http-nio-8080-exec-4","level":"INFO","level_value":20000,"traceId":"79181b80b092a0fa","spanId":"79181b80b092a0fa","reqMetaData":null,"appName":"IRS-INTAKE-ACL","appVersion":"0.0.33"}
{"@timestamp":"2023-02-01T15:33:28.713(EST)","@version":"1","message":"Processing  2 records. override url http://172.27.123.175:10234. ","logger_name":"gov.ssa.irsrptg.fileprocessor.EawutRecordProcessor","thread_name":"http-nio-8080-exec-4","level":"INFO","level_value":20000,"traceId":"79181b80b092a0fa","spanId":"79181b80b092a0fa","reqMetaData":null,"appName":"IRS-INTAKE-ACL","appVersion":"0.0.33"}
{"@timestamp":"2023-02-01T15:33:28.723(EST)","@version":"1","message":"Processing completed.","logger_name":"gov.ssa.irsrptg.fileprocessor.EawutRecordProcessor","thread_name":"http-nio-8080-exec-4","level":"INFO","level_value":20000,"traceId":"79181b80b092a0fa","spanId":"79181b80b092a0fa","reqMetaData":null,"appName":"IRS-INTAKE-ACL","appVersion":"0.0.33"}

The revelant Logger is LoggingProducerListener which is created in the library that the service is using. As you can see the output is not present and there is no error sent to the console either.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.kafka.support.ProducerListener;

public class LoggingProducerListener
        implements ProducerListener<SpecificRecord, SpecificRecord> {

    private static final Logger LOGGER = LoggerFactory
            .getLogger(LoggingProducerListener.class);

    @Override
    public void onSuccess(ProducerRecord<SpecificRecord, SpecificRecord> producerRecord,
            RecordMetadata recordMetadata) {

        LOGGER.info("Publishing to Kafka successful; {}; {}; {}; {}; {}; {}",
                keyValue("topic", producerRecord.topic()),
                keyValue("key", producerRecord.key()),
                keyValue("headers", producerRecord.headers()),
                keyValue("partition", recordMetadata.partition()),
                keyValue("offset", recordMetadata.offset()),
                keyValue("timestamp", recordMetadata.timestamp()));

    }

logback-spring.xml

<!DOCTYPE xml>
<configuration>
	<property resource="application.properties" />
	<property name="LOG_LEVEL" value="INFO" />
	<property name="LOG_LEVEL_PATTERN" value="%5p [${spring.application.name}:${app.version},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]" />
	<property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
	

	<springProfile name="local">
		<!-- use Spring default values -->
    	<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
	
		<appender name="consoleAppender"
			class="ch.qos.logback.core.ConsoleAppender">
			<layout class="ch.qos.logback.classic.PatternLayout">
				<!-- Add %M %line to pattern to get method and line number -->
				<Pattern>
					<!--  %d{yyyy-MM-dd'T'HH:mm:ss.SSS, America/New_York} [%thread] [TraceId:%X{X-B3-TraceId:-}] %X{reqMetaData} %-5level %logger - %msg%n -->
					${CONSOLE_LOG_PATTERN}
				</Pattern>
			</layout>
		</appender>
		<root level="INFO">
			<appender-ref ref="consoleAppender" />
		</root>
	</springProfile>

	<springProfile name="!local">
	
		<!-- use Spring default values -->
    	<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
		<appender name="jsonAppender"
			class="ch.qos.logback.core.ConsoleAppender">
			
			
			

			<encoder class="net.logstash.logback.encoder.LogstashEncoder">
				MDC
				Exclude MDC Key 'reqMetaData' directly adding to JSON
				<excludeMdcKeyName>reqMetaData</excludeMdcKeyName>
				Customize MDC Key 'reqMetaData' data to log as JSON Note: Value 
					set to 'reqMetaData' in MDS should be JSON string
				<provider
					class="net.logstash.logback.composite.loggingevent.LoggingEventPatternJsonProvider">
					<pattern>{"reqMetaData": "#asJson{%mdc{reqMetaData}}"}</pattern>
				</provider>
				Include Custom Fields
				<customFields>{
					"appName":"${spring.application.name}",
					"appVersion":"${app.version}"
					}
				</customFields>

				Customize fields
				<timeZone>US/Eastern</timeZone>
				<timestampPattern>yyyy-MM-dd'T'HH:mm:ss.SSS(zzz)</timestampPattern>
				<includeContext>false</includeContext>
				<throwableConverter
					class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
					<exclude>sun\.reflect\..*\.invoke.*</exclude>
					<exclude>net\.sf\.cglib\.proxy\.MethodProxy\.invoke</exclude>
					<rootCauseFirst>true</rootCauseFirst>
					<inlineHash>true</inlineHash>
				</throwableConverter>
				Note: For Masking specific fields future refer this version 6.3 
					(not in NEXUS Repo as of 12/04/2019): net.logstash.logback.decorate.mask.MaskingJsonGeneratorDecorator
			</encoder>
		</appender>

		<root level="INFO">
			<appender-ref ref="jsonAppender" />
		</root>
	<!-- 			

		
	</springProfile>


</configuration>

[philsttr]

Hi @bjeSSAdev

To help debug, please enable logback's status listener, and run your example again to see if any status messages are output on the console.

[bjeSSAdev]

This allowed me to diagnose the error which led to it being Jackson unable to serialize the SpecificRecord type.
producerRecord.key() returns type SpecificRecord. Jackson attemps to serialize this lead to an m.fasterxml.jackson.databind.JsonMappingException: Not an array: ommited for brevity... (through reference chain: gov.ssa.irsrptg.avro.UnreportedWagesKey["schema"]->org.apache.avro.Schema$RecordSchema["elementType"]). This is identified in the following Stack Overflow question: https://stackoverflow.com/a/68087222

I solved it by passing the string presentation of the object which Jackson has no issue encoding.

    @Override
    public void onSuccess(ProducerRecord<SpecificRecord, SpecificRecord> producerRecord,
            RecordMetadata recordMetadata) {

        String keyString = getKeyAsString(producerRecord);
        
        LOGGER.info("Publishing to Kafka successful; {}; {}; {}; {}; {}; {}",
                keyValue("topic", producerRecord.topic()),
                keyValue("key", keyString),
                keyValue("headers", producerRecord.headers()),
                keyValue("partition", recordMetadata.partition()),
                keyValue("offset", recordMetadata.offset()),
                keyValue("timestamp", recordMetadata.timestamp()));

    }