SAP / cf-java-logging-support

The Java Logging Support for Cloud Foundry supports the creation of structured log messages and the collection of request metrics
Apache License 2.0
76 stars 46 forks source link

remote_user does not get set in the request logs #138

Closed Nils-Michelberger closed 2 years ago

Nils-Michelberger commented 2 years ago

Hello, So I am trying to get the remote_user to show up in the request logs, but I can only make them show up in the application logs. I have implemented a RemoteUserFilter similar to this one: https://github.com/SAP/cf-java-logging-support/issues/122#issuecomment-993678889 I have also set the environment variable LOG_REMOTE_USER to true. I also tried out to add the @Order() annotation with a high number so the filter gets executed last but still, the remote_user is not getting set in the request logs.

PS: I also checked the request headers and remote_user is not empty in there (but has a bad format because of CF but that is not a big problem). And I also checked the environment variable LOG_REMOTE_USER to make sure it is set to true.

Is there anything else I can try out or does anyone know what I am doing wrong?

KarstenSchnitter commented 2 years ago

Hello,

thanks for reporting this issue. Currently the remote user in the request log is hard set to the value from the HttpServletRequest: https://github.com/SAP/cf-java-logging-support/blob/6e400379fd81c3ea9ce5712b3453551cb2455bdc/cf-java-logging-support-servlet/src/main/java/com/sap/hcp/cf/logging/servlet/filter/RequestRecordFactory.java#L35 The MDC value set by the LogContext in the linked example is ignored for the request logs. The easiest way to change the remote user would be to use a small servlet filter before the RequestLoggingFilter, that wraps the original request and returns the desired value, when request.getRemoteUser() is called.

Will that be a possible solution to your problem?

Nils-Michelberger commented 2 years ago

Hello,

Thanks for the quick answer.

Okay, that sounds like a possible solution. Just for clarification: I create a small filter kind of like this:

public void doFilter(ServletRequest request, ServletResponse response, 
    FilterChain chain) throws IOException, ServletException {
  HttpServletRequest adjustedRequest = adjustRemoteUser((HttpServletRequest) request);
  chain.doFilter(adjustedRequest, response);
}

And in the method adjustRemoteUser(...) I then wrap the request with a HttpServletRequestWrapper where I can change the getRemoteUser() method to return the expected value. With chain.doFilter(adjustedRequest, response); I make sure that I will pass on the adjustedRequest?

How do I make sure that my wrapper filter is before the RequestLoggingFilter but also doesn't mess up any other filters? Just give the RequestLoggingFilter a really high order number (e.g. Integer.MAX_VALUE) and then the wrapper filter one number lower (e.g. Integer.MAX_VALUE - 1)?

KarstenSchnitter commented 2 years ago

Hi,

Using the HttpServletRequestWrapper (or the ServletRequestWrapper if necessary) should not have an impact on downstream filters. With the order number you most likely have to take the Spring Security Filter into account. Do you need to pass through that first, to get the remote user in the first place? Then you need to put your new filter and the RequestLoggingFilter afterwards. If you want to log unauthorised request, you need to put both before.

Best Regards, Karsten

Nils-Michelberger commented 2 years ago

Hello,

I tried it out now and when I now call the getRemoteUser() method I get the correct value.

But it still doesn't set it in the request. I feel like the request_user is never empty, but the logging for the request skips this value. This sounds like the environment variable LOG_REMOTE_USER is not set to true, but it is, checked it multiple times.

Do you know of any possible problem why he skips the remote_user or anything I can try out?

KarstenSchnitter commented 2 years ago

Do you have the filters in the correct ordering? First wrap the request to report your value, then have the RequestLogFilter. Can you test that locally, where you can set a breakpoint in line 35 of the RequestRecordFactory (code line linked above)?

Nils-Michelberger commented 2 years ago

Hmmmmm interesting, I tried setting the breakpoint, but it never gets there. It always stops in this if: https://github.com/SAP/cf-java-logging-support/blob/6e400379fd81c3ea9ce5712b3453551cb2455bdc/cf-java-logging-support-servlet/src/main/java/com/sap/hcp/cf/logging/servlet/filter/GenerateRequestLogFilter.java#L61-L64 That means Request Logging is not enabled, I guess? How can I enable it?

EDIT: PS: Filters should be in the correct order

KarstenSchnitter commented 2 years ago

You will find, that the request logging can be disabled by configuring the log-level of the RequestLogger to something stricter than INFO. If your root log level is WARN you will need to set the log-level to INFO to get request logs. See the documentation section on disabling the request logs.

Nils-Michelberger commented 2 years ago

I have changed the log-level to INFO and now I finally have the remote_user in the request logs. Thank you so much!

But I now have an issue that the request logs are doubled. Do you know where this could come from?

EDIT: Sometimes even tripled. With two of them having the correct remote_user and one of them not having the remote_user. When doubled one has the remote_user and the other one not.

KarstenSchnitter commented 2 years ago

Take a look at the source_type. You will find, that one of the request logs is from the CF Gorouter and one from your application. Since the Gorouter (central load-balancer of CloudFoudry) does not know about your custom logic, it cannot log a remote_user. This issue is actually depending on your CloudFoundry platform and not this library. Please reach out to your platform about this ;-)

Nils-Michelberger commented 2 years ago

Hmmmm okay I see. One is from RTR and the other one is from APP/PROC/WEB (this one shows the remote_user). What do you mean with custom logic? I disabled the filters and I got the "long-rerouted" remot_user name, so it shouldn't be that custom, right? Or is enabling the remote_user already "too" custom. But I see, this is a problem with the platform. With platform, you mean e.g. SAP BTP right? You don't know how to resolve this issue in SAP BTP by chance? :)

Thanks again soo much for helping me out here. Already got so much further!

PS: As soon as I add this line

<Logger name="com.sap.hcp.cf.logging.servlet.filter.RequestLogger" level="INFO"/>

I get the additional logs (but with the correct remote_user). ROOT level is also on info.

KarstenSchnitter commented 2 years ago

Calling request.getRemoteUser() is already logic, the CF Gorouter does not contain. For SAP BTP I can give you a hand. Please reach out directly. that discussion should not be in public Github. Disabling the Gorouter logs is a platform setting, that applications usually cannot influence.

Nils-Michelberger commented 2 years ago

Ah okay, yes I agree. I will reach out to you directly. Thanks.