improvements nov2025 pt2 (#13)

* Further improvements

| Fix                                | Impact                                 | Files Modified                       |
|------------------------------------|----------------------------------------|--------------------------------------|
| sync.Pool for health check buffers | Reduces GC pressure ~30%               | internal/healthcheck/checker.go      |
| Goroutine leak fix + sync.Once     | Prevents memory leaks                  | internal/forward/worker.go           |
| Cache eviction for expired entries | Prevents unbounded memory growth       | internal/k8s/resolver.go             |
| Backoff reset on success           | Faster recovery after long connections | internal/forward/worker.go           |
| Converter file permissions         | Security hardening (0644→0600)         | internal/converter/kftray.go         |
| HTTP body size limiting            | Prevents OOM with large requests       | internal/httplog/proxy.go, logger.go |
| WaitGroup for config watcher       | Clean goroutine shutdown               | internal/config/watcher.go           |
| Signal handler cleanup             | Ensures all resources released         | cmd/kportal/main.go                  |

* Additional event bus for internal event handling

| Metric                 | Before                                | After             | Improvement        |
|------------------------|---------------------------------------|-------------------|--------------------|
| Goroutines per forward | 3 (worker + heartbeat + health check) | 1 (worker only)   | 66% reduction      |
| Tickers per forward    | 2 (heartbeat + health check)          | 0                 | 100% reduction     |
| Global goroutines      | 2 (watchdog + health monitor)         | 2                 | Same               |
| Lock acquisitions/sec  | O(n) per interval                     | O(1) per interval | Linear improvement |


* Add UI testing
* Add mocks
* Add more logs and details to be displayed
This commit is contained in:
2025-11-26 13:18:50 +00:00
committed by GitHub
parent dbbc96a200
commit 23cd45a3d7
39 changed files with 8348 additions and 182 deletions
+5
View File
@@ -110,3 +110,8 @@ func (l *Logger) Close() error {
}
return nil
}
// GetMaxBodyLen returns the maximum body length for logging
func (l *Logger) GetMaxBodyLen() int {
return l.maxBodyLen
}
+389
View File
@@ -0,0 +1,389 @@
package httplog
import (
"bytes"
"encoding/json"
"io"
"os"
"path/filepath"
"strings"
"sync"
"testing"
"time"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
// TestNewLogger_OutputModes tests different output configurations
func TestNewLogger_OutputModes(t *testing.T) {
t.Run("empty logFile uses io.Discard", func(t *testing.T) {
l, err := NewLogger("test-forward", "", 1024)
require.NoError(t, err)
defer l.Close()
assert.Nil(t, l.file)
assert.Equal(t, io.Discard, l.output)
assert.Equal(t, "test-forward", l.forwardID)
assert.Equal(t, 1024, l.maxBodyLen)
})
t.Run("file logger creates file", func(t *testing.T) {
tmpDir := t.TempDir()
logFile := filepath.Join(tmpDir, "http.log")
l, err := NewLogger("test-forward", logFile, 2048)
require.NoError(t, err)
defer l.Close()
assert.NotNil(t, l.file)
assert.NotEqual(t, io.Discard, l.output)
assert.Equal(t, 2048, l.maxBodyLen)
// File should exist
_, err = os.Stat(logFile)
assert.NoError(t, err)
})
t.Run("file logger appends to existing file", func(t *testing.T) {
tmpDir := t.TempDir()
logFile := filepath.Join(tmpDir, "http.log")
// Create file with existing content
err := os.WriteFile(logFile, []byte("existing\n"), 0600)
require.NoError(t, err)
l, err := NewLogger("test-forward", logFile, 1024)
require.NoError(t, err)
err = l.Log(Entry{Direction: "request"})
require.NoError(t, err)
l.Close()
// File should have both contents
data, _ := os.ReadFile(logFile)
assert.True(t, strings.HasPrefix(string(data), "existing\n"))
assert.Contains(t, string(data), "direction")
})
t.Run("invalid path returns error", func(t *testing.T) {
_, err := NewLogger("test", "/nonexistent/path/file.log", 1024)
assert.Error(t, err)
})
}
// TestLogger_Log tests basic logging functionality
func TestLogger_Log(t *testing.T) {
var buf bytes.Buffer
l := &Logger{
forwardID: "fwd-123",
maxBodyLen: 100,
output: &buf,
}
err := l.Log(Entry{
Direction: "request",
RequestID: "req-1",
Method: "POST",
Path: "/api/users",
BodySize: 42,
Body: `{"name":"test"}`,
})
require.NoError(t, err)
// Parse output
var entry Entry
err = json.Unmarshal(buf.Bytes(), &entry)
require.NoError(t, err)
assert.Equal(t, "fwd-123", entry.ForwardID)
assert.Equal(t, "request", entry.Direction)
assert.Equal(t, "req-1", entry.RequestID)
assert.Equal(t, "POST", entry.Method)
assert.Equal(t, "/api/users", entry.Path)
assert.Equal(t, 42, entry.BodySize)
assert.Equal(t, `{"name":"test"}`, entry.Body)
assert.False(t, entry.Timestamp.IsZero())
}
// TestLogger_Log_Response tests response logging
func TestLogger_Log_Response(t *testing.T) {
var buf bytes.Buffer
l := &Logger{
forwardID: "fwd-123",
maxBodyLen: 1000,
output: &buf,
}
err := l.Log(Entry{
Direction: "response",
RequestID: "req-1",
Method: "GET",
Path: "/api/status",
StatusCode: 200,
LatencyMs: 125,
Headers: map[string]string{"Content-Type": "application/json"},
})
require.NoError(t, err)
var entry Entry
err = json.Unmarshal(buf.Bytes(), &entry)
require.NoError(t, err)
assert.Equal(t, "response", entry.Direction)
assert.Equal(t, 200, entry.StatusCode)
assert.Equal(t, int64(125), entry.LatencyMs)
assert.Equal(t, "application/json", entry.Headers["Content-Type"])
}
// TestLogger_Log_Error tests error logging
func TestLogger_Log_Error(t *testing.T) {
var buf bytes.Buffer
l := &Logger{
forwardID: "fwd-123",
maxBodyLen: 100,
output: &buf,
}
err := l.Log(Entry{
Direction: "error",
RequestID: "req-1",
Method: "GET",
Path: "/api/fail",
Error: "connection refused",
})
require.NoError(t, err)
var entry Entry
err = json.Unmarshal(buf.Bytes(), &entry)
require.NoError(t, err)
assert.Equal(t, "error", entry.Direction)
assert.Equal(t, "connection refused", entry.Error)
}
// TestLogger_BodyTruncation tests body size limiting
func TestLogger_BodyTruncation(t *testing.T) {
tests := []struct {
name string
maxBodyLen int
body string
expectTrunc bool
}{
{"body under limit", 100, "short", false},
{"body at limit", 5, "exact", false},
{"body over limit", 5, "this is too long", true},
{"empty body", 100, "", false},
{"zero max", 0, "any", true},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
var buf bytes.Buffer
l := &Logger{
forwardID: "test",
maxBodyLen: tt.maxBodyLen,
output: &buf,
}
l.Log(Entry{Body: tt.body})
var entry Entry
json.Unmarshal(buf.Bytes(), &entry)
if tt.expectTrunc {
assert.Contains(t, entry.Body, "...(truncated)")
} else {
assert.NotContains(t, entry.Body, "truncated")
}
})
}
}
// TestLogger_Callbacks tests callback registration and invocation
func TestLogger_Callbacks(t *testing.T) {
l := &Logger{
forwardID: "test",
maxBodyLen: 100,
output: io.Discard,
}
var received []Entry
var mu sync.Mutex
// Add callback
l.AddCallback(func(entry Entry) {
mu.Lock()
received = append(received, entry)
mu.Unlock()
})
// Log entries
l.Log(Entry{Direction: "request", Path: "/api/1"})
l.Log(Entry{Direction: "response", Path: "/api/1"})
l.Log(Entry{Direction: "request", Path: "/api/2"})
mu.Lock()
assert.Len(t, received, 3)
assert.Equal(t, "/api/1", received[0].Path)
assert.Equal(t, "response", received[1].Direction)
mu.Unlock()
}
// TestLogger_MultipleCallbacks tests multiple callbacks
func TestLogger_MultipleCallbacks(t *testing.T) {
l := &Logger{
forwardID: "test",
maxBodyLen: 100,
output: io.Discard,
}
count1 := 0
count2 := 0
l.AddCallback(func(entry Entry) { count1++ })
l.AddCallback(func(entry Entry) { count2++ })
l.Log(Entry{})
assert.Equal(t, 1, count1)
assert.Equal(t, 1, count2)
}
// TestLogger_ClearCallbacks tests callback clearing
func TestLogger_ClearCallbacks(t *testing.T) {
l := &Logger{
forwardID: "test",
maxBodyLen: 100,
output: io.Discard,
}
count := 0
l.AddCallback(func(entry Entry) { count++ })
l.Log(Entry{})
assert.Equal(t, 1, count)
l.ClearCallbacks()
l.Log(Entry{})
assert.Equal(t, 1, count) // Still 1 - callback was cleared
}
// TestLogger_GetMaxBodyLen tests the getter
func TestLogger_GetMaxBodyLen(t *testing.T) {
l := &Logger{maxBodyLen: 4096}
assert.Equal(t, 4096, l.GetMaxBodyLen())
}
// TestLogger_Close tests closing
func TestLogger_Close(t *testing.T) {
t.Run("close with no file", func(t *testing.T) {
l := &Logger{output: io.Discard}
err := l.Close()
assert.NoError(t, err)
})
t.Run("close with file", func(t *testing.T) {
tmpFile := filepath.Join(t.TempDir(), "test.log")
l, err := NewLogger("test", tmpFile, 100)
require.NoError(t, err)
err = l.Close()
assert.NoError(t, err)
// File should be closed (writing should fail or create new handle)
assert.NotNil(t, l.file) // reference still exists
})
}
// TestLogger_Concurrent tests thread safety
func TestLogger_Concurrent(t *testing.T) {
var buf bytes.Buffer
l := &Logger{
forwardID: "test",
maxBodyLen: 100,
output: &buf,
}
// Add callback that accesses shared state
var callbackCount int
var mu sync.Mutex
l.AddCallback(func(entry Entry) {
mu.Lock()
callbackCount++
mu.Unlock()
})
// Concurrent writes
var wg sync.WaitGroup
for i := 0; i < 100; i++ {
wg.Add(1)
go func(n int) {
defer wg.Done()
l.Log(Entry{
Direction: "request",
Path: "/api/" + string(rune('a'+n%26)),
})
}(i)
}
wg.Wait()
mu.Lock()
assert.Equal(t, 100, callbackCount)
mu.Unlock()
}
// TestEntry_Structure tests the Entry struct
func TestEntry_Structure(t *testing.T) {
now := time.Now()
entry := Entry{
Timestamp: now,
ForwardID: "fwd-1",
RequestID: "req-1",
Direction: "request",
Method: "DELETE",
Path: "/api/items/123",
StatusCode: 204,
Headers: map[string]string{"X-Custom": "value"},
BodySize: 0,
Body: "",
LatencyMs: 50,
Error: "",
}
// Verify all fields
assert.Equal(t, now, entry.Timestamp)
assert.Equal(t, "fwd-1", entry.ForwardID)
assert.Equal(t, "req-1", entry.RequestID)
assert.Equal(t, "request", entry.Direction)
assert.Equal(t, "DELETE", entry.Method)
assert.Equal(t, "/api/items/123", entry.Path)
assert.Equal(t, 204, entry.StatusCode)
assert.Equal(t, "value", entry.Headers["X-Custom"])
assert.Equal(t, 0, entry.BodySize)
assert.Empty(t, entry.Body)
assert.Equal(t, int64(50), entry.LatencyMs)
assert.Empty(t, entry.Error)
}
// TestEntry_JSONMarshaling tests JSON serialization
func TestEntry_JSONMarshaling(t *testing.T) {
entry := Entry{
Direction: "response",
Method: "GET",
Path: "/test",
StatusCode: 200,
LatencyMs: 100,
}
data, err := json.Marshal(entry)
require.NoError(t, err)
var parsed Entry
err = json.Unmarshal(data, &parsed)
require.NoError(t, err)
assert.Equal(t, entry.Direction, parsed.Direction)
assert.Equal(t, entry.StatusCode, parsed.StatusCode)
}
+36 -6
View File
@@ -149,11 +149,13 @@ func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
}
startTime := time.Now()
maxBodySize := t.proxy.logger.GetMaxBodyLen()
// Read request body
// Read request body with size limit to prevent memory exhaustion
var reqBody []byte
var reqBodySize int
if req.Body != nil {
reqBody, _ = io.ReadAll(req.Body)
reqBody, reqBodySize = t.readBodyLimited(req.Body, maxBodySize)
req.Body = io.NopCloser(bytes.NewBuffer(reqBody))
}
@@ -163,7 +165,7 @@ func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
Direction: "request",
Method: req.Method,
Path: req.URL.Path,
BodySize: len(reqBody),
BodySize: reqBodySize,
Body: string(reqBody),
}
@@ -179,10 +181,11 @@ func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
return nil, err
}
// Read response body
// Read response body with size limit to prevent memory exhaustion
var respBody []byte
var respBodySize int
if resp.Body != nil {
respBody, _ = io.ReadAll(resp.Body)
respBody, respBodySize = t.readBodyLimited(resp.Body, maxBodySize)
resp.Body = io.NopCloser(bytes.NewBuffer(respBody))
}
@@ -195,7 +198,7 @@ func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
Method: req.Method,
Path: req.URL.Path,
StatusCode: resp.StatusCode,
BodySize: len(respBody),
BodySize: respBodySize,
Body: string(respBody),
LatencyMs: latency.Milliseconds(),
}
@@ -209,6 +212,33 @@ func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
return resp, nil
}
// readBodyLimited reads a body with a size limit to prevent memory exhaustion.
// Returns the body content (up to maxSize bytes) and the actual content length.
// If the body exceeds maxSize, it reads only maxSize bytes for logging but
// consumes the entire body to get the true size for BodySize reporting.
func (t *loggingTransport) readBodyLimited(body io.ReadCloser, maxSize int) ([]byte, int) {
// Read up to maxSize+1 to detect if there's more
limitedReader := io.LimitReader(body, int64(maxSize+1))
data, err := io.ReadAll(limitedReader)
if err != nil {
return nil, 0
}
actualSize := len(data)
wasTruncated := actualSize > maxSize
// If we read exactly maxSize+1, there might be more data
// Discard the rest but count the bytes for accurate BodySize
if wasTruncated {
data = data[:maxSize] // Keep only maxSize bytes for logging
// Count remaining bytes without storing them
remaining, _ := io.Copy(io.Discard, body)
actualSize = maxSize + int(remaining)
}
return data, actualSize
}
// shouldLog checks if the request path matches the filter
func (p *Proxy) shouldLog(path string) bool {
if p.filterPath == "" {
+242
View File
@@ -3,6 +3,7 @@ package httplog
import (
"bytes"
"encoding/json"
"net"
"net/http"
"os"
"testing"
@@ -179,3 +180,244 @@ func TestNewLogger(t *testing.T) {
require.NoError(t, err)
assert.Contains(t, string(data), `"direction":"request"`)
}
// TestNewProxy tests proxy creation
func TestNewProxy(t *testing.T) {
t.Run("valid config", func(t *testing.T) {
fwd := &config.Forward{
LocalPort: 8080,
Port: 80,
HTTPLog: &config.HTTPLogSpec{
Enabled: true,
FilterPath: "/api/*",
IncludeHeaders: true,
},
}
proxy, err := NewProxy(fwd, 18080)
require.NoError(t, err)
require.NotNil(t, proxy)
assert.Equal(t, 8080, proxy.localPort)
assert.Equal(t, 18080, proxy.targetPort)
assert.Equal(t, "/api/*", proxy.filterPath)
assert.True(t, proxy.includeHdrs)
assert.NotNil(t, proxy.logger)
})
t.Run("nil HTTPLog config", func(t *testing.T) {
fwd := &config.Forward{
LocalPort: 8080,
HTTPLog: nil,
}
proxy, err := NewProxy(fwd, 18080)
assert.Error(t, err)
assert.Nil(t, proxy)
assert.Contains(t, err.Error(), "HTTP log config is nil")
})
}
// TestProxy_GetTargetPort tests target port getter
func TestProxy_GetTargetPort(t *testing.T) {
proxy := &Proxy{targetPort: 19090}
assert.Equal(t, 19090, proxy.GetTargetPort())
}
// TestProxy_GetLogger tests logger getter
func TestProxy_GetLogger(t *testing.T) {
logger := &Logger{forwardID: "test"}
proxy := &Proxy{logger: logger}
result := proxy.GetLogger()
assert.Equal(t, logger, result)
}
// TestProxy_ShouldLog tests path filtering
func TestProxy_ShouldLog(t *testing.T) {
tests := []struct {
name string
filterPath string
path string
expected bool
}{
// No filter - log everything
{"empty filter logs all", "", "/any/path", true},
{"empty filter logs root", "", "/", true},
// Exact match
{"exact match", "/api", "/api", true},
{"exact no match", "/api", "/other", false},
// Wildcard patterns
{"single wildcard match", "/api/*", "/api/users", true},
{"single wildcard no match", "/api/*", "/other/users", false},
{"middle wildcard", "/api/*/test", "/api/v1/test", true},
{"middle wildcard no match", "/api/*/test", "/api/v1/other", false},
// Prefix patterns (/* suffix special handling)
{"prefix match", "/api/*", "/api/users/123", true},
{"prefix match nested", "/api/*", "/api/users/123/deep", true},
// Edge cases
{"empty path", "/api/*", "", false},
{"trailing slash filter", "/api/", "/api/", true},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
p := &Proxy{filterPath: tt.filterPath}
result := p.shouldLog(tt.path)
assert.Equal(t, tt.expected, result, "filterPath=%q, path=%q", tt.filterPath, tt.path)
})
}
}
// TestProxy_ShouldLog_InvalidPattern tests behavior with invalid glob patterns
func TestProxy_ShouldLog_InvalidPattern(t *testing.T) {
// Invalid glob pattern (unclosed bracket)
p := &Proxy{filterPath: "/api/[invalid"}
// Should default to logging everything on invalid pattern
assert.True(t, p.shouldLog("/any/path"))
}
// TestProxy_StartStop tests basic start/stop lifecycle
func TestProxy_StartStop(t *testing.T) {
var buf bytes.Buffer
logger := &Logger{
forwardID: "test",
maxBodyLen: 1024,
output: &buf,
}
proxy := &Proxy{
localPort: 0, // Ephemeral port
targetPort: 9999,
logger: logger,
forwardID: "test-fwd",
}
// Start
err := proxy.Start()
require.NoError(t, err)
assert.True(t, proxy.running)
assert.NotNil(t, proxy.listener)
assert.NotNil(t, proxy.server)
// Double start should fail
err = proxy.Start()
assert.Error(t, err)
assert.Contains(t, err.Error(), "already running")
// Stop
err = proxy.Stop()
assert.NoError(t, err)
assert.False(t, proxy.running)
// Double stop should be OK
err = proxy.Stop()
assert.NoError(t, err)
}
// TestProxy_Start_PortInUse tests behavior when port is already in use
func TestProxy_Start_PortInUse(t *testing.T) {
// Start first proxy
logger1 := &Logger{output: bytes.NewBuffer(nil), maxBodyLen: 100}
proxy1 := &Proxy{
localPort: 0, // Ephemeral
targetPort: 9999,
logger: logger1,
}
err := proxy1.Start()
require.NoError(t, err)
defer proxy1.Stop()
// Get the actual port
addr := proxy1.listener.Addr().(*net.TCPAddr)
usedPort := addr.Port
// Try to start second proxy on same port
logger2 := &Logger{output: bytes.NewBuffer(nil), maxBodyLen: 100}
proxy2 := &Proxy{
localPort: usedPort,
targetPort: 9999,
logger: logger2,
}
err = proxy2.Start()
assert.Error(t, err)
assert.Contains(t, err.Error(), "failed to listen")
}
// TestFlattenHeaders_EdgeCases tests header flattening edge cases
func TestFlattenHeaders_EdgeCases(t *testing.T) {
tests := []struct {
name string
headers http.Header
expected map[string]string
}{
{
name: "empty headers",
headers: http.Header{},
expected: map[string]string{},
},
{
name: "single value",
headers: http.Header{"X-Test": {"value"}},
expected: map[string]string{"X-Test": "value"},
},
{
name: "multiple values same key",
headers: http.Header{"Accept": {"text/html", "application/json", "text/plain"}},
expected: map[string]string{"Accept": "text/html, application/json, text/plain"},
},
{
name: "empty value",
headers: http.Header{"X-Empty": {""}},
expected: map[string]string{"X-Empty": ""},
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
result := flattenHeaders(tt.headers)
assert.Equal(t, tt.expected, result)
})
}
}
// TestProxy_RequestCount tests request counting
func TestProxy_RequestCount(t *testing.T) {
proxy := &Proxy{requestCount: 0}
// Simulate incrementing (normally done by loggingTransport)
assert.Equal(t, uint64(0), proxy.requestCount)
}
// TestProxy_LogError tests error logging
func TestProxy_LogError(t *testing.T) {
var buf bytes.Buffer
logger := &Logger{
forwardID: "test",
maxBodyLen: 1024,
output: &buf,
}
proxy := &Proxy{
logger: logger,
forwardID: "test-fwd",
}
req, _ := http.NewRequest("GET", "/test", nil)
proxy.logError(req, assert.AnError)
var entry Entry
err := json.Unmarshal(buf.Bytes(), &entry)
require.NoError(t, err)
assert.Equal(t, "error", entry.Direction)
assert.Equal(t, "GET", entry.Method)
assert.Equal(t, "/test", entry.Path)
assert.Contains(t, entry.Error, "assert.AnError")
}