|
| 1 | +package latency1 |
| 2 | + |
| 3 | +import ( |
| 4 | + "context" |
| 5 | + "encoding/json" |
| 6 | + "errors" |
| 7 | + "net" |
| 8 | + "net/http" |
| 9 | + "sync" |
| 10 | + "time" |
| 11 | + |
| 12 | + "github.com/charmbracelet/log" |
| 13 | + "github.com/jellydator/ttlcache/v3" |
| 14 | + "github.com/m-lab/go/memoryless" |
| 15 | + "github.com/m-lab/go/rtx" |
| 16 | + "github.com/m-lab/msak/internal/handler" |
| 17 | + "github.com/m-lab/msak/internal/persistence" |
| 18 | + "github.com/m-lab/msak/pkg/latency1/model" |
| 19 | +) |
| 20 | + |
| 21 | +const sendDuration = 5 * time.Second |
| 22 | + |
| 23 | +var ( |
| 24 | + errorUnauthorized = errors.New("unauthorized") |
| 25 | + errorInvalidSeqN = errors.New("invalid sequence number") |
| 26 | +) |
| 27 | + |
| 28 | +// Handler is the handler for latency tests. |
| 29 | +type Handler struct { |
| 30 | + dataDir string |
| 31 | + sessions *ttlcache.Cache[string, *model.Session] |
| 32 | + sessionsMu sync.Mutex |
| 33 | +} |
| 34 | + |
| 35 | +// NewHandler returns a new handler for the UDP latency test. |
| 36 | +// It sets up a cache for sessions that writes the results to disk on item |
| 37 | +// eviction. |
| 38 | +func NewHandler(dir string, cacheTTL time.Duration) *Handler { |
| 39 | + |
| 40 | + cache := ttlcache.New( |
| 41 | + ttlcache.WithTTL[string, *model.Session](cacheTTL), |
| 42 | + ttlcache.WithDisableTouchOnHit[string, *model.Session](), |
| 43 | + ) |
| 44 | + cache.OnEviction(func(ctx context.Context, |
| 45 | + er ttlcache.EvictionReason, |
| 46 | + i *ttlcache.Item[string, *model.Session]) { |
| 47 | + log.Debug("Session expired", "id", i.Value().ID, "reason", er) |
| 48 | + |
| 49 | + // Save data to disk when the session expires. |
| 50 | + archive := i.Value().Archive() |
| 51 | + archive.EndTime = time.Now() |
| 52 | + _, err := persistence.WriteDataFile(dir, "latency1", "application", archive.ID, archive) |
| 53 | + if err != nil { |
| 54 | + log.Error("failed to write latency result", "mid", archive.ID, "error", err) |
| 55 | + return |
| 56 | + } |
| 57 | + }) |
| 58 | + |
| 59 | + go cache.Start() |
| 60 | + return &Handler{ |
| 61 | + dataDir: dir, |
| 62 | + sessions: cache, |
| 63 | + } |
| 64 | +} |
| 65 | + |
| 66 | +// Authorize verifies that the request includes a valid JWT, extracts its jti |
| 67 | +// and adds a new empty session to the sessions cache. |
| 68 | +// It returns a valid kickoff LatencyPacket for this new session in the |
| 69 | +// response body. |
| 70 | +func (h *Handler) Authorize(rw http.ResponseWriter, req *http.Request) { |
| 71 | + mid, err := handler.GetMIDFromRequest(req) |
| 72 | + if err != nil { |
| 73 | + log.Info("Received request without mid", "source", req.RemoteAddr, |
| 74 | + "error", err) |
| 75 | + rw.WriteHeader(http.StatusUnauthorized) |
| 76 | + rw.Header().Set("Connection", "Close") |
| 77 | + return |
| 78 | + } |
| 79 | + |
| 80 | + // Create a new session for this mid. |
| 81 | + session := model.NewSession(mid) |
| 82 | + h.sessionsMu.Lock() |
| 83 | + h.sessions.Set(mid, session, ttlcache.DefaultTTL) |
| 84 | + h.sessionsMu.Unlock() |
| 85 | + |
| 86 | + log.Debug("session created", "id", mid) |
| 87 | + |
| 88 | + // Create a valid kickoff packet for this session and send it in the |
| 89 | + // response body. |
| 90 | + kickoff := &model.LatencyPacket{ |
| 91 | + Type: "c2s", |
| 92 | + ID: mid, |
| 93 | + Seq: 0, |
| 94 | + } |
| 95 | + |
| 96 | + b, err := json.Marshal(kickoff) |
| 97 | + // This should never happen. |
| 98 | + rtx.Must(err, "cannot marshal LatencyPacket") |
| 99 | + |
| 100 | + _, err = rw.Write(b) |
| 101 | + if err != nil { |
| 102 | + // TODO: add Prometheus metric for write errors. |
| 103 | + return |
| 104 | + } |
| 105 | + |
| 106 | +} |
| 107 | + |
| 108 | +// Result returns a result for a given measurement id. Possible status codes |
| 109 | +// are: |
| 110 | +// - 400 if the request does not contain a mid |
| 111 | +// - 404 if the mid is not found in the sessions cache |
| 112 | +// - 500 if the session JSON cannot be marshalled |
| 113 | +func (h *Handler) Result(rw http.ResponseWriter, req *http.Request) { |
| 114 | + mid, err := handler.GetMIDFromRequest(req) |
| 115 | + if err != nil { |
| 116 | + log.Info("Received request without mid", "source", req.RemoteAddr, |
| 117 | + "error", err) |
| 118 | + rw.WriteHeader(http.StatusBadRequest) |
| 119 | + rw.Header().Set("Connection", "Close") |
| 120 | + return |
| 121 | + } |
| 122 | + |
| 123 | + h.sessionsMu.Lock() |
| 124 | + cachedResult := h.sessions.Get(mid) |
| 125 | + h.sessionsMu.Unlock() |
| 126 | + if cachedResult == nil { |
| 127 | + rw.WriteHeader(http.StatusNotFound) |
| 128 | + return |
| 129 | + } |
| 130 | + |
| 131 | + session := cachedResult.Value() |
| 132 | + b, err := json.Marshal(session.Summarize()) |
| 133 | + if err != nil { |
| 134 | + rw.WriteHeader(http.StatusInternalServerError) |
| 135 | + return |
| 136 | + } |
| 137 | + |
| 138 | + _, err = rw.Write(b) |
| 139 | + if err != nil { |
| 140 | + // TODO: add Prometheus metric for write errors. |
| 141 | + return |
| 142 | + } |
| 143 | + |
| 144 | + // Remove this session from the cache. |
| 145 | + h.sessions.Delete(mid) |
| 146 | +} |
| 147 | + |
| 148 | +// sendLoop sends UDP pings with progressive sequence numbers until the context |
| 149 | +// expires or is canceled. |
| 150 | +func (h *Handler) sendLoop(ctx context.Context, conn net.PacketConn, |
| 151 | + remoteAddr net.Addr, session *model.Session, duration time.Duration) error { |
| 152 | + seq := 0 |
| 153 | + var err error |
| 154 | + |
| 155 | + timeout, cancel := context.WithTimeout(ctx, duration) |
| 156 | + defer cancel() |
| 157 | + |
| 158 | + memoryless.Run(timeout, func() { |
| 159 | + b, marshalErr := json.Marshal(&model.LatencyPacket{ |
| 160 | + ID: session.ID, |
| 161 | + Type: "s2c", |
| 162 | + Seq: seq, |
| 163 | + LastRTT: int(session.LastRTT.Load()), |
| 164 | + }) |
| 165 | + |
| 166 | + // This should never happen, since we should always be able to marshal |
| 167 | + // a LatencyPacket struct. |
| 168 | + rtx.Must(marshalErr, "cannot marshal LatencyPacket") |
| 169 | + |
| 170 | + // Call time.Now() just before writing to the socket. The RTT will |
| 171 | + // include the ping packet's write time. This is intentional. |
| 172 | + sendTime := time.Now() |
| 173 | + // As the kernel's socket buffers are usually much larger than the |
| 174 | + // packets we send here, calling conn.WriteTo is expected to take a |
| 175 | + // negligible time. |
| 176 | + n, writeErr := conn.WriteTo(b, remoteAddr) |
| 177 | + if writeErr != nil { |
| 178 | + err = writeErr |
| 179 | + cancel() |
| 180 | + return |
| 181 | + } |
| 182 | + if n != len(b) { |
| 183 | + err = errors.New("partial write") |
| 184 | + cancel() |
| 185 | + return |
| 186 | + } |
| 187 | + |
| 188 | + // Update the SendTimes map after a successful write. |
| 189 | + session.SendTimesMu.Lock() |
| 190 | + session.SendTimes = append(session.SendTimes, sendTime) |
| 191 | + session.SendTimesMu.Unlock() |
| 192 | + |
| 193 | + // Add this packet to the Results slice. Results are "lost" until a |
| 194 | + // reply is received from the server. |
| 195 | + session.RoundTrips = append(session.RoundTrips, model.RoundTrip{ |
| 196 | + Lost: true, |
| 197 | + }) |
| 198 | + |
| 199 | + seq++ |
| 200 | + |
| 201 | + log.Debug("packet sent", "len", n, "id", session.ID, "seq", seq) |
| 202 | + |
| 203 | + }, memoryless.Config{ |
| 204 | + // Using randomized intervals allows to detect cyclic network |
| 205 | + // behaviors where a fixed interval could align to the cycle. |
| 206 | + Expected: 25 * time.Millisecond, |
| 207 | + Min: 10 * time.Millisecond, |
| 208 | + Max: 40 * time.Millisecond, |
| 209 | + }) |
| 210 | + return err |
| 211 | +} |
| 212 | + |
| 213 | +// processPacket processes a single UDP latency packet. |
| 214 | +func (h *Handler) processPacket(conn net.PacketConn, remoteAddr net.Addr, |
| 215 | + packet []byte, recvTime time.Time) error { |
| 216 | + // Attempt to unmarshal the packet. |
| 217 | + var m model.LatencyPacket |
| 218 | + err := json.Unmarshal(packet, &m) |
| 219 | + if err != nil { |
| 220 | + return err |
| 221 | + } |
| 222 | + |
| 223 | + // Check if this is a known session. |
| 224 | + h.sessionsMu.Lock() |
| 225 | + cachedResult := h.sessions.Get(m.ID) |
| 226 | + h.sessionsMu.Unlock() |
| 227 | + if cachedResult == nil { |
| 228 | + return errorUnauthorized |
| 229 | + } |
| 230 | + |
| 231 | + session := cachedResult.Value() |
| 232 | + |
| 233 | + // If this message's type is s2c, it was a server ping echoed back by the |
| 234 | + // client. Store it in the session's result and compute the RTT. |
| 235 | + if m.Type == "s2c" { |
| 236 | + session.SendTimesMu.Lock() |
| 237 | + defer session.SendTimesMu.Unlock() |
| 238 | + if m.Seq >= len(session.SendTimes) { |
| 239 | + // TODO: Add Prometheus metric. |
| 240 | + log.Info("received packet with valid mid and invalid seq number", |
| 241 | + "mid", m.ID, |
| 242 | + "seq", m.Seq, |
| 243 | + "addr", remoteAddr.String()) |
| 244 | + return errorInvalidSeqN |
| 245 | + } |
| 246 | + |
| 247 | + rtt := recvTime.Sub(session.SendTimes[m.Seq]).Microseconds() |
| 248 | + session.LastRTT.Store(rtt) |
| 249 | + session.RoundTrips[m.Seq].RTT = int(rtt) |
| 250 | + session.RoundTrips[m.Seq].Lost = false |
| 251 | + |
| 252 | + log.Debug("received pong, updating result", "mid", session.ID, |
| 253 | + "result", session.RoundTrips[m.Seq]) |
| 254 | + // TODO: prometheus metric |
| 255 | + return nil |
| 256 | + } |
| 257 | + |
| 258 | + // If this message's type is c2s, it's a kickoff packet. Record |
| 259 | + // local/remote addresses and trigger the send loop. |
| 260 | + if m.Type == "c2s" { |
| 261 | + session.StartedMu.Lock() |
| 262 | + defer session.StartedMu.Unlock() |
| 263 | + if !session.Started { |
| 264 | + session.Started = true |
| 265 | + session.Client = remoteAddr.String() |
| 266 | + session.Server = conn.LocalAddr().String() |
| 267 | + go h.sendLoop(context.Background(), conn, remoteAddr, session, |
| 268 | + sendDuration) |
| 269 | + } |
| 270 | + } |
| 271 | + |
| 272 | + return nil |
| 273 | +} |
| 274 | + |
| 275 | +// ProcessPacketLoop is the main packet processing loop. For each incoming |
| 276 | +// packet, it records its timestamp and acts depending on the packet type. |
| 277 | +func (h *Handler) ProcessPacketLoop(conn net.PacketConn) { |
| 278 | + log.Info("Accepting UDP packets...") |
| 279 | + buf := make([]byte, 1024) |
| 280 | + for { |
| 281 | + n, addr, err := conn.ReadFrom(buf) |
| 282 | + if err != nil { |
| 283 | + log.Error("error while reading UDP packet", "err", err) |
| 284 | + continue |
| 285 | + } |
| 286 | + // The receive time should be recorded as soon as possible after |
| 287 | + // reading the packet, to improve accuracy. |
| 288 | + recvTime := time.Now() |
| 289 | + log.Debug("received UDP packet", "addr", addr, "n", n, "data", string(buf[:n])) |
| 290 | + err = h.processPacket(conn, addr, buf[:n], recvTime) |
| 291 | + if err != nil { |
| 292 | + log.Debug("failed to process packet", |
| 293 | + "err", err, |
| 294 | + "addr", addr.String()) |
| 295 | + } |
| 296 | + } |
| 297 | +} |
0 commit comments