Use monotonic clock for elapsed time calculations

README.md

@@ -90,6 +90,7 @@ Psiphon Tunnel Core uses:
 * [OpenSSL Bindings for Go](https://github.com/spacemonkeygo/openssl)
 * [goptlib](https://github.com/Yawning/goptlib)
 * [goregen](https://github.com/zach-klippenstein/goregen)
+* [monotime](https://github.com/aristanetworks/goarista)
 
 Licensing
 --------------------------------------------------------------------------------

psiphon/common/net.go

@@ -25,6 +25,8 @@ import (
 	"sync"
 	"sync/atomic"
 	"time"
+
+	"github.com/Psiphon-Inc/goarista/monotime"
 )
 
 // Conns is a synchronized list of Conns that is used to coordinate
@@ -187,8 +189,9 @@ type ActivityMonitoredConn struct {
 	// Note: 64-bit ints used with atomic operations are at placed
 	// at the start of struct to ensure 64-bit alignment.
 	// (https://golang.org/pkg/sync/atomic/#pkg-note-BUG)
-	startTime            int64
+	monotonicStartTime   int64
 	lastReadActivityTime int64
+	realStartTime        time.Time
 	net.Conn
 	inactivityTimeout time.Duration
 	activeOnWrite     bool
@@ -208,13 +211,14 @@ func NewActivityMonitoredConn(
 		}
 	}
 
-	now := time.Now().UnixNano()
+	now := int64(monotime.Now())
 
 	return &ActivityMonitoredConn{
 		Conn:                 conn,
 		inactivityTimeout:    inactivityTimeout,
 		activeOnWrite:        activeOnWrite,
-		startTime:            now,
+		realStartTime:        time.Now(),
+		monotonicStartTime:   now,
 		lastReadActivityTime: now,
 		lruEntry:             lruEntry,
 	}, nil
@@ -223,19 +227,19 @@ func NewActivityMonitoredConn(
 // GetStartTime gets the time when the ActivityMonitoredConn was
 // initialized.
 func (conn *ActivityMonitoredConn) GetStartTime() time.Time {
-	return time.Unix(0, conn.startTime)
+	return conn.realStartTime
 }
 
 // GetActiveDuration returns the time elapsed between the initialization
 // of the ActivityMonitoredConn and the last Read. Only reads are used
 // for this calculation since writes may succeed locally due to buffering.
 func (conn *ActivityMonitoredConn) GetActiveDuration() time.Duration {
-	return time.Duration(atomic.LoadInt64(&conn.lastReadActivityTime) - conn.startTime)
+	return time.Duration(atomic.LoadInt64(&conn.lastReadActivityTime) - conn.monotonicStartTime)
 }
 
-// GetLastActivityTime returns the time of the last Read.
-func (conn *ActivityMonitoredConn) GetLastActivityTime() time.Time {
-	return time.Unix(0, atomic.LoadInt64(&conn.lastReadActivityTime))
+// GetLastActivityTime returns the arbitrary monotonic time of the last Read.
+func (conn *ActivityMonitoredConn) GetLastActivityMonotime() monotime.Time {
+	return monotime.Time(atomic.LoadInt64(&conn.lastReadActivityTime))
 }
 
 func (conn *ActivityMonitoredConn) Read(buffer []byte) (int, error) {
@@ -252,7 +256,7 @@ func (conn *ActivityMonitoredConn) Read(buffer []byte) (int, error) {
 			conn.lruEntry.Touch()
 		}
 
-		atomic.StoreInt64(&conn.lastReadActivityTime, time.Now().UnixNano())
+		atomic.StoreInt64(&conn.lastReadActivityTime, int64(monotime.Now()))
 
 	}
 	// Note: no context error to preserve error type

psiphon/common/net_test.go

@@ -25,6 +25,8 @@ import (
 	"testing"
 	"testing/iotest"
 	"time"
+
+	"github.com/Psiphon-Inc/goarista/monotime"
 )
 
 type dummyConn struct {
@@ -109,7 +111,9 @@ func TestActivityMonitoredConn(t *testing.T) {
 		t.Fatalf("NewActivityMonitoredConn failed")
 	}
 
-	startTime := time.Now()
+	realStartTime := time.Now()
+
+	monotonicStartTime := monotime.Now()
 
 	time.Sleep(100 * time.Millisecond)
 
@@ -139,7 +143,7 @@ func TestActivityMonitoredConn(t *testing.T) {
 		t.Fatalf("previous write failed to extend timeout")
 	}
 
-	lastSuccessfulReadTime := time.Now()
+	lastSuccessfulReadTime := monotime.Now()
 
 	time.Sleep(100 * time.Millisecond)
 
@@ -155,15 +159,16 @@ func TestActivityMonitoredConn(t *testing.T) {
 		t.Fatalf("failed to timeout")
 	}
 
-	if startTime.Round(time.Millisecond) != conn.GetStartTime().Round(time.Millisecond) {
+	if realStartTime.Round(time.Millisecond) != conn.GetStartTime().Round(time.Millisecond) {
 		t.Fatalf("unexpected GetStartTime")
 	}
 
-	if lastSuccessfulReadTime.Round(time.Millisecond) != conn.GetLastActivityTime().Round(time.Millisecond) {
-		t.Fatalf("unexpected GetLastActivityTimes")
+	if int64(lastSuccessfulReadTime)/int64(time.Millisecond) !=
+		int64(conn.GetLastActivityMonotime())/int64(time.Millisecond) {
+		t.Fatalf("unexpected GetLastActivityTime")
 	}
 
-	diff := lastSuccessfulReadTime.Sub(startTime).Nanoseconds() - conn.GetActiveDuration().Nanoseconds()
+	diff := lastSuccessfulReadTime.Sub(monotonicStartTime).Nanoseconds() - conn.GetActiveDuration().Nanoseconds()
 	if diff < 0 {
 		diff = -diff
 	}

psiphon/common/throttled_test.go

@@ -28,6 +28,8 @@ import (
 	"net/http"
 	"testing"
 	"time"
+
+	"github.com/Psiphon-Inc/goarista/monotime"
 )
 
 const (
@@ -120,7 +122,7 @@ func run(t *testing.T, rateLimits RateLimits) {
 	testData, _ := MakeSecureRandomBytes(testDataSize)
 	requestBody := bytes.NewReader(testData)
 
-	startTime := time.Now()
+	startTime := monotime.Now()
 
 	response, err := client.Post("http://"+serverAddress, "application/octet-stream", requestBody)
 	if err == nil && response.StatusCode != http.StatusOK {
@@ -134,9 +136,9 @@ func run(t *testing.T, rateLimits RateLimits) {
 
 	// Test: elapsed upload time must reflect rate limit
 
-	checkElapsedTime(t, testDataSize, rateLimits.UpstreamBytesPerSecond, time.Now().Sub(startTime))
+	checkElapsedTime(t, testDataSize, rateLimits.UpstreamBytesPerSecond, monotime.Since(startTime))
 
-	startTime = time.Now()
+	startTime = monotime.Now()
 
 	body, err := ioutil.ReadAll(response.Body)
 	if err != nil {
@@ -148,7 +150,7 @@ func run(t *testing.T, rateLimits RateLimits) {
 
 	// Test: elapsed download time must reflect rate limit
 
-	checkElapsedTime(t, testDataSize, rateLimits.DownstreamBytesPerSecond, time.Now().Sub(startTime))
+	checkElapsedTime(t, testDataSize, rateLimits.DownstreamBytesPerSecond, monotime.Since(startTime))
 }
 
 func checkElapsedTime(t *testing.T, dataSize int, rateLimit int64, duration time.Duration) {

psiphon/controller.go

@@ -30,6 +30,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/Psiphon-Inc/goarista/monotime"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 )
 
@@ -66,10 +67,9 @@ type Controller struct {
 }
 
 type candidateServerEntry struct {
-	serverEntry               *ServerEntry
-	isServerAffinityCandidate bool
-	establishStartTime        time.Time
-	networkWaitDuration       time.Duration
+	serverEntry                *ServerEntry
+	isServerAffinityCandidate  bool
+	adjustedEstablishStartTime monotime.Time
 }
 
 // NewController initializes a new controller.
@@ -289,7 +289,7 @@ func (controller *Controller) remoteServerListFetcher() {
 		return
 	}
 
-	var lastFetchTime time.Time
+	var lastFetchTime monotime.Time
 
 fetcherLoop:
 	for {
@@ -302,7 +302,8 @@ fetcherLoop:
 
 		// Skip fetch entirely (i.e., send no request at all, even when ETag would save
 		// on response size) when a recent fetch was successful
-		if time.Now().Before(lastFetchTime.Add(FETCH_REMOTE_SERVER_LIST_STALE_PERIOD)) {
+		if lastFetchTime != 0 &&
+			lastFetchTime.Add(FETCH_REMOTE_SERVER_LIST_STALE_PERIOD).After(monotime.Now()) {
 			continue
 		}
 
@@ -326,7 +327,7 @@ fetcherLoop:
 				controller.untunneledDialConfig)
 
 			if err == nil {
-				lastFetchTime = time.Now()
+				lastFetchTime = monotime.Now()
 				break retryLoop
 			}
 
@@ -454,7 +455,7 @@ func (controller *Controller) startOrSignalConnectedReporter() {
 func (controller *Controller) upgradeDownloader() {
 	defer controller.runWaitGroup.Done()
 
-	var lastDownloadTime time.Time
+	var lastDownloadTime monotime.Time
 
 downloadLoop:
 	for {
@@ -469,7 +470,8 @@ downloadLoop:
 		// Unless handshake is explicitly advertizing a new version, skip
 		// checking entirely when a recent download was successful.
 		if handshakeVersion == "" &&
-			time.Now().Before(lastDownloadTime.Add(DOWNLOAD_UPGRADE_STALE_PERIOD)) {
+			lastDownloadTime != 0 &&
+			lastDownloadTime.Add(DOWNLOAD_UPGRADE_STALE_PERIOD).After(monotime.Now()) {
 			continue
 		}
 
@@ -494,7 +496,7 @@ downloadLoop:
 				controller.untunneledDialConfig)
 
 			if err == nil {
-				lastDownloadTime = time.Now()
+				lastDownloadTime = monotime.Now()
 				break retryLoop
 			}
 
@@ -670,7 +672,7 @@ loop:
 //
 // Concurrency note: only the runTunnels() goroutine may call classifyImpairedProtocol
 func (controller *Controller) classifyImpairedProtocol(failedTunnel *Tunnel) {
-	if failedTunnel.establishedTime.Add(IMPAIRED_PROTOCOL_CLASSIFICATION_DURATION).After(time.Now()) {
+	if failedTunnel.establishedTime.Add(IMPAIRED_PROTOCOL_CLASSIFICATION_DURATION).After(monotime.Now()) {
 		controller.impairedProtocolClassification[failedTunnel.protocol] += 1
 	} else {
 		controller.impairedProtocolClassification[failedTunnel.protocol] = 0
@@ -995,8 +997,7 @@ func (controller *Controller) establishCandidateGenerator(impairedProtocols []st
 	// networkWaitDuration is the elapsed time spent waiting
 	// for network connectivity. This duration will be excluded
 	// from reported tunnel establishment duration.
-	// networkWaitDuration may include device sleep time.
-	establishStartTime := time.Now()
+	establishStartTime := monotime.Now()
 	var networkWaitDuration time.Duration
 
 	iterator, err := NewServerEntryIterator(controller.config)
@@ -1019,7 +1020,7 @@ loop:
 	// Repeat until stopped
 	for i := 0; ; i++ {
 
-		networkWaitStartTime := time.Now()
+		networkWaitStartTime := monotime.Now()
 
 		if !WaitForNetworkConnectivity(
 			controller.config.NetworkConnectivityChecker,
@@ -1028,10 +1029,10 @@ loop:
 			break loop
 		}
 
-		networkWaitDuration += time.Since(networkWaitStartTime)
+		networkWaitDuration += monotime.Since(networkWaitStartTime)
 
 		// Send each iterator server entry to the establish workers
-		startTime := time.Now()
+		startTime := monotime.Now()
 		for {
 			serverEntry, err := iterator.Next()
 			if err != nil {
@@ -1064,11 +1065,13 @@ loop:
 				}
 			}
 
+			// adjustedEstablishStartTime is establishStartTime shifted
+			// to exclude time spent waiting for network connectivity.
+
 			candidate := &candidateServerEntry{
-				serverEntry:               serverEntry,
-				isServerAffinityCandidate: isServerAffinityCandidate,
-				establishStartTime:        establishStartTime,
-				networkWaitDuration:       networkWaitDuration,
+				serverEntry:                serverEntry,
+				isServerAffinityCandidate:  isServerAffinityCandidate,
+				adjustedEstablishStartTime: establishStartTime.Add(networkWaitDuration),
 			}
 
 			// Note: there must be only one server affinity candidate, as it
@@ -1086,7 +1089,7 @@ loop:
 				break loop
 			}
 
-			if time.Now().After(startTime.Add(ESTABLISH_TUNNEL_WORK_TIME)) {
+			if startTime.Add(ESTABLISH_TUNNEL_WORK_TIME).Before(monotime.Now()) {
 				// Start over, after a brief pause, with a new shuffle of the server
 				// entries, and potentially some newly fetched server entries.
 				break
@@ -1160,8 +1163,7 @@ loop:
 			controller.sessionId,
 			controller.establishPendingConns,
 			candidateServerEntry.serverEntry,
-			candidateServerEntry.establishStartTime,
-			candidateServerEntry.networkWaitDuration,
+			candidateServerEntry.adjustedEstablishStartTime,
 			controller) // TunnelOwner
 		if err != nil {
 

psiphon/controller_test.go

@@ -34,6 +34,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/Psiphon-Inc/goarista/monotime"
 	socks "github.com/Psiphon-Inc/goptlib"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"github.com/elazarl/goproxy"
@@ -692,14 +693,14 @@ func controllerRun(t *testing.T, runConfig *controllerRunConfig) {
 		// ensure failed tunnel detection, and ultimately hitting
 		// impaired protocol checks.
 
-		startTime := time.Now()
+		startTime := monotime.Now()
 
 		for {
 
 			time.Sleep(1 * time.Second)
 			useTunnel(t, httpProxyPort)
 
-			if startTime.Add(runConfig.runDuration).Before(time.Now()) {
+			if startTime.Add(runConfig.runDuration).Before(monotime.Now()) {
 				break
 			}
 		}

psiphon/meekConn.go

@@ -34,6 +34,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/Psiphon-Inc/goarista/monotime"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/upstreamproxy"
 	"golang.org/x/crypto/nacl/box"
@@ -571,7 +572,7 @@ func (meek *MeekConn) roundTrip(sendPayload []byte) (receivedPayload io.ReadClos
 	// through the first hop. In addition, this will require additional support for timely shutdown.
 
 	retries := uint(0)
-	retryDeadline := time.Now().Add(MEEK_ROUND_TRIP_RETRY_DEADLINE)
+	retryDeadline := monotime.Now().Add(MEEK_ROUND_TRIP_RETRY_DEADLINE)
 
 	var response *http.Response
 	for {
@@ -603,7 +604,7 @@ func (meek *MeekConn) roundTrip(sendPayload []byte) (receivedPayload io.ReadClos
 			break
 		}
 
-		if retries >= 1 && time.Now().After(retryDeadline) {
+		if retries >= 1 && monotime.Now().After(retryDeadline) {
 			break
 		}
 		retries += 1

psiphon/server/dns.go

@@ -28,6 +28,7 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/Psiphon-Inc/goarista/monotime"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 )
 
@@ -71,7 +72,7 @@ type DNSResolver struct {
 func NewDNSResolver(defaultResolver string) (*DNSResolver, error) {
 
 	dns := &DNSResolver{
-		lastReloadTime: time.Now().Unix(),
+		lastReloadTime: int64(monotime.Now()),
 	}
 
 	dns.ReloadableFile = common.NewReloadableFile(
@@ -130,8 +131,8 @@ func (dns *DNSResolver) Get() net.IP {
 	// write lock, we only incur write lock blocking when "/etc/resolv.conf"
 	// has actually changed.
 
-	lastReloadTime := atomic.LoadInt64(&dns.lastReloadTime)
-	stale := time.Unix(lastReloadTime, 0).Add(DNS_SYSTEM_CONFIG_RELOAD_PERIOD).Before(time.Now())
+	lastReloadTime := monotime.Time(atomic.LoadInt64(&dns.lastReloadTime))
+	stale := monotime.Now().After(lastReloadTime.Add(DNS_SYSTEM_CONFIG_RELOAD_PERIOD))
 
 	if stale {
 

psiphon/server/meek.go

@@ -33,6 +33,7 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/Psiphon-Inc/goarista/monotime"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"golang.org/x/crypto/nacl/box"
@@ -453,12 +454,12 @@ type meekSession struct {
 }
 
 func (session *meekSession) touch() {
-	atomic.StoreInt64(&session.lastActivity, time.Now().UnixNano())
+	atomic.StoreInt64(&session.lastActivity, int64(monotime.Now()))
 }
 
 func (session *meekSession) expired() bool {
-	lastActivity := atomic.LoadInt64(&session.lastActivity)
-	return time.Since(time.Unix(0, lastActivity)) > MEEK_MAX_SESSION_STALENESS
+	lastActivity := monotime.Time(atomic.LoadInt64(&session.lastActivity))
+	return monotime.Since(lastActivity) > MEEK_MAX_SESSION_STALENESS
 }
 
 // makeMeekTLSConfig creates a TLS config for a meek HTTPS listener.
@@ -675,7 +676,7 @@ func (conn *meekConn) Read(buffer []byte) (int, error) {
 // Note: channel scheme assumes only one concurrent call to pumpWrites
 func (conn *meekConn) pumpWrites(writer io.Writer) error {
 
-	startTime := time.Now()
+	startTime := monotime.Now()
 	timeout := time.NewTimer(MEEK_TURN_AROUND_TIMEOUT)
 	defer timeout.Stop()
 
@@ -698,7 +699,7 @@ func (conn *meekConn) pumpWrites(writer io.Writer) error {
 				// MEEK_MAX_PAYLOAD_LENGTH response bodies
 				return nil
 			}
-			totalElapsedTime := time.Now().Sub(startTime) / time.Millisecond
+			totalElapsedTime := monotime.Since(startTime) / time.Millisecond
 			if totalElapsedTime >= MEEK_EXTENDED_TURN_AROUND_TIMEOUT {
 				return nil
 			}

psiphon/splitTunnel.go

@@ -35,6 +35,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/Psiphon-Inc/goarista/monotime"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 )
 
@@ -83,7 +84,7 @@ type SplitTunnelClassifier struct {
 
 type classification struct {
 	isUntunneled bool
-	expiry       time.Time
+	expiry       monotime.Time
 }
 
 func NewSplitTunnelClassifier(config *Config, tunneler Tunneler) *SplitTunnelClassifier {
@@ -161,7 +162,7 @@ func (classifier *SplitTunnelClassifier) IsUntunneled(targetAddress string) bool
 	classifier.mutex.RLock()
 	cachedClassification, ok := classifier.cache[targetAddress]
 	classifier.mutex.RUnlock()
-	if ok && cachedClassification.expiry.After(time.Now()) {
+	if ok && cachedClassification.expiry.After(monotime.Now()) {
 		return cachedClassification.isUntunneled
 	}
 
@@ -171,7 +172,7 @@ func (classifier *SplitTunnelClassifier) IsUntunneled(targetAddress string) bool
 		NoticeAlert("failed to resolve address for split tunnel classification: %s", err)
 		return false
 	}
-	expiry := time.Now().Add(ttl)
+	expiry := monotime.Now().Add(ttl)
 
 	isUntunneled := classifier.ipAddressInRoutes(ipAddr)
 

psiphon/tunnel.go

@@ -33,6 +33,7 @@ import (
 	"time"
 
 	"github.com/Psiphon-Inc/crypto/ssh"
+	"github.com/Psiphon-Inc/goarista/monotime"
 	regen "github.com/Psiphon-Inc/goregen"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/transferstats"
@@ -81,7 +82,7 @@ type Tunnel struct {
 	signalPortForwardFailure     chan struct{}
 	totalPortForwardFailures     int
 	establishDuration            time.Duration
-	establishedTime              time.Time
+	establishedTime              monotime.Time
 	dialStats                    *TunnelDialStats
 	newClientVerificationPayload chan string
 }
@@ -118,8 +119,7 @@ func EstablishTunnel(
 	sessionId string,
 	pendingConns *common.Conns,
 	serverEntry *ServerEntry,
-	establishStartTime time.Time,
-	establishNetworkWaitDuration time.Duration,
+	adjustedEstablishStartTime monotime.Time,
 	tunnelOwner TunnelOwner) (tunnel *Tunnel, err error) {
 
 	selectedProtocol, err := selectProtocol(config, serverEntry)
@@ -179,8 +179,6 @@ func EstablishTunnel(
 		}
 	}
 
-	tunnel.establishedTime = time.Now()
-
 	// establishDuration is the elapsed time between the controller starting tunnel
 	// establishment and this tunnel being established. The reported value represents
 	// how long the user waited between starting the client and having a usable tunnel;
@@ -188,18 +186,10 @@ func EstablishTunnel(
 	// completing automatic reestablishment.
 	//
 	// This time period may include time spent unsuccessfully connecting to other
-	// servers. Time spent waiting for network connectivity is excluded. This duration
-	// calculation doesn't exclude host or device sleep time, except that which is
-	// included in establishNetworkWaitDuration.
-	tunnel.establishDuration =
-		time.Duration(tunnel.establishedTime.Sub(establishStartTime).Nanoseconds() -
-			establishNetworkWaitDuration.Nanoseconds())
-
-	// A negative duration typically shouldn't happen, unless the user changes
-	// the OS clock. Always report 0 in this case.
-	if tunnel.establishDuration < 0 {
-		tunnel.establishDuration = 0
-	}
+	// servers. Time spent waiting for network connectivity is excluded.
+	tunnel.establishDuration = monotime.Since(adjustedEstablishStartTime)
+
+	tunnel.establishedTime = monotime.Now()
 
 	// Now that network operations are complete, cancel interruptibility
 	pendingConns.Remove(dialConn)
@@ -825,9 +815,9 @@ func makeRandomPeriod(min, max time.Duration) time.Duration {
 func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 	defer tunnel.operateWaitGroup.Done()
 
-	lastBytesReceivedTime := time.Now()
+	lastBytesReceivedTime := monotime.Now()
 
-	lastTotalBytesTransferedTime := time.Now()
+	lastTotalBytesTransferedTime := monotime.Now()
 	totalSent := int64(0)
 	totalReceived := int64(0)
 
@@ -954,15 +944,15 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 				tunnel.serverEntry.IpAddress)
 
 			if received > 0 {
-				lastBytesReceivedTime = time.Now()
+				lastBytesReceivedTime = monotime.Now()
 			}
 
 			totalSent += sent
 			totalReceived += received
 
-			if lastTotalBytesTransferedTime.Add(TOTAL_BYTES_TRANSFERRED_NOTICE_PERIOD).Before(time.Now()) {
+			if lastTotalBytesTransferedTime.Add(TOTAL_BYTES_TRANSFERRED_NOTICE_PERIOD).Before(monotime.Now()) {
 				NoticeTotalBytesTransferred(tunnel.serverEntry.IpAddress, totalSent, totalReceived)
-				lastTotalBytesTransferedTime = time.Now()
+				lastTotalBytesTransferedTime = monotime.Now()
 			}
 
 			// Only emit the frequent BytesTransferred notice when tunnel is not idle.
@@ -978,7 +968,7 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 			statsTimer.Reset(nextStatusRequestPeriod())
 
 		case <-sshKeepAliveTimer.C:
-			if lastBytesReceivedTime.Add(TUNNEL_SSH_KEEP_ALIVE_PERIODIC_INACTIVE_PERIOD).Before(time.Now()) {
+			if lastBytesReceivedTime.Add(TUNNEL_SSH_KEEP_ALIVE_PERIODIC_INACTIVE_PERIOD).Before(monotime.Now()) {
 				select {
 				case signalSshKeepAlive <- time.Duration(*tunnel.config.TunnelSshKeepAlivePeriodicTimeoutSeconds) * time.Second:
 				default:
@@ -992,7 +982,7 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 			NoticeInfo("port forward failures for %s: %d",
 				tunnel.serverEntry.IpAddress, tunnel.totalPortForwardFailures)
 
-			if lastBytesReceivedTime.Add(TUNNEL_SSH_KEEP_ALIVE_PROBE_INACTIVE_PERIOD).Before(time.Now()) {
+			if lastBytesReceivedTime.Add(TUNNEL_SSH_KEEP_ALIVE_PROBE_INACTIVE_PERIOD).Before(monotime.Now()) {
 				select {
 				case signalSshKeepAlive <- time.Duration(*tunnel.config.TunnelSshKeepAliveProbeTimeoutSeconds) * time.Second:
 				default:
@@ -1029,7 +1019,9 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 	// the handshake response as the absolute tunnel start time. This time
 	// will be slightly earlier than the actual tunnel activation time, as the
 	// client has to receive and parse the response and activate the tunnel.
-	//
+
+	tunnelStartTime := tunnel.serverContext.serverHandshakeTimestamp
+
 	// For the tunnel duration calculation, we use the local clock. The start time
 	// is tunnel.establishedTime as recorded when the tunnel was established. For the
 	// end time, we do not use the current time as we may now be long past the
@@ -1049,6 +1041,8 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 	// the last-received-time scheme can undercount tunnel durations by up to
 	// TUNNEL_SSH_KEEP_ALIVE_PERIOD_MAX to idle tunnels.
 
+	tunnelDuration := tunnel.monitoredConn.GetLastActivityMonotime().Sub(tunnel.establishedTime)
+
 	// Tunnel does not have a serverContext when DisableApi is set.
 	if tunnel.serverContext != nil && !tunnel.IsDiscarded() {
 		err := RecordTunnelStats(
@@ -1056,8 +1050,8 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 			tunnel.serverContext.tunnelNumber,
 			tunnel.serverEntry.IpAddress,
 			fmt.Sprintf("%d", tunnel.establishDuration),
-			tunnel.serverContext.serverHandshakeTimestamp,
-			fmt.Sprintf("%d", tunnel.monitoredConn.GetLastActivityTime().Sub(tunnel.establishedTime)),
+			tunnelStartTime,
+			fmt.Sprintf("%d", tunnelDuration),
 			totalSent,
 			totalReceived)
 		if err != nil {