perf(recovery): optimize the log output of CustomRecoveryWithWriter

[1911860538]

• Moved the generation of stack and secureRequestDump into conditional blocks so they only execute when needed.
• Improved the performance of masking the Authorization header by avoiding unnecessary conversions between string and []byte.
• Updated the logic for handling and masking the Authorization header in secureRequestDump, accounting for the fact that httputil.DumpRequest normalizes all header keys (e.g., "authorization" or "AUTHORIZATION", and so on) to "Authorization".

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 98.92%. Comparing base (3dc1cd6) to head (63316b8).
Report is 129 commits behind head on master.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #4258      +/-   ##
==========================================
- Coverage   99.21%   98.92%   -0.30%     
==========================================
  Files          42       44       +2     
  Lines        3182     3434     +252     
==========================================
+ Hits         3157     3397     +240     
- Misses         17       26       +9     
- Partials        8       11       +3     

Flag	Coverage Δ
	?
--ldflags="-checklinkname=0" -tags sonic	98.85% <100.00%> (?)
-tags go_json	98.85% <100.00%> (?)
-tags nomsgpack	98.90% <100.00%> (?)
go-1.18	?
go-1.19	?
go-1.20	?
go-1.21	?
go-1.23	98.92% <100.00%> (?)
go-1.24	98.92% <100.00%> (?)
macos-latest	98.92% <100.00%> (-0.30%)	⬇️
ubuntu-latest	98.92% <100.00%> (-0.30%)	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[1911860538]

secureRequestDump test code

package recovery

import (
	"bytes"
	"net/http"
	"net/http/httputil"
	"strings"
	"testing"
)

func maskHeaders(r *http.Request) string {
	httpRequest, _ := httputil.DumpRequest(r, false)
	headers := strings.Split(string(httpRequest), "\r\n")
	maskAuthorization(headers)
	return strings.Join(headers, "\r\n")
}

func maskAuthorization(headers []string) {
	for idx, header := range headers {
		key, _, _ := strings.Cut(header, ":")
		if strings.EqualFold(key, "Authorization") {
			headers[idx] = key + ": *"
		}
	}
}

var (
	crlfBytes       = []byte("\r\n")
	authKeyBytes    = []byte("Authorization")
	secureAuthBytes = []byte("Authorization: *")
	colonBytes      = []byte(":")
)

func secureRequestDump(r *http.Request) []byte {
	httpRequest, _ := httputil.DumpRequest(r, false) // []byte
	lines := bytes.Split(httpRequest, crlfBytes)

	for i, line := range lines {
		key, _, found := bytes.Cut(line, colonBytes)
		if found && bytes.Equal(key, authKeyBytes) {
			lines[i] = secureAuthBytes
		}
	}

	return bytes.Join(lines, crlfBytes)
}

func makeTestRequest() *http.Request {
	req, _ := http.NewRequest("GET", "http://example.com/foo", nil)
	req.Header.Set("Authorization", "Bearer secret-token")
	req.Header.Set("User-Agent", "GoTest")
	return req
}

var (
	stringRes string
	bytesRes  []byte
)

func BenchmarkMaskHeaders(b *testing.B) {
	b.Run("original", func(b *testing.B) {
		req := makeTestRequest()
		var bStringRes string
		b.ResetTimer()
		b.ReportAllocs()
		for i := 0; i < b.N; i++ {
			bStringRes = maskHeaders(req)
		}
		stringRes = bStringRes
	})

	b.Run("optimized", func(b *testing.B) {
		req := makeTestRequest()
		var bBytesRes []byte
		b.ResetTimer()
		b.ReportAllocs()
		for i := 0; i < b.N; i++ {
			bBytesRes = secureRequestDump(req)
		}
		bytesRes = bBytesRes
	})
}

benchmark secureRequestDump output

goos: darwin
goarch: amd64
pkg: testgolang/gin/recovery
cpu: Intel(R) Core(TM) i7-8569U CPU @ 2.80GHz
BenchmarkMaskHeaders
BenchmarkMaskHeaders/original
BenchmarkMaskHeaders/original-8         	  787179	      1287 ns/op	     576 B/op	      10 allocs/op
BenchmarkMaskHeaders/optimized
BenchmarkMaskHeaders/optimized-8        	  877323	      1152 ns/op	     512 B/op	       8 allocs/op
PASS

Process finished with the exit code 0

hey load test

recovery test code

package main

import (
	"log"
	"net/http"

	"github.com/gin-gonic/gin"
)

func main() {
	gin.SetMode(gin.ReleaseMode)

	r := gin.New()

	r.Use(gin.CustomRecoveryWithWriter(gin.DefaultErrorWriter, func(c *gin.Context, err any) {
		c.JSON(http.StatusInternalServerError, gin.H{
			"message": "internal error",
		})
	}))

	r.GET("/panic", func(c *gin.Context) {
		panic("trigger panic")
	})

	err := r.Run(":8080")
	if err != nil {
		log.Fatal(err)
	}
}

hey command

hey -n 100000 -c 100 http://localhost:8080/panic

benchmark results before optimization using hey

 hey -n 100000 -c 100 http://localhost:8080/panic

Summary:
  Total:        25.3032 secs
  Slowest:      0.3537 secs
  Fastest:      0.0005 secs
  Average:      0.0245 secs
  Requests/sec: 3952.0755
  
  Total data:   2800000 bytes
  Size/request: 28 bytes

Response time histogram:
  0.001 [1]     |
  0.036 [73128] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.071 [18003] |■■■■■■■■■■
  0.106 [6049]  |■■■
  0.142 [1955]  |■
  0.177 [618]   |
  0.212 [169]   |
  0.248 [51]    |
  0.283 [18]    |
  0.318 [5]     |
  0.354 [3]     |


Latency distribution:
  10% in 0.0013 secs
  25% in 0.0024 secs
  50% in 0.0061 secs
  75% in 0.0374 secs
  90% in 0.0679 secs
  95% in 0.0896 secs
  99% in 0.1376 secs

Details (average, fastest, slowest):
  DNS+dialup:   0.0000 secs, 0.0005 secs, 0.3537 secs
  DNS-lookup:   0.0000 secs, 0.0000 secs, 0.0075 secs
  req write:    0.0000 secs, 0.0000 secs, 0.0037 secs
  resp wait:    0.0245 secs, 0.0005 secs, 0.3537 secs
  resp read:    0.0000 secs, 0.0000 secs, 0.0030 secs

Status code distribution:
  [500] 100000 responses

benchmark results after optimization using hey

hey -n 100000 -c 100 http://localhost:8080/panic

Summary:
Total:        24.2673 secs
Slowest:      0.3359 secs
Fastest:      0.0005 secs
Average:      0.0237 secs
Requests/sec: 4120.7731

Total data:   2800000 bytes
Size/request: 28 bytes

Response time histogram:
0.001 [1]     |
0.034 [72225] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
0.068 [18400] |■■■■■■■■■■
0.101 [6245]  |■■■
0.135 [2095]  |■
0.168 [708]   |
0.202 [222]   |
0.235 [66]    |
0.269 [28]    |
0.302 [8]     |
0.336 [2]     |


Latency distribution:
10% in 0.0013 secs
25% in 0.0024 secs
50% in 0.0057 secs
75% in 0.0362 secs
90% in 0.0660 secs
95% in 0.0872 secs
99% in 0.1356 secs

Details (average, fastest, slowest):
DNS+dialup:   0.0000 secs, 0.0005 secs, 0.3359 secs
DNS-lookup:   0.0000 secs, 0.0000 secs, 0.0071 secs
req write:    0.0000 secs, 0.0000 secs, 0.0036 secs
resp wait:    0.0236 secs, 0.0005 secs, 0.3359 secs
resp read:    0.0000 secs, 0.0000 secs, 0.0030 secs

Status code distribution:
[500] 100000 responses