Monday, July 28, 2014

Log4j 2.0 Async loggers and immutability

One of the headline grabbing things that people seem to be raving about over Log4J 2.0 is async loggers.

Now do not get me wrong, they are great… as long as you know what you are doing.

If you are using async loggers you had better make sure you are only passing immutable objects to your loggers, because otherwise you may end up logging the state of your objects at the time of the log record being written and not the time you called log.

Now there are many other good reasons why you should use immutable objects for your logging, but async logging is the tipping point.

A few years ago I was burned by this exact class of problem in a conferencing call bridge, where we had a log message recording the participants that were actively talking (i.e. their volume was greater than the threshold). Spurious line noise would result in messages like:

Bob has started talking, Bob’s volume is 1, threshold is 64
Bob has stopped talking, Bob’s volume is 120, threshold is 64

Which was a result of the mutable object that held the volume for Bob being changed by the media server in between creating the log record and writing the log record to disk.

Consider the following simple test class:

package test;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import java.util.concurrent.atomic.AtomicLong;
public class App {
    private static final AtomicLong value = new AtomicLong();
    public String toString() {
        return Long.toString(value.get());
    }
    public long next() {
        return value.incrementAndGet();
    }
    public static void main(String[] args) {
        for (int i = 0; i < 32; i++) {
            new Thread() {
                final Logger logger = LogManager.getLogger(App.class);
                final App instance = new App();
                @Override
                public void run() {
                    for (int i = 0; i < 100000; i++) {
                        logger.warn("{} == {}", instance.next(), instance);
                    }
                }
            }.start();
        }
    }
}

Now run this code...

Here is the first few lines of logging output

2014-07-28 15:59:45,729 WARN t.App [Thread-13] 13 == 13 
2014-07-28 15:59:45,730 WARN t.App [Thread-29] 29 == 29
2014-07-28 15:59:45,729 WARN t.App [Thread-15] 15 == 15
2014-07-28 15:59:45,729 WARN t.App [Thread-6] 6 == 6
2014-07-28 15:59:45,730 WARN t.App [Thread-30] 30 == 30
2014-07-28 15:59:45,729 WARN t.App [Thread-20] 20 == 20
2014-07-28 15:59:45,729 WARN t.App [Thread-8] 8 == 8
2014-07-28 15:59:45,730 WARN t.App [Thread-28] 28 == 28
2014-07-28 15:59:45,729 WARN t.App [Thread-19] 19 == 19
2014-07-28 15:59:45,729 WARN t.App [Thread-18] 18 == 18
2014-07-28 15:59:45,729 WARN t.App [Thread-5] 5 == 6
2014-07-28 15:59:45,731 WARN t.App [Thread-13] 33 == 37
2014-07-28 15:59:45,731 WARN t.App [Thread-8] 39 == 39
2014-07-28 15:59:45,731 WARN t.App [Thread-28] 40 == 41
2014-07-28 15:59:45,731 WARN t.App [Thread-18] 42 == 43
2014-07-28 15:59:45,731 WARN t.App [Thread-5] 43 == 43

Spot anything wrong with that?

Now of course I have written the class to have mutable state… because I wanted to test if Log4J 2.0 was capturing the toString() at the time of logging… which it isn’t.

So if you have an object with a toString() method that depends on mutable state, you will have to:

  • Check that the logger is enabled for the logging level
  • Call toString() by hand
  • Pass the toString() result as the parameter.
To make my previous code work with Asynchronous loggers (other than by fixing the mutable state) I would need to log like this:
if (logger.isWarnEnabled()) {
    logger.warn("{} == {}", instance.next(), instance.toString());
}

Yep, we are back to that old pattern.

TL;DR Unless you know that every parameter object passed to a log statement is using immutable objects, enabling Asynchronous loggers in Log4J may well result in logs with messages you cannot trust.  

Update

Here is the log4j2.xml configuration file I used

<?xml version="1.0" encoding="UTF-8"?>

<!-- Don't forget to set system property
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
to make all loggers asynchronous. -->

<Configuration status="WARN">
<Appenders>
<!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
<RandomAccessFile name="RandomAccessFile" fileName="async.log" immediateFlush="false" append="false">
<PatternLayout>
<Pattern>%d %p %c{1.} [%t] %m %ex%n</Pattern>
</PatternLayout>
</RandomAccessFile>
</Appenders>
<Loggers>
<Root level="info" includeLocation="false">
<AppenderRef ref="RandomAccessFile"/>
</Root>
</Loggers>
</Configuration>

Which is the example on the Log4j Website

Thursday, January 30, 2014

If you don't like Maven, you would not be a good manager...

We have all had the bad technical managers… the ones who tell you to go and do something… and then micromanage the task they have “delegated” to you.

They are a pain to work for.

One of the qualities of a good manager is to tailor their delegation to the people they are delegating to.

So they task Gillian, a senior engineer, with “writing some smoke tests to verify that the application works when deployed to the app server” and they are happy to let Gillian work within that scope because they trust that Gillian will come back to seek clarification if the description is lacking, or if there are issues down the road.

Kevin, a junior engineer, on the other hand, has proven over many many tasks to need more detail, so they give Kevin a more detailed written description of the task and they check in on Kevin as he is going along… because Kevin has proven that he needs a certain level of micromanagement… the good manager is all the time testing to see if Kevin can survive with less micromanagement.

Note: one of the biggest cognitive distortions of bad managers is the thinking that in order to treat everyone fairly, you must treat everyone equally. If we did that then either Gillian gets micromanaged which is unfair to Gillian or Kevin gets under-managed which is unfair to Kevin.

So, what does all that have to do with liking Maven?

Well Maven is a build tool. If you need Maven to build a .war file, you should just tell it to build a .war file

<project>
  <groupId>…</groupId>
  <artifactId>…</artifactId>
  <version>…</version>
  <packaging>war</packaging>
  <dependencies>
    ...
  </dependencies>
</project>

Why do you want to micromanage Maven and tell it every little thing it must do to build the .war file. Wait until you see what it did with your instructions, then and only then should you refine your instructions.

So… If you don't like Maven, you would not be a good manager… The corollaries are not necessarily true though...

  • Liking Maven does not mean you will be a good manager… there are other qualities that make a good manager… understanding when and how to micromanage is only one of those qualities
  • Being a good manager does not mean you will like Maven… for example if all your developers (who love to micromanage and thankfully are not managers because of their micromanagement adoration) tell you that Maven is a pain… well a good manager will hear what their team is saying and take it on board… after all they are there to manage, not to do… if they were to see a Maven build where it has not been micromanaged by the developers, then a different view they will form.

Wednesday, November 06, 2013

Jenkins' Maven job type considered evil

There are two ways to build a Maven project with Jenkins*

  • Use a free-style project with a Maven build step
  • Use a Maven-style project
The first way runs the build as Maven intended. The second way adds a whole lot of hooks and can even modify the build in ways that Maven did not intend.
 
The first way requires that you configure stuff yourself. The second way tries to “guess” what you want and auto-configure it.
 
The first way is initially less user friendly, i.e. you have more UI to click through to get the full set of reports. The second way is initially more user friendly… but when things go wrong… well sorry out of luck.
 
If something goes wrong with the first way, worst case you add a shell build step above the Maven build step that just runs SET, trigger a build, login to the build slave, switch to the user the build is running as, apply the environment your SET build step output and then run the Maven command that the build’s console log captured. That will give you an exact reproduction of the Maven build and you can debug why your build is not working.
 
When something goes wrong with the second way, well good luck. By all means try to do the same as you would for a free-style project, but at the end of the day, there is no way you can replicate the injected hooks that Jenkins puts into your Maven build. You can get an approximate reproduction, and hey, that may just be enough to let you figure out what is wrong and fix your build… but there are cases where you cannot.
 
Hence why, since 2007, I have been saying that the Maven job type is considered evil…
  • It has very attractive because is easy to configure (so users use it) and gives nice per-module reports
  • When it blows up, and it will blow up, it blows up big

-Stephen

* well actually three ways if you include the literate job type

Friday, April 19, 2013

About test coverage

I was given a link to yet another article preaching about how 100% code coverage is the only goal (the article is preaching, not Tatu BTW)

There is an issue I have with how the 100% coverage advocates present their argument, but we'll get to that later.

The case for 100% coverage is put quite simply:

Anything less than 100% coverage means that there are some lines in your code that are untested, and are you seriously willing to let code be released without being tested?

Now if your code is 100 lines long, and you have 95% coverage, 5 lines doesn't seem too bad. In fact looking at the code coverage report you see those 5 lines, and you make a judgement call that they are an acceptable risk. No harm done, right?

When the code grows to 1,000 lines long, 95% coverage is giving you less of that warm and fuzzy feeling, but a quick scan of the coverage report and you can visually check the 50 lines untested, and you make a judgement call that they are an acceptable risk. No harm done, right?

With a 10,000+ LOC code base and 95% coverage and your boss wants to know if it is OK to push this code into production now, the 500+ uncovered lines that you need to review are now much more than a headache…

Are you a convert now? Do you believe in 100% coverage? It's a nice argument. But there is a flaw… in some cases that is!

When you are dealing with a dynamically typed language, especially some of the more expressive ones, the only tests you can have are the tests you write yourself. In those languages, the 100% coverage zealots have me sold (at least for code that needs to be maintained and is longer than 100 lines or so!)

But in different languages we can, and do, have additional tests that are provided by tooling:

  • Syntax tests that verify that every line of code is syntactically correct
  • Scoping tests (in languages that force declaring names before first use within a scope) that verify that each line only accesses those names within the correct scope for the line.
  • Type tests (in statically typed languages) 

And that's not all… most of the code I write runs on the JVM, there are more tests I can add to the mix when on the JVM

  • Static analysis tools, such as Checkstyle, PMD and Findbugs provide an additional set of tests that I can run automatically on my code looking for common problems and possible mistakes. In fact I've found and fixed bugs with Findbugs in code that had 100% coverage already.
  • Annotation's in code can be used to, not only document the code contracts, but aid and assist Findbugs in catching bugs. Specifically I am referring to the @CheckForNull and @NonNull annotations. I apply these annotations to the production code, and there are tests applied to the code for free by the toolchain I use

So when I am writing Java code, every line I write already has at least five tests covering it and I haven't even started adding unit tests into the mix!

Now I am not arguing that the above tests are enough for your code on it's own… but when you look at my unit test coverage at 83.7% and ask am I "happy to ship with 1,630 untested lines of code", I will answer that those 1,630 lines of code are tested, they may not be our best tests, but we have tests on them.

Show me a real code base with 100% coverage, and I will show you a good number of crappy tests helping that code base get to 100% coverage...

On the other hand, if you ask me am I happy to ship that Ruby on Rails / Node.JS / etc application into production with 99.5% coverage, I'll say no way are we shipping that code with 50 untested LOC.

Monday, February 04, 2013

Note to self: Updated usejava BASH function for MacOSX

For use when you have multiple JVM providers (Apple & Oracle), you want to be able to switch between JDKs for each CLI

usejava ()
{
    local sel=$1.jdk
    if [ -x "/Library/Java/JavaVirtualMachines/jdk$sel/Contents/Home/bin/java" -a ! -x "/Library/Java/JavaVirtualMachines/$1/Contents/Home/bin/java" ]
    then
        sel=jdk$sel
    fi
    local base=/Library/Java/JavaVirtualMachines
    if [ -x "/System/Library/Java/JavaVirtualMachines/$sel/Contents/Home/bin/java" ]
    then
        base=/System/Library/Java/JavaVirtualMachines
    fi

    if [ -z "$1" -o ! -x "$base/$sel/Contents/Home/bin/java" ]
    then
        local prefix="Syntax: usejava "
        for i in /Library/Java/JavaVirtualMachines/* /System/Library/Java/JavaVirtualMachines/*
        do
            if [ -x "$i/Contents/Home/bin/java" ]
            then
                /bin/echo -n "$prefix$(basename $i | sed -e "s/^jdk//;s/\.jdk$//;")"
                prefix=" | "
            fi
        done
        /bin/echo ""
    else
        if [ -z "$JAVA_HOME" ]
        then
            export PATH=$base/$sel/Contents/Home/bin:$PATH
        else
            export PATH=$(echo $PATH|sed -e "s:$JAVA_HOME/bin:$base/$sel/Contents/Home/bin:g")
        fi
        export JAVA_HOME=$base/$sel/Contents/Home
        echo -n -e "\033]0;$(java -version 2>&1 | sed -e "s/.*\"\(.*\)\".*/Java \1/;q")\007"
    fi
}

There is additional fun to be had, given that most Java based launchers that try to fix JAVA_HOME when not set will guess the Apple JVM path… so the following Java program can help

public class FixJavaHome {
  public static void main(String[] args) {
  	String javaHome = System.getProperty("java.home");
  	if (javaHome.endsWith("/jre")) {
  		javaHome = javaHome.substring(0,javaHome.length() - "/jre".length());
  	}
    System.out.println("export JAVA_HOME=\""+javaHome+'\"');
  }
}

Install like so

mkdir -p ~/bin/FixJavaHome && cd ~/bin/FixJavaHome && cat > FixJavaHome.java <<EOF
public class FixJavaHome {
  public static void main(String[] args) {
  	String javaHome = System.getProperty("java.home");
  	if (javaHome.endsWith("/jre")) {
  		javaHome = javaHome.substring(0,javaHome.length() - "/jre".length());
  	}
    System.out.println("export JAVA_HOME=\""+javaHome+'\"');
  }
}
EOF
javac FixJavaHome.java
cd -

If you add the following to your ~/.bash_profile

eval $(java -cp ~/bin/FixJavaHome/ FixJavaHome)
echo -n -e "\033]0;$(java -version 2>&1 | sed -e "s/.*\"\(.*\)\".*/Java \1/;q")\007"

Then your JAVA_HOME should be set up from the start, as well as your Terminal window title