Enhancement: Avoid log flooding with useless negative rtt messages

[gjaekel]

In our production environment, messages like

20201217-130426.066 INFO  [Thread-86] [o.j.o.p.o.JitsiJvbWrapper] WARNING: [1077] [confId=4a2658cf6c0c1ad6 epId=e4bbf339 gid=354370 stats_id=Brittany-aNP [email protected]] EndpointConnectionStats.processReportBlock#153: Negative rtt value: -1.0101310000000012 ms, remote processing delay was PT0.176010131S (11535), srSentTime was 2020-12-17T12:04:25.890Z, received time was 2020-12-17T12:04:26.065Z
20201217-130427.006 INFO  [Thread-86] [o.j.o.p.o.JitsiJvbWrapper] WARNING: [1076] [confId=4a2658cf6c0c1ad6 epId=e4bbf339 gid=354370 stats_id=Brittany-aNP conf_name=************************] EndpointConnectionStats.processReportBlock#153: Negative rtt value: -1.0093990000000304 ms, remote processing delay was PT0.719009399S (47121), srSentTime was 2020-12-17T12:04:26.287Z, received time was 2020-12-17T12:04:27.005Z
20201217-130427.012 INFO  [Thread-86] [o.j.o.p.o.JitsiJvbWrapper] WARNING: [1071] [confId=4a2658cf6c0c1ad6 epId=e4bbf339 gid=354370 stats_id=Brittany-aNP conf_name=************************] EndpointConnectionStats.processReportBlock#153: Negative rtt value: -1.0092769999999973 ms, remote processing delay was PT1.122009277S (73532), srSentTime was 2020-12-17T12:04:25.890Z, received time was 2020-12-17T12:04:27.011Z
20201217-130427.117 INFO  [Thread-86] [o.j.o.p.o.JitsiJvbWrapper] WARNING: [1065] [confId=5b58f5db317c7912 epId=576f776c gid=140178 stats_id=Carlos-8a0 conf_name=************************] EndpointConnectionStats.processReportBlock#153: Negative rtt value: -1.0069580000000542 ms, remote processing delay was PT0.279006958S (18285), srSentTime was 2020-12-17T12:04:26.838Z, received time was 2020-12-17T12:04:27.116Z
20201217-130429.006 INFO  [Thread-86] [o.j.o.p.o.JitsiJvbWrapper] WARNING: [1076] [confId=4a2658cf6c0c1ad6 epId=e4bbf339 gid=354370 stats_id=Brittany-aNP conf_name=************************] EndpointConnectionStats.processReportBlock#153: Negative rtt value: -1.012939000000074 ms, remote processing delay was PT0.532012939S (34866), srSentTime was 2020-12-17T12:04:28.474Z, received time was 2020-12-17T12:04:29.005Z
20201217-130429.721 INFO  [Thread-86] [o.j.o.p.o.JitsiJvbWrapper] WARNING: [1068] [confId=4a2658cf6c0c1ad6 epId=e4bbf339 gid=354370 stats_id=Brittany-aNP conf_name=************************] EndpointConnectionStats.processReportBlock#153: Negative rtt value: -1.004760000000033 ms, remote processing delay was PT0.28300476S (18547), srSentTime was 2020-12-17T12:04:29.438Z, received time was 2020-12-17T12:04:29.720Z

really flood the log. This message are produced by

jitsi-media-transform/src/main/kotlin/org/jitsi/nlj/stats/EndpointConnectionStats.kt

Lines 168 to 175 in c833b08

	} else if (rtt < -1.0) {
	// Allow some small slop here, since receivedTime and srSentTime are only accurate to the nearest
	// millisecond.
	logger.warn(
	"Negative rtt value: $rtt ms, remote processing delay was " +
	"$remoteProcessingDelay (${reportBlock.delaySinceLastSr}), srSentTime was $srSentTime, " +
	"received time was $receivedTime"
	)

I wonder, if the slop value of 1.0ms is small enough and if there might be "other" reasons that lead to the point of view of a "time-travel paradoxon", i.e. the answer is delivered before the question was asked.

I suggest either to raise the slop value and/or choose a lower logging level, i.e. INFO or even DEBUG for this message. Because of the only instrument I see is to quite this complete logger by the logging configuration and this will cut off "valid" WARNINGs.