Fix missing set for http line delimiter on text proto writes (#216)

* Fix missing set for http line delimiter on text proto writes

Remove logging recorder in favour of recorder interface impelmentation

* Fixup bytes log and related expectation

Rename local config var due to import package naming

* Add test-cases for simple endpoint responses

logging/access_log.go

@@ -25,6 +25,12 @@ type AccessLog struct {
 	logger logrus.FieldLogger
 }
 
+type RecorderInfo interface {
+	StatusCode() int
+	WrittenBytes() int
+	ErrorHeader() string // TODO: drop in favour of new error-handling
+}
+
 func NewAccessLog(c *Config, logger logrus.FieldLogger) *AccessLog {
 	return &AccessLog{
 		conf:   c,
@@ -33,9 +39,6 @@ func NewAccessLog(c *Config, logger logrus.FieldLogger) *AccessLog {
 }
 
 func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextHandler http.Handler, startTime time.Time) {
-	statusRecorder := NewStatusRecorder(rw)
-	rw = statusRecorder
-
 	oCtx, acContext := ac.NewWithContext(req.Context())
 	*req = *req.WithContext(oCtx)
 
@@ -44,7 +47,6 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 
 	fields := Fields{
 		"proto": req.Proto,
-		"bytes": statusRecorder.writtenBytes,
 	}
 
 	backendName, _ := req.Context().Value(request.BackendName).(string)
@@ -97,16 +99,26 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 		fields["auth_user"] = user
 	}
 
+	var statusCode int
+	var writtenBytes int
+	var couperErr string
+	if recorder, ok := rw.(RecorderInfo); ok {
+		statusCode = recorder.StatusCode()
+		writtenBytes = recorder.WrittenBytes()
+		couperErr = recorder.ErrorHeader()
+	}
+
 	fields["realtime"] = roundMS(serveDone.Sub(startTime))
-	fields["status"] = statusRecorder.status
+	fields["status"] = statusCode
 
 	responseFields := Fields{
 		"headers": filterHeader(log.conf.ResponseHeaders, rw.Header()),
 	}
 	fields["response"] = responseFields
 
-	if statusRecorder.writtenBytes > 0 {
-		responseFields["bytes"] = statusRecorder.writtenBytes
+	if writtenBytes > 0 {
+		fields["bytes"] = writtenBytes
+		responseFields["bytes"] = writtenBytes
 	}
 
 	requestFields["tls"] = req.TLS != nil
@@ -126,7 +138,7 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 
 	var err error
 	fields["client_ip"], _ = splitHostPort(req.RemoteAddr)
-	if couperErr := statusRecorder.Header().Get(errors.HeaderErrorCode); couperErr != "" {
+	if couperErr != "" {
 		i, _ := strconv.Atoi(couperErr[:4])
 		err = errors.Code(i)
 		fields["code"] = i
@@ -139,7 +151,7 @@ func (log *AccessLog) ServeHTTP(rw http.ResponseWriter, req *http.Request, nextH
 		err = fmt.Errorf("access control: %s: %s", acContext.Name(), acError)
 	}
 
-	if statusRecorder.status == http.StatusInternalServerError || err != nil {
+	if statusCode == http.StatusInternalServerError || err != nil {
 		if err != nil {
 			entry.Error(err)
 			return

server/http_integration_test.go

@@ -28,6 +28,7 @@ import (
 	"github.com/avenga/couper/config"
 	"github.com/avenga/couper/config/configload"
 	"github.com/avenga/couper/internal/test"
+	"github.com/avenga/couper/logging"
 )
 
 var (
@@ -837,23 +838,27 @@ func TestHTTPServer_RequestHeaders(t *testing.T) {
 
 func TestHTTPServer_LogFields(t *testing.T) {
 	client := newClient()
-	config := "testdata/integration/endpoint_eval/10_couper.hcl"
+	conf := "testdata/integration/endpoint_eval/10_couper.hcl"
 
 	helper := test.New(t)
-	shutdown, logHook := newCouper(config, helper)
+	shutdown, logHook := newCouper(conf, helper)
 	defer shutdown()
 
 	req, err := http.NewRequest(http.MethodGet, "http://example.com:8080", nil)
 	helper.Must(err)
 
 	logHook.Reset()
-	_, err = client.Do(req)
+	res, err := client.Do(req)
 	helper.Must(err)
 
 	if l := len(logHook.Entries); l != 2 {
 		t.Fatalf("Unexpected number of log lines: %d", l)
 	}
 
+	resBytes, err := ioutil.ReadAll(res.Body)
+	helper.Must(err)
+	helper.Must(res.Body.Close())
+
 	backendLog := logHook.Entries[0]
 	accessLog := logHook.Entries[1]
 
@@ -877,22 +882,22 @@ func TestHTTPServer_LogFields(t *testing.T) {
 	if e, ok := accessLog.Data["endpoint"]; !ok || e != "/" {
 		t.Fatalf("Unexpected endpoint: %s", e)
 	}
-	if b, ok := accessLog.Data["bytes"]; !ok || b != 482 {
-		t.Fatalf("Unexpected number of bytes: %d", b)
+	if b, ok := accessLog.Data["bytes"]; !ok || b != len(resBytes) {
+		t.Fatalf("Unexpected number of bytes: %d\npayload: %s", b, string(resBytes))
 	}
 }
 
 func TestHTTPServer_QueryEncoding(t *testing.T) {
 	client := newClient()
 
-	config := "testdata/integration/endpoint_eval/10_couper.hcl"
+	conf := "testdata/integration/endpoint_eval/10_couper.hcl"
 
 	type expectation struct {
 		RawQuery string
 	}
 
 	helper := test.New(t)
-	shutdown, _ := newCouper(config, helper)
+	shutdown, _ := newCouper(conf, helper)
 	defer shutdown()
 
 	req, err := http.NewRequest(http.MethodGet, "http://example.com:8080?a=a%20a&x=x+x", nil)
@@ -1044,7 +1049,7 @@ func TestHTTPServer_OriginVsURL(t *testing.T) {
 func TestHTTPServer_TrailingSlash(t *testing.T) {
 	client := newClient()
 
-	config := "testdata/integration/endpoint_eval/11_couper.hcl"
+	conf := "testdata/integration/endpoint_eval/11_couper.hcl"
 
 	type expectation struct {
 		Path string
@@ -1065,7 +1070,7 @@ func TestHTTPServer_TrailingSlash(t *testing.T) {
 	} {
 		t.Run("TrailingSlash "+tc.path, func(subT *testing.T) {
 			helper := test.New(subT)
-			shutdown, _ := newCouper(config, helper)
+			shutdown, _ := newCouper(conf, helper)
 			defer shutdown()
 
 			req, err := http.NewRequest(http.MethodGet, "http://example.com:8080"+tc.path, nil)
@@ -2313,3 +2318,71 @@ func TestFunctions(t *testing.T) {
 		})
 	}
 }
+
+func TestEndpoint_Response(t *testing.T) {
+	client := newClient()
+	var redirSeen bool
+	client.CheckRedirect = func(req *http.Request, via []*http.Request) error {
+		redirSeen = true
+		return fmt.Errorf("do not follow")
+	}
+
+	shutdown, logHook := newCouper("testdata/integration/endpoint_eval/17_couper.hcl", test.New(t))
+	defer shutdown()
+
+	type testCase struct {
+		path          string
+		expStatusCode int
+	}
+
+	for _, tc := range []testCase{
+		{"/200", http.StatusOK},
+		{"/200/this-is-my-resp-body", http.StatusOK},
+		{"/204", http.StatusNoContent},
+		{"/301", http.StatusMovedPermanently},
+	} {
+		t.Run(tc.path[1:], func(subT *testing.T) {
+			helper := test.New(subT)
+
+			req, err := http.NewRequest(http.MethodGet, "http://localhost:8080"+tc.path, nil)
+			helper.Must(err)
+
+			res, err := client.Do(req)
+			if tc.expStatusCode == http.StatusMovedPermanently {
+				if !redirSeen {
+					t.Errorf("expected a redirect response")
+				}
+
+				resp := logHook.LastEntry().Data["response"]
+				fields := resp.(logging.Fields)
+				headers := fields["headers"].(map[string]string)
+				if headers["location"] != "https://couper.io/" {
+					t.Errorf("expected location header log")
+				}
+			} else {
+				helper.Must(err)
+			}
+
+			resBytes, err := ioutil.ReadAll(res.Body)
+			helper.Must(err)
+			helper.Must(res.Body.Close())
+
+			if res.StatusCode != tc.expStatusCode {
+				t.Errorf("%q: expected Status %d, got: %d", tc.path, tc.expStatusCode, res.StatusCode)
+				return
+			}
+
+			if logHook.LastEntry().Data["status"] != tc.expStatusCode {
+				t.Logf("%v", logHook.LastEntry())
+				t.Errorf("Expected statusCode log: %d", tc.expStatusCode)
+			}
+
+			if len(resBytes) > 0 {
+				b, exist := logHook.LastEntry().Data["bytes"]
+				if !exist || b != len(resBytes) {
+					t.Errorf("Want bytes log: %d\ngot:\t%v", len(resBytes), logHook.LastEntry())
+				}
+			}
+		})
+	}
+}

server/rw_wrapper.go

@@ -10,13 +10,16 @@ import (
 	"net/textproto"
 	"strconv"
 
+	"github.com/avenga/couper/errors"
 	"github.com/avenga/couper/handler/transport"
+	"github.com/avenga/couper/logging"
 )
 
 var (
-	_ http.Flusher        = &RWWrapper{}
-	_ http.Hijacker       = &RWWrapper{}
-	_ http.ResponseWriter = &RWWrapper{}
+	_ http.Flusher         = &RWWrapper{}
+	_ http.Hijacker        = &RWWrapper{}
+	_ http.ResponseWriter  = &RWWrapper{}
+	_ logging.RecorderInfo = &RWWrapper{}
 )
 
 // RWWrapper wraps the <http.ResponseWriter>.
@@ -28,6 +31,10 @@ type RWWrapper struct {
 	httpLineDelim []byte
 	secureCookies string
 	statusWritten bool
+	// logging info
+	statusCode      int
+	rawBytesWritten int
+	bytesWritten    int
 }
 
 // NewRWWrapper creates a new RWWrapper object.
@@ -52,10 +59,18 @@ func (w *RWWrapper) Header() http.Header {
 
 // Write wraps the Write method of the <http.ResponseWriter>.
 func (w *RWWrapper) Write(p []byte) (int, error) {
+	l := len(p)
+	w.rawBytesWritten += l
 	if !w.statusWritten {
 		if len(w.httpStatus) == 0 {
 			w.httpStatus = p[:]
-			return len(p), nil
+			// required for short writes without any additional header
+			// to detect EOH chunk later on
+			if l >= 2 {
+				w.httpLineDelim = p[l-2 : l]
+			}
+
+			return l, nil
 		}
 
 		// End-of-header
@@ -69,18 +84,21 @@ func (w *RWWrapper) Write(p []byte) (int, error) {
 			w.WriteHeader(w.parseStatusCode(w.httpStatus))
 		}
 
-		l := len(p)
 		if l >= 2 {
 			w.httpLineDelim = p[l-2 : l]
 		}
 		return w.headerBuffer.Write(p)
 	}
 
+	var n int
+	var writeErr error
 	if w.gz != nil {
-		return w.gz.Write(p)
+		n, writeErr = w.gz.Write(p)
+	} else {
+		n, writeErr = w.rw.Write(p)
 	}
-
-	return w.rw.Write(p)
+	w.bytesWritten += n
+	return n, writeErr
 }
 
 func (w *RWWrapper) Hijack() (net.Conn, *bufio.ReadWriter, error) {
@@ -118,6 +136,7 @@ func (w *RWWrapper) WriteHeader(statusCode int) {
 	w.configureHeader()
 	w.rw.WriteHeader(statusCode)
 	w.statusWritten = true
+	w.statusCode = statusCode
 }
 
 func (w *RWWrapper) configureHeader() {
@@ -141,3 +160,15 @@ func (w *RWWrapper) parseStatusCode(p []byte) int {
 	code, _ := strconv.Atoi(string(p[9:12]))
 	return code
 }
+
+func (w *RWWrapper) StatusCode() int {
+	return w.statusCode
+}
+
+func (w *RWWrapper) WrittenBytes() int {
+	return w.bytesWritten
+}
+
+func (w *RWWrapper) ErrorHeader() string {
+	return w.Header().Get(errors.HeaderErrorCode)
+}