lib/connections, lib/model: Track last connection duration (ref #7223) (#7242)

This adds a statistic to track the last connection duration per device.
It isn't used for much in this PR, but it's available for #7223 to use
in deciding how to order device connection attempts (deprioritizing
devices that just dropped our connection the last time).

lib/connections/quic_dial.go

@@ -87,7 +87,7 @@ func (d *quicDialer) Dial(ctx context.Context, _ protocol.DeviceID, uri *url.URL
 		return internalConn{}, errors.Wrap(err, "open stream")
 	}
 
-	return internalConn{&quicTlsConn{session, stream, createdConn}, connTypeQUICClient, quicPriority}, nil
+	return newInternalConn(&quicTlsConn{session, stream, createdConn}, connTypeQUICClient, quicPriority), nil
 }
 
 type quicDialerFactory struct {

lib/connections/quic_listen.go

@@ -150,7 +150,7 @@ func (t *quicListener) serve(ctx context.Context) error {
 			continue
 		}
 
-		t.conns <- internalConn{&quicTlsConn{session, stream, nil}, connTypeQUICServer, quicPriority}
+		t.conns <- newInternalConn(&quicTlsConn{session, stream, nil}, connTypeQUICServer, quicPriority)
 	}
 }
 

lib/connections/relay_dial.go

@@ -63,7 +63,7 @@ func (d *relayDialer) Dial(ctx context.Context, id protocol.DeviceID, uri *url.U
 		return internalConn{}, err
 	}
 
-	return internalConn{tc, connTypeRelayClient, relayPriority}, nil
+	return newInternalConn(tc, connTypeRelayClient, relayPriority), nil
 }
 
 type relayDialerFactory struct{}

lib/connections/relay_listen.go

@@ -105,7 +105,7 @@ func (t *relayListener) serve(ctx context.Context) error {
 				continue
 			}
 
-			t.conns <- internalConn{tc, connTypeRelayServer, relayPriority}
+			t.conns <- newInternalConn(tc, connTypeRelayServer, relayPriority)
 
 		// Poor mans notifier that informs the connection service that the
 		// relay URI has changed. This can only happen when we connect to a

lib/connections/structs.go

@@ -35,8 +35,9 @@ type tlsConn interface {
 // came from (type, priority).
 type internalConn struct {
 	tlsConn
-	connType connType
-	priority int
+	connType      connType
+	priority      int
+	establishedAt time.Time
 }
 
 type connType int
@@ -82,6 +83,15 @@ func (t connType) Transport() string {
 	}
 }
 
+func newInternalConn(tc tlsConn, connType connType, priority int) internalConn {
+	return internalConn{
+		tlsConn:       tc,
+		connType:      connType,
+		priority:      priority,
+		establishedAt: time.Now(),
+	}
+}
+
 func (c internalConn) Close() error {
 	// *tls.Conn.Close() does more than it says on the tin. Specifically, it
 	// sends a TLS alert message, which might block forever if the
@@ -119,6 +129,10 @@ func (c internalConn) Transport() string {
 	return transport + "6"
 }
 
+func (c internalConn) EstablishedAt() time.Time {
+	return c.establishedAt
+}
+
 func (c internalConn) String() string {
 	return fmt.Sprintf("%s-%s/%s/%s", c.LocalAddr(), c.RemoteAddr(), c.Type(), c.Crypto())
 }

lib/connections/tcp_dial.go

@@ -57,7 +57,7 @@ func (d *tcpDialer) Dial(ctx context.Context, _ protocol.DeviceID, uri *url.URL)
 		return internalConn{}, err
 	}
 
-	return internalConn{tc, connTypeTCPClient, tcpPriority}, nil
+	return newInternalConn(tc, connTypeTCPClient, tcpPriority), nil
 }
 
 type tcpDialerFactory struct{}

lib/connections/tcp_listen.go

@@ -137,7 +137,7 @@ func (t *tcpListener) serve(ctx context.Context) error {
 			continue
 		}
 
-		t.conns <- internalConn{tc, connTypeTCPServer, tcpPriority}
+		t.conns <- newInternalConn(tc, connTypeTCPServer, tcpPriority)
 	}
 }
 

lib/model/model.go

@@ -246,7 +246,7 @@ func NewModel(cfg config.Wrapper, id protocol.DeviceID, clientName, clientVersio
 		started: make(chan struct{}),
 	}
 	for devID := range cfg.Devices() {
-		m.deviceStatRefs[devID] = stats.NewDeviceStatisticsReference(m.db, devID.String())
+		m.deviceStatRefs[devID] = stats.NewDeviceStatisticsReference(m.db, devID)
 	}
 	m.Add(m.progressEmitter)
 	m.Add(svcutil.AsService(m.serve, m.String()))
@@ -1684,6 +1684,7 @@ func (m *model) Closed(conn protocol.Connection, err error) {
 		m.pmut.Unlock()
 		return
 	}
+
 	delete(m.conn, device)
 	delete(m.connRequestLimiters, device)
 	delete(m.helloMessages, device)
@@ -1695,6 +1696,7 @@ func (m *model) Closed(conn protocol.Connection, err error) {
 	m.pmut.Unlock()
 
 	m.progressEmitter.temporaryIndexUnsubscribe(conn)
+	m.deviceDidClose(device, time.Since(conn.EstablishedAt()))
 
 	l.Infof("Connection to %s at %s closed: %v", device, conn, err)
 	m.evLogger.Log(events.DeviceDisconnected, map[string]string{
@@ -2175,7 +2177,16 @@ func (m *model) deviceWasSeen(deviceID protocol.DeviceID) {
 	sr, ok := m.deviceStatRefs[deviceID]
 	m.fmut.RUnlock()
 	if ok {
-		sr.WasSeen()
+		_ = sr.WasSeen()
+	}
+}
+
+func (m *model) deviceDidClose(deviceID protocol.DeviceID, duration time.Duration) {
+	m.fmut.RLock()
+	sr, ok := m.deviceStatRefs[deviceID]
+	m.fmut.RUnlock()
+	if ok {
+		_ = sr.LastConnectionDuration(duration)
 	}
 }
 
@@ -2674,7 +2685,7 @@ func (m *model) CommitConfiguration(from, to config.Configuration) bool {
 	for deviceID, toCfg := range toDevices {
 		fromCfg, ok := fromDevices[deviceID]
 		if !ok {
-			sr := stats.NewDeviceStatisticsReference(m.db, deviceID.String())
+			sr := stats.NewDeviceStatisticsReference(m.db, deviceID)
 			m.fmut.Lock()
 			m.deviceStatRefs[deviceID] = sr
 			m.fmut.Unlock()

lib/protocol/protocol.go

@@ -152,6 +152,7 @@ type ConnectionInfo interface {
 	Priority() int
 	String() string
 	Crypto() string
+	EstablishedAt() time.Time
 }
 
 type rawConnection struct {

lib/stats/device.go

@@ -10,26 +10,34 @@ import (
 	"time"
 
 	"github.com/syncthing/syncthing/lib/db"
+	"github.com/syncthing/syncthing/lib/db/backend"
+	"github.com/syncthing/syncthing/lib/protocol"
+)
+
+const (
+	lastSeenKey     = "lastSeen"
+	connDurationKey = "lastConnDuration"
 )
 
 type DeviceStatistics struct {
-	LastSeen time.Time `json:"lastSeen"`
+	LastSeen                time.Time `json:"lastSeen"`
+	LastConnectionDurationS float64   `json:"lastConnectionDurationS"`
 }
 
 type DeviceStatisticsReference struct {
 	ns     *db.NamespacedKV
-	device string
+	device protocol.DeviceID
 }
 
-func NewDeviceStatisticsReference(ldb *db.Lowlevel, device string) *DeviceStatisticsReference {
+func NewDeviceStatisticsReference(dba backend.Backend, device protocol.DeviceID) *DeviceStatisticsReference {
 	return &DeviceStatisticsReference{
-		ns:     db.NewDeviceStatisticsNamespace(ldb, device),
+		ns:     db.NewDeviceStatisticsNamespace(dba, device.String()),
 		device: device,
 	}
 }
 
 func (s *DeviceStatisticsReference) GetLastSeen() (time.Time, error) {
-	t, ok, err := s.ns.Time("lastSeen")
+	t, ok, err := s.ns.Time(lastSeenKey)
 	if err != nil {
 		return time.Time{}, err
 	} else if !ok {
@@ -41,9 +49,25 @@ func (s *DeviceStatisticsReference) GetLastSeen() (time.Time, error) {
 	return t, nil
 }
 
+func (s *DeviceStatisticsReference) GetLastConnectionDuration() (time.Duration, error) {
+	d, ok, err := s.ns.Int64(connDurationKey)
+	if err != nil {
+		return 0, err
+	} else if !ok {
+		return 0, nil
+	}
+	l.Debugln("stats.DeviceStatisticsReference.GetLastConnectionDuration:", s.device, d)
+	return time.Duration(d), nil
+}
+
 func (s *DeviceStatisticsReference) WasSeen() error {
 	l.Debugln("stats.DeviceStatisticsReference.WasSeen:", s.device)
-	return s.ns.PutTime("lastSeen", time.Now())
+	return s.ns.PutTime(lastSeenKey, time.Now())
+}
+
+func (s *DeviceStatisticsReference) LastConnectionDuration(d time.Duration) error {
+	l.Debugln("stats.DeviceStatisticsReference.LastConnectionDuration:", s.device, d)
+	return s.ns.PutInt64(connDurationKey, d.Nanoseconds())
 }
 
 func (s *DeviceStatisticsReference) GetStatistics() (DeviceStatistics, error) {
@@ -51,7 +75,12 @@ func (s *DeviceStatisticsReference) GetStatistics() (DeviceStatistics, error) {
 	if err != nil {
 		return DeviceStatistics{}, err
 	}
+	lastConnDuration, err := s.GetLastConnectionDuration()
+	if err != nil {
+		return DeviceStatistics{}, err
+	}
 	return DeviceStatistics{
-		LastSeen: lastSeen,
+		LastSeen:                lastSeen,
+		LastConnectionDurationS: lastConnDuration.Seconds(),
 	}, nil
 }

lib/stats/empty_test.go

@@ -1,10 +0,0 @@
-// Copyright (C) 2016 The Syncthing Authors.
-//
-// This Source Code Form is subject to the terms of the Mozilla Public
-// License, v. 2.0. If a copy of the MPL was not distributed with this file,
-// You can obtain one at https://mozilla.org/MPL/2.0/.
-
-// The existence of this file means we get 0% test coverage rather than no
-// test coverage at all. Remove when implementing an actual test.
-
-package stats

lib/stats/stats_test.go

@@ -0,0 +1,43 @@
+// Copyright (C) 2020 The Syncthing Authors.
+//
+// This Source Code Form is subject to the terms of the Mozilla Public
+// License, v. 2.0. If a copy of the MPL was not distributed with this file,
+// You can obtain one at https://mozilla.org/MPL/2.0/.
+
+// The existence of this file means we get 0% test coverage rather than no
+// test coverage at all. Remove when implementing an actual test.
+
+package stats
+
+import (
+	"testing"
+	"time"
+
+	"github.com/syncthing/syncthing/lib/db/backend"
+	"github.com/syncthing/syncthing/lib/protocol"
+)
+
+func TestDeviceStat(t *testing.T) {
+	db := backend.OpenLevelDBMemory()
+	defer db.Close()
+
+	sr := NewDeviceStatisticsReference(db, protocol.LocalDeviceID)
+	if err := sr.WasSeen(); err != nil {
+		t.Fatal(err)
+	}
+	if err := sr.LastConnectionDuration(42 * time.Second); err != nil {
+		t.Fatal(err)
+	}
+
+	stat, err := sr.GetStatistics()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	if d := time.Since(stat.LastSeen); d > 5*time.Second {
+		t.Error("Last seen far in the past:", d)
+	}
+	if d := stat.LastConnectionDurationS; d != 42 {
+		t.Error("Bad last duration:", d)
+	}
+}

lib/testutils/testutils.go

@@ -10,6 +10,7 @@ import (
 	"errors"
 	"net"
 	"sync"
+	"time"
 )
 
 var ErrClosed = errors.New("closed")
@@ -90,6 +91,10 @@ func (f *FakeConnectionInfo) String() string {
 	return ""
 }
 
+func (f *FakeConnectionInfo) EstablishedAt() time.Time {
+	return time.Time{}
+}
+
 type FakeAddr struct{}
 
 func (FakeAddr) Network() string {