Changing log levels in Log4j2

How do you change log levels in Log4j 2 when the Logger API does not have a setLevel() method?

The Configurator class provides several methods to change levels in Log4j. An important feature to understand before using these APIs is that logger names are hierarchical, see Refining Logging with Hierarchical Loggers.

Configurator.setAllLevels(String, Level)

The Configurator.setAllLevels(String, Level) method sets the level of the given named logger and all child loggers. Recall that in Log4j, loggers are hierachical. If you have the loggers com.foo.acom.foo.b, and com.foo.c, and you call setAllLevels("com.foo", Level.DEBUG) then all the loggers I listed will be set to DEBUG as will "com.foo". A logger "com.bar" will remain as is.

Configurator.setLevel(Map<String, Level>)

The method Configurator.setLevel(Map<String, Level>) will set each named logger to its Level from the map. No child loggers will be affected unlike setAllLevels(String, Level).

For example:

Map&amp;lt;String, Level&amp;gt; map = new HashMap&amp;lt;&amp;gt;();
map.put(&quot;com.foo&quot;, Level.DEBUG);
map.put(&quot;com.bar&quot;, Level.DEBUG);
Configurator.setLevel(map);

This will set the loggers "com.foo" and "com.bar" to DEBUG but no existing child loggers of either will be affected. If you create a new child logger though, that child logger will inherit its level from its parent.

Configurator.setLevel(String, Level)

The method Configurator.setLevel(String, Level) sets the named logger to the given level without affecting child loggers (unlike setAllLevels(String, Level)).

Configurator.setRootLevel(Level)

Finally, Configurator.setRootLevel(Level) sets the level of the root logger to the given level without affecting child loggers. The root logger is the topmost logger with a name of "" (the empty string).

Happy Coding,
Gary Gregory

All about Java 9

These videos are all about Java 9 from the Devoxx conference:

Thanks to Arnaud Héritier for gathering these links for the Maven dev mailing list.

The Java lowercase conversion surprise in Turkey

You can convert Strings to lowercase in Java with String.toLowerCase().

The following code will work anywhere in the world except Turkey:

import java.util.Locale;

public class LocaleTest {

  @Test
  public void test() {
    Assert.assertEquals("title", "TITLE".toLowerCase());
  }

}

In Turkey, this will give you:

org.junit.ComparisonFailure: expected:<t[i]tle> but was:<t[?]tle>
	at org.junit.Assert.assertEquals(Assert.java:115)
	at org.junit.Assert.assertEquals(Assert.java:144)
	at com.garygregory.util.LocaleTest.testBug2(LocaleTest.java:23)
	... 24 more

Why is that?

Under the covers, the call to toLowerCase() becomes toLowerCase(Locale.getDefault()), and of course getDefault() changes depending on your country. So what really happens in Turkey is toLowerCase(Locale.forLanguageTag("TR"))).

In the Turkish locale, the Unicode LATIN CAPITAL LETTER I becomes a LATIN SMALL LETTER DOTLESS I. That’s not a lowercase “i”.

If you index maps with String keys that include the letter I and you normalize keys to lowercase, your program will have a bug when running on the Turkish locale.

How are you supposed to deal with that?! Well, luckily, you can use a Locale that does not perform such conversions, namely Locale.ENGLISH and more generically, Locale.ROOT.

You defensively written code becomes one of:

Assert.assertEquals("title", "TITLE".toLowerCase(Locale.ENGLISH));
Assert.assertEquals("title", "TITLE".toLowerCase(Locale.ROOT));

If you write your code “in English”, the Locale.ENGLISH is fine, but consider Locale.ROOT for more general support.

Java defines Locale.ROOT as:

/**
 * Useful constant for the root locale. The root locale is the locale whose
 * language, country, and variant are empty ("") strings. This is regarded
 * as the base locale of all locales, and is used as the language/country
 * neutral locale for the locale sensitive operations.
 *
 * @since 1.6
 */
static public final Locale ROOT = createConstant("", "");

As a reminder, Java provides localization support with the java.util.Locale class, from the Javadoc:

A Locale object represents a specific geographical, political, or cultural region. An operation that requires a Locale to perform its task is called locale-sensitive and uses the Locale to tailor information for the user. For example, displaying a number is a locale-sensitive operation— the number should be formatted according to the customs and conventions of the user’s native country, region, or culture.

The Locale class implements IETF BCP 47 which is composed of RFC 4647 “Matching of Language Tags” and RFC 5646 “Tags for Identifying Languages” with support for the LDML (UTS#35, “Unicode Locale Data Markup Language”) BCP 47-compatible extensions for locale data exchange.

For further experimentation, the following Java system properties affect how Java initializes the default locale:

  • user.language
  • user.region
  • user.script
  • user.country
  • user.variant

Here is the full source code code for the test:

package com.garygregory.util;

import java.util.Locale;

import org.junit.Assert;
import org.junit.Assume;
import org.junit.ComparisonFailure;
import org.junit.Test;

public class LocaleTest {

  private static final Locale TURKISH = Locale.forLanguageTag("tr");

  @Test
  public void testBug1() {
    Assume.assumeTrue(Locale.getDefault() != TURKISH);
    Assert.assertEquals("title", "TITLE".toLowerCase());
    Assert.assertEquals("title", "TITLE".toLowerCase(Locale.getDefault()));
  }

  @Test(expected = ComparisonFailure.class)
  public void testBug2() {
    Assert.assertEquals("title", "TITLE".toLowerCase(TURKISH));
  }

  @Test
  public void testFix() {
    Assert.assertEquals("title", "TITLE".toLowerCase(Locale.ENGLISH));
    Assert.assertEquals("title", "TITLE".toLowerCase(Locale.ROOT));
  }

}

In summary, use toLowerCase(Locale.ROOT) instead of toLowerCase() for internal maps.

Happy Coding,
Gary Gregory

The Art of Logging: An exploration with Apache Log4j 2

I’ll be giving my talk “The Art of Logging: An exploration with Apache Log4j 2” at the South Bay Java User’s Group, Thursday, November 19, 2015 at 6:30 PM. Come check it out if you are in the area! For more details, please visit http://www.meetup.com/South-Bay-JVM-User-Group/events/226362027/

The Art of Logging: Advanced message formatting

In this post, I’ll show you how to format your Log4j logging message like a pro.

Let’s start with a bland and inefficient logging statement:

logger.debug("There are " + getUserCount() + " users logged in now.");

This is lame for three reasons:

  1. You are always building the full string before calling debug()
  2. You are always calling getUserCount()
  3. Both of the above happens even if debug logging is disabled!

In the old days of logging, you avoided these problems with more code like this:

if (logger.isDebugEnabled()) {
  logger.debug("There are " + getUserCount() + " users logged in now.");
}

This is quite verbose and unnecessary if you are using Log4j 2. Instead, use this:

logger.debug("There are {} users logged in now.", getUserCount());

We’ve removed one level of lameness: the final string is only built when debug logging is enabled. The complete message only gets built when debug logging is enabled: the “{}” parameter marker is replaced by the value returned by getUserCount(). The getUserCount() method is still called whenever the debug() method is called. That part is still Lame.

As I point out in this post, Log4j 2.4 and Java 8 come to the rescue with lambdas to clean this up as follows:

logger.debug("There are {} users logged in now.", () ->; getUserCount());

All lameness is now removed:

  • The getUserCount() function is only called when debug logging is enabled. This happens because the expression “() -> getUserCount()” does not call the getUserCount() method before debug() is called. Instead, Java creates a block of code that Log4j executes later, if it needs the result.
  • The complete message is only built with the result of getUserCount() when debug logging is enabled.

The only possible drawback is that the getUserCount() function is called a little later in the code path which could be an issue if the method relies on precise and exact timing or position on the stack, that would be unusual but possible.

Next up is the actual format of the message.

Using “{}” parameter markers causes Log4j to call toString() on each argument you pass to logger methods like debug().

This is ugly when it comes to printing large numbers for example:

There are 2147483647 users logged in now.

Instead, I want something that looks civilized like this:

There are 2,147,483,647 users logged in now.

You can do this using a different kind of logger and a format string:

Logger logger = LogManager.getFormatterLogger();
logger.debug("There are %,d users logged in now.", () -> getUserCount());

A formatter logger let’s you use patterns like “%,d” and all the power of the stock Java java.util.Formatter class.

You can format numbers like this as well:

logger.debug("Gain or loss: $ %(,.2f", delta);

Gives you:

Gain or loss: $ (12,582.19)

You can get extra fancy with dates:

Calendar c = new GregorianCalendar(1918, MAY, 11);
logger.info("Richard Feynman's Birthday: %1$tb %1$te, %1$tY", c);

Gives you:

Richard Feynman's: May 11, 1918

Super powerful, super nice.

The only caveat is that you will not get the same performance out of a formatter logger as you would out of the default logger. Still, pretty neat.

Happy Coding,
Gary Gregory

The Art of Test Driven Development: Running unit tests conditionally

There comes a time where Java’s promise of “write once, run anywhere” breaks down for some of us. In my case and my Windows users, file paths present platform specific challenges. This article will show you how to run unit tests conditionally; only on Windows for example.

I talked about conditionally ignoring tests in JUnit in the past, but I’d like to revisit this topic in a little more detail.

I have an application that uses URIs for file references, but for most sane Windows users, a file reference is something like E:\some\folder\foo.txt, not file:///E:/some/folder/foo.txt. Is it ‘file’, a colon, and two slashes, or three, or four? Darn!

To make life easier for normal and power users, the application supports both Windows paths and URIs. The application converts Windows file paths to URIs internally and everyone’s happy. How do you unit test this? Just as always, you say. The trick comes when your build runs on a farm of Windows and Linux boxes, and some of your carefully crafted tests pass on Windows but fail on Linux for obtuse reasons that are not the point of this write up. The bottom line is that I want to run certain tests on Windows only. Fortunately, JUnit provides a nice way to do this using its Assume class.

Here’s how you do it:

private static final boolean IS_WINDOWS =
  System.getProperty("os.name").startsWith("Windows");

@Test
public void testMeOnWindows() {
  Assume.assumeTrue(IS_WINDOWS);
  …
}

We first set a Boolean constant that indicates that we are running on Windows or not. To do that, we simply lookup the os.name system property and check that it starts with the String “Windows”.

The JUnit Assume class causes JUnit to ignore a test if the given condition fails. In our example, the test method will only proceed on Windows; but the test will not fail.

A failed assumption does not mean you have a bug or that the test failed, it means that JUnit should not continue running the test and not mark it as a failure. JUnit test runners will skip tests will failing assumptions. Your mileage may vary with other test runners.

Assume checks can be for any condition, giving you and your tests a lot of flexibility.

Under the hood

How does JUnit do this? When you call an Assume method like assumeTrue(), the following appens:

public static void assumeTrue(boolean b) {
  assumeThat(b, is(true));
}

JUnit calls the more general assumeThat() method with a Hamcrest matcher from org.hamcrest.CoreMatchers.is(T):

public static <T> void assumeThat(T actual, Matcher<T> matcher) {
  if (!matcher.matches(actual)) {
    throw new AssumptionViolatedException(actual, matcher);
  }
}

The expression matcher.matches(actual) uses Hamcrest to evaluate your condition and returns true if it passes. If your condition fails, the method assumeThat() throws an AssumptionViolatedException; which JUnit uses to implement assumptions. The JUnit guts catch these exceptions and handle them differently than other exceptions by adding the assumption violation to a list it uses in its reports.

There you have it, JUnit assumptions give your tests an extra level of flexibility by allowing you to run tests conditionally.

Happy Coding,
Gary Gregory