Wednesday, December 23, 2015

Looking for problematic logging with JUnit

Stefan Birkner's System Rules is one of my favorite JUnit extension libraries. I commonly use it to verify System.out and System.err, for example validating audit trail logging.

Growing tired of the same boilerplate, I rolled some simple rules into an aggregated JUnit @Rule, called NiceLoggingRule. It enforces:

  • No logging to System.err
  • No WARN or ERROR logging to System.out

A more sophisticated version would let the user decide on more than "log level" as to what is an acceptable log line, but it gives a good demonstration of writing complex JUnit rules:

public final class NiceLoggingRule
        implements TestRule {
    private static final Pattern NEWLINE = compile("\n");

    private final SystemOutRule sout = new SystemOutRule().
            enableLog().
            muteForSuccessfulTests();
    private final SystemErrRule serr = new SystemErrRule().
            enableLog();

    private final Pattern logLinePattern;
    private final Predicate<String> problematic;
    private final RuleChain delegate;

    public NiceLoggingRule(final String logLinePattern,
            final Predicate<String> problematic) {
        this.logLinePattern = compile(logLinePattern);
        this.problematic = problematic;
        delegate = outerRule(NiceLoggingStatement::new).
                around(sout).
                around(serr);
    }

    @Override
    public Statement apply(final Statement base,
            final Description description) {
        return delegate.apply(base, description);
    }

    private final class NiceLoggingStatement
            extends Statement {
        private final Statement base;
        private final Description description;

        private NiceLoggingStatement(final Statement base,
                final Description description) {
            this.base = base;
            this.description = description;
        }

        @Override
        public void evaluate()
                throws Throwable {
            base.evaluate();
            checkSystemErr(description);
            checkSystemOut(description);
        }

        private void checkSystemErr(final Description description) {
            final String cleanSerr = serr.getLogWithNormalizedLineSeparator();
            final List<String> errors = NEWLINE.splitAsStream(cleanSerr).
                    collect(toList());
            if (!errors.isEmpty())
                fail("Output to System.err from " + description + ":\n"
                        + cleanSerr);
        }

        private void checkSystemOut(final Description description) {
            final String cleanSout = sout.getLogWithNormalizedLineSeparator();
            final List<LogLine> problems = NEWLINE.splitAsStream(cleanSout).
                    map(LogLine::new).
                    filter(LogLine::problematic).
                    collect(toList());
            if (!problems.isEmpty())
                fail(problems.stream().
                        map(Object::toString).
                        collect(joining("",
                                "Problems to System.out from " + description
                                        + ":\n", "")));
        }
    }

    private final class LogLine {
        @Nonnull
        private final String line;
        @Nonnull
        private final String level;

        private LogLine(@Nonnull final String line) {
            final Matcher match = logLinePattern.matcher(line);
            if (!match.find()) // Not match! Ignore trailing CR?NL
                fail(format(
                        "Log line does not match expected pattern (%s): %s",
                        logLinePattern.pattern(), line));
            this.line = line;
            level = match.group("level");
        }

        public boolean problematic() {
            return problematic.test(level);
        }

        @Override
        public String toString() {
            return line;
        }
    }
}

For example, using it with Spring Boot's default log pattern one might write a factory helper:

public final class SpringDefaultNiceLoggingRule {
    private static final String logLevels = Stream.of(LogLevel.values()).
            filter(level -> OFF != level).
            map(Enum::name).
            collect(joining("|"));

    public static NiceLoggingRule springDefaultNiceLoggingRule() {
        return new NiceLoggingRule(
                "^(?<timestamp>\\d{4,4}-\\d{2,2}-\\d{2,2} \\d{2,2}:\\d{2,2}:\\d{2,2}\\.\\d{3,3}) +(?<level>"
                        + logLevels + ") +",
                SpringDefaultNiceLoggingRule::problematic);
    }

    private static boolean problematic(final String level) {
        return 0 > INFO.compareTo(LogLevel.valueOf(level));
    }
}

Then a simple Spring Boot unit test becomes:

@RunWith(SpringJUnit4ClassRunner.class)
@SpringApplicationConfiguration(classes = MockServletContext.class)
public final class RootControllerTest {
    @Rule
    public final NiceLoggingRule niceLogging = springDefaultNiceLoggingRule();

    private MockMvc mvc;

    @Before
    public void setUp()
            throws Exception {
        mvc = standaloneSetup(new RootController()).build();
    }

    @Test
    public void shouldGetRoot()
            throws Exception {
        mvc.perform(get("/").
                accept(APPLICATION_JSON_UTF8)).
                andExpect(status().isOk()).
                andExpect(jsonPath("$.message", equalTo("Hello, world!")));
    }
}

Monday, December 21, 2015

RESTful helper script

I find this script useful working on modern RESTful services. It shows both the headers and the formatted JSON response body. The idea is that most times you provide a URL and want to see the full response. If you need extra flags for curl just add them (e.g., user/password). If you want to customize jq—say, filter for just a particular piece of the response—use a double-dash ("--") to separate curl and jq arguments:

An example with Spring Boot (plus some custom actuator endpoints). Note "jq" colorizes the output on the command line (below is plain text):

$ ~/bin/jurlq http://localhost:8081/remote-hello/health
HTTP/1.1 200 OK
Server: Apache-Coyote/1.1
Strict-Transport-Security: max-age=31536000 ; includeSubDomains
X-Application-Context: remote-hello:8081
Content-Type: application/json;charset=UTF-8
Transfer-Encoding: chunked
Date: Mon, 21 Dec 2015 13:28:07 GMT

{
  "status": "UP",
  "cpu": {
    "status": "UP",
    "processors": 8,
    "system-loadavg": -1,
    "process-cpu-load": 0.22963892677420872,
    "process-cpu-time": "PT42.71875S",
    "system-cpu-load": -1
  },
  "file": {
    "status": "UP",
    "usable-disk": 55486464000,
    "total-disk": 299694551040
  },
  "java": {
    "status": "UP",
    "start-time": "2015-12-21T07:27:06.970-06:00",
    "uptime-beats": 0,
    "vm-name": "Java HotSpot(TM) 64-Bit Server VM",
    "vm-vendor": "Oracle Corporation",
    "vm-version": "25.66-b17"
  },
  "memory": {
    "status": "UP",
    "committed-virtual-memory": 991350784,
    "free-physical-memory": 1952854016,
    "free-swap-space": 1203003392,
    "total-physical-memory": 8540618752,
    "total-swap-space": 10354229248
  },
  "os": {
    "status": "UP",
    "arch": "amd64",
    "name": "Windows 10",
    "version": "10.0"
  },
  "threads": {
    "status": "UP",
    "count": 22,
    "daemon-count": 20,
    "peak-count": 22,
    "started-count": 26
  },
  "diskSpace": {
    "status": "UP",
    "free": 55486464000,
    "threshold": 10485760
  },
  "configServer": {
    "status": "UNKNOWN",
    "error": "no property sources located"
  },
  "hystrix": {
    "status": "UP"
  }
}

UPDATE: Tried Github Gist for the source, but it does not show in my blog feed reader. Here's the script:

#!/bin/bash

curl_args=()
for arg
do
    case "$arg" in
    -- ) shift ; break ;;
    * ) curl_args=("${curl_args[@]}" "$arg") ; shift ;;
    esac
done

jq_args=("${@-.}")

curl -s -D - "${curl_args[@]}" | tr -d '\r' | {
    while read line
    do
        case "$line" in
        '' ) echo ; break ;;
        * ) echo "$line" ;;
        esac
    done

    exec jq "${jq_args[@]}"
}

Saturday, December 19, 2015

Spring REST showcase

I've noodled for some time now at mini-projects showcasing Spring REST with as many bells and whistles as I could pack in before it broke. I've never reached a satisfactory conclusion, which is more a testament to my mercurial temperament than to Spring. My ideal project would include:

  • No XML, if avoidable (Lombok, I'm looking at you)
  • No properties files (thank you, Spring YAML support)
  • Annotations and code generation (thank you, Spring Boot and Lombok)
  • Good documentation (Swagger and RAML, why do you need to be so tricky?)
  • Complete REST adherence (HATEOAS, you are still an ugly child, sorry to say that)
  • Modern Java
  • No external container (Spring Boot to the rescue!)
  • Many example integration points (and this is why I stay with you Spring)
  • Maven build (sorry Gradle, I gave up makefiles so I would never again debug my build)
  • Production support (Spring actuator: genius; see OSI)
  • Cloud support
  • Full CD pipeline (Boxfuse, you may save me yet; Github and Travis, you're still the best)

Essentially I want to implement a showcase REST microservice adhering to Larry Wall's three great virtues of a programmer: Laziness, Impatience and Hubris.

Well, there's always yet another Github repo.

Updates I'll keep updating this post as I find new things to desire in a showcase project.