more request logging (note: changes some log messages and properties)

server/node.go

@@ -77,7 +77,7 @@ func (n *Node) startProxyWorker(id int32, cancelContext context.Context) {
 
 			// Send response
 			_log.Debug("request processed, sending response")
-			sent := req.SendResponse(SimResponse{Payload: payload, NodeURI: n.URI, SimDuration: requestDuration})
+			sent := req.SendResponse(SimResponse{Payload: payload, NodeURI: n.URI, SimDuration: requestDuration, SimAt: timeBeforeProxy})
 			if !sent {
 				_log.Errorw("couldn't send node response to client (SendResponse returned false)", "secSinceRequestCreated", time.Since(req.CreatedAt).Seconds())
 			}

server/types.go

@@ -43,4 +43,5 @@ type SimResponse struct {
 	ShouldRetry bool // When response has an error, whether it should be retried
 	NodeURI     string
 	SimDuration time.Duration
+	SimAt       time.Time // time when proxying started
 }

server/webserver.go

@@ -110,21 +110,38 @@ func (s *Webserver) HandleQueueRequest(w http.ResponseWriter, req *http.Request)
 		return
 	}
 
-	lenFastTrack, lenHighPrio, lenLowPrio := s.prioQueue.Len()
-	log.Infow("Request added to queue. prioQueue size:", "requestIsHighPrio", isHighPrio, "requestIsFastTrack", isFastTrack, "fastTrack", lenFastTrack, "highPrio", lenHighPrio, "lowPrio", lenLowPrio)
+	startQueueSizeFastTrack, startQueueSizeHighPrio, startQueueSizeLowPrio := s.prioQueue.Len()
+	startItemQueueSize := startQueueSizeLowPrio
+	if isFastTrack {
+		startItemQueueSize = startQueueSizeFastTrack
+	} else if isHighPrio {
+		startItemQueueSize = startQueueSizeHighPrio
+	}
+
+	log = log.With(
+		"requestIsHighPrio", isHighPrio,
+		"requestIsFastTrack", isFastTrack,
+		"payloadSize", len(body),
+
+		"startQueueSize", s.prioQueue.NumRequests(),
+		"startQueueSizeFastTrack", startQueueSizeFastTrack,
+		"startQueueSizeHighPrio", startQueueSizeHighPrio,
+		"startQueueSizeLowPrio", startQueueSizeLowPrio,
+	)
+	log.Infow("Request added to queue")
 
 	// Wait for response or cancel
 	for {
 		select {
 		case <-ctx.Done(): // if user closes connection, cancel the simreq
-			log.Infow("client closed the connection prematurely", "err", ctx.Err(), "queueItems", s.prioQueue.NumRequests(), "payloadSize", len(body), "requestTries", simReq.Tries, "requestCancelled", simReq.Cancelled)
+			log.Infow("Client closed the connection prematurely", "err", ctx.Err(), "queueItems", s.prioQueue.NumRequests(), "payloadSize", len(body), "requestTries", simReq.Tries, "requestCancelled", simReq.Cancelled)
 			if ctx.Err() != nil {
 				simReq.Cancelled = true
 			}
 			return
 		case resp := <-simReq.ResponseC:
 			if resp.Error != nil {
-				log.Infow("HandleSim error", "err", resp.Error, "try", simReq.Tries, "shouldRetry", resp.ShouldRetry, "nodeURI", resp.NodeURI)
+				log.Infow("Request proxying failed", "err", resp.Error, "try", simReq.Tries, "shouldRetry", resp.ShouldRetry, "nodeURI", resp.NodeURI)
 				if simReq.Tries < RequestMaxTries && resp.ShouldRetry {
 					s.prioQueue.Push(simReq)
 					continue
@@ -148,25 +165,41 @@ func (s *Webserver) HandleQueueRequest(w http.ResponseWriter, req *http.Request)
 				resp.StatusCode = http.StatusOK
 			}
 
+			queueDurationUs := resp.SimAt.Sub(startTime).Microseconds()
+			endQueueSizeFastTrack, endQueueSizeHighPrio, endQueueSizeLowPrio := s.prioQueue.Len()
+			endItemQueueSize := endQueueSizeLowPrio
+			if isFastTrack {
+				endItemQueueSize = endQueueSizeFastTrack
+			} else if isHighPrio {
+				endItemQueueSize = endQueueSizeHighPrio
+			}
+
+			// Add additional profiling information about this request as part of the response headers
+			w.Header().Set("X-PrioLB-QueueDurationUs", fmt.Sprint(queueDurationUs))
+			w.Header().Set("X-PrioLB-SimDurationUs", fmt.Sprint(resp.SimDuration.Microseconds()))
+			w.Header().Set("X-PrioLB-TotalDurationUs", fmt.Sprint(time.Since(startTime).Microseconds()))
+			w.Header().Set("X-PrioLB-QueueSizeStart", fmt.Sprint(startItemQueueSize))
+			w.Header().Set("X-PrioLB-QueueSizeEnd", fmt.Sprint(endItemQueueSize))
+
+			// Send the response
 			w.Header().Set("Content-Type", "application/json")
 			w.WriteHeader(resp.StatusCode)
 			w.Write(resp.Payload)
 
-			lenFastTrack, lenHighPrio, lenLowPrio := s.prioQueue.Len()
 			log.Infow("Request completed",
-				"durationMs", time.Since(startTime).Milliseconds(),
-				"durationUs", time.Since(startTime).Microseconds(),
-				"simDurationUs", resp.SimDuration.Microseconds(),
-				"requestIsHighPrio", isHighPrio,
-				"requestIsFastTrack", isFastTrack,
-				"payloadSize", len(body),
+				"durationMs", time.Since(startTime).Milliseconds(), // full request duration in milliseconds
+				"durationUs", time.Since(startTime).Microseconds(), // full request duration in microseconds
+				"simDurationUs", resp.SimDuration.Microseconds(), // time only for simulation (proxying)
+				"queueDurationUs", queueDurationUs, // time until request was proxied (queue wait time)
+
 				"statusCode", resp.StatusCode,
 				"nodeURI", resp.NodeURI,
 				"requestTries", simReq.Tries,
-				"queueItems", s.prioQueue.NumRequests(),
-				"queueItemsFastTrack", lenFastTrack,
-				"queueItemsHighPrio", lenHighPrio,
-				"queueItemsLowPrio", lenLowPrio,
+
+				"endQueueSize", s.prioQueue.NumRequests(),
+				"endQueueSizeFastTrack", endQueueSizeFastTrack,
+				"endQueueSizeHighPrio", endQueueSizeHighPrio,
+				"endQueueSizeLowPrio", endQueueSizeLowPrio,
 			)
 			return
 		}