NullPointerException in RequestLogCollection Jetty 9.3.9

I am using Jetty 9.3.9.v20160517 in my embedded application, and I have configured the logging using jetty-requestlog.xml like so:

<?xml version="1.0"?>
<!DOCTYPE Configure PUBLIC "-//Jetty//Configure//EN" "http://www.eclipse.org/jetty/configure_9_3.dtd">

<!-- =============================================================== -->
<!-- Configure the Jetty Request Log                                 -->
<!-- =============================================================== -->
<Configure id="Server" class="org.eclipse.jetty.server.Server">

  <!-- =========================================================== -->
  <!-- Configure Request Log for Server                            -->
  <!-- (Use RequestLogHandler for a context specific RequestLog    -->
  <!-- =========================================================== -->
  <Set name="RequestLog">
    <New id="RequestLog" class="org.eclipse.jetty.server.AsyncNCSARequestLog">
      <Set name="filename"><Property name="jetty.base" default="." /><Property>
          <Name>jetty.requestlog.filePath</Name>
          <Deprecated>requestlog.filename</Deprecated>
          <Default><Property name="jetty.requestlog.dir" default="/logs"/>/yyyy_mm_dd.request.log</Default>
        </Property>
      </Set>
      <Set name="filenameDateFormat"><Property name="jetty.requestlog.filenameDateFormat" deprecated="requestlog.filenameDateFormat" default="yyyy_MM_dd"/></Set>
      <Set name="retainDays"><Property name="jetty.requestlog.retainDays" deprecated="requestlog.retain" default="90"/></Set>
      <Set name="append"><Property name="jetty.requestlog.append" deprecated="requestlog.append" default="true"/></Set>
      <Set name="extended"><Property name="jetty.requestlog.extended" deprecated="requestlog.extended" default="false"/></Set>
      <Set name="logCookies"><Property name="jetty.requestlog.cookies" deprecated="requestlog.cookies" default="false"/></Set>
      <Set name="LogTimeZone"><Property name="jetty.requestlog.timezone" deprecated="requestlog.timezone" default="GMT"/></Set>
    </New>
  </Set>
</Configure>

However, at runtime when Jetty actually tries to log anything I get the following NPE each time I make a request to the server, even though the logs do seem to be written to $jetty.base/logs/2016_06_15.request.log.

2016-06-15 22:19:23,302 [eXistThread-29] WARN  (HttpChannel.java [handle]:479) - //localhost:8080/exist/apps/dashboard/modules/get-icon.xql?package=http://exist-db.org/apps/eXide 
java.lang.NullPointerException
    at org.eclipse.jetty.server.RequestLogCollection.log(RequestLogCollection.java:44) ~[jetty-server-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:620) ~[jetty-server-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:453) [jetty-server-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:253) [jetty-server-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273) [jetty-io-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95) [jetty-io-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [jetty-io-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [jetty-util-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [jetty-util-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [jetty-util-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [jetty-util-9.3.9.v20160517.jar:9.3.9.v20160517]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [jetty-util-9.3.9.v20160517.jar:9.3.9.v20160517]
    at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]

So... What is causing these NPE's and how do I fix them please?

Solution

Your XML load order is bad (see etc/enabled-jetty-config in your source)

I mentioned this in an earlier answer.

Here's a way you can see how this order works.

Use the jetty-distribution :-)

# Use a new empty base
$ cd /path/to/mybase

# Lets add the modules into this base
$ java -jar /path/to/jetty-dist/start.jar --add-to-start=annotations,deploy,https,gzip,jmx,requestlog
INFO: server          initialised (transitively) in ${jetty.base}/start.ini
INFO: gzip            initialised in ${jetty.base}/start.ini
INFO: jmx             initialised in ${jetty.base}/start.ini
INFO: requestlog      initialised in ${jetty.base}/start.ini
INFO: ssl             initialised (transitively) in ${jetty.base}/start.ini
INFO: https           initialised in ${jetty.base}/start.ini
INFO: deploy          initialised in ${jetty.base}/start.ini
INFO: annotations     initialised in ${jetty.base}/start.ini
MKDIR: ${jetty.base}/logs
DOWNLOAD: https://raw.githubusercontent.com/eclipse/jetty.project/master/jetty-server/src/test/config/etc/keystore?id=master to ${jetty.base}/etc/keystore
MKDIR: ${jetty.base}/webapps
INFO: Base directory was modified

# Lets ask the jetty-distribution what its XML load order is
java -jar /path/to/jetty-dist/start.jar --list-config
...(snip lots of output)...
Jetty Active XMLs:
------------------
 ${jetty.home}/etc/jetty.xml
 ${jetty.home}/etc/jetty-gzip.xml
 ${jetty.home}/etc/jetty-jmx.xml
 ${jetty.home}/etc/jetty-requestlog.xml
 ${jetty.home}/etc/jetty-ssl.xml
 ${jetty.home}/etc/jetty-ssl-context.xml
 ${jetty.home}/etc/jetty-https.xml
 ${jetty.home}/etc/jetty-deploy.xml
 ${jetty.home}/etc/jetty-plus.xml
 ${jetty.home}/etc/jetty-annotations.xml

Note: this load order can (and does!) change between releases of Jetty. Don't rely on this being the one true load order for all versions of Jetty going forward. You'll either have to implement the same start.jar module logic, or redo this jetty-distribution/start.jar --list-config with each upgrade of your project.

WARNING: Don't do this, don't mix jetty-distribution and embedded-jetty, you are just creating lots of extra work for yourself, increasing your maintenance tasks, etc. Use embedded-jetty *or* jetty-distribution directly.