Implement json formatting and static fields #5

heewa · 2015-06-30T20:19:56Z

static fields: when creating a logger, any fields specified will be logged on every line using that logger. Useful for making a logger per request, to log request-global things like RequestID, UserID, etc.
json format: optionally specify JsonFormat for a logger, to output a json blob per log line. This allows structured data to be extracted much more reliably than regex parsing, which breaks on so many scenarios.
explicit/implicit format: when creating a logger, you can specify DefaultFormat (default for old, deprecated New fns), and it uses an env variable to choose PlainTextFormat or JsonFormat, defaulting to plain text. This allows a user to have local development default to plain text, but on the server use json, for log aggregation.

Example of PlainTextFormat:

2015/06/30 16:11:07 | INFO  | SetupCaches | Cache initialized. | name='accounts'

Example of JsonFormat:

{"ts":"2015-06-30 15:36:52.649267033 -0400 EDT","lvl":"INFO","name":"SetupCaches","msg":"Cache initialized.","fields":{"name":"accounts"}}

@kjsteuer @kevin-cantwell @biasedbit @bdotdub

bdotdub · 2015-06-30T20:33:09Z

log/logging.go

 // New creates a new logger instance.
+// DEPRECATED: use `NewLogger(...)` instead. That one returns an interface,
+// which allows the underlying data structure to change without breaking
+// clients.
 func New() *Logger {


Could we move the NewLogger code into here instead? It is idiomatic to have the constructor simply be New and omit the redundant package name in the construction function name.

I know that it's a breaking change but this seems pretty fundamental to how we're using this logger library.

The only reason I hesitated is that the old functions return a *Logger, which is a struct. The new ones return an interface, so in the future we can make changes more safely. Also the new constructor takes different args. Is it ok to break the package like that?

I'm feeling ok with it – if other's aren't, then I'm not married to it.

Ultimately, the lack of versioning in Go is what's failing here.

If we break it how about tagging the current commit with v1.0 and set this to tag 2.0?

What about v0.5 and now v1.0?

that works too

I'd take a more radical approach and make Logger an interface and New() return that interface. The current struct would then become logger.

Also, by moving to the interface approach, I'd use the format to create a different type of logger per format, instead of having a single struct handle all possible types of formats, i.e. PlainTextFormat -> plainTextLogger struct, JsonFormat -> jsonLogger struct.

I see we do that at the formatter level. That makes sense too.

bdotdub · 2015-06-30T20:42:15Z

I think at this point, it would make sense to decouple the outputting of the message itself into an interface. It would remove a whole swath of if blocks and potentially allow us to expand into different formatters (csv formatter for s3?).

This is what I'm thinking:

type Formatter interface {
    LogMessage(logger *log.Logger, name, level, msg string, staticFields map[string]string, extraFields ...interface{})
}

And then this code:

if DefaultLogger.format == JsonFormat {
    logMessageInJson(DefaultLogger.l, id, "ERROR", description, nil, keysAndValues...)
} else {
    logMessage(DefaultLogger.l, id, "ERROR", description, nil, keysAndValues...)
}

turns into:

DefaultLogger.Formatter.LogMessageInJson(DefaultLogger.l, id, "ERROR", description, nil, keysAndValues...)

heewa · 2015-06-30T20:43:05Z

Ooo, I like that! I'll try that out.

kjsteuer · 2015-06-30T21:42:41Z

log/logging.go

@@ -291,18 +403,35 @@ func (s *Logger) SetTimestampFlags(flags int) {
 	s.l.SetFlags(flags)
 }

+func (s *Logger) SetField(name string, value interface{}) {


nice!

💅 pls add a comment, especially around the fact this is static.

heewa · 2015-06-30T21:57:47Z

What do y'all think of using struct for creating a logger? That way if we want to add options in the future, it doesn't break, cuz same function signature:

type Options struct {
    ID           string
    Format       LogFormat
    StaticFields []interface{}
}

func New(options Options) Logger {
    return newLoggerStruct(options.Format, options.ID, options.StaticFields)
}

Used by a client like:

myLogger := log.New(log.Options{ID: "MINE!", Format: log.JsonFormat})

And even if, for example, the StaticFields attribute wasn't on Options when that client first started using golog, and they updated after we added it, their code wouldn't break. But if the options were arguments to New(), then their code would break.

@bdotdub @kjsteuer

bdotdub · 2015-06-30T22:03:45Z

I think that makes sense. The only change I would make is s/Options/Config/

biasedbit · 2015-07-01T15:11:21Z

log/logging.go

+	} else {
+		// Whether it's explicitly a DefaultFormat, or it's an unrecognized value,
+		// try to take from env var.
+		envFormat := os.Getenv("DEFAULT_LOG_ENCODING_FORMAT")


If it's an env var for a lib, we should prefix it with the project name, e.g. GOLOG_DEFAULT_LOG_FORMAT.

(I'd also update the other env vars that aren't following this convention.)

Actually, since there won't be multiple logging packages per project (right? :badpokerface:) keeping this un-namedspaced is totally fine. In this case I'd maybe just swap (or even drop) "DEFAULT" and "LOG" to keep all env vars consistently prefixed as "LOG_": "LOG_ENCODING_FORMAT"?

kjsteuer · 2015-07-01T15:11:50Z

Yeah, the options struct makes sense.

biasedbit · 2015-07-01T15:27:43Z

log/logging.go

+	s.staticArgs[name] = fmt.Sprintf("%v", value)
+}
+
+type logFormatter interface {


The name of this interface is a bit misleading. It appears to be a formatter but it also has side effects (printing the log) which aren't immediately obvious.

This also strikes me as a good chance to use go's first-class treatment of functions by changing this interface to become a function alias.

Unless we rename this to a LogPrinter, I'd definitely leave the actual printing up to whoever uses the formatter (in this case, the logger).

type Formatter func(id string, level LogLevelName /* etc */) string func formatAsPlainText(id string, level LogLevelName /* etc */) string { // ... } func formatAsJson(id string, level LogLevelName /* etc */) string { // ... } type logger struct { formatter Formatter } func NewJsonLogger() Logger { return &logger{formatter: formatAsJson} }

Something along those lines. Playground example: http://play.golang.org/p/z7jjYpcV6a

biasedbit · 2015-07-01T15:31:00Z

I think that makes sense. The only change I would make is s/Options/Config/

Definitely Config. And for the sake of convenience, throw in some sensible defaults for NewConsoleLogger() and NewJSONLogger() to reduce friction of adopting the lib.

heewa · 2015-07-02T17:58:13Z

Ok, I think I addressed everyone's suggestions. Except that I didn't remove the prefix stuff, cuz I haven't gone through our infrastructure and made sure it wasn't being used. Should I? @bdotdub @biasedbit @kjsteuer

heewa · 2015-07-02T18:02:05Z

Btw, the new changes don't break whois. And using the new logger New fn looks like:

logger := log.New(log.Config{ID: "yay", Format: log.JsonFormat}, "userID", userID)
logger.Debug("Oh noes!")
logger.Info("More context:", "admin", user.IsAdmin)

And as Bruno suggested, there's a simpler way too:

logger := log.NewDefault()
logger.Debug("I like white bread.")

kevin-cantwell · 2015-07-06T17:20:08Z

log/logging.go

+	SetTimestampFlags(flags int)
+	SetStaticField(name string, value interface{})
+
+	logMessage(level LogLevelName, id string, description string, keysAndValues ...interface{})


Not sure if anyone has pointed this out yet, but this will prevent anyone outside of this package from actually implementing this interface. Intentional?

To sum up what we spoke about in person: we mean this interface to allow us to change the underlying struct without breaking users of the package, not for them to have an interface they can implement. So it's fine that they can't.

As always, if they want to mock our Logger, they can make their own interface and pass that around, and mock it in tests. Just like we do with libraries we use that don't supply interfaces.

heewa · 2015-07-06T20:56:40Z

Ok, I think I've addressed all comments. How's everyone feeling about it?

kjsteuer · 2015-07-13T15:46:37Z

🚢

kevin-cantwell · 2015-07-13T20:23:27Z

log/logging.go

-		ID:    id,
-		Level: Level,
+// Logger config. Default/unset values for each attribute are safe.
+type Config struct {


kevin-cantwell · 2015-07-13T20:27:50Z

Not to come in at the 11th hour with another delay, but it looks like our code coverage went down about 10% on this PR. Would be great to get that back up to 67% or higher! :)

heewa · 2015-07-14T17:26:09Z

🎊 🎊 🎊
✨ 💯 ✨
🎉 🎉 🎉

@kevin-cantwell

kevin-cantwell · 2015-07-15T15:24:31Z

omg omg omg. Ship itttttt!

Implement json formatting and static fields

Implement json formatting and static fields

3ddb55f

bdotdub reviewed Jun 30, 2015
View reviewed changes

heewa added 2 commits June 30, 2015 16:45

Remove json prefix for now.

d281aa8

Format using formatter, extendable private interface

a1189cb

kjsteuer reviewed Jun 30, 2015
View reviewed changes

Rename SetStaticField for clarity

f2ac5fe

biasedbit reviewed Jul 1, 2015
View reviewed changes

heewa added 4 commits July 2, 2015 13:46

Switch to typed LogLevel

b74d667

Check for log level using typed consts

22b8201

Switch fully to interface, with new New and NewDefault fns

913b4a0

Separate formatting and printing responsibilities

9119ccf

Rename encoding env to be consistent with others

6728ed3

kevin-cantwell reviewed Jul 6, 2015
View reviewed changes

Use regular fns for formatting

56d7c6c

kevin-cantwell reviewed Jul 13, 2015
View reviewed changes

Test init fn

713fb06

heewa added 15 commits July 13, 2015 19:06

Test SetPrefix fn

522c576

Test Fatal logging fns

1051ac5

Test logging with lower than fatal level

de3cf62

Test SanitizeFormat fn

914ba3f

Specify log level types

2a66098

Harden prefix-format test with regex

8f96f8f

Test JsonFormat with prefix through env var

8038e47

Test json formatting

2593bb0

Test static & dynamic fields

02a8098

Override static fields in plain text logger

ba44b72

Test static/dynamic field in both formats

ed1c737

Test setting static fields on existing logger

a23fc67

Manually set types on log level consts

dacb64e

Test logger logging fns

0a2f892

Ignore son error for 100% test coverage

119722d

heewa added a commit that referenced this pull request Jul 15, 2015

Merge pull request #5 from timehop/hb-json-format

0d46e27

Implement json formatting and static fields

heewa merged commit 0d46e27 into master Jul 15, 2015

heewa deleted the hb-json-format branch July 15, 2015 16:48

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement json formatting and static fields #5

Implement json formatting and static fields #5

heewa commented Jun 30, 2015

bdotdub Jun 30, 2015

heewa Jun 30, 2015

bdotdub Jun 30, 2015

kjsteuer Jun 30, 2015

bdotdub Jun 30, 2015

kjsteuer Jul 1, 2015

biasedbit Jul 1, 2015

biasedbit Jul 1, 2015

bdotdub commented Jun 30, 2015

heewa commented Jun 30, 2015

kjsteuer Jun 30, 2015

heewa commented Jun 30, 2015

bdotdub commented Jun 30, 2015

biasedbit Jul 1, 2015

biasedbit Jul 1, 2015

biasedbit Jul 2, 2015

kjsteuer commented Jul 1, 2015

biasedbit Jul 1, 2015

biasedbit commented Jul 1, 2015

heewa commented Jul 2, 2015

heewa commented Jul 2, 2015

kevin-cantwell Jul 6, 2015

heewa Jul 6, 2015

heewa commented Jul 6, 2015

kjsteuer commented Jul 13, 2015

kevin-cantwell Jul 13, 2015

kevin-cantwell commented Jul 13, 2015

heewa commented Jul 14, 2015

kevin-cantwell commented Jul 15, 2015

Implement json formatting and static fields #5

Implement json formatting and static fields #5

Conversation

heewa commented Jun 30, 2015

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

bdotdub commented Jun 30, 2015

heewa commented Jun 30, 2015

Choose a reason for hiding this comment

heewa commented Jun 30, 2015

bdotdub commented Jun 30, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kjsteuer commented Jul 1, 2015

Choose a reason for hiding this comment

biasedbit commented Jul 1, 2015

heewa commented Jul 2, 2015

heewa commented Jul 2, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

heewa commented Jul 6, 2015

kjsteuer commented Jul 13, 2015

Choose a reason for hiding this comment

kevin-cantwell commented Jul 13, 2015

heewa commented Jul 14, 2015

kevin-cantwell commented Jul 15, 2015