Missing server request logs from DropWizard application

[railsharipov]

The issue: I don't see any server request logs being delivered to OTel receiver.

I am running Dropwizard app with OTel Contrib Java agent. I am running agent with default config, I have otlp log export enabled. I do see logs from application loggers (logback) but no server request logs.

As far as I can tell Dropwizard uses Jetty http server. According to docs, Dropwizard uses the logback-access library for processing request logs.

Here is my Dropwizard HTTP server config:

server:
  type: simple
  ...
  gzip:
    bufferSize: 8KiB
    enabled: true
    minimumEntitySize: 128B
    deflateCompressionLevel: 9
  requestLog:
    appenders:
      - type: console

Here is my Dropwizard logging config:

logging:
  level: INFO
  loggers:
    ...
  appenders:
    - type: console
      threshold: TRACE
      timeZone: "UTC"
      logFormat: ...

Here is the docker image I use to run app:

FROM amzn-corretto:17-alpine
...
ENV OTEL_LOG_LEVEL=error
ENV OTEL_JAVAAGENT_LOGGING=simple

ENV OTEL_LOGS_EXPORTER=otlp
ENV OTEL_EXPORTER_OTLP_LOGS_ENDPOINT=http://otlp.example.com/v1/logs
ENV OTEL_EXPORTER_OTLP_LOGS_PROTOCOL=http/protobuf

ENV OTEL_SERVICE_NAME=example

CMD exec java \
    -javaagent:opentelemetry-javaagent.jar \
    -jar /opt/example/example-shadow.jar server /etc/example/config.yml

When I run app locally, I can see request logs being printed to the console. I have enabled detailed debug logs on OTel collector side and see no incoming events containing request logs.

dropwizardVersion = "2.1.0"

Please advice.

[trask]

I do see logs from application loggers (logback) but no server request logs.

can you include examples of the server request logs? are those coming directly from Jetty? can you identify which logging library those are using?

[railsharipov]

Thank you for responding. I have put another breakpoint:

log:132,%20RequestLogImpl%20(ch.qos.logback.access.jetty)%0AonCompleted%3A911,%20HttpChannel%20(org.eclipse.jetty.server)%0Ahandle%3A467,%20HttpChannel%20(org.eclipse.jetty.server)%0AonFillable%3A277,%20HttpConnection%20(org.eclipse.jetty.server)%0Asucceeded%3A311,%20AbstractConnection$ReadCallback%20(org.eclipse.jetty.io)%0Afillable%3A105,%20FillInterest%20(org.eclipse.jetty.io)%0Arun%3A104,%20ChannelEndPoint$1%20(org.eclipse.jetty.io)%0ArunJob%3A883,%20QueuedThreadPool%20(org.eclipse.jetty.util.thread)%0Arun%3A1034,%20QueuedThreadPool$Runner%20(org.eclipse.jetty.util.thread)%0Arun%3A840,%20Thread%20(java.lang)

So it’s actually log back after all: RequestLogImpl (ch.qos.logback.access.jetty)

[trask]

this is the method that the Java agent instruments:

opentelemetry-java-instrumentation/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackInstrumentation.java

Lines 27 to 41 in 3c48d85

	@Override
	public ElementMatcher<TypeDescription> typeMatcher() {
	return named("ch.qos.logback.classic.Logger");
	}
	@Override
	public void transform(TypeTransformer transformer) {
	transformer.applyAdviceToMethod(
	isMethod()
	.and(isPublic())
	.and(named("callAppenders"))
	.and(takesArguments(1))
	.and(takesArgument(0, named("ch.qos.logback.classic.spi.ILoggingEvent"))),
	LogbackInstrumentation.class.getName() + "$CallAppendersAdvice");
	}

can you see if it flows through there, or through a different method in ch.qos.logback.classic.Logger?

[railsharipov]

I think I was able to trace it down to the following method call: ch.qos.logback.core.OutputStreamAppender.append()

append:102, OutputStreamAppender (ch.qos.logback.core)
doAppend:84, UnsynchronizedAppenderBase (ch.qos.logback.core)
appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi)
run:290, AsyncAppenderBase$Worker (ch.qos.logback.core)
...
append:160, AsyncAppenderBase (ch.qos.logback.core)
doAppend:84, UnsynchronizedAppenderBase (ch.qos.logback.core)
appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi)
log:137, RequestLogImpl (ch.qos.logback.access.jetty)
onCompleted:911, HttpChannel (org.eclipse.jetty.server)
handle:467, HttpChannel (org.eclipse.jetty.server)
onFillable:277, HttpConnection (org.eclipse.jetty.server)
succeeded:311, AbstractConnection$ReadCallback (org.eclipse.jetty.io)
fillable:105, FillInterest (org.eclipse.jetty.io)
run:104, ChannelEndPoint$1 (org.eclipse.jetty.io)
runJob:883, QueuedThreadPool (org.eclipse.jetty.util.thread)
run:1034, QueuedThreadPool$Runner (org.eclipse.jetty.util.thread)
run:840, Thread (java.lang)

I set break points both for ch.qos.logback.classic.Logger methods and ch.qos.logback.core.OutputStreamAppender.

When request logs are being printed in the console the trace does not go through ch.qos.logback.classic.Logger, it goes only through ch.qos.logback.core.OutputStreamAppender.

For other logs (not request logs) trace goes through ch.qos.logback.classic.Logger and ch.qos.logback.core.OutputStreamAppender.

[trask]

this is interesting, it goes through ch.qos.logback.access.jetty.RequestLogImpl

I looked that up and found https://logback.qos.ch/access.html:

It should be noted that while logback-access requires logback-core, it is independent of logback-classic as well as slf4j

which would explain the issue, since the OpenTelemetry instrumentation applies specifically to logback-classic

[railsharipov]

Thank you for your help. Would you recommend creating an issue referring this discussion?

[trask]

yeah, sounds good

[railsharipov]

Apparently, there is way to use classic logger for request logs: https://www.dropwizard.io/en/release-2.1.x/manual/configuration.html#classic-request-log

I have used following configuration for request logging this time:

server:
  requestLog:
    type: classic
    timeZone: UTC
    appenders:
      - type: console

But I'm still not seeing request log being delivered to OTel collector (nothing in debug logs for collector mentions request logs).

I see that trace is now different, I can observe the message being set as well:

setMessage:225, LoggingEvent (ch.qos.logback.classic.spi)
write:29, DropwizardSlf4jRequestLogWriter (io.dropwizard.request.logging.old)
log:339, CustomRequestLog (org.eclipse.jetty.server)
onCompleted:911, HttpChannel (org.eclipse.jetty.server)
handle:467, HttpChannel (org.eclipse.jetty.server)
onFillable:277, HttpConnection (org.eclipse.jetty.server)
succeeded:311, AbstractConnection$ReadCallback (org.eclipse.jetty.io)
fillable:105, FillInterest (org.eclipse.jetty.io)
run:104, ChannelEndPoint$1 (org.eclipse.jetty.io)
runJob:883, QueuedThreadPool (org.eclipse.jetty.util.thread)
run:1034, QueuedThreadPool$Runner (org.eclipse.jetty.util.thread)
run:840, Thread (java.lang)

I can observe event being appended:

getFormattedMessage:289, LoggingEvent (ch.qos.logback.classic.spi)
prepareForDeferredProcessing:206, LoggingEvent (ch.qos.logback.classic.spi)
preprocess:43, AsyncAppender (ch.qos.logback.classic)
preprocess:28, AsyncAppender (ch.qos.logback.classic)
append:160, AsyncAppenderBase (ch.qos.logback.core)
doAppend:84, UnsynchronizedAppenderBase (ch.qos.logback.core)
appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi)
write:32, DropwizardSlf4jRequestLogWriter (io.dropwizard.request.logging.old)
log:339, CustomRequestLog (org.eclipse.jetty.server)
onCompleted:911, HttpChannel (org.eclipse.jetty.server)
handle:467, HttpChannel (org.eclipse.jetty.server)
onFillable:277, HttpConnection (org.eclipse.jetty.server)
succeeded:311, AbstractConnection$ReadCallback (org.eclipse.jetty.io)
fillable:105, FillInterest (org.eclipse.jetty.io)
run:104, ChannelEndPoint$1 (org.eclipse.jetty.io)
runJob:883, QueuedThreadPool (org.eclipse.jetty.util.thread)
run:1034, QueuedThreadPool$Runner (org.eclipse.jetty.util.thread)
run:840, Thread (java.lang)

I can observe the message being printed to console:

append:98, OutputStreamAppender (ch.qos.logback.core)
doAppend:84, UnsynchronizedAppenderBase (ch.qos.logback.core)
appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi)
run:290, AsyncAppenderBase$Worker (ch.qos.logback.core)

Does that mean that logback-core has to be instrumented?