Logging for preliminary review #421

silasdavis · 2016-12-12T17:19:29Z

This WIP PR included the framework of the logging system I have written so far to implement ideas from #421. It also includes some changes that seemed apt to make as I introduce a non-global logger at the root level.

Guide to changes:

Housekeeping

Convert global vars (like do *definition.Do and loggers) into functional dependencies:
- better for testing
- less action at a distance
Safely wrapped Viper's subconfig
Bit of gofmt and imports

Logging

Opted for to use go-kit log as the underlying interface (see below for discussion)
Opted to support log15 both on input and output (to make use of its handlers)
Introduced InfoTraceLogger as the main binary interface (choose just one level/channel) for our logging. Each channel can be routed separately
Used ChannelLogger to have a non-blocking non-overflowing never-stop-the-caller execution
Introduced MultipleChannelLogger and MultipleOutputLogger allowing composing of loggers roughly under 'OR' / 'AND' logic respectively. These will will allow for setting up arbitrary numbers of logging sinks (remote servers, syslog, stderr, files, etc).

go-kit log and log15

After various drafts of logging and flip-flopping between just using log15's interface as our main interface and wrapping it and just go-kit log I have opted for something of a mash-up between go-kit log and log15. Although I would argue (having read up quite a bit on the design intentions of go-kit log) that I am using go-kit log as intended: in that it is designed to be wrapped and composed. In some ways you might see go-kit log as a logging facade rather like slf4j (in Java land), but simpler.

go-kit is a thematically related collection of packages designed for 'microservice architectures'. You don't have to care about that in order for it to be relevant. But it is based around a generic structured logging interface Log (keyvals... interface{}) error. This is very similar to log15's handler, but by making it the single interface everything is built around it encourages logging to behave has a composable pipeline with a somewhat flexible, but structured, schema, that you can wrap for consumption (which is what InfoTraceLogger does). They also model Context as a struct that wraps a logger rather than a field within a Record as log15 does. This means that contexts are established external to loggers/records and that there are no 'preferred fields'.

My feeling is that this suits how we should come to think about logs: as data in their own right that drives other things. I also think that this kind of machinery might be a better way to think about events in general, though it needn't be.

I was also keen not to have too many log levels, because I think they rely on that a shared hierarchy exists between the mind of the log line emitter and the mind of log line consumer that does not generally exist. I also think that Critical, Error, and Fatal are somewhat misnomers: in that if you are logging something then by definition you have handled any error (this might be appropriate in other settings, but for us as a fault tolerant system I think most things should not be fatal). However it does seem useful to have a 'noisy' and a 'quiet' channel for logs, which I have designated as 'Trace' and 'Info' respectively. I prefer 'trace' from 'debug' because I like that it doesn't try to suggest the noisy log channel is only good for debugging, in fact it might be used to drive other systems. It would have be hard to wrap log15 to provide this interface.

However, since log15 has lots of nice handlers and since Tendermint uses log15 (their very slightly different fork) I have written an adapter that allows us to capture log15 logging and also allows use to use log15 handlers. I think this kind of wrapping is in the spirit of go-kit log, but wouldn't really be the other way around.

benjaminbollen

There was a lot to absorb here, but this is great work.

benjaminbollen · 2016-12-13T14:02:26Z

cmd/serve.go

+			// the use of any assumptions while starting Eris-DB
+			if do.WorkDir == "" {
+				if currentDirectory, err := os.Getwd(); err != nil {
+					panic(fmt.Sprintf("No directory provided and failed to get current "+


we don't need to panic here, if we cleanly os.Exit(1) below ?

benjaminbollen · 2016-12-13T14:44:19Z

cmd/serve.go

-		err = serverProcess.Start()
+
+		newCore, err := NewCoreFromDo(do)
+


redundant whiteline

benjaminbollen · 2016-12-13T14:51:49Z

config/viper.go

+
+// Safely get the subtree from a viper config, returning an error if it could not
+// be obtained for any reason.
+func ViperSubConfig(conf *viper.Viper, configSubtreePath string) (subConfig *viper.Viper, err error) {


benjaminbollen · 2016-12-13T14:57:53Z

logging/adapters/logrus/logrus.go

+	logger logrus.Logger
+}
+
+var _ kitlog.Logger = (*logrusLogger)(nil)


benjaminbollen · 2016-12-13T14:58:42Z

logging/adapters/stdlib/capture.go

+)
+
+func Capture(stdLibLogger log.Logger,
+logger loggers.InfoTraceLogger) io.Writer {


indentation

benjaminbollen · 2016-12-13T15:33:10Z

logging/loggers/channel_logger.go

+package loggers
+
+import (
+	"github.com/eapache/channels"


we should maybe try to import from the "official" (does such a thing exist ?) golang repository where possible?
import "gopkg.in/eapache/channels.v1"

benjaminbollen · 2016-12-13T16:18:47Z

logging/metadata.go

+	// context: [log call site (5), Info/Trace (4), MultipleChannelLogger.Log (3),
+	// kitlog.Context.Log (2), kitlog.bindValues (1) (binding occurs),
+	// kitlog.Caller (0), stack.caller]
+	infoTraceLoggerCallDepth = 5


yeah, about that... :) - it's ok though, we have a specific logging situation and the proposed solution is, albeit complete, but elegant

benjaminbollen · 2016-12-13T16:21:21Z

manager/eris-mint/pipe.go

 	vm "github.com/eris-ltd/eris-db/manager/eris-mint/evm"
 	"github.com/eris-ltd/eris-db/manager/eris-mint/state"
 	state_types "github.com/eris-ltd/eris-db/manager/eris-mint/state/types"
 	manager_types "github.com/eris-ltd/eris-db/manager/types"
 	rpc_tm_types "github.com/eris-ltd/eris-db/rpc/tendermint/core/types"
 	"github.com/eris-ltd/eris-db/txs"
+	log "github.com/eris-ltd/eris-logger"


do we still need eris-logger?

it definitely needs to go else cli gets a build error when importing edb

benjaminbollen · 2016-12-13T16:22:58Z

manager/eris-mint/pipe.go

+		"chainId", startedState.ChainID,
+		"lastBlockHeight", startedState.LastBlockHeight,
+		"lastBlockHash", startedState.LastBlockHash,
+		structure.MessageKey, "Loaded state")


where is stMessageKey defined / imported ?

benjaminbollen · 2016-12-13T16:30:42Z

manager/eris-mint/state/state.go

@@ -12,14 +12,14 @@ import (
 	ptypes "github.com/eris-ltd/eris-db/permission/types"
 	"github.com/eris-ltd/eris-db/txs"

-	. "github.com/tendermint/go-common"


benjaminbollen · 2016-12-15T11:50:22Z

LGTM

Logging for preliminary review

Silas Davis added 3 commits December 12, 2016 17:17

Avoid . import and use our version of exit command

fa73526

Logging draft

489899e

Add adapter for log15 etc

e6e4d8d

silasdavis force-pushed the logging branch from ebdbeab to e6e4d8d Compare December 12, 2016 17:25

benjaminbollen reviewed Dec 13, 2016

View reviewed changes

Silas Davis added 2 commits December 15, 2016 10:09

fix tests

cb1ffca

document structure a bit better

8a1708f

silasdavis force-pushed the logging branch from c0d5ea7 to 8a1708f Compare December 15, 2016 10:22

benjaminbollen changed the title ~~[WIP] Logging for preliminary review~~ Logging for preliminary review Dec 15, 2016

benjaminbollen changed the base branch from develop to feature_logging December 15, 2016 11:49

benjaminbollen merged commit 4f0b5fb into hyperledger-archives:feature_logging Dec 15, 2016

silasdavis pushed a commit to silasdavis/burrow that referenced this pull request Mar 9, 2019

Merge pull request hyperledger-archives#421 from silasdavis/logging

84f2935

Logging for preliminary review

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging for preliminary review #421

Logging for preliminary review #421

silasdavis commented Dec 12, 2016 •

edited

Loading

benjaminbollen left a comment

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

VoR0220 Dec 13, 2016

zramsay Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen Dec 13, 2016

benjaminbollen commented Dec 15, 2016

		err = serverProcess.Start()

		newCore, err := NewCoreFromDo(do)

Logging for preliminary review #421

Logging for preliminary review #421

Conversation

silasdavis commented Dec 12, 2016 • edited Loading

Housekeeping

Logging

go-kit log and log15

benjaminbollen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benjaminbollen commented Dec 15, 2016

silasdavis commented Dec 12, 2016 •

edited

Loading