Extra 'noise' error messages

[whyrusleeping]

In the normal course of operations in the DHT we throw a large number of error messages like the ones shown in the following gist:

https://gist.github.com/whyrusleeping/c8bdc6163ea29f54a3ba

This is because when we receive the value we are looking for from one peer, with an outstanding request with another, we simple cancel the context, and remove the 'callback' for that request. This becomes an issue if the other peer finally responds, as it looks like an error to us.

I propose that when we cancel the context for a request like this, instead of removing the entry, we 'void' it, or mark it stale. and then when the call times out, or the peer responds, we simply note that its voided, remove the entry and return.

[btc]

Sounds good.

Going forward, "got a response from peer, but I was too late. One already arrived" is probably a useful DHT event to be aware of. Same goes for bitswap as well.

[whyrusleeping]

Yeah, especially if that happens very often, it shows inefficiency in the network

[btc]

You guys okay with me removing this log output?

15:58:18.173 NOTIC  merkledag: setting logger: "merkledag" to DEBUG log.go:78
15:58:18.174 NOTIC net_messag: setting logger: "net_message_adapter" to DEBUG log.go:78
15:58:18.174 NOTIC      dagio: setting logger: "dagio" to DEBUG log.go:78
15:58:18.174 NOTIC commands/h: setting logger: "commands/http" to DEBUG log.go:78
15:58:18.174 NOTIC   cmd/ipfs: setting logger: "cmd/ipfs" to DEBUG log.go:78
15:58:18.174 NOTIC       util: setting logger: "util" to DEBUG log.go:78
15:58:18.174 NOTIC   blockset: setting logger: "blockset" to DEBUG log.go:78
15:58:18.174 NOTIC       core: setting logger: "core" to DEBUG log.go:78
15:58:18.174 NOTIC    command: setting logger: "command" to DEBUG log.go:78
15:58:18.174 NOTIC      swarm: setting logger: "swarm" to DEBUG log.go:78
15:58:18.174 NOTIC        dht: setting logger: "dht" to DEBUG log.go:78
15:58:18.174 NOTIC    namesys: setting logger: "namesys" to DEBUG log.go:78
15:58:18.174 NOTIC       ipns: setting logger: "ipns" to DEBUG log.go:78
15:58:18.174 NOTIC     crypto: setting logger: "crypto" to DEBUG log.go:78
15:58:18.174 NOTIC      table: setting logger: "table" to DEBUG log.go:78
15:58:18.174 NOTIC    service: setting logger: "service" to DEBUG log.go:78
15:58:18.174 NOTIC       path: setting logger: "path" to DEBUG log.go:78
15:58:18.174 NOTIC diagnostic: setting logger: "diagnostics" to DEBUG log.go:78
15:58:18.174 NOTIC       tour: setting logger: "tour" to DEBUG log.go:78
15:58:18.174 NOTIC    updates: setting logger: "updates" to DEBUG log.go:78
15:58:18.174 NOTIC       conn: setting logger: "conn" to DEBUG log.go:78
15:58:18.174 NOTIC        pin: setting logger: "pin" to DEBUG log.go:78
15:58:18.174 NOTIC core/comma: setting logger: "core/commands" to DEBUG log.go:78
15:58:18.174 NOTIC     config: setting logger: "config" to DEBUG log.go:78
15:58:18.174 NOTIC blockservi: setting logger: "blockservice" to DEBUG log.go:78
15:58:18.174 NOTIC      chunk: setting logger: "chunk" to DEBUG log.go:78
15:58:18.174 NOTIC      muxer: setting logger: "muxer" to DEBUG log.go:78
15:58:18.174 NOTIC    bitswap: setting logger: "bitswap" to DEBUG log.go:78
15:58:18.174 NOTIC   importer: setting logger: "importer" to DEBUG log.go:78
15:58:18.174 NOTIC       ipfs: setting logger: "ipfs" to DEBUG log.go:78

[jbenet]

@maybebtc sure

[btc]

fixed in 682d2ba

[whyrusleeping]

I think we need a new log function: log.Event, a lot of our DEBUG logs are really just noting events that happened, and arent really 'debug' info.

[btc]

I support.

Are you imagining Event being one level less verbose than Debug?

[jbenet]

We already have a lot. why not log.Info or log.Notice? (we could move our current uses up a notch)

[btc]

proposal

We sort of need an approach that we can all agree on and internalize. Here's a proposal. It may be off by a constant factors.

We probably need (0) decide which of these characteristics we find meaningful (1) to decide which of these tiers we are interested in and (2) agree on conventions for mapping characteristics to the identified tiers.

Thoughts?

Critical/Error

• something occurred and it's very bad
• perhaps the system cannot recover
• in a production network deployment, requires the attention of inactive operators even at the middle of the night
• immediately visible in console

(failed to connect to bootstrap nodes. a value came back nil and I really cannot move forward without it)

Error/Warm

• something unexpected occurred, but was able to be handled
• does not require the immediate attention of a human operator
• immediately visible in console

Notice/Info

• important high level events that occur during normal operation of the system
• should not cause alarm
• immediately visible in console

Info/Debug

• events that occur during normal operation
• do not require the attention of an active human operator
• common events and metrics logged at this level
• maybe this is where the global --debug flag takes you

(connected to peer, disconnected from peer, sent a message, received a message, received a request, got providers for key)

Debug/Trace

• granular statements that are useful when debugging
• should be able to
• not appropriate for display during normal operation

Trace

• highest volume and completely unappropriate for normal operation
• important to set specific subsystems to this level rather than enabling for all subsystems

(when the value of the index i of the for loop was 7, the value of strs[i] was 'baz')

[whyrusleeping]

Critical should require IMMEDIATE attention from anyone who cares about the node, Error should be logged in a visible place, but should not be thrown in instances where the program cannot continue. Warnings should be when something looks odd, or out of place, or potentially troublesome, but not actively error causing. Notice/Infoshould allow a high level view of the systems behaviour. Debug should contain only extra information that would aid in debugging an issue.

'Events' should be pulled mainly from Notice/Info, but also potentially finer grained events could potentially be sourced from Trace messages.