LogInstructions.md

Logging

Running

Logging within the code

Basics

Within factomd, logs are generated by a package called Logurs. Logrus was chosen as it is easy to switch from human readable logs, to json formatted logs. This is because when using the ELK stack, fields are preffered over long messages for easy parsing. This changes the way we construct a log message. When constructing a log statement, you have to think of fields, instead of a message, like so:

A log message that used to be:

log.Printf("Error: DBHt: %d LHt: %d VM%3d, DBStateMsg failed to validate. Signer[:3]=%x PrevDBKeyMR[:3]=%x hash[:3]=%x",
		m.DBHeight, s.LLeaderHeight, m.VMIndex,
		m.ServerIdentityChainID.Bytes()[2:6],
		m.DirectoryBlockHeader.GetPrevKeyMR().Bytes()[:3],
		m.GetHash().Bytes()[:3]))

Will now be this: (We include the package and function for easy location of logs)

	log.WithFields(log.Fields{
	"package":"messages",
	"func":"Validate",
	"message":"DBState",
	"dbheight":m.DBHeight,
	"llheight":s.LLeaderHeight,
	"vm":m.VMIndex,
	"signer":m.ServerIdentityChainID.String()[4:12],
	"prevmr":m.DirectoryBlockHeader.GetPrevKeyMR().String()[:6],
	"hash":m.GetHash().String()[:6],
	}).Error("Failed to validate")

The human readable form will look like this:

ERRO[0000] Failed to validate                            dbheight=5 func=Validate hash=123BCD llheight=5 message=DBState package=messages prevmr=ABCDEF signer=88AAEE vm=0

Shortcuts

This code is annoying and repitive. So we use some shortcuts to make it a little easier. You can create and reuse a logger with defined fields, so each package will have something like this:

var packageLogger = log.WithFields(log.Fields{"package": "state"})

To make a new log within a function extending the packageLogger, simply do:

func Foo() {
	// If only adding a single field, you can do 'WithField', and define that one field
	fooLogger := packageLogger.WithField("func","Foo")
	...
	fooLogger.Error("Something bad happened!")
}

If a function has many log printouts, we can define the function logger with more fields

func (m *message) Validate() {
	vlog := packageLogger.WithFields(log.Fields{"func": "Validate", "msgheight": m.DBHeight, "lheight": state.GetLeaderHeight()})
	...
	vlog.Error("Failed!")
	vlog.Info("Just something you should know")

	vlog.WithField("extra":"MoreInfo").Error("An error with another field")
}

Defining fields can also be a little repetitive, even if it's only once per function. To make things even easier, some interfaces (like messages) have a function called LogFields(). That function will return the log fields to pass into your logger, which essentially acts as a String() function, putting the message fields into logrus defined fields.

var m interface.IMsg
log.WithFields(m.LogFields()).Info("Logging is easy!")

Levels

Run factomd with factomd -loglvl=info

debug
info
warning
error
panic

Run as json formatted factomd -logjson

Some tricks

Logging is expensive. String formatting is expensive. If you want to use the same fields in every error log message in a function, you will have to instantiate it so every error message is within the same scope as the log instantiation. Example:

func Foo() {
	// 1300ns cost
	funcLogger := log.WithField("func":"Foo")

	err := doSomething()
	if err != nil {
		funcLogger.Error("Something bad")
	}

	err := doSomethingElse()
	if err != nil {
		funcLogger.Error("Something else bad")
	}
}

The problem here is that errors are infrequent, but every call has to instantiat the logger. This is wasted expense, but can be minimized. Instead of instantiating a logger, you can instantiate a function. That way, the logger is only instantiated if the function is called (AKA only the error case). In the normal case, the cost is drastically reduced.

Solution:

func Foo() {
	// 1.99ns cost
	funcLogger := func(format string, args ...interface{}) {
		log.WithField("func":"Foo").Errorf(format, args...)
	}

	err := doSomething()
	if err != nil {
		funcLogger("Something bad")
	}

	err := doSomethingElse()
	if err != nil {
		funcLogger("Something else bad")
	}
}

Benchmarks (See common/messages/directoryBlockSignature_test.go for actual code to benchmark it)

// Operations           Time per op
// 2000000000	         1.99 ns/op
func Foo(m *msg) {
	// Instantiating a function, rather than a logger
	vlog := func(format string, args ...interface{}) {
		log.WithFields(log.Fields{"msgheight": m.DBHeight, "lheight": s.GetLeaderHeight()}).Errorf(format, args...)
	}
}

// Operations     Time per op
//  1000000	      1312 ns/op
func Foo(m *msg) {
	// Instantiating a logger
	vlog := log.WithFields(log.Fields{"msgheight": m.DBHeight, "lheight": s.GetLeaderHeight()})
}

// Comparing printing to std to ioutil.Discard
//
// To ioutil.Discard
//  100000	     27277 ns/op
//
// Printing to stdout
//  30000	     60523 ns/op
func Foo(m *msg) {
	// Actually printing a log
	vlog := func(format string, args ...interface{}) {
		log.WithFields(log.Fields{"msgheight": m.DBHeight, "lheight": s.GetLeaderHeight()}).Errorf(format, args...)
	}
	vlog("%s", "hello")
}