feat: add TunnelTime metric

README.md

@@ -42,11 +42,7 @@ To fetch and update MMDB files from [DB-IP](https://db-ip.com), you can do somet
 
 ## Full Working Example: Try It!
 
-Fetch dependencies for this demo:
-```
-GO111MODULE=off go get github.com/prometheus/prometheus/cmd/...
-```
-If that doesn't work, download the [prometheus](https://prometheus.io/download/) binary directly.
+Download the [Prometheus](https://prometheus.io/download/) binary.
 
 
 ### Run the server
@@ -60,7 +56,7 @@ In production, you may want to specify `-ip_country_db` to get per-country metri
 ### Run the Prometheus scraper for metrics collection
 On Terminal 2, start prometheus scraper for metrics collection:
 ```
-$(go env GOPATH)/bin/prometheus --config.file=cmd/outline-ss-server/prometheus_example.yml
+prometheus --config.file=cmd/outline-ss-server/prometheus_example.yml
 ```
 
 ### Run the SOCKS-to-Shadowsocks client

cmd/outline-ss-server/metrics.go

@@ -16,7 +16,9 @@ package main
 
 import (
 	"fmt"
+	"net"
 	"strconv"
+	"sync"
 	"time"
 
 	"github.com/Jigsaw-Code/outline-ss-server/ipinfo"
@@ -25,8 +27,15 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 )
 
+// How often to report the active IP key TunnelTime.
+const tunnelTimeTrackerReportingInterval = 5 * time.Second
+
+// Now is stubbable for testing.
+var Now = time.Now
+
 type outlineMetrics struct {
 	ipinfo.IPInfoMap
+	tunnelTimeTracker
 
 	buildInfo            *prometheus.GaugeVec
 	accessKeys           prometheus.Gauge
@@ -36,6 +45,9 @@ type outlineMetrics struct {
 	timeToCipherMs       *prometheus.HistogramVec
 	// TODO: Add time to first byte.
 
+	TunnelTimePerKey      *prometheus.CounterVec
+	TunnelTimePerLocation *prometheus.CounterVec
+
 	tcpProbes               *prometheus.HistogramVec
 	tcpOpenConnections      *prometheus.CounterVec
 	tcpClosedConnections    *prometheus.CounterVec
@@ -49,9 +61,106 @@ type outlineMetrics struct {
 var _ service.TCPMetrics = (*outlineMetrics)(nil)
 var _ service.UDPMetrics = (*outlineMetrics)(nil)
 
+type ReportTunnelTimeFunc func(IPKey, ipinfo.IPInfo, time.Duration)
+
+type activeClient struct {
+	mu              sync.Mutex
+	IPKey           IPKey
+	clientInfo      ipinfo.IPInfo
+	connectionCount int
+	startTime       time.Time
+}
+
+type IPKey struct {
+	ip        string
+	accessKey string
+}
+
+type tunnelTimeTracker struct {
+	mu               sync.Mutex
+	activeClients    map[IPKey]*activeClient
+	reportTunnelTime ReportTunnelTimeFunc
+}
+
+// Reports time connected for all active clients, called at a regular interval.
+func (t *tunnelTimeTracker) reportAll(now time.Time) {
+	if len(t.activeClients) == 0 {
+		logger.Debugf("No active clients. No TunnelTime activity to report.")
+		return
+	}
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	for _, c := range t.activeClients {
+		t.reportDuration(c, now)
+	}
+}
+
+// Reports time connected for a given active client.
+func (t *tunnelTimeTracker) reportDuration(c *activeClient, now time.Time) {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	connDuration := now.Sub(c.startTime)
+	logger.Debugf("Reporting activity for key `%v`, duration: %v", c.IPKey.accessKey, connDuration)
+	t.reportTunnelTime(c.IPKey, c.clientInfo, connDuration)
+	// Reset the start time now that it's been reported.
+	c.startTime = Now()
+}
+
+// Registers a new active connection for a client [net.Addr] and access key.
+func (t *tunnelTimeTracker) startConnection(clientInfo ipinfo.IPInfo, clientAddr net.Addr, accessKey string) {
+	hostname, _, _ := net.SplitHostPort(clientAddr.String())
+	ipKey := IPKey{ip: hostname, accessKey: accessKey}
+
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	c, exists := t.activeClients[ipKey]
+	if !exists {
+		c = &activeClient{
+			IPKey:      ipKey,
+			clientInfo: clientInfo,
+			startTime:  Now(),
+		}
+	}
+	c.connectionCount++
+	t.activeClients[ipKey] = c
+}
+
+// Removes an active connection for a client [net.Addr] and access key.
+func (t *tunnelTimeTracker) stopConnection(clientAddr net.Addr, accessKey string) {
+	hostname, _, _ := net.SplitHostPort(clientAddr.String())
+	ipKey := IPKey{ip: hostname, accessKey: accessKey}
+
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	c, exists := t.activeClients[ipKey]
+	if !exists {
+		logger.Warningf("Failed to find active client")
+		return
+	}
+	c.mu.Lock()
+	c.connectionCount--
+	c.mu.Unlock()
+	if c.connectionCount <= 0 {
+		t.reportDuration(c, Now())
+		delete(t.activeClients, ipKey)
+		return
+	}
+}
+
+func newTunnelTimeTracker(report ReportTunnelTimeFunc) *tunnelTimeTracker {
+	tracker := &tunnelTimeTracker{activeClients: make(map[IPKey]*activeClient), reportTunnelTime: report}
+	ticker := time.NewTicker(tunnelTimeTrackerReportingInterval)
+	go func() {
+		for t := range ticker.C {
+			tracker.reportAll(t)
+		}
+	}()
+	return tracker
+}
+
 // newPrometheusOutlineMetrics constructs a metrics object that uses
-// `ipCountryDB` to convert IP addresses to countries, and reports all
-// metrics to Prometheus via `registerer`.  `ipCountryDB` may be nil, but
+// `ip2info` to convert IP addresses to countries, and reports all
+// metrics to Prometheus via `registerer`. `ip2info` may be nil, but
 // `registerer` must not be.
 func newPrometheusOutlineMetrics(ip2info ipinfo.IPInfoMap, registerer prometheus.Registerer) *outlineMetrics {
 	m := &outlineMetrics{
@@ -104,6 +213,16 @@ func newPrometheusOutlineMetrics(ip2info ipinfo.IPInfoMap, registerer prometheus
 					float64(7 * 24 * time.Hour.Milliseconds()), // Week
 				},
 			}, []string{"status"}),
+		TunnelTimePerKey: prometheus.NewCounterVec(prometheus.CounterOpts{
+			Namespace: "shadowsocks",
+			Name:      "tunnel_time_seconds",
+			Help:      "Time at least 1 connection was open for a (IP, access key) pair, per key",
+		}, []string{"access_key"}),
+		TunnelTimePerLocation: prometheus.NewCounterVec(prometheus.CounterOpts{
+			Namespace: "shadowsocks",
+			Name:      "tunnel_time_seconds_per_location",
+			Help:      "Time at least 1 connection was open for a (IP, access key) pair, per location",
+		}, []string{"location", "asn"}),
 		dataBytes: prometheus.NewCounterVec(
 			prometheus.CounterOpts{
 				Namespace: "shadowsocks",
@@ -145,10 +264,12 @@ func newPrometheusOutlineMetrics(ip2info ipinfo.IPInfoMap, registerer prometheus
 				Help:      "Entries removed from the UDP NAT table",
 			}),
 	}
+	m.tunnelTimeTracker = *newTunnelTimeTracker(m.addTunnelTime)
 
 	// TODO: Is it possible to pass where to register the collectors?
 	registerer.MustRegister(m.buildInfo, m.accessKeys, m.ports, m.tcpProbes, m.tcpOpenConnections, m.tcpClosedConnections, m.tcpConnectionDurationMs,
-		m.dataBytes, m.dataBytesPerLocation, m.timeToCipherMs, m.udpPacketsFromClientPerLocation, m.udpAddedNatEntries, m.udpRemovedNatEntries)
+		m.dataBytes, m.dataBytesPerLocation, m.timeToCipherMs, m.udpPacketsFromClientPerLocation, m.udpAddedNatEntries, m.udpRemovedNatEntries,
+		m.TunnelTimePerKey, m.TunnelTimePerLocation)
 	return m
 }
 
@@ -165,6 +286,16 @@ func (m *outlineMetrics) AddOpenTCPConnection(clientInfo ipinfo.IPInfo) {
 	m.tcpOpenConnections.WithLabelValues(clientInfo.CountryCode.String(), asnLabel(clientInfo.ASN)).Inc()
 }
 
+// Reports total time connected (i.e. TunnelTime), by access key and by country.
+func (m *outlineMetrics) addTunnelTime(ipKey IPKey, clientInfo ipinfo.IPInfo, duration time.Duration) {
+	m.TunnelTimePerKey.WithLabelValues(ipKey.accessKey).Add(duration.Seconds())
+	m.TunnelTimePerLocation.WithLabelValues(clientInfo.CountryCode.String(), asnLabel(clientInfo.ASN)).Add(duration.Seconds())
+}
+
+func (m *outlineMetrics) AddAuthenticatedTCPConnection(clientInfo ipinfo.IPInfo, clientAddr net.Addr, accessKey string) {
+	m.tunnelTimeTracker.startConnection(clientInfo, clientAddr, accessKey)
+}
+
 // addIfNonZero helps avoid the creation of series that are always zero.
 func addIfNonZero(value int64, counterVec *prometheus.CounterVec, lvs ...string) {
 	if value > 0 {
@@ -179,7 +310,7 @@ func asnLabel(asn int) string {
 	return fmt.Sprint(asn)
 }
 
-func (m *outlineMetrics) AddClosedTCPConnection(clientInfo ipinfo.IPInfo, accessKey, status string, data metrics.ProxyMetrics, duration time.Duration) {
+func (m *outlineMetrics) AddClosedTCPConnection(clientInfo ipinfo.IPInfo, clientAddr net.Addr, accessKey, status string, data metrics.ProxyMetrics, duration time.Duration) {
 	m.tcpClosedConnections.WithLabelValues(clientInfo.CountryCode.String(), asnLabel(clientInfo.ASN), status, accessKey).Inc()
 	m.tcpConnectionDurationMs.WithLabelValues(status).Observe(duration.Seconds() * 1000)
 	addIfNonZero(data.ClientProxy, m.dataBytes, "c>p", "tcp", accessKey)
@@ -190,6 +321,8 @@ func (m *outlineMetrics) AddClosedTCPConnection(clientInfo ipinfo.IPInfo, access
 	addIfNonZero(data.TargetProxy, m.dataBytesPerLocation, "p<t", "tcp", clientInfo.CountryCode.String(), asnLabel(clientInfo.ASN))
 	addIfNonZero(data.ProxyClient, m.dataBytes, "c<p", "tcp", accessKey)
 	addIfNonZero(data.ProxyClient, m.dataBytesPerLocation, "c<p", "tcp", clientInfo.CountryCode.String(), asnLabel(clientInfo.ASN))
+
+	m.tunnelTimeTracker.stopConnection(clientAddr, accessKey)
 }
 
 func (m *outlineMetrics) AddUDPPacketFromClient(clientInfo ipinfo.IPInfo, accessKey, status string, clientProxyBytes, proxyTargetBytes int) {
@@ -207,12 +340,16 @@ func (m *outlineMetrics) AddUDPPacketFromTarget(clientInfo ipinfo.IPInfo, access
 	addIfNonZero(int64(proxyClientBytes), m.dataBytesPerLocation, "c<p", "udp", clientInfo.CountryCode.String(), asnLabel(clientInfo.ASN))
 }
 
-func (m *outlineMetrics) AddUDPNatEntry() {
+func (m *outlineMetrics) AddUDPNatEntry(clientInfo ipinfo.IPInfo, clientAddr net.Addr, accessKey string) {
 	m.udpAddedNatEntries.Inc()
+
+	m.tunnelTimeTracker.startConnection(clientInfo, clientAddr, accessKey)
 }
 
-func (m *outlineMetrics) RemoveUDPNatEntry() {
+func (m *outlineMetrics) RemoveUDPNatEntry(clientAddr net.Addr, accessKey string) {
 	m.udpRemovedNatEntries.Inc()
+
+	m.tunnelTimeTracker.stopConnection(clientAddr, accessKey)
 }
 
 func (m *outlineMetrics) AddTCPProbe(status, drainResult string, port int, clientProxyBytes int64) {