Logging Executor Decorator

[dmfs]

We could use a logging decorator to log every request. The core requirements are:

• independent from any specific logging facility
• customizable log policy like
  • log headers vs. don't log headers
  • log message body vs. don't log it or only log text message bodies vs. log only the first n characters
  • log headers that contain personal data (e.g. Authorization header) vs. don't log these
  • log request or just response?
  • log only in case of an error
  • …

[dmfs]

@lemonboston please suggest a reasonable architecture for this task.

Btw, it's clear that a Logging decorator will not log the request as it's ultimately sent over the wire, because subsequent decorators and the actual executor will add and modify things. But it's certainly good enough for most debugging tasks.

[lemonboston]

Ok, I created a first skeleton, but I plan to revisit this possibly multiple times in the coming days, just want to start to share now so you can comment. (I am going to add a PR just so you can check it here quicker, not for merging.)

This would be the HttpLogger interface:

public interface HttpLogger
{
    void log(URI uri, HttpRequest<?> request);

    void log(HttpResponse response);
}

I realized in the end that response logging method might need to return decorated HttpResponse similarly as in caching because of the consumption of the body - I'll get back to this at the bottom.

The policy:

public interface HttpLogPolicy
{
    // Decide whether to log, allowing any custom filter, eg for URL, 
    // or just generally return true or false
    boolean logRequest(URI uri, HttpRequest<?> request);

    boolean logResponse(HttpResponse response);

    // How to log:
    boolean logHeaders();

    boolean logErrorsOnly();

    LogLevel logLevel();

    String tag();
    ....
}

The first two methods can tell whether to log requests and responses in general and also allows the flexibility to define any kind of custom filter, for example logging calls sent to certain urls only. Rest of the properties mostly tell how to log. These first two methods could be moved to a separate interface and applied before calling log methods, not sure which ones is better, I kept it like this, so the whole policy is defined at one place (some stuff might relate to each other.)

This would be the executor decorator:

public final class Logging implements HttpRequestExecutor
{
    ....
    public Logging(HttpRequestExecutor delegateExecutor, HttpLogger httpLogger)
    {
        mDelegateExecutor = delegateExecutor;
        mHttpLogger = httpLogger;
    }

    @Override
    public <T> T execute(URI uri, HttpRequest<T> request) throws IOException, ProtocolError, ProtocolException, RedirectionException, UnexpectedStatusException
    {
        mHttpLogger.log(uri, request);
        return mDelegateExecutor.execute(uri, new ResponseDecorated<T>(request, new LoggingResponseDecoration()));
    }

    private class LoggingResponseDecoration implements Decoration<HttpResponse>
    {
        @Override
        public HttpResponse decorated(HttpResponse original)
        {
            mHttpLogger.log(original);
            return original;
        }
    }
}

A small note regarding what you mentioned, that the place of the Logging decorator in the decorator chain would affect what we can log from requests and responses: with the ability to log only requests or responses, if it made sense, we would have the option to add two Loggings, one close to the http client to log requests and one outer one to log the responses the client eventually receives.

The logger interface to cover the actual logging facility:

public interface Logger
{
    void log(LogLevel logLevel, String tag, String message);

    void log(LogLevel logLevel, String tag, String message, Throwable throwable);

}

HttpLogger implementation uses HttpLogPolicy and Logger:

public final class DefaultHttpLogger implements HttpLogger
{
    private final HttpLogPolicy mPolicy;
    private final Logger mLogger;

    public DefaultHttpLogger(HttpLogPolicy policy, Logger logger)
    {
        mPolicy = policy;
        mLogger = logger;
    }

    @Override
    public void log(URI uri, HttpRequest<?> request)
    {
        if (!mPolicy.logRequest(uri, request))
        {
            return;
        }

        String requestLog = null; // compose using uri, request and policy

        mLogger.log(mPolicy.logLevel(), mPolicy.tag(), requestLog);
    }

    @Override
    public void log(HttpResponse response)
    {
        if (!mPolicy.logResponse(response))
        {
            return;
        }

        String responseLog = null; // compose using response and policy

        mLogger.log(mPolicy.logLevel(), mPolicy.tag(), responseLog);
    }
}

And back to the response body stream consumption: I still don't know enough about streams and these network streams in particular, so I am not sure how to handle this. I guess we need to keep the stream open, so it's not good to consume it, print it and create a new ByteArrayInputStream with the content, right? (cloning Inputstream ) So I guess some kind of duplicating/copying is needed here as well, like you used at caching. Not sure at what point do we print, for every line, or do we wait until the whole message in consumed? Thanks for any input on this.

[lemonboston]

..just realized that the request body printing and consumption is also a question of course.

[dmfs]

I don't think that we need log levels. To me that's an internal of the logger (it could be a parameter of the Log facility though). Btw. I like the name LogFacility better than Logger, it sounds more like a real object.

I don't really like the current idea of the HttpLogPolicy. Why not use a decorator approach in this case as well. Kind of a "filter chain" like new NoHeaders(new NoBody(new LogAllPolicy())) which would log method, URI and response code only. That would mean we basically need sort of these methods

void log(HttpMethod, URI, LogFacility);

void log(HttpStatus, LogFacility);

void log(Header, LogFacility);

void log(HttpRequestEntity, LogFacility);

void log(HttpResponseEntity, LogFacility);

Maybe we could further distinguish void log(Header, LogFacility) into two separate methods to log request and response headers. We could also add the HttpStatus to all response log methods to allow filtering by status. A LogPolicy like this would support all the requirements above.

Not sure if it's better to pass the LogFacility to each method or just once as a parameter to LogAllPolicy.

Also I'm not quite sure how to pass HttpRequestEntity and HttpResponseEntity. It certainly wouldn't work the way I outlined above since we have to decorate them. Maybe it's sufficient to return them decorated.

Also, I'm not sure what the best way would be to log the entity body. We could write a LoggingInputStream that logs essentially everything that's read. The only challenge with this is the character set. No one guarantees that the client always reads complete code points, so we would need some sort of buffer that makes sure we don't try to log partial code points.

[lemonboston]

Yes, decorators would be nice, it occurred to me too, for the 'formatter' level, sort of, but I wasn't sure how to do that. So I also like this approach with the list of methods you suggested. With some modification, this is what I came to now:

public interface HttpLogComposer
{
    // return null means not to log

    String requestMsg(HttpMethod method, URI uri);

    String requestMsg(Header header);

    String requestMsg(HttpRequestEntity entity);

    BodyLogComposer requestBodyComposer();

    String responseMsg(HttpStatus status);

    String responseMsg(Header header, HttpStatus status);

    String responseMsg(HttpResponseEntity entity, HttpStatus status);

    BodyLogComposer responseBodyComposer();

}

So it returns the string messages to log instead of logging them itself with the LoggingFacility. It's a bit of separation of concerns and also allows appending decorations. The tricky part with logging the bodies: I thought this component should not be concerned with streams, but just provide something that defines how the body should be logged and it can be used by the stream duplicating class. So this BodyLogComposer and the LoggingFacility will be passed on to the request and response decoration to the stream handling, where they can just be used.

public interface BodyLogComposer
{
    /**
     * Charset of the body, the stream utility can use it for reading
     */
    String charset();

    /**
     * @param aLineInTheBody
     *         a line in the request or response body
     *
     * @return the string to print to the log
     */
    String bodyLineMsg(String aLineInTheBody);
}

Not sure if this string to string method is what we need, but I guess we need to log the body line by line. What do you think?

I separated the filtering to:

public interface HttpLogFilter
{
    boolean logRequest(URI uri, HttpRequest<?> request);

    boolean logResponse(HttpResponse response);
}

And 'HttpLogger' now returns the decorated request and response:

public interface HttpLogger
{
    HttpRequest log(URI uri, HttpRequest<?> request);

    HttpResponse log(HttpResponse response);
}

Logging executor decorator only depends on this high-level interface, this allows nice decoupling and flexibility to change anything under it. (Maybe create tracking, analytics implementations for example.) The default HttpLogger implementation uses HttpLogFilter to decide whether to even log a certain request or response, and uses HttpLogComposer to actually create the log message. HttpLogComposer knows what parts of the request, response to log and how to log them, and it can be chained with decorators as you wrote. (DefaultHttpLogger uses something similar to template method pattern now to compose parts of the message, but instead of abstract method hooks and inheritance, it uses composition with HttpLogComposer.)

Regarding LoggingFacility, this initial version below is an abstraction above logcat and sl4j interfaces, the log levels can be matched up clearly.

public interface LoggingFacility
{
    void log(LogLevel logLevel, String tag, String message);

    void log(LogLevel logLevel, String tag, String message, Throwable throwable);

}

We can 'move' this abstraction higher, to have log level internal as you mentioned (and tag also):

public interface LoggingFacility2
{
    void log(String message);

    // throwable can be null
    void logError(String message, Throwable throwable);
}

I think the 1st version is a pure, thin adapter to the actual logger without any interpretation, the 2nd one might do a little more than that. But I think both can work. With the 2nd one, in LogcatLogginFacility2 constructor, we would define default log level and tag.

I plan to come back to this tomorrow again and possibly start looking into the i/o stream logging.

[lemonboston]

Just 2 more notes:

HttpLogFormatter might be better name than HttpLogComposer, cause the full composition of the message is done by the client of that interface actually.

We could combine HttpLogFilter and HttpLogFormatter (currently ..Composer) this way:

interface HttpLogPolicy   // not sure about the name
{
   // returning null means not to log   
   HttpLogFormatter requestFormatter(URI uri, HttpRequest request);

   HttpLogFormatter responseFormatter(HttpResponse response);
}

This way we could define logging per request and response, too. For example for https requests, only log some minimal information, while for http request, log everything.

[lemonboston]

About the byte stream to character decoding, new line detection: CharsetDecoder can decode bytes as they come in through a ByteBuffer, leaving incomplete code points out at the end, controlled by a boolean param endOfInput (method decode). So in theory we can detect new line chars on the fly this way, I am working on a LogSink implementation using this approach.

[lemonboston]

I've implemented the char by char decoding in CharacterLogSink. When it encounters a new line (\n currently) or when the character buffer is full, it flushes the buffer to the log output. @dmfs When you have time for this, please check it out along with the initial test: CharacterLogSinkTest. If this approach could work, I would review again and test it with more tricky inputs.

I am not sure about endianness. I see that jdk provides Charsets for UTF-16BE and UTF-16LE, so if content header contains these specifiers to signal difference from standard one, the decoding would work correctly (tried it with the test). Otherwise we might need to implement BOM parsing as well, but I am not sure, maybe CharsetDecoder does that and changes the ByteBuffer.order() accordingly (I couldn't find the source). I might be able to test that with synthetic byte arrays containing BOM.

[lemonboston]

I've created and alternative design for the logging in elements subpackage.

There are RequestLogElements and ResponseLogElements, which can be anything that we would want to log from a request or response.

public interface RequestLogElement
{
    void log(HttpRequest<?> request, URI uri, StringBuilder log);
}

public interface ResponseLogElement
{
    void log(HttpResponse response, StringBuilder log);
}

Lists of them can be put together to a HttpLogElements that will ultimately be used by the HttpLogger implementation.

Usage would look like this:

HttpLogElements httpLogElements = new HttpLogElementsBuilder()
                // Request elements in the order of printing:
                .add(new MethodAndUri())
                .add(new Headers(ONLY_NON_PERSONAL))

                // Response elements in the order of printing:
                .add(new Status())
                .add(new Headers())

                // LogSinkProvider for the body logging:
                .add(new TextBody())
                .build();

HttpRequestExecutor originalExecutor = null;
new Logging(originalExecutor, new BaseHttpLogger(httpLogElements));

So HttpLogElements looks like this:

public interface HttpLogElements
{
    List<RequestLogElement> requestLogElements();

    List<ResponseLogElement> responseLogElements();

    LogSinkProvider entityBodyLogSinkProvider();

   // plus the Builder
}

BaseHttpLogger just iterates over the lists and calls them all.

Body logging 'policy' is provided by LogSinkProvider (may also be separated for request and response):

public interface LogSinkProvider
{
    // return null means not to log body
    LogSink provide(URI uri, HttpRequest<?> request);

    LogSink provide(HttpResponse response);
}

It allows to assign different LogSinks to different content types.

What do you think?

I think the power of this is that these elements receive the full request and response, so they always have all information there is to decide what and how to log, so it is very open and flexible to add anything to the log. We don't need to define or constrain upfront what properties of the request/response could be logged and how (no policy definition needed).

(Some code under request and response *LogElements could be further organized if needed, for example there could be a HeaderLogger with void log(Header header, StringBuilder log) so we could use the same ones for request and response (they could implement filtering for header type).)

[dmfs]

Regarding the LogSinkProvider, I don't think that this class should be allowed to decide whether to log or not to log. It should stick to what it's meant for, to return a LogSink for a specific content type, so it's actually a factory.

public interface LogSinkFactory 
{
    LogSink logSink(MediaType mediaType);
}

In the end, the type of the LogSink only depends on the media type of the response. If a specific content type should not be logged it would return a NullLogSink which doesn't forward the data to the LogFacility or a SupressingLogSink which just writes a specific text when the sink is closed (e.g. Suppressed %d octets of payload with content-type %s).

The LogFacility should probably be passed to the constructor of the factory.

A LogSink just needs a way to feed bytes and to close it (to flush any incomplete line). It indeed has a lot in common with an OutputStream. Unfortunately that's not an interface.

Maybe LogSink is not a good name yet, because it's meant to log the message payload only.

I'm currently thinking of a "composable" LogPolicy (that's probably not a good name in that case), but I don't have a clear picture yet, so it's to early to write it down.

[lemonboston]

Yes, I agree that a LogSinkFactory is useful for selecting LogSinks for content types. I've created it.

LogSinkProvider is one level higher, the idea there would be to allow selecting LogSink based on full information of request and response, just as with the RequestLogElement and ResponseLogElement. It may not be needed, because all we care about is content type, but I think this is how this approach is coherent. (AllBody LogSinkProvider now uses a LogSinkFactory)

Why I currently like this approach is because a RequestLogElement with method void log(HttpRequest<?> request, URI uri, StringBuilder log) can be anything we would want to log from a request (except the body content), so we are free to create any implementation and compose the log this way. This eliminates the need to define policy construct that could fix what can be configured for logging based on specific parameters of request and response.

The elements are put into lists currently, but composable decorators could be used here as well - then these RequestLogElements would mostly be decorators. So instead of this:

        HttpLogElements httpLogElements = new HttpLogElementsBuilder()
                // Request elements in the order of printing:
                .add(new MethodAndUri())
                .add(new RequestHeaders(ONLY_NON_PERSONAL))
                .add(new RequestContentDesc())

                // Response elements in the order of printing:
                .add(new Status())
                .add(new ResponseHeaders())
                .add(new ResponseContentDesc())

                // LogSinkProvider for the body logging:
                .add(new AllBody(new LogcatLogFacility()))
                .build();

        new Logging(originalExecutor, new BasicHttpLogger(httpLogElements));

It would be something like this:

RequestLogElement requestLog = new MethodAndUri(new RequestHeaders(ONLY_NON_PERSONAL, new RequestContentDesc())
ResponseLogElement responseLog = new Status(new ResponseHeaders(new ResponseContentDesc());
LogSinkProvider logSinkProvider = new AllBody(new LogcateFacility())

new Logging(originalExecutor, new BasicHttpLogger(requestLog, responseLog, logSinkProvider));

But I think the List approach is more straighforward, it easier to see there with the builder how actually the log will look like, and each *LogElement stands on their own, no need to decorate something (no need inside them to decide to log before or after the delegate for example).

Regarding finding a better name for LogSink, how about ContentSink?

[lemonboston]

I don't continue with this now, so to sum up for the time when you get back to this, please check the approach in elements package and CharacterLogSink to see if something like that could work for the body byte stream logging.