Logging with google-cloud-logging-logback is not grouping request logs

[mgenov]

Environment details

1. Logging
2. OS type and version: Linux
3. Java version: 11
4. google-cloud-java version(s): 0.103.0-alpha

Steps to reproduce

Code example

class TraceLoggingEnhancer : LoggingEnhancer {
  override fun enhanceLogEntry(builder: LogEntry.Builder) {
    val req = HttpContext.get() ?: return
    val projectId = ServiceOptions.getDefaultProjectId();
    val spanId = req.headers("x-b3-spanid")
    val traceId = req.headers("x-b3-traceid")

    builder.setHttpRequest(HttpRequest.newBuilder()
            .setRequestUrl(req.url())
            .setStatus(200)
            .setUserAgent(req.userAgent())
            .setRequestMethod(HttpRequest.RequestMethod.valueOf(req.requestMethod()))
            .build())

    builder.setTrace(composeFullTraceName(projectId, traceId))
    builder.setSpanId(spanId)
  }

  private fun composeFullTraceName(projectId: String, traceId: String): String {
    return "projects/$projectId/traces/$traceId";
  }

}

Any additional information below

The log lines: line1 and line2 are not rendered as single log entry as on GAE or on Flexible Environment.

[codyoss]

Thanks for the report @mgenov. Could you please provide me with an example of how you are producing your log entries as well as what compute product this application is running on?

[codyoss]

@mgenov Is this still an issue for you?

[codyoss]

Closing due to lack of response. Please reopen if you are still experiencing issues.

[darewreck54]

@codyoss this is still an issue. Can we reopen it?

I"m trying to setup stack driver logging for my GAE web application but i'm having issue getting the traceLoggingEnhancer provided by google to work properly.

Library: https://github.com/googleapis/google-cloud-java/issues/6061

I've created a repo of the example: https://github.com/darewreck54/GoogleTraceIdExample

Goal: I wanted to associate a trace ID with all the logs that occur from one request. In the code, i'm using dropwizard web framework hooked up with slf4j logging. From my understanding, all i need to do is create a Filter and an Appender. The filter called TraceLogFilter.java would either grab a unique ID from X_CLOUD_TRACE or generate one. It will store the ID in TraceLoggerEnhancer.setCurrentTraceId() which every web request would hit.

I also created a log appender called ConsoleJsonAppenderFactory.java labeled with 'cloud-stackdriver'. I add this to the dropwizard equivalent of logback.xml in /config/dropWizardConfig-dev.yaml or /config/dropWizardConfig-stage.yaml.

Whenever a log was made. ex: log.INFO("test") it should trigger the log appender which would then add should call setTrace in the TraceLoggingEnhancer::enhanceLogEntry. However, when i step through the code this isn't happening. What i'm seeing is that the traceId is set to null but that part doesn't make sense unless there is some threading issue i'm not seeing.

Here is an example so that you can get a better example:

• clone repository https://github.com/darewreck54/GoogleTraceIdExample
• cd GoogleTraceIdExample
• ./gradlew build
• cd build/libs
• java -jar google_trace_example-1.0-SNAPSHOT-all.jar server ../../config/dropWizardConfig-dev.yaml
• This will run the web service. Go to http://localhost:8080/swagger and try out the end point curl -X GET "http://localhost:8080/hello-world/date" -H "accept: text/plain".
• If you look at the code, HelloWorldResource.java

@get
@path("/date")
@produces(MediaType.TEXT_PLAIN)
public String receiveDate(@QueryParam("date") Optional dateTimeParam) {
if (dateTimeParam.isPresent()) {
final DateTimeParam actualDateTimeParam = dateTimeParam.get();
LOGGER.info("Received a date: {}", actualDateTimeParam);
return actualDateTimeParam.get().toString();
} else {
LOGGER.info("TraceID: {}", TraceLoggingEnhancer.getCurrentTraceId());
LOGGER.warn("No received date");
return null;
}
}

When you trigger the endpoint without a date param, you will hit the else statement. The code first make sure the trace ID is stored and it is so it prints out the traceId. Then it triggers the LOGGER.warn. If you step through the code it hits the the TraceLoggingEnhancer::enhanceLogEntry(). In this it tries to get the traceId, but it's null. As a result, it never gets added to the log message. This is the part that doesn't make sense to me because prior to this I retrieved the traceId correctly and it wasn't null.

The only thing that I can think is somehow they are on different threads and it's not clear how you are support set it up properly.

Filter https://github.com/darewreck54/GoogleTraceIdExample/blob/master/src/main/java/com/example/google_trace_example/filter/TraceLogFilter.java

log coniguration: https://github.com/darewreck54/GoogleTraceIdExample/blob/master/config/dropWizardConfig-dev.yaml

Customer Logger: https://github.com/darewreck54/GoogleTraceIdExample/blob/master/src/main/java/com/example/google_trace_example/logger/ConsoleJsonAppenderFactory.java.

Documentation is really limiting to so it's hard to figure out what is suppose to be correct.

Existing doc: https://cloud.google.com/logging/docs/setup/java#jul_config

[codyoss]

@darewreck54 Thank you for your detailed report.

[codyoss]

cc @chingor13

[simonz130]

Logback is using AsyncAppenderWorker threads (different threads than what's handling incoming requests).

So when incoming request comes in, the traceId is set in customer's TraceLogFilter code on the thread that handles that request. It uses Google's TraceLoggingEnhancer to set the TraceId. TraceLoggingEnhancer stores its data in thread local storage, so the same traceId is available in all getCurrentTraceId calls that happen on the same thread. However when log entry is sent with logback to the appenders and is being enhanced (in our case, with traceId), it's done on a different thread (AsyncAppenderWorker) than the one that is handling the incoming request. Therefore, TraceLoggingEnhancer.getCurrentTraceId will return null when called in AsyncAppenderWorker. When enhancing the log entry with labels, there is no request-specific information that is meant to be there, so the problem is not relevant.

In order to allow enriching the log entry with traceId or any other request specific info, we need to provide a callback on the library side that's running on a user thread instead of the logback thread. This is a new feature, not a bug in existing functionality, which we plan to address soon.

[darewreck54]

@simonz130 Thanks for the clarification. Whats the ETA for this new feature and is there something I can subscribe to so that I can follow it?

Just out of curiosity what was the intention of the usage of TraceLoggingEnhancer. I figured that being able to associate a traceId generated from a request would be a common use case. Am I using it incorrectly?

[asodja]

I played with this before I saw this issue. And it seems that it works if you implement LoggingEventEnhancer and you pass trace id to MDC. You can access MDC from ILoggingEvent e in enchancer like e.getMDCPropertyMap().get("your-trace-id-key"). You can register LoggingEventEnhancer like:

<appender name="CLOUD" class="com.google.cloud.logging.logback.LoggingAppender">
    <loggingEventEnhancer>org.example.logging.MyLoggingEventEnhancer</loggingEventEnhancer>
    ...
</appender>

But I tried with just few requests and not with a lot of traffic.

Hope this helps.

[zmeggyesi]

While a roundabout way, what @asodja proposes is, in fact, the solution.

At the start of your request, you need to grab the x-cloud-trace-context header's value from the request, retrieve the project ID, and add the resulting trace ID to your MDC, with something like MDC.put("logging.googleapis.com/trace", String.format("projects/%s/traces/%s", project, traceId)).
StackDriver will then automatically collate all loglines with the same trace ID under the initial request that spawned the entry.

[zmeggyesi]

@pouyanjazayeri Thanks for collecting the full solution - eventually, I arrived at the same conclusion and it's been running fine for a year now.

The only pain point is that it requires a Filter and an MDC to work, and not out-of-the-box like the previous versions.
Also, once you group the logs like this, you cannot filter them! Example: I have three separate logs, one for my framework, one for the app code, and one for Objectify (which has been throwing me for loops too, hence its debug logging); once you open the reuqest_log in Stackdriver, you will not be able to drop/hide the Objectify logs.

[pouyanjazayeri]

adding the solution again since I deleted it by mistake:

add the following to your logback config file:

    <appender name="CLOUD" class="com.google.cloud.logging.logback.LoggingAppender">
        <resourceType>gae_app_standard</resourceType>
        <loggingEventEnhancer>com.google.cloud.logging.logback.TraceLoggingEventEnhancer</loggingEventEnhancer>
       <log>appengine.googleapis.com/request_log</log>
      .....
    </appender>

the use an http filter to set the trace in the MDC:

package com.example.appengine.springboot;


import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;
 
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import org.slf4j.MDC; 

@Component
public class TraceFilter extends OncePerRequestFilter {
 
    @Override
    protected void doFilterInternal(HttpServletRequest httpServletRequest,
                                    HttpServletResponse httpServletResponse,
                                    FilterChain filterChain)
                                    throws ServletException, IOException {
        String traceId = httpServletRequest.getHeader("x-cloud-trace-context");
        String trace = String.format("projects/%s/traces/%s", "YOUR_PROJECT_ID", traceId.split("/")[0]);
        MDC.put("logging.googleapis.trace", trace);
        filterChain.doFilter(httpServletRequest, httpServletResponse);
    }
}

replace YOUR_PROJECT_ID with your actual project id. Note that only the first part before "/" is used from the x-cloud-trace-context header.

Now the logs should be grouped in the request log.