Blog

Blog

Neues aus unserem Blog

Request-Logging mit JAX-RS und Jersey

Jochen Just Donnerstag, 24. März 2016 @ 09:12 geschrieben von Jochen Just

Entwickelt man mit Jersey ein Backend, kann man auf die Idee kommen, jeden Request Loggen zu wollen. Passenderweise geht das mit Jersey-Bordmitteln: Und zwar mit Hilfe des LoggingFilters.

public class RequestLoggingApplication extends Application {
...
   public Set<Object> singletons () {
      final Set<Object> singletons = new HashSet<> ();
      ...
      singletons.add(new LoggingFilter ());
      ...
     return singletons;
   }
}
...

Dessen Ausgabe sieht folgendermaßen aus:

14:38:08.630 [qtp634210724-18] mdc: INFO LoggingFilter - 1
    * Server has received a request on thread qtp634210724-18
1 > GET http://localhost:8080/jersey-request-logging/sample1
1 > Accept: */*
1 > Host: localhost:8080
1 > User-Agent: curl/7.35.0
14:38:08.640 [qtp634210724-18] mdc: INFO Sample1Resource
    - Sample1Resource.get.
14:38:08.647 [qtp634210724-18] mdc: INFO LoggingFilter - 1
    * Server responded with a response on thread qtp634210724-18
1 < 200
1 < Content-Type: text/plain

So steht alles über den Request im Log und man kann sogar die HTTP-Entities des Requests oder der Response ausgeben lassen (Siehe Javadocs von LoggingFilter).

Großartig. Fertig.

Nun gut, fast.

Das Ganze hat zwei Probleme:

  1. Man kann den Inhalt der Ausgabe nicht beeinflussen. Auf den ersten Blick ist das nicht schlimm. Aber falls z.B. plötzlich Passwörter geloggt werden, ist es schon ein Problem. Ich persönlich mag auch die Zeilenumbrüche nicht.
  2. Man kann den Zeitpunkt, wann geloggt wird, nicht beeinflussen.

Gerade der letztere Fall machte mir in einem Projekt Probleme. Dort kam SLF4J zum Einsatz und ich brauchte Inhalt aus dem Mapped-Diagnostic-Context (MDC) in der Ausgabe. Der ist zu dem Zeitpunkt, zu dem LoggingFilter aktiv wird, aber entweder noch nicht gefüllt (Request) oder bereits wieder geleert (Response). Das kann man an obiger Ausgabe daran erkennen, dass hinter mdc: nur ein Leerzeichen, aber kein Inhalt kommt.

Was könnten Alternativen sein:

ServletFilter

Eine klassischer ServletFilter hat das gleiche Problem wie die LoggingFilter-Lösung. Der Filter läuft, bevor Jersey überhaupt zum Zuge kommt. Ergo fehlen auch dort die Daten des MDCs.

Aufrufzeitpunkt des LoggingFilter beeinflussen

Um den Zeitpunkt des Aufrufs zu beeinflussen, wäre folgendes Konstrukt denkbar:

@Priority(Integer.MAX_VALUE)
// hierüber sorgt man dafür, dass der Aufruf nach dem
// ContainerRequestFilter kommt, der den MDC befüllt.
public class PrioritizedLoggingFilter implements ContainerRequestFilter, 
   ContainerResponseFilter, WriterInterceptor
{
   // Per Delegation. Vererbung scheidet aus, da LoggingFilter final ist.
   private final LoggingFilter delegate = new LoggingFilter();
   public void filter(ContainerRequestContext requestContext, 
         ContainerResponseContext responseContext) throws IOException {
      delegate.filter(requestContext, responseContext);
   }
   public void filter(ContainerRequestContext context) throws IOException {
      delegate.filter(context);
   }
   public void aroundWriteTo(WriterInterceptorContext writerInterceptorContext)
         throws IOException, WebApplicationException {
      delegate.aroundWriteTo(writerInterceptorContext);
   }
}

Dann sieht die Ausgabe so aus (man beachte, dass nun ein Wert hinter mdc: steht):

15:59:12.694 [qtp1046302571-14] mdc:MDC-Value INFO  LoggingFilter - 1 
    * Server has received a request on thread qtp1046302571-14
1 > GET http://localhost:8080/jersey-request-logging/sample1
1 > Accept: */*
1 > Host: localhost:8080
1 > User-Agent: curl/7.35.0
15:59:12.700 [qtp1046302571-14] mdc:MDC-Value INFO  Sample1Resource
    - Sample1Resource.get.
15:59:12.709 [qtp1046302571-14] mdc:MDC-Value INFO  LoggingFilter - 1
    * Server responded with a response on thread qtp1046302571-14
1 < 200
1 < Content-Type: text/plain

Es bleibt aber immer noch das Problem, dass der Inhalt nicht beeinflussbar ist.

ApplicationEventListener

Über einen ApplicationEventListener kann man sowohl den Zeitpunkt als auch den Inhalt der Log-Nachricht bestimmen.

Hier folgt ein Code-Beispiel unter Verwendung von SLF4J:

public class RequestLoggingApplicationListener implements ApplicationEventListener {
   public void onEvent(ApplicationEvent applicationEvent) {// nothing to do here }
 
   public RequestEventListener onRequest(RequestEvent requestEvent) {
      return LoggingRequestEventListener.INSTANCE;
   }
 
   private static class LoggingRequestEventListener implements RequestEventListener {
      private static final Logger LOGGER = LoggerFactory
         .getLogger(LoggingRequestEventListener.class);
      public static final LoggingRequestEventListener INSTANCE = 
         new LoggingRequestEventListener();
 
      public void onEvent(RequestEvent requestEvent) {
         final ContainerRequest containerRequest = requestEvent.getContainerRequest();
         switch (requestEvent.getType()) {
            case REQUEST_FILTERED:
               // first event that is called, after all request filters are called
               LOGGER.info("Start request {} {}"
                  , containerRequest.getMethod()
                  , containerRequest.getRequestUri());
               break;
            case RESP_FILTERS_START:
               // first event that contains a response
               LOGGER.info("End request {} {} {}"
                   , containerRequest.getMethod()
                   , containerRequest.getRequestUri()
                   , requestEvent.getContainerResponse().getStatus());
               break;
         }
      }
   }
}

Ausgabe für obiges Beispiel sieht dann ungefähr so aus:

14:53:56.805 [qtp1002410023-13] mdc:MDC-Value INFO  LoggingRequestEventListener
    - Start request GET http://localhost:8080/jersey-request-logging/sample1
14:53:56.808 [qtp1002410023-13] mdc:MDC-Value INFO  d.a.s.j.Sample1Resource
    - Sample1Resource.get.
14:53:56.814 [qtp1002410023-13] mdc:MDC-Value INFO  LoggingRequestEventListener
    - End request GET http://localhost:8080/jersey-request-logging/sample1 200

Einen weiteren Vorteil des RequestEvenListeners gegenüber einem ContainerRequestFilter- und ContainerResponseFilter-Gespann (wie der LoggingFilter eben) ist, dass er unabhängig von der Aufrufreihenfolge der Filter-Kette funktioniert. Bricht z.B. ein Filter den Request ab, werden die nachgfolgenden Filter nicht aufgerufen. Möchte man z.B. ein einfache Zeitmessung und MDC-Werte im Log ausgeben, hat man keinen Startzeitpunkt, da der zuständige Request-Filter wegen des Abbruchs nie aufgerufen wird. Der Response-Filter wird aber sehr wohl aufgerufen.

Sobald der RequestEventListener einen State benötigt (z.B. zum Berechnen der Request-Dauer) muss man bedenken, dass der oben verwendete Singleton-Ansatz natürlich nicht funktioniert. In diesem Fall muss man in ApplicationEventListener.onRequest(RequestEvent) jeweils einen neue Instanz der RequestEventListener-Klasse zurückgeben.

Will man nun noch Daten der HTTP-Entity loggen, wird es etwas komplizierter. Man kann nicht einfach die Streams des Requests order der Response auslesen. Die übrigen Teile der Anwendung bzw. der Aufrufer benötigen diese Daten ja auch noch. Die Implementierung des Jersey-LoggingFilters kann als Inspiration dienen, um dieses Problem zu lösen.

Zum Ausprobieren und genaueren Begutachten kann man das Projekt mit dem Beispiel-Code ansehen.


zur Übersicht

Willkommen auf dem avono Blog

Hier auf dem avono Blog finden Sie in regelmäßigen Abständen sowohl technische Neuigkeiten aus unserer Partnerproduktwelt als auch nützliche Entwicklertipps.
Und jetzt kommt der obligatorische Disclaimer: Die Ausführungen der Blogeinträge spiegeln nicht die Meinung der avono AG sondern nur die Sicht der einzelnen Autoren wider.

Weitere Blogeinträge