Log Tenant ID with custom Filter

Hi colleagues,

In our project, we are using the SAP's XSUAA Library to parse JWT Tokens. We want to add a custom Filter to add the Zone ID to the LogContext. Our implementation, aligned on what your sample application does, looks like this:

@Configuration
class LoggingConfiguration {
  private static final Logger LOGGER = LoggerFactory.getLogger(LoggingConfiguration.class);
  private static final Marker MARKER = LoggingMarker.LOGGING.getMarker();

  /**
   * Adds a servlet filter which extracts the correlation id from the request
   * header and adds it to the log context. Filter is set to be applied last
   * (after spring security filter chain)
   */
  @Bean
  public FilterRegistrationBean<Filter> loggingFilter() {
    final FilterRegistrationBean<Filter> filterRegistrationBean = new FilterRegistrationBean<>();
    filterRegistrationBean.setFilter(new LoggingFilter());
    filterRegistrationBean.setName("request-logging");
    filterRegistrationBean.addUrlPatterns("/*");
    filterRegistrationBean.setDispatcherTypes(DispatcherType.REQUEST);
    filterRegistrationBean.setOrder(Integer.MAX_VALUE);
    return filterRegistrationBean;
  }

  private static class TenantIdFilter extends AbstractLoggingFilter {
    @Override
    protected void beforeFilter(HttpServletRequest request, HttpServletResponse response) {
      try {
        String tenantId = SpringSecurityContext.getToken().getZoneId();
        LogContext.add(Fields.TENANT_ID, tenantId);
      } catch (AccessDeniedException ade) {
        LOGGER.info(MARKER, "tenant_id not available, so not written to log context: {}", ade.getMessage());
      }
    }

    @Override
    protected void cleanup(HttpServletRequest request, HttpServletResponse response) {
      LogContext.remove(Fields.TENANT_ID);
    }
  }

  private static class LoggingFilter extends CompositeFilter {
    public LoggingFilter() {
      super(new AddVcapEnvironmentToLogContextFilter(), new AddHttpHeadersToLogContextFilter(),
          new CorrelationIdFilter(), new TenantIdFilter(), new DynamicLogLevelFilter(), new GenerateRequestLogFilter());
    }
  }
}

However, we found that the GenerateRequestLogFilter somehow overrides the tenant_id field in LogContext. Seems like the corresponding header is marked as propagated, and this line of code here overwrites the field from the headers:

cf-java-logging-support/cf-java-logging-support-servlet/src/main/java/com/sap/hcp/cf/logging/servlet/filter/RequestRecordFactory.java

Line 40 in 74ef2e7

rrb.addContextTag(header.getField(), getHeaderValue(request, header, null));

This seems strange -- we would have expected that our custom fields are not overwritten. We tried to work around this by trying to set the Header on the HttpServletRequest, but this isn't possible unless you (uglyly) subclass HttpServletRequestWrapper. We found that when we set the tenantid header on the response, though, this somehow works (as it works with the correlation id as well) -- but we don't understand why:

    @Override
    protected void beforeFilter(HttpServletRequest request, HttpServletResponse response) {
      try {
        final String tenantId = SpringSecurityContext.getToken().getZoneId();
        LogContext.add(Fields.TENANT_ID, tenantId);
        if (!response.isCommitted())
          response.addHeader(HttpHeaders.TENANT_ID.getName(), tenantId);
      } catch (AccessDeniedException ade) {
        LOGGER.info(MARKER, "tenant_id not available, so not written to log context: {}", ade.getMessage());
      }
    }

Is this intended (and stable behavior in your api)? Is there a better way to do this?
To me, it seems like addContextTag shouldn't overwrite the LogContext if a field has already been set, especially as the headers should have already been set there by the AddHttpHeadersToLogContextFilter -- but I don't know if there's something else at play here.

Thank you for your support!
Kind regards
Lukas

Hi Lukas,

Many thanks for reporting the issue and sharing your code. I will have a look into this. The idea would have been, that the TENANT_ID is populated in the AddHttpHeadersToLogContextFilter and not overwritten afterwards. I will investigate, whether something went wrong, when the separation was introduced.

Best Regards,
Karsten

I had a brief look at the code. I think that the problematic code is in the RequestRecordFactory:

public RequestRecord create(HttpServletRequest request) {
    // left out for consiseness
    for (HttpHeader header: HttpHeaders.propagated()) {
        rrb.addContextTag(header.getField(), getHeaderValue(request, header, null));
    }
    return rrb.build();
}

I can remove the entire for loop, without test failures. Actually this functionality should be done by the AddHttpHeadersToLogContextFilter. I still need to check for side-effects, if the code is removed. I also want to provide some additional unit test, that includes your example.

Best Regards,
Karsten

Cool, that's good to hear! Let me know if you need more information.

I provided #117 with a fix for this issue.

Resolved with #117