Uploaded image for project: 'Undertow'
  1. Undertow
  2. UNDERTOW-597

DefaultAccessLogReceiver cannot always be closed cleanly and may log a NullPointerException

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • 1.2.13.Final, 1.4.0.Beta1, 1.3.11.Final
    • 1.2.12.Final, 1.3.10.Final
    • None
    • None
    • Hide

      These two tests should hopefully illustrate the problem:

      @Test
    public void cleanShutdownAfterLoggingAMessage()
            throws IOException, InterruptedException {
        Xnio xnio = Xnio.getInstance(getClass().getClassLoader());
        XnioWorker worker = xnio.createWorker(OptionMap.builder().getMap());
        File outputDirectory = new File("target/access_logs");
        outputDirectory.mkdirs();
        DefaultAccessLogReceiver receiver = new DefaultAccessLogReceiver(worker,
                outputDirectory, "foo.");
        // This will work because logging the message causes the writer to be created.
        receiver.logMessage("message");
        // Sleep for a bit so that the writer gets created before we close the receiver
        Thread.sleep(100);
        receiver.close();
        // Sleep for a bit to give any exception a chance to occur
        Thread.sleep(100);
    }

    @Test
    public void cleanShutdownWithAFreshReceiver()
            throws IOException, InterruptedException {
        Xnio xnio = Xnio.getInstance(getClass().getClassLoader());
        XnioWorker worker = xnio.createWorker(OptionMap.builder().getMap());
        File outputDirectory = new File("target/access_logs");
        outputDirectory.mkdirs();
        DefaultAccessLogReceiver receiver = new DefaultAccessLogReceiver(worker,
                outputDirectory, "foo.");
        // This will NPE because the receiver's writer is null. This can happen if the
        // receiver isn't used before it's closed, or it's closed after it's been rotated.
        receiver.close();
        // Sleep for a bit to give any exception a chance to occur
        Thread.sleep(100);
    }

      The first test will not log any exception due to the logging of the message creating the writer. The second test will log an NPE because the writer is null.

      Show
      These two tests should hopefully illustrate the problem: @Test public void cleanShutdownAfterLoggingAMessage() throws IOException, InterruptedException { Xnio xnio = Xnio.getInstance(getClass().getClassLoader()); XnioWorker worker = xnio.createWorker(OptionMap.builder().getMap()); File outputDirectory = new File("target/access_logs"); outputDirectory.mkdirs(); DefaultAccessLogReceiver receiver = new DefaultAccessLogReceiver(worker, outputDirectory, "foo."); // This will work because logging the message causes the writer to be created. receiver.logMessage("message"); // Sleep for a bit so that the writer gets created before we close the receiver Thread.sleep(100); receiver.close(); // Sleep for a bit to give any exception a chance to occur Thread.sleep(100); } @Test public void cleanShutdownWithAFreshReceiver() throws IOException, InterruptedException { Xnio xnio = Xnio.getInstance(getClass().getClassLoader()); XnioWorker worker = xnio.createWorker(OptionMap.builder().getMap()); File outputDirectory = new File("target/access_logs"); outputDirectory.mkdirs(); DefaultAccessLogReceiver receiver = new DefaultAccessLogReceiver(worker, outputDirectory, "foo."); // This will NPE because the receiver's writer is null. This can happen if the // receiver isn't used before it's closed, or it's closed after it's been rotated. receiver.close(); // Sleep for a bit to give any exception a chance to occur Thread.sleep(100); } The first test will not log any exception due to the logging of the message creating the writer. The second test will log an NPE because the writer is null.

      When DefaultAccessLogReceiver is closed with a null writer an NPE is logged to System.err. The writer may be null because the receiver hasn't been used or because it's just rotated its log file. The NPE looks like this:

      Exception in thread "XNIO-1 task-1" java.lang.NullPointerException
	at io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver.run(DefaultAccessLogReceiver.java:192)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

      This happens on both 1.2.x (1.2.12.Final) and 1.3.x (1.3.10.Final).

              sdouglas1@redhat.com Stuart Douglas (Inactive)
              ankinson Andy Wilkinson (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: