feature: Add allocation lifecycle event reporting

go.mod

@@ -16,6 +16,7 @@ require (
 	github.com/oapi-codegen/runtime v1.1.1
 	github.com/pion/datachannel v1.5.9
 	github.com/pion/dtls/v3 v3.0.3
+	github.com/pion/ice/v4 v4.0.2
 	github.com/pion/logging v0.2.2
 	github.com/pion/transport/v3 v3.0.7
 	github.com/pion/turn/v4 v4.0.0
@@ -81,7 +82,6 @@ require (
 	github.com/mxk/go-flowrate v0.0.0-20140419014527-cca7078d478f // indirect
 	github.com/perimeterx/marshmallow v1.1.5 // indirect
 	github.com/peterbourgon/diskv v2.0.1+incompatible // indirect
-	github.com/pion/ice/v4 v4.0.2 // indirect
 	github.com/pion/interceptor v0.1.37 // indirect
 	github.com/pion/mdns/v2 v2.0.7 // indirect
 	github.com/pion/randutil v0.1.0 // indirect
@@ -123,4 +123,4 @@ require (
 	sigs.k8s.io/structured-merge-diff/v4 v4.4.1 // indirect
 )
 
-// replace github.com/pion/turn/v2 => github.com/l7mp/turn/v2 v2.0.11
+replace github.com/pion/turn/v4 => github.com/l7mp/turn/v4 v4.0.1-0.20241205140700-99276149099b

go.sum

@@ -95,6 +95,8 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=
 github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
 github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc=
 github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw=
+github.com/l7mp/turn/v4 v4.0.1-0.20241205140700-99276149099b h1:HYqcjCtvPIqjoHUfM/WHzJMBAh9ZgCY8qbq8AbxZj6k=
+github.com/l7mp/turn/v4 v4.0.1-0.20241205140700-99276149099b/go.mod h1:0F3wpjtwvLRrpRiKXB4YzJ9B88nlS3ppSQnYldpnh0s=
 github.com/liggitt/tabwriter v0.0.0-20181228230101-89fcab3d43de h1:9TO3cAIGXtEhnIaL+V+BEER86oLrvS+kWobKpbJuye0=
 github.com/liggitt/tabwriter v0.0.0-20181228230101-89fcab3d43de/go.mod h1:zAbeS9B/r2mtpb6U+EI2rYA5OAXxsYw6wTamcNW+zcE=
 github.com/mailru/easyjson v0.7.7 h1:UGYAvKxe3sBsEDzO8ZeWOSlIQfWFlxbzLZe7hwFURr0=
@@ -155,8 +157,6 @@ github.com/pion/stun/v3 v3.0.0 h1:4h1gwhWLWuZWOJIJR9s2ferRO+W3zA/b6ijOI6mKzUw=
 github.com/pion/stun/v3 v3.0.0/go.mod h1:HvCN8txt8mwi4FBvS3EmDghW6aQJ24T+y+1TKjB5jyU=
 github.com/pion/transport/v3 v3.0.7 h1:iRbMH05BzSNwhILHoBoAPxoB9xQgOaJk+591KC9P1o0=
 github.com/pion/transport/v3 v3.0.7/go.mod h1:YleKiTZ4vqNxVwh77Z0zytYi7rXHl7j6uPLGhhz9rwo=
-github.com/pion/turn/v4 v4.0.0 h1:qxplo3Rxa9Yg1xXDxxH8xaqcyGUtbHYw4QSCvmFWvhM=
-github.com/pion/turn/v4 v4.0.0/go.mod h1:MuPDkm15nYSklKpN8vWJ9W2M0PlyQZqYt1McGuxG7mA=
 github.com/pion/webrtc/v4 v4.0.1 h1:6Unwc6JzoTsjxetcAIoWH81RUM4K5dBc1BbJGcF9WVE=
 github.com/pion/webrtc/v4 v4.0.1/go.mod h1:SfNn8CcFxR6OUVjLXVslAQ3a3994JhyE3Hw1jAuqEto=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=

handlers.go

@@ -2,10 +2,12 @@ package stunner
 
 import (
 	"errors"
+	"fmt"
 	"net"
 
 	"github.com/l7mp/stunner/internal/object"
 	"github.com/l7mp/stunner/internal/util"
+	"github.com/pion/turn/v4"
 
 	stnrv1 "github.com/l7mp/stunner/pkg/apis/v1"
 	a12n "github.com/l7mp/stunner/pkg/authentication"
@@ -22,7 +24,7 @@ func (s *Stunner) NewAuthHandler() a12n.AuthHandler {
 
 		switch auth.Type {
 		case stnrv1.AuthTypeStatic:
-			auth.Log.Infof("static auth request: username=%q realm=%q srcAddr=%v\n",
+			auth.Log.Tracef("static auth request: username=%q realm=%q srcAddr=%v\n",
 				username, realm, srcAddr)
 
 			key := a12n.GenerateAuthKey(auth.Username, auth.Realm, auth.Password)
@@ -31,11 +33,11 @@ func (s *Stunner) NewAuthHandler() a12n.AuthHandler {
 				return key, true
 			}
 
-			auth.Log.Info("static auth request: failed: invalid username")
+			auth.Log.Infof("static auth request: failed: invalid username")
 			return nil, false
 
 		case stnrv1.AuthTypeEphemeral:
-			auth.Log.Infof("ephemeral auth request: username=%q realm=%q srcAddr=%v",
+			auth.Log.Tracef("ephemeral auth request: username=%q realm=%q srcAddr=%v",
 				username, realm, srcAddr)
 
 			if err := a12n.CheckTimeWindowedUsername(username); err != nil {
@@ -45,12 +47,12 @@ func (s *Stunner) NewAuthHandler() a12n.AuthHandler {
 
 			password, err := a12n.GetLongTermCredential(username, auth.Secret)
 			if err != nil {
-				auth.Log.Infof("ephemeral auth request: error generating password: %s",
+				auth.Log.Debugf("ephemeral auth request: error generating password: %s",
 					err)
 				return nil, false
 			}
 
-			auth.Log.Info("ephemeral auth request: success")
+			auth.Log.Debug("ephemeral auth request: success")
 			return a12n.GenerateAuthKey(username, auth.Realm, password), true
 
 		default:
@@ -71,7 +73,7 @@ func (s *Stunner) NewPermissionHandler(l *object.Listener) a12n.PermissionHandle
 		auth := s.GetAuth()
 
 		peerIP := peer.String()
-		auth.Log.Debugf("permission handler for listener %q: client %q, peer %q", l.Name,
+		auth.Log.Tracef("permission handler for listener %q: client %q, peer %q", l.Name,
 			src.String(), peerIP)
 
 		clusters := s.clusterManager.Keys()
@@ -81,14 +83,14 @@ func (s *Stunner) NewPermissionHandler(l *object.Listener) a12n.PermissionHandle
 				auth.Log.Tracef("considering cluster %q", r)
 				c := s.GetCluster(r)
 				if c.Route(peer) {
-					auth.Log.Infof("permission granted on listener %q for client "+
+					auth.Log.Debugf("permission granted on listener %q for client "+
 						"%q to peer %s via cluster %q", l.Name, src.String(),
 						peerIP, c.Name)
 					return true
 				}
 			}
 		}
-		auth.Log.Debugf("permission denied on listener %q for client %q to peer %s: "+
+		auth.Log.Infof("permission denied on listener %q for client %q to peer %s: "+
 			"no route to endpoint", l.Name, src.String(), peerIP)
 		return false
 	}
@@ -119,3 +121,57 @@ func (s *Stunner) NewRealmHandler() object.RealmHandler {
 func (s *Stunner) NewStatusHandler() object.StatusHandler {
 	return func() stnrv1.Status { return s.Status() }
 }
+
+var lifecycleEventHandlerConstructor = newLifecycleEventHandlerStub
+
+// NewLifecycleEventHandler creates a set of callbcks for tracking the lifecycle of TURN allocations.
+func (s *Stunner) NewLifecycleEventHandler() turn.EventHandlers {
+	return lifecycleEventHandlerConstructor(s)
+}
+
+// LifecycleEventHandlerStub is a simple stub that logs allocation events.
+func newLifecycleEventHandlerStub(s *Stunner) turn.EventHandlers {
+	return turn.EventHandlers{
+		OnAuth: func(src, dst net.Addr, proto, username, realm string, method string, verdict bool) {
+			status := "REJECTED"
+			if verdict {
+				status = "ACCEPTED"
+			}
+			s.log.Infof("Authentication request: client=%s, method=%s, verdict=%s",
+				dumpClient(src, dst, proto, username, realm), method, status)
+		},
+		OnAllocationCreated: func(src, dst net.Addr, proto, username, realm string, relayAddr net.Addr, reqPort int) {
+			s.log.Infof("Allocation created: client=%s, relay-address=%s, requested-port=%d",
+				dumpClient(src, dst, proto, username, realm), relayAddr.String(), reqPort)
+		},
+		OnAllocationDeleted: func(src, dst net.Addr, proto, username, realm string) {
+			s.log.Infof("Allocation deleted: client=%s", dumpClient(src, dst, proto, username, realm))
+		},
+		OnAllocationError: func(src, dst net.Addr, proto, message string) {
+			s.log.Infof("Allocation error: client=%s-%s:%s, error=%s", src, dst, proto, message)
+		},
+		OnPermissionCreated: func(src, dst net.Addr, proto, username, realm string, relayAddr net.Addr, peer net.IP) {
+			s.log.Infof("Permission created: client=%s, relay-addr=%s, peer=%s",
+				dumpClient(src, dst, proto, username, realm), relayAddr.String(), peer.String())
+		},
+		OnPermissionDeleted: func(src, dst net.Addr, proto, username, realm string, relayAddr net.Addr, peer net.IP) {
+			s.log.Infof("Permission deleted: client=%s, relay-addr=%s, peer=%s",
+				dumpClient(src, dst, proto, username, realm), relayAddr.String(), peer.String())
+		},
+		OnChannelCreated: func(src, dst net.Addr, proto, username, realm string, relayAddr, peer net.Addr, chanNum uint16) {
+			s.log.Infof("Channel created: client=%s, relay-addr=%s, peer=%s, channel-num=%d",
+				dumpClient(src, dst, proto, username, realm), relayAddr.String(),
+				peer.String(), chanNum)
+		},
+		OnChannelDeleted: func(src, dst net.Addr, proto, username, realm string, relayAddr, peer net.Addr, chanNum uint16) {
+			s.log.Infof("Channel deleted: client=%s, relay-addr=%s, peer=%s, channel-num=%d",
+				dumpClient(src, dst, proto, username, realm), relayAddr.String(),
+				peer.String(), chanNum)
+		},
+	}
+}
+
+func dumpClient(srcAddr, dstAddr net.Addr, protocol, username, realm string) string {
+	return fmt.Sprintf("%s-%s:%s, username=%s, realm=%s", srcAddr.String(), dstAddr.String(),
+		protocol, username, realm)
+}

server.go

@@ -154,6 +154,7 @@ func (s *Stunner) StartServer(l *object.Listener) error {
 	t, err := turn.NewServer(turn.ServerConfig{
 		Realm:             s.GetRealm(),
 		AuthHandler:       s.NewAuthHandler(),
+		EventHandlers:     s.NewLifecycleEventHandler(),
 		PacketConnConfigs: pConns,
 		ListenerConfigs:   lConns,
 		LoggerFactory:     logger.NewRateLimitedLoggerFactory(s.logger, LogRateLimit, LogBurst),

turncat.go

@@ -349,15 +349,16 @@ func (t *Turncat) deleteConnection(conn *connection) {
 
 	t.log.Infof("Closing client connection to %s", caddr)
 
-	if err := conn.clientConn.Close(); err != nil {
-		t.log.Warnf("Error closing client connection for %s:%s: %s",
-			conn.clientAddr.Network(), conn.clientAddr.String(), err.Error())
-	}
 	if err := conn.serverConn.Close(); err != nil {
 		t.log.Warnf("Error closing relayed TURN server connection for %s:%s: %s",
 			conn.clientAddr.Network(), conn.clientAddr.String(), err.Error())
 	}
 
+	if err := conn.clientConn.Close(); err != nil {
+		t.log.Warnf("Error closing client connection for %s:%s: %s",
+			conn.clientAddr.Network(), conn.clientAddr.String(), err.Error())
+	}
+
 	conn.turnClient.Close()
 	conn.turnConn.Close()
 }