Ask HN: Best practices for log format?

As part of my current role, I setup and managed a unified logging infrastructure as part of a SIEM install. We're talking ingesting logs in the order of TBs a day (Lots). Here are my observations:

1. Syslog type logs are great when the volume is low, but field extraction can be a pain (unless you're a Regex savant)

2. Structured logs are nice to deal with. Fairly easy to read and a dream to parse. Make sure you have a good ETL process in place to process these logs so they are searchable. 3. If you have a lot of logs, they are only as good at the usability of the search on that corpus of text.

I use Splunk to ingest the logs and once the extractions are in place, it is a dream to search. Other options like ELK are available and work pretty well too.

Show the devs the advantages of having structured logs indexed and ready to search. No more: SSH > cat | grep | tail | less | more

Real-time functionality and the ability to alert on certain conditions is an added bonus.

Have you looked into https://brandur.org/logfmt?

Having lived with various points between the 'awesome to read' and 'simplest to parse' I currently favor simpler parsing and investing in tooling that makes manual parsing of logs easier.

Of course the decision should include the scale of the microservices. There would be no benefit in optimizing too much for readability if the number of requests to your services is so high that you would need complex filtering before you can look at them.

Another way to cut down the bike shedding is to go with a library that wraps around the format you choose. We built GitHub.com/clever/Kayvee and have changed the format a few times. However since everyone uses the kayvee libraries at Clever it's not too crazy to change the format.

Hopefully this was useful. Apologies for the disconnected paragraphs - on public transit :)

What part of making everyone happy are you struggling with? Logging is simple, don't over-complicate it, just dump plaintext to a file.

If Ops really need those features they can have a process read the logs and ingest them into whatever system they want. Plaintext with the fields the devs want (time stamp, severity, etc) is easily parsable. Don't underestimate what you can do with tail and a few scripts.

If you are micro-services based architecture, then it is very important to track and log a request through the multi-service calls and relate the logs.

Syslog with a common UUID set at the entry point (typically at proxy or load balancer level e.g. nginx) of the request and then logger will log the UUID as the part of UUID parameter of Syslog.

Syslog then can be parsed and also form JSON objects for the poeple in Ops and send it to a service. Basically you could have one more internal micro-service to handle logs from Syslog and then parse it and send it wherever Ops would need.

We generate structured logs, I.e. key-value pairs. Depending on the environment they are either formatted with logfmt or JSON. This serves our use cases quite well.

Imo json gives you the most flexibility and adds as much metadata the developer (applocation side) and ops (in case you use an orchestratiom such as kubernetes, etc) need.

Eg in kubernetes it's pretty common for applocations to log everything in json, kubernetes will then wrap the app logs in another layer of json that includes information about the container name, id, host ip, etc.

Microservices and containers will most likely require you to have some centralized way to view your logs (kibana etc) so ops and devs can create their own views.

Even in the basic case of tailing log files you can use a jq alias with a custom format to convert the json logs to something colorful and readable.

Ps. On mobile so i apologise for possible mistakes

We developed a common logging module that we include in our micro services to log to json. It also takes in environment variables so we can include the deployment related information to identify and query the logs once they get centralized to splunk.

> traditional timestamp

As as sysadmin I implore you use ISO 8601 format, preferably with the UTC offset.

    2017-04-27T09:43:04Z

      NOTE: ISO 8601 defines date and time separated by "T".
      Applications using this syntax may choose, for the sake of
      readability, to specify a full-date and full-time separated by
      (say) a space character.

JSON feeded into ElasticSearch works pretty well for us. I was a bit sceptical about it a first moment since I was used to grep classic logs in /var/log/, but it's actually really good. Kibana allows you to have a bunch of dynamic criteria for the logs, and filtering obviously JSON is better than randomly grepping a thing in text. I cant think of any other solution than files in /var/log, and a thing from top of my head which annoys me in text logs - when you dont know when exactly something happened (eg. before midnight or after a midnight?), you have to grep two files (expecting you have one log file per day). Also to grep the files, you need to have an access to the servers, but the fewer people have the access there, the better.

If folks want a fancy format they can always use AWK to reformat the beautifully readable developer logs. Anyway why use Elastic Search when you could use Splunk?

If folks want a fancy format they can always use AWK to reformat the beautifully readable developer logs. Anyway why use Elastic Search when you could use Splunk?

Converting a structured format into a human-readable form is relatively easy. Parsing unstructured logs is hard.

This is a node module but the idea can be applied generally (https://github.com/trentm/node-bunyan). Basically you output the logs in the format ops require(Which i assume would be structured) and for devs put a beautifier that parses the logs and prints in the format they require.

All applications should generate JSON logs.

The transport system (syslog usually) will take care of time stamping and some meta data.

application => (JSON text) => syslog daemon => (syslog message) => graylog/ELK/splunk

Being in a situation where logs are not read, or can't be read, is very similar to not having logs. So it's important to emphasize formatting and productivity when it comes to logs.

JSON can be useful. You can use jq (https://stedolan.github.io/jq/manual/) and common unix commands to parse logs (grep to filter, wc -l to count results, sort|uniq to get unique results, colrm to truncate lines, cut to get fields)... using those can be as powerful as using a query language.

Then, you can use a log aggregator to have access to all your logs. ElasticSearch/Kibana can be useful for that. Commercial services such as Splunk or SumoLogic can also be very helpful.

My preference is:

2017-04-27T02:46:20.762-07:00 [$level] $message

Where $level is one of [debug, info, warn, error] and $message is a string log message.

If your working with distributed systems may want to add $hostname between the date and level.

Full example:

2017-04-27T02:46:20.762-07:00 web4 [warn] unable to connect to mobile interface

On one really large project with lots of microservices that generated requests to lots of other microservices, we ended up using JSON logs and some convention. We had libraries in all the languages we were using (php, node js, go, python, c / c++) that followed the convention.

The convention was simple. Every log MUST have at least these three parameters: --action, --r, and --t, and one optional one: --p.

--action would be the "subject" of the message with a dot notation. A lot of times it's simply class.method or class.method.something.finished.

--r is the "request" hash. This hash represented everything that has happened in the current process to handle whatever was asked of it. So for a web request, the --r would start as the request came in from nginx, and the --r would end when the response was sent back.

--t is the "thread" hash. If the calling process sent a --t parameter, use that. Otherwise, generate a new one.

--p is the "parent" hash. If the calling process sent a --r parameter, set that as --p. Otherwise, don't add it.

All of this was automated in the logging libraries. So generally a developer would simply call Log.d('whatever', {something: 'something something'}) or Log::d('whatever', ['something', 'something else']);

Requiring those four params allows us a couple fantastic things. First, highlighting the --action field made it a lot like looking at your inbox. Every message had a subject; This made for very simple skimming. Second, when hunting errors, it was very easy to find all the other related log messages by searching for the matching --r(equest) value. Third, for larger processes that sometimes involved tens of servers, it was easy to generate a tree of the entire request from start to finish, by simply using the --t(hread), --p(arent), and --r(equest) values.

These logs were all sent to rsyslog, which forwarded all logs to a central server (Also running rsyslog), which kept up beautifully. Besides handling the collection and transport for us, it was great to be able to watch the logs centrally - and then on each server when necessary - just by tailing /var/log/syslog. I had written a couple parsers for our logs on the central server, but eventually, as the project grew, our logs became far too much to handle with simple tailing apps, so we went with ELK (Elasticsearch, Logstash, Kibana).

Back then we used Logstash for the conversion, but on recent projects, I've just used rsyslog's @cee plugin, which skips the "L".

And, over time, we'd added a few more indices that worked well with kibana dashboards and tables. The two most useful were --i and --ms.

An --i parameter was simply an incrementing int starting at 0 for every new --r(equest hash). Lots of times our logs came in out of order, so having an explicit incrementing value in the log messages was really handy. An --ms parameter was for milliseconds. Any log message that had timed something included an --ms message. That was most excellent for dashboards.

Also, all hashes were simply truncated SHA1 hashes. For instance, on the API server, we explicitly took the server IP, request URI, headers, parameters and a timestamp (to the ms), hashed it, and truncated to 12 chars. Any collisions were generally spread out apart enough in time that they weren't an issue.

The only thing I can add to everyone else's replies is: VERSION IT.

This will allow you to write a parser which parses all versions of your log format, whichever such versions are – based on the version… and allow you to amend the log format at any time without worry that suddenly your old logs aren't going to be compatible with new ones.

"we" use this even for Apache access log files, and it's one small thing which has helped a ton.

General rule: writing logs is a means, not an end, so whoever reads it most gets to decide what it should look like.

Corollary 1: allow developers to use whatever they see fit for DEBUG logging.

Corollary 2: require single-line json for everything else (if your developers have to read lots of production logs, you probably have a bigger problem than your log format)

You will need something to have ops filter DEBUG lines out.

Options:

- disallow having DEBUG logging in production

- separate log file for DEBUG logging

- start each line with the log level

Also: give the developers a tool that converts the 'one json line per event' file to what they want. Configure less and other tooling to know about it.

Optionally, tweak the json serializer used in logging to always output the time stamp, severity, and short description at the start of the line.

Do not invent your own formats.

There is an RFC for structured logging [1]

Also, journald does structured logging, plus indexing and searching like a simple database and it's designed for your use case. It can receive the logs and forward them using a connector for ElasticSearch [2]

[1] https://tools.ietf.org/html/rfc5424 [2] https://www.loggly.com/blog/why-journald/

   journalctl -f -o json | send-logs remote-server

Not directly answering your question but

1) fluentd[0] can be used to parse diverse log formats

2) You can set an environment variable, e.g. `ENV`, and output to a more human readable format when `ENV=development`.

[0] https://github.com/fluent/fluentd/

    maybe a JSON object in many lines with details about the
    request, possibly with blank lines and indentation to make
    everything very easy to read

Pretty-printing the JSON is a presentation concern - it shouldn't be baked into what's being written to the logs.

JSON-formatted log files can be pretty-printed by tools like the Logfile Navigator:

http://lnav.org

That should make the decision a lot easier.

If you're using a configurable logging library like logback for Java, it is fairly easy to have your application support both structured logging directly to Elasticsearch, and logging a more human readable format to disk or stderr for development.

It would be nice if there was a standard format you could just ship to a logging service, but the closest seems to be syslog, which is somewhat janky.

Re-parsing logs after they have been formatted for human consumption feels like an anti-pattern motivated by anemic logging libraries.