feat: add request diagnostics

README.md

@@ -9,6 +9,7 @@ A lightweight Modbus TCP proxy with in-memory caching. Designed to reduce load o
 - **Read-only mode**: Optionally block or ignore write requests
 - **Auto-reconnect**: Automatic upstream reconnection on failure
 - **Stale data fallback**: Optionally serve stale cache on upstream errors
+- **Request diagnostics**: Structured lifecycle timing, retry, exception, and health state
 - **Graceful shutdown**: Complete in-flight requests before terminating
 - **Minimal footprint**: ~6MB Docker image (scratch base)
 
@@ -57,6 +58,35 @@ validation uses the standard validation exception codes.
 
 `/mbproxy -health` performs an internal upstream connectivity check and does not open a separate local TCP health port.
 
+### Production Diagnostics
+
+Upstream lifecycle logs identify requests with `slave_id`, `func`, `addr`,
+`qty`, and `write`; write payloads are never logged. Timing fields separate
+`queue_duration`, `attempt_duration`, `reconnect_duration`, and
+`total_duration`. Retry and failure records also include `attempt`, `attempts`,
+`error_kind`, `will_retry`, and the preserved `exception_code` or mapped
+`downstream_exception` when applicable.
+
+The first retryable read transport failure is logged at DEBUG with
+`will_retry=true`; a recovered second attempt is logged at DEBUG with
+`attempts=2`. Final upstream failures and genuine upstream Modbus exceptions
+are WARN records. Request cancellation is DEBUG. Requests already canceled or
+expired do not select stale fallback, and the fallback record does not claim
+downstream delivery. Coalesced followers report `coalesced=true`,
+`coalesced_wait_duration`, and zero attempts so they are not mistaken for
+independent upstream traffic. A follower that outlives a canceled leader and
+performs the replacement fetch instead reports `coalesced_waited=true` with
+`coalesced=false`, preserving both its wait and its real upstream attempt.
+
+The health response includes cumulative `total_retries` and
+`recovered_retries`, consecutive first-attempt and final-failure counts, the
+last first-attempt success, the last successful request, and degradation flags.
+A recovered retry immediately sets `degraded=true` but remains HTTP 200 with
+status `ok`. If no first-attempt success clears that state for one minute,
+status becomes `degraded` while remaining HTTP 200. A final upstream failure
+still returns HTTP 503 `unhealthy`. Success timestamps are `null` until the
+corresponding success has occurred.
+
 ### Read-Only Modes
 
 - `false`: Full read/write passthrough to upstream device

SPEC.md

@@ -91,6 +91,34 @@ type CacheEntry struct {
 - Not reapplied between a failed read attempt and its retry
 - Logged at DEBUG level when a request waits for its slot
 
+### Request Diagnostics and Health
+
+- Structured upstream lifecycle logs include request identity (`slave_id`,
+  `func`, `addr`, `qty`, `write`), attempt state (`attempt`, `attempts`,
+  `will_retry`, `error_kind`), and disjoint timing
+  (`queue_duration`, `attempt_duration`, `reconnect_duration`,
+  `total_duration`). Write payloads are excluded.
+- A first retryable read transport failure is DEBUG; a successful retry is
+  DEBUG with `attempts=2`; a final upstream failure or genuine upstream Modbus
+  exception is WARN. Request cancellation is DEBUG. Requests already canceled
+  or expired do not select stale fallback, and the fallback record does not
+  claim downstream delivery. Genuine exceptions preserve their nonzero
+  `exception_code` and are not retried or reconnected.
+- Downstream failure logs include the mapped `downstream_exception`.
+  Coalesced followers use `coalesced=true`, expose their wait duration, and
+  report zero attempts instead of inheriting the leader's wire-attempt timing.
+  A follower that takes over after a canceled leader instead uses
+  `coalesced_waited=true` with `coalesced=false`; its wait is logged separately
+  and its replacement fetch keeps its actual upstream-attempt diagnostics.
+- Diagnostics retain cumulative retry and recovered-retry counters,
+  consecutive first-attempt and final-failure counts, last first-attempt
+  success, and last successful request.
+- A recovered retry sets diagnostic degradation immediately and that state is
+  cleared only by a later first-attempt success. It remains available and does
+  not fail health. If degradation persists for one minute, the health JSON
+  status becomes `degraded` while HTTP status remains 200. A final upstream
+  failure remains `unhealthy` with HTTP 503.
+
 ### 4. Read-Only Mode
 Three modes:
 - `false`: Full read/write passthrough
@@ -259,10 +287,10 @@ The cache also exposes `Coalesce(ctx, rangeKey, fetch)` for request coalescing.
 level=INFO msg="starting proxy" listen=:5502 upstream=192.168.1.100:502
 level=DEBUG msg="cache hit" slave_id=1 func=0x03 addr=0 qty=10
 level=DEBUG msg="cache miss" slave_id=1 func=0x03 addr=0 qty=10
-level=DEBUG msg="upstream request completed" slave_id=1 func=0x03 addr=0 qty=10 duration=15ms
+level=DEBUG msg="upstream request completed" slave_id=1 func=0x03 addr=0 qty=10 write=false attempt=1 attempts=1 queue_duration=2ms attempt_duration=15ms reconnect_duration=0s total_duration=17ms error_kind="" will_retry=false
 level=DEBUG msg="waiting for upstream request slot" delay=100ms
 level=DEBUG msg="applying connect delay" delay=500ms
-level=WARN msg="upstream error, serving stale" slave_id=1 error="timeout"
+level=WARN msg="stale fallback selected" slave_id=1 stale_fallback_selected=true error_kind=transport_timeout
 level=INFO msg="shutting down"
 ```
 

internal/cache/cache.go

@@ -43,6 +43,43 @@ type inflightRequest struct {
 	followers int
 }
 
+// CoalesceResult describes whether a caller shared another caller's fetch.
+type CoalesceResult struct {
+	Coalesced    bool
+	Waited       bool
+	WaitDuration time.Duration
+}
+
+type coalescingError struct {
+	err          error
+	coalesced    bool
+	waitDuration time.Duration
+}
+
+func (e *coalescingError) Error() string {
+	return e.err.Error()
+}
+
+func (e *coalescingError) Unwrap() error {
+	return e.err
+}
+
+func (e *coalescingError) Coalesced() bool {
+	return e.coalesced
+}
+
+func (e *coalescingError) CoalescedWaitDuration() time.Duration {
+	return e.waitDuration
+}
+
+func attributedCoalescingError(err error, coalesced bool, waitDuration time.Duration) error {
+	return &coalescingError{
+		err:          err,
+		coalesced:    coalesced,
+		waitDuration: waitDuration,
+	}
+}
+
 // New creates a new cache with the specified default TTL.
 // If keepStale is true, expired entries are retained for stale serving.
 func New(defaultTTL time.Duration, keepStale bool) *Cache {
@@ -213,9 +250,20 @@ func (c *Cache) DeleteRange(slaveID byte, functionCode byte, startAddr uint16, q
 // Other callers with the same key wait for and share the first caller's result.
 // This handles request coalescing only — it does not interact with cache storage.
 func (c *Cache) Coalesce(ctx context.Context, key string, fetch func(context.Context) ([]byte, error)) ([]byte, error) {
+	data, _, err := c.CoalesceWithStatus(ctx, key, fetch)
+	return data, err
+}
+
+// CoalesceWithStatus is Coalesce with explicit leader/follower attribution.
+func (c *Cache) CoalesceWithStatus(ctx context.Context, key string, fetch func(context.Context) ([]byte, error)) ([]byte, CoalesceResult, error) {
+	var totalWait time.Duration
+	waited := false
 	for {
 		if err := ctx.Err(); err != nil {
-			return nil, err
+			if waited {
+				err = attributedCoalescingError(err, false, totalWait)
+			}
+			return nil, CoalesceResult{Waited: waited, WaitDuration: totalWait}, err
 		}
 
 		c.inflightMu.Lock()
@@ -229,25 +277,35 @@ func (c *Cache) Coalesce(ctx context.Context, key string, fetch func(context.Con
 		c.inflightMu.Unlock()
 
 		if ok {
+			waited = true
+			waitStart := time.Now()
 			if err := ctx.Err(); err != nil {
-				return nil, err
+				waitDuration := time.Since(waitStart)
+				totalWait += waitDuration
+				return nil, CoalesceResult{Coalesced: true, Waited: true, WaitDuration: totalWait},
+					attributedCoalescingError(err, true, totalWait)
 			}
 			select {
 			case <-req.done:
+				totalWait += time.Since(waitStart)
 				if err := ctx.Err(); err != nil {
-					return nil, err
+					return nil, CoalesceResult{Coalesced: true, Waited: true, WaitDuration: totalWait},
+						attributedCoalescingError(err, true, totalWait)
 				}
 				if req.err != nil {
 					if errors.Is(req.err, context.Canceled) || errors.Is(req.err, context.DeadlineExceeded) {
 						continue
 					}
-					return nil, req.err
+					return nil, CoalesceResult{Coalesced: true, Waited: true, WaitDuration: totalWait},
+						attributedCoalescingError(req.err, true, totalWait)
 				}
 				data := make([]byte, len(req.result))
 				copy(data, req.result)
-				return data, nil
+				return data, CoalesceResult{Coalesced: true, Waited: true, WaitDuration: totalWait}, nil
 			case <-ctx.Done():
-				return nil, ctx.Err()
+				totalWait += time.Since(waitStart)
+				return nil, CoalesceResult{Coalesced: true, Waited: true, WaitDuration: totalWait},
+					attributedCoalescingError(ctx.Err(), true, totalWait)
 			}
 		}
 
@@ -265,12 +323,15 @@ func (c *Cache) Coalesce(ctx context.Context, key string, fetch func(context.Con
 		close(req.done)
 
 		if err != nil {
-			return nil, err
+			if waited {
+				err = attributedCoalescingError(err, false, totalWait)
+			}
+			return nil, CoalesceResult{Waited: waited, WaitDuration: totalWait}, err
 		}
 
 		result := make([]byte, len(data))
 		copy(result, data)
-		return result, nil
+		return result, CoalesceResult{Waited: waited, WaitDuration: totalWait}, nil
 	}
 }