segfetcher: Improve logging / documentation

scionproto · Aug 27, 2019 · 3b9a4dd · 3b9a4dd
1 parent 6e17dc3
commit 3b9a4dd
Show file tree

Hide file tree

Showing 3 changed files with 14 additions and 8 deletions.
diff --git a/go/lib/infra/modules/segfetcher/fetcher.go b/go/lib/infra/modules/segfetcher/fetcher.go
@@ -110,11 +110,15 @@ func (f *Fetcher) FetchSegs(ctx context.Context, req Request) (Segments, error)
 			break
 		}
 		if i > 3 {
-			log.FromCtx(ctx).Crit("No convergence in looking up", "i", i)
+			log.FromCtx(ctx).Error("No convergence in looking up", "i", i)
 			return segs, common.NewBasicError("Segment lookup doesn't converge", nil,
 				"iterations", i)
 		}
-		reqCtx, cancelF := context.WithTimeout(ctx, 2*time.Second)
+		// XXX(lukedirtwalker): Optimally we wouldn't need a different timeout
+		// here. The problem is that revocations can't be differentiated from
+		// timeouts. And having 10s timeouts plays really bad together with
+		// revocations. See also: https://github.com/scionproto/scion/issues/3052
+		reqCtx, cancelF := context.WithTimeout(ctx, 3*time.Second)
 		replies := f.Requester.Request(reqCtx, reqSet)
 		// TODO(lukedirtwalker): We need to have early trigger for the last request.
 		if err := f.waitOnProcessed(ctx, replies); err != nil {

diff --git a/go/path_srv/internal/segreq/handler.go b/go/path_srv/internal/segreq/handler.go
@@ -76,19 +76,21 @@ func (h *handler) Handle(request *infra.Request) *infra.HandlerResult {
 	}
 	revs, err := revcache.RelevantRevInfos(ctx, h.revCache, segs.Up, segs.Core, segs.Down)
 	if err != nil {
-		logger.Error("[segReqHandler] Failed to find relevant revocations for reply", "err", err)
+		logger.Warn("[segReqHandler] Failed to find relevant revocations for reply", "err", err)
 		// the client might still be able to use the segments so continue here.
 	}
-	err = rw.SendSegReply(ctx, &path_mgmt.SegReply{
+	reply := &path_mgmt.SegReply{
 		Req: segReq,
 		Recs: &path_mgmt.SegRecs{
 			Recs:      segsToRecs(ctx, segs),
 			SRevInfos: revs,
 		},
-	})
+	}
+	err = rw.SendSegReply(ctx, reply)
 	if err != nil {
 		return infra.MetricsErrInternal
 	}
+	logger.Debug("[segReqHandler] Replied with segments", "segs", len(reply.Recs.Recs))
 	return infra.MetricsResultOk
 }
 

diff --git a/go/path_srv/internal/segreq/helpers.go b/go/path_srv/internal/segreq/helpers.go
@@ -50,7 +50,7 @@ func segsToRecs(ctx context.Context, segs segfetcher.Segments) []*seg.Meta {
 		}
 		s := segs.Up[i]
 		logger.Trace(fmt.Sprintf("[segReqHandler:collectSegs] up %v -> %v",
-			s.FirstIA(), s.LastIA()))
+			s.FirstIA(), s.LastIA()), "seg", s.GetLoggingID())
 		recs = append(recs, seg.NewMeta(s, proto.PathSegType_up))
 	}
 	for i := range segs.Core {
@@ -59,7 +59,7 @@ func segsToRecs(ctx context.Context, segs segfetcher.Segments) []*seg.Meta {
 		}
 		s := segs.Core[i]
 		logger.Trace(fmt.Sprintf("[segReqHandler:collectSegs] core %v -> %v",
-			s.FirstIA(), s.LastIA()))
+			s.FirstIA(), s.LastIA()), "seg", s.GetLoggingID())
 		recs = append(recs, seg.NewMeta(s, proto.PathSegType_core))
 	}
 	for i := range segs.Down {
@@ -68,7 +68,7 @@ func segsToRecs(ctx context.Context, segs segfetcher.Segments) []*seg.Meta {
 		}
 		s := segs.Down[i]
 		logger.Trace(fmt.Sprintf("[segReqHandler:collectSegs] down %v -> %v",
-			s.FirstIA(), s.LastIA()))
+			s.FirstIA(), s.LastIA()), "seg", s.GetLoggingID())
 		recs = append(recs, seg.NewMeta(s, proto.PathSegType_down))
 	}
 	return recs