Clean up sd logging

[scrye]

Fixes #1966

---

This change is 

[lukedirtwalker]

In general I think there are a lot of warning that I think could be promoted to error. If we can't reply to a client it is IMO an error not just a warning. (I'm aware that this is just partially related to this PR)

Re Prefix: I think the prefix[SCIOND:..] is nice. Maybe we could drop the SCIOND part? Also I think it would make sense to have the prefix consistently applied, e.g. now it is only on some messages:

2018-10-24 06:11:26.031287+0000 [DBUG] [SCIOND:PathRequestHandler] Received request debug_id=852a035f request=0-0->1-ff00:0:132 count=5 flags={Refresh:false}
2018-10-24 06:11:26.031379+0000 [DBUG] Requesting segments debug_id=852a035f
2018-10-24 06:11:26.035745+0000 [DBUG] Segments inserted in DB debug_id=852a035f segments=[b5f9b96a829e]

If we'd have it everywhere we could easily filter by handler.

Re commit message: We often have the service prefix, I think that would make sense here as well: SD: Clean up logging

Reviewed 3 of 3 files at r1.
Reviewable status: all files reviewed, 6 unresolved discussions (waiting on @scrye, @shitz, and @kormat)

---

go/sciond/internal/fetcher/fetcher.go, line 435 at r1 (raw file):

	reply, err := f.getSegmentsFromNetwork(ctx, req, ps)
	if err != nil {
		f.logger.Warn("Unable to retrieve paths from network", "err", err)

I'd say this should be logged as an error?

---

go/sciond/internal/fetcher/fetcher.go, line 488 at r1 (raw file):

		RawDstIA: req.Dst,
	}
	f.logger.Debug("Requesting segments")

I'd print the ps
f.logger.Debug("Requesting segments", "ps", ps)

---

go/sciond/internal/servers/handlers.go, line 64 at r1 (raw file):

request", fmt.Sprintf("%v->%v", pld.PathReq.Src, pld.PathReq.Dst),

Why not just create String() method on PathReq. Then simplifies this to "req", pld.PathReq ?

---

go/sciond/internal/servers/handlers.go, line 69 at r1 (raw file):

	getPathsReply, err := h.Fetcher.GetPaths(workCtx, &pld.PathReq, DefaultEarlyReply, logger)
	if err != nil {
		logger.Warn("[SCIOND:PathRequestHandler] Unable to get paths", "err", err)

I'd say this should be an error

---

go/sciond/internal/servers/handlers.go, line 87 at r1 (raw file):

	if err := transport.SendMsgTo(ctx, b, src); err != nil {
		logger.Warn("[SCIOND:PathRequestHandler] Unable to reply to client",
			"client", src, "err", err)

I'd say this should be an error

---

go/sciond/internal/servers/handlers.go, line 154 at r1 (raw file):

	defer cancelF()
	if err := transport.SendMsgTo(ctx, b, src); err != nil {
		logger.Warn("Unable to reply to client", "client", src, "err", err)

Error?

[kormat]

Reviewed 3 of 3 files at r1.
Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @scrye and @shitz)

---

go/sciond/internal/servers/handlers.go, line 87 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

I'd say this should be an error

I think warning is more appropriate for these, if the default assumption is that it's the client's fault (by exiting, or just closing the socket, etc).

---

go/sciond/internal/servers/handlers.go, line 92 at r1 (raw file):

	logger.Debug("[SCIOND:PathRequestHandler] Replied with paths", "num_paths",
		len(getPathsReply.Entries))
	logger.Trace("[SCIOND:PathRequestHandler] Full reply", "paths", getPathsReply)

The formatting of sciond.PathReply is awful - if would help a lot if you could add a string method to it.

[scrye]

Discussed this a bit with @kormat and for brevity / simplicity we'll use only the debug_id for now, and see if it is sufficient handler context.

If debugging is too difficult, we'll add prefix support.

Reviewable status: 1 of 4 files reviewed, 7 unresolved discussions (waiting on @kormat, @lukedirtwalker, @scrye, and @shitz)

---

go/sciond/internal/fetcher/fetcher.go, line 435 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

I'd say this should be logged as an error?

Done.

---

go/sciond/internal/fetcher/fetcher.go, line 488 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

I'd print the ps
f.logger.Debug("Requesting segments", "ps", ps)

Done.

---

go/sciond/internal/servers/handlers.go, line 64 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

request", fmt.Sprintf("%v->%v", pld.PathReq.Src, pld.PathReq.Dst),

Why not just create String() method on PathReq. Then simplifies this to "req", pld.PathReq ?

Done.

---

go/sciond/internal/servers/handlers.go, line 69 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

I'd say this should be an error

Done.

---

go/sciond/internal/servers/handlers.go, line 87 at r1 (raw file):

Previously, kormat (Stephen Shirley) wrote…

I think warning is more appropriate for these, if the default assumption is that it's the client's fault (by exiting, or just closing the socket, etc).

I don't think there's much difference between warning and error here. I left it as Warn, as it's mostly harmless situations like a client going away to soon (e.g., the python end to end test).

---

go/sciond/internal/servers/handlers.go, line 92 at r1 (raw file):
Reformatted to:

2018-10-24 12:42:13.082249+0000 [DBUG] Full reply debug_id=168fda30 paths=
>  ErrorCode=OK
>  Hops: [1-ff00:0:110 63>46 1-ff00:0:130 99>39 1-ff00:0:112] Mtu: 1450 NextHop=[127.0.0.66]:30075
>  Hops: [1-ff00:0:110 63>46 1-ff00:0:130 18>27 1-ff00:0:111 25>38 1-ff00:0:112] Mtu: 1450 NextHop=[127.0.0.66]:30075
>  Hops: [1-ff00:0:110 86>76 1-ff00:0:120 61>71 1-ff00:0:130 99>39 1-ff00:0:112] Mtu: 1450 NextHop=[127.0.0.65]:30088
>  Hops: [1-ff00:0:110 86>76 1-ff00:0:120 62>34 1-ff00:0:111 25>38 1-ff00:0:112] Mtu: 1450 NextHop=[127.0.0.65]:30088
>  Hops: [1-ff00:0:110 86>76 1-ff00:0:120 61>71 1-ff00:0:130 18>27 1-ff00:0:111 25>38 1-ff00:0:112] Mtu: 1450 NextHop=[127.0.0.65]:30088
>  Hops: [1-ff00:0:110 63>46 1-ff00:0:130 71>61 1-ff00:0:120 62>34 1-ff00:0:111 25>38 1-ff00:0:112] Mtu: 1450 NextHop=[127.0.0.66]:30075

---

go/sciond/internal/servers/handlers.go, line 154 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

Error?

See discussion in other item.

[lukedirtwalker]

Reviewed 3 of 3 files at r2.
Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @kormat and @shitz)

[kormat]

Reviewed 3 of 3 files at r2.
Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @scrye and @shitz)

---

go/lib/sciond/types.go, line 158 at r2 (raw file):

		strEntries[i] = r.Entries[i].String()
	}
	return fmt.Sprintf("ErrorCode=%v\n%v", r.ErrorCode, strings.Join(strEntries, "\n"))

Indent by 2 spaces after a newline.

[scrye]

Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @kormat and @shitz)

---

go/lib/sciond/types.go, line 158 at r2 (raw file):

Previously, kormat (Stephen Shirley) wrote…

Indent by 2 spaces after a newline.

Done.

[kormat]

Reviewed 1 of 1 files at r3.
Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @shitz)