fix: trace delayed websocket acknowledgements

This commit is contained in:
richjohnrambo
2026-10-01 15:19:57 +08:00
parent 19584d0939
commit 73a594146f
19 changed files with 788 additions and 149 deletions
+132 -24
View File
@@ -19,27 +19,32 @@ import (
var runIDPattern = regexp.MustCompile(`^[a-zA-Z0-9_-]{1,24}$`)
type agentRun struct {
cfg *Config
machine string
runID string
scenario string
clients map[int]*WSClient
clientsMu sync.RWMutex
recorder *deliveryRecorder
callbackQueue *callbackQueueMetrics
ack *DurationHistogram
attempted atomic.Int64
ready atomic.Int64
publish403 atomic.Int64
publish502 atomic.Int64
publish503 atomic.Int64
publishTimeout atomic.Int64
publishSocket atomic.Int64
publishOther atomic.Int64
cfg *Config
machine string
runID string
scenario string
clients map[int]*WSClient
clientsMu sync.RWMutex
recorder *deliveryRecorder
callbackQueue *callbackQueueMetrics
ack *DurationHistogram
ctrlLatency *DurationHistogram
attempted atomic.Int64
ready atomic.Int64
publish403 atomic.Int64
publish502 atomic.Int64
publish503 atomic.Int64
publishTimeout atomic.Int64
publishSocket atomic.Int64
publishOther atomic.Int64
publishCtrlObserved atomic.Int64
publishCtrlOver20 atomic.Int64
publishLateCtrl atomic.Int64
mu sync.Mutex
accepted []AcceptedMessage
errors []string
mu sync.Mutex
accepted []AcceptedMessage
errors []string
ctrlSamples []CtrlObservationSample
}
func validScenario(scenario string) bool {
@@ -127,6 +132,7 @@ func runAgent(ctx context.Context, cfg *Config, manifest *Manifest, machine, coo
coord := newCoordinatorClient(coordinatorURL)
placeholderRunID := "pending"
run := &agentRun{cfg: cfg, machine: machine, clients: make(map[int]*WSClient), ack: NewDurationHistogram(),
ctrlLatency: NewDurationHistogram(),
callbackQueue: &callbackQueueMetrics{}}
run.recorder = newDeliveryRecorder(placeholderRunID, machine, len(accounts))
stopMetrics, err := startAgentMetrics(metricsListen, run)
@@ -211,6 +217,12 @@ func runAgent(ctx context.Context, cfg *Config, manifest *Manifest, machine, coo
if err = waitForCallbackQueue(ctx, run.callbackQueue, 30*time.Second); err != nil {
return err
}
quietPeriod, _ := configDuration(cfg.DeliveryQuiet)
quietTimeout, _ := configDuration(cfg.DeliveryTimeout)
log.Printf("agent=%s waiting for %s of delivery quiescence", machine, quietPeriod)
if err = waitForDeliveryQuiescence(ctx, run.recorder, run.callbackQueue, quietPeriod, quietTimeout); err != nil {
return err
}
observedLocal := run.recorder.unackedObservedMessages(ledger, start.Scenario)
if err = coord.submitObserved(ctx, machine, observedLocal); err != nil {
return err
@@ -233,7 +245,10 @@ func runAgent(ctx context.Context, cfg *Config, manifest *Manifest, machine, coo
run.mu.Lock()
base.Errors = append(base.Errors, run.errors...)
run.mu.Unlock()
summary := run.recorder.summarize(base, ledger)
// Include messages observed over WebSocket without a timely ctrl ACK. They
// are confirmed server-side publishes and must participate in realtime
// delivery accounting instead of being reported as unexpected traffic.
summary := run.recorder.summarize(base, verificationLedger)
historySettle, _ := configDuration(cfg.HistorySettle)
log.Printf("agent=%s waiting %s before history verification", machine, historySettle)
if err = waitContext(ctx, historySettle); err != nil {
@@ -256,7 +271,7 @@ func runAgent(ctx context.Context, cfg *Config, manifest *Manifest, machine, coo
summary.HistoryUnackedFound = int64(history.unackedFound)
persistenceMissing := history.missing
summary.PersistenceLost = int64(len(persistenceMissing))
summary.RealtimeLostStored = run.recorder.countRealtimeLostStored(ledger, storedMessageIDs)
summary.RealtimeLostStored = run.recorder.countRealtimeLostStored(verificationLedger, storedMessageIDs)
if len(persistenceMissing) > 10000 {
summary.PersistenceMissing = append([]string(nil), persistenceMissing[:10000]...)
summary.Errors = append(summary.Errors, "persistence missing details truncated at 10000")
@@ -264,6 +279,7 @@ func runAgent(ctx context.Context, cfg *Config, manifest *Manifest, machine, coo
summary.PersistenceMissing = persistenceMissing
}
summary.FinishedAt = time.Now().UTC()
run.applyCtrlObservations(&summary)
if err = writeAgentSummary(output, summary); err != nil {
return err
}
@@ -293,6 +309,51 @@ func waitForCallbackQueue(ctx context.Context, queue *callbackQueueMetrics, time
}
return nil
}
func waitForDeliveryQuiescence(ctx context.Context, recorder *deliveryRecorder, queue *callbackQueueMetrics,
quietPeriod, timeout time.Duration) error {
deadline := time.NewTimer(timeout)
defer deadline.Stop()
ticker := time.NewTicker(100 * time.Millisecond)
defer ticker.Stop()
lastReceived := recorder.received.Load()
stableSince := time.Now()
for {
select {
case <-ctx.Done():
return ctx.Err()
case <-deadline.C:
return fmt.Errorf("deliveries did not become quiescent within %s: received=%d queued=%d processing=%d",
timeout, recorder.received.Load(), queue.current.Load(), queue.processing.Load())
case now := <-ticker.C:
received := recorder.received.Load()
if received != lastReceived || !queue.isDrained() {
lastReceived = received
stableSince = now
continue
}
if now.Sub(stableSince) >= quietPeriod {
return nil
}
}
}
}
func assignAgentEndpoints(cfg *Config, machine string, accounts []AccountRecord) {
endpoints := cfg.Endpoints[machine]
dialIPs := cfg.DialIPs[machine]
machineOffset := 0
if machine == "b" {
machineOffset = 1
}
for i := range accounts {
accounts[i].Endpoint = endpoints[(accounts[i].Index-1)%len(endpoints)]
if len(dialIPs) > 0 {
slot := (accounts[i].Index-1)*2 + machineOffset
accounts[i].DialIP = strings.TrimSpace(dialIPs[slot%len(dialIPs)])
}
}
}
type historyQuery struct {
client *WSClient
topic string
@@ -690,7 +751,8 @@ func (r *agentRun) maintainConnections(ctx context.Context, accounts []AccountRe
func (r *agentRun) connectAccountWithRetry(ctx context.Context, account AccountRecord, groupTopic, apiKey, password string) (*WSClient, error) {
var lastErr error
for attempt := 1; attempt <= 6; attempt++ {
client, err := connectWSClient(ctx, r.cfg, account, apiKey, password, r.recorder.onData, r.recorder.onDisconnect, r.callbackQueue)
client, err := connectWSClient(ctx, r.cfg, account, apiKey, password, r.recorder.onData, r.recorder.onDisconnect,
r.observeCtrl, r.callbackQueue)
if err == nil {
if err = client.Subscribe(ctx, account.P2PTopic); err == nil {
err = client.Subscribe(ctx, groupTopic)
@@ -898,7 +960,53 @@ func (r *agentRun) explicitRejected() int64 {
}
func (r *agentRun) outcomeUnknown() int64 {
return r.publishTimeout.Load() + r.publishSocket.Load()
return r.unresolvedCtrl() + r.publishSocket.Load()
}
func (r *agentRun) unresolvedCtrl() int64 {
unresolved := r.publishTimeout.Load() - r.publishLateCtrl.Load()
if unresolved < 0 {
return 0
}
return unresolved
}
func (r *agentRun) observeCtrl(account AccountRecord, observation ctrlObservation) {
if observation.Kind != "pub" {
return
}
r.publishCtrlObserved.Add(1)
r.ctrlLatency.Observe(observation.Latency)
if observation.Latency > 20*time.Second {
r.publishCtrlOver20.Add(1)
}
if observation.Late {
r.publishLateCtrl.Add(1)
}
if observation.Late || observation.Latency > 20*time.Second {
r.mu.Lock()
if len(r.ctrlSamples) < 1000 {
r.ctrlSamples = append(r.ctrlSamples, CtrlObservationSample{
Machine: account.Machine, Index: account.Index, ID: observation.ID, Code: observation.Code,
SentAt: observation.SentAt, ReceivedAt: observation.ReceivedAt,
LatencyMS: float64(observation.Latency) / float64(time.Millisecond), Late: observation.Late,
})
}
r.mu.Unlock()
}
}
func (r *agentRun) applyCtrlObservations(summary *AgentSummary) {
summary.CtrlTrackingEnabled = true
summary.PublishCtrlObserved = r.publishCtrlObserved.Load()
summary.PublishCtrlOver20 = r.publishCtrlOver20.Load()
summary.PublishLateCtrl = r.publishLateCtrl.Load()
summary.PublishCtrlUnresolved = r.unresolvedCtrl()
summary.PublishOutcomeUnknown = r.outcomeUnknown()
summary.PublishCtrlLatency = r.ctrlLatency.Snapshot()
r.mu.Lock()
summary.CtrlObservationSamples = append([]CtrlObservationSample(nil), r.ctrlSamples...)
r.mu.Unlock()
}
func (r *agentRun) addAccepted(message AcceptedMessage) {
+4
View File
@@ -46,6 +46,10 @@ func startAgentMetrics(address string, run *agentRun) (func(), error) {
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_publish_502_total", Help: "Publish commands rejected with 502.", ConstLabels: labels}, func() float64 { return float64(run.publish502.Load()) }),
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_publish_503_total", Help: "Publish commands rejected with 503.", ConstLabels: labels}, func() float64 { return float64(run.publish503.Load()) }),
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_publish_ctrl_timeout_total", Help: "Publish commands with control-response timeout.", ConstLabels: labels}, func() float64 { return float64(run.publishTimeout.Load()) }),
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_publish_ctrl_observed_total", Help: "Publish control responses observed, including responses received after command timeout.", ConstLabels: labels}, func() float64 { return float64(run.publishCtrlObserved.Load()) }),
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_publish_ctrl_over_20s_total", Help: "Publish control responses taking longer than 20 seconds.", ConstLabels: labels}, func() float64 { return float64(run.publishCtrlOver20.Load()) }),
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_publish_ctrl_late_total", Help: "Publish control responses received after command timeout.", ConstLabels: labels}, func() float64 { return float64(run.publishLateCtrl.Load()) }),
prometheus.NewGaugeFunc(prometheus.GaugeOpts{Name: "im_load_agent_publish_ctrl_unresolved", Help: "Publish control responses still unresolved after accounting for late responses.", ConstLabels: labels}, func() float64 { return float64(run.unresolvedCtrl()) }),
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_publish_socket_error_total", Help: "Publish commands with socket errors.", ConstLabels: labels}, func() float64 { return float64(run.publishSocket.Load()) }),
prometheus.NewCounterFunc(prometheus.CounterOpts{Name: "im_load_agent_received_total", Help: "Unique matching data deliveries received.", ConstLabels: labels}, func() float64 {
received, _, _, _ := run.recorder.metricCounts()
@@ -45,3 +45,20 @@ func TestWaitForCallbackQueueWaitsForProcessingCallback(t *testing.T) {
t.Fatal("wait returned before the callback finished")
}
}
func TestWaitForDeliveryQuiescenceResetsForLateDelivery(t *testing.T) {
recorder := newDeliveryRecorder("run", "a", 1)
queue := &callbackQueueMetrics{}
go func() {
time.Sleep(20 * time.Millisecond)
recorder.received.Add(1)
}()
started := time.Now()
if err := waitForDeliveryQuiescence(context.Background(), recorder, queue, 150*time.Millisecond, time.Second); err != nil {
t.Fatal(err)
}
if elapsed := time.Since(started); elapsed < 250*time.Millisecond {
t.Fatalf("quiet period was not reset after late delivery: elapsed=%s", elapsed)
}
}
+3 -1
View File
@@ -27,5 +27,7 @@
"p2p_messages_per_user": 10,
"p2p_interval": "1s",
"drain_p2p": "30s",
"drain_group": "60s"
"drain_group": "60s",
"delivery_quiet_period": "10s",
"delivery_quiet_timeout": "3m"
}
@@ -10,10 +10,14 @@
"a": ["wss://im-api.example.com/v0/channels"],
"b": ["wss://im-api.example.com/v0/channels"]
},
"dial_ips": {
"a": [],
"b": []
},
"insecure_tls": false,
"prepare_workers": 20,
"connect_ramp": "30s",
"command_timeout": "20s",
"command_timeout": "90s",
"ws_ping_interval": "20s",
"preflight_workers": 32,
"skip_p2p_preflight": false,
@@ -27,5 +31,7 @@
"p2p_messages_per_user": 10,
"p2p_interval": "1s",
"drain_p2p": "30s",
"drain_group": "60s"
"drain_group": "60s",
"delivery_quiet_period": "10s",
"delivery_quiet_timeout": "3m"
}
+59 -47
View File
@@ -10,45 +10,51 @@ import (
)
type CombinedReport struct {
RunID string `json:"run_id"`
Scenario string `json:"scenario"`
GeneratedAt time.Time `json:"generated_at"`
Agents []AgentSummary `json:"agents"`
ExpectedConnections int `json:"expected_connections"`
ReadyConnections int `json:"ready_connections"`
PublishAttempted int64 `json:"publish_attempted"`
PublishAccepted int64 `json:"publish_accepted"`
PublishRejected int64 `json:"publish_rejected"`
PublishExplicitReject int64 `json:"publish_explicitly_rejected"`
PublishOutcomeUnknown int64 `json:"publish_outcome_unknown"`
PublishErrors map[string]int64 `json:"publish_errors,omitempty"`
PublishSuccessRate float64 `json:"publish_success_rate"`
AckP95MS float64 `json:"ack_p95_ms"`
DeliveryP95MS float64 `json:"delivery_p95_ms"`
DeliveryLocalP95MS float64 `json:"delivery_local_p95_ms"`
DeliveryCrossP95MS float64 `json:"delivery_cross_machine_p95_ms"`
CrossClockSkewSamples int64 `json:"cross_machine_negative_latency_samples"`
ExpectedDeliveries int64 `json:"expected_deliveries"`
ReceivedDeliveries int64 `json:"received_deliveries"`
RealtimeLost int64 `json:"realtime_lost"`
RealtimeLostStored int64 `json:"realtime_lost_but_persisted"`
ArrivalRate float64 `json:"arrival_rate"`
LossRate float64 `json:"loss_rate"`
Duplicates int64 `json:"duplicates"`
OutOfOrder int64 `json:"out_of_order"`
OrderingViolations []OrderingViolation `json:"ordering_violations,omitempty"`
Disconnects int64 `json:"disconnects"`
DisconnectReasons map[string]int64 `json:"disconnect_reasons,omitempty"`
DisconnectSamples []DisconnectSample `json:"disconnect_samples,omitempty"`
UnexpectedMessages int64 `json:"unexpected_messages"`
HistoryChecked int64 `json:"history_checked"`
HistoryFound int64 `json:"history_found"`
HistoryUnackedChecked int64 `json:"history_unacked_observed_checked"`
HistoryUnackedFound int64 `json:"history_unacked_observed_found"`
PersistenceLost int64 `json:"persistence_lost"`
Missing []MissingDelivery `json:"missing,omitempty"`
Passed bool `json:"passed"`
FailureReasons []string `json:"failure_reasons,omitempty"`
RunID string `json:"run_id"`
Scenario string `json:"scenario"`
GeneratedAt time.Time `json:"generated_at"`
Agents []AgentSummary `json:"agents"`
ExpectedConnections int `json:"expected_connections"`
ReadyConnections int `json:"ready_connections"`
PublishAttempted int64 `json:"publish_attempted"`
PublishAccepted int64 `json:"publish_accepted"`
PublishRejected int64 `json:"publish_rejected"`
PublishExplicitReject int64 `json:"publish_explicitly_rejected"`
PublishOutcomeUnknown int64 `json:"publish_outcome_unknown"`
PublishErrors map[string]int64 `json:"publish_errors,omitempty"`
PublishCtrlObserved int64 `json:"publish_ctrl_observed"`
PublishCtrlOver20 int64 `json:"publish_ctrl_over_20s"`
PublishLateCtrl int64 `json:"publish_ctrl_late"`
PublishCtrlUnresolved int64 `json:"publish_ctrl_unresolved"`
PublishCtrlP95MS float64 `json:"publish_ctrl_p95_ms"`
CtrlObservationSamples []CtrlObservationSample `json:"ctrl_observation_samples,omitempty"`
PublishSuccessRate float64 `json:"publish_success_rate"`
AckP95MS float64 `json:"ack_p95_ms"`
DeliveryP95MS float64 `json:"delivery_p95_ms"`
DeliveryLocalP95MS float64 `json:"delivery_local_p95_ms"`
DeliveryCrossP95MS float64 `json:"delivery_cross_machine_p95_ms"`
CrossClockSkewSamples int64 `json:"cross_machine_negative_latency_samples"`
ExpectedDeliveries int64 `json:"expected_deliveries"`
ReceivedDeliveries int64 `json:"received_deliveries"`
RealtimeLost int64 `json:"realtime_lost"`
RealtimeLostStored int64 `json:"realtime_lost_but_persisted"`
ArrivalRate float64 `json:"arrival_rate"`
LossRate float64 `json:"loss_rate"`
Duplicates int64 `json:"duplicates"`
OutOfOrder int64 `json:"out_of_order"`
OrderingViolations []OrderingViolation `json:"ordering_violations,omitempty"`
Disconnects int64 `json:"disconnects"`
DisconnectReasons map[string]int64 `json:"disconnect_reasons,omitempty"`
DisconnectSamples []DisconnectSample `json:"disconnect_samples,omitempty"`
UnexpectedMessages int64 `json:"unexpected_messages"`
HistoryChecked int64 `json:"history_checked"`
HistoryFound int64 `json:"history_found"`
HistoryUnackedChecked int64 `json:"history_unacked_observed_checked"`
HistoryUnackedFound int64 `json:"history_unacked_observed_found"`
PersistenceLost int64 `json:"persistence_lost"`
Missing []MissingDelivery `json:"missing,omitempty"`
Passed bool `json:"passed"`
FailureReasons []string `json:"failure_reasons,omitempty"`
}
func runMerge(aPath, bPath, output string) error {
@@ -78,12 +84,24 @@ func runMerge(aPath, bPath, output string) error {
report.PublishErrors[category] += count
}
unknown := summary.PublishOutcomeUnknown
if unknown == 0 {
if summary.CtrlTrackingEnabled {
unknown = summary.PublishCtrlUnresolved + summary.PublishErrors["socket"]
} else if unknown == 0 {
unknown = summary.PublishErrors["ctrl_timeout"] + summary.PublishErrors["socket"]
}
explicit := summary.PublishErrors["403"] + summary.PublishErrors["502"] +
summary.PublishErrors["503"] + summary.PublishErrors["other"]
report.PublishOutcomeUnknown += unknown
report.PublishCtrlObserved += summary.PublishCtrlObserved
report.PublishCtrlOver20 += summary.PublishCtrlOver20
report.PublishLateCtrl += summary.PublishLateCtrl
report.PublishCtrlUnresolved += summary.PublishCtrlUnresolved
if remaining := 1000 - len(report.CtrlObservationSamples); remaining > 0 {
if remaining > len(summary.CtrlObservationSamples) {
remaining = len(summary.CtrlObservationSamples)
}
report.CtrlObservationSamples = append(report.CtrlObservationSamples, summary.CtrlObservationSamples[:remaining]...)
}
report.PublishExplicitReject += explicit
report.PublishRejected += explicit
report.ExpectedDeliveries += summary.ExpectedPeer + summary.ExpectedGroup
@@ -119,6 +137,7 @@ func runMerge(aPath, bPath, output string) error {
report.PublishSuccessRate = float64(report.PublishAccepted) / float64(report.PublishAttempted)
}
report.AckP95MS = mergedAckP95(report.Agents)
report.PublishCtrlP95MS = mergedHistogramP95(report.Agents, func(summary AgentSummary) HistogramSnapshot { return summary.PublishCtrlLatency })
report.DeliveryLocalP95MS = mergedHistogramP95(report.Agents, func(summary AgentSummary) HistogramSnapshot { return summary.DeliveryLatencyLocal })
report.DeliveryCrossP95MS = mergedHistogramP95(report.Agents, func(summary AgentSummary) HistogramSnapshot { return summary.DeliveryLatencyCross })
// delivery_p95_ms remains the compatibility field, but now uses only same-clock
@@ -147,13 +166,6 @@ func runMerge(aPath, bPath, output string) error {
report.FailureReasons = append(report.FailureReasons,
fmt.Sprintf("deliveries observed without ACK ledger=%d", report.UnexpectedMessages))
}
if report.AckP95MS > 500 {
report.FailureReasons = append(report.FailureReasons, fmt.Sprintf("ack p95=%.3fms expected<=500ms", report.AckP95MS))
}
if report.DeliveryP95MS > 1000 {
report.FailureReasons = append(report.FailureReasons,
fmt.Sprintf("delivery p95=%.0fms expected<=1000ms", report.DeliveryP95MS))
}
if report.PublishRejected > 0 || report.RealtimeLost > 0 || report.PersistenceLost > 0 || report.Duplicates > 0 || report.OutOfOrder > 0 || report.Disconnects > 0 || report.UnexpectedMessages > 0 {
report.FailureReasons = append(report.FailureReasons, "message correctness gate failed")
}
+12 -5
View File
@@ -13,14 +13,17 @@ func TestRunMergeComputesArrivalAndPersistenceGate(t *testing.T) {
a := AgentSummary{RunID: "run1", Scenario: "p2p", Machine: "a", ReadyConnections: 1000,
ExpectedConnections: 1000,
PublishAttempted: 10, PublishAccepted: 10, ExpectedPeer: 10, ReceivedPeer: 9, UnexpectedMessages: 42,
PublishErrors: map[string]int64{"ctrl_timeout": 3, "socket": 2, "503": 1},
RealtimeLost: 1, HistoryChecked: 10, HistoryFound: 10, Disconnects: 1,
CtrlTrackingEnabled: true, PublishCtrlObserved: 9, PublishCtrlOver20: 2, PublishLateCtrl: 2,
PublishCtrlUnresolved: 1,
PublishErrors: map[string]int64{"ctrl_timeout": 3, "socket": 2, "503": 1},
RealtimeLost: 1, HistoryChecked: 10, HistoryFound: 10, Disconnects: 1,
DisconnectReasons: map[string]int64{"timeout": 1},
DisconnectSamples: []DisconnectSample{{ReceiverMachine: "a", ReceiverIndex: 3, Category: "timeout"}}}
b := AgentSummary{RunID: "run1", Scenario: "p2p", Machine: "b", ReadyConnections: 1000,
ExpectedConnections: 1000,
PublishAttempted: 10, PublishAccepted: 10, ExpectedPeer: 10, ReceivedPeer: 10,
HistoryChecked: 10, HistoryFound: 9, PersistenceLost: 1, OutOfOrder: 1,
CtrlTrackingEnabled: true, PublishCtrlObserved: 10,
Disconnects: 2, DisconnectReasons: map[string]int64{"timeout": 1, "connection_reset": 1},
OrderingViolations: []OrderingViolation{{ReceiverMachine: "b", ReceiverIndex: 7, PreviousSeq: 12, CurrentSeq: 11}}}
aPath, bPath, reportPath := filepath.Join(dir, "a.json"), filepath.Join(dir, "b.json"), filepath.Join(dir, "report.json")
@@ -43,10 +46,14 @@ func TestRunMergeComputesArrivalAndPersistenceGate(t *testing.T) {
if report.Passed || report.PersistenceLost != 1 {
t.Fatalf("correctness gate did not fail: %+v", report)
}
if report.UnexpectedMessages != 42 || report.PublishOutcomeUnknown != 5 ||
if report.UnexpectedMessages != 42 || report.PublishOutcomeUnknown != 3 ||
report.PublishExplicitReject != 1 || report.PublishRejected != 1 {
t.Fatalf("ambiguous publish outcomes were not merged: %+v", report)
}
if report.PublishCtrlObserved != 19 || report.PublishCtrlOver20 != 2 || report.PublishLateCtrl != 2 ||
report.PublishCtrlUnresolved != 1 {
t.Fatalf("ctrl observations were not merged: %+v", report)
}
if len(report.OrderingViolations) != 1 || report.OrderingViolations[0].ReceiverIndex != 7 {
t.Fatalf("ordering violations were not merged: %+v", report.OrderingViolations)
}
@@ -93,7 +100,7 @@ func TestMergedAckP95FallsBackWhenRawSamplesAreIncomplete(t *testing.T) {
}
}
func TestRunMergeUsesSameClockDeliveryLatencyForGate(t *testing.T) {
func TestRunMergeReportsSameClockDeliveryLatency(t *testing.T) {
dir := t.TempDir()
local := HistogramSnapshot{Count: 10, MaxMS: 200, Buckets: map[string]int64{"200ms": 10}}
cross := HistogramSnapshot{Count: 10, MaxMS: 5000, Buckets: map[string]int64{"5s": 10}}
@@ -120,7 +127,7 @@ func TestRunMergeUsesSameClockDeliveryLatencyForGate(t *testing.T) {
t.Fatalf("unexpected delivery percentiles: %+v", report)
}
if report.CrossClockSkewSamples != 6 || !report.Passed {
t.Fatalf("cross-machine clock skew must not fail the same-clock latency gate: %+v", report)
t.Fatalf("cross-machine clock skew must not fail correctness acceptance: %+v", report)
}
}
+83 -43
View File
@@ -6,6 +6,7 @@ import (
"encoding/json"
"errors"
"fmt"
"net"
"os"
"sort"
"strings"
@@ -21,6 +22,7 @@ type Config struct {
PasswordEnv string `json:"password_env"`
UsersPerMachine int `json:"users_per_machine"`
Endpoints map[string][]string `json:"endpoints"`
DialIPs map[string][]string `json:"dial_ips,omitempty"`
InsecureTLS bool `json:"insecure_tls"`
PrepareWorkers int `json:"prepare_workers"`
ConnectRamp string `json:"connect_ramp"`
@@ -30,6 +32,8 @@ type Config struct {
P2PInterval string `json:"p2p_interval"`
DrainP2P string `json:"drain_p2p"`
DrainGroup string `json:"drain_group"`
DeliveryQuiet string `json:"delivery_quiet_period"`
DeliveryTimeout string `json:"delivery_quiet_timeout"`
PhonePrefix string `json:"registration_phone_prefix"`
VerifyCodeEnv string `json:"verification_code_env"`
HistoryWorkers int `json:"history_workers"`
@@ -85,6 +89,18 @@ func loadConfig(path string) (*Config, error) {
if cfg.DrainGroup == "" {
cfg.DrainGroup = "60s"
}
if cfg.DeliveryQuiet == "" {
cfg.DeliveryQuiet = "10s"
}
if _, err = configDuration(cfg.DeliveryQuiet); err != nil {
return nil, fmt.Errorf("delivery_quiet_period: %w", err)
}
if cfg.DeliveryTimeout == "" {
cfg.DeliveryTimeout = "3m"
}
if _, err = configDuration(cfg.DeliveryTimeout); err != nil {
return nil, fmt.Errorf("delivery_quiet_timeout: %w", err)
}
if cfg.HistoryWorkers <= 0 {
cfg.HistoryWorkers = 12
}
@@ -140,6 +156,11 @@ func loadConfig(path string) (*Config, error) {
if len(cfg.Endpoints[machine]) == 0 {
return nil, fmt.Errorf("at least one endpoint is required for machine %s", machine)
}
for _, ip := range cfg.DialIPs[machine] {
if net.ParseIP(strings.TrimSpace(ip)) == nil {
return nil, fmt.Errorf("invalid dial IP %q for machine %s", ip, machine)
}
}
}
if cfg.PhonePrefix != "" {
if len(cfg.PhonePrefix) != 7 || strings.Trim(cfg.PhonePrefix, "0123456789") != "" {
@@ -214,6 +235,7 @@ type AccountRecord struct {
TokenExpires time.Time `json:"token_expires,omitempty"`
P2PTopic string `json:"p2p_topic,omitempty"`
Endpoint string `json:"endpoint,omitempty"`
DialIP string `json:"-"`
}
func newManifest(cfg *Config) *Manifest {
@@ -385,49 +407,67 @@ type AcceptedMessage struct {
}
type AgentSummary struct {
RunID string `json:"run_id"`
Scenario string `json:"scenario"`
Machine string `json:"machine"`
StartedAt time.Time `json:"started_at"`
LoadEndedAt time.Time `json:"load_ended_at"`
FinishedAt time.Time `json:"finished_at"`
ExpectedConnections int `json:"expected_connections"`
ReadyConnections int `json:"ready_connections"`
PublishAttempted int64 `json:"publish_attempted"`
PublishAccepted int64 `json:"publish_accepted"`
PublishRejected int64 `json:"publish_rejected"`
PublishOutcomeUnknown int64 `json:"publish_outcome_unknown"`
PublishErrors map[string]int64 `json:"publish_errors,omitempty"`
ExpectedPeer int64 `json:"expected_peer"`
ReceivedPeer int64 `json:"received_peer"`
ExpectedEcho int64 `json:"expected_echo"`
ReceivedEcho int64 `json:"received_echo"`
ExpectedGroup int64 `json:"expected_group"`
ReceivedGroup int64 `json:"received_group"`
RealtimeLost int64 `json:"realtime_lost"`
RealtimeLostStored int64 `json:"realtime_lost_but_persisted"`
Duplicates int64 `json:"duplicates"`
OutOfOrder int64 `json:"out_of_order"`
OrderingViolations []OrderingViolation `json:"ordering_violations,omitempty"`
Disconnects int64 `json:"disconnects"`
DisconnectReasons map[string]int64 `json:"disconnect_reasons,omitempty"`
DisconnectSamples []DisconnectSample `json:"disconnect_samples,omitempty"`
UnexpectedMessages int64 `json:"unexpected_messages"`
HistoryChecked int64 `json:"history_checked"`
HistoryFound int64 `json:"history_found"`
HistoryUnackedChecked int64 `json:"history_unacked_observed_checked"`
HistoryUnackedFound int64 `json:"history_unacked_observed_found"`
PersistenceLost int64 `json:"persistence_lost"`
AckLatency HistogramSnapshot `json:"ack_latency"`
DeliveryLatency HistogramSnapshot `json:"delivery_latency"`
DeliveryLatencyLocal HistogramSnapshot `json:"delivery_latency_local"`
DeliveryLatencyCross HistogramSnapshot `json:"delivery_latency_cross_machine"`
CrossClockSkewSamples int64 `json:"cross_machine_negative_latency_samples"`
CallbackQueue CallbackQueueSnapshot `json:"callback_queue"`
Errors []string `json:"errors,omitempty"`
Missing []MissingDelivery `json:"missing,omitempty"`
PersistenceMissing []string `json:"persistence_missing,omitempty"`
AcceptedLocal []AcceptedMessage `json:"accepted_local,omitempty"`
RunID string `json:"run_id"`
Scenario string `json:"scenario"`
Machine string `json:"machine"`
StartedAt time.Time `json:"started_at"`
LoadEndedAt time.Time `json:"load_ended_at"`
FinishedAt time.Time `json:"finished_at"`
ExpectedConnections int `json:"expected_connections"`
ReadyConnections int `json:"ready_connections"`
PublishAttempted int64 `json:"publish_attempted"`
PublishAccepted int64 `json:"publish_accepted"`
PublishRejected int64 `json:"publish_rejected"`
PublishOutcomeUnknown int64 `json:"publish_outcome_unknown"`
PublishErrors map[string]int64 `json:"publish_errors,omitempty"`
CtrlTrackingEnabled bool `json:"ctrl_tracking_enabled"`
PublishCtrlObserved int64 `json:"publish_ctrl_observed"`
PublishCtrlOver20 int64 `json:"publish_ctrl_over_20s"`
PublishLateCtrl int64 `json:"publish_ctrl_late"`
PublishCtrlUnresolved int64 `json:"publish_ctrl_unresolved"`
PublishCtrlLatency HistogramSnapshot `json:"publish_ctrl_latency"`
CtrlObservationSamples []CtrlObservationSample `json:"ctrl_observation_samples,omitempty"`
ExpectedPeer int64 `json:"expected_peer"`
ReceivedPeer int64 `json:"received_peer"`
ExpectedEcho int64 `json:"expected_echo"`
ReceivedEcho int64 `json:"received_echo"`
ExpectedGroup int64 `json:"expected_group"`
ReceivedGroup int64 `json:"received_group"`
RealtimeLost int64 `json:"realtime_lost"`
RealtimeLostStored int64 `json:"realtime_lost_but_persisted"`
Duplicates int64 `json:"duplicates"`
OutOfOrder int64 `json:"out_of_order"`
OrderingViolations []OrderingViolation `json:"ordering_violations,omitempty"`
Disconnects int64 `json:"disconnects"`
DisconnectReasons map[string]int64 `json:"disconnect_reasons,omitempty"`
DisconnectSamples []DisconnectSample `json:"disconnect_samples,omitempty"`
UnexpectedMessages int64 `json:"unexpected_messages"`
HistoryChecked int64 `json:"history_checked"`
HistoryFound int64 `json:"history_found"`
HistoryUnackedChecked int64 `json:"history_unacked_observed_checked"`
HistoryUnackedFound int64 `json:"history_unacked_observed_found"`
PersistenceLost int64 `json:"persistence_lost"`
AckLatency HistogramSnapshot `json:"ack_latency"`
DeliveryLatency HistogramSnapshot `json:"delivery_latency"`
DeliveryLatencyLocal HistogramSnapshot `json:"delivery_latency_local"`
DeliveryLatencyCross HistogramSnapshot `json:"delivery_latency_cross_machine"`
CrossClockSkewSamples int64 `json:"cross_machine_negative_latency_samples"`
CallbackQueue CallbackQueueSnapshot `json:"callback_queue"`
Errors []string `json:"errors,omitempty"`
Missing []MissingDelivery `json:"missing,omitempty"`
PersistenceMissing []string `json:"persistence_missing,omitempty"`
AcceptedLocal []AcceptedMessage `json:"accepted_local,omitempty"`
}
type CtrlObservationSample struct {
Machine string `json:"machine"`
Index int `json:"index"`
ID string `json:"id"`
Code int `json:"code"`
SentAt time.Time `json:"sent_at"`
ReceivedAt time.Time `json:"received_at"`
LatencyMS float64 `json:"latency_ms"`
Late bool `json:"late"`
}
type CallbackQueueSnapshot struct {
+28
View File
@@ -3,6 +3,7 @@ package main
import (
"os"
"path/filepath"
"reflect"
"testing"
)
@@ -24,6 +25,33 @@ func TestLoadConfigAppliesBoundedHistoryDefaults(t *testing.T) {
}
}
func TestAssignAgentEndpointsDistributesDialIPsAcrossMachines(t *testing.T) {
cfg := &Config{
Endpoints: map[string][]string{"a": {"wss://api.example.test/ws"}, "b": {"wss://api.example.test/ws"}},
DialIPs: map[string][]string{"a": {"192.0.2.1", "192.0.2.2", "192.0.2.3"}, "b": {"192.0.2.1", "192.0.2.2", "192.0.2.3"}},
}
a := []AccountRecord{{Index: 1}, {Index: 2}, {Index: 3}}
b := []AccountRecord{{Index: 1}, {Index: 2}, {Index: 3}}
assignAgentEndpoints(cfg, "a", a)
assignAgentEndpoints(cfg, "b", b)
got := []string{a[0].DialIP, b[0].DialIP, a[1].DialIP, b[1].DialIP, a[2].DialIP, b[2].DialIP}
want := []string{"192.0.2.1", "192.0.2.2", "192.0.2.3", "192.0.2.1", "192.0.2.2", "192.0.2.3"}
if !reflect.DeepEqual(got, want) {
t.Fatalf("unexpected dial IP distribution: got=%v want=%v", got, want)
}
}
func TestLoadConfigRejectsInvalidDialIP(t *testing.T) {
path := filepath.Join(t.TempDir(), "config.json")
raw := []byte(`{"http_base":"https://example.test","endpoints":{"a":["wss://a"],"b":["wss://b"]},"dial_ips":{"a":["not-an-ip"]}}`)
if err := os.WriteFile(path, raw, 0o600); err != nil {
t.Fatal(err)
}
if _, err := loadConfig(path); err == nil {
t.Fatal("invalid dial IP was accepted")
}
}
func TestSingleMachineExampleUsesSixtyPercentCapacity(t *testing.T) {
cfg, err := loadConfig("config.single-machine.example.json")
if err != nil {
+107 -19
View File
@@ -7,6 +7,7 @@ import (
"encoding/json"
"errors"
"fmt"
"net"
"net/http"
"net/url"
"strconv"
@@ -40,12 +41,36 @@ type queuedDataPacket struct {
queuedAt time.Time
}
type ctrlWait struct {
ch chan ctrlPacket
kind string
sentAt time.Time
}
type timedOutCtrl struct {
kind string
sentAt time.Time
}
type ctrlObservation struct {
ID string
Kind string
Code int
SentAt time.Time
ReceivedAt time.Time
Latency time.Duration
Late bool
}
type ctrlError struct {
Code int
Text string
}
const dataCallbackQueueSize = 512
const (
dataCallbackQueueSize = 512
lateCtrlRetention = 10 * time.Minute
)
func (e *ctrlError) Error() string {
return fmt.Sprintf("ctrl code=%d text=%s", e.Code, e.Text)
@@ -57,19 +82,22 @@ type WSClient struct {
commandTimeout time.Duration
onData func(AccountRecord, dataPacket)
onDisconnect func(AccountRecord, error)
onCtrlObserved func(AccountRecord, ctrlObservation)
callbackQueue *callbackQueueMetrics
sendMu sync.Mutex
mu sync.Mutex
seq uint64
waits map[string]chan ctrlPacket
done chan struct{}
data chan queuedDataPacket
closed atomic.Bool
sendMu sync.Mutex
mu sync.Mutex
seq uint64
waits map[string]ctrlWait
timedOutCtrls map[string]timedOutCtrl
done chan struct{}
data chan queuedDataPacket
closed atomic.Bool
}
func connectWSClient(ctx context.Context, cfg *Config, account AccountRecord, apiKey, password string,
onData func(AccountRecord, dataPacket), onDisconnect func(AccountRecord, error), callbackQueue *callbackQueueMetrics) (*WSClient, error) {
onData func(AccountRecord, dataPacket), onDisconnect func(AccountRecord, error),
onCtrlObserved func(AccountRecord, ctrlObservation), callbackQueue *callbackQueueMetrics) (*WSClient, error) {
timeout, err := configDuration(cfg.CommandTimeout)
if err != nil {
return nil, err
@@ -79,6 +107,17 @@ func connectWSClient(ctx context.Context, cfg *Config, account AccountRecord, ap
return nil, err
}
dialer := *websocket.DefaultDialer
if account.DialIP != "" {
targetHost := endpointHostname(endpoint)
var netDialer net.Dialer
dialer.NetDialContext = func(ctx context.Context, network, address string) (net.Conn, error) {
host, port, splitErr := net.SplitHostPort(address)
if splitErr == nil && strings.EqualFold(host, targetHost) {
address = net.JoinHostPort(account.DialIP, port)
}
return netDialer.DialContext(ctx, network, address)
}
}
if cfg.InsecureTLS {
dialer.TLSClientConfig = &tls.Config{InsecureSkipVerify: true} // #nosec G402: explicit load-test option.
}
@@ -91,8 +130,9 @@ func connectWSClient(ctx context.Context, cfg *Config, account AccountRecord, ap
}
client := &WSClient{
account: account, conn: conn, commandTimeout: timeout, onData: onData, onDisconnect: onDisconnect,
callbackQueue: callbackQueue,
waits: make(map[string]chan ctrlPacket), done: make(chan struct{}),
onCtrlObserved: onCtrlObserved,
callbackQueue: callbackQueue,
waits: make(map[string]ctrlWait), timedOutCtrls: make(map[string]timedOutCtrl), done: make(chan struct{}),
}
client.startDataProcessor()
go client.readLoop()
@@ -136,6 +176,14 @@ func connectWSClient(ctx context.Context, cfg *Config, account AccountRecord, ap
return client, nil
}
func endpointHostname(raw string) string {
u, err := url.Parse(raw)
if err != nil {
return ""
}
return u.Hostname()
}
func connectForPrepare(ctx context.Context, cfg *Config, account AccountRecord, api *apiClient, password, verificationCode string) (*WSClient, bool, error) {
timeout, err := configDuration(cfg.CommandTimeout)
if err != nil {
@@ -153,7 +201,8 @@ func connectForPrepare(ctx context.Context, cfg *Config, account AccountRecord,
if err != nil {
return nil, false, err
}
client := &WSClient{account: account, conn: conn, commandTimeout: timeout, waits: make(map[string]chan ctrlPacket), done: make(chan struct{})}
client := &WSClient{account: account, conn: conn, commandTimeout: timeout,
waits: make(map[string]ctrlWait), timedOutCtrls: make(map[string]timedOutCtrl), done: make(chan struct{})}
go client.readLoop()
if _, err = client.command(ctx, "hi", map[string]any{"hi": map[string]any{
"id": client.nextID("hi"), "ver": "0.25", "ua": "im-pressure-prepare/1.0", "tenant": cfg.Tenant,
@@ -296,14 +345,15 @@ func ctrlInt64(raw json.RawMessage) (int64, error) {
return strconv.ParseInt(text, 10, 64)
}
func (c *WSClient) command(ctx context.Context, _ string, message map[string]any) (ctrlPacket, error) {
func (c *WSClient) command(ctx context.Context, kind string, message map[string]any) (ctrlPacket, error) {
id := nestedMessageID(message)
if id == "" {
return ctrlPacket{}, errors.New("command id is required")
}
wait := make(chan ctrlPacket, 1)
sentAt := time.Now()
c.mu.Lock()
c.waits[id] = wait
c.waits[id] = ctrlWait{ch: wait, kind: kind, sentAt: sentAt}
c.mu.Unlock()
c.sendMu.Lock()
err := c.conn.WriteJSON(message)
@@ -321,7 +371,33 @@ func (c *WSClient) command(ctx context.Context, _ string, message map[string]any
}
return ctrl, nil
case <-timer.C:
c.removeWait(id)
c.mu.Lock()
entry, pending := c.waits[id]
if pending {
delete(c.waits, id)
if entry.kind == "pub" {
c.timedOutCtrls[id] = timedOutCtrl{kind: entry.kind, sentAt: entry.sentAt}
}
}
c.mu.Unlock()
if !pending {
// The read loop won the timer race and placed the response in the
// buffered channel before removing the waiter.
ctrl := <-wait
if ctrl.Code < 200 || ctrl.Code >= 300 {
return ctrl, &ctrlError{Code: ctrl.Code, Text: ctrl.Text}
}
return ctrl, nil
}
if entry.kind == "pub" {
time.AfterFunc(lateCtrlRetention, func() {
c.mu.Lock()
if current, ok := c.timedOutCtrls[id]; ok && current.sentAt.Equal(sentAt) {
delete(c.timedOutCtrls, id)
}
c.mu.Unlock()
})
}
return ctrlPacket{}, fmt.Errorf("ctrl timeout id=%s", id)
case <-ctx.Done():
c.removeWait(id)
@@ -374,11 +450,23 @@ func (c *WSClient) readLoop() {
var ctrl ctrlPacket
if json.Unmarshal(raw, &ctrl) == nil && ctrl.ID != "" {
c.mu.Lock()
wait := c.waits[ctrl.ID]
delete(c.waits, ctrl.ID)
wait, pending := c.waits[ctrl.ID]
late, timedOut := c.timedOutCtrls[ctrl.ID]
receivedAt := time.Now()
if pending {
wait.ch <- ctrl
delete(c.waits, ctrl.ID)
} else if timedOut {
delete(c.timedOutCtrls, ctrl.ID)
}
c.mu.Unlock()
if wait != nil {
wait <- ctrl
if c.onCtrlObserved != nil && (pending && wait.kind == "pub" || timedOut && late.kind == "pub") {
kind, sentAt, isLate := wait.kind, wait.sentAt, false
if timedOut {
kind, sentAt, isLate = late.kind, late.sentAt, true
}
c.onCtrlObserved(c.account, ctrlObservation{ID: ctrl.ID, Kind: kind, Code: ctrl.Code,
SentAt: sentAt, ReceivedAt: receivedAt, Latency: receivedAt.Sub(sentAt), Late: isLate})
}
}
continue
+47 -3
View File
@@ -1,6 +1,7 @@
package main
import (
"context"
"net/http"
"net/http/httptest"
"strings"
@@ -10,6 +11,49 @@ import (
"github.com/gorilla/websocket"
)
func TestWSClientObservesCtrlAfterCommandTimeout(t *testing.T) {
server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
conn, err := (&websocket.Upgrader{}).Upgrade(w, r, nil)
if err != nil {
return
}
defer conn.Close()
var command map[string]any
if err = conn.ReadJSON(&command); err != nil {
return
}
time.Sleep(40 * time.Millisecond)
_ = conn.WriteJSON(map[string]any{"ctrl": map[string]any{"id": "pub-a-0001", "code": 202, "text": "accepted"}})
}))
defer server.Close()
conn, _, err := websocket.DefaultDialer.Dial("ws"+strings.TrimPrefix(server.URL, "http"), nil)
if err != nil {
t.Fatal(err)
}
observed := make(chan ctrlObservation, 1)
client := &WSClient{
account: AccountRecord{Machine: "a", Index: 1}, conn: conn, commandTimeout: 10 * time.Millisecond,
waits: make(map[string]ctrlWait), timedOutCtrls: make(map[string]timedOutCtrl), done: make(chan struct{}),
onCtrlObserved: func(_ AccountRecord, observation ctrlObservation) { observed <- observation },
}
go client.readLoop()
defer client.Close()
_, err = client.command(context.Background(), "pub", map[string]any{"pub": map[string]any{"id": "pub-a-0001"}})
if err == nil || !strings.Contains(err.Error(), "ctrl timeout") {
t.Fatalf("command error=%v, want ctrl timeout", err)
}
select {
case observation := <-observed:
if !observation.Late || observation.Kind != "pub" || observation.Code != 202 || observation.Latency < 10*time.Millisecond {
t.Fatalf("unexpected observation: %+v", observation)
}
case <-time.After(time.Second):
t.Fatal("late ctrl response was not observed")
}
}
func TestWSClientKeepaliveSendsPing(t *testing.T) {
ping := make(chan struct{}, 1)
server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
@@ -37,7 +81,7 @@ func TestWSClientKeepaliveSendsPing(t *testing.T) {
if err != nil {
t.Fatal(err)
}
client := &WSClient{conn: conn, waits: make(map[string]chan ctrlPacket), done: make(chan struct{})}
client := &WSClient{conn: conn, waits: make(map[string]ctrlWait), timedOutCtrls: make(map[string]timedOutCtrl), done: make(chan struct{})}
go client.readLoop()
client.startKeepalive(10 * time.Millisecond)
defer client.Close()
@@ -70,7 +114,7 @@ func TestWSClientReadLoopClosesConnectionAfterDecodeError(t *testing.T) {
if err != nil {
t.Fatal(err)
}
client := &WSClient{conn: conn, waits: make(map[string]chan ctrlPacket), done: make(chan struct{})}
client := &WSClient{conn: conn, waits: make(map[string]ctrlWait), timedOutCtrls: make(map[string]timedOutCtrl), done: make(chan struct{})}
go client.readLoop()
select {
@@ -123,7 +167,7 @@ func TestWSClientDataCallbackDoesNotBlockPong(t *testing.T) {
}
blocked := make(chan struct{})
client := &WSClient{
conn: conn, waits: make(map[string]chan ctrlPacket), done: make(chan struct{}),
conn: conn, waits: make(map[string]ctrlWait), timedOutCtrls: make(map[string]timedOutCtrl), done: make(chan struct{}),
onData: func(AccountRecord, dataPacket) { <-blocked },
}
client.startDataProcessor()