Improve OPA logging

This changes how OPA logs API requests and responses.

Before:
- OPA would not log at level.Info
- OPA would log request header and body and response header (but not
  body) at level.Debug.

After:
- OPA logs request and response headers at level.Info
- OPA includes request and response body at level.Debug.

runtime/logging.go

@@ -18,10 +18,8 @@ import (
 	"github.com/open-policy-agent/opa/server/types"
 )
 
-// DebugLogging returns true if log verbosity is high enough to emit debug
-// messages.
-func DebugLogging() bool {
-	return logrus.DebugLevel >= logrus.GetLevel()
+func loggingEnabled(level logrus.Level) bool {
+	return level <= logrus.GetLevel()
 }
 
 // LoggingHandler returns an http.Handler that will print log messages
@@ -37,37 +35,39 @@ func NewLoggingHandler(inner http.Handler) http.Handler {
 }
 
 func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
-	recorder := newRecorder(w)
+	recorder := newRecorder(w, loggingEnabled(logrus.DebugLevel))
 	t0 := time.Now()
 	requestID := atomic.AddUint64(&h.requestID, uint64(1))
 
-	if DebugLogging() {
+	if loggingEnabled(logrus.InfoLevel) {
+
+		fields := logrus.Fields{
+			"client_addr": r.RemoteAddr,
+			"req_id":      requestID,
+			"req_method":  r.Method,
+			"req_path":    r.URL.Path,
+			"req_params":  r.URL.Query(),
+		}
 
-		var bs []byte
 		var err error
 
-		if r.Body != nil {
-			bs, r.Body, err = readBody(r.Body)
+		if loggingEnabled(logrus.DebugLevel) {
+			var bs []byte
+			var err error
+			if r.Body != nil {
+				bs, r.Body, err = readBody(r.Body)
+			}
+			if err == nil {
+				fields["req_body"] = string(bs)
+			} else {
+				fields["err"] = err
+			}
 		}
 
 		if err == nil {
-			logrus.WithFields(logrus.Fields{
-				"client_addr": r.RemoteAddr,
-				"req_id":      requestID,
-				"req_method":  r.Method,
-				"req_path":    r.URL.Path,
-				"req_params":  r.URL.Query(),
-				"req_body":    string(bs),
-			}).Debug("Received request.")
+			logrus.WithFields(fields).Info("Received request.")
 		} else {
-			logrus.WithFields(logrus.Fields{
-				"client_addr": r.RemoteAddr,
-				"req_id":      requestID,
-				"req_method":  r.Method,
-				"req_path":    r.URL.Path,
-				"req_params":  r.URL.Query(),
-				"err":         err,
-			}).Error("Failed to read body.")
+			logrus.WithFields(fields).Error("Failed to read body.")
 		}
 	}
 
@@ -79,27 +79,39 @@ func (h *LoggingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		statusCode = recorder.statusCode
 	}
 
-	if DebugLogging() {
-		logrus.WithFields(logrus.Fields{
+	if loggingEnabled(logrus.InfoLevel) {
+		fields := logrus.Fields{
 			"client_addr":   r.RemoteAddr,
 			"req_id":        requestID,
 			"req_method":    r.Method,
 			"req_path":      r.URL.Path,
 			"resp_status":   statusCode,
 			"resp_bytes":    recorder.bytesWritten,
 			"resp_duration": float64(dt.Nanoseconds()) / 1e6,
-		}).Debug("Sent response.")
+		}
+
+		if loggingEnabled(logrus.DebugLevel) {
+			fields["resp_body"] = recorder.buf.String()
+		}
+
+		logrus.WithFields(fields).Info("Sent response.")
 	}
 }
 
 type recorder struct {
 	inner        http.ResponseWriter
+	buf          *bytes.Buffer
 	bytesWritten int
 	statusCode   int
 }
 
-func newRecorder(w http.ResponseWriter) *recorder {
+func newRecorder(w http.ResponseWriter, buffer bool) *recorder {
+	var buf *bytes.Buffer
+	if buffer {
+		buf = new(bytes.Buffer)
+	}
 	return &recorder{
+		buf:   buf,
 		inner: w,
 	}
 }
@@ -110,6 +122,9 @@ func (r *recorder) Header() http.Header {
 
 func (r *recorder) Write(bs []byte) (int, error) {
 	r.bytesWritten += len(bs)
+	if r.buf != nil {
+		r.buf.Write(bs)
+	}
 	return r.inner.Write(bs)
 }
 

site/documentation/references/deployments/index.md

@@ -63,18 +63,20 @@ curl -i localhost:8181/
 
 #### Logging
 
-OPA logs to stderr. The verbosity can be increased with `--log-level
-debug` to provide details on API requests and responses:
+OPA logs to stderr and the level can be set with `--log-level/-l`. The default log level is `info` which causes OPA to log request/response headers.
 
 ```
 time="2017-03-12T03:03:23Z" level=info msg="First line of log stream." addr=":8181"
 time="2017-03-12T03:03:30Z" level=debug msg="Received request." client_addr="172.17.0.1:60952" req_body= req_id=1 req_method=GET req_params=map[] req_path="/v1/data"
 time="2017-03-12T03:03:30Z" level=debug msg="Sent response." client_addr="172.17.0.1:60952" req_id=1 req_method=GET req_path="/v1/data" resp_bytes=13 resp_duration=0.402793 resp_status=200
 ```
 
-> Request logs contain the entire message body. This is useful for debugging
-> purposes but can be expensive in practice.
-{: .opa-tip }
+If the log level is set to `debug` the request and response message bodies will be logged. This is useful for development however it can be expensive in production.
+
+```
+time="2017-05-16T00:09:24Z" level=info msg="Received request." client_addr="172.17.0.1:42164" req_body="{"input": "hello"}" req_id=1 req_method=POST req_params=map[] req_path="/v1/data"
+time="2017-05-16T00:09:24Z" level=info msg="Sent response." client_addr="172.17.0.1:42164" req_id=1 req_method=POST req_path="/v1/data" resp_body="{"result":{"example":{"message":"world"}}}" resp_bytes=42 resp_duration=0.618689 resp_status=200
+```
 
 The default log format is text-based and intended for development. For
 production, enable JSON formatting with `--log-format json`: