Repository: labstack/echo
Pull request #2176 (2022-05-12 14:04:06)

fix: duplicated findStaticChild process at findChildWithLabel
duplicated findStaticChild process at findChildWithLabel in router.go

I think less duplicate processing more readable except  performance decrement.

codecov[bot]: # [Codecov](https://codecov.io/gh/labstack/echo/pull/2176?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) Report
> Merging [#2176](https://codecov.io/gh/labstack/echo/pull/2176?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) (609021d) into [master](https://codecov.io/gh/labstack/echo/commit/6df1c355c26f7fdfde0ce85265dc7d386638f659?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) (6df1c35) will **not change** coverage.
> The diff coverage is `100.00%`.

```diff
@@           Coverage Diff           @@
##           master    #2176   +/-   ##
=======================================
  Coverage   92.20%   92.20%           
=======================================
  Files          37       37           
  Lines        3090     3090           
=======================================
  Hits         2849     2849           
  Misses        151      151           
  Partials       90       90           
```


| [Impacted Files](https://codecov.io/gh/labstack/echo/pull/2176?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack) | Coverage Δ | |
|---|---|---|
| [router.go](https://codecov.io/gh/labstack/echo/pull/2176/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack#diff-cm91dGVyLmdv) | `96.50% <100.00%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/labstack/echo/pull/2176?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/labstack/echo/pull/2176?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack). Last update [6df1c35...609021d](https://codecov.io/gh/labstack/echo/pull/2176?src=pr&el=lastupdated&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=labstack).


Patch:
diff --git a/middleware/basic_auth.go b/middleware/basic_auth.go
index 8cf1ed9..52ef104 100644
--- a/middleware/basic_auth.go
+++ b/middleware/basic_auth.go
@@ -4,6 +4,7 @@ import (
 	"encoding/base64"
 	"strconv"
 	"strings"
+	"net/http"
 
 	"github.com/labstack/echo/v4"
 )
@@ -74,10 +75,13 @@ func BasicAuthWithConfig(config BasicAuthConfig) echo.MiddlewareFunc {
 			l := len(basic)
 
 			if len(auth) > l+1 && strings.EqualFold(auth[:l], basic) {
+				// Invalid base64 shouldn't be treated as error
+				// instead should be treated as invalid client input
 				b, err := base64.StdEncoding.DecodeString(auth[l+1:])
 				if err != nil {
-					return err
+					return echo.NewHTTPError(http.StatusBadRequest).SetInternal(err)
 				}
+
 				cred := string(b)
 				for i := 0; i < len(cred); i++ {
 					if cred[i] == ':' {
diff --git a/router.go b/router.go
index a1de2d6..b5e50d9 100644
--- a/router.go
+++ b/router.go
@@ -333,10 +333,8 @@ func (n *node) findStaticChild(l byte) *node {
 }
 
 func (n *node) findChildWithLabel(l byte) *node {
-	for _, c := range n.staticChildren {
-		if c.label == l {
-			return c
-		}
+	if c := n.findStaticChild(l); c != nil {
+		return c
 	}
 	if l == paramLabel {
 		return n.paramChild


Test patch:
diff --git a/middleware/basic_auth_test.go b/middleware/basic_auth_test.go
index 76039db..4c355aa 100644
--- a/middleware/basic_auth_test.go
+++ b/middleware/basic_auth_test.go
@@ -58,6 +58,12 @@ func TestBasicAuth(t *testing.T) {
 	assert.Equal(http.StatusUnauthorized, he.Code)
 	assert.Equal(basic+` realm="someRealm"`, res.Header().Get(echo.HeaderWWWAuthenticate))
 
+	// Invalid base64 string
+	auth = basic + " invalidString"
+	req.Header.Set(echo.HeaderAuthorization, auth)
+	he = h(c).(*echo.HTTPError)
+	assert.Equal(http.StatusBadRequest, he.Code)
+
 	// Missing Authorization header
 	req.Header.Del(echo.HeaderAuthorization)
 	he = h(c).(*echo.HTTPError)
diff --git a/middleware/timeout_test.go b/middleware/timeout_test.go
index 7fb802a..56eb7bc 100644
--- a/middleware/timeout_test.go
+++ b/middleware/timeout_test.go
@@ -2,6 +2,7 @@ package middleware
 
 import (
 	"bytes"
+	"context"
 	"errors"
 	"fmt"
 	"io/ioutil"
@@ -12,6 +13,7 @@ import (
 	"net/url"
 	"reflect"
 	"strings"
+	"sync"
 	"testing"
 	"time"
 
@@ -327,12 +329,13 @@ func TestTimeoutCanHandleContextDeadlineOnNextHandler(t *testing.T) {
 func TestTimeoutWithFullEchoStack(t *testing.T) {
 	// test timeout with full http server stack running, do see what http.Server.ErrorLog contains
 	var testCases = []struct {
-		name                 string
-		whenPath             string
-		expectStatusCode     int
-		expectResponse       string
-		expectLogContains    []string
-		expectLogNotContains []string
+		name                    string
+		whenPath                string
+		whenForceHandlerTimeout bool
+		expectStatusCode        int
+		expectResponse          string
+		expectLogContains       []string
+		expectLogNotContains    []string
 	}{
 		{
 			name:                 "404 - write response in global error handler",
@@ -351,57 +354,60 @@ func TestTimeoutWithFullEchoStack(t *testing.T) {
 			expectLogContains:    []string{`"status":418,"error":"",`},
 		},
 		{
-			name:             "503 - handler timeouts, write response in timeout middleware",
-			whenPath:         "/?delay=50ms",
-			expectResponse:   "<html><head><title>Timeout</title></head><body><h1>Timeout</h1></body></html>",
-			expectStatusCode: http.StatusServiceUnavailable,
+			name:                    "503 - handler timeouts, write response in timeout middleware",
+			whenForceHandlerTimeout: true,
+			whenPath:                "/",
+			expectResponse:          "<html><head><title>Timeout</title></head><body><h1>Timeout</h1></body></html>",
+			expectStatusCode:        http.StatusServiceUnavailable,
 			expectLogNotContains: []string{
 				"echo:http: superfluous response.WriteHeader call from",
-				"{", // means that logger was not called.
 			},
+			expectLogContains: []string{"http: Handler timeout"},
 		},
 	}
 
-	e := echo.New()
-
-	buf := new(bytes.Buffer)
-	e.Logger.SetOutput(buf)
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			e := echo.New()
 
-	// NOTE: timeout middleware is first as it changes Response.Writer and causes data race for logger middleware if it is not first
-	// FIXME: I have no idea how to fix this without adding mutexes.
-	e.Use(TimeoutWithConfig(TimeoutConfig{
-		Timeout: 15 * time.Millisecond,
-	}))
-	e.Use(Logger())
-	e.Use(Recover())
+			buf := new(coroutineSafeBuffer)
+			e.Logger.SetOutput(buf)
 
-	e.GET("/", func(c echo.Context) error {
-		var delay time.Duration
-		if err := echo.QueryParamsBinder(c).Duration("delay", &delay).BindError(); err != nil {
-			return err
-		}
-		if delay > 0 {
-			time.Sleep(delay)
-		}
-		return c.JSON(http.StatusTeapot, map[string]string{"message": "OK"})
-	})
+			// NOTE: timeout middleware is first as it changes Response.Writer and causes data race for logger middleware if it is not first
+			e.Use(TimeoutWithConfig(TimeoutConfig{
+				Timeout: 15 * time.Millisecond,
+			}))
+			e.Use(Logger())
+			e.Use(Recover())
 
-	server, addr, err := startServer(e)
-	if err != nil {
-		assert.NoError(t, err)
-		return
-	}
-	defer server.Close()
+			wg := sync.WaitGroup{}
+			if tc.whenForceHandlerTimeout {
+				wg.Add(1) // make `wg.Wait()` block until we release it with `wg.Done()`
+			}
+			e.GET("/", func(c echo.Context) error {
+				wg.Wait()
+				return c.JSON(http.StatusTeapot, map[string]string{"message": "OK"})
+			})
 
-	for _, tc := range testCases {
-		t.Run(tc.name, func(t *testing.T) {
-			buf.Reset() // this is design this can not be run in parallel
+			server, addr, err := startServer(e)
+			if err != nil {
+				assert.NoError(t, err)
+				return
+			}
+			defer server.Close()
 
 			res, err := http.Get(fmt.Sprintf("http://%v%v", addr, tc.whenPath))
 			if err != nil {
 				assert.NoError(t, err)
 				return
 			}
+			if tc.whenForceHandlerTimeout {
+				wg.Done()
+				// shutdown waits for server to shutdown. this way we wait logger mw to be executed
+				ctx, cancel := context.WithTimeout(context.Background(), 150*time.Millisecond)
+				defer cancel()
+				server.Shutdown(ctx)
+			}
 
 			assert.Equal(t, tc.expectStatusCode, res.StatusCode)
 			if body, err := ioutil.ReadAll(res.Body); err == nil {
@@ -412,15 +418,45 @@ func TestTimeoutWithFullEchoStack(t *testing.T) {
 
 			logged := buf.String()
 			for _, subStr := range tc.expectLogContains {
-				assert.True(t, strings.Contains(logged, subStr))
+				assert.True(t, strings.Contains(logged, subStr), "expected logs to contain: %v, logged: '%v'", subStr, logged)
 			}
 			for _, subStr := range tc.expectLogNotContains {
-				assert.False(t, strings.Contains(logged, subStr))
+				assert.False(t, strings.Contains(logged, subStr), "expected logs not to contain: %v, logged: '%v'", subStr, logged)
 			}
 		})
 	}
 }
 
+// as we are spawning multiple coroutines - one for http server, one for request, one by timeout middleware, one by testcase
+// we are accessing logger (writing/reading) from multiple coroutines and causing dataraces (most often reported on macos)
+// we could be writing to logger in logger middleware and at the same time our tests is getting logger buffer contents
+// in testcase coroutine.
+type coroutineSafeBuffer struct {
+	bytes.Buffer
+	lock sync.RWMutex
+}
+
+func (b *coroutineSafeBuffer) Write(p []byte) (n int, err error) {
+	b.lock.Lock()
+	defer b.lock.Unlock()
+
+	return b.Buffer.Write(p)
+}
+
+func (b *coroutineSafeBuffer) Bytes() []byte {
+	b.lock.RLock()
+	defer b.lock.RUnlock()
+
+	return b.Buffer.Bytes()
+}
+
+func (b *coroutineSafeBuffer) String() string {
+	b.lock.RLock()
+	defer b.lock.RUnlock()
+
+	return b.Buffer.String()
+}
+
 func startServer(e *echo.Echo) (*http.Server, string, error) {
 	l, err := net.Listen("tcp", ":0")
 	if err != nil {