Skip to content

Commit 3c1b00f

Browse files
committed
Add detailed debug logging to TrafficSim for improved visibility
Enhanced `TrafficSim` debug logs with detailed metrics and state information, including RTT/jitter percentiles, packet sequences, and stats reporting. Introduced the `mapKeys` helper function for logging map contents.
1 parent 2c82cdc commit 3c1b00f

1 file changed

Lines changed: 25 additions & 4 deletions

File tree

probes/trafficsim.go

Lines changed: 25 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1017,6 +1017,14 @@ func percentile(vals []float64, pct int) float64 {
10171017
return sorted[idx]
10181018
}
10191019

1020+
func mapKeys(m map[string]interface{}) []string {
1021+
keys := make([]string, 0, len(m))
1022+
for k := range m {
1023+
keys = append(keys, k)
1024+
}
1025+
return keys
1026+
}
1027+
10201028
func (ts *TrafficSim) calculateStats(cycle *CycleTracker) map[string]interface{} {
10211029
cycle.mu.RLock()
10221030
defer cycle.mu.RUnlock()
@@ -1073,6 +1081,8 @@ func (ts *TrafficSim) calculateStats(cycle *CycleTracker) map[string]interface{}
10731081
p95RTT := percentile(rtts, 95)
10741082
p99RTT := percentile(rtts, 99)
10751083

1084+
log.Printf("[trafficsim] DEBUG percentile: rtts.len=%d medianRTT=%v p95RTT=%v p99RTT=%v", len(rtts), medianRTT, p95RTT, p99RTT)
1085+
10761086
// Jitter: mean absolute deviation of inter-packet delays
10771087
var jitterVals []float64
10781088
for i := 1; i < len(rtts); i++ {
@@ -1089,9 +1099,14 @@ func (ts *TrafficSim) calculateStats(cycle *CycleTracker) map[string]interface{}
10891099
jitterMedian := percentile(jitterVals, 50)
10901100
jitterP95 := percentile(jitterVals, 95)
10911101

1102+
log.Printf("[trafficsim] DEBUG jitter percentile: jitterVals.len=%d jitterMedian=%v jitterP95=%v", len(jitterVals), jitterMedian, jitterP95)
1103+
10921104
log.Infof("[trafficsim] calculateStats: totalPacketSeqs=%d receivedRtts=%d lost=%d jitterVals=%d outOfOrder=%d duplicates=%d",
10931105
total, len(rtts), lost, len(jitterVals), cycle.outOfOrder, cycle.duplicates)
10941106

1107+
log.Printf("[trafficsim] DEBUG calculateStats RETURNING: medianRTT=%v p95RTT=%v p99RTT=%v jitterMedian=%v jitterP95=%v jitterAvg=%v",
1108+
medianRTT, p95RTT, p99RTT, jitterMedian, jitterP95, jitterAvg)
1109+
10951110
return map[string]interface{}{
10961111
"lostPackets": lost,
10971112
"lossPercentage": lossPercent,
@@ -1474,6 +1489,9 @@ func (ts *TrafficSim) handleReverseAck(connection *AgentConnection, data Traffic
14741489
cycle.mu.Lock()
14751490
defer cycle.mu.Unlock()
14761491

1492+
log.Printf("[trafficsim] REVERSE handleReverseAck START: seq=%d ReverseSequence=%d cycle.StartSeq=%d len(PacketSeqs)=%d len(PacketTimes)=%d",
1493+
seq, connection.ReverseSequence, cycle.StartSeq, len(cycle.PacketSeqs), len(cycle.PacketTimes))
1494+
14771495
// Track duplicate/out-of-order
14781496
cycle.receivedSeqs[seq]++
14791497
receiveCount := cycle.receivedSeqs[seq]
@@ -1489,24 +1507,27 @@ func (ts *TrafficSim) handleReverseAck(connection *AgentConnection, data Traffic
14891507
if pt, ok := cycle.PacketTimes[seq]; ok && pt.Received == 0 {
14901508
pt.Received = recvTime
14911509
cycle.PacketTimes[seq] = pt
1492-
log.Infof("[trafficsim] REVERSE handleReverseAck seq=%d rtt=%dms PacketTimes.count=%d", seq, recvTime-pt.Sent, len(cycle.PacketTimes))
1510+
log.Printf("[trafficsim] REVERSE handleReverseAck seq=%d rtt=%dms PacketTimes.count=%d", seq, recvTime-pt.Sent, len(cycle.PacketTimes))
14931511
} else if pt, ok := cycle.PacketTimes[seq]; ok {
1494-
log.Infof("[trafficsim] REVERSE handleReverseAck seq=%d ALREADY RECEIVED rtt=%dms", seq, recvTime-pt.Sent)
1512+
log.Printf("[trafficsim] REVERSE handleReverseAck seq=%d ALREADY RECEIVED rtt=%dms", seq, recvTime-pt.Sent)
14951513
} else {
1496-
log.Infof("[trafficsim] REVERSE handleReverseAck seq=%d NOT FOUND in PacketTimes (current size=%d)", seq, len(cycle.PacketTimes))
1514+
log.Printf("[trafficsim] REVERSE handleReverseAck seq=%d NOT FOUND in PacketTimes (current size=%d) - may be from rotated cycle", seq, len(cycle.PacketTimes))
14971515
}
14981516
}
14991517

15001518
// reportCycleStats calculates and reports stats for a completed reverse cycle
15011519
func (ts *TrafficSim) reportCycleStats(cycle *CycleTracker, probeID uint, agentID uint, target string) {
15021520
if ts.DataChan == nil || !ts.isRunning() {
1521+
log.Printf("[trafficsim] REVERSE reportCycleStats skipped: DataChan=%v running=%v", ts.DataChan, ts.isRunning())
15031522
return
15041523
}
15051524

15061525
// Calculate stats using the same method as client
15071526
stats := ts.calculateStats(cycle)
15081527

1509-
log.Infof("[trafficsim] REVERSE stats map before marshal: %+v", stats)
1528+
log.Printf("[trafficsim] REVERSE reportCycleStats: probeID=%d agentID=%d target=%s statsLen=%d", probeID, agentID, target, len(stats))
1529+
log.Printf("[trafficsim] REVERSE stats map keys: %v", mapKeys(stats))
1530+
log.Debugf("[trafficsim] REVERSE stats map before marshal: %+v", stats)
15101531

15111532
payload, err := json.Marshal(stats)
15121533
if err != nil {

0 commit comments

Comments
 (0)