Merge 926fcf202a into 3e7d8fb0f5

Since the ordering may have been previously defaulted and saved as "ntp,http", but that was being ignored and fallback-defaults were being used, in Ordering, `ntp` means use the fallback NTP servers, and `http` means use the fallback HTTP URLs. Thus `ntp_user_provided` and `http_user_provided` are the user specified static lists.

internal/confparser/confparser_test.go

@@ -43,9 +43,11 @@ type testNetworkConfig struct {
 	LLDPTxTLVs              []string    `json:"lldp_tx_tlvs,omitempty" one_of:"chassis,port,system,vlan" default:"chassis,port,system,vlan"`
 	MDNSMode                null.String `json:"mdns_mode,omitempty" one_of:"disabled,auto,ipv4_only,ipv6_only" default:"auto"`
 	TimeSyncMode            null.String `json:"time_sync_mode,omitempty" one_of:"ntp_only,ntp_and_http,http_only,custom" default:"ntp_and_http"`
-	TimeSyncOrdering        []string    `json:"time_sync_ordering,omitempty" one_of:"http,ntp,ntp_dhcp,ntp_user_provided,ntp_fallback" default:"ntp,http"`
+	TimeSyncOrdering        []string    `json:"time_sync_ordering,omitempty" one_of:"http,ntp,ntp_dhcp,ntp_user_provided,http_user_provided" default:"ntp,http"`
 	TimeSyncDisableFallback null.Bool   `json:"time_sync_disable_fallback,omitempty" default:"false"`
 	TimeSyncParallel        null.Int    `json:"time_sync_parallel,omitempty" default:"4"`
+	TimeSyncNTPServers      []string    `json:"time_sync_ntp_servers,omitempty" validate_type:"ipv4_or_ipv6" required_if:"TimeSyncOrdering=ntp_user_provided"`
+	TimeSyncHTTPUrls        []string    `json:"time_sync_http_urls,omitempty" validate_type:"url" required_if:"TimeSyncOrdering=http_user_provided"`
 }
 
 func TestValidateConfig(t *testing.T) {

internal/network/config.go

@@ -45,9 +45,11 @@ type NetworkConfig struct {
 	LLDPTxTLVs              []string    `json:"lldp_tx_tlvs,omitempty" one_of:"chassis,port,system,vlan" default:"chassis,port,system,vlan"`
 	MDNSMode                null.String `json:"mdns_mode,omitempty" one_of:"disabled,auto,ipv4_only,ipv6_only" default:"auto"`
 	TimeSyncMode            null.String `json:"time_sync_mode,omitempty" one_of:"ntp_only,ntp_and_http,http_only,custom" default:"ntp_and_http"`
-	TimeSyncOrdering        []string    `json:"time_sync_ordering,omitempty" one_of:"http,ntp,ntp_dhcp,ntp_user_provided,ntp_fallback" default:"ntp,http"`
+	TimeSyncOrdering        []string    `json:"time_sync_ordering,omitempty" one_of:"http,ntp,ntp_dhcp,ntp_user_provided,http_user_provided" default:"ntp,http"`
 	TimeSyncDisableFallback null.Bool   `json:"time_sync_disable_fallback,omitempty" default:"false"`
 	TimeSyncParallel        null.Int    `json:"time_sync_parallel,omitempty" default:"4"`
+	TimeSyncNTPServers      []string    `json:"time_sync_ntp_servers,omitempty" validate_type:"ipv4_or_ipv6" required_if:"TimeSyncOrdering=ntp_user_provided"`
+	TimeSyncHTTPUrls        []string    `json:"time_sync_http_urls,omitempty" validate_type:"url" required_if:"TimeSyncOrdering=http_user_provided"`
 }
 
 func (c *NetworkConfig) GetMDNSMode() *mdns.MDNSListenOptions {

internal/network/netif.go

@@ -21,6 +21,7 @@ type NetworkInterfaceState struct {
 	ipv6Addr      *net.IP
 	ipv6Addresses []IPv6Address
 	ipv6LinkLocal *net.IP
+	ntpAddresses  []*net.IP
 	macAddr       *net.HardwareAddr
 
 	l         *zerolog.Logger
@@ -76,6 +77,7 @@ func NewNetworkInterfaceState(opts *NetworkInterfaceOptions) (*NetworkInterfaceS
 		onInitialCheck:  opts.OnInitialCheck,
 		cbConfigChange:  opts.OnConfigChange,
 		config:          opts.NetworkConfig,
+		ntpAddresses:    make([]*net.IP, 0),
 	}
 
 	// create the dhcp client
@@ -89,7 +91,7 @@ func NewNetworkInterfaceState(opts *NetworkInterfaceOptions) (*NetworkInterfaceS
 				opts.Logger.Error().Err(err).Msg("failed to update network state")
 				return
 			}
-
+			_ = s.updateNtpServersFromLease(lease)
 			_ = s.setHostnameIfNotSame()
 
 			opts.OnDhcpLeaseChange(lease)
@@ -135,6 +137,27 @@ func (s *NetworkInterfaceState) IPv6String() string {
 	return s.ipv6Addr.String()
 }
 
+func (s *NetworkInterfaceState) NtpAddresses() []*net.IP {
+	return s.ntpAddresses
+}
+
+func (s *NetworkInterfaceState) NtpAddressesString() []string {
+	ntpServers := []string{}
+
+	if s != nil {
+		s.l.Debug().Any("s", s).Msg("getting NTP address strings")
+
+		if len(s.ntpAddresses) > 0 {
+			for _, server := range s.ntpAddresses {
+				s.l.Debug().IPAddr("server", *server).Msg("converting NTP address")
+				ntpServers = append(ntpServers, server.String())
+			}
+		}
+	}
+
+	return ntpServers
+}
+
 func (s *NetworkInterfaceState) MAC() *net.HardwareAddr {
 	return s.macAddr
 }
@@ -318,6 +341,25 @@ func (s *NetworkInterfaceState) update() (DhcpTargetState, error) {
 	return dhcpTargetState, nil
 }
 
+func (s *NetworkInterfaceState) updateNtpServersFromLease(lease *udhcpc.Lease) error {
+	if lease != nil && len(lease.NTPServers) > 0 {
+		s.l.Info().Msg("lease found, updating DHCP NTP addresses")
+		s.ntpAddresses = make([]*net.IP, 0, len(lease.NTPServers))
+
+		for _, ntpServer := range lease.NTPServers {
+			if ntpServer != nil {
+				s.l.Info().IPAddr("ntp_server", ntpServer).Msg("NTP server found in lease")
+				s.ntpAddresses = append(s.ntpAddresses, &ntpServer)
+			}
+		}
+	} else {
+		s.l.Info().Msg("no NTP servers found in lease")
+		s.ntpAddresses = make([]*net.IP, 0, len(s.config.TimeSyncNTPServers))
+	}
+
+	return nil
+}
+
 func (s *NetworkInterfaceState) CheckAndUpdateDhcp() error {
 	dhcpTargetState, err := s.update()
 	if err != nil {

internal/timesync/http.go

@@ -19,9 +19,9 @@ var defaultHTTPUrls = []string{
 	// "http://www.msftconnecttest.com/connecttest.txt",
 }
 
-func (t *TimeSync) queryAllHttpTime() (now *time.Time) {
-	chunkSize := 4
-	httpUrls := t.httpUrls
+func (t *TimeSync) queryAllHttpTime(httpUrls []string) (now *time.Time) {
+	chunkSize := int(t.networkConfig.TimeSyncParallel.ValueOr(4))
+	t.l.Info().Strs("httpUrls", httpUrls).Int("chunkSize", chunkSize).Msg("querying HTTP URLs")
 
 	// shuffle the http urls to avoid always querying the same servers
 	rand.Shuffle(len(httpUrls), func(i, j int) { httpUrls[i], httpUrls[j] = httpUrls[j], httpUrls[i] })

internal/timesync/metrics.go

@@ -73,6 +73,7 @@ var (
 		},
 		[]string{"url"},
 	)
+
 	metricNtpServerInfo = promauto.NewGaugeVec(
 		prometheus.GaugeOpts{
 			Name: "jetkvm_timesync_ntp_server_info",

internal/timesync/ntp.go

@@ -1,6 +1,7 @@
 package timesync
 
 import (
+	"context"
 	"math/rand/v2"
 	"strconv"
 	"time"
@@ -21,9 +22,9 @@ var defaultNTPServers = []string{
 	"3.pool.ntp.org",
 }
 
-func (t *TimeSync) queryNetworkTime() (now *time.Time, offset *time.Duration) {
-	chunkSize := 4
-	ntpServers := t.ntpServers
+func (t *TimeSync) queryNetworkTime(ntpServers []string) (now *time.Time, offset *time.Duration) {
+	chunkSize := int(t.networkConfig.TimeSyncParallel.ValueOr(4))
+	t.l.Info().Strs("servers", ntpServers).Int("chunkSize", chunkSize).Msg("querying NTP servers")
 
 	// shuffle the ntp servers to avoid always querying the same servers
 	rand.Shuffle(len(ntpServers), func(i, j int) { ntpServers[i], ntpServers[j] = ntpServers[j], ntpServers[i] })
@@ -46,6 +47,10 @@ type ntpResult struct {
 
 func (t *TimeSync) queryMultipleNTP(servers []string, timeout time.Duration) (now *time.Time, offset *time.Duration) {
 	results := make(chan *ntpResult, len(servers))
+
+	_, cancel := context.WithTimeout(context.Background(), timeout)
+	defer cancel()
+
 	for _, server := range servers {
 		go func(server string) {
 			scopedLogger := t.l.With().
@@ -66,15 +71,25 @@ func (t *TimeSync) queryMultipleNTP(servers []string, timeout time.Duration) (no
 				return
 			}
 
+			if response.IsKissOfDeath() {
+				scopedLogger.Warn().
+					Str("kiss_code", response.KissCode).
+					Msg("ignoring NTP server kiss of death")
+				results <- nil
+				return
+			}
+
+			rtt := float64(response.RTT.Milliseconds())
+
 			// set the last RTT
 			metricNtpServerLastRTT.WithLabelValues(
 				server,
-			).Set(float64(response.RTT.Milliseconds()))
+			).Set(rtt)
 
 			// set the RTT histogram
 			metricNtpServerRttHistogram.WithLabelValues(
 				server,
-			).Observe(float64(response.RTT.Milliseconds()))
+			).Observe(rtt)
 
 			// set the server info
 			metricNtpServerInfo.WithLabelValues(
@@ -91,10 +106,13 @@ func (t *TimeSync) queryMultipleNTP(servers []string, timeout time.Duration) (no
 			scopedLogger.Info().
 				Str("time", now.Format(time.RFC3339)).
 				Str("reference", response.ReferenceString()).
-				Str("rtt", response.RTT.String()).
+				Float64("rtt", rtt).
 				Str("clockOffset", response.ClockOffset.String()).
 				Uint8("stratum", response.Stratum).
 				Msg("NTP server returned time")
+
+			cancel()
+
 			results <- &ntpResult{
 				now:    now,
 				offset: &response.ClockOffset,

internal/timesync/timesync.go

@@ -28,9 +28,8 @@ type TimeSync struct {
 	syncLock *sync.Mutex
 	l        *zerolog.Logger
 
-	ntpServers    []string
-	httpUrls      []string
-	networkConfig *network.NetworkConfig
+	networkConfig    *network.NetworkConfig
+	dhcpNtpAddresses []string
 
 	rtcDevicePath string
 	rtcDevice     *os.File //nolint:unused
@@ -64,14 +63,13 @@ func NewTimeSync(opts *TimeSyncOptions) *TimeSync {
 	}
 
 	t := &TimeSync{
-		syncLock:      &sync.Mutex{},
-		l:             opts.Logger,
-		rtcDevicePath: rtcDevice,
-		rtcLock:       &sync.Mutex{},
-		preCheckFunc:  opts.PreCheckFunc,
-		ntpServers:    defaultNTPServers,
-		httpUrls:      defaultHTTPUrls,
-		networkConfig: opts.NetworkConfig,
+		syncLock:         &sync.Mutex{},
+		l:                opts.Logger,
+		dhcpNtpAddresses: []string{},
+		rtcDevicePath:    rtcDevice,
+		rtcLock:          &sync.Mutex{},
+		preCheckFunc:     opts.PreCheckFunc,
+		networkConfig:    opts.NetworkConfig,
 	}
 
 	if t.rtcDevicePath != "" {
@@ -82,34 +80,42 @@ func NewTimeSync(opts *TimeSyncOptions) *TimeSync {
 	return t
 }
 
+func (t *TimeSync) SetDhcpNtpAddresses(addresses []string) {
+	t.dhcpNtpAddresses = addresses
+}
+
 func (t *TimeSync) getSyncMode() SyncMode {
 	syncMode := SyncMode{
+		Ntp:             true,
+		Http:            true,
+		Ordering:        []string{"ntp_dhcp", "ntp", "http"},
 		NtpUseFallback:  true,
 		HttpUseFallback: true,
 	}
-	var syncModeString string
 
 	if t.networkConfig != nil {
-		syncModeString = t.networkConfig.TimeSyncMode.String
+		switch t.networkConfig.TimeSyncMode.String {
+		case "ntp_only":
+			syncMode.Http = false
+		case "http_only":
+			syncMode.Ntp = false
+		}
+
 		if t.networkConfig.TimeSyncDisableFallback.Bool {
 			syncMode.NtpUseFallback = false
 			syncMode.HttpUseFallback = false
 		}
+
+		var syncOrdering = t.networkConfig.TimeSyncOrdering
+		if len(syncOrdering) > 0 {
+			syncMode.Ordering = syncOrdering
+		}
 	}
 
-	switch syncModeString {
-	case "ntp_only":
-		syncMode.Ntp = true
-	case "http_only":
-		syncMode.Http = true
-	default:
-		syncMode.Ntp = true
-		syncMode.Http = true
-	}
+	t.l.Debug().Strs("Ordering", syncMode.Ordering).Bool("Ntp", syncMode.Ntp).Bool("Http", syncMode.Http).Bool("NtpUseFallback", syncMode.NtpUseFallback).Bool("HttpUseFallback", syncMode.HttpUseFallback).Msg("sync mode")
 
 	return syncMode
 }
-
 func (t *TimeSync) doTimeSync() {
 	metricTimeSyncStatus.Set(0)
 	for {
@@ -154,16 +160,61 @@ func (t *TimeSync) Sync() error {
 		offset *time.Duration
 	)
 
-	syncMode := t.getSyncMode()
-
 	metricTimeSyncCount.Inc()
 
-	if syncMode.Ntp {
-		now, offset = t.queryNetworkTime()
-	}
+	syncMode := t.getSyncMode()
 
-	if syncMode.Http && now == nil {
-		now = t.queryAllHttpTime()
+Orders:
+	for _, mode := range syncMode.Ordering {
+		switch mode {
+		case "ntp_user_provided":
+			if syncMode.Ntp {
+				t.l.Info().Msg("using NTP custom servers")
+				now, offset = t.queryNetworkTime(t.networkConfig.TimeSyncNTPServers)
+				if now != nil {
+					t.l.Info().Str("source", "NTP").Time("now", *now).Msg("time obtained")
+					break Orders
+				}
+			}
+		case "ntp_dhcp":
+			if syncMode.Ntp {
+				t.l.Info().Msg("using NTP servers from DHCP")
+				now, offset = t.queryNetworkTime(t.dhcpNtpAddresses)
+				if now != nil {
+					t.l.Info().Str("source", "NTP DHCP").Time("now", *now).Msg("time obtained")
+					break Orders
+				}
+			}
+		case "ntp":
+			if syncMode.Ntp && syncMode.NtpUseFallback {
+				t.l.Info().Msg("using NTP fallback")
+				now, offset = t.queryNetworkTime(defaultNTPServers)
+				if now != nil {
+					t.l.Info().Str("source", "NTP fallback").Time("now", *now).Msg("time obtained")
+					break Orders
+				}
+			}
+		case "http_user_provided":
+			if syncMode.Http {
+				t.l.Info().Msg("using HTTP custom URLs")
+				now = t.queryAllHttpTime(t.networkConfig.TimeSyncHTTPUrls)
+				if now != nil {
+					t.l.Info().Str("source", "HTTP").Time("now", *now).Msg("time obtained")
+					break Orders
+				}
+			}
+		case "http":
+			if syncMode.Http && syncMode.HttpUseFallback {
+				t.l.Info().Msg("using HTTP fallback")
+				now = t.queryAllHttpTime(defaultHTTPUrls)
+				if now != nil {
+					t.l.Info().Str("source", "HTTP fallback").Time("now", *now).Msg("time obtained")
+					break Orders
+				}
+			}
+		default:
+			t.l.Warn().Str("mode", mode).Msg("unknown time sync mode, skipping")
+		}
 	}
 
 	if now == nil {

internal/usbgadget/hid_keyboard.go

@@ -143,15 +143,21 @@ func (u *UsbGadget) listenKeyboardEvents() {
 			default:
 				l.Trace().Msg("reading from keyboard")
 				if u.keyboardHidFile == nil {
-					l.Error().Msg("keyboardHidFile is nil")
+					u.logWithSupression("keyboardHidFileNil", 100, &l, nil, "keyboardHidFile is nil")
+					// show the error every 100 times to avoid spamming the logs
 					time.Sleep(time.Second)
 					continue
 				}
+				// reset the counter
+				u.resetLogSuppressionCounter("keyboardHidFileNil")
+
 				n, err := u.keyboardHidFile.Read(buf)
 				if err != nil {
-					l.Error().Err(err).Msg("failed to read")
+					u.logWithSupression("keyboardHidFileRead", 100, &l, err, "failed to read")
 					continue
 				}
+				u.resetLogSuppressionCounter("keyboardHidFileRead")
+
 				l.Trace().Int("n", n).Bytes("buf", buf).Msg("got data from keyboard")
 				if n != 1 {
 					l.Trace().Int("n", n).Msg("expected 1 byte, got")
@@ -195,12 +201,12 @@ func (u *UsbGadget) keyboardWriteHidFile(data []byte) error {
 
 	_, err := u.keyboardHidFile.Write(data)
 	if err != nil {
-		u.log.Error().Err(err).Msg("failed to write to hidg0")
+		u.logWithSupression("keyboardWriteHidFile", 100, u.log, err, "failed to write to hidg0")
 		u.keyboardHidFile.Close()
 		u.keyboardHidFile = nil
 		return err
 	}
-
+	u.resetLogSuppressionCounter("keyboardWriteHidFile")
 	return nil
 }
 

internal/usbgadget/hid_mouse_absolute.go

@@ -75,11 +75,12 @@ func (u *UsbGadget) absMouseWriteHidFile(data []byte) error {
 
 	_, err := u.absMouseHidFile.Write(data)
 	if err != nil {
-		u.log.Error().Err(err).Msg("failed to write to hidg1")
+		u.logWithSupression("absMouseWriteHidFile", 100, u.log, err, "failed to write to hidg1")
 		u.absMouseHidFile.Close()
 		u.absMouseHidFile = nil
 		return err
 	}
+	u.resetLogSuppressionCounter("absMouseWriteHidFile")
 	return nil
 }
 

internal/usbgadget/hid_mouse_relative.go

@@ -65,11 +65,12 @@ func (u *UsbGadget) relMouseWriteHidFile(data []byte) error {
 
 	_, err := u.relMouseHidFile.Write(data)
 	if err != nil {
-		u.log.Error().Err(err).Msg("failed to write to hidg2")
+		u.logWithSupression("relMouseWriteHidFile", 100, u.log, err, "failed to write to hidg2")
 		u.relMouseHidFile.Close()
 		u.relMouseHidFile = nil
 		return err
 	}
+	u.resetLogSuppressionCounter("relMouseWriteHidFile")
 	return nil
 }
 

internal/usbgadget/usbgadget.go

@@ -79,6 +79,8 @@ type UsbGadget struct {
 	onKeyboardStateChange *func(state KeyboardState)
 
 	log *zerolog.Logger
+
+	logSuppressionCounter map[string]int
 }
 
 const configFSPath = "/sys/kernel/config"
@@ -126,6 +128,8 @@ func newUsbGadget(name string, configMap map[string]gadgetConfigItem, enabledDev
 
 		strictMode: config.strictMode,
 
+		logSuppressionCounter: make(map[string]int),
+
 		absMouseAccumulatedWheelY: 0,
 	}
 	if err := g.Init(); err != nil {

internal/usbgadget/utils.go

@@ -6,6 +6,8 @@ import (
 	"path/filepath"
 	"strconv"
 	"strings"
+
+	"github.com/rs/zerolog"
 )
 
 func joinPath(basePath string, paths []string) string {
@@ -78,3 +80,27 @@ func compareFileContent(oldContent []byte, newContent []byte, looserMatch bool)
 
 	return false
 }
+
+func (u *UsbGadget) logWithSupression(counterName string, every int, logger *zerolog.Logger, err error, msg string, args ...interface{}) {
+	if _, ok := u.logSuppressionCounter[counterName]; !ok {
+		u.logSuppressionCounter[counterName] = 0
+	} else {
+		u.logSuppressionCounter[counterName]++
+	}
+
+	l := logger.With().Int("counter", u.logSuppressionCounter[counterName]).Logger()
+
+	if u.logSuppressionCounter[counterName]%every == 0 {
+		if err != nil {
+			l.Error().Err(err).Msgf(msg, args...)
+		} else {
+			l.Error().Msgf(msg, args...)
+		}
+	}
+}
+
+func (u *UsbGadget) resetLogSuppressionCounter(counterName string) {
+	if _, ok := u.logSuppressionCounter[counterName]; !ok {
+		u.logSuppressionCounter[counterName] = 0
+	}
+}

network.go

@@ -19,6 +19,14 @@ func networkStateChanged() {
 	// do not block the main thread
 	go waitCtrlAndRequestDisplayUpdate(true)
 
+	if timeSync != nil {
+		if networkState != nil {
+			timeSync.SetDhcpNtpAddresses(networkState.NtpAddressesString())
+		}
+
+		timeSync.Sync()
+	}
+
 	// always restart mDNS when the network state changes
 	if mDNS != nil {
 		_ = mDNS.SetListenOptions(config.NetworkConfig.GetMDNSMode())