Blog from September, 2017

In an attempt to help determine the cause of the intermittent REST call failures in the juneau-microservice-test project, I've made some debugging enhancements to the microservice.

The test project will now generate 4 log files...

The jetty-thread-dump.log file is generated by Jetty on the event of a failed request and shows a snapshot of the current state of the threads in Jetty. The retry handler in TestMicroservice is shown below and will stop the tests as soon as the first error occurs...

  new HttpRequestRetryHandler() {
    @Override
    public boolean retryRequest(IOException exception, int executionCount, HttpContext context) {
      System.err.println("*** ERROR ***");
      TestMicroservice.jettyDump();
      microservice.stop();
      System.exit(2);
      return true;
    }
  }
 
  public static void jettyDump() {
    try {
      String dump = microservice.getServer().dump();
      IOUtils.pipe(dump, new FileWriter(microservice.getConfig().getString("Logging/logDir") + "/jetty-thread-dump.log"));
    } catch (Exception e) {
      e.printStackTrace();
    }
  }

The jetty-requests.log is generated by adding this to the jetty.xml file...

<Set name="requestLog">
  <New id="RequestLogImpl" class="org.eclipse.jetty.server.NCSARequestLog">
    <Set name="filename"><Property name="jetty.logs" default="$C{Logging/logDir,logs}"/>/jetty-requests.log</Set>
    <Set name="filenameDateFormat">yyyy_MM_dd</Set>
    <Set name="LogTimeZone">GMT</Set>
    <Set name="retainDays">90</Set>
    <Set name="append">false</Set>
    <Set name="LogLatency">true</Set>
  </New>
</Set>

This just shows if Jetty actually got the request from the last call.

Note that the jetty.xml file now supports embedded Juneau variables (e.g. $C{Logging/logDir}).

I also created a separate Jetty section in the config file...

#=======================================================================================================================
# Jetty settings
#=======================================================================================================================
[Jetty]
# Path of the jetty.xml file used to configure the Jetty server.
config = jetty.xml

# Resolve Juneau variables in the jetty.xml file.
resolveVars = true

# Port to use for the jetty server.
# You can specify multiple ports. The first available will be used. '0' indicates to try a random port.
# The resulting available port gets set as the system property "availablePort" which can be referenced in the 
# jetty.xml file as "$S{availablePort}" (assuming resolveVars is enabled).
port = 10000,0,0,0

Note that we now support dynamically specifying the port again through the use of the $S{availablePort} variable.

The test.0.log file now contains the entire debug logging generated by Jetty (yea...it's big...7.8MB). I had to create a new org.apache.juneau.microservice.JettyLogger class to serve as a simple bridge between Jetty logging and java-util-logging, but it now allows all the logging to be directed to a single log file. The configuration for doing this is shown below:

[Logging]
logDir = $S{user.dir}/target/logs
logFile = test.%g.log
levels = 
  { 
    '':'WARNING', 
    org.apache.juneau: 'WARNING', 
    org.eclipse.jetty: 'FINEST' 
  }
consoleLevel = WARNING
fileLevel = FINEST

[SystemProperties]
org.eclipse.jetty.util.log.class = org.apache.juneau.microservice.JettyLogger
org.eclipse.jetty.LEVEL = ALL

If an error is occurring somewhere in Jetty, it should show up here.

The third-party-proxy-resource.txt file contains log entries from RestHooks added to the ThirdPartyProxyResource class (which seems to be a common place for failure). This makes sure that the failure isn't occurring within our logic. If we see START/PRE/POST/END messages for our calls, then we know we're not causing a problem.

public static FileWriter logFile;
static {
  try {
    logFile = new FileWriter("./target/logs/third-party-proxy-resource.txt", false);
  } catch (IOException e) {
    e.printStackTrace();
  }
}

@RestHook(HookEvent.START_CALL)
public static void startCall(HttpServletRequest req) {
  try {
    logFile.append("START["+new Date()+"]-").append(req.getQueryString()).append("\n");
    logFile.flush();
  } catch (IOException e) {
    e.printStackTrace();
  }
}

@RestHook(HookEvent.PRE_CALL)
public static void preCall(HttpServletRequest req) {
  try {
    logFile.append("PRE["+new Date()+"]-").append(req.getQueryString()).append("\n");
    logFile.flush();
  } catch (IOException e) {
    e.printStackTrace();
  }
}

@RestHook(HookEvent.POST_CALL)
public static void postCall(HttpServletRequest req) {
  try {
    logFile.append("POST["+new Date()+"]-").append(req.getQueryString()).append("\n");
    logFile.flush();
  } catch (IOException e) {
    e.printStackTrace();
  }
}

@RestHook(HookEvent.END_CALL)
public static void endCall(HttpServletRequest req) {
  try {
    Exception e = (Exception)req.getAttribute("Exception");
    Long execTime = (Long)req.getAttribute("ExecTime");
    logFile.append("END["+new Date()+"]-").append(req.getQueryString()).append(", time=").append(""+execTime).append(", exception=").append(e == null ? null : e.toString()).append("\n");
    logFile.flush();
  } catch (IOException e) {
    e.printStackTrace();
  }
}

If you do encounter testcase failure due to HTTP request errors, I recommend using WireShark listening on port 10001:

This should help show whether the requests appear to be failing on the server or client side...

Space shortcuts

Blog

Blog from September, 2017