Logging To Papertrail From CoreOS

Posted on January 30, 2016 by Bryan Rockwood

TL;DR Give me the script…

Here at C2FO, we are in the process of switching our deployment system over to CoreOS and Docker. One of the services we wanted to utilize from our legacy configuration was Papertrail but there was a problem. While Papertrail integrates really well with older logging tools like Syslog, there wasn’t a simple solution which integrated well with CoreOS’ journald logging system. Performing a quick Google search led to the following on Papertrail’s discussion site:

journalctl -o short -f | ncat --udp <address> <port>

The “address” and the “port” above are available for your account under Settings ⇨ Log Destinations. While this solution works, it is not very reliable for a couple of reasons:

  • Because we run everything inside of Docker containers, log entries would show up as coming from the “docker” process instead of the underlying systemd unit name.
  • The pipe to ncat does not stop if ncat fails. So, if the connection to Papertrail were to die, the systemd unit file that runs this code would never enter a failed state.

Let’s take a look at how we solved the first part.

JSON and jq To The Rescue

The first issue we ran in to was that the “journalctl -o short” output was missing a key piece of information. Here’s the output from one of our boxes:

Jan 30 23:08:38 example.c2fo.com docker[23519]: c2fo.server.private DEBUG - logger.go:116: Completed 200 OK in 82.54µs

With our services now running in a Docker container, every service is reported via the “short” output as coming from a Docker PID, the docker[23519] above. This made it incredibly difficult to find specific services via the Papertrail search tools. A neat feature of journald, though, is that “short” is not the only output format supported. A quick search of the journalctl help page led us to JSON as one of the supported formats which looks like this (I xxx’ed out some things we do not care about to make the output a little cleaner):

{
	"__CURSOR" : "xxxxxxxxxxxxxxxxxxxx",
	"__REALTIME_TIMESTAMP" : "1454195918925104",
	"__MONOTONIC_TIMESTAMP" : "763088682268",
	"_BOOT_ID" : "xxxxxxxxxxxxxxxxxxxx",
	"PRIORITY" : "6",
	"SYSLOG_FACILITY" : "3",
	"_SELINUX_CONTEXT" : "system_u:system_r:kernel_t:s0",
	"_MACHINE_ID" : "xxxxxxxxxxxxxxxxxxxx",
	"_HOSTNAME" : "example.c2fo.com",
	"_TRANSPORT" : "stdout",
	"SYSLOG_IDENTIFIER" : "docker",
	"_UID" : "500",
	"_GID" : "500",
	"_COMM" : "docker",
	"_EXE" : "/usr/bin/docker",
	"_CMDLINE" : "/usr/bin/docker run --name c2fo-app -e NODE_ENV=prod -p 1234:1234 c2fo-app:latest",
	"_CAP_EFFECTIVE" : "0",
	"_SYSTEMD_CGROUP" : "/system.slice/c2fo-app.service",
	"_SYSTEMD_UNIT" : "c2fo-app.service",
	"_SYSTEMD_SLICE" : "system.slice",
	"_PID" : "23519",
	"MESSAGE" : "c2fo.server.private DEBUG - logger.go:116: Completed 200 OK in 82.54µs"
}

Journald provides a number of fields in that JSON but the important piece that we want is the _SYSTEMD_UNIT field. Luckily, CoreOS comes preinstalled with jq, a tool which “…is like sed for JSON data”. Perfect. So, setting the output from journalctl to JSON, we pipe it to the following:

jq -r --unbuffered '"\(.__REALTIME_TIMESTAMP | tonumber / 1000000) \(._HOSTNAME) \(._SYSTEMD_UNIT // .UNIT // .SYSLOG_IDENTIFIER): \(.msgtype = (.MESSAGE | type) | if .msgtype == "array" then (.MESSAGE | implode) else .MESSAGE end)"'

If you’re interested in a quick overview of the jq output format, you can run through a tutorial on their website. Here are a few gotchas that we ran in to:

  • –unbuffered — This argument makes sure that everything piped to jq is immediately output and not buffered.
  • \(.__REALTIME_TIMESTAMP | tonumber / 1000000) — This takes the __REALTIME_TIMESTAMP field, converts it to a number and then divides that number by 1000000 to get seconds from microseconds.
  • \(._SYSTEMD_UNIT // .UNIT // .SYSLOG_IDENTIFIER) — We wanted to send all log output from journald to Papertrail, not just our services. To make sure we have the unit name instead of the process name, we wanted to print the _SYSTEMD_UNIT field. Unfortunately, not all log entries come from units so that field could be blank. So, we check for the systemd unit name. If that field is not set, then try outputting the straight unit name, .UNIT, and finally, the Syslog identifier.
  • \(.msgtype = (.MESSAGE | type) | if .msgtype == “array” then (.MESSAGE | implode) else .MESSAGE end) — This one was interesting. Under certain circumstances, a log message will be returned as a JSON array of bytes instead of a string. This expression will store the JSON type in .msgtype and then check if it is an arrray. If it is, then use the implode function to convert it to a string. Otherwise, the expression will use the message as is.

This leads to the following output:

1454196428.940741 example.c2fo.com c2fo-app.service: c2fo.server.private DEBUG - logger.go:116: Completed 200 OK in 82.54µs

So close! Unfortunately, the time at the beginning is not in a standard logging format. This is where the command line tool awk steps in:

awk '{ $1=strftime("%b %d %T", $1); print $0; fflush(); }'

The command is pretty straight forward. We are taking the first column and running it through “strftime” to get the correct time format. One important take away is the “fflush();” at the end. Just like “–unbuffered” above, this tells awk to immediately dump the text it is working on so there is no delay.

The final command we came up with looks like this:

journalctl -o json -f | jq -r --unbuffered '"\(.__REALTIME_TIMESTAMP | tonumber / 1000000) \(._HOSTNAME) \(._SYSTEMD_UNIT // .UNIT // .SYSLOG_IDENTIFIER): \(.msgtype = (.MESSAGE | type) | if .msgtype == "array" then (.MESSAGE | implode) else .MESSAGE end)"' | awk '{ $1=strftime("%b %d %T", $1); print $0; fflush(); }' | ncat <address> <port>

Unfortunately, a busted pipe became a huge problem….

That Busted Pipe Issue

The command above works incredibly well until the ncat section of the pipe fails. When that happens, and it will due to a network hiccup or Papertrail’s endpoint becoming temporarily unavailable, the processes further up the pipe chain will not know of the failure and continue. This will lead to errors from awk in the local journald logs but nothing new in Papertrail. The systemd unit we run this in did not fail since the very first command, the journalctl, has not crashed. This is where coproc comes in. Using this shell command, we are able to move the netcat to the front of the command. Let’s break this apart.

The coproc command sets up pipes to stdin and stdout of the process that is called. Additionally, we add logic that if the ncat process fails, keep trying to reconnect:

coproc netcat { while true; do ncat <address1> <port>; done ;}

We redirect all output for that shell to the coproc pipe:

exec >&${netcat[1]} 2>&1

Here is the final one liner:

coproc netcat { while true; do ncat <address1> <port>; done ;};exec >&${netcat[1]} 2>&1;journalctl -o json -f | jq -r --unbuffered '"\(.__REALTIME_TIMESTAMP | tonumber / 1000000) \(._HOSTNAME) \(._SYSTEMD_UNIT // .UNIT // .SYSLOG_IDENTIFIER): \(.msgtype = (.MESSAGE | type) | if .msgtype == "array" then (.MESSAGE | implode) else .MESSAGE end)"' | awk '{ $1=strftime("%b %d %T", $1); print $0; fflush(); }'

This can be used in an ExecStart section of a systemd unit file or broken up into a script.

If you find this useful, please let us know! Thanks go out to Robert Fairburn @ c2fo.com for providing the coproc fix for the netcat issue!