dispatcher: debug log unroutable SCMP error packets

[lukedirtwalker]

Instead of logging at error level only log unroutbale SCMP error packets on Debug level. For some of the usecases there is simply not much we can do, so we shouldn't care too much and fload the error log.

[jiceatscion]

This change is 

[jiceatscion]

Reviewed 1 of 1 files at r1, all commit messages.
Reviewable status: all files reviewed, 3 unresolved discussions (waiting on @JordiSubira and @lukedirtwalker)

---

dispatcher/dispatcher.go line 200 at r1 (raw file):

	case slayers.LayerTypeSCMP:
		// send response to BR
		switch s.scmpLayer.TypeCode.Type() {

We get the typecode twice, in 3 places. Maybe it's worth storing it in a var and pass it to the getxxxDst() functions?

---

dispatcher/dispatcher.go line 210 at r1 (raw file):

			}
			if dstAddrPort.Addr().Unmap().Compare(underlay.Unmap()) != 0 {
				log.Error("UDP/IP addr destination different from UDP/SCION addr",

Is the explicit String() necessary here? The log functions do the string conversion themselves if/when logging happens, no? Also, I don't think the ":" at the end of the keys is redundant, since the logging functions do their own "key:value" formatting.

---

dispatcher/dispatcher.go line 225 at r1 (raw file):

			}
			if dstAddrPort.Addr().Unmap().Compare(underlay.Unmap()) != 0 {
				log.Debug("UDP/IP addr destination different from UDP/SCION addr",

ditto

[lukedirtwalker]

Reviewable status: all files reviewed, 3 unresolved discussions (waiting on @jiceatscion and @JordiSubira)

---

dispatcher/dispatcher.go line 200 at r1 (raw file):

Previously, jiceatscion wrote…

We get the typecode twice, in 3 places. Maybe it's worth storing it in a var and pass it to the getxxxDst() functions?

Done.

---

dispatcher/dispatcher.go line 210 at r1 (raw file):

Previously, jiceatscion wrote…

Is the explicit String() necessary here? The log functions do the string conversion themselves if/when logging happens, no? Also, I don't think the ":" at the end of the keys is redundant, since the logging functions do their own "key:value" formatting.

I blindly copied this. Done.

---

dispatcher/dispatcher.go line 225 at r1 (raw file):

Previously, jiceatscion wrote…

ditto

Done.

[jiceatscion]

Reviewed 1 of 1 files at r2, all commit messages.
Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @JordiSubira)

[JordiSubira]

I agree some of the log levels on this file should be reconsidered. Probably there are more than the ones we are discussing here (see inline comments)

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @lukedirtwalker)

---

dispatcher/dispatcher.go line 210 at r2 (raw file):

			}
			if dstAddrPort.Addr().Unmap().Compare(underlay.Unmap()) != 0 {
				log.Error("UDP/IP addr destination different from UDP/SCION addr",

This error is equivalent to the one in the default case, so IMO it should be equally treated.

---

dispatcher/dispatcher.go line 225 at r2 (raw file):

			}
			if dstAddrPort.Addr().Unmap().Compare(underlay.Unmap()) != 0 {
				log.Debug("UDP/IP addr destination different from UDP/SCION addr",

Indeed this shouldn't be log.Error because this error may be caused by a misbehaving/malicious sender. I am wondering actually whether "Debug" is the right level here. For instance, some users may want to log this "warnings" about potential misbehaving senders. We don't have a "Warn" level, perhaps this should be desirable for this type of errors? We may also investigate this in a separate PR.

---

dispatcher/dispatcher.go line 235 at r2 (raw file):

		dstAddrPort, err = s.getDstSCIONUDP()
		if err != nil {
			log.Error("Getting destination for SCION/UDP message", "err", err)

We may also want to change this log level

---

dispatcher/dispatcher.go line 239 at r2 (raw file):

		}
		if dstAddrPort.Addr().Unmap().Compare(underlay.Unmap()) != 0 {
			log.Error("UDP/IP addr destination different from UDP/SCION addr",

This error is equivalent to the one in the "LayerTypeSCMP" case, so IMO it should be equally treated.

[jiceatscion]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @JordiSubira and @lukedirtwalker)

---

dispatcher/dispatcher.go line 225 at r2 (raw file):

Previously, JordiSubira wrote…

Indeed this shouldn't be log.Error because this error may be caused by a misbehaving/malicious sender. I am wondering actually whether "Debug" is the right level here. For instance, some users may want to log this "warnings" about potential misbehaving senders. We don't have a "Warn" level, perhaps this should be desirable for this type of errors? We may also investigate this in a separate PR.

The problem with logging it under normal operations is that it exposes the system to being DOS'd by deliberately triggering the costly logging code. It might be more appropriate to have metrics for potentially malicious behavior. That would be less expensive than logging, would it not?

[JordiSubira]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @jiceatscion and @lukedirtwalker)

---

dispatcher/dispatcher.go line 225 at r2 (raw file):

Previously, jiceatscion wrote…

The problem with logging it under normal operations is that it exposes the system to being DOS'd by deliberately triggering the costly logging code. It might be more appropriate to have metrics for potentially malicious behavior. That would be less expensive than logging, would it not?

Well, several software solutions log this type of events (for example, apache-http access logs) and they are consumed by other backend services such as splunk log ingestor. tbh, I haven't investigated how good the log implementation we are using is, for instance deferring costly operations and so. Of course, we can have alternatives to logging, but we don't have one right now for this type of events.

[jiceatscion]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @JordiSubira and @lukedirtwalker)

---

dispatcher/dispatcher.go line 225 at r2 (raw file):

Previously, JordiSubira wrote…

Well, several software solutions log this type of events (for example, apache-http access logs) and they are consumed by other backend services such as splunk log ingestor. tbh, I haven't investigated how good the log implementation we are using is, for instance deferring costly operations and so. Of course, we can have alternatives to logging, but we don't have one right now for this type of events.

So, definitely more conversation required. Let's not block this PR over that. File an issue and leave the log level here as it is for now?

[JordiSubira]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @jiceatscion and @lukedirtwalker)

---

dispatcher/dispatcher.go line 225 at r2 (raw file):

Previously, jiceatscion wrote…

So, definitely more conversation required. Let's not block this PR over that. File an issue and leave the log level here as it is for now?

Sure, we can move this discussion somewhere else and perhaps Roman's observation about the efficiency of our wrapper calls around the log (I saw the comment even it doesn't show up on the discussion, don't know why...)

[romshark]

@JordiSubira

Roman's observation about the efficiency of our wrapper calls around the log (I saw the comment even it doesn't show up on the discussion, don't know why...)

I made a stupid mistake while measuring and measured it wrong :)

Hence removed the comment to avoid misleading people.

the Go compiler seems to be able to optimize most of the Debug overhead away somehow (no variadic params slice allocation when debug logs are disabled and even if Debug is //go:noinline'ed)

I won't dig deeper since I think I would first want to gather profiles from the router before trying to optimize anything by assuming cost without having the numbers

[jiceatscion]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @JordiSubira and @lukedirtwalker)

---

dispatcher/dispatcher.go line 225 at r2 (raw file):

Previously, JordiSubira wrote…

Sure, we can move this discussion somewhere else and perhaps Roman's observation about the efficiency of our wrapper calls around the log (I saw the comment even it doesn't show up on the discussion, don't know why...)

Filed #4685 for that purpose.