Building Application to Be Troubleshooting Friendly

The Problem
There is always bug in code that will be found later in production, and in some cases we can't easily reproduce it in test environment.

Ideally we want to rerun the request, check the log in server or maybe change the log level to info or debug.

But usually we can't or at least not that easy: to check the realtime log in production machine or login to it, we have to talk with operation team or open ticket and get it approved; let alone restart the machine to change log level.

Solution

• Change log level per request.
• Return diagnosis information in API response.

Implementation
When client sends request with headers: X-Debug-Request=true, and X-DEBUG-KEY equals the encrypted debug.key defined in properties file, the application will change some loggers to debug level(so it will print more logging to help us trouble shooting the problem) and add diagnosis info in response. 

We can put the diagnosis info in header or request body. In this example, we choose to put it in request body.

-- We use debug.key to protect this feature and change it frequently (in each deployment).

The response would be like:
-- We wrap the real response in data tag, so we can easily extend it to add other related data later. 

{
 "data": { // here it can be an object(for getById) or an array(for query)
 }
 "diagnosis": [] // list of string that may help diagnose the problem
 // here can be some pagination meta data 
}

Code
The following code uses Logback and Jersey 1.

PerRequestTurboFilter

public class PerRequestTurboFilter extends DynamicThresholdFilter {
    @Override
    public FilterReply decide(final Marker marker, final Logger logger, final Level level, final String s,
            final Object[] objects, final Throwable throwable) {

        final String loggerName = logger.getName();

        if (loggerName.startsWith("com.myapp") || loggerName.startsWith("org.apache.http")
                || loggerName.startsWith("httpclient.wire")) {
            return super.decide(marker, logger, level, s, objects, throwable);
        }
        addMesToRequestConext(reply, loggerName, msg);
        return FilterReply.NEUTRAL;
    }
    protected void addMesToRequestConext(final FilterReply reply, final String loggerName, final String msg,) {
        final String mdcValue = MDC.get(getKey());
        if (mdcValue != null && reply.equals(FilterReply.ACCEPT) && StringUtils.isNotBlank(msg)
                && loggerName.startsWith("com.myapp")) {
            RequestContextUtil.getRequestContext().addDiagnosis(msg);
        }
    }
} 

PerRequestTurboFilter extends Logback DynamicThresholdFilter, it will only change logger level for com.app and apache http and httpclient. If MDC contains X-Debug-Request, and its value is true, the filter will accept the log request.

Also it will add the log message into the ThreadLocal RequestContext if the logger starts with com.myapp.
Logback.xml

<turboFilter class="com.myapp.PerRequestTurboFilter">
 <Key>X-Debug-Request</Key>
 <OnHigherOrEqual>ACCEPT</OnHigherOrEqual>
 <OnLower>NEUTRAL</OnLower>
 <MDCValueLevelPair>
  <value>true</value>
  <level>DEBUG</level>
 </MDCValueLevelPair>
</turboFilter>

Jersey Filter

@Provider
@Component
public class HttpHeaderFilter implements ContainerRequestFilter, ContainerResponseFilter {

    public static final String X_DEBUG_REQUEST = "X-Debug-Request";
    private static final String X_DEBUG_KEY = "X-DEBUG-KEY";
    // Used to protect debug header, we can change it from property file.
    @Value("${debug.key:}")
    private String debugKey;

    @Context
    HttpServletRequest servletRequest;

    @Override
    public ContainerRequest filter(final ContainerRequest request) {
        setLogDiagnosticContextParams(request);
        return request;
    }

    private void setLogDiagnosticContextParams(final ContainerRequest request) {
        final String debugRequest = request.getHeaderValue(X_DEBUG_REQUEST);;
        if (debugRequest != null) {

            final String clientKey = request.getHeaderValue(X_DEBUG_KEY);
            if (debugKey.equals(clientKey)) {
                MDC.put(X_DEBUG_REQUEST, debugRequest);
                RequestContextUtil.getRequestContext().setEnableDebug(Boolean.valueOf(debugRequest));
            } else {
                RequestContextUtil.getRequestContext().setEnableDebug(false);
            }
        }
    }

    @Override
    public ContainerResponse filter(final ContainerRequest request, final ContainerResponse response) {
        final MultivaluedMap<String, Object> headers = response.getHttpHeaders();

        final Object entity = response.getEntity();
 if (RequestContextUtil.getRequestContext().isEnableDebug()) {
     if (entity instanceof ClientData) {
         final ClientData<?> clientData = (ClientData<?>) entity;
         clientData.add(ClientData.DIAGNOSIS, RequestContextUtil.getRequestContext().getDiagnosises());
     } else {
         headers.add(ClientData.DIAGNOSIS, RequestContextUtil.getRequestContext().getDiagnosises());
     }
 }
        clear();
        return response;
    }

    private void clear() {
        MDC.clear();
        RequestContextUtil.removeRequestContext();
    }
}

We can also add request-id, logged userinto MDC, and change log pattern to include them in logback.xml.

In code, we can add diagnosis info like: RequestContextUtil.getRequestContext().getDiagnosises().add(String.format("query: %s", query));

RequestContextUtil and RequestContext

public class RequestContextUtil {
    private static ThreadLocal<RequestContext> requestContextLocal = new ThreadLocal<RequestContext>() {
        protected RequestContext initialValue() {
            return new RequestContext();
        };
    };

    public static ThreadLocal<RequestContext> getRequestContextLocal() {
        return requestContextLocal;
    }

    public static void setRequestContext(final RequestContext userContext) {
        requestContextLocal.set(userContext);
    }

    public static RequestContext getRequestContext() {
        return requestContextLocal.get();
    }

    public static void removeRequestContext() {
        requestContextLocal.remove();
    }

    public static class RequestContext implements Serializable {
        private static final long serialVersionUID = 1L;

        private boolean enableDebug;
        final List<String> diagnosises = new ArrayList<>();

        public List<String> getDiagnosises() {
            return diagnosises;
        }

        public void addDiagnosis(final String diagnosis) {
            diagnosises.add(diagnosis);
        }

        public boolean isEnableDebug() {
            return enableDebug;
        }

        public void setEnableDebug(final boolean enableDebug) {
            this.enableDebug = enableDebug;
        }
    }
}

Other Approaches

• Expose API to change log level dynamically and recover it later.

Misc

Debug Feature
Return debug info that can check from response without having to check the log
- Of course secured, protected

Mock User Feature
Preview Feature
In memory test users in test env