Irregular tunnel enhancements

- Use short term client IP cache to distinguish expected
  replay cases such as meek retries

- Log elapsed time between encountering duplicates

- Log duplicate seed value

psiphon/common/errors/errors.go

@@ -40,6 +40,14 @@ func TraceNew(message string) error {
 	return fmt.Errorf("%s#%d: %w", stacktrace.GetFunctionName(pc), line, err)
 }
 
+// BackTraceNew returns a new error with the given message, wrapped with the
+// caller stack frame information going back up the stack until the caller of
+// the specified function name is encountered.
+func BackTraceNew(backTraceFuncName, message string) error {
+	err := fmt.Errorf("%s", message)
+	return fmt.Errorf("%s%w", backTrace(backTraceFuncName), err)
+}
+
 // Tracef returns a new error with the given formatted message, wrapped with
 // the caller stack frame information.
 func Tracef(format string, args ...interface{}) error {
@@ -66,3 +74,25 @@ func TraceMsg(err error, message string) error {
 	pc, _, line, _ := runtime.Caller(1)
 	return fmt.Errorf("%s#%d: %s: %w", stacktrace.GetFunctionName(pc), line, message, err)
 }
+
+func backTrace(backTraceFuncName string) string {
+	stop := false
+	trace := ""
+	// Skip starts at 2, assuming backTrace is called as a helper function.
+	for n := 2; ; n++ {
+		pc, _, line, ok := runtime.Caller(n)
+		if !ok {
+			break
+		}
+		funcName := stacktrace.GetFunctionName(pc)
+		trace = fmt.Sprintf("%s#%d: ", funcName, line) + trace
+		if stop {
+			break
+		}
+		if funcName == backTraceFuncName {
+			// Stop after the _next_ function
+			stop = true
+		}
+	}
+	return trace
+}

psiphon/common/net.go

@@ -24,6 +24,7 @@ import (
 	"context"
 	"net"
 	"net/http"
+	"strconv"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -82,6 +83,19 @@ func IPAddressFromAddr(addr net.Addr) string {
 	return ipAddress
 }
 
+// PortFromAddr is a helper which extracts a port number from a net.Addr or
+// returns 0 if there is no port number.
+func PortFromAddr(addr net.Addr) int {
+	port := 0
+	if addr != nil {
+		_, portStr, err := net.SplitHostPort(addr.String())
+		if err == nil {
+			port, _ = strconv.Atoi(portStr)
+		}
+	}
+	return port
+}
+
 // Conns is a synchronized list of Conns that is used to coordinate
 // interrupting a set of goroutines establishing connections, or
 // close a set of open connections, etc.

psiphon/common/obfuscator/history.go

@@ -20,40 +20,135 @@
 package obfuscator
 
 import (
+	"encoding/hex"
 	"time"
 
+	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	lrucache "github.com/cognusion/go-cache-lru"
 )
 
 const (
-	OBFUSCATE_SEED_HISTORY_TTL         = 24 * time.Hour
-	OBFUSCATE_SEED_HISTORY_MAX_ENTRIES = 1000000
+	HISTORY_SEED_TTL              = 24 * time.Hour
+	HISTORY_SEED_MAX_ENTRIES      = 1000000
+	HISTORY_CLIENT_IP_TTL         = 2 * time.Minute
+	HISTORY_CLIENT_IP_MAX_ENTRIES = 10000
 )
 
 // SeedHistory maintains a history of recently observed obfuscation seed values.
+// This history is used to identify duplicate seed messages.
+//
+// As a heurististic to exclude expected duplicates, due to, for example, meek
+// retries, the source client IP is retained for comparison for a short
+// duration -- long enough to cover meek retries without retaining client
+// IPs in memory long past a client connection lifetime.
 type SeedHistory struct {
-	history *lrucache.Cache
+	seedTTL        time.Duration
+	seedToTime     *lrucache.Cache
+	seedToClientIP *lrucache.Cache
 }
 
-// NewSeedHistory creates a new SeedHistory.
-func NewSeedHistory() *SeedHistory {
+type SeedHistoryConfig struct {
+	SeedTTL            time.Duration
+	SeedMaxEntries     int
+	ClientIPTTL        time.Duration
+	ClientIPMaxEntries int
+}
+
+// NewSeedHistory creates a new SeedHistory. Config is optional.
+func NewSeedHistory(config *SeedHistoryConfig) *SeedHistory {
 
-	// TTL and MAX_ENTRIES are tuned to provide an effective history size while
-	// bounding the amount of memory that will be used. While a probabilistic
-	// data structure such as a Bloom filter would provide a smaller memory
-	// footprint, we wish to avoid the associated risk of false positives.
+	// Default TTL and MAX_ENTRIES are tuned to provide an effective history size
+	// while bounding the amount of memory that will be used. While a
+	// probabilistic data structure such as a Bloom filter would provide a
+	// smaller memory footprint, we wish to avoid the associated risk of false
+	// positives.
+	//
+	// Limitation: As go-cache-lru does not currently support iterating over all
+	// items (without making a full copy of the enture cache), the client IP with
+	// shorter TTL is stored in a second, smaller cache instead of the same cache
+	// with a a pruner. This incurs some additional overhead, as the seed key is
+	// stored twice, once in each cache.
+
+	useConfig := SeedHistoryConfig{
+		SeedTTL:            HISTORY_SEED_TTL,
+		SeedMaxEntries:     HISTORY_SEED_MAX_ENTRIES,
+		ClientIPTTL:        HISTORY_CLIENT_IP_TTL,
+		ClientIPMaxEntries: HISTORY_CLIENT_IP_MAX_ENTRIES,
+	}
+
+	if config != nil {
+		if config.SeedTTL != 0 {
+			useConfig.SeedTTL = config.SeedTTL
+		}
+		if config.SeedMaxEntries != 0 {
+			useConfig.SeedMaxEntries = config.SeedMaxEntries
+		}
+		if config.ClientIPTTL != 0 {
+			useConfig.ClientIPTTL = config.ClientIPTTL
+		}
+		if config.ClientIPMaxEntries != 0 {
+			useConfig.ClientIPMaxEntries = config.ClientIPMaxEntries
+		}
+	}
 
 	return &SeedHistory{
-		history: lrucache.NewWithLRU(
-			OBFUSCATE_SEED_HISTORY_TTL,
+		seedTTL: useConfig.SeedTTL,
+
+		seedToTime: lrucache.NewWithLRU(
+			useConfig.SeedTTL,
 			1*time.Minute,
-			OBFUSCATE_SEED_HISTORY_MAX_ENTRIES),
+			useConfig.SeedMaxEntries),
+
+		seedToClientIP: lrucache.NewWithLRU(
+			useConfig.ClientIPTTL,
+			30*time.Second,
+			useConfig.ClientIPMaxEntries),
 	}
 }
 
 // AddNew adds a new seed value to the history. If the seed value is already
-// in the history, AddNew returns false.
-func (s *SeedHistory) AddNew(seed []byte) bool {
-	err := s.history.Add(string(seed), true, 0)
-	return err == nil
+// in the history, and an expected case such as a meek retry is ruled out,
+// AddNew returns false.
+//
+// When a duplicate seed is found, a common.LogFields instance is returned,
+// populated with event data. Log fields may be returned in either the false
+// or true case.
+func (h *SeedHistory) AddNew(clientIP string, seed []byte) (bool, *common.LogFields) {
+	key := string(seed)
+
+	// Limitation: go-cache-lru does not currently support atomically setting if
+	// a key is unset and otherwise _returning the corresponding value_. There is
+	// an unlikely possibility that this Add and the following Get don't see the
+	// same existing key/value state.
+
+	if h.seedToTime.Add(key, time.Now(), 0) == nil {
+		// Seed was not already in cache
+		h.seedToClientIP.Set(key, clientIP, 0)
+		return true, nil
+	}
+
+	previousTime, ok := h.seedToTime.Get(key)
+	if !ok {
+		// Inconsistent Add/Get state: assume cache item just expired.
+		previousTime = h.seedTTL
+	}
+
+	logFields := common.LogFields{
+		"duplicate_seed":            hex.EncodeToString(seed),
+		"duplicate_elapsed_time_ms": int64(time.Since(previousTime.(time.Time)) / time.Millisecond),
+	}
+
+	previousClientIP, ok := s.seedToClientIP.Get(key)
+	if ok {
+		if clientIP == previousClientIP.(string) {
+			logFields["duplicate_client_ip"] = "equal"
+			return true, &logFields
+		} else {
+			logFields["duplicate_client_ip"] = "unequal"
+			return false, &logFields
+		}
+	}
+
+	logFields["duplicate_client_ip"] = "unknown"
+	return false, &logFields
 }

psiphon/common/obfuscator/obfuscatedSshConn.go

@@ -127,7 +127,7 @@ func NewObfuscatedSSHConn(
 	obfuscationPaddingPRNGSeed *prng.Seed,
 	minPadding, maxPadding *int,
 	seedHistory *SeedHistory,
-	irregularLogger func(error)) (*ObfuscatedSSHConn, error) {
+	irregularLogger func(clientIP string, logFields common.LogFields)) (*ObfuscatedSSHConn, error) {
 
 	var err error
 	var obfuscator *Obfuscator
@@ -151,11 +151,13 @@ func NewObfuscatedSSHConn(
 	} else {
 		// NewServerObfuscator reads a seed message from conn
 		obfuscator, err = NewServerObfuscator(
-			conn, &ObfuscatorConfig{
+			&ObfuscatorConfig{
 				Keyword:         obfuscationKeyword,
 				SeedHistory:     seedHistory,
 				IrregularLogger: irregularLogger,
-			})
+			},
+			common.IPAddressFromAddr(conn.RemoteAddr()),
+			conn)
 		if err != nil {
 
 			// Obfuscated SSH protocol spec:
@@ -217,7 +219,7 @@ func NewServerObfuscatedSSHConn(
 	conn net.Conn,
 	obfuscationKeyword string,
 	seedHistory *SeedHistory,
-	irregularLogger func(error)) (*ObfuscatedSSHConn, error) {
+	irregularLogger func(clientIP string, logFields common.LogFields)) (*ObfuscatedSSHConn, error) {
 
 	return NewObfuscatedSSHConn(
 		OBFUSCATION_CONN_MODE_SERVER,

psiphon/common/obfuscator/obfuscator.go

@@ -70,7 +70,7 @@ type ObfuscatorConfig struct {
 	// server obfuscators.
 
 	SeedHistory     *SeedHistory
-	IrregularLogger func(error)
+	IrregularLogger func(clientIP string, logFields common.LogFields)
 }
 
 // NewClientObfuscator creates a new Obfuscator, staging a seed message to be
@@ -93,7 +93,7 @@ func NewClientObfuscator(
 		return nil, errors.Trace(err)
 	}
 
-	clientToServerCipher, serverToClientCipher, err := initObfuscatorCiphers(obfuscatorSeed, config)
+	clientToServerCipher, serverToClientCipher, err := initObfuscatorCiphers(config, obfuscatorSeed)
 	if err != nil {
 		return nil, errors.Trace(err)
 	}
@@ -141,11 +141,14 @@ func NewClientObfuscator(
 // ObfuscatorConfig.PaddingPRNGSeed is not used, as the server obtains a PRNG
 // seed from the client's initial obfuscator message; this scheme allows for
 // optional replay of the downstream obfuscator padding.
+//
+// The clientIP value is used by the SeedHistory, which retains client IP values
+// for a short time. See SeedHistory documentation.
 func NewServerObfuscator(
-	clientReader io.Reader, config *ObfuscatorConfig) (obfuscator *Obfuscator, err error) {
+	config *ObfuscatorConfig, clientIP string, clientReader io.Reader) (obfuscator *Obfuscator, err error) {
 
 	clientToServerCipher, serverToClientCipher, paddingPRNGSeed, err := readSeedMessage(
-		clientReader, config)
+		config, clientIP, clientReader)
 	if err != nil {
 		return nil, errors.Trace(err)
 	}
@@ -195,7 +198,7 @@ func (obfuscator *Obfuscator) ObfuscateServerToClient(buffer []byte) {
 }
 
 func initObfuscatorCiphers(
-	obfuscatorSeed []byte, config *ObfuscatorConfig) (*rc4.Cipher, *rc4.Cipher, error) {
+	config *ObfuscatorConfig, obfuscatorSeed []byte) (*rc4.Cipher, *rc4.Cipher, error) {
 
 	clientToServerKey, err := deriveKey(obfuscatorSeed, []byte(config.Keyword), []byte(OBFUSCATE_CLIENT_TO_SERVER_IV))
 	if err != nil {
@@ -267,7 +270,9 @@ func makeSeedMessage(
 }
 
 func readSeedMessage(
-	clientReader io.Reader, config *ObfuscatorConfig) (*rc4.Cipher, *rc4.Cipher, *prng.Seed, error) {
+	config *ObfuscatorConfig,
+	clientIP string,
+	clientReader io.Reader) (*rc4.Cipher, *rc4.Cipher, *prng.Seed, error) {
 
 	seed := make([]byte, OBFUSCATE_SEED_LENGTH)
 	_, err := io.ReadFull(clientReader, seed)
@@ -290,17 +295,26 @@ func readSeedMessage(
 	// message bytes) are not considered a reliable indicator of irregular
 	// events.
 
+	// To distinguish different cases, irregular tunnel logs should indicate
+	// which function called NewServerObfuscator.
+	errBackTrace := "obfuscator.NewServerObfuscator"
+
 	if config.SeedHistory != nil {
-		if !config.SeedHistory.AddNew(seed) {
-			err := errors.TraceNew("duplicate obfuscation seed")
+		ok, duplicateLogFields := config.SeedHistory.AddNew(clientIP, seed)
+		errStr := "duplicate obfuscation seed"
+		if duplicateLogFields != nil {
 			if config.IrregularLogger != nil {
-				config.IrregularLogger(err)
+				setIrregularTunnelErrorLogField(
+					*duplicateLogFields, errors.BackTraceNew(errBackTrace, errStr))
+				config.IrregularLogger(clientIP, *duplicateLogFields)
 			}
-			return nil, nil, nil, err
+		}
+		if !ok {
+			return nil, nil, nil, errors.TraceNew(errStr)
 		}
 	}
 
-	clientToServerCipher, serverToClientCipher, err := initObfuscatorCiphers(seed, config)
+	clientToServerCipher, serverToClientCipher, err := initObfuscatorCiphers(config, seed)
 	if err != nil {
 		return nil, nil, nil, errors.Trace(err)
 	}
@@ -330,20 +344,24 @@ func readSeedMessage(
 		return nil, nil, nil, errors.Trace(err)
 	}
 
+	errStr := ""
+
 	if magicValue != OBFUSCATE_MAGIC_VALUE {
-		err := errors.TraceNew("invalid magic value")
-		if config.IrregularLogger != nil {
-			config.IrregularLogger(err)
-		}
-		return nil, nil, nil, err
+		errStr = "invalid magic value"
 	}
 
-	if paddingLength < 0 || paddingLength > OBFUSCATE_MAX_PADDING {
-		err := errors.TraceNew("invalid padding length")
+	if errStr == "" && (paddingLength < 0 || paddingLength > OBFUSCATE_MAX_PADDING) {
+		errStr = "invalid padding length"
+	}
+
+	if errStr != "" {
 		if config.IrregularLogger != nil {
-			config.IrregularLogger(err)
+			errLogFields := make(common.LogFields)
+			setIrregularTunnelErrorLogField(
+				errLogFields, errors.BackTraceNew(errBackTrace, errStr))
+			config.IrregularLogger(clientIP, errLogFields)
 		}
-		return nil, nil, nil, err
+		return nil, nil, nil, errors.TraceNew(errStr)
 	}
 
 	padding := make([]byte, paddingLength)
@@ -375,3 +393,9 @@ func readSeedMessage(
 
 	return clientToServerCipher, serverToClientCipher, paddingPRNGSeed, nil
 }
+
+func setIrregularTunnelErrorLogField(
+	logFields common.LogFields, tunnelError error) {
+
+	logFields["tunnel_error"] = tunnelError
+}

psiphon/common/obfuscator/obfuscator_test.go

@@ -28,6 +28,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/crypto/ssh"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/prng"
 )
@@ -43,12 +44,17 @@ func TestObfuscator(t *testing.T) {
 		t.Fatalf("prng.NewSeed failed: %s", err)
 	}
 
+	var irregularLogFields common.LogFields
+
 	config := &ObfuscatorConfig{
 		Keyword:         keyword,
 		MaxPadding:      &maxPadding,
 		PaddingPRNGSeed: paddingPRNGSeed,
-		SeedHistory:     NewSeedHistory(),
-		IrregularLogger: func(err error) { t.Logf("IrregularLogger: %s", err) },
+		SeedHistory:     NewSeedHistory(&SeedHistoryConfig{ClientIPTTL: 500 * time.Millisecond}),
+		IrregularLogger: func(_ string, logFields common.LogFields) {
+			irregularLogFields = logFields
+			t.Logf("IrregularLogger: %+v", logFields)
+		},
 	}
 
 	client, err := NewClientObfuscator(config)
@@ -58,7 +64,7 @@ func TestObfuscator(t *testing.T) {
 
 	seedMessage := client.SendSeedMessage()
 
-	server, err := NewServerObfuscator(bytes.NewReader(seedMessage), config)
+	server, err := NewServerObfuscator(config, "", bytes.NewReader(seedMessage))
 	if err != nil {
 		t.Fatalf("NewServerObfuscator failed: %s", err)
 	}
@@ -83,12 +89,59 @@ func TestObfuscator(t *testing.T) {
 		t.Fatalf("unexpected client message")
 	}
 
-	// Test: duplicate obfuscation seed
+	// Test: duplicate obfuscation seed cases
+
+	client, err = NewClientObfuscator(config)
+	if err != nil {
+		t.Fatalf("NewClientObfuscator failed: %s", err)
+	}
+
+	seedMessage = client.SendSeedMessage()
+
+	clientIP := "192.168.0.1"
+
+	_, err = NewServerObfuscator(config, clientIP, bytes.NewReader(seedMessage))
+	if err != nil {
+		t.Fatalf("NewServerObfuscator failed: %s", err)
+	}
+
+	irregularLogFields = nil
+
+	_, err = NewServerObfuscator(config, clientIP, bytes.NewReader(seedMessage))
+	if err != nil {
+		t.Fatalf("NewServerObfuscator failed: %s", err)
+	}
+
+	duplicateClientID := irregularLogFields["duplicate_client_ip"]
+	if duplicateClientID != "equal" {
+		t.Fatalf("Unexpected duplicate_client_ip: %s", duplicateClientID)
+	}
+
+	irregularLogFields = nil
 
-	server, err = NewServerObfuscator(bytes.NewReader(seedMessage), config)
+	_, err = NewServerObfuscator(config, "192.168.0.2", bytes.NewReader(seedMessage))
 	if err == nil {
 		t.Fatalf("NewServerObfuscator unexpectedly succeeded")
 	}
+
+	duplicateClientID = irregularLogFields["duplicate_client_ip"]
+	if duplicateClientID != "unequal" {
+		t.Fatalf("Unexpected duplicate_client_ip: %s", duplicateClientID)
+	}
+
+	time.Sleep(600 * time.Millisecond)
+
+	irregularLogFields = nil
+
+	_, err = NewServerObfuscator(config, clientIP, bytes.NewReader(seedMessage))
+	if err == nil {
+		t.Fatalf("NewServerObfuscator unexpectedly succeeded")
+	}
+
+	duplicateClientID = irregularLogFields["duplicate_client_ip"]
+	if duplicateClientID != "unknown" {
+		t.Fatalf("Unexpected duplicate_client_ip: %s", duplicateClientID)
+	}
 }
 
 func TestObfuscatedSSHConn(t *testing.T) {
@@ -131,8 +184,10 @@ func TestObfuscatedSSHConn(t *testing.T) {
 			conn, err = NewServerObfuscatedSSHConn(
 				conn,
 				keyword,
-				NewSeedHistory(),
-				func(err error) { t.Fatalf("IrregularLogger: %s", err) })
+				NewSeedHistory(nil),
+				func(_ string, logFields common.LogFields) {
+					t.Logf("IrregularLogger: %+v", logFields)
+				})
 		}
 
 		if err == nil {

psiphon/common/tactics/tactics.go

@@ -1730,8 +1730,9 @@ func unboxPayload(
 	obfuscatedReader := bytes.NewReader(obfuscatedBoxedPayload[:])
 
 	obfuscator, err := obfuscator.NewServerObfuscator(
-		obfuscatedReader,
-		&obfuscator.ObfuscatorConfig{Keyword: string(obfuscatedKey)})
+		&obfuscator.ObfuscatorConfig{Keyword: string(obfuscatedKey)},
+		"",
+		obfuscatedReader)
 	if err != nil {
 		return nil, errors.Trace(err)
 	}

psiphon/server/api.go

@@ -863,14 +863,7 @@ func getRequestLogFields(
 		logFields["event_name"] = eventName
 	}
 
-	// In psi_web, the space replacement was done to accommodate space
-	// delimited logging, which is no longer required; we retain the
-	// transformation so that stats aggregation isn't impacted.
-	logFields["client_region"] = strings.Replace(geoIPData.Country, " ", "_", -1)
-	logFields["client_city"] = strings.Replace(geoIPData.City, " ", "_", -1)
-	logFields["client_isp"] = strings.Replace(geoIPData.ISP, " ", "_", -1)
-	logFields["client_asn"] = strings.Replace(geoIPData.ASN, " ", "_", -1)
-	logFields["client_aso"] = strings.Replace(geoIPData.ASO, " ", "_", -1)
+	geoIPData.SetLogFields(logFields)
 
 	if len(authorizedAccessTypes) > 0 {
 		logFields["authorized_access_types"] = authorizedAccessTypes

psiphon/server/geoip.go

@@ -28,6 +28,7 @@ import (
 	"os"
 	"path/filepath"
 	"strconv"
+	"strings"
 	"time"
 
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
@@ -68,6 +69,20 @@ func NewGeoIPData() GeoIPData {
 	}
 }
 
+// SetLogFields adds the GeoIPData fields to LogFields, following Psiphon
+// metric field name and format conventions.
+func (g GeoIPData) SetLogFields(logFields LogFields) {
+
+	// In psi_web, the space replacement was done to accommodate space
+	// delimited logging, which is no longer required; we retain the
+	// transformation so that stats aggregation isn't impacted.
+	logFields["client_region"] = strings.Replace(g.Country, " ", "_", -1)
+	logFields["client_city"] = strings.Replace(g.City, " ", "_", -1)
+	logFields["client_isp"] = strings.Replace(g.ISP, " ", "_", -1)
+	logFields["client_asn"] = strings.Replace(g.ASN, " ", "_", -1)
+	logFields["client_aso"] = strings.Replace(g.ASO, " ", "_", -1)
+}
+
 // GeoIPService implements GeoIP lookup and session/GeoIP caching.
 // Lookup is via a MaxMind database; the ReloadDatabase function
 // supports hot reloading of MaxMind data while the server is

psiphon/server/meek.go

@@ -145,7 +145,7 @@ func NewMeekServer(
 		listener:               listener,
 		listenerTunnelProtocol: listenerTunnelProtocol,
 		listenerPort:           listenerPort,
-		obfuscatorSeedHistory:  obfuscator.NewSeedHistory(),
+		obfuscatorSeedHistory:  obfuscator.NewSeedHistory(nil),
 		clientHandler:          clientHandler,
 		openConns:              common.NewConns(),
 		stopBroadcast:          stopBroadcast,
@@ -876,18 +876,20 @@ func (server *MeekServer) getMeekCookiePayload(
 	reader := bytes.NewReader(decodedValue[:])
 
 	obfuscator, err := obfuscator.NewServerObfuscator(
-		reader,
 		&obfuscator.ObfuscatorConfig{
 			Keyword:     server.support.Config.MeekObfuscatedKey,
 			SeedHistory: server.obfuscatorSeedHistory,
-			IrregularLogger: func(err error) {
+			IrregularLogger: func(clientIP string, logFields common.LogFields) {
 				logIrregularTunnel(
+					server.support,
 					server.listenerTunnelProtocol,
 					server.listenerPort,
-					server.support.GeoIPService.Lookup(clientIP),
-					err)
+					clientIP,
+					LogFields(logFields))
 			},
-		})
+		},
+		clientIP,
+		reader)
 	if err != nil {
 		return nil, errors.Trace(err)
 	}

psiphon/server/services.go

@@ -359,16 +359,17 @@ func logServerLoad(server *TunnelServer) {
 }
 
 func logIrregularTunnel(
+	support *SupportServices,
 	listenerTunnelProtocol string,
 	listenerPort int,
-	geoIPData GeoIPData,
-	tunnelError error) {
-
-	irregularTunnel := getRequestLogFields("irregular_tunnel", geoIPData, nil, nil, nil)
-	irregularTunnel["listener_protocol"] = listenerTunnelProtocol
-	irregularTunnel["listener_port_number"] = listenerPort
-	irregularTunnel["tunnel_error"] = tunnelError.Error()
-	log.LogRawFieldsWithTimestamp(irregularTunnel)
+	clientIP string,
+	logFields LogFields) {
+
+	logFields["event_name"] = "irregular_tunnel"
+	logFields["listener_protocol"] = listenerTunnelProtocol
+	logFields["listener_port_number"] = listenerPort
+	support.GeoIPService.Lookup(clientIP).SetLogFields(logFields)
+	log.LogRawFieldsWithTimestamp(logFields)
 }
 
 // SupportServices carries common and shared data components

psiphon/server/tunnelServer.go

@@ -398,7 +398,7 @@ func newSSHServer(
 		clients:                 make(map[string]*sshClient),
 		oslSessionCache:         oslSessionCache,
 		authorizationSessionIDs: make(map[string]string),
-		obfuscatorSeedHistory:   obfuscator.NewSeedHistory(),
+		obfuscatorSeedHistory:   obfuscator.NewSeedHistory(nil),
 	}, nil
 }
 
@@ -433,8 +433,7 @@ func (sshServer *sshServer) runListener(
 	listenerError chan<- error,
 	listenerTunnelProtocol string) {
 
-	_, listenerPortStr, _ := net.SplitHostPort(listener.Addr().String())
-	listenerPort, _ := strconv.Atoi(listenerPortStr)
+	listenerPort := common.PortFromAddr(listener.Addr())
 
 	runningProtocols := make([]string, 0)
 	for tunnelProtocol := range sshServer.support.Config.TunnelProtocolPorts {
@@ -1268,12 +1267,13 @@ func (sshClient *sshClient) run(
 				conn,
 				sshClient.sshServer.support.Config.ObfuscatedSSHKey,
 				sshClient.sshServer.obfuscatorSeedHistory,
-				func(err error) {
+				func(clientIP string, logFields common.LogFields) {
 					logIrregularTunnel(
+						sshClient.sshServer.support,
 						sshClient.listenerTunnelProtocol,
 						sshClient.listenerPort,
-						sshClient.geoIPData,
-						err)
+						clientIP,
+						LogFields(logFields))
 				})
 
 			if err != nil {
@@ -2131,7 +2131,7 @@ func (sshClient *sshClient) logTunnel(additionalMetrics []LogFields) {
 	logFields["session_id"] = sshClient.sessionID
 	logFields["handshake_completed"] = sshClient.handshakeState.completed
 	logFields["start_time"] = sshClient.activityConn.GetStartTime()
-	logFields["duration"] = sshClient.activityConn.GetActiveDuration() / time.Millisecond
+	logFields["duration"] = int64(sshClient.activityConn.GetActiveDuration() / time.Millisecond)
 	logFields["bytes_up_tcp"] = sshClient.tcpTrafficState.bytesUp
 	logFields["bytes_down_tcp"] = sshClient.tcpTrafficState.bytesDown
 	logFields["peak_concurrent_dialing_port_forward_count_tcp"] = sshClient.tcpTrafficState.peakConcurrentDialingPortForwardCount