Jetty (specifically Solr) request latency logging to application insights

Question

I can configure Jetty to log request latency https://support.lucidworks.com/s/question/0D58000003LRo9YCAT/how-to-log-http-request-latencies-for-solr-in-jetty-logs

<Ref id="Handlers">
      <Call name="addHandler">
        <Arg>
          <New id="RequestLog" class="org.eclipse.jetty.server.handler.RequestLogHandler">
            <Set name="requestLog">
              <New id="RequestLogImpl" class="org.eclipse.jetty.server.NCSARequestLog">
                <Set name="filename">
                   logs/request.yyyy_mm_dd.log
                </Set>
                <Set name="filenameDateFormat">yyyy_MM_dd</Set>
                <Set name="retainDays">90</Set>
                <Set name="append">true</Set>
                <Set name="extended">false</Set>
                <Set name="logCookies">false</Set>
                <Set name="LogTimeZone">UTC</Set>
                <Set name="logLatency">true</Set>                
              </New>
            </Set>
          </New>
        </Arg>
      </Call>
    </Ref>

However this goes to a separate log file, and log4j isn't used, so the application insights log4j appender doesn't pick it up. (See - Solr to Application Insights)

How can I get log4j to record jetty request latency?

Alternatively, I see that logback has built in support for it's own RequestLogImpl https://logback.qos.ch/access.html

And application insights supports logback https://docs.microsoft.com/en-us/azure/azure-monitor/app/java-trace-logs

<Ref id="Handlers">
  <Call name="addHandler">
    <Arg>
      <New id="RequestLog" class="org.eclipse.jetty.server.handler.RequestLogHandler">
        <Set name="requestLog">
            <New id="requestLogImpl" class="ch.qos.logback.access.jetty.RequestLogImpl">
            </New>
        </Set>
      </New>
    </Arg>
  </Call>
</Ref>

server\lib\ext\logback-access-1.2.3.jar

server\lib\ext\logback-core-1.2.3.jar

However, I can't seem to get logback to log any requests to a file. Not sure it's picking up the logback-access.xml configuration, tried supplying the file path, using the default, but no luck.

server\etc\logback-access.xml (same location at jetty.xml)

and tried specifying relative, fully qualified paths to log file location, but none have worked.

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
  <!-- always a good activate OnConsoleStatusListener -->
  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>C:\logcallback\access.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>C:\logcallback\access.%d{yyyy-MM-dd}.log.zip</fileNamePattern>
    </rollingPolicy>

    <encoder>
      <pattern>combined</pattern>
    </encoder>
  </appender>

  <logger name="org.eclipse.jetty.server.RequestLog" level="DEBUG" additivity="false">
    <appender-ref ref="FILE" />
  </logger>

   <root level="DEBUG">
        <appender-ref ref="FILE"/>
    </root>
</configuration>

So how can I get Solr to log Jetty Request latency metrics to application insights, using either log4j or logback?

Answer 1

I found this code (Thanks) https://github.com/Fewbytes/jetty-log4j-request-log/tree/master/src/main/java/com/fewbytes/jetty/log4j

which when adapted, I got the Jetty response times logged to log4j.

<Ref id="Handlers">
  <Call name="addHandler">
    <Arg>
      <New id="RequestLog" class="org.eclipse.jetty.server.handler.RequestLogHandler">
        <Set name="requestLog">
            <New id="requestLogImpl" class="com.fewbytes.jetty.log4j.Log4JRequestHandler">
            </New>
        </Set>
      </New>
    </Arg>
  </Call>
</Ref>

had to add an overloaded parameter-less constructor, as was getting an invalid configuration error before this.

public Log4JRequestHandler()
    {
        this.loggerName = "com.fewbytes.jetty.log4j";
    }
    public Log4JRequestHandler(String loggerName) {
        this.loggerName = loggerName;
    }

I had to modify the ResponseDescriptor as getting null errors and didn't need all the cookies etc, and serializable wasn't working for me so had to overload to string (just output a couple of properties on toString to test this out)

public JettyRequestResponseDescriptor(Request request, Response response) {
        method = request.getMethod();
        requestURL = request.getRequestURL().toString();
        status = response.getStatus();
        latency = System.currentTimeMillis() - request.getTimeStamp();
        remoteHost = request.getRemoteHost();
        remotePort = request.getRemotePort();
        scheme = request.getScheme();
        protocol = request.getProtocol();
        localName = request.getLocalName();
        localPort = request.getLocalPort();
        requestURI = request.getRequestURI();
        responseLength = response.getContentCount();
        serverName = request.getServerName();
        timestamp = request.getTimeStamp();
        referrer = request.getHeader(HttpHeaders.REFERER);
        userAgent = request.getHeader(HttpHeaders.USER_AGENT);
        X_Forwarded_For = request.getHeader(HttpHeaders.X_FORWARDED_FOR);
    }
    @Override
    public String toString() {
        return "JettyRequestResponseDescriptor [requestURL=" + requestURL + ", latency=" + latency + "]";
    }

then in log4j.properties

Set logging level for this logger

com.fewbytes.jetty.log4j=INFO

To build the package had to download maven

run against the pom.xml file

c:\apache-maven-3.6.1-bin\apache-maven-3.6.1\bin\mvn package

Copy the generated "jetty-log4j-request-log-1.0-SNAPSHOT.jar" file to "server\lib\ext"

And could see in the solr log files generated by log4j the request and latency times from jetty!

2019-08-16 12:51:41.318 INFO  (qtp100555887-18) [   ] c.f.j.log4j JettyRequestResponseDescriptor [requestURL=http://localhost:8983/solr/admin/collections, latency=110]

Now proven can do it, time to tidy it up.