Structured logging to journald from within a docke

Question

What is the best way to write structured logs to journald from within a docker container?

For example, I have an application that writes using sd_journal_send Rather than change the app, I have tried passing through

-v /var/log/systemd/journal:/var/log/systemd/journal

It works on the my Ubuntu 16.04 desktop, but not on the CoreOS instances where the app runs (which use the Ubuntu 16.04 base image). I don't quite understand why. Perhaps there is a better way to send to the journal?

What limitations does the docker journald output logging option have? It didn't appear it supported apps writing more than just the message field.

--

So I have found I need -v /dev/log:/dev/log

But there is also another problem in that there is no association to the service file that starts the docker container. Manually adding UNIT: servicename.service didn't solve it. And so when looking at and shipping logs for the service, it's associated with the exe but not the container or service. Whose encountered these problems and how have you solved them?

-- Ok let me expand this a bit.

A C program can write to the systemd journal like this:

#include <systemd/sd-journal.h>
#include <unistd.h>
#include <stdlib.h>

int main(int argc, char *argv[]) {
        sd_journal_send("MESSAGE=Hello World!",
                        "MESSAGE_ID=52fb62f99e2c49d89cfbf9d6de5e3555",
                        "PRIORITY=5",
                        "HOME=%s", getenv("HOME"),
                        "TERM=%s", getenv("TERM"),
                        "PAGE_SIZE=%li", sysconf(_SC_PAGESIZE),
                        "N_CPUS=%li", sysconf(_SC_NPROCESSORS_ONLN),
                        NULL);
        return 0;
}

This writes to the journal and adds custom fields like HOME, TERM, PAGE_SIZE etc. When I use journalbeat to ship them to the ELK stack, those fields end up nicely in elasticsearch and I can search on them directly.

However, it seems that docker, simply takes the stdout of apps, and feeds it to the journald with only a few fields it adds itself. e.g. CONTAINER_ID.

When using programs like this inside a docker container and then running them from a service file it creates a slight problem.

1) I have to pass through some directories and device files to get it to write with sd_journal_send.

2) if you start the container from a systemd .service file and expect to use journalctl -u servicename and see the messages, those log messages aren't seen because they went into the journal a different route and don't get associated with the service that ran them.

3) You can add some arbitary fields/tags using docker's journald logging driver, they are fixed, one time additions that will appear on every message sent and are unchanging. They are not dynamic fields like I want from the C code above.

Essentially, the journald log driver is insuffient in my case.

Any suggestions on how both to link the service name so journalctl -u shows up the log messages from sd_journal_send? as that would fix it then.

-- I've found a solution. I'll put the answer below in case others are interested in how I've solved it.

Answer 1

You need to mount the socket on which journald listens. In case of ubuntu it is /run/systemd/journal/socket. Map this insider you docker container and it would work fine

Figured that out using strace on your sample code

sendmsg(3, {msg_name(29)={sa_family=AF_LOCAL, sun_path="/run/systemd/journal/socket"}, 
msg_iov(23)=[{"CODE_FILE=test.c", 16}, {"\n", 1}, {"CODE_LINE=13", 12}, {"\n", 1}, {"CODE_FUNC=main", 14}, {"\n", 1}, 
{"MESSAGE=Hello World!", 20}, {"\n", 1}, {"MESSAGE_ID=52fb62f99e2c49d89cfbf"..., 43}, {"\n", 1}, {"PRIORITY=5", 10}, {"\n", 1}, 
{"HOME=/home/vagrant", 18}, {"\n", 1}, {"TERM=xterm-256color", 19}, {"\n", 1}, {"PAGE_SIZE=4096", 14}, {"\n", 1}, 
{"N_CPUS=1", 8}, {"\n", 1}, {"SYSLOG_IDENTIFIER=", 18}, {"a.out", 5}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 208

And test it in ubuntu docker container using below

docker run -v /run/systemd/journal/socket:/run/systemd/journal/socket -v $PWD:/jd -it -w /jd ubuntu:16.04 ./a.out

And I get a entry in journalctl -f (on host)

Aug 15 21:40:33 vagrant a.out[11263]: Hello World!

Answer 2

The eventual solution turned out to be really simple.

I switched to writing my messages as pure json. So journalctl -u now works and shows the MESSAGE field now containing json data.

I then used journalbeat to send that to logstash.

To logstash.conf I added:

filter {
  json {
    source => "message"
  }
}

What this does is it expands the json data from the message field into separate fields at the top level before sending them to elasticsearch.

Details about the json filter for logstash can be found here