SPIKE: Formalize the type of logs we want filecoin to produce

[frrist]

Description

We need to make a decision on what type of logs we want filecoin to produce and where we want said logs to be stored / viewable. Currently, filecoin is capable of producing 2 types of logging metrics using go-log.

Go-Log

Filecoin uses go-log, go-log is capable of producing Leveled Logs (currently human readable message on stdout) and and Traces (ndjson where each line repesents a span) via the opentracing spec.

A point of debate has been whether or not we should add a 3rd logging facet for Event logs. This would be something separate from the Leveled Logs and Traces, capable of producing structured messages, that have a human and machine readable format.
I am of the opinion that a Span from a trace can be used to represent an Event log (since it already contains structured data and is machine readable -- meaning it can be transformed into something that is human readable)

Leveled Logging

Leveled (DEBUG, INFO, ERROR) Logs are written to stderr when the filecoin daemon starts. These logs are human readable by default and can be enabled/disabled based on priority.

Open Questions:

• Should these be written to a file by default?
  • If so, where?
• Do these need a machine readable format?
  • If so, should the human or machine readable format be the default?
• What levels do we want to support, currently we use DEBUG, INFO, WARN, and ERROR.

Traces

Here a log line in the code:
https://github.com/filecoin-project/go-filecoin/blob/13f7311efa541cd4a02d0a91c02685d1490ca7ae/node/node.go#L656-L660

Here is the corresponding log line collected from the log tail command:

{"TraceID":4618426481524616321,"SpanID":4306752283975776193,"ParentSpanID":0,"Operation":"Node.CreateMiner","Start":"2018-08-28T14:51:09.042771951-07:00","Duration":840650,"Tags":{"error":true,"system":"node"},"Logs":[{"Timestamp":"2018-08-28T14:51:09.043612184-07:00","Fields":[{"Key":"error","Value":"couldn't get next nonce: actor not found"}]}]}

Here is an example of log lines viewed as a trace using Jaeger (generated from ipfs add -r <file>)
https://user-images.githubusercontent.com/6546409/34731105-2d315a84-f516-11e7-9722-7e3b1a15cbb7.png

Currently these logs are generate on demand when a user runs the go-filecoin log tail command.

Open Questions:

• Should these be written to a file by default?
  • If so, where?
• Do these need a human readable format?
• Do we think these can be used to represent event logs, or do we need something separate from this?

Related Work

• Observability Design
• Kitty Hawk Design

[whyrusleeping]

I would not write anything to a file by default. That's something elses responsibility, not filecoins.

Having both human and machine readable output modes for things is always good, why not both?

Traces and Event logs seem like the same thing to me. (and in fact, thats how it currently works, IIUC)

[phritz]

Should these be written to a file by default?

Yes. If I'm running a thingy and it logs I would expect the log to be output to a file so if it crashes or stops or whatever I can go look and see what it was doing. Logging to files also keeps a nice separation between log types. Typically you have a log file for each level that includes the ones above it, but I don't really care about that.

If so, where?

'/var/log/' is pretty standard but you could log in a subdir if you wanted.

Do these need a human readable format?

Level logs are generally human readable. If a machine needs to read something then obv it should be machine-readable. Seems more important for traces & events to be machine-readable.

Do we think these can be used to represent event logs, or do we need something separate from this?

Make a proposal. Define what "event" means in the context of filecoin, what the requirements are, and how it is used and then say how using traces achieves that. Seems like there's an existing mechanism that works, you just have to tell everyone how it works.

[frrist]

We are sending mixed messages here

I would not write anything to a file by default

Yes. If I'm running a thingy and it logs I would expect the log to be output to a file

Perhaps we could add a flag option that will cause logs to be written to a file instead of stdout -- I think that satisfies both of the above points.

Make a proposal. Define what "event" means in the context of filecoin

Okay, I will add definitions for leveled, event, and trace logging in the observability design doc

[phritz]

There's nothing stopping you from writing logs to a file and to stdout at the same time.

[frrist]

If we want to write logs to a file, we should do it explicitly -- using a command like tee or similar. If we start logging to a file by default we will need to import a package like https://github.com/natefinch/lumberjack to handle the rollover of the files, this seems like a lot of extra work for not a lot of gain.

[whyrusleeping]

@phritz why can't we just let the supervisor (systemd, launchd, etc) handle the logs that we spit out to stderr? Thats what most applications I know of do. Writing to a file has a lot of side effects, and is a lot of extra code and work that we really shouldnt have to deal with.

[phritz]

I don't know about any side effects or extra code, writing to a file shouldn't be any different than writing to stdout. Don't worry about log truncation locally, and in the cloud use one of a million possible log truncators/rotators. Having said that...

I guess the only potential issues with using stdout/err are:

• comingling different kinds of logs in one stream, making that stream harder to use. I'm OK with dealing with this if it becomes a problem.
• logs persisting beyond the lifetime of the process. If we use syslog this is not a problem.
• application log lines making the syslog basically unusable for anything other than the application because the app is so loggy/spammy. I'm ok with this if you are.

So, go for it.

[frrist]

Here is a PR that adds support for file logging and sys logging (controlled via env vars), this also leaves logging to stderr in place - ipfs/go-log#46

Will use this issue to track the PR's progress.

[frrist]

Changes bubbled up here ipfs/go-log#49 - closing as the go-log PR addresses the issue