Log fixes

DOCKER.md

@@ -20,22 +20,24 @@ docker run --rm -p 8080:8080 -v `pwd`:/htdocs avenga/couper
 | Variable  | Default  | Description  |
 |---        |---       |---           |
 | COUPER_CONFIG_FILE | `couper.hcl`  | Path to the configuration file. |
-| COUPER_LOG_FORMAT | `common`  | Can be set to `json` output which is the _container default_. |
 | COUPER_DEFAULT_PORT   | `8080`    | Sets the default port to the given value and does not override explicit `[host:port]` configurations from file. |
 | COUPER_XFH    | `false`   | Global configurations which uses the `Forwarded-Host` header instead of the request host.   |
 | COUPER_HEALTH_PATH    | `/healthz`   | Path for health-check requests for all servers and ports.   |
 | COUPER_NO_PROXY_FROM_ENV | `false` | Disables the connect hop to configured [proxy via environment](https://godoc.org/golang.org/x/net/http/httpproxy). |
 | COUPER_REQUEST_ID_FORMAT    | `common`   | If set to `uuid4` a rfc4122 uuid is used for `request.id` and related log fields.   |
 | COUPER_SECURE_COOKIES | `""` | If set to `"strip"`, the `Secure` flag is removed from all `Set-Cookie` HTTP header fields. |
-| COUPER_ACCESS_LOG_PARENT_FIELD | `""`  | An option for `json` log format to add all log fields as child properties. |
+| COUPER_TIMING_IDLE_TIMEOUT | `60s`  | The maximum amount of time to wait for the next request on client connections when keep-alives are enabled. |
+| COUPER_TIMING_READ_HEADER_TIMEOUT | `10s`  | The amount of time allowed to read client request headers. |
+| COUPER_TIMING_SHUTDOWN_DELAY | `0`  | The amount of time the server is marked as unhealthy until calling server close finally. |
+| COUPER_TIMING_SHUTDOWN_TIMEOUT | `0`  | The maximum amount of time allowed to close the server with all running connections. |
+|   |   |   |
+| COUPER_LOG_FORMAT | `common`  | Can be set to `json` output which is the _container default_. |
+| COUPER_LOG_PRETTY | `false`  | Global option for `json` log format which pretty prints with basic key coloring. |
+| COUPER_LOG_PARENT_FIELD | `""`  | An option for `json` log format to add all log fields as child properties. |
+| COUPER_LOG_TYPE_VALUE | `couper_daemon`  | Value for the runtime log field `type`. |
 | COUPER_ACCESS_LOG_TYPE_VALUE | `couper_access`  | Value for the log field `type`. |
 | COUPER_ACCESS_LOG_REQUEST_HEADERS | `User-Agent, Accept, Referer`  | A comma separated list of header names whose values should be logged. |
 | COUPER_ACCESS_LOG_RESPONSE_HEADERS | `Cache-Control, Content-Encoding, Content-Type, Location`  | A comma separated list of header names whose values should be logged. |
-| COUPER_BACKEND_LOG_PARENT_FIELD | `""`  | An option for `json` log format to add all log fields as child properties. |
 | COUPER_BACKEND_LOG_TYPE_VALUE | `couper_backend`  | Value for the log field `type`. |
 | COUPER_BACKEND_LOG_REQUEST_HEADERS | `User-Agent, Accept, Referer`  | A comma separated list of header names whose values should be logged. |
 | COUPER_BACKEND_LOG_RESPONSE_HEADERS | `Cache-Control, Content-Encoding, Content-Type, Location`  | A comma separated list of header names whose values should be logged. |
-| COUPER_TIMING_IDLE_TIMEOUT | `60s`  | The maximum amount of time to wait for the next request on client connections when keep-alives are enabled. |
-| COUPER_TIMING_READ_HEADER_TIMEOUT | `10s`  | The amount of time allowed to read client request headers. |
-| COUPER_TIMING_SHUTDOWN_DELAY | `0`  | The amount of time the server is marked as unhealthy until calling server close finally. |
-| COUPER_TIMING_SHUTDOWN_TIMEOUT | `0`  | The maximum amount of time allowed to close the server with all running connections. |

command/run.go

@@ -54,7 +54,7 @@ func (r Run) Execute(args Args, config *config.Couper, logEntry *logrus.Entry) e
 		return err
 	}
 
-	serverList, listenCmdShutdown := server.NewServerList(r.context, config.Context, logEntry.Logger, config.Settings, &timings, srvConf)
+	serverList, listenCmdShutdown := server.NewServerList(r.context, config.Context, logEntry, config.Settings, &timings, srvConf)
 	for _, srv := range serverList {
 		srv.Listen()
 	}

config/settings.go

@@ -15,6 +15,7 @@ type Settings struct {
 	DefaultPort     int    `hcl:"default_port,optional"`
 	HealthPath      string `hcl:"health_path,optional"`
 	LogFormat       string `hcl:"log_format,optional"`
+	LogPretty       bool   `hcl:"log_pretty,optional"`
 	NoProxyFromEnv  bool   `hcl:"no_proxy_from_env,optional"`
 	RequestIDFormat string `hcl:"request_id_format,optional"`
 	SecureCookies   string `hcl:"secure_cookies,optional"`

docs/README.md

@@ -844,6 +844,7 @@ gateway instance.
 | `no_proxy_from_env` | Disables the connect hop to configured [proxy via environment](https://godoc.org/golang.org/x/net/http/httpproxy). | `false` |
 | `default_port`      | Port which will be used if not explicitly specified per host within the [`hosts`](#server-block) list | `8080` |
 | `log_format`        | Switch for tab/field based colored view or json log lines | `common` |
+| `log_pretty`        | Global option for `json` log format which pretty prints with basic key coloring | `false` |
 | `xfh`               | Option to use the `X-Forwarded-Host` header as the request host | `false` |
 | `request_id_format` | If set to `uuid4` a rfc4122 uuid is used for `request.id` and related log fields | `common` |
 | `secure_cookies`    | If set to `"strip"`, the `Secure` flag is removed from all `Set-Cookie` HTTP header fields. | `""` |

go.mod

@@ -5,10 +5,12 @@ go 1.16
 require (
 	github.com/dgrijalva/jwt-go/v4 v4.0.0-preview1
 	github.com/docker/go-units v0.4.0
+	github.com/fatih/color v1.10.0
 	github.com/getkin/kin-openapi v0.49.0
 	github.com/hashicorp/hcl/v2 v2.9.1
 	github.com/rs/xid v1.2.1
 	github.com/russellhaering/gosaml2 v0.6.0
+	github.com/russellhaering/goxmldsig v1.1.0
 	github.com/satori/go.uuid v1.2.0
 	github.com/sirupsen/logrus v1.8.1
 	github.com/zclconf/go-cty v1.8.0

go.sum

@@ -14,6 +14,8 @@ github.com/dgrijalva/jwt-go/v4 v4.0.0-preview1 h1:CaO/zOnF8VvUfEbhRatPcwKVWamvbY
 github.com/dgrijalva/jwt-go/v4 v4.0.0-preview1/go.mod h1:+hnT3ywWDTAFrW5aE+u2Sa/wT555ZqwoCS+pk3p6ry4=
 github.com/docker/go-units v0.4.0 h1:3uh0PgVws3nIA0Q+MwDC8yjEPf9zjRfZZWXZYDct3Tw=
 github.com/docker/go-units v0.4.0/go.mod h1:fgPhTUdO+D/Jk86RDLlptpiXQzgHJF7gydDDbaIK4Dk=
+github.com/fatih/color v1.10.0 h1:s36xzo75JdqLaaWoiEHk767eHiwo0598uUxyfiPkDsg=
+github.com/fatih/color v1.10.0/go.mod h1:ELkj/draVOlAH/xkhN6mQ50Qd0MPOk5AAr3maGEBuJM=
 github.com/getkin/kin-openapi v0.49.0 h1:nKSq662fS0kZ11+Wu3FLg3GQGL0UuH1VxF8wV1QuDEU=
 github.com/getkin/kin-openapi v0.49.0/go.mod h1:ZJSfy1PxJv2QQvH9EdBj3nupRTVvV42mkW6zKUlRBwk=
 github.com/ghodss/yaml v1.0.0 h1:wQHKEahhL6wmXdzwWG11gIVCkOv05bNOh+Rxn0yngAk=
@@ -45,6 +47,10 @@ github.com/mailru/easyjson v0.0.0-20190626092158-b2ccc519800e h1:hB2xlXdHp/pmPZq
 github.com/mailru/easyjson v0.0.0-20190626092158-b2ccc519800e/go.mod h1:C1wdFJiN94OJF2b5HbByQZoLdCWB1Yqtg26g4irojpc=
 github.com/mattermost/xml-roundtrip-validator v0.0.0-20201208211235-fe770d50d911 h1:erppMjjp69Rertg1zlgRbLJH1u+eCmRPxKjMZ5I8/Ro=
 github.com/mattermost/xml-roundtrip-validator v0.0.0-20201208211235-fe770d50d911/go.mod h1:qccnGMcpgwcNaBnxqpJpWWUiPNr5H3O8eDgGV9gT5To=
+github.com/mattn/go-colorable v0.1.8 h1:c1ghPdyEDarC70ftn0y+A/Ee++9zz8ljHG1b13eJ0s8=
+github.com/mattn/go-colorable v0.1.8/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
+github.com/mattn/go-isatty v0.0.12 h1:wuysRhFDzyxgEmMf5xjvJ2M9dZoWAXNNr5LSBS7uHXY=
+github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
 github.com/mitchellh/go-wordwrap v0.0.0-20150314170334-ad45545899c7 h1:DpOJ2HYzCv8LZP15IdmG+YdwD2luVPHITV96TkirNBM=
 github.com/mitchellh/go-wordwrap v0.0.0-20150314170334-ad45545899c7/go.mod h1:ZXFpozHsX6DPmq2I0TCekCxypsnAUbP2oI0UX1GXzOo=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
@@ -65,8 +71,8 @@ github.com/spf13/pflag v1.0.2/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnIn
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
-github.com/stretchr/testify v1.5.1 h1:nOGnQDM7FYENwehXlg/kFVnos3rEvtKTjRvOWSzb6H4=
 github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA=
+github.com/stretchr/testify v1.6.1 h1:hDPOHmpOpP40lSULcqw7IrRb/u7w6RpDC9399XyoNd0=
 github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/vmihailenco/msgpack v3.3.3+incompatible/go.mod h1:fy3FlTQTDXWkZ7Bh6AcGMlsjHatGryHQYUTf1ShIgkk=
 github.com/vmihailenco/msgpack/v4 v4.3.12/go.mod h1:gborTTJjAo/GWTqqRjrLCn9pgNN+NXzzngzBKDPIqw4=
@@ -90,6 +96,8 @@ golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5h
 golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20190502175342-a43fa875dd82/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20200116001909-b77594299b42/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20200223170610-d5e6a3e2c0ae/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f h1:+Nyd8tzPX9R7BWHguqsrbFdRx3WQ/1ib8I44HXV5yTA=
 golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
@@ -109,4 +117,5 @@ gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.3.0 h1:clyUAQHOM3G0M3f5vQj7LuJrETvjVot3Z5el9nffUtU=
 gopkg.in/yaml.v2 v2.3.0/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c h1:dUUwHk2QECo/6vqA44rthZ8ie2QXMNeKRTHCNY2nXvo=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

logging/access_log.go

@@ -136,12 +136,7 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 		fields["code"] = i
 	}
 
-	var entry *logrus.Entry
-	if log.conf.ParentFieldKey != "" {
-		entry = log.logger.WithField(log.conf.ParentFieldKey, fields)
-	} else {
-		entry = log.logger.WithFields(logrus.Fields(fields))
-	}
+	entry := log.logger.WithFields(logrus.Fields(fields))
 	entry.Time = startTime
 
 	if statusRecorder.status == http.StatusInternalServerError || err != nil {

logging/json_color_formatter.go

@@ -0,0 +1,40 @@
+package logging
+
+import (
+	"regexp"
+
+	"github.com/fatih/color"
+	"github.com/sirupsen/logrus"
+)
+
+type JSONColorFormatter struct {
+	inner *logrus.JSONFormatter
+}
+
+func NewJSONColorFormatter(parent string, pretty bool) logrus.Formatter {
+	return &JSONColorFormatter{
+		inner: &logrus.JSONFormatter{
+			DataKey: parent,
+			FieldMap: logrus.FieldMap{
+				logrus.FieldKeyTime: "timestamp",
+				logrus.FieldKeyMsg:  "message",
+			},
+			PrettyPrint: pretty,
+		},
+	}
+}
+
+var keyRegex = regexp.MustCompile(`"(?:(?:[^"]|\\")*)"\s*:`)
+
+func (jcf *JSONColorFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	b, err := jcf.inner.Format(entry)
+	if !jcf.inner.PrettyPrint || err != nil {
+		return b, err
+	}
+
+	result := keyRegex.ReplaceAllFunc(b, func(needle []byte) []byte {
+		return []byte(color.HiGreenString("%s", string(needle)))
+	})
+
+	return result, err
+}

logging/upstream_log.go

@@ -146,12 +146,7 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 	fields["timings"] = timingResults
 	//timings["ttlb"] = roundMS(rtDone.Sub(timeTTFB)) // TODO: depends on stream or buffer
 
-	var entry *logrus.Entry
-	if u.config.ParentFieldKey != "" {
-		entry = u.log.WithField(u.config.ParentFieldKey, fields)
-	} else {
-		entry = u.log.WithFields(logrus.Fields(fields))
-	}
+	entry := u.log.WithFields(logrus.Fields(fields))
 	entry.Time = startTime
 
 	if (beresp != nil && beresp.StatusCode == http.StatusInternalServerError) || err != nil {

main.go

@@ -14,11 +14,11 @@ import (
 	"github.com/avenga/couper/config/configload"
 	"github.com/avenga/couper/config/env"
 	"github.com/avenga/couper/config/runtime"
+	"github.com/avenga/couper/logging"
 )
 
 var (
 	fields = logrus.Fields{
-		"type":    "couper_daemon",
 		"build":   runtime.BuildName,
 		"version": runtime.VersionName,
 	}
@@ -46,18 +46,20 @@ func realmain(arguments []string) int {
 	}
 
 	var filePath, logFormat string
+	var logPretty bool
 	set := flag.NewFlagSet("global", flag.ContinueOnError)
 	set.StringVar(&filePath, "f", config.DefaultFilename, "-f ./couper.hcl")
 	set.StringVar(&logFormat, "log-format", config.DefaultSettings.LogFormat, "-log-format=common")
+	set.BoolVar(&logPretty, "log-pretty", config.DefaultSettings.LogPretty, "-log-pretty")
 	err := set.Parse(args.Filter(set))
 	if err != nil {
-		newLogger(logFormat).WithFields(fields).Error(err)
+		newLogger(logFormat, logPretty).Error(err)
 		return 1
 	}
 
 	confFile, err := configload.LoadFile(filePath)
 	if err != nil {
-		newLogger(logFormat).WithFields(fields).Error(err)
+		newLogger(logFormat, logPretty).Error(err)
 		return 1
 	}
 
@@ -66,11 +68,14 @@ func realmain(arguments []string) int {
 	if logFormat != config.DefaultSettings.LogFormat {
 		confFile.Settings.LogFormat = logFormat
 	}
-	logger := newLogger(confFile.Settings.LogFormat).WithFields(fields)
+	if logPretty != config.DefaultSettings.LogPretty {
+		confFile.Settings.LogPretty = logPretty
+	}
+	logger := newLogger(confFile.Settings.LogFormat, confFile.Settings.LogPretty)
 
 	wd, err := os.Getwd()
 	if err != nil {
-		logger.WithFields(fields).Error(err)
+		logger.Error(err)
 		return 1
 	}
 	logger.Infof("working directory: %s", wd)
@@ -85,23 +90,28 @@ func realmain(arguments []string) int {
 // newLogger creates a log instance with the configured formatter.
 // Since the format option may required to be correct in early states
 // we parse the env configuration on every call.
-func newLogger(format string) logrus.FieldLogger {
+func newLogger(format string, pretty bool) *logrus.Entry {
 	logger := logrus.New()
 	logger.Out = os.Stdout
 	if hook != nil {
 		logger.AddHook(hook)
 		logger.Out = ioutil.Discard
 	}
 
-	settings := &config.Settings{LogFormat: format}
+	settings := &config.Settings{
+		LogFormat: format,
+		LogPretty: pretty,
+	}
 	env.Decode(settings)
 
+	logConf := &logging.Config{
+		TypeFieldKey: "couper_daemon",
+	}
+	env.Decode(logConf)
+
 	if settings.LogFormat == "json" {
-		logger.Formatter = &logrus.JSONFormatter{FieldMap: logrus.FieldMap{
-			logrus.FieldKeyTime: "timestamp",
-			logrus.FieldKeyMsg:  "message",
-		}}
+		logger.SetFormatter(logging.NewJSONColorFormatter(logConf.ParentFieldKey, settings.LogPretty))
 	}
 	logger.Level = logrus.DebugLevel
-	return logger
+	return logger.WithField("type", logConf.TypeFieldKey).WithFields(fields)
 }