Add option to enable WebRTC debug logging

MobileLibrary/psi/psi.go

@@ -488,7 +488,7 @@ func GetPacketTunnelMTU() int {
 // If called before Start, log notices will emit to stderr.
 func WriteRuntimeProfiles(outputDirectory string, cpuSampleDurationSeconds, blockSampleDurationSeconds int) {
 	common.WriteRuntimeProfiles(
-		psiphon.NoticeCommonLogger(),
+		psiphon.NoticeCommonLogger(false),
 		outputDirectory,
 		"",
 		cpuSampleDurationSeconds,

psiphon/common/inproxy/client.go

@@ -57,6 +57,9 @@ type ClientConfig struct {
 	// Logger is used to log events.
 	Logger common.Logger
 
+	// EnableWebRTCDebugLogging indicates whether to emit WebRTC debug logs.
+	EnableWebRTCDebugLogging bool
+
 	// BaseAPIParameters should be populated with Psiphon handshake metrics
 	// parameters. These will be sent to and logger by the broker.
 	BaseAPIParameters common.APIParameters
@@ -285,6 +288,7 @@ func dialClientWebRTCConn(
 	webRTCConn, SDP, SDPMetrics, err := NewWebRTCConnWithOffer(
 		ctx, &WebRTCConfig{
 			Logger:                      config.Logger,
+			EnableDebugLogging:          config.EnableWebRTCDebugLogging,
 			WebRTCDialCoordinator:       config.WebRTCDialCoordinator,
 			ClientRootObfuscationSecret: clientRootObfuscationSecret,
 			DoDTLSRandomization:         doTLSRandomization,

psiphon/common/inproxy/proxy.go

@@ -71,6 +71,9 @@ type ProxyConfig struct {
 	// Logger is used to log events.
 	Logger common.Logger
 
+	// EnableWebRTCDebugLogging indicates whether to emit WebRTC debug logs.
+	EnableWebRTCDebugLogging bool
+
 	// GetBrokerClient provides a BrokerClient which the proxy will use for
 	// making broker requests. If GetBrokerClient returns a shared
 	// BrokerClient instance, the BrokerClient must support multiple,
@@ -579,6 +582,7 @@ func (p *Proxy) proxyOneClient(ctx context.Context, delayAnnounce bool) (bool, e
 		webRTCAnswerCtx,
 		&WebRTCConfig{
 			Logger:                      p.config.Logger,
+			EnableDebugLogging:          p.config.EnableWebRTCDebugLogging,
 			WebRTCDialCoordinator:       webRTCCoordinator,
 			ClientRootObfuscationSecret: announceResponse.ClientRootObfuscationSecret,
 			DoDTLSRandomization:         announceResponse.DoDTLSRandomization,

psiphon/common/inproxy/webrtc.go

@@ -40,6 +40,7 @@ import (
 	"github.com/pion/datachannel"
 	"github.com/pion/dtls/v2"
 	"github.com/pion/ice/v2"
+	pion_logging "github.com/pion/logging"
 	"github.com/pion/sdp/v3"
 	"github.com/pion/transport/v2"
 	"github.com/pion/webrtc/v3"
@@ -113,6 +114,11 @@ type WebRTCConfig struct {
 	// Logger is used to log events.
 	Logger common.Logger
 
+	// EnableDebugLogging indicates whether to log pion/webrtc debug and trace
+	// events. When enabled, these events will be logged to the specified
+	// Logger at a Debug log level.
+	EnableDebugLogging bool
+
 	// WebRTCDialCoordinator specifies specific WebRTC dial strategies and
 	// settings; WebRTCDialCoordinator also facilities dial replay by
 	// receiving callbacks when individual dial steps succeed or fail.
@@ -295,12 +301,19 @@ func newWebRTCConn(
 	deadline, _ := ctx.Deadline()
 	TTL := time.Until(deadline)
 
-	pionLogger := newPionLogger(config.Logger)
-	pionNetwork := newPionNetwork(ctx, pionLogger, config.WebRTCDialCoordinator)
+	pionLoggerFactory := newPionLoggerFactory(
+		config.Logger,
+		config.EnableDebugLogging)
+
+	pionNetwork := newPionNetwork(
+		ctx, pionLoggerFactory.NewLogger("net"), config.WebRTCDialCoordinator)
 
-	udpMux := webrtc.NewICEUniversalUDPMux(pionLogger, udpConn, TTL, pionNetwork)
+	udpMux := webrtc.NewICEUniversalUDPMux(
+		pionLoggerFactory.NewLogger("mux"), udpConn, TTL, pionNetwork)
 
-	settingEngine := webrtc.SettingEngine{}
+	settingEngine := webrtc.SettingEngine{
+		LoggerFactory: pionLoggerFactory,
+	}
 	settingEngine.SetNet(pionNetwork)
 	settingEngine.DetachDataChannels()
 	settingEngine.SetICEMulticastDNSMode(ice.MulticastDNSModeDisabled)
@@ -1490,55 +1503,89 @@ func processSDPAddresses(
 	return encodedSDP, metrics, nil
 }
 
+type pionLoggerFactory struct {
+	logger       common.Logger
+	debugLogging bool
+}
+
+func newPionLoggerFactory(logger common.Logger, debugLogging bool) *pionLoggerFactory {
+	return &pionLoggerFactory{
+		logger:       logger,
+		debugLogging: debugLogging,
+	}
+}
+
+func (f *pionLoggerFactory) NewLogger(scope string) pion_logging.LeveledLogger {
+	return newPionLogger(scope, f.logger, f.debugLogging)
+}
+
 // pionLogger wraps common.Logger and implements
 // https://pkg.go.dev/github.com/pion/logging#LeveledLogger for passing into
 // pion.
 type pionLogger struct {
-	logger common.Logger
+	scope        string
+	logger       common.Logger
+	debugLogging bool
 }
 
-func newPionLogger(logger common.Logger) *pionLogger {
-	return &pionLogger{logger: logger}
+func newPionLogger(scope string, logger common.Logger, debugLogging bool) *pionLogger {
+	return &pionLogger{
+		scope:        scope,
+		logger:       logger,
+		debugLogging: debugLogging,
+	}
 }
 
 func (l *pionLogger) Trace(msg string) {
-	// Ignored.
+	if !l.debugLogging {
+		return
+	}
+	l.logger.WithTrace().Debug(fmt.Sprintf("webRTC: %s: %s", l.scope, msg))
 }
 
 func (l *pionLogger) Tracef(format string, args ...interface{}) {
-	// Ignored.
+	if !l.debugLogging {
+		return
+	}
+	l.logger.WithTrace().Debug(fmt.Sprintf("webRTC: %s: %s", l.scope, fmt.Sprintf(format, args...)))
 }
 
 func (l *pionLogger) Debug(msg string) {
-	l.logger.WithTrace().Debug("webRTC: " + msg)
+	if !l.debugLogging {
+		return
+	}
+	l.logger.WithTrace().Debug(fmt.Sprintf("[webRTC: %s: %s", l.scope, msg))
 }
 
 func (l *pionLogger) Debugf(format string, args ...interface{}) {
-	l.logger.WithTrace().Debug("webRTC: " + fmt.Sprintf(format, args...))
+	if !l.debugLogging {
+		return
+	}
+	l.logger.WithTrace().Debug(fmt.Sprintf("webRTC: %s: %s", l.scope, fmt.Sprintf(format, args...)))
 }
 
 func (l *pionLogger) Info(msg string) {
-	l.logger.WithTrace().Info("webRTC: " + msg)
+	l.logger.WithTrace().Info(fmt.Sprintf("webRTC: %s: %s", l.scope, msg))
 }
 
 func (l *pionLogger) Infof(format string, args ...interface{}) {
-	l.logger.WithTrace().Info("webRTC: " + fmt.Sprintf(format, args...))
+	l.logger.WithTrace().Info(fmt.Sprintf("webRTC: %s: %s", l.scope, fmt.Sprintf(format, args...)))
 }
 
 func (l *pionLogger) Warn(msg string) {
-	l.logger.WithTrace().Warning("webRTC: " + msg)
+	l.logger.WithTrace().Warning(fmt.Sprintf("webRTC: %s: %s", l.scope, msg))
 }
 
 func (l *pionLogger) Warnf(format string, args ...interface{}) {
-	l.logger.WithTrace().Warning("webRTC: " + fmt.Sprintf(format, args...))
+	l.logger.WithTrace().Warning(fmt.Sprintf("webRTC: %s: %s", l.scope, fmt.Sprintf(format, args...)))
 }
 
 func (l *pionLogger) Error(msg string) {
-	l.logger.WithTrace().Error("webRTC: " + msg)
+	l.logger.WithTrace().Error(fmt.Sprintf("webRTC: %s: %s", l.scope, msg))
 }
 
 func (l *pionLogger) Errorf(format string, args ...interface{}) {
-	l.logger.WithTrace().Error("webRTC: " + fmt.Sprintf(format, args...))
+	l.logger.WithTrace().Error(fmt.Sprintf("webRTC: %s: %s", l.scope, fmt.Sprintf(format, args...)))
 }
 
 // pionNetwork implements pion/transport.Net.
@@ -1551,13 +1598,13 @@ func (l *pionLogger) Errorf(format string, args ...interface{}) {
 // Psiphon custom resolver.
 type pionNetwork struct {
 	dialCtx               context.Context
-	logger                *pionLogger
+	logger                pion_logging.LeveledLogger
 	webRTCDialCoordinator WebRTCDialCoordinator
 }
 
 func newPionNetwork(
 	dialCtx context.Context,
-	logger *pionLogger,
+	logger pion_logging.LeveledLogger,
 	webRTCDialCoordinator WebRTCDialCoordinator) *pionNetwork {
 
 	return &pionNetwork{

psiphon/config.go

@@ -989,6 +989,7 @@ type Config struct {
 	InproxyProxyDestinationDialTimeoutMilliseconds         *int
 	InproxyPsiphonAPIRequestTimeoutMilliseconds            *int
 	InproxySkipAwaitFullyConnected                         bool
+	InproxyEnableWebRTCDebugLogging                        bool
 
 	// params is the active parameters.Parameters with defaults, config values,
 	// and, optionally, tactics applied.

psiphon/controller.go

@@ -201,7 +201,7 @@ func NewController(config *Config) (controller *Controller, err error) {
 		packetTunnelTransport := NewPacketTunnelTransport()
 
 		packetTunnelClient, err := tun.NewClient(&tun.ClientConfig{
-			Logger:                    NoticeCommonLogger(),
+			Logger:                    NoticeCommonLogger(false),
 			TunFileDescriptor:         config.PacketTunnelTunFileDescriptor,
 			TransparentDNSIPv4Address: config.PacketTunnelTransparentDNSIPv4Address,
 			TransparentDNSIPv6Address: config.PacketTunnelTransparentDNSIPv6Address,
@@ -2571,8 +2571,15 @@ func (controller *Controller) runInproxyProxy() {
 		return
 	}
 
+	// The debugLogging flag is passed to both NoticeCommonLogger and to the
+	// inproxy package as well; skipping debug logs in the inproxy package,
+	// before calling into the notice logger, avoids unnecessary allocations
+	// and formatting when debug logging is off.
+	debugLogging := controller.config.InproxyEnableWebRTCDebugLogging
+
 	config := &inproxy.ProxyConfig{
-		Logger:                        NoticeCommonLogger(),
+		Logger:                        NoticeCommonLogger(debugLogging),
+		EnableWebRTCDebugLogging:      debugLogging,
 		GetBrokerClient:               controller.inproxyGetProxyBrokerClient,
 		GetBaseAPIParameters:          controller.inproxyGetAPIParameters,
 		MakeWebRTCDialCoordinator:     controller.inproxyMakeWebRTCDialCoordinator,

psiphon/notice.go

@@ -1273,23 +1273,28 @@ func (writer *NoticeWriter) Write(p []byte) (n int, err error) {
 // NoticeCommonLogger maps the common.Logger interface to the notice facility.
 // This is used to make the notice facility available to other packages that
 // don't import the "psiphon" package.
-func NoticeCommonLogger() common.Logger {
-	return &commonLogger{}
+func NoticeCommonLogger(debugLogging bool) common.Logger {
+	return &commonLogger{
+		debugLogging: debugLogging,
+	}
 }
 
 type commonLogger struct {
+	debugLogging bool
 }
 
 func (logger *commonLogger) WithTrace() common.LogTrace {
 	return &commonLogTrace{
-		trace: stacktrace.GetParentFunctionName(),
+		trace:        stacktrace.GetParentFunctionName(),
+		debugLogging: logger.debugLogging,
 	}
 }
 
 func (logger *commonLogger) WithTraceFields(fields common.LogFields) common.LogTrace {
 	return &commonLogTrace{
-		trace:  stacktrace.GetParentFunctionName(),
-		fields: fields,
+		trace:        stacktrace.GetParentFunctionName(),
+		fields:       fields,
+		debugLogging: logger.debugLogging,
 	}
 }
 
@@ -1300,8 +1305,7 @@ func (logger *commonLogger) LogMetric(metric string, fields common.LogFields) {
 }
 
 func (log *commonLogger) IsLogLevelDebug() bool {
-	// There are no debug-level notices
-	return false
+	return log.debugLogging
 }
 
 func listCommonFields(fields common.LogFields) []interface{} {
@@ -1313,8 +1317,9 @@ func listCommonFields(fields common.LogFields) []interface{} {
 }
 
 type commonLogTrace struct {
-	trace  string
-	fields common.LogFields
+	trace        string
+	fields       common.LogFields
+	debugLogging bool
 }
 
 func (log *commonLogTrace) outputNotice(
@@ -1330,7 +1335,10 @@ func (log *commonLogTrace) outputNotice(
 }
 
 func (log *commonLogTrace) Debug(args ...interface{}) {
-	// Ignored.
+	if !log.debugLogging {
+		return
+	}
+	log.outputNotice("Debug", args...)
 }
 
 func (log *commonLogTrace) Info(args ...interface{}) {

psiphon/tunnel.go

@@ -1306,7 +1306,7 @@ func dialConjure(
 		STUNServerAddress:           dialParams.ConjureSTUNServerAddress,
 		DTLSEmptyInitialPacket:      dialParams.ConjureDTLSEmptyInitialPacket,
 		DiagnosticID:                diagnosticID,
-		Logger:                      NoticeCommonLogger(),
+		Logger:                      NoticeCommonLogger(false),
 	}
 
 	if dialParams.ConjureAPIRegistration {
@@ -1519,8 +1519,15 @@ func dialInproxy(
 	// server_tunnel if the subsequent WebRTC dials fail.
 	params := getBaseAPIParameters(baseParametersNoDialParameters, config, nil)
 
+	// The debugLogging flag is passed to both NoticeCommonLogger and to the
+	// inproxy package as well; skipping debug logs in the inproxy package,
+	// before calling into the notice logger, avoids unnecessary allocations
+	// and formatting when debug logging is off.
+	debugLogging := config.InproxyEnableWebRTCDebugLogging
+
 	clientConfig := &inproxy.ClientConfig{
-		Logger:                       NoticeCommonLogger(),
+		Logger:                       NoticeCommonLogger(debugLogging),
+		EnableWebRTCDebugLogging:     debugLogging,
 		BaseAPIParameters:            params,
 		BrokerClient:                 dialParams.inproxyBrokerClient,
 		WebRTCDialCoordinator:        webRTCDialInstance,