Add http status code to the main log msg (#719)

* Add http status code to the main log msg

runtime/server_http_request_test.go

@@ -175,7 +175,7 @@ func TestDoubleParseQueryValues(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingGetQueryBool(t *testing.T) {
@@ -237,7 +237,7 @@ func TestFailingGetQueryBool(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingGetQueryInt8(t *testing.T) {
@@ -299,7 +299,7 @@ func TestFailingGetQueryInt8(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingHasQueryValue(t *testing.T) {
@@ -361,7 +361,7 @@ func TestFailingHasQueryValue(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingGetQueryInt16(t *testing.T) {
@@ -423,7 +423,7 @@ func TestFailingGetQueryInt16(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingGetQueryInt32(t *testing.T) {
@@ -485,7 +485,7 @@ func TestFailingGetQueryInt32(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingGetQueryInt64(t *testing.T) {
@@ -547,7 +547,7 @@ func TestFailingGetQueryInt64(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingGetQueryFloat64(t *testing.T) {
@@ -609,7 +609,7 @@ func TestFailingGetQueryFloat64(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestFailingHasQueryPrefix(t *testing.T) {
@@ -671,7 +671,7 @@ func TestFailingHasQueryPrefix(t *testing.T) {
 	// Assert that there is only one log even though
 	// we double call GetQueryValue
 	assert.Equal(t, 1, len(logs["Got request with invalid query string"]))
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 }
 
 func TestGetQueryBoolList(t *testing.T) {
@@ -2378,9 +2378,9 @@ func TestIncomingHTTPRequestServerLog(t *testing.T) {
 	assert.NoError(t, err)
 
 	allLogs := bgateway.AllLogs()
-	assert.Equal(t, 1, len(allLogs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(allLogs["Finished an incoming server HTTP request with 200 status code"]))
 
-	tags := allLogs["Finished an incoming server HTTP request"][0]
+	tags := allLogs["Finished an incoming server HTTP request with 200 status code"][0]
 	dynamicHeaders := []string{
 		"requestUUID",
 		"remoteAddr",
@@ -2397,7 +2397,7 @@ func TestIncomingHTTPRequestServerLog(t *testing.T) {
 	}
 
 	expectedValues := map[string]interface{}{
-		"msg":             "Finished an incoming server HTTP request",
+		"msg":             "Finished an incoming server HTTP request with 200 status code",
 		"env":             "test",
 		"level":           "debug",
 		"zone":            "unknown",

runtime/server_http_response.go

@@ -120,7 +120,7 @@ func (res *ServerHTTPResponse) finish(ctx context.Context) {
 	}
 
 	logFn(
-		"Finished an incoming server HTTP request",
+		fmt.Sprintf("Finished an incoming server HTTP request with %d status code", res.StatusCode),
 		append(logFields, serverHTTPLogFields(res.Request, res)...)...,
 	)
 }

test/endpoints/bar/bar_arg_with_query_params_test.go

@@ -730,7 +730,7 @@ func TestBarWithManyQueryParamsRequiredCall(t *testing.T) {
 
 	logs := gateway.AllLogs()
 
-	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request"]))
+	assert.Equal(t, 1, len(logs["Finished an incoming server HTTP request with 400 status code"]))
 	assert.Equal(t, 1, len(logs["Started Example-gateway"]))
 	assert.Equal(t, 1, len(logs["Got request with missing query string value"]))
 

test/endpoints/baz/baz_simpleservice_method_ping_test.go

@@ -206,7 +206,7 @@ func TestPingWithInvalidResponse(t *testing.T) {
 	assert.Len(t, gateway.Logs("info", "Created new active connection."), 1)
 	assert.Len(t, gateway.Logs("info", "Failed after non-retriable error."), 1)
 	assert.Len(t, gateway.Logs("warn", "Client failure: TChannel client call returned error"), 1)
-	assert.Len(t, gateway.Logs("warn", "Finished an incoming server HTTP request"), 1)
+	assert.Len(t, gateway.Logs("warn", "Finished an incoming server HTTP request with 500 status code"), 1)
 	assert.Len(t, gateway.Logs("warn", "Failed to send outgoing client TChannel request"), 1)
 	assert.Len(t, gateway.Logs("warn", "Client failure: could not make client request"), 1)
 

test/lib/bench_gateway/bench_gateway.go

@@ -21,7 +21,6 @@
 package benchgateway
 
 import (
-	"bytes"
 	"context"
 	"encoding/json"
 	"io"
@@ -32,6 +31,8 @@ import (
 	"strings"
 	"time"
 
+	"github.com/uber/zanzibar/test/lib/util"
+
 	"github.com/uber/zanzibar/config"
 	zanzibar "github.com/uber/zanzibar/runtime"
 	testBackend "github.com/uber/zanzibar/test/lib/test_backend"
@@ -46,7 +47,7 @@ type BenchGateway struct {
 
 	backendsHTTP     map[string]*testBackend.TestHTTPBackend
 	backendsTChannel map[string]*testBackend.TestTChannelBackend
-	logBytes         *bytes.Buffer
+	logBytes         *util.Buffer
 	readLogs         bool
 	logMessages      map[string][]testGateway.LogMessage
 	httpClient       *http.Client
@@ -133,7 +134,7 @@ func CreateGateway(
 		},
 		backendsHTTP:     backendsHTTP,
 		backendsTChannel: backendsTChannel,
-		logBytes:         bytes.NewBuffer(nil),
+		logBytes:         &util.Buffer{},
 
 		readLogs:     false,
 		logMessages:  map[string][]testGateway.LogMessage{},

test/lib/util/util.go

@@ -21,8 +21,10 @@
 package util
 
 import (
+	"bytes"
 	"path/filepath"
 	"runtime"
+	"sync"
 )
 
 // DefaultMainFile returns the expected main.go file path for an example
@@ -58,3 +60,25 @@ func getDirName() string {
 
 	return filepath.Dir(file)
 }
+
+// Buffer is a goroutine safe bytes.Buffer
+type Buffer struct {
+	buffer bytes.Buffer
+	mutex  sync.Mutex
+}
+
+// Write appends the contents of p to the buffer, growing the buffer as needed. It returns
+// the number of bytes written.
+func (s *Buffer) Write(p []byte) (n int, err error) {
+	s.mutex.Lock()
+	defer s.mutex.Unlock()
+	return s.buffer.Write(p)
+}
+
+// String returns the contents of the unread portion of the buffer
+// as a string.  If the Buffer is a nil pointer, it returns "<nil>".
+func (s *Buffer) String() string {
+	s.mutex.Lock()
+	defer s.mutex.Unlock()
+	return s.buffer.String()
+}