Repository: valyala/fasthttp
Pull request #1001 (2021-03-24 18:46:43)

Adding support for securing error logs
For some applications handling sensitive data, it can violate certain certifications, such as HIPAA, to log parts of requests and responses like the header and body.

This PR adds the option `SecureErrorLogMessage` which will replace the fully detailed error messages with more generic ones so that they can safely be logged.


Patch:
diff --git a/client.go b/client.go
index cce5fa7..f135ec3 100644
--- a/client.go
+++ b/client.go
@@ -297,6 +297,8 @@ type Client struct {
 	mLock sync.Mutex
 	m     map[string]*HostClient
 	ms    map[string]*HostClient
+	readerPool sync.Pool
+	writerPool sync.Pool
 }
 
 // Get returns the status code and body of url.
@@ -503,6 +505,8 @@ func (c *Client) Do(req *Request, resp *Response) error {
 			DisablePathNormalizing:        c.DisablePathNormalizing,
 			MaxConnWaitTimeout:            c.MaxConnWaitTimeout,
 			RetryIf:                       c.RetryIf,
+			clientReaderPool:              &c.readerPool,
+			clientWriterPool:              &c.writerPool,
 		}
 		m[string(host)] = hc
 		if len(m) == 1 {
@@ -723,6 +727,14 @@ type HostClient struct {
 	// extra slashes are removed, special characters are encoded.
 	DisablePathNormalizing bool
 
+	// Will not log potentially sensitive content in error logs
+	//
+	// This option is useful for servers that handle sensitive data
+	// in the request/response.
+	//
+	// Client logs full errors by default.
+	SecureErrorLogMessage bool
+
 	// Maximum duration for waiting for a free connection.
 	//
 	// By default will not waiting, return ErrNoFreeConns immediately
@@ -751,6 +763,9 @@ type HostClient struct {
 	readerPool sync.Pool
 	writerPool sync.Pool
 
+	clientReaderPool *sync.Pool
+	clientWriterPool *sync.Pool
+
 	pendingRequests int32
 
 	connsCleanerRun bool
@@ -1325,6 +1340,12 @@ func (c *HostClient) doNonNilReqResp(req *Request, resp *Response) (bool, error)
 		panic("BUG: resp cannot be nil")
 	}
 
+	// Secure header error logs configuration
+	resp.secureErrorLogMessage = c.SecureErrorLogMessage
+	resp.Header.secureErrorLogMessage = c.SecureErrorLogMessage
+	req.secureErrorLogMessage = c.SecureErrorLogMessage
+	req.Header.secureErrorLogMessage = c.SecureErrorLogMessage
+
 	if c.IsTLS != bytes.Equal(req.uri.Scheme(), strHTTPS) {
 		return false, ErrHostClientRedirectToDifferentScheme
 	}
@@ -1743,39 +1764,73 @@ func (c *HostClient) releaseConn(cc *clientConn) {
 }
 
 func (c *HostClient) acquireWriter(conn net.Conn) *bufio.Writer {
-	v := c.writerPool.Get()
-	if v == nil {
-		n := c.WriteBufferSize
-		if n <= 0 {
-			n = defaultWriteBufferSize
+	var v interface{}
+	if c.clientWriterPool != nil {
+		v = c.clientWriterPool.Get()
+		if v == nil {
+			n := c.WriteBufferSize
+			if n <= 0 {
+				n = defaultWriteBufferSize
+			}
+			return bufio.NewWriterSize(conn, n)
+		}
+	} else {
+		v = c.writerPool.Get()
+		if v == nil {
+			n := c.WriteBufferSize
+			if n <= 0 {
+				n = defaultWriteBufferSize
+			}
+			return bufio.NewWriterSize(conn, n)
 		}
-		return bufio.NewWriterSize(conn, n)
 	}
+
 	bw := v.(*bufio.Writer)
 	bw.Reset(conn)
 	return bw
 }
 
 func (c *HostClient) releaseWriter(bw *bufio.Writer) {
-	c.writerPool.Put(bw)
+	if c.clientWriterPool != nil {
+		c.clientWriterPool.Put(bw)
+	} else {
+		c.writerPool.Put(bw)
+	}
 }
 
 func (c *HostClient) acquireReader(conn net.Conn) *bufio.Reader {
-	v := c.readerPool.Get()
-	if v == nil {
-		n := c.ReadBufferSize
-		if n <= 0 {
-			n = defaultReadBufferSize
+	var v interface{}
+	if c.clientReaderPool != nil {
+		v = c.clientReaderPool.Get()
+		if v == nil {
+			n := c.ReadBufferSize
+			if n <= 0 {
+				n = defaultReadBufferSize
+			}
+			return bufio.NewReaderSize(conn, n)
+		}
+	} else {
+		v = c.readerPool.Get()
+		if v == nil {
+			n := c.ReadBufferSize
+			if n <= 0 {
+				n = defaultReadBufferSize
+			}
+			return bufio.NewReaderSize(conn, n)
 		}
-		return bufio.NewReaderSize(conn, n)
 	}
+
 	br := v.(*bufio.Reader)
 	br.Reset(conn)
 	return br
 }
 
 func (c *HostClient) releaseReader(br *bufio.Reader) {
-	c.readerPool.Put(br)
+	if c.clientReaderPool != nil {
+		c.clientReaderPool.Put(br)
+	} else {
+		c.readerPool.Put(br)
+	}
 }
 
 func newClientTLSConfig(c *tls.Config, addr string) *tls.Config {
diff --git a/header.go b/header.go
index d2caba2..3a552d9 100644
--- a/header.go
+++ b/header.go
@@ -35,6 +35,7 @@ type ResponseHeader struct {
 	statusCode         int
 	contentLength      int
 	contentLengthBytes []byte
+	secureErrorLogMessage     bool
 
 	contentType []byte
 	server      []byte
@@ -65,6 +66,7 @@ type RequestHeader struct {
 
 	contentLength      int
 	contentLengthBytes []byte
+	secureErrorLogMessage     bool
 
 	method      []byte
 	requestURI  []byte
@@ -1354,6 +1356,11 @@ func (h *ResponseHeader) tryRead(r *bufio.Reader, n int) error {
 
 		// This is for go 1.6 bug. See https://github.com/golang/go/issues/14121 .
 		if err == bufio.ErrBufferFull {
+			if h.secureErrorLogMessage {
+				return &ErrSmallBuffer{
+					error: fmt.Errorf("error when reading response headers"),
+				}
+			}
 			return &ErrSmallBuffer{
 				error: fmt.Errorf("error when reading response headers: %s", errSmallBuffer),
 			}
@@ -1364,15 +1371,15 @@ func (h *ResponseHeader) tryRead(r *bufio.Reader, n int) error {
 	b = mustPeekBuffered(r)
 	headersLen, errParse := h.parse(b)
 	if errParse != nil {
-		return headerError("response", err, errParse, b)
+		return headerError("response", err, errParse, b, h.secureErrorLogMessage)
 	}
 	mustDiscard(r, headersLen)
 	return nil
 }
 
-func headerError(typ string, err, errParse error, b []byte) error {
+func headerError(typ string, err, errParse error, b []byte, secureErrorLogMessage bool) error {
 	if errParse != errNeedMore {
-		return headerErrorMsg(typ, errParse, b)
+		return headerErrorMsg(typ, errParse, b, secureErrorLogMessage)
 	}
 	if err == nil {
 		return errNeedMore
@@ -1385,14 +1392,17 @@ func headerError(typ string, err, errParse error, b []byte) error {
 	}
 
 	if err != bufio.ErrBufferFull {
-		return headerErrorMsg(typ, err, b)
+		return headerErrorMsg(typ, err, b, secureErrorLogMessage)
 	}
 	return &ErrSmallBuffer{
-		error: headerErrorMsg(typ, errSmallBuffer, b),
+		error: headerErrorMsg(typ, errSmallBuffer, b, secureErrorLogMessage),
 	}
 }
 
-func headerErrorMsg(typ string, err error, b []byte) error {
+func headerErrorMsg(typ string, err error, b []byte, secureErrorLogMessage bool) error {
+	if secureErrorLogMessage {
+		return fmt.Errorf("error when reading %s headers: %s. Buffer size=%d", typ, err, len(b))
+	}
 	return fmt.Errorf("error when reading %s headers: %s. Buffer size=%d, contents: %s", typ, err, len(b), bufferSnippet(b))
 }
 
@@ -1444,7 +1454,7 @@ func (h *RequestHeader) tryRead(r *bufio.Reader, n int) error {
 	b = mustPeekBuffered(r)
 	headersLen, errParse := h.parse(b)
 	if errParse != nil {
-		return headerError("request", err, errParse, b)
+		return headerError("request", err, errParse, b, h.secureErrorLogMessage)
 	}
 	mustDiscard(r, headersLen)
 	return nil
@@ -1724,6 +1734,9 @@ func (h *ResponseHeader) parseFirstLine(buf []byte) (int, error) {
 	// parse protocol
 	n := bytes.IndexByte(b, ' ')
 	if n < 0 {
+		if h.secureErrorLogMessage {
+			return 0, fmt.Errorf("cannot find whitespace in the first line of response")
+		}
 		return 0, fmt.Errorf("cannot find whitespace in the first line of response %q", buf)
 	}
 	h.noHTTP11 = !bytes.Equal(b[:n], strHTTP11)
@@ -1732,9 +1745,15 @@ func (h *ResponseHeader) parseFirstLine(buf []byte) (int, error) {
 	// parse status code
 	h.statusCode, n, err = parseUintBuf(b)
 	if err != nil {
+		if h.secureErrorLogMessage {
+			return 0, fmt.Errorf("cannot parse response status code: %s", err)
+		}
 		return 0, fmt.Errorf("cannot parse response status code: %s. Response %q", err, buf)
 	}
 	if len(b) > n && b[n] != ' ' {
+		if h.secureErrorLogMessage {
+			return 0, fmt.Errorf("unexpected char at the end of status code")
+		}
 		return 0, fmt.Errorf("unexpected char at the end of status code. Response %q", buf)
 	}
 
@@ -1754,6 +1773,9 @@ func (h *RequestHeader) parseFirstLine(buf []byte) (int, error) {
 	// parse method
 	n := bytes.IndexByte(b, ' ')
 	if n <= 0 {
+		if h.secureErrorLogMessage {
+			return 0, fmt.Errorf("cannot find http request method")
+		}
 		return 0, fmt.Errorf("cannot find http request method in %q", buf)
 	}
 	h.method = append(h.method[:0], b[:n]...)
@@ -1767,6 +1789,9 @@ func (h *RequestHeader) parseFirstLine(buf []byte) (int, error) {
 		n = len(b)
 		protoStr = strHTTP10
 	} else if n == 0 {
+		if h.secureErrorLogMessage {
+			return 0, fmt.Errorf("requestURI cannot be empty")
+		}
 		return 0, fmt.Errorf("requestURI cannot be empty in %q", buf)
 	} else if !bytes.Equal(b[n+1:], strHTTP11) {
 		h.noHTTP11 = true
diff --git a/http.go b/http.go
index 7be092b..a8efbe8 100644
--- a/http.go
+++ b/http.go
@@ -41,6 +41,7 @@ type Request struct {
 
 	multipartForm         *multipart.Form
 	multipartFormBoundary string
+	secureErrorLogMessage        bool
 
 	// Group bool members in order to reduce Request object size.
 	parsedURI      bool
@@ -88,6 +89,7 @@ type Response struct {
 	SkipBody bool
 
 	keepBodyBuffer bool
+	secureErrorLogMessage bool
 
 	// Remote TCPAddr from concurrently net.Conn
 	raddr net.Addr
@@ -1368,6 +1370,9 @@ func (req *Request) Write(w *bufio.Writer) error {
 	if hasBody {
 		_, err = w.Write(body)
 	} else if len(body) > 0 {
+		if req.secureErrorLogMessage {
+			return fmt.Errorf("non-zero body for non-POST request")
+		}
 		return fmt.Errorf("non-zero body for non-POST request. body=%q", body)
 	}
 	return err
diff --git a/server.go b/server.go
index 600b065..67f47d8 100644
--- a/server.go
+++ b/server.go
@@ -312,6 +312,14 @@ type Server struct {
 	// are suppressed in order to limit output log traffic.
 	LogAllErrors bool
 
+	// Will not log potentially sensitive content in error logs
+	//
+	// This option is useful for servers that handle sensitive data
+	// in the request/response.
+	//
+	// Server logs all full errors by default.
+	SecureErrorLogMessage bool
+
 	// Header names are passed as-is without normalization
 	// if this option is set.
 	//
@@ -2055,6 +2063,12 @@ func (s *Server) serveConn(c net.Conn) (err error) {
 		ctx.Response.Header.noDefaultContentType = s.NoDefaultContentType
 		ctx.Response.Header.noDefaultDate = s.NoDefaultDate
 
+		// Secure header error logs configuration
+		ctx.Request.Header.secureErrorLogMessage = s.SecureErrorLogMessage
+		ctx.Response.Header.secureErrorLogMessage = s.SecureErrorLogMessage
+		ctx.Request.secureErrorLogMessage = s.SecureErrorLogMessage
+		ctx.Response.secureErrorLogMessage = s.SecureErrorLogMessage
+
 		if err == nil {
 			if s.ReadTimeout > 0 {
 				if err := c.SetReadDeadline(time.Now().Add(s.ReadTimeout)); err != nil {


Test patch:
diff --git a/header_test.go b/header_test.go
index f82d221..e18c5cb 100644
--- a/header_test.go
+++ b/header_test.go
@@ -2399,6 +2399,31 @@ func TestResponseHeaderReadError(t *testing.T) {
 	testResponseHeaderReadError(t, h, "HTTP/1.1 200 OK\r\nContent-Length: 123\r\nContent-Type: text/html\r\n")
 }
 
+func TestResponseHeaderReadErrorSecureLog(t *testing.T) {
+	h := &ResponseHeader{
+		secureErrorLogMessage: true,
+	}
+
+	// incorrect first line
+	testResponseHeaderReadSecuredError(t, h, "fo")
+	testResponseHeaderReadSecuredError(t, h, "foobarbaz")
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1")
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1 ")
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1 s")
+
+	// non-numeric status code
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1 foobar OK\r\nContent-Length: 123\r\nContent-Type: text/html\r\n\r\n")
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1 123foobar OK\r\nContent-Length: 123\r\nContent-Type: text/html\r\n\r\n")
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1 foobar344 OK\r\nContent-Length: 123\r\nContent-Type: text/html\r\n\r\n")
+
+
+	// no headers
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1 200 OK\r\n")
+
+	// no trailing crlf
+	testResponseHeaderReadSecuredError(t, h, "HTTP/1.1 200 OK\r\nContent-Length: 123\r\nContent-Type: text/html\r\n")
+}
+
 func TestRequestHeaderReadError(t *testing.T) {
 	t.Parallel()
 
@@ -2417,6 +2442,25 @@ func TestRequestHeaderReadError(t *testing.T) {
 	testRequestHeaderReadError(t, h, "POST /a HTTP/1.1\r\nHost: bb\r\nContent-Type: aa\r\nContent-Length: dff\r\n\r\nqwerty")
 }
 
+func TestRequestHeaderReadSecuredError(t *testing.T) {
+	t.Parallel()
+
+	h := &RequestHeader{
+		secureErrorLogMessage: true,
+	}
+
+	// incorrect first line
+	testRequestHeaderReadSecuredError(t, h, "fo")
+	testRequestHeaderReadSecuredError(t, h, "GET ")
+	testRequestHeaderReadSecuredError(t, h, "GET / HTTP/1.1\r")
+
+	// missing RequestURI
+	testRequestHeaderReadSecuredError(t, h, "GET  HTTP/1.1\r\nHost: google.com\r\n\r\n")
+
+	// post with invalid content-length
+	testRequestHeaderReadSecuredError(t, h, "POST /a HTTP/1.1\r\nHost: bb\r\nContent-Type: aa\r\nContent-Length: dff\r\n\r\nqwerty")
+}
+
 func testResponseHeaderReadError(t *testing.T, h *ResponseHeader, headers string) {
 	r := bytes.NewBufferString(headers)
 	br := bufio.NewReader(r)
@@ -2424,7 +2468,21 @@ func testResponseHeaderReadError(t *testing.T, h *ResponseHeader, headers string
 	if err == nil {
 		t.Fatalf("Expecting error when reading response header %q", headers)
 	}
+	// make sure response header works after error
+	testResponseHeaderReadSuccess(t, h, "HTTP/1.1 200 OK\r\nContent-Type: foo/bar\r\nContent-Length: 12345\r\n\r\nsss",
+		200, 12345, "foo/bar", "sss")
+}
 
+func testResponseHeaderReadSecuredError(t *testing.T, h *ResponseHeader, headers string) {
+	r := bytes.NewBufferString(headers)
+	br := bufio.NewReader(r)
+	err := h.Read(br)
+	if err == nil {
+		t.Fatalf("Expecting error when reading response header %q", headers)
+	}
+	if strings.Contains(err.Error(), headers) {
+		t.Fatalf("Not expecting header content in err %q", err)
+	}
 	// make sure response header works after error
 	testResponseHeaderReadSuccess(t, h, "HTTP/1.1 200 OK\r\nContent-Type: foo/bar\r\nContent-Length: 12345\r\n\r\nsss",
 		200, 12345, "foo/bar", "sss")
@@ -2443,6 +2501,21 @@ func testRequestHeaderReadError(t *testing.T, h *RequestHeader, headers string)
 		-2, "/foo/bar", "aaaa", "", "", "xxx")
 }
 
+func testRequestHeaderReadSecuredError(t *testing.T, h *RequestHeader, headers string) {
+	r := bytes.NewBufferString(headers)
+	br := bufio.NewReader(r)
+	err := h.Read(br)
+	if err == nil {
+		t.Fatalf("Expecting error when reading request header %q", headers)
+	}
+	if strings.Contains(err.Error(), headers) {
+		t.Fatalf("Not expecting header content in err %q", err)
+	}
+	// make sure request header works after error
+	testRequestHeaderReadSuccess(t, h, "GET /foo/bar HTTP/1.1\r\nHost: aaaa\r\n\r\nxxx",
+		-2, "/foo/bar", "aaaa", "", "", "xxx")
+}
+
 func testResponseHeaderReadSuccess(t *testing.T, h *ResponseHeader, headers string, expectedStatusCode, expectedContentLength int,
 	expectedContentType, expectedTrailer string) {
 	r := bytes.NewBufferString(headers)