Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Implement json formatting and static fields #5

Merged
merged 26 commits into from
Jul 15, 2015
Merged
Changes from 4 commits
Commits
Show all changes
26 commits
Select commit Hold shift + click to select a range
3ddb55f
Implement json formatting and static fields
heewa Jun 30, 2015
d281aa8
Remove json prefix for now.
heewa Jun 30, 2015
a1189cb
Format using formatter, extendable private interface
heewa Jun 30, 2015
f2ac5fe
Rename SetStaticField for clarity
heewa Jun 30, 2015
b74d667
Switch to typed LogLevel
heewa Jul 2, 2015
22b8201
Check for log level using typed consts
heewa Jul 2, 2015
913b4a0
Switch fully to interface, with new New and NewDefault fns
heewa Jul 2, 2015
9119ccf
Separate formatting and printing responsibilities
heewa Jul 2, 2015
6728ed3
Rename encoding env to be consistent with others
heewa Jul 2, 2015
56d7c6c
Use regular fns for formatting
heewa Jul 6, 2015
713fb06
Test init fn
heewa Jul 13, 2015
522c576
Test SetPrefix fn
heewa Jul 13, 2015
1051ac5
Test Fatal logging fns
heewa Jul 13, 2015
de3cf62
Test logging with lower than fatal level
heewa Jul 13, 2015
914ba3f
Test SanitizeFormat fn
heewa Jul 14, 2015
2a66098
Specify log level types
heewa Jul 14, 2015
8f96f8f
Harden prefix-format test with regex
heewa Jul 14, 2015
8038e47
Test JsonFormat with prefix through env var
heewa Jul 14, 2015
2593bb0
Test json formatting
heewa Jul 14, 2015
02a8098
Test static & dynamic fields
heewa Jul 14, 2015
ba44b72
Override static fields in plain text logger
heewa Jul 14, 2015
ed1c737
Test static/dynamic field in both formats
heewa Jul 14, 2015
a23fc67
Test setting static fields on existing logger
heewa Jul 14, 2015
dacb64e
Manually set types on log level consts
heewa Jul 14, 2015
0a2f892
Test logger logging fns
heewa Jul 14, 2015
119722d
Ignore son error for 100% test coverage
heewa Jul 14, 2015
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
227 changes: 205 additions & 22 deletions log/logging.go
Original file line number Diff line number Diff line change
Expand Up @@ -32,13 +32,15 @@
package log

import (
"encoding/json"
"fmt"
"io"
"log"
"math"
"os"
"strconv"
"strings"
"time"
)

const (
Expand All @@ -50,6 +52,17 @@ const (
LevelTrace
)

type LogLevelName string

const (
LevelFatalName LogLevelName = "FATAL"
LevelErrorName = "ERROR"
LevelWarnName = "WARN"
LevelInfoName = "INFO"
LevelDebugName = "DEBUG"
LevelTraceName = "TRACE"
)

const (
FlagsNone = 0
FlagsDate = log.Ldate
Expand Down Expand Up @@ -114,7 +127,7 @@ func Fatal(id, description string, keysAndValues ...interface{}) {
if Level < LevelFatal {
return
}
logMessage(DefaultLogger.l, id, "FATAL", description, keysAndValues...)
DefaultLogger.formatter.logMessage(DefaultLogger.l, id, LevelFatalName, description, nil, keysAndValues...)
os.Exit(1)
}

Expand All @@ -123,7 +136,7 @@ func Error(id, description string, keysAndValues ...interface{}) {
if Level < LevelError {
return
}
logMessage(DefaultLogger.l, id, "ERROR", description, keysAndValues...)
DefaultLogger.formatter.logMessage(DefaultLogger.l, id, LevelErrorName, description, nil, keysAndValues...)
}

// Warn outputs a warning message with an optional list of key/value pairs.
Expand All @@ -134,7 +147,7 @@ func Warn(id, description string, keysAndValues ...interface{}) {
if Level < LevelWarn {
return
}
logMessage(DefaultLogger.l, id, "WARN ", description, keysAndValues...)
DefaultLogger.formatter.logMessage(DefaultLogger.l, id, LevelWarnName, description, nil, keysAndValues...)
}

// Info outputs an info message with an optional list of key/value pairs.
Expand All @@ -145,7 +158,7 @@ func Info(id, description string, keysAndValues ...interface{}) {
if Level < LevelInfo {
return
}
logMessage(DefaultLogger.l, id, "INFO ", description, keysAndValues...)
DefaultLogger.formatter.logMessage(DefaultLogger.l, id, LevelInfoName, description, nil, keysAndValues...)
}

// Debug outputs an info message with an optional list of key/value pairs.
Expand All @@ -156,7 +169,7 @@ func Debug(id, description string, keysAndValues ...interface{}) {
if Level < LevelDebug {
return
}
logMessage(DefaultLogger.l, id, "DEBUG", description, keysAndValues...)
DefaultLogger.formatter.logMessage(DefaultLogger.l, id, LevelDebugName, description, nil, keysAndValues...)
}

// Trace outputs an info message with an optional list of key/value pairs.
Expand All @@ -167,7 +180,7 @@ func Trace(id, description string, keysAndValues ...interface{}) {
if Level < LevelTrace {
return
}
logMessage(DefaultLogger.l, id, "TRACE", description, keysAndValues...)
DefaultLogger.formatter.logMessage(DefaultLogger.l, id, LevelTraceName, description, nil, keysAndValues...)
}

// SetOutput sets the output destination for the default logger.
Expand All @@ -188,22 +201,118 @@ func SetTimestampFlags(flags int) {
DefaultLogger.SetTimestampFlags(flags)
}

type LoggerInterface interface {
Fatal(description string, keysAndValues ...interface{})
Error(description string, keysAndValues ...interface{})
Warn(description string, keysAndValues ...interface{})
Info(description string, keysAndValues ...interface{})
Debug(description string, keysAndValues ...interface{})
Trace(description string, keysAndValues ...interface{})
SetOutput(w io.Writer)
SetTimestampFlags(flags int)
SetStaticField(name string, value interface{})
}

func NewLogger(format LogFormat, id string, staticKeysAndValues ...interface{}) LoggerInterface {
return newLoggerStruct(format, id, staticKeysAndValues...)
}

func newLoggerStruct(format LogFormat, id string, staticKeysAndValues ...interface{}) *Logger {
var prefix string
var flags int
var formatter logFormatter
staticArgs := make(map[string]string, 0)

format = SanitizeFormat(format)

if format == JsonFormat {
formatter = jsonLogFormatter{}

// Don't mess up the json by letting logger print these:
prefix = ""
flags = 0

// Instead put them into the staticArgs
if defaultPrefix != "" {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I know we discussed this yesterday, but handling both a json parseable string or just a string seems more complicated than it needs to be.

I'd suggest making prefix just a string and then if we want more context, let's add that support later. In retrospect, I think we might have jumped the gun on adding this complexity before we need it.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's see if we're using this prefix anywhere. If not, nix it.

staticArgs["prefix"] = defaultPrefix
}
} else {
formatter = plainTextLogFormatter{}
prefix = defaultPrefix
flags = Flags
}

// Do this after handling prefix, so that individual loggers can override
// external env variable.
currentKey := ""
for i, arg := range staticKeysAndValues {
if i%2 == 0 {
currentKey = fmt.Sprintf("%v", arg)
} else {
staticArgs[currentKey] = fmt.Sprintf("%v", arg)
}
}

// If there are an odd number of keys+values, add the dangling key with empty
// value.
if len(staticKeysAndValues)%2 == 1 {
staticArgs[currentKey] = ""
}

return &Logger{
ID: id,
Level: Level,

formatter: formatter,
staticArgs: staticArgs,

// don't touch the default logger on 'log' package
l: log.New(defaultOutput, prefix, flags),
}
}

type LogFormat string

const (
DefaultFormat LogFormat = "" // Use env variable, defaulting to PlainTextFormat
PlainTextFormat = "text"
JsonFormat = "json"
)

func SanitizeFormat(format LogFormat) LogFormat {
if format == PlainTextFormat || format == JsonFormat {
return format
} 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")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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"?

if envFormat == string(JsonFormat) || envFormat == string(PlainTextFormat) {
return LogFormat(envFormat)
}
}

// Fall back to text
return PlainTextFormat
}

// 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 {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about v0.5 and now v1.0?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that works too

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

return NewWithID("")
return newLoggerStruct(DefaultFormat, "")
}

// NewWithID creates a new logger instance that will output use the supplied id
// as prefix for all the log messages.
// The format is:
// Level | Prefix | Message | key='value' key2=value2, ...
//
// DEPRECATED: use `NewLogger(...)` instead. That one returns an interface,
// which allows the underlying data structure to change without breaking
// clients.
func NewWithID(id string) *Logger {
return &Logger{
ID: id,
Level: Level,
// don't touch the default logger on 'log' package
l: log.New(defaultOutput, defaultPrefix, Flags),
}
return newLoggerStruct(DefaultFormat, id)
}

// Logger represents a logger, through which output is generated.
Expand All @@ -215,6 +324,9 @@ type Logger struct {
ID string
Level int

formatter logFormatter
staticArgs map[string]string

l *log.Logger
}

Expand All @@ -223,7 +335,7 @@ func (s *Logger) Fatal(description string, keysAndValues ...interface{}) {
if s.Level < LevelFatal {
return
}
logMessage(s.l, s.ID, "FATAL", description, keysAndValues...)
s.formatter.logMessage(s.l, s.ID, LevelFatalName, description, s.staticArgs, keysAndValues...)
os.Exit(1)
}

Expand All @@ -232,7 +344,7 @@ func (s *Logger) Error(description string, keysAndValues ...interface{}) {
if s.Level < LevelError {
return
}
logMessage(s.l, s.ID, "ERROR", description, keysAndValues...)
s.formatter.logMessage(s.l, s.ID, LevelErrorName, description, s.staticArgs, keysAndValues...)
}

// Warn outputs a warning message with an optional list of key/value pairs.
Expand All @@ -243,7 +355,7 @@ func (s *Logger) Warn(description string, keysAndValues ...interface{}) {
if s.Level < LevelWarn {
return
}
logMessage(s.l, s.ID, "WARN ", description, keysAndValues...)
s.formatter.logMessage(s.l, s.ID, LevelWarnName, description, s.staticArgs, keysAndValues...)
}

// Info outputs an info message with an optional list of key/value pairs.
Expand All @@ -254,7 +366,7 @@ func (s *Logger) Info(description string, keysAndValues ...interface{}) {
if s.Level < LevelInfo {
return
}
logMessage(s.l, s.ID, "INFO ", description, keysAndValues...)
s.formatter.logMessage(s.l, s.ID, LevelInfoName, description, s.staticArgs, keysAndValues...)
}

// Debug outputs an info message with an optional list of key/value pairs.
Expand All @@ -265,7 +377,7 @@ func (s *Logger) Debug(description string, keysAndValues ...interface{}) {
if s.Level < LevelDebug {
return
}
logMessage(s.l, s.ID, "DEBUG", description, keysAndValues...)
s.formatter.logMessage(s.l, s.ID, LevelDebugName, description, s.staticArgs, keysAndValues...)
}

// Trace outputs an info message with an optional list of key/value pairs.
Expand All @@ -276,7 +388,7 @@ func (s *Logger) Trace(description string, keysAndValues ...interface{}) {
if s.Level < LevelTrace {
return
}
logMessage(s.l, s.ID, "TRACE", description, keysAndValues...)
s.formatter.logMessage(s.l, s.ID, LevelTraceName, description, s.staticArgs, keysAndValues...)
}

// SetOutput sets the output destination for the logger.
Expand All @@ -291,18 +403,36 @@ func (s *Logger) SetTimestampFlags(flags int) {
s.l.SetFlags(flags)
}

// Add a key/value field to every log line from this logger.
func (s *Logger) SetStaticField(name string, value interface{}) {
s.staticArgs[name] = fmt.Sprintf("%v", value)
}

type logFormatter interface {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

logMessage(
logger *log.Logger,
id string,
level LogLevelName,
description string,
staticFields map[string]string,
extraFieldKeysAndValues ...interface{},
)
}

type plainTextLogFormatter struct{}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry to ring this bell again, but what are y'all's feels on keeping this as an interface+structs vs just use a func alias (i.e. expose that formatLogEvent signature as the Formatter itself)?

I kinda like the idea of the statelessness of formatting, deeply enforced by a function.


// logMessage writes a formatted message to the default logger.
//
// Format is "SEVERITY | Description [| k1='v1' k2='v2' k3=]"
// with key/value pairs being optional, depending on whether args are provided
func logMessage(logger *log.Logger, id, severity, description string, args ...interface{}) {
func (lf plainTextLogFormatter) logMessage(logger *log.Logger, id string, level LogLevelName, description string, staticFields map[string]string, args ...interface{}) {
// A full log statement is <id> | <severity> | <description> | <keys and values>
items := make([]interface{}, 0, 8)
if logger.Flags() > FlagsNone {
items = append(items, "|")
}

items = append(items, severity)
items = append(items, level)
items = append(items, "|")

if len(id) > 0 {
Expand All @@ -312,7 +442,12 @@ func logMessage(logger *log.Logger, id, severity, description string, args ...in

items = append(items, description)

if len(args) > 0 {
if len(args)+len(staticFields) > 0 {
// Prefix with static fields.
for key, value := range staticFields {
args = append([]interface{}{key, value}, args...)
}

keysAndValues := expandKeyValuePairs(args)
items = append(items, "|")
items = append(items, keysAndValues)
Expand Down Expand Up @@ -344,3 +479,51 @@ func expandKeyValuePairs(keyValuePairs []interface{}) string {

return strings.Join(kvPairs, " ")
}

type jsonLogFormatter struct{}

func (lf jsonLogFormatter) logMessage(logger *log.Logger, name string, level LogLevelName, msg string, staticFields map[string]string, extraFields ...interface{}) {
entry := jsonLogEntry{
Timestamp: time.Now().String(),
Level: level,
Name: name,
Message: msg,
}

// If there are an odd number of keys+values, round up, cuz empty key will still be added.
var numExtraKeyValuePairs int = (len(extraFields) + 1) / 2

entry.Fields = make(map[string]string, len(staticFields)+numExtraKeyValuePairs)
for key, value := range staticFields {
entry.Fields[key] = value
}

currentKey := ""
for i, field := range extraFields {
if i%2 == 0 {
currentKey = fmt.Sprintf("%v", field)
} else {
entry.Fields[currentKey] = fmt.Sprintf("%v", field)
}
}

// If there are an odd number of keys+values, add empty key
if len(extraFields)%2 == 1 {
entry.Fields[currentKey] = ""
}

encodedEntry, err := json.Marshal(entry)
if err != nil {
logger.Printf("{\"ts\": %v, \"msg\": \"failed to marshal log entry\"}", entry.Timestamp)
} else {
logger.Println(string(encodedEntry))
}
}

type jsonLogEntry struct {
Timestamp string `json:"ts"`
Level LogLevelName `json:"lvl"`
Name string `json:"name,omitempty"`
Message string `json:"msg,omitempty"`
Fields map[string]string `json:"fields,omitempty"`
}