From 09033d1080428845b1b65ab079d3d58d3cf41cab Mon Sep 17 00:00:00 2001 From: Gabor Retvari Date: Thu, 5 Dec 2024 17:34:54 +0100 Subject: [PATCH] feature: Add allocation lifecycle event reporting --- go.mod | 4 +-- go.sum | 4 +-- handlers.go | 72 +++++++++++++++++++++++++++++++++++++++++++++++------ server.go | 1 + turncat.go | 9 ++++--- 5 files changed, 74 insertions(+), 16 deletions(-) diff --git a/go.mod b/go.mod index 3b089f2..38af851 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index f4688bd..af14749 100644 --- a/go.sum +++ b/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= diff --git a/handlers.go b/handlers.go index 60814cd..08e1983 100644 --- a/handlers.go +++ b/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) +} diff --git a/server.go b/server.go index e3eda17..7d3e288 100644 --- a/server.go +++ b/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), diff --git a/turncat.go b/turncat.go index 7dd9dcc..9c5f45b 100644 --- a/turncat.go +++ b/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() }