Less is more when it comes to Travis CI logs

Originally published on the Codecraft at Vaamo Blog

There is always a little adrenaline surge when I see one of my commits failing on Travis, which we use to continuously integrate our projects. Since we try to keep a linear commit history and a master that is always deployable, I naturally want to get the build green as fast as possible, which means I want to find out quickly what went wrong.

The problem

The backend for our app is written in Scala and our tests are all written in Scalatest. Also we use sbt to build and test our project. As a result our Travis build log had about 5,000 lines total output, of which around 1,500 read something along the lines of:

[info] Resolving org.scoverage#scalac-scoverage-plugin_2.11;0.98.4 ...
[info] Resolving commons-io#commons-io;2.4 ...
[info] Done updating.
[info] Updating {file:/home/travis/build/Vaamo/vaamo-backend/}vaamo-backend...

… Followed by about 2,500 lines of successful tests with 10 lines somewhere in the middle that tell you about the actual error. Not ideal, is it?

The solution

So here is what I did to improve the situation:

1. Reduce output of the ScalaTest runner

Sbt allows us to supply arguments to the ScalaTest runner which enables us to filter out certain events that are raised during testing. As of ScalaTest 2.2.2 you can disable all output except output for failed tests.
When doing this I recommend enabling the Unformatted mode to see not only the name and reason for failure of the failed test but also the suite the test is located in.

testOptions in test in Test := Seq(
  Tests.Argument(TestFrameworks.ScalaTest, "-oUNCXHELPOQRM")
)

2. Filter superfluous sbt output

Removing all the superfluous messages related to dependency resolution was a little bit more effort. Paul Phillips seemed to have had the same problem recently and solved it by filtering the output of sbt using grep and a couple of regular expressions. Unfortunately his solution does not work on the coloured sbt output because terminal escape codes aren’t matched by the regexes. So, here is my improved solution that keeps colored output intact.

#!/usr/bin/env bash
# Licensed under the Apache License, Version 2.0
# Adapted from https://github.com/paulp/psp-std/blob/master/bin/test

runTests () {
  sbt test || exit 1
  echo "[info] $(date) - finished sbt test"
}

stripTerminalEscapeCodes () {
  sed -r "s/\x1B\[([0-9]{1,2}(;[0-9]{1,2})?)?[mGKM]//g"
}

mkRegex () { ( IFS="|" && echo "$*" ); }

filterOutput() {
  while read line; do
    if ! [[ $(echo $line | stripTerminalEscapeCodes) =~ $excludeRegex ]] ; then
      echo $line
    fi
  done
}

main() {
  # sbt output filter
  local excludeRegex=$(mkRegex \
    '\[info\] (Resolving|Loading|Updating|Packaging|Done updating)' \
    're[-]run with [-]unchecked for details' \
    'one warning found'
  )

  echo "[info] $(date) - starting sbt test"
  (set -o pipefail && runTests |& filterOutput)
}

main $@

So in the end we brought down the build log to 1,800 lines, of which most are hidden by the automatic folding feature of Travis. We are now able to spot the failed tests much more quickly and as an added benefit, we now notice compiler warnings we hadn’t really seen before.

The code is also on github.