gs: Add debug prints for #3487

pkg/gatewayserver/io/io.go

@@ -17,6 +17,7 @@ package io
 import (
 	"context"
 	"fmt"
+	"os"
 	"sync/atomic"
 	"time"
 
@@ -35,9 +36,15 @@ const (
 	bufferSize = 1 << 4
 
 	maxRTTs = 20
-	rttTTL  = 30 * time.Minute
 )
 
+var rttTTL = func() time.Duration {
+	if d, err := time.ParseDuration(os.Getenv("TTN_LW_EXP_RTT_TTL")); err == nil {
+		return d
+	}
+	return 30 * time.Minute
+}()
+
 // Frontend provides supported features by the gateway frontend.
 type Frontend interface {
 	// Protocol returns the protocol used in the frontend.

pkg/gatewayserver/io/rtts.go

@@ -15,6 +15,8 @@
 package io
 
 import (
+	"fmt"
+	"os"
 	"sort"
 	"sync"
 	"time"
@@ -48,6 +50,7 @@ func (r *rtts) Record(d time.Duration, t time.Time) {
 		r.items = append(r.items[:0], r.items[1:]...)
 	}
 	r.mu.Unlock()
+	fmt.Fprintln(os.Stdout, "#3487", "Record:", d, "at", t)
 }
 
 // Last returns the last measured round-trip time.
@@ -75,6 +78,7 @@ func (r *rtts) Stats(percentile int, ref time.Time) (min, max, median, np time.D
 		return
 	}
 	sort.Slice(sorted, func(i, j int) bool { return sorted[i].d < sorted[j].d })
+	fmt.Fprintln(os.Stdout, "#3487", "Stats:", "sorted items:", sorted)
 	min = sorted[0].d
 	max = sorted[len(sorted)-1].d
 	if l := len(sorted); l%2 == 0 {

pkg/gatewayserver/scheduling/scheduler.go

@@ -16,8 +16,11 @@ package scheduling
 
 import (
 	"context"
+	"fmt"
 	"math"
+	"os"
 	"runtime/trace"
+	"strconv"
 	"sync"
 	"time"
 
@@ -47,7 +50,12 @@ var (
 
 	// scheduleMinRTTCount is the minimum number of observed round-trip times that are taken into account before using
 	// using their statistics for calculating an absolute time or determining whether scheduling is too late.
-	scheduleMinRTTCount = 5
+	scheduleMinRTTCount = func() int {
+		if count, err := strconv.ParseInt(os.Getenv("TTN_LW_EXP_SCHEDULE_MIN_RTT_COUNT"), 10, 32); err == nil {
+			return int(count)
+		}
+		return 5
+	}()
 
 	// scheduleLateRTTPercentile is the percentile of round-trip times that is considered for determining whether
 	// scheduling is too late.
@@ -297,7 +305,12 @@ func (s *Scheduler) ScheduleAt(ctx context.Context, opts Options) (Emission, err
 		if _, _, median, np, n := opts.RTTs.Stats(scheduleLateRTTPercentile, s.timeSource.Now()); n >= scheduleMinRTTCount {
 			minScheduleTime = np/2 + QueueDelay
 			medianRTT = &median
+			fmt.Fprintln(os.Stdout, "#3487", "ScheduleAt:", "median is", median)
+		} else {
+			fmt.Fprintln(os.Stdout, "#3487", "ScheduleAt:", "too few round trip times:", n, "<", scheduleMinRTTCount)
 		}
+	} else {
+		fmt.Fprintln(os.Stdout, "#3487", "ScheduleAt:", "no round trip times available")
 	}
 	var starts ConcentratorTime
 	now, ok := s.clock.FromServerTime(s.timeSource.Now())
@@ -310,8 +323,10 @@ func (s *Scheduler) ScheduleAt(ctx context.Context, opts Options) (Emission, err
 				if !ok {
 					return Emission{}, errNoServerTime.New()
 				}
+				fmt.Fprintln(os.Stdout, "#3487", "ScheduleAt:", "use median", *medianRTT)
 				starts = serverTime - ConcentratorTime(*medianRTT/2)
 			} else {
+				fmt.Fprintln(os.Stdout, "#3487", "ScheduleAt:", "no absolute gateway time")
 				return Emission{}, errNoAbsoluteGatewayTime.New()
 			}
 		}