log: Add structured logging (#1171)

* basic implementation * log: deprecate duplicate function, add tests and refine calls. * linter: fixes * linter: update struct * linter and new type * log tests: update to not lint issue * linter: stop complaining please * glorious: nits * log: rm comment code * glorious: nits * glorious: nits * glorious: nits * glorious: nits missed --------- Co-authored-by: Ryan O'Hara-Reid <ryan.oharareid@thrasher.io>
2026-05-13 23:16:45 +00:00 · 2023-05-10 17:52:53 +10:00
parent 6e1cbfc31e
commit db8735ec99
44 changed files with 679 additions and 476 deletions
--- a/log/logger.go
+++ b/log/logger.go
@@ -13,7 +13,7 @@ var (
 	ErrSubLoggerAlreadyRegistered = errors.New("sub logger already registered")
 )

-func newLogger(c *Config) Logger {
+func newLogger(c *Config, botName string) Logger {
 	return Logger{
 		TimestampFormat:               c.AdvancedSettings.TimeStampFormat,
 		Spacer:                        c.AdvancedSettings.Spacer,
@@ -23,6 +23,7 @@ func newLogger(c *Config) Logger {
 		DebugHeader:                   c.AdvancedSettings.Headers.Debug,
 		ShowLogSystemName:             c.AdvancedSettings.ShowLogSystemName != nil && *c.AdvancedSettings.ShowLogSystemName,
 		BypassJobChannelFilledWarning: c.AdvancedSettings.BypassJobChannelFilledWarning,
+		botName:                       botName,
 	}
 }

--- a/log/logger_multiwriter.go
+++ b/log/logger_multiwriter.go
@@ -1,6 +1,7 @@
 package log

 import (
+	"encoding/json"
 	"errors"
 	"fmt"
 	"io"
@@ -9,9 +10,14 @@ import (
 )

 var (
-	errWriterAlreadyLoaded = errors.New("io.Writer already loaded")
-	errJobsChannelIsFull   = errors.New("logger jobs channel is filled")
-	errWriterIsNil         = errors.New("io writer is nil")
+	errWriterAlreadyLoaded     = errors.New("io.Writer already loaded")
+	errJobsChannelIsFull       = errors.New("logger jobs channel is filled")
+	errWriterIsNil             = errors.New("io writer is nil")
+	message                Key = "message"
+	timestamp              Key = "timestamp"
+	severity               Key = "severity"
+	subLoggerName          Key = "sublogger"
+	botName                Key = "botname"
 )

 // loggerWorker handles all work staged to be written to configured io.Writer(s)
@@ -22,28 +28,58 @@ func loggerWorker() {
 	buffer := make([]byte, 0, defaultBufferCapacity)
 	var n int
 	var err error
+
+	structuredOutbound := ExtraFields{}
 	for j := range jobsChannel {
 		if j.Passback != nil {
 			j.Passback <- struct{}{}
 			continue
 		}
-		data := j.fn()
-		buffer = append(buffer, j.Header...)
-		if j.ShowLogSystemName {
-			buffer = append(buffer, j.Spacer...)
-			buffer = append(buffer, j.SlName...)
-		}
-		buffer = append(buffer, j.Spacer...)
-		if j.TimestampFormat != "" {
-			buffer = time.Now().AppendFormat(buffer, j.TimestampFormat)
-		}
-		buffer = append(buffer, j.Spacer...)
-		buffer = append(buffer, data...)
-		if data == "" || data[len(data)-1] != '\n' {
+		msg := j.fn()
+		if j.StructuredLogging {
+			structuredOutbound[message] = msg
+			structuredOutbound[timestamp] = time.Now().UnixMilli()
+			structuredOutbound[severity] = j.Severity
+			structuredOutbound[subLoggerName] = j.SubLoggerName
+			structuredOutbound[botName] = j.Instance
+			for k, v := range j.StructuredFields {
+				_, ok := structuredOutbound[k]
+				if ok {
+					// Disallow overwriting of key values
+					displayError(fmt.Errorf("structured logging: cannot overwrite key [%s]", k))
+					continue
+				}
+				structuredOutbound[k] = v
+			}
+			buffer, err = json.Marshal(structuredOutbound)
+			if err != nil {
+				log.Println("log: failed to marshal structured log data:", err)
+			}
+			for k := range j.StructuredFields {
+				// Delete non-persistent structured fields
+				delete(structuredOutbound, k)
+			}
 			buffer = append(buffer, '\n')
+		} else {
+			buffer = append(buffer, j.Header...)
+			if j.ShowLogSystemName {
+				buffer = append(buffer, j.Spacer...)
+				buffer = append(buffer, []byte(j.SubLoggerName)...)
+			}
+			buffer = append(buffer, j.Spacer...)
+			if j.TimestampFormat != "" {
+				buffer = time.Now().AppendFormat(buffer, j.TimestampFormat)
+			}
+			buffer = append(buffer, j.Spacer...)
+			buffer = append(buffer, msg...)
+			if msg == "" || msg[len(msg)-1] != '\n' {
+				buffer = append(buffer, '\n')
+			}
 		}

 		for x := range j.Writers {
+			// NOTE: byte slice is not copied, this is a pointer to the buffer.
+			// This is only safe if the buffer is not modified after this point.
 			n, err = j.Writers[x].Write(buffer)
 			if err != nil {
 				displayError(fmt.Errorf("%T %w", j.Writers[x], err))
@@ -51,7 +87,7 @@ func loggerWorker() {
 				displayError(fmt.Errorf("%T %w", j.Writers[x], io.ErrShortWrite))
 			}
 		}
-		buffer = buffer[:0] // Clean buffer
+		buffer = buffer[:0] // Clean buffer for next use
 		jobsPool.Put(j)
 	}
 }
@@ -63,15 +99,19 @@ type deferral func() string
 // StageLogEvent stages a new logger event in a jobs channel to be processed by
 // a worker pool. This segregates the need to process the log string and the
 // writes to the required io.Writer.
-func (mw *multiWriterHolder) StageLogEvent(fn deferral, header, slName, spacer, timestampFormat string, showLogSystemName, bypassWarning bool) {
+func (mw *multiWriterHolder) StageLogEvent(fn deferral, header, slName, spacer, timestampFormat, instance, level string, showLogSystemName, bypassWarning, structuredLog bool, fields map[Key]interface{}) {
 	newJob := jobsPool.Get().(*job) //nolint:forcetypeassert // Not necessary from a pool
 	newJob.Writers = mw.writers
 	newJob.fn = fn
 	newJob.Header = header
-	newJob.SlName = slName
+	newJob.SubLoggerName = slName
 	newJob.ShowLogSystemName = showLogSystemName
 	newJob.Spacer = spacer
 	newJob.TimestampFormat = timestampFormat
+	newJob.Instance = instance
+	newJob.StructuredFields = fields
+	newJob.StructuredLogging = structuredLog
+	newJob.Severity = level

 	select {
 	case jobsChannel <- newJob:
--- a/log/logger_setup.go
+++ b/log/logger_setup.go
@@ -147,8 +147,9 @@ func SetupSubLoggers(s []SubLoggerConfig) error {
 	return nil
 }

-// SetupGlobalLogger setup the global loggers with the default global config values
-func SetupGlobalLogger() error {
+// SetupGlobalLogger setup the global loggers with the default global config
+// values.
+func SetupGlobalLogger(botName string, structuredOutput bool) error {
 	mu.Lock()
 	defer mu.Unlock()

@@ -167,12 +168,14 @@ func SetupGlobalLogger() error {

 	for _, subLogger := range SubLoggers {
 		subLogger.setLevels(splitLevel(globalLogConfig.Level))
+		subLogger.structuredLogging = structuredOutput
 		err = subLogger.setOutput(writers)
 		if err != nil {
 			return err
 		}
+		subLogger.botName = botName
 	}
-	logger = newLogger(globalLogConfig)
+	logger = newLogger(globalLogConfig, botName)
 	return nil
 }

@@ -213,9 +216,11 @@ func registerNewSubLogger(subLogger string) *SubLogger {
 	}

 	temp := &SubLogger{
-		name:   strings.ToUpper(subLogger),
-		output: tempHolder,
-		levels: splitLevel("INFO|WARN|DEBUG|ERROR"),
+		name:              strings.ToUpper(subLogger),
+		output:            tempHolder,
+		levels:            splitLevel("INFO|WARN|DEBUG|ERROR"),
+		botName:           logger.botName,
+		structuredLogging: globalLogConfig != nil && globalLogConfig.AdvancedSettings.StructuredLogging,
 	}
 	SubLoggers[subLogger] = temp
 	return temp
--- a/log/logger_test.go
+++ b/log/logger_test.go
@@ -1,6 +1,7 @@
 package log

 import (
+	"encoding/json"
 	"errors"
 	"io"
 	"log"
@@ -9,6 +10,7 @@ import (
 	"testing"
 	"time"

+	"github.com/gofrs/uuid"
 	"github.com/thrasher-corp/gocryptotrader/common/convert"
 )

@@ -76,7 +78,7 @@ func setupTestLoggers() error {
 	if err != nil {
 		return err
 	}
-	err = SetupGlobalLogger()
+	err = SetupGlobalLogger("test", false)
 	if err != nil {
 		return err
 	}
@@ -88,7 +90,7 @@ func SetupDisabled() error {
 	if err != nil {
 		return err
 	}
-	err = SetupGlobalLogger()
+	err = SetupGlobalLogger("test", false)
 	if err != nil {
 		return err
 	}
@@ -195,17 +197,17 @@ var errWriteError = errors.New("write error")
 func TestMultiWriterWrite(t *testing.T) {
 	t.Parallel()

-	fields := &logFields{}
+	f := &fields{}
 	buff := newTestBuffer()

 	var err error
-	fields.output, err = multiWriter(io.Discard, buff)
+	f.output, err = multiWriter(io.Discard, buff)
 	if err != nil {
 		t.Fatal(err)
 	}

 	payload := "woooooooooooooooooooooooooooooooooooow"
-	fields.output.StageLogEvent(func() string { return payload }, "", "", "", "", false, false)
+	f.output.StageLogEvent(func() string { return payload }, "", "", "", "", "", "", false, false, false, nil)
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -215,17 +217,17 @@ func TestMultiWriterWrite(t *testing.T) {
 		t.Errorf("received: '%v' but expected: '%v'", contents, payload)
 	}

-	fields.output, err = multiWriter(&WriteShorter{}, io.Discard)
+	f.output, err = multiWriter(&WriteShorter{}, io.Discard)
 	if err != nil {
 		t.Fatal(err)
 	}
-	fields.output.StageLogEvent(func() string { return payload }, "", "", "", "", false, false) // Will display error: Logger write error: *log.WriteShorter short write
+	f.output.StageLogEvent(func() string { return payload }, "", "", "", "", "", "", false, false, false, nil) // Will display error: Logger write error: *log.WriteShorter short write

-	fields.output, err = multiWriter(&WriteError{}, io.Discard)
+	f.output, err = multiWriter(&WriteError{}, io.Discard)
 	if err != nil {
 		t.Fatal(err)
 	}
-	fields.output.StageLogEvent(func() string { return payload }, "", "", "", "", false, false) // Will display error: Logger write error: *log.WriteError write error
+	f.output.StageLogEvent(func() string { return payload }, "", "", "", "", "", "", false, false, false, nil) // Will display error: Logger write error: *log.WriteError write error
 }

 func TestGetWriters(t *testing.T) {
@@ -343,8 +345,8 @@ func TestStageNewLogEvent(t *testing.T) {
 	w := newTestBuffer()
 	mw := &multiWriterHolder{writers: []io.Writer{w}}

-	fields := &logFields{output: mw}
-	fields.output.StageLogEvent(func() string { return "out" }, "header", "SUBLOGGER", " space ", "", false, false)
+	f := &fields{output: mw}
+	f.output.StageLogEvent(func() string { return "out" }, "header", "SUBLOGGER", " space ", "", "", "", false, false, false, nil)

 	<-w.Finished
 	if contents := w.Read(); contents != "header space  space out\n" { //nolint:dupword // False positive
@@ -354,6 +356,7 @@ func TestStageNewLogEvent(t *testing.T) {

 func TestInfo(t *testing.T) {
 	t.Parallel()
+
 	w := newTestBuffer()
 	mw := &multiWriterHolder{writers: []io.Writer{w}}

@@ -367,26 +370,22 @@ func TestInfo(t *testing.T) {
 		t.Fatal(err)
 	}

-	Info(sl, "Hello")
-	<-w.Finished
-	contents := w.Read()
-
-	if !strings.Contains(contents, "Hello") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "Hello")
-	}
+	Infof(nil, "%s", "bad")

 	Infof(sl, "%s", "hello")
 	<-w.Finished
-	contents = w.Read()
+	contents := w.Read()
 	if !strings.Contains(contents, "hello") {
 		t.Errorf("received: '%v' but expected: '%v'", contents, "hello")
 	}

+	Infoln(nil, "hello", "bad")
+
 	Infoln(sl, "hello", "goodbye")
 	<-w.Finished
 	contents = w.Read()
-	if !strings.Contains(contents, "hello goodbye") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "hello goodbye")
+	if !strings.Contains(contents, "hellogoodbye") {
+		t.Errorf("received: '%v' but expected: '%v'", contents, "hellogoodbye")
 	}

 	_, err = SetLevel("TESTYMCTESTALOTINFO", "")
@@ -396,12 +395,6 @@ func TestInfo(t *testing.T) {

 	// Should not write to buffer at all as it should return if functionality
 	// is not enabled.
-	Info(sl, "HelloHello")
-	contents = w.Read()
-	if contents != "" {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "")
-	}
-
 	Infoln(sl, "HelloHello")
 	contents = w.Read()
 	if contents != "" {
@@ -424,26 +417,22 @@ func TestDebug(t *testing.T) {
 		t.Fatal(err)
 	}

-	Debug(sl, "Hello")
-	<-w.Finished
-	contents := w.Read()
-
-	if !strings.Contains(contents, "Hello") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "Hello")
-	}
+	Debugf(nil, "%s", "bad")

 	Debugf(sl, "%s", "hello")
 	<-w.Finished
-	contents = w.Read()
+	contents := w.Read()
 	if !strings.Contains(contents, "hello") {
 		t.Errorf("received: '%v' but expected: '%v'", contents, "hello")
 	}

+	Debugln(nil, ":sun_with_face:", "bad")
+
 	Debugln(sl, ":sun_with_face:", ":angrysun:")
 	<-w.Finished
 	contents = w.Read()
-	if !strings.Contains(contents, ":sun_with_face: :angrysun:") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, ":sun_with_face: :angrysun:")
+	if !strings.Contains(contents, ":sun_with_face::angrysun:") {
+		t.Errorf("received: '%v' but expected: '%v'", contents, ":sun_with_face::angrysun:")
 	}

 	_, err = SetLevel("TESTYMCTESTALOTDEBUG", "")
@@ -453,12 +442,6 @@ func TestDebug(t *testing.T) {

 	// Should not write to buffer at all as it should return if functionality
 	// is not enabled.
-	Debug(sl, "HelloHello")
-	contents = w.Read()
-	if contents != "" {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "")
-	}
-
 	Debugln(sl, "HelloHello")
 	contents = w.Read()
 	if contents != "" {
@@ -481,26 +464,22 @@ func TestWarn(t *testing.T) {
 		t.Fatal(err)
 	}

-	Warn(sl, "Hello")
-	<-w.Finished
-	contents := w.Read()
-
-	if !strings.Contains(contents, "Hello") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "Hello")
-	}
+	Warnf(nil, "%s", "silly")

 	Warnf(sl, "%s", "hello")
 	<-w.Finished
-	contents = w.Read()
+	contents := w.Read()
 	if !strings.Contains(contents, "hello") {
 		t.Errorf("received: '%v' but expected: '%v'", contents, "hello")
 	}

+	Warnln(nil, "super", "silly")
+
 	Warnln(sl, "hello", "world")
 	<-w.Finished
 	contents = w.Read()
-	if !strings.Contains(contents, "hello world") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "hello world")
+	if !strings.Contains(contents, "helloworld") {
+		t.Errorf("received: '%v' but expected: '%v'", contents, "helloworld")
 	}

 	_, err = SetLevel("TESTYMCTESTALOTWARN", "")
@@ -510,12 +489,6 @@ func TestWarn(t *testing.T) {

 	// Should not write to buffer at all as it shhould return if functionality
 	// is not enabled.
-	Warn(sl, "HelloHello")
-	contents = w.Read()
-	if contents != "" {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "")
-	}
-
 	Warnln(sl, "HelloHello")
 	contents = w.Read()
 	if contents != "" {
@@ -543,26 +516,22 @@ func TestError(t *testing.T) {
 		t.Fatal(err)
 	}

-	Error(sl, "Hello")
-	<-w.Finished
-	contents := w.Read()
-
-	if !strings.Contains(contents, "Hello") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "Hello")
-	}
+	Errorf(nil, "%s", "oh wow")

 	Errorf(sl, "%s", "hello")
 	<-w.Finished
-	contents = w.Read()
+	contents := w.Read()
 	if !strings.Contains(contents, "hello") {
 		t.Errorf("received: '%v' but expected: '%v'", contents, "hello")
 	}

+	Errorln(nil, "nil", "days")
+
 	Errorln(sl, "hello", "goodbye")
 	<-w.Finished
 	contents = w.Read()
-	if !strings.Contains(contents, "hello goodbye") {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "hello goodbye")
+	if !strings.Contains(contents, "hellogoodbye") {
+		t.Errorf("received: '%v' but expected: '%v'", contents, "hellogoodbye")
 	}

 	_, err = SetLevel("TESTYMCTESTALOTERROR", "")
@@ -572,12 +541,6 @@ func TestError(t *testing.T) {

 	// Should not write to buffer at all as it shhould return if functionality
 	// is not enabled.
-	Error(sl, "HelloHello")
-	contents = w.Read()
-	if contents != "" {
-		t.Errorf("received: '%v' but expected: '%v'", contents, "")
-	}
-
 	Errorln(sl, "HelloHello")
 	contents = w.Read()
 	if contents != "" {
@@ -602,14 +565,14 @@ func TestSubLoggerName(t *testing.T) {
 	w := newTestBuffer()
 	mw := &multiWriterHolder{writers: []io.Writer{w}}

-	mw.StageLogEvent(func() string { return "out" }, "header", "SUBLOGGER", "||", time.RFC3339, true, false)
+	mw.StageLogEvent(func() string { return "out" }, "header", "SUBLOGGER", "||", "", "", time.RFC3339, true, false, false, nil)
 	<-w.Finished
 	contents := w.Read()
 	if !strings.Contains(contents, "SUBLOGGER") {
 		t.Error("Expected SUBLOGGER in output")
 	}

-	mw.StageLogEvent(func() string { return "out" }, "header", "SUBLOGGER", "||", time.RFC3339, false, false)
+	mw.StageLogEvent(func() string { return "out" }, "header", "SUBLOGGER", "||", "", "", time.RFC3339, false, false, false, nil)
 	<-w.Finished
 	contents = w.Read()
 	if strings.Contains(contents, "SUBLOGGER") {
@@ -629,7 +592,7 @@ func TestNewSubLogger(t *testing.T) {
 		t.Fatalf("received: %v but expected: %v", err, nil)
 	}

-	Debug(sl, "testerinos")
+	Debugln(sl, "testerinos")

 	_, err = NewSubLogger("TESTERINOS")
 	if !errors.Is(err, ErrSubLoggerAlreadyRegistered) {
@@ -694,19 +657,28 @@ func TestOpenNew(t *testing.T) {
 }

 type testBuffer struct {
-	value    string
+	value    []byte
 	Finished chan struct{}
 }

 func (tb *testBuffer) Write(p []byte) (int, error) {
-	tb.value = string(p)
+	cpy := make([]byte, len(p))
+	copy(cpy, p)
+	tb.value = cpy
 	tb.Finished <- struct{}{}
 	return len(p), nil
 }

 func (tb *testBuffer) Read() string {
-	defer func() { tb.value = "" }()
-	return tb.value
+	defer func() { tb.value = tb.value[:0] }()
+	return string(tb.value)
+}
+
+func (tb *testBuffer) ReadRaw() []byte {
+	defer func() { tb.value = tb.value[:0] }()
+	cpy := make([]byte, len(tb.value))
+	copy(cpy, tb.value)
+	return cpy
 }

 func newTestBuffer() *testBuffer {
@@ -717,7 +689,7 @@ func newTestBuffer() *testBuffer {
 func BenchmarkNewLogEvent(b *testing.B) {
 	mw := &multiWriterHolder{writers: []io.Writer{io.Discard}}
 	for i := 0; i < b.N; i++ {
-		mw.StageLogEvent(func() string { return "somedata" }, "header", "sublog", "||", time.RFC3339, true, false)
+		mw.StageLogEvent(func() string { return "somedata" }, "header", "sublog", "||", "", "", time.RFC3339, true, false, false, nil)
 	}
 }

@@ -725,7 +697,7 @@ func BenchmarkNewLogEvent(b *testing.B) {
 func BenchmarkInfo(b *testing.B) {
 	b.ResetTimer()
 	for n := 0; n < b.N; n++ {
-		Info(Global, "Hello this is an info benchmark")
+		Infoln(Global, "Hello this is an info benchmark")
 	}
 }

@@ -737,7 +709,7 @@ func BenchmarkInfoDisabled(b *testing.B) {

 	b.ResetTimer()
 	for n := 0; n < b.N; n++ {
-		Info(Global, "Hello this is an info benchmark")
+		Infoln(Global, "Hello this is an info benchmark")
 	}
 }

@@ -756,3 +728,144 @@ func BenchmarkInfoln(b *testing.B) {
 		Infoln(Global, "Hello this is an infoln benchmark")
 	}
 }
+
+type testCapture struct {
+	Message   string    `json:"message"`
+	Timestamp int64     `json:"timestamp"`
+	Severity  string    `json:"severity"`
+	SubLogger string    `json:"sublogger"`
+	BotName   string    `json:"botname"`
+	ID        uuid.UUID `json:"id"`
+}
+
+func TestWithFields(t *testing.T) {
+	t.Parallel()
+	writer := newTestBuffer()
+	mwh := &multiWriterHolder{writers: []io.Writer{writer}}
+
+	sl, err := NewSubLogger("TESTSTRUCTUREDLOGGING")
+	if err != nil {
+		t.Fatal(err)
+	}
+	sl.structuredLogging = true
+	sl.setLevelsProtected(splitLevel("DEBUG|ERROR|INFO|WARN"))
+	err = sl.setOutputProtected(mwh)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	id, err := uuid.NewV4()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	ErrorlnWithFields(nil, ExtraFields{"id": id}, "nilerinos")
+	ErrorlnWithFields(sl, ExtraFields{"id": id}, "hello")
+	<-writer.Finished
+	var captured testCapture
+	bro := writer.ReadRaw()
+	err = json.Unmarshal(bro, &captured)
+	if err != nil {
+		t.Fatal(err, string(bro))
+	}
+	checkCapture(t, &captured, id, "hello", "error")
+
+	ErrorfWithFields(nil, ExtraFields{"id": id}, "%v", "nilerinos")
+	ErrorfWithFields(sl, ExtraFields{"id": id}, "%v", "good")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	checkCapture(t, &captured, id, "good", "error")
+
+	DebuglnWithFields(nil, ExtraFields{"id": id}, "nilerinos")
+	DebuglnWithFields(sl, ExtraFields{"id": id}, "sir")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	checkCapture(t, &captured, id, "sir", "debug")
+
+	DebugfWithFields(nil, ExtraFields{"id": id}, "%v", "nilerinos")
+	DebugfWithFields(sl, ExtraFields{"id": id}, "%v", "how")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	checkCapture(t, &captured, id, "how", "debug")
+
+	WarnlnWithFields(nil, ExtraFields{"id": id}, "nilerinos")
+	WarnlnWithFields(sl, ExtraFields{"id": id}, "are")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	checkCapture(t, &captured, id, "are", "warn")
+
+	WarnfWithFields(nil, ExtraFields{"id": id}, "%v", "nilerinos")
+	WarnfWithFields(sl, ExtraFields{"id": id}, "%v", "you")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	checkCapture(t, &captured, id, "you", "warn")
+
+	InfolnWithFields(nil, ExtraFields{"id": id}, "nilerinos")
+	InfolnWithFields(sl, ExtraFields{"id": id}, "today")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	checkCapture(t, &captured, id, "today", "info")
+
+	InfofWithFields(nil, ExtraFields{"id": id}, "%v", "nilerinos")
+	InfofWithFields(sl, ExtraFields{"id": id}, "%v", "?")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	checkCapture(t, &captured, id, "?", "info")
+
+	// Conflicting fields
+	InfofWithFields(nil, ExtraFields{botName: "lol"}, "%v", "nilerinos")
+	InfofWithFields(sl, ExtraFields{botName: "lol"}, "%v", "?")
+	<-writer.Finished
+	err = json.Unmarshal(writer.ReadRaw(), &captured)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if captured.BotName != "test" {
+		t.Fatalf("received: '%v' but expected: '%v'", captured.BotName, "test")
+	}
+}
+
+func checkCapture(t *testing.T, c *testCapture, expID uuid.UUID, expMessage, expSeverity string) {
+	t.Helper()
+
+	if c.ID != expID {
+		t.Errorf("received: '%v' but expected: '%v'", c.ID, expID)
+	}
+
+	if c.Message != expMessage {
+		t.Errorf("received: '%v' but expected: '%v'", c.Message, expMessage)
+	}
+
+	if c.Severity != expSeverity {
+		t.Errorf("received: '%v' but expected: '%v'", c.Severity, expSeverity)
+	}
+
+	if c.SubLogger != "TESTSTRUCTUREDLOGGING" {
+		t.Errorf("received: '%v' but expected: '%v'", c.SubLogger, "TESTSTRUCTUREDLOGGING")
+	}
+
+	if c.BotName != "test" {
+		t.Errorf("received: '%v' but expected: '%v'", c.BotName, "test")
+	}
+}
--- a/log/logger_types.go
+++ b/log/logger_types.go
@@ -31,7 +31,7 @@ var (

 	// Note: Logger state within logFields will be persistent until it's garbage
 	// collected. This is a little bit more efficient.
-	logFieldsPool = &sync.Pool{New: func() interface{} { return &logFields{logger: logger} }}
+	logFieldsPool = &sync.Pool{New: func() interface{} { return &fields{logger: logger} }}

 	// LogPath system path to store log files in
 	logPath string
@@ -44,10 +44,14 @@ type job struct {
 	Writers           []io.Writer
 	fn                deferral
 	Header            string
-	SlName            string
+	SubLoggerName     string
 	Spacer            string
 	TimestampFormat   string
 	ShowLogSystemName bool
+	Instance          string
+	StructuredFields  map[Key]interface{}
+	StructuredLogging bool
+	Severity          string
 	Passback          chan<- struct{}
 }

@@ -66,6 +70,7 @@ type advancedSettings struct {
 	TimeStampFormat               string  `json:"timeStampFormat"`
 	Headers                       headers `json:"headers"`
 	BypassJobChannelFilledWarning bool    `json:"bypassJobChannelFilledWarning"`
+	StructuredLogging             bool    `json:"structuredLogging"`
 }

 type headers struct {
@@ -95,6 +100,8 @@ type Logger struct {
 	TimestampFormat                                  string
 	InfoHeader, ErrorHeader, DebugHeader, WarnHeader string
 	Spacer                                           string
+	Level                                            string
+	botName                                          string
 }

 // Levels flags for each sub logger type
@@ -105,3 +112,11 @@ type Levels struct {
 type multiWriterHolder struct {
 	writers []io.Writer
 }
+
+// ExtraFields is a map of key value pairs that can be added to a structured
+// log output.
+type ExtraFields map[Key]interface{}
+
+// Key is used for structured logging fields to ensure no collisions occur.
+// Unexported keys are default fields which cannot be overwritten.
+type Key string
--- a/log/loggers.go
+++ b/log/loggers.go
@@ -5,244 +5,213 @@ import (
 	"log"
 )

-// Info takes a pointer subLogger struct and string sends to StageLogEvent
-func Info(sl *SubLogger, data string) {
+// Infoln is a logging function that takes a sublogger and an arbitrary number
+// of interface{} arguments. This writes to configured io.Writer(s) as an
+// information message using default formats for its operands. A new line is
+// automatically added to the output.
+func Infoln(sl *SubLogger, a ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.stageln(f.logger.InfoHeader, a...)
 	}
-	if fields.info {
-		fields.output.StageLogEvent(func() string { return data },
-			fields.logger.InfoHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Infoln takes a pointer subLogger struct and interface sends to StageLogEvent
-func Infoln(sl *SubLogger, v ...interface{}) {
+// InfolnWithFields is a logging function that takes a sublogger, additional
+// structured logging fields and an arbitrary number of interface{} arguments.
+// This writes to configured io.Writer(s) as an information message using
+// default formats for its operands. A new line is automatically added to the
+// output. If structured logging is not enabled, the fields will be ignored.
+func InfolnWithFields(sl *SubLogger, extra ExtraFields, a ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stageln(f.logger.InfoHeader, a...)
 	}
-	if fields.info {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintln(v...) },
-			fields.logger.InfoHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Infof takes a pointer subLogger struct, string and interface formats sends to StageLogEvent
-func Infof(sl *SubLogger, data string, v ...interface{}) {
+// Infof is a logging function that takes a sublogger, a format string along
+// with optional arguments. This writes to configured io.Writer(s) as an
+// information message which formats according to the format specifier.
+// A new line is automatically added to the output.
+func Infof(sl *SubLogger, format string, a ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		sl.getFields().stagef(f.logger.InfoHeader, format, a...)
 	}
-	if fields.info {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintf(data, v...) },
-			fields.logger.InfoHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Debug takes a pointer subLogger struct and string sends to StageLogEvent
-func Debug(sl *SubLogger, data string) {
+// InfofWithFields is a logging function that takes a sublogger, additional
+// structured logging fields, a format string along with optional arguments.
+// This writes to configured io.Writer(s) as an information message which
+// formats according to the format specifier. A new line is automatically added
+// to the output. If structured logging is not enabled, the fields will be
+// ignored.
+func InfofWithFields(sl *SubLogger, extra ExtraFields, format string, a ...interface{}) { //nolint:goprintffuncname // False positive
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stagef(f.logger.InfoHeader, format, a...)
 	}
-	if fields.debug {
-		fields.output.StageLogEvent(func() string { return data },
-			fields.logger.DebugHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Debugln takes a pointer subLogger struct, string and interface sends to StageLogEvent
+// Debugln is a logging function that takes a sublogger and an arbitrary number
+// of interface{} arguments. This writes to configured io.Writer(s) as an
+// debug message using default formats for its operands. A new line is
+// automatically added to the output.
 func Debugln(sl *SubLogger, v ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.stageln(f.logger.DebugHeader, v...)
 	}
-	if fields.debug {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintln(v...) },
-			fields.logger.DebugHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Debugf takes a pointer subLogger struct, string and interface formats sends to StageLogEvent
+// DebuglnWithFields is a logging function that takes a sublogger, additional
+// structured logging fields and an arbitrary number of interface{} arguments.
+// This writes to configured io.Writer(s) as an debug message using default
+// formats for its operands. A new line is automatically added to the
+// output. If structured logging is not enabled, the fields will be ignored.
+func DebuglnWithFields(sl *SubLogger, extra ExtraFields, a ...interface{}) {
+	mu.RLock()
+	defer mu.RUnlock()
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stageln(f.logger.DebugHeader, a...)
+	}
+}
+
+// Debugf is a logging function that takes a sublogger, a format string along
+// with optional arguments. This writes to configured io.Writer(s) as an
+// debug message which formats according to the format specifier. A new line is
+// automatically added to the output.
 func Debugf(sl *SubLogger, data string, v ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		sl.getFields().stagef(f.logger.DebugHeader, data, v...)
 	}
-	if fields.debug {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintf(data, v...) },
-			fields.logger.DebugHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Warn takes a pointer subLogger struct & string and sends to StageLogEvent
-func Warn(sl *SubLogger, data string) {
+// DebugfWithFields is a logging function that takes a sublogger, additional
+// structured logging fields, a format string along with optional arguments.
+// This writes to configured io.Writer(s) as an debug message which formats
+// according to the format specifier. A new line is automatically added to the
+// output. If structured logging is not enabled, the fields will be ignored.
+func DebugfWithFields(sl *SubLogger, extra ExtraFields, format string, a ...interface{}) { //nolint:goprintffuncname // False positive
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stagef(f.logger.DebugHeader, format, a...)
 	}
-	if fields.warn {
-		fields.output.StageLogEvent(func() string { return data },
-			fields.logger.WarnHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Warnln takes a pointer subLogger struct & interface formats and sends to StageLogEvent
+// Warnln is a logging function that takes a sublogger and an arbitrary number
+// of interface{} arguments. This writes to configured io.Writer(s) as an
+// warning message using default formats for its operands. A new line is
+// automatically added to the output.
 func Warnln(sl *SubLogger, v ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.stageln(f.logger.WarnHeader, v...)
 	}
-	if fields.warn {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintln(v...) },
-			fields.logger.WarnHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Warnf takes a pointer subLogger struct, string and interface formats sends to StageLogEvent
+// WarnlnWithFields is a logging function that takes a sublogger, additional
+// structured logging fields and an arbitrary number of interface{} arguments.
+// This writes to configured io.Writer(s) as an warning message using default
+// formats for its operands. A new line is automatically added to the
+// output. If structured logging is not enabled, the fields will be ignored.
+func WarnlnWithFields(sl *SubLogger, extra ExtraFields, a ...interface{}) {
+	mu.RLock()
+	defer mu.RUnlock()
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stageln(f.logger.WarnHeader, a...)
+	}
+}
+
+// Warnf is a logging function that takes a sublogger, a format string along
+// with optional arguments. This writes to configured io.Writer(s) as an
+// warning message which formats according to the format specifier. A new line
+// is automatically added to the output.
 func Warnf(sl *SubLogger, data string, v ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		sl.getFields().stagef(f.logger.WarnHeader, data, v...)
 	}
-	if fields.warn {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintf(data, v...) },
-			fields.logger.WarnHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Error takes a pointer subLogger struct & interface formats and sends to StageLogEvent
-func Error(sl *SubLogger, data ...interface{}) {
+// WarnfWithFields is a logging function that takes a sublogger, additional
+// structured logging fields, a format string along with optional arguments.
+// This writes to configured io.Writer(s) as an warning message which formats
+// according to the format specifier. A new line is automatically added to the
+// output. If structured logging is not enabled, the fields will be ignored.
+func WarnfWithFields(sl *SubLogger, extra ExtraFields, format string, a ...interface{}) { //nolint:goprintffuncname // False positive
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stagef(f.logger.WarnHeader, format, a...)
 	}
-	if fields.error {
-		fields.output.StageLogEvent(func() string { return fmt.Sprint(data...) },
-			fields.logger.ErrorHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Errorln takes a pointer subLogger struct, string & interface formats and sends to StageLogEvent
+// Errorln is a logging function that takes a sublogger and an arbitrary number
+// of interface{} arguments. This writes to configured io.Writer(s) as an
+// error message using default formats for its operands. A new line is
+// automatically added to the output.
 func Errorln(sl *SubLogger, v ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		f.stageln(f.logger.ErrorHeader, v...)
 	}
-	if fields.error {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintln(v...) },
-			fields.logger.ErrorHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
-	}
-	logFieldsPool.Put(fields)
 }

-// Errorf takes a pointer subLogger struct, string and interface formats sends to StageLogEvent
+// ErrorlnWithFields is a logging function that takes a sublogger, additional
+// structured logging fields and an arbitrary number of interface{} arguments.
+// This writes to configured io.Writer(s) as an error message using default
+// formats for its operands. A new line is automatically added to the
+// output. If structured logging is not enabled, the fields will be ignored.
+func ErrorlnWithFields(sl *SubLogger, extra ExtraFields, a ...interface{}) {
+	mu.RLock()
+	defer mu.RUnlock()
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stageln(f.logger.ErrorHeader, a...)
+	}
+}
+
+// Errorf is a logging function that takes a sublogger, a format string along
+// with optional arguments. This writes to configured io.Writer(s) as an
+// error message which formats according to the format specifier. A new line
+// is automatically added to the output.
 func Errorf(sl *SubLogger, data string, v ...interface{}) {
 	mu.RLock()
 	defer mu.RUnlock()
-	fields := sl.getFields()
-	if fields == nil {
-		return
+	if f := sl.getFields(); f != nil {
+		sl.getFields().stagef(f.logger.ErrorHeader, data, v...)
 	}
-	if fields.error {
-		fields.output.StageLogEvent(func() string { return fmt.Sprintf(data, v...) },
-			fields.logger.ErrorHeader,
-			fields.name,
-			fields.logger.Spacer,
-			fields.logger.TimestampFormat,
-			fields.logger.ShowLogSystemName,
-			fields.logger.BypassJobChannelFilledWarning)
+}
+
+// ErrorfWithFields is a logging function that takes a sublogger, additional
+// structured logging fields, a format string along with optional arguments.
+// This writes to configured io.Writer(s) as an error message which formats
+// according to the format specifier. A new line is automatically added to the
+// output. If structured logging is not enabled, the fields will be ignored.
+func ErrorfWithFields(sl *SubLogger, extra ExtraFields, format string, a ...interface{}) { //nolint:goprintffuncname // False positive
+	mu.RLock()
+	defer mu.RUnlock()
+	if f := sl.getFields(); f != nil {
+		f.structuredFields = extra
+		f.stagef(f.logger.ErrorHeader, format, a...)
 	}
-	logFieldsPool.Put(fields)
 }

 func displayError(err error) {
@@ -250,3 +219,57 @@ func displayError(err error) {
 		log.Printf("Logger write error: %v\n", err)
 	}
 }
+
+// enabled checks if the log level is enabled
+func (l *fields) enabled(header string) string {
+	switch header {
+	case l.logger.InfoHeader:
+		if l.info {
+			return "info"
+		}
+	case l.logger.WarnHeader:
+		if l.warn {
+			return "warn"
+		}
+	case l.logger.ErrorHeader:
+		if l.error {
+			return "error"
+		}
+	case l.logger.DebugHeader:
+		if l.debug {
+			return "debug"
+		}
+	}
+	return ""
+}
+
+// stage stages a log event
+func (l *fields) stage(header string, deferFunc deferral) {
+	if l == nil {
+		return
+	}
+	if level := l.enabled(header); level != "" {
+		l.output.StageLogEvent(deferFunc,
+			header,
+			l.name,
+			l.logger.Spacer,
+			l.logger.TimestampFormat,
+			l.botName,
+			level,
+			l.logger.ShowLogSystemName,
+			l.logger.BypassJobChannelFilledWarning,
+			l.structuredLogging,
+			l.structuredFields)
+	}
+	logFieldsPool.Put(l)
+}
+
+// stageln stages a log event
+func (l *fields) stageln(header string, a ...interface{}) {
+	l.stage(header, func() string { return fmt.Sprint(a...) })
+}
+
+// stagef stages a log event
+func (l *fields) stagef(header, format string, a ...interface{}) {
+	l.stage(header, func() string { return fmt.Sprintf(format, a...) })
+}
--- a/log/sublogger.go
+++ b/log/sublogger.go
@@ -38,17 +38,18 @@ func (sl *SubLogger) setLevels(newLevels Levels) {

 // getFields returns sub logger specific fields for the potential log job.
 // Note: Calling function must have mutex lock in place.
-func (sl *SubLogger) getFields() *logFields {
+func (sl *SubLogger) getFields() *fields {
 	if sl == nil || globalLogConfig == nil || globalLogConfig.Enabled == nil || !*globalLogConfig.Enabled {
 		return nil
 	}
-
-	fields := logFieldsPool.Get().(*logFields) //nolint:forcetypeassert // Not necessary from a pool
-	fields.info = sl.levels.Info
-	fields.warn = sl.levels.Warn
-	fields.debug = sl.levels.Debug
-	fields.error = sl.levels.Error
-	fields.name = sl.name
-	fields.output = sl.output
-	return fields
+	f := logFieldsPool.Get().(*fields) //nolint:forcetypeassert // Not necessary from a pool
+	f.info = sl.levels.Info
+	f.warn = sl.levels.Warn
+	f.debug = sl.levels.Debug
+	f.error = sl.levels.Error
+	f.name = sl.name
+	f.output = sl.output
+	f.botName = sl.botName
+	f.structuredLogging = sl.structuredLogging
+	return f
 }
--- a/log/sublogger_types.go
+++ b/log/sublogger_types.go
@@ -35,19 +35,24 @@ var (
 // SubLogger defines a sub logger can be used externally for packages wanted to
 // leverage GCT library logger features.
 type SubLogger struct {
-	name   string
-	levels Levels
-	output *multiWriterHolder
+	name              string
+	levels            Levels
+	output            *multiWriterHolder
+	botName           string
+	structuredLogging bool
 }

-// logFields is used to store data in a non-global and thread-safe manner
+// fields is used to store data in a non-global and thread-safe manner
 // so logs cannot be modified mid-log causing a data-race issue
-type logFields struct {
-	info   bool
-	warn   bool
-	debug  bool
-	error  bool
-	name   string
-	output *multiWriterHolder
-	logger Logger
+type fields struct {
+	info              bool
+	warn              bool
+	debug             bool
+	error             bool
+	structuredLogging bool
+	name              string
+	output            *multiWriterHolder
+	logger            Logger
+	botName           string
+	structuredFields  ExtraFields
 }