feature: machine-readable logging

[btc]

updated:

This PR adds support for machine-readable logging. Here's the skinny:

The eventlog package extends our existing logging functionality to provide structured, machine-readable logs. It exposes the eventlog.Logger which wraps the util.Logger, making it a drop-in replacement.

var log = eventlog.Logger("dht")

func processMsg() error {
    log.Debugf("msg received from %s", p.ID.Pretty()) // delegated to existing util.Logger

    log.Event(ctx, "messageReceived", p, pbmsg) // goes to the machine-readable logger
}

By implementing the Loggable interface, objects marshal themselves into map[string]interface{} with keys that are consistent across the entire project.

type Loggable interface {
  Loggable() map[string]interface{}
}

By default, logs are written to ~/.go-ipfs/logs/events.log as line-delimited JSON. This can be overridden at config initialization or updated from the CLI with ipfs config. The init override flag has not yet been exposed.

{"event":"sentMessage","localPeer":{"id":"EiCsOiFNw0RDqkoNuVeGtGoz4JrHVdLoZhOBhU7dbaSOCg==","latency":0},"message":{"type":"PING"},"system":"dht","time":"2014-11-16T14:04:45.554426994Z","remotePeer":{"id":"EiCwSlfUDsoTiAnxOadrEgRDM8N0A5HJvxzp2OIaeSEL/Q==","latency":0}}

Log initialization is performed as a pre-command hook. We take care to not read the config when the executing command will not read the config.

Now we can grep our logs and transform them for protocol-agnostic analysis.

func main() {
    f, _ := os.Open("events.log")
    r := bufio.NewReader(f)
    for {
        ldjson, _, err := r.ReadLine()
        if err != nil {
            return
        }
        json, _ := simplejson.NewJson(ldjson)
        e, _ := json.Get("event").String()
        fmt.Println(e)
    }
}

interfaceListenAddresses
interfaceListenAddresses
sentMessage
interfaceListenAddresses
interfaceListenAddresses
sentMessage

future work

• implement leveled logging (we need to decide what levels we want for the structured logs)
• expose a flag to override log directory
• remove the logrus dependency

dependencies
logrus (MIT) aims to provide functionality similar to our eventlog package. While leveraging logrus allows us to keep our package small while we iterate on the design, I recommend we move off of this once we make decisions about 1) leveled logging and 2) alternatives to statically importing var log = Logger(package) in client packages.

lumberjack (MIT) provides log file rotation. I predict it will be quite useful as a medium/long-term dependency.

additional info

• this package is very loosely connected to util.Logger. If desired, we can easily separate it entirely. I left them together to ease the transition.

[btc]

@whyrusleeping @jbenet @mappum

At this point, there's one particular design decision I would like some feedback on:

It's important to be standardize the keys used to logged metadata. In the ideal case, when logging peers in metadata, they're logged under the same key system-wide. This is a subset of the signifiers in use today:

local_peer
peer
peer_id
remote_peer
remote_peer_id
partner
provider
provider_id

We only really need two keys: local_peer, remote_peer. For all of the roles a peer can play, we derive sufficient information from the logged event name. For example:

provider -> dht:provide
partner -> exchange:bitswap:send,exchange:bitswap:receive

To make this work with minimal effort, it would be ideal to be able to generate log events without specifying remote/local. One idea is to let peers carry a type (Unspecified (default), Local, Remote). This way, by implementing the Loggable interface, programmers don't need to explicitly state remote/local every time they log. To reduce chance of error, we default to Unspecified.

// simple logging
log.Debug(ctx, ..., peer)
// peer is Remote so Loggable returns an appropriate map[string]val

Please critique early and often. Thanks.

ps. NB: I've added methods to the Peer interface. I have a proposal for cutting down on the Peer interface and making global peer-management safer, but implementation of this is out of the scope of this PR. (In short, we would perform create, get, and modify operations on the Peerstore itself. The Peer interface would become read-only)

[cleichner]

I don't have good context for this, but is it a good idea to commit a private key?

[whyrusleeping]

Yeah, it's fine since its just for testing.

[btc]

^ Yeah. This is a unit-test mock.

[cleichner]

Great! I was just browsing through and wanted to make sure.

[jbenet]

@cleichner thanks for checking. btw, lots of security stuff in IPFS is not yet done correctly. (like we store the keys we generate in your config file). no one should assume ipfs is secure yet.

[dborzov]

@jbenet , how should the keys be stored then ideally?

[btc]

This branch is pretty far behind master at the moment. I'd like to rebase. Anyone working on this actively?

[whyrusleeping]

i havent touched it, youre good to go as far as im concerned

[btc]

SGTM. Rebasing now.

@whyrusleeping here's a preview of the logging output:

18:33:02.164  INFO        dht: {"event":"sentMessage","localPeer":{"id":"EiC0y+qq4qAzdTbqZVZU8K1Gdl2Hb5g8qiwAAm4o9ge4Ag==","latency":0},"message":{"type":"PING"},"unspecifiedPeer":{"id":"EiCwSlfUDsoTiAnxOadrEgRDM8N0A5HJvxzp2OIaeSEL/Q==","latency":0}} log.go:64
18:33:02.165 DEBUG        dht: Sent message type: 'PING' to [Peer QmaCpDMGvV2B] dht.go:198

[btc]

I will document the API so it's more accessible. Here's a brief outline of my intentions for this PR.

• document API
• post API documentation here for review
• revise API based on CR
• set up new logging backend for Events (rotated files)

backend
what backend do we want to use for these event logs? file? syslog? rotated files

packages
Please suggest packages you'd like to see integrated. I'll prioritize one of the suggested packages in order to demonstrate functionality and focus the review.

[btc]

@whyrusleeping @mappum @jbenet ready for code review

[jbenet]

i think we can cross that bridge when people ask for it?

[btc]

+1

[jbenet]

@maybebtc a few random comments but everything here LGTM!!

[btc]

@jbenet merge when LGTU

rebased and merged

#movefastandfixthings

[jbenet]

This snuck in. i only caught it in my email. Let's not do this pattern. Please pass in a writer, if you want to redirect (or silence) the ouput

[btc]

It's not to silence the output. It's to protect the messages from being accidentally modified by someone making changes to the identity code. Otherwise we'll face regressions.

[dborzov]

@maybebtc , cudos, so cool!! 👍

@maybebtc , you are saying you are going to work on API documentation for this now? I should stay in tune to make sure it can be picked up by NetVis right away.

In this example:

     {"event":"sentMessage","localPeer":{"id":"EiCsOiFNw0RDqkoNuVeGtGoz4JrHVdLoZhOBhU7dbaSOCg==","latency":0},"message":{"type":"PING"},"system":"dht","time":"2014-11-16T14:04:45.554426994Z","remotePeer":{"id":"EiCwSlfUDsoTiAnxOadrEgRDM8N0A5HJvxzp2OIaeSEL/Q==","latency":0}}

does localPeer stand for the peer who received the message and know logs it and remotePeer is the sender?

[btc]

Yes. localPeer is the logger of the message. localPeer sent a message to remotePeer

[jbenet]

I should stay in tune to make sure it can be picked up by NetVis right away.

And it's okay if we have to feed ipfs log output through an ipfs-to-netvis transformer script.