fix: log upstream duration excluding request delay

Move duration logging from proxy to client, measuring only the actual
upstream request time. This prevents the configured request delay from
being included in the logged duration.

Author: tma

SPEC.md

@@ -193,8 +193,8 @@ func (c *Cache) Set(key string, data []byte, ttl time.Duration) {
 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 read" slave_id=1 func=0x03 addr=0 qty=10 duration=15ms
-level=DEBUG msg="applying request delay" duration=100ms
+level=DEBUG msg="upstream request completed" slave_id=1 func=0x03 addr=0 qty=10 duration=15ms
+level=DEBUG msg="applying request delay" delay=100ms
 level=WARN msg="upstream error, serving stale" slave_id=1 error="timeout"
 level=INFO msg="shutting down"
 ```

internal/modbus/client.go

@@ -89,7 +89,8 @@ func (c *Client) Execute(ctx context.Context, req *Request) ([]byte, error) {
 	// Set slave ID
 	c.conn.SlaveID = req.SlaveID
 
-	// Execute request
+	// Execute request and measure time
+	start := time.Now()
 	resp, err := c.executeRequest(ctx, req)
 	if err != nil {
 		// Try reconnect once
@@ -98,15 +99,25 @@ func (c *Client) Execute(ctx context.Context, req *Request) ([]byte, error) {
 			return nil, fmt.Errorf("reconnect failed: %w", reconnErr)
 		}
 		c.conn.SlaveID = req.SlaveID
+		start = time.Now() // Reset timer for retry
 		resp, err = c.executeRequest(ctx, req)
 		if err != nil {
 			return nil, err
 		}
 	}
+	duration := time.Since(start)
+
+	c.logger.Debug("upstream request completed",
+		"slave_id", req.SlaveID,
+		"func", fmt.Sprintf("0x%02X", req.FunctionCode),
+		"addr", req.Address,
+		"qty", req.Quantity,
+		"duration", duration,
+	)
 
 	// Apply request delay if configured (only after successful requests)
 	if c.requestDelay > 0 {
-		c.logger.Debug("applying request delay", "duration", c.requestDelay)
+		c.logger.Debug("applying request delay", "delay", c.requestDelay)
 		select {
 		case <-time.After(c.requestDelay):
 		case <-ctx.Done():

internal/proxy/proxy.go

@@ -87,14 +87,12 @@ func (p *Proxy) Shutdown(timeout time.Duration) error {
 
 // HandleRequest implements modbus.Handler interface.
 func (p *Proxy) HandleRequest(ctx context.Context, req *modbus.Request) ([]byte, error) {
-	start := time.Now()
-
 	if modbus.IsWriteFunction(req.FunctionCode) {
-		return p.handleWrite(ctx, req, start)
+		return p.handleWrite(ctx, req)
 	}
 
 	if modbus.IsReadFunction(req.FunctionCode) {
-		return p.handleRead(ctx, req, start)
+		return p.handleRead(ctx, req)
 	}
 
 	// Unknown function code
@@ -105,7 +103,7 @@ func (p *Proxy) HandleRequest(ctx context.Context, req *modbus.Request) ([]byte,
 	return modbus.BuildExceptionResponse(req.FunctionCode, modbus.ExcIllegalFunction), nil
 }
 
-func (p *Proxy) handleRead(ctx context.Context, req *modbus.Request, start time.Time) ([]byte, error) {
+func (p *Proxy) handleRead(ctx context.Context, req *modbus.Request) ([]byte, error) {
 	key := cache.Key(req.SlaveID, req.FunctionCode, req.Address, req.Quantity)
 
 	// Use GetOrFetch for request coalescing
@@ -117,20 +115,7 @@ func (p *Proxy) handleRead(ctx context.Context, req *modbus.Request, start time.
 			"qty", req.Quantity,
 		)
 
-		resp, err := p.client.Execute(ctx, req)
-		if err != nil {
-			return nil, err
-		}
-
-		p.logger.Debug("upstream read",
-			"slave_id", req.SlaveID,
-			"func", fmt.Sprintf("0x%02X", req.FunctionCode),
-			"addr", req.Address,
-			"qty", req.Quantity,
-			"duration", time.Since(start),
-		)
-
-		return resp, nil
+		return p.client.Execute(ctx, req)
 	})
 
 	if err != nil {
@@ -159,7 +144,7 @@ func (p *Proxy) handleRead(ctx context.Context, req *modbus.Request, start time.
 	return data, nil
 }
 
-func (p *Proxy) handleWrite(ctx context.Context, req *modbus.Request, start time.Time) ([]byte, error) {
+func (p *Proxy) handleWrite(ctx context.Context, req *modbus.Request) ([]byte, error) {
 	switch p.cfg.ReadOnly {
 	case config.ReadOnlyOn:
 		// Silently ignore, return success response
@@ -186,14 +171,6 @@ func (p *Proxy) handleWrite(ctx context.Context, req *modbus.Request, start time
 			return nil, err
 		}
 
-		p.logger.Debug("upstream write",
-			"slave_id", req.SlaveID,
-			"func", fmt.Sprintf("0x%02X", req.FunctionCode),
-			"addr", req.Address,
-			"qty", req.Quantity,
-			"duration", time.Since(start),
-		)
-
 		// Invalidate exact matching cache entries for all read function codes
 		p.invalidateCache(req)