diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml new file mode 100644 index 0000000..716b48c --- /dev/null +++ b/.github/workflows/go.yml @@ -0,0 +1,22 @@ +name: Go + +on: + push: + branches: [ master ] + pull_request: + branches: [ master ] + +jobs: + + build: + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v2 + + - name: Set up Go + uses: actions/setup-go@v2 + with: + go-version: 1.17 + + - name: Test + run: go test -v . diff --git a/.github/workflows/lock-threads.yml b/.github/workflows/lock-threads.yml new file mode 100644 index 0000000..e2c1b12 --- /dev/null +++ b/.github/workflows/lock-threads.yml @@ -0,0 +1,31 @@ +name: 'Lock Threads' + +on: + schedule: + - cron: '0 0 * * *' + workflow_dispatch: + +permissions: + issues: write + pull-requests: write + +concurrency: + group: lock + +jobs: + action: + runs-on: ubuntu-latest + steps: + - uses: dessant/lock-threads@v3 + with: + pr-inactive-days: '90' + issue-inactive-days: '90' + add-issue-labels: 'locked' + issue-comment: > + This issue was marked as resolved a long time ago and now has been + automatically locked as there has not been any recent activity after it. + You can still open a new issue and reference this link. + pr-comment: > + This pull request was marked as resolved a long time ago and now has been + automatically locked as there has not been any recent activity after it. + You can still open a new issue and reference this link. \ No newline at end of file diff --git a/README.md b/README.md index c1d53af..2dd37ff 100644 --- a/README.md +++ b/README.md @@ -1,2 +1,8 @@ -# krakend-gcplogging -Krakend Log Formatting for GCP +# krakend-gcploggin +A KrakenD log formatter compatible with gcplogging + +https://cloud.google.com/logging/docs/structured-logging + +Based on the following repository +https://github.com/krakend/krakend-logstash + diff --git a/go.mod b/go.mod new file mode 100644 index 0000000..59d7bd2 --- /dev/null +++ b/go.mod @@ -0,0 +1,14 @@ +module github.com/rachirib/krakend-gcplogging/v2 + +go 1.17 + +require ( + github.com/krakendio/krakend-gologging/v2 v2.0.1 + github.com/luraproject/lura/v2 v2.0.5 +) + +require ( + github.com/krakendio/flatmap v1.1.1 // indirect + github.com/op/go-logging v0.0.0-20160315200505-970db520ece7 // indirect + github.com/valyala/fastrand v1.1.0 // indirect +) diff --git a/go.sum b/go.sum new file mode 100644 index 0000000..0b53ceb --- /dev/null +++ b/go.sum @@ -0,0 +1,10 @@ +github.com/krakendio/flatmap v1.1.1 h1:rGBNVpBY0pMk6cLOwerVzoKY4HELnpu0xvqB231lOCQ= +github.com/krakendio/flatmap v1.1.1/go.mod h1:KBuVkiH5BcBFRa5A1HdSHDn8a8LzsyRTKZArX0vqTbo= +github.com/krakendio/krakend-gologging/v2 v2.0.1 h1:QuBgXfo9AMbMW2KrACPKGMg+gcbkGQqbiYnGDSPapS8= +github.com/krakendio/krakend-gologging/v2 v2.0.1/go.mod h1:ar6rViGYhsxtiCfxGeh7b7Djbh5wMIBXsyBKudADLJs= +github.com/luraproject/lura/v2 v2.0.5 h1:Mc4uj37s7mv6qRLy+Uo983CiaITPSVJYooeUilbiD+k= +github.com/luraproject/lura/v2 v2.0.5/go.mod h1:r2N4j89Snm1j+Y9CCa9cYR1T2ETRL0E4y9P+DgymqX4= +github.com/op/go-logging v0.0.0-20160315200505-970db520ece7 h1:lDH9UUVJtmYCjyT0CI4q8xvlXPxeZ0gYCVvWbmPlp88= +github.com/op/go-logging v0.0.0-20160315200505-970db520ece7/go.mod h1:HzydrMdWErDVzsI23lYNej1Htcns9BCg93Dk0bBINWk= +github.com/valyala/fastrand v1.1.0 h1:f+5HkLW4rsgzdNoleUOB69hyT9IlD2ZQh9GyDMfb5G8= +github.com/valyala/fastrand v1.1.0/go.mod h1:HWqCzkrkg6QXT8V2EXWvXCoow7vLwOFN002oeRzjapQ= diff --git a/logger.go b/logger.go new file mode 100644 index 0000000..99def66 --- /dev/null +++ b/logger.go @@ -0,0 +1,178 @@ +// Package logstash provides a logstash formatter for the krakend-gologging pkg +package gcplog + +import ( + "encoding/json" + "errors" + "fmt" + "io" + "os" + "time" + + gologging "github.com/krakendio/krakend-gologging/v2" + "github.com/luraproject/lura/v2/config" + "github.com/luraproject/lura/v2/logging" + "github.com/luraproject/lura/v2/proxy" +) + +const Namespace = "github.com/rachirib/krakend-gcplogging" + +var ( + ErrNothingToLog = errors.New("nothing to log") + ErrWrongConfig = fmt.Errorf("getting the extra config for the krakend-logstash module") + hostname = "localhost" + loggingPattern = "%{message}" +) + +func init() { + name, err := os.Hostname() + if err == nil { + hostname = name + } +} + +// NewLogger returns a krakend logger wrapping a gologging logger +func NewLogger(cfg config.ExtraConfig, ws ...io.Writer) (logging.Logger, error) { + _, ok := cfg[Namespace] + if !ok { + return nil, ErrWrongConfig + } + serviceName := "KRAKEND" + gologging.DefaultPattern = loggingPattern + if tmp, ok := cfg[gologging.Namespace]; ok { + if section, ok := tmp.(map[string]interface{}); ok { + if tmp, ok = section["prefix"]; ok { + if v, ok := tmp.(string); ok { + serviceName = v + } + delete(section, "prefix") + } + } + } + + loggr, err := gologging.NewLogger(cfg, ws...) + if err != nil { + return nil, err + } + + return &Logger{loggr, serviceName}, nil +} + +// Logger is a wrapper over a github.com/devopsfaith/krakend/logging logger +type Logger struct { + logger logging.Logger + serviceName string +} + +var now = time.Now + +func (l *Logger) format(logLevel LogLevel, v ...interface{}) ([]byte, error) { + if len(v) == 0 { + return []byte{}, ErrNothingToLog + } + + msg, ok := v[0].(string) + if !ok { + msg = fmt.Sprintf("%+v", v[0]) + } + record := map[string]interface{}{} + if len(v) > 1 { + for _, ctx := range v[1:] { + switch value := ctx.(type) { + case map[string]interface{}: + for k, item := range value { + record[k] = item + } + case int: + msg = fmt.Sprintf("%s %d", msg, value) + case bool: + msg = fmt.Sprintf("%s %t", msg, value) + case float64: + msg = fmt.Sprintf("%s %f", msg, value) + case string: + msg += " " + value + case *proxy.Request: + record["proxy.Request"] = value + case *proxy.Response: + record["proxy.Response"] = value + default: + record[fmt.Sprintf("%T", ctx)] = ctx + } + } + } + + record["@version"] = 1 + record["@timestamp"] = now().Format(ISO_8601) + record["module"] = l.serviceName + record["host"] = hostname + record["message"] = msg + record["severity"] = logLevel + + return json.Marshal(record) +} + +// Debug implements the logger interface +func (l *Logger) Debug(v ...interface{}) { + data, err := l.format(LEVEL_DEBUG, v...) + if err != nil { + return + } + l.logger.Debug(string(data)) +} + +// Info implements the logger interface +func (l *Logger) Info(v ...interface{}) { + data, err := l.format(LEVEL_INFO, v...) + if err != nil { + return + } + l.logger.Info(string(data)) +} + +// Warning implements the logger interface +func (l *Logger) Warning(v ...interface{}) { + data, err := l.format(LEVEL_WARNING, v...) + if err != nil { + return + } + l.logger.Warning(string(data)) +} + +// Error implements the logger interface +func (l *Logger) Error(v ...interface{}) { + data, err := l.format(LEVEL_ERROR, v...) + if err != nil { + return + } + l.logger.Error(string(data)) +} + +// Critical implements the logger interface +func (l *Logger) Critical(v ...interface{}) { + data, err := l.format(LEVEL_CRITICAL, v...) + if err != nil { + return + } + l.logger.Critical(string(data)) +} + +// Fatal implements the logger interface +func (l *Logger) Fatal(v ...interface{}) { + data, err := l.format(LEVEL_CRITICAL, v...) + if err != nil { + return + } + l.logger.Fatal(string(data)) +} + +type LogLevel string + +const ( + LEVEL_DEBUG = "DEBUG" + LEVEL_INFO = "INFO" + LEVEL_WARNING = "WARN" + LEVEL_ERROR = "ERROR" + LEVEL_CRITICAL = "EMERGENCY" + + ISO_8601 = "2006-01-02T15:04:05.000000-07:00" +) diff --git a/logger_test.go b/logger_test.go new file mode 100644 index 0000000..9b39908 --- /dev/null +++ b/logger_test.go @@ -0,0 +1,230 @@ +package gcplog + +import ( + "bytes" + "encoding/json" + "math" + "os" + "reflect" + "strings" + "testing" + "time" + + gologging "github.com/krakendio/krakend-gologging/v2" + "github.com/luraproject/lura/v2/config" + "github.com/luraproject/lura/v2/logging" +) + +func TestNewLogger(t *testing.T) { + logger, err := NewLogger(config.ExtraConfig{}) + if err == nil { + t.Error("expecting an error due empty config") + return + } + + cfg := config.ExtraConfig{ + gologging.Namespace: map[string]interface{}{ + "level": LEVEL_DEBUG, + "prefix": "module_name", + "stdout": true, + }, + Namespace: nil, + } + logger, err = NewLogger(cfg) + if err != nil { + t.Errorf("unexpected error: %s", err.Error()) + return + } + + logger.Debug("mayday, mayday, mayday", map[string]interface{}{"a": true, "b": false, "cost": math.Pi}) +} + +func TestLogger_nothingToLog(t *testing.T) { + buff := new(bytes.Buffer) + l, _ := logging.NewLogger(LEVEL_DEBUG, buff, "") + logger := Logger{ + logger: l, + serviceName: "some", + } + + logger.Debug() + logger.Info() + logger.Warning() + logger.Error() + logger.Critical() + + if content := buff.String(); content != "" { + t.Errorf("unexpected log content: %s", content) + } +} + +func TestLogger(t *testing.T) { + expectedModuleName := "module_name" + expectedMsg := "mayday, mayday, mayday" + buff := new(bytes.Buffer) + l, _ := logging.NewLogger(LEVEL_DEBUG, buff, "") + logger := Logger{ + logger: l, + serviceName: expectedModuleName, + } + + location, _ := time.LoadLocation("") + now = func() time.Time { + return time.Unix(1526464967, 0).In(location) + } + defer func() { now = time.Now }() + + logger.Debug(expectedMsg, map[string]interface{}{"a": true, "b": false, "cost": 42}) + logger.Info(expectedMsg, map[string]interface{}{"a": true, "b": false, "cost": 42}) + logger.Warning(expectedMsg, map[string]interface{}{"a": true, "b": false, "cost": 42}) + logger.Error(expectedMsg, map[string]interface{}{"a": true, "b": false, "cost": 42}) + logger.Critical(expectedMsg, map[string]interface{}{"a": true, "b": false, "cost": 42}) + + lines := strings.Split(buff.String(), "\n") + if len(lines) < 5 { + t.Errorf("unexpected number of logged lines (%d) : %s", len(lines), buff.String()) + return + } + levels := []string{"DEBUG", "INFO", "WARN", "ERROR", "EMERGENCY"} + for line, logLine := range lines[:5] { + if logLine[20:] == levels[line]+`: [{"@timestamp":"2018-05-16T10:02:47.000000+00:00","@version":1,"a":true,"b":false,"cost":42,"host":"localhost","severity":"`+levels[line]+`","message":"mayday, mayday, mayday","module":"module_name"}]]` { + t.Errorf("The output doesn't contain the expected msg for the line %d: [%s]", line, logLine) + } + } +} + +func TestLogger_format(t *testing.T) { + expectedModuleName := "module_name" + expectedMsg := "mayday, mayday, mayday" + cfg := config.ExtraConfig{ + gologging.Namespace: map[string]interface{}{ + "level": LEVEL_DEBUG, + "prefix": expectedModuleName, + "stdout": true, + }, + Namespace: nil, + } + logger, err := NewLogger(cfg) + if err != nil { + t.Errorf("unexpected error: %s", err.Error()) + return + } + + location, _ := time.LoadLocation("") + now = func() time.Time { + return time.Unix(1526464967, 0).In(location) + } + defer func() { now = time.Now }() + + for i, logLevel := range []LogLevel{ + LEVEL_DEBUG, + LEVEL_INFO, + LEVEL_WARNING, + LEVEL_ERROR, + LEVEL_CRITICAL, + } { + data, err := logger.(*Logger).format(logLevel, expectedMsg, map[string]interface{}{"a": true, "b": false, "cost": 42}) + if err != nil { + t.Errorf("unexpected error runing test case #%d: %s", i, err.Error()) + continue + } + var content map[string]interface{} + if err := json.Unmarshal(data, &content); err != nil { + t.Errorf("unexpected error unmarshaling the message #%d: %s", i, err.Error()) + continue + } + + expectedHostname, err := os.Hostname() + if err != nil { + t.Errorf("failed to get hostname runing test case #%d: %s", i, err.Error()) + continue + } + + expectedMessage := map[string]interface{}{ + "a": true, + "b": false, + "cost": 42.0, + "@version": 1.0, + "@timestamp": "2018-05-16T10:02:47.000000+00:00", + "module": expectedModuleName, + "host": expectedHostname, + "message": expectedMsg, + "severity": string(logLevel), + } + + for k, v := range content { + tmp, ok := expectedMessage[k] + if !ok { + t.Errorf("no value for key %s", k) + continue + } + + if !reflect.DeepEqual(tmp, v) { + t.Errorf("unexpected value for key %s. Have: %v, Want: %v", k, v, tmp) + } + } + } +} + +func TestLogger_format_unexpectedMessageType(t *testing.T) { + buff := new(bytes.Buffer) + l, _ := logging.NewLogger(LEVEL_DEBUG, buff, "") + logger := Logger{ + logger: l, + serviceName: "some", + } + + location, _ := time.LoadLocation("") + now = func() time.Time { + return time.Unix(1526464967, 0).In(location) + } + defer func() { now = time.Now }() + + expectedHostname, err := os.Hostname() + if err != nil { + t.Errorf("failed to get hostname: %s", err.Error()) + return + } + + for i, testCase := range []struct { + Expected string + Values []interface{} + }{ + { + Expected: `{"@timestamp":"2018-05-16T10:02:47.000000+00:00","@version":1,"host":"` + expectedHostname + `","message":"42","module":"some","severity":"DEBUG"}`, + Values: []interface{}{42}, + }, + { + Expected: `{"@timestamp":"2018-05-16T10:02:47.000000+00:00","@version":1,"a":1,"host":"` + expectedHostname + `","message":"42","module":"some","severity":"DEBUG"}`, + Values: []interface{}{42, map[string]interface{}{"a": 1}}, + }, + { + Expected: `{"@timestamp":"2018-05-16T10:02:47.000000+00:00","@version":1,"gcplog.sample":{"A":1},"host":"` + expectedHostname + `","message":"42","module":"some","severity":"DEBUG"}`, + Values: []interface{}{42, sample{A: 1}}, + }, + { + Expected: `{"@timestamp":"2018-05-16T10:02:47.000000+00:00","@version":1,"host":"` + expectedHostname + `","message":"hey there multi parts","module":"some","severity":"DEBUG"}`, + Values: []interface{}{"hey", "there", "multi", "parts"}, + }, + { + Expected: `{"@timestamp":"2018-05-16T10:02:47.000000+00:00","@version":1,"host":"` + expectedHostname + `","message":"true 3 1.100000 basic types true","module":"some","severity":"DEBUG"}`, + Values: []interface{}{true, 3, 1.1, "basic types", true}, + }, + { + Expected: `{"@timestamp":"2018-05-16T10:02:47.000000+00:00","@version":1,"gcplog.sample":{"A":1},"host":"` + expectedHostname + `","message":"true 3 1.100000 basic types true","module":"some","severity":"DEBUG"}`, + Values: []interface{}{true, 3, sample{A: 1}, 1.1, "basic types", true}, + }, + } { + data, err := logger.format(LEVEL_DEBUG, testCase.Values...) + if err != nil { + t.Errorf("unexpected error (#%d): %s", i, err.Error()) + continue + } + + if string(data) != testCase.Expected { + t.Errorf("unexpected result (#%d). Have: %s, Want: %s", i, string(data), testCase.Expected) + } + } +} + +type sample struct{ A int }