Log format is difficult to parse

[ghost]

The log format produced by consul is rather difficult to parse when attempting to build a multiline filter pattern for logstash. I have several different applications submitting their logs to the server and therefore would like an standardised pattern. Due to consul adding spaces to log messages, it causes problems when defining the pattern.

consul/command/agent/command.go

Line 554 in 8defe75

c.Ui = &cli.PrefixedUi{

    c.Ui = &cli.PrefixedUi{
        OutputPrefix: "==> ",
        InfoPrefix:   "    ",
        ErrorPrefix:  "==> ",
        Ui:           c.Ui,
    }

Example Filter

filter {
  multiline {
    pattern => "^\s"
    what => "previous"
  }
}

Example Log Output

==> WARNING: Bootstrap mode enabled! Do not enable unless necessary
==> WARNING: It is highly recommended to set GOMAXPROCS higher than 1
==> Starting Consul agent...
==> Starting Consul agent RPC...
==> Consul agent running!
         Node name: '10.0.255.5'
        Datacenter: 'dc1'
            Server: true (bootstrap: true)
       Client Addr: 0.0.0.0 (HTTP: 8500, HTTPS: -1, DNS: 8600, RPC: 8400)
      Cluster Addr: 10.0.255.5 (LAN: 8301, WAN: 8302)
    Gossip encrypt: true, RPC-TLS: false, TLS-Incoming: false
             Atlas: <disabled>

==> Log data will now stream in as it occurs:

    2015/11/24 11:41:05 [INFO] serf: EventMemberJoin: 10.0.255.5 10.0.255.5
    2015/11/24 11:41:05 [INFO] serf: EventMemberJoin: 10.0.255.5.dc1 10.0.255.5
    2015/11/24 11:41:05 [INFO] raft: Node at 10.0.255.5:8300 [Follower] entering Follower state
    2015/11/24 11:41:05 [INFO] consul: adding server 10.0.255.5 (Addr: 10.0.255.5:8300) (DC: dc1)

Expected Log Output

==> WARNING: Bootstrap mode enabled! Do not enable unless necessary
==> WARNING: It is highly recommended to set GOMAXPROCS higher than 1
==> Starting Consul agent...
==> Starting Consul agent RPC...
==> Consul agent running!
         Node name: '10.0.255.5'
        Datacenter: 'dc1'
            Server: true (bootstrap: true)
       Client Addr: 0.0.0.0 (HTTP: 8500, HTTPS: -1, DNS: 8600, RPC: 8400)
      Cluster Addr: 10.0.255.5 (LAN: 8301, WAN: 8302)
    Gossip encrypt: true, RPC-TLS: false, TLS-Incoming: false
             Atlas: <disabled>

==> Log data will now stream in as it occurs:

2015/11/24 11:41:05 [INFO] serf: EventMemberJoin: 10.0.255.5 10.0.255.5
2015/11/24 11:41:05 [INFO] serf: EventMemberJoin: 10.0.255.5.dc1 10.0.255.5
2015/11/24 11:41:05 [INFO] raft: Node at 10.0.255.5:8300 [Follower] entering Follower state
2015/11/24 11:41:05 [INFO] consul: adding server 10.0.255.5 (Addr: 10.0.255.5:8300) (DC: dc1)

[ryanuber]

The original indentation gave us very easy visibility when the UI would output something using the ==> prefix, as the left-most column is empty otherwise. In practice though, this has only ever been used during initailization, and for Checkpoint to notify the user of potential security vulnerabilities or software updates.

You should still be able to get multi-line to work. The ^\s won't work as-is, not only because of the prefix, but also because if we do have a multi-line message, it does not get indented in the same way (it will start at position 0). You could get this going by using the negate = "true", and matching leading spaces or the ==> marker. Dealing with these differences in logging systems is an unfortunate reality, but that is where using multiple grok's really shines to bring it all together.

Hope that helps!

[slackpad]

Closing this out per the suggestion in #1446 (comment).

[mterron]

@slackpad should the interactive use case drive the user experience? I'd argue that the automated log collection and analysis is way more common than "the operator looking at the console output" and therefore an easily machine consumed format should be the standard.

[slackpad]

@mterron that's a fair point, though these are only shown a startup, which is pretty common for people to see interactively when people are using to learn Consul. We can revisit this if we change to a different logging library that may also support more structured logging / alternate formats. I don't have an ETA on that, but it is something we are thinking about.

[mterron]

That's good to know @slackpad . Just removing the indentation from the beginning of log lines will make consumption much easier without being a major change I think.

Cheers

[slackpad]

Hmm - I'll kick this open again for now.

[mterron]

Since it's still being considered, the date in ISO8601 format would be great! I'll dig into the code and see if I can come up with a painless PR.

[mterron]

OK, I'm the worst golang practitioner ever (read as this is the first time I tried to do anything with it).

To format the date, this seems to work without using any fancy packages:
https://play.golang.org/p/RC9JxV_LaA

I'm not quite sure where I can use that snippet within Consul though. @slackpad can you take a look? Seem to be a simple change but I don't know about how to integrate with the consul codebase.

Thanks!

[michalgasek]

Just in case someone out there is trying to get logs parsed...
Below works very well for me with CloudWatch Logs agent:

$ cat /var/awslogs/etc/config/consul.conf 
[/var/log/upstart/consul.log]
datetime_format = %Y/%m/%d %H:%M:%S
multi_line_start_pattern = (==>\s|\s{3}\d{4}/\d{2}/\d{2}\s\d{2}:\d{2}:\d{2})
file = /var/log/upstart/consul.log
log_stream_name = {instance_id}-{hostname}-{ip_address}
log_group_name = /var/log/upstart/consul.log

[mrwulf]

Similar to @michalgasek , this config has been working well for filebeat... (with all of the puppet-config goodness...):

  filebeat::prospector{ 'consul':
    paths        => [ '/var/log/consul', ],
    input_type   => 'log',
    ignore_older => '24h',
    fields       => {
      'app' => 'consul',
    },
    multiline    => {
      'pattern' => '"^(==>\s|\s+\d{4}/\d{2}/\d{2}\s)"',
      'negate'  => false,
      'match'   => 'after',
    },
  }

[Priyankam8]

Hii all,
what would be config that works with rsyslog agent in order to get consul logs parsed?
Thanks.

[jstoja]

@mrwulf You probably meant negate => true as you select the lines that shouldn't be considered as multiline.
@slackpad I add my grain of sand as I find the date prepended by space being the only exceptions in our logs in the middle of hundred of apps... The overall convention seem to be that multiline is handled when line starts with spaces (which is easy to parse and easy to read).
I find it sad that logs readability for developers is preferred over logs parsing for the whole team.

[hanshasselberg]

This has improved dramatically since using hclog. You can now even get json formatted logs.

[pekuz]

I'm reopening, the log messages format is still difficult to parse and unnecessary indented.

My expectation is that:

• either the log message format could be customized using a configurable pattern or
• log message "humanization" (indentation and sections) applies only in -dev mode

Thank you for considering.