go-sip/internal/logging/http.go

package logging

import (
	"bytes"
	"context"
	"errors"
	"fmt"
	"io"
	"log/slog"
	"mime"
	"net/http"
	"strings"
	"sync"
	"time"
)

// HTTPClient clones the client, retaining its TLS, redirect, timeout and custom
// transport settings. Only bytes actually read at the boundary are observed.
func HTTPClient(client *http.Client, local, remote string) *http.Client {
	if client == nil {
		client = http.DefaultClient
	}
	clone := *client
	transport := client.Transport
	if transport == nil {
		transport = http.DefaultTransport
	}
	if observed, ok := transport.(*httpObserver); ok {
		transport = observed.next
	}
	clone.Transport = &httpObserver{next: transport, local: local, remote: remote}
	return &clone
}

// ObserveDefaultHTTP covers library-owned HTTP clients (including native ARI)
// whose supported API does not expose a transport. Call only at service startup.
func ObserveDefaultHTTP(local string) {
	next := http.DefaultTransport
	if observed, ok := next.(*httpObserver); ok {
		next = observed.next
	}
	http.DefaultTransport = &httpObserver{next: next, local: local}
}

// CloneDefaultTransport retains explicit transport settings used by isolated
// TLS tests. A custom non-HTTP transport is an error, not a silent fallback.
func CloneDefaultTransport() (*http.Transport, error) {
	base := http.DefaultTransport
	if observed, ok := base.(*httpObserver); ok {
		base = observed.next
	}
	transport, ok := base.(*http.Transport)
	if !ok {
		return nil, fmt.Errorf("default HTTP transport cannot be cloned: %T", base)
	}
	return transport.Clone(), nil
}

type httpObserver struct {
	next          http.RoundTripper
	local, remote string
}

func (t *httpObserver) RoundTrip(req *http.Request) (*http.Response, error) {
	started := time.Now()
	remote := t.remote
	if remote == "" {
		remote = req.URL.Host
		if remote == "127.0.0.1:8088" {
			remote = "asterisk"
		}
	}
	attrs := []any{"transport", "http", "method", req.Method, "url", req.URL.String()}
	ctx := req.Context()
	slog.InfoContext(ctx, "HTTP request", append(attrs, "direction", t.local+"->"+remote, "stage", "request_start")...)
	clone := req.Clone(ctx)
	if req.Body != nil {
		clone.Body = newObservedBody(ctx, req.Body, req.Header.Get("Content-Type"), "HTTP request data", append(attrs, "direction", t.local+"->"+remote)...)
	}
	res, err := t.next.RoundTrip(clone)
	result := append(attrs, "direction", remote+"->"+t.local, "duration_ms", time.Since(started).Milliseconds())
	if err != nil {
		slog.ErrorContext(ctx, "HTTP failed", append(result, "stage", "transport_failed", "error", err)...)
		return res, err
	}
	slog.InfoContext(ctx, "HTTP response", append(result, "stage", "response_received", "http_status", res.StatusCode, "content_type", res.Header.Get("Content-Type"))...)
	// HTTP upgrades require the original read/write stream (ASR/TTS WebSocket).
	if res.StatusCode == http.StatusSwitchingProtocols {
		return res, nil
	}
	if res.Body != nil {
		res.Body = newObservedBody(ctx, res.Body, res.Header.Get("Content-Type"), "HTTP response data", append(result, "http_status", res.StatusCode)...)
	}
	return res, nil
}

type observedBody struct {
	source  io.ReadCloser
	ctx     context.Context
	message string
	attrs   []any
	collect bool
	text    bool
	mu      sync.Mutex
	data    bytes.Buffer
	count   int64
	done    bool
	started time.Time
}

func newObservedBody(ctx context.Context, source io.ReadCloser, contentType, message string, attrs ...any) *observedBody {
	media, _, err := mime.ParseMediaType(contentType)
	isJSON := err == nil && (media == "application/json" || strings.HasSuffix(media, "+json"))
	isText := err == nil && (strings.HasPrefix(media, "text/") || media == "application/xml" || strings.HasSuffix(media, "+xml") || media == "application/x-www-form-urlencoded")
	mode := "binary_omitted"
	if isJSON {
		mode = "json"
	} else if isText {
		mode = "text"
	}
	return &observedBody{source: source, ctx: ctx, message: message, attrs: append(append([]any{}, attrs...), "content_type", contentType, "body_mode", mode), collect: (isJSON || isText) && slog.Default().Enabled(ctx, slog.LevelDebug), text: isText && !isJSON, started: time.Now()}
}
func (r *observedBody) Read(p []byte) (int, error) {
	n, err := r.source.Read(p)
	r.mu.Lock()
	defer r.mu.Unlock()
	r.count += int64(n)
	if r.collect && !r.done {
		r.data.Write(p[:n])
	}
	if errors.Is(err, io.EOF) {
		r.finishLocked(true, nil)
	} else if err != nil {
		r.finishLocked(false, err)
	}
	return n, err
}
func (r *observedBody) Close() error {
	err := r.source.Close()
	r.mu.Lock()
	defer r.mu.Unlock()
	r.finishLocked(false, err)
	if err != nil {
		slog.ErrorContext(r.ctx, "HTTP body close failed", append(r.attrs, "stage", "body_close_failed", "error", err)...)
	}
	return err
}
func (r *observedBody) finishLocked(complete bool, err error) {
	if r.done {
		return
	}
	r.done = true
	stage := "body_read"
	if !complete {
		stage = "body_read_incomplete"
	}
	attrs := append(append([]any{}, r.attrs...), "stage", stage, "bytes_read", r.count, "body_duration_ms", time.Since(r.started).Milliseconds())
	if err != nil {
		slog.ErrorContext(r.ctx, "HTTP body read failed", append(attrs, "error", err)...)
	} else {
		slog.InfoContext(r.ctx, "HTTP body observation", attrs...)
	}
	if r.collect {
		// A decoder may close after consuming a valid JSON value without reading
		// EOF. Log observed bytes without claiming a complete wire body; malformed
		// prefixes still produce an explicit safe redaction diagnostic.
		if r.text {
			TextBody(r.ctx, r.message, r.data.Bytes(), append(attrs, "body_complete", complete)...)
		} else {
			Body(r.ctx, r.message, r.data.Bytes(), append(attrs, "body_complete", complete)...)
		}
	}
	r.data.Reset()
}