From 4b4f54e5e39ae0357fdd696437fa0bd32bfcf686 Mon Sep 17 00:00:00 2001 From: Denys Smirnov Date: Sat, 19 Oct 2024 15:56:45 +0300 Subject: [PATCH] Switch to slog for structured logging. --- client.go | 12 ++--- dialog_server_test.go | 7 +-- example/proxysip/go.mod | 6 +-- example/proxysip/go.sum | 29 ++---------- example/proxysip/main.go | 63 ++++++++++++------------- example/proxysip/main_test.go | 28 +++-------- example/register/client/main.go | 46 +++++++++--------- example/register/server/main.go | 43 ++++++++--------- go.mod | 3 -- go.sum | 14 ------ server.go | 18 ++++--- server_test.go | 21 ++++----- sip/headers.go | 5 +- sip/parser.go | 10 ++-- sip/sip.go | 11 ++--- sip/transaction.go | 9 ++-- sip/transaction_client_tx.go | 26 +++++----- sip/transaction_client_tx_fsm.go | 8 ++-- sip/transaction_client_tx_test.go | 14 ++++-- sip/transaction_layer.go | 36 +++++++------- sip/transaction_server_tx.go | 16 +++---- sip/transaction_server_tx_fsm.go | 10 ++-- sip/transaction_server_tx_test.go | 11 +++-- sip/transport_connection_pool.go | 16 ++++--- sip/transport_connection_pool_test.go | 14 +++--- sip/transport_layer.go | 47 +++++++++--------- sip/transport_tcp.go | 68 +++++++++++++-------------- sip/transport_tls.go | 16 ++++--- sip/transport_udp.go | 57 +++++++++++----------- sip/transport_ws.go | 62 ++++++++++++------------ sip/transport_wss.go | 15 +++--- siptest/server_tx_recorder.go | 6 +-- 32 files changed, 341 insertions(+), 406 deletions(-) diff --git a/client.go b/client.go index 717b54c..c20e36d 100644 --- a/client.go +++ b/client.go @@ -3,13 +3,13 @@ package sipgo import ( "context" "fmt" + "log/slog" "net" - "github.com/emiago/sipgo/sip" "github.com/google/uuid" "github.com/icholy/digest" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" + + "github.com/emiago/sipgo/sip" ) func Init() { @@ -25,7 +25,7 @@ type Client struct { host string port int rport bool - log zerolog.Logger + log *slog.Logger // TxRequester allows you to use your transaction requester instead default from transaction layer // Useful only for testing @@ -37,7 +37,7 @@ type Client struct { type ClientOption func(c *Client) error // WithClientLogger allows customizing client logger -func WithClientLogger(logger zerolog.Logger) ClientOption { +func WithClientLogger(logger *slog.Logger) ClientOption { return func(s *Client) error { s.log = logger return nil @@ -94,7 +94,7 @@ func WithClientAddr(addr string) ClientOption { func NewClient(ua *UserAgent, options ...ClientOption) (*Client, error) { c := &Client{ UserAgent: ua, - log: log.Logger.With().Str("caller", "Client").Logger(), + log: slog.With("caller", "Client"), } for _, o := range options { diff --git a/dialog_server_test.go b/dialog_server_test.go index 9942401..048e864 100644 --- a/dialog_server_test.go +++ b/dialog_server_test.go @@ -2,12 +2,13 @@ package sipgo import ( "context" + "log/slog" "testing" - "github.com/emiago/sipgo/sip" - "github.com/rs/zerolog/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + + "github.com/emiago/sipgo/sip" ) func TestDialogServerByeRequest(t *testing.T) { @@ -26,7 +27,7 @@ func TestDialogServerByeRequest(t *testing.T) { invite.AppendHeader(&sip.RecordRouteHeader{Address: sip.Uri{Host: "P2", Port: 5060}}) invite.AppendHeader(&sip.RecordRouteHeader{Address: sip.Uri{Host: "P3", Port: 5060}}) - dialog, err := dialogSrv.ReadInvite(invite, sip.NewServerTx("test", invite, nil, log.Logger)) + dialog, err := dialogSrv.ReadInvite(invite, sip.NewServerTx("test", invite, nil, slog.Default())) require.NoError(t, err) res := sip.NewResponseFromRequest(invite, sip.StatusOK, "OK", nil) diff --git a/example/proxysip/go.mod b/example/proxysip/go.mod index 9504534..1c10fa1 100644 --- a/example/proxysip/go.mod +++ b/example/proxysip/go.mod @@ -8,8 +8,6 @@ require ( github.com/arl/statsviz v0.6.0 github.com/emiago/sipgo v0.23.1-0.20240913054121-597f4c4406dd github.com/prometheus/client_golang v1.17.0 - github.com/rs/zerolog v1.32.0 - github.com/sirupsen/logrus v1.9.3 github.com/stretchr/testify v1.9.0 ) @@ -25,15 +23,13 @@ require ( github.com/gorilla/websocket v1.5.0 // indirect github.com/icholy/digest v0.1.22 // indirect github.com/kr/text v0.2.0 // indirect - github.com/mattn/go-colorable v0.1.13 // indirect - github.com/mattn/go-isatty v0.0.20 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect github.com/prometheus/client_model v0.4.1-0.20230718164431-9a2bf3000d16 // indirect github.com/prometheus/common v0.44.0 // indirect github.com/prometheus/procfs v0.11.1 // indirect github.com/satori/go.uuid v1.2.1-0.20181028125025-b2ce2384e17b // indirect - golang.org/x/sys v0.19.0 // indirect + golang.org/x/sys v0.24.0 // indirect google.golang.org/protobuf v1.31.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/example/proxysip/go.sum b/example/proxysip/go.sum index ed1362b..83ebb24 100644 --- a/example/proxysip/go.sum +++ b/example/proxysip/go.sum @@ -4,9 +4,7 @@ github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= github.com/cespare/xxhash/v2 v2.2.0 h1:DC2CZ1Ep5Y4k3ZQ899DldepgrayRUGE6BBZ/cd9Cj44= github.com/cespare/xxhash/v2 v2.2.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= -github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= -github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/gobwas/httphead v0.1.0 h1:exrUm0f4YX0L7EBwZHuCF4GDp8aJfVeBrlLQrs6NqWU= @@ -15,7 +13,6 @@ github.com/gobwas/pool v0.2.1 h1:xfeeEhW7pwmX8nuLVlqbzVc7udMDrwetjEv+TZIz1og= github.com/gobwas/pool v0.2.1/go.mod h1:q8bcK0KcYlCgd9e7WYLm9LpyS+YeLd8JVDW6WezmKEw= github.com/gobwas/ws v1.3.2 h1:zlnbNHxumkRvfPWgfXu8RBwyNR1x8wh9cf5PTOCqs9Q= github.com/gobwas/ws v1.3.2/go.mod h1:hRKAFb8wOxFROYNsT1bqfWnhX+b5MFeJM9r2ZSwg/KY= -github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaSAoJOfIk= github.com/golang/protobuf v1.5.3 h1:KhyjKVUg7Usr/dYsdSqoFveMYd5ko72D+zANwlG1mmg= @@ -34,16 +31,9 @@ github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= -github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= -github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= -github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= -github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= -github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= -github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/matttproud/golang_protobuf_extensions v1.0.4 h1:mmDVorXM7PCGKw94cs5zkfA9PSy5pEvNWRP0ET0TIVo= github.com/matttproud/golang_protobuf_extensions v1.0.4/go.mod h1:BSXmuO+STAnVfrANrmjBb36TMTDstsz7MSK+HVaYKv4= github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= -github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/prometheus/client_golang v1.17.0 h1:rl2sfwZMtSthVU752MqfjQozy7blglC+1SOtjMAMh+Q= @@ -54,18 +44,11 @@ github.com/prometheus/common v0.44.0 h1:+5BrQJwiBB9xsMygAB3TNvpQKOwlkc25LbISbrdO github.com/prometheus/common v0.44.0/go.mod h1:ofAIvZbQ1e/nugmZGz4/qCb9Ap1VoSTIO7x0VV9VvuY= github.com/prometheus/procfs v0.11.1 h1:xRC8Iq1yyca5ypa9n1EZnWZkt7dwcoRPQwX/5gwaUuI= github.com/prometheus/procfs v0.11.1/go.mod h1:eesXgaPo1q7lBpVMoMy0ZOFTth9hBn4W/y0/p/ScXhY= -github.com/rogpeppe/go-internal v1.11.0 h1:cWPaGQEPrBb5/AsnsZesgZZ9yb1OQ+GOISoDNXVBh4M= -github.com/rogpeppe/go-internal v1.11.0/go.mod h1:ddIwULY96R17DhadqLgMfk9H9tvdUzkipdSkR5nkCZA= -github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= -github.com/rs/zerolog v1.32.0 h1:keLypqrlIjaFsbmJOBdB/qvyF8KEtCWHwobLp5l/mQ0= -github.com/rs/zerolog v1.32.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= +github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8= +github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4= github.com/satori/go.uuid v1.2.1-0.20181028125025-b2ce2384e17b h1:gQZ0qzfKHQIybLANtM3mBXNUtOfsCFXeTsnBqCsx1KM= github.com/satori/go.uuid v1.2.1-0.20181028125025-b2ce2384e17b/go.mod h1:dA0hQrYB0VpLJoorglMZABFdXlWrHn1NEOzdhQKdks0= -github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ= -github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ= github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4= -github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= -github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsTg= github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= @@ -73,12 +56,9 @@ golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= -golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.19.0 h1:q5f1RH2jigJ1MoAWp2KTp3gm5zAGFUTarQZ5U386+4o= -golang.org/x/sys v0.19.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= +golang.org/x/sys v0.24.0 h1:Twjiwq9dn6R1fQcyiK+wQyHWfaz/BJB+YIpzU/Cv3Xg= +golang.org/x/sys v0.24.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/tools v0.0.0-20190624222133-a101b041ded4/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc= golang.org/x/tools v0.1.12 h1:VveCTK38A2rkS8ZqFY25HIDFscX5X9OoEhJd3quQmXU= @@ -91,7 +71,6 @@ google.golang.org/protobuf v1.31.0/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqw gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= -gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gotest.tools/v3 v3.0.2/go.mod h1:3SzNCllyD9/Y+b5r9JIKQ474KzkZyqLqEfYqMsX94Bk= diff --git a/example/proxysip/main.go b/example/proxysip/main.go index 269f12f..386e809 100644 --- a/example/proxysip/main.go +++ b/example/proxysip/main.go @@ -5,24 +5,22 @@ import ( "encoding/json" "errors" "flag" + "log/slog" "net/http" + _ "net/http/pprof" "os" "os/signal" "runtime" "runtime/pprof" "strconv" - "time" "github.com/arl/statsviz" - "github.com/emiago/sipgo/sip" - _ "net/http/pprof" + "github.com/emiago/sipgo/sip" "github.com/emiago/sipgo" "github.com/prometheus/client_golang/prometheus/promhttp" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" // _ "go.uber.org/automaxprocs" ) @@ -45,21 +43,17 @@ func main() { runtime.MemProfileRate = 64 } - lev := zerolog.InfoLevel + lev := slog.LevelInfo debuglev := os.Getenv("LOGDEBUG") if *debflag || debuglev != "" { - lev = zerolog.DebugLevel + lev = slog.LevelDebug sip.SIPDebug = true } - zerolog.TimeFieldFormat = zerolog.TimeFormatUnixMicro - log.Logger = zerolog.New(zerolog.ConsoleWriter{ - Out: os.Stdout, - TimeFormat: time.StampMicro, - }).With().Timestamp().Logger().Level(lev) + slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: lev}))) - log.Info().Int("cpus", runtime.NumCPU()).Msg("Runtime") - log.Info().Msg("Server routes setuped") + slog.Info("Runtime", "cpus", runtime.NumCPU()) + slog.Info("Server routes setuped") go httpServer(":8080") srv := setupSipProxy(*dst, *extIP) @@ -68,7 +62,7 @@ func main() { defer stop() if err := srv.ListenAndServe(ctx, *transportType, *extIP); err != nil { - log.Error().Err(err).Msg("Fail to start sip server") + slog.Error("Fail to start sip server", "error", err) return } } @@ -90,7 +84,7 @@ func httpServer(address string) { }) statsviz.Register(http.DefaultServeMux) - log.Info().Msgf("Http server started address=%s", address) + slog.Info("Http server started address=%s", address) http.ListenAndServe(address, nil) } @@ -99,19 +93,22 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { host, port, _ := sip.ParseAddr(ip) ua, err := sipgo.NewUA() if err != nil { - log.Fatal().Err(err).Msg("Fail to setup user agent") + slog.Error("Fail to setup user agent", "error", err) + os.Exit(1) } srv, err := sipgo.NewServer(ua) if err != nil { - log.Fatal().Err(err).Msg("Fail to setup server handle") + slog.Error("Fail to setup server handle", "error", err) + os.Exit(1) } client, err := sipgo.NewClient(ua, sipgo.WithClientAddr( ip, )) if err != nil { - log.Fatal().Err(err).Msg("Fail to setup client handle") + slog.Error("Fail to setup client handle", "error", err) + os.Exit(1) } registry := NewRegistry() @@ -130,7 +127,7 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { resp := sip.NewResponseFromRequest(req, code, reason, nil) resp.SetDestination(req.Source()) //This is optional, but can make sure not wrong via is read if err := tx.Respond(resp); err != nil { - log.Error().Err(err).Msg("Fail to respond on transaction") + slog.Error("Fail to respond on transaction", "error", err) } } @@ -150,14 +147,14 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { // Start client transaction and relay our request clTx, err := client.TransactionRequest(ctx, req, sipgo.ClientRequestAddVia, sipgo.ClientRequestAddRecordRoute) if err != nil { - log.Error().Err(err).Msg("RequestWithContext failed") + slog.Error("RequestWithContext failed", "error", err) reply(tx, req, 500, "") return } defer clTx.Terminate() // Keep monitoring transactions, and proxy client responses to server transaction - log.Debug().Str("req", req.Method.String()).Msg("Starting transaction") + slog.Debug("Starting transaction", "req", req.Method.String()) for { select { @@ -174,7 +171,7 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { // Removes top most header res.RemoveHeader("Via") if err := tx.Respond(res); err != nil { - log.Error().Err(err).Msg("ResponseHandler transaction respond failed") + slog.Error("ResponseHandler transaction respond failed", "error", err) } // Early terminate @@ -184,13 +181,13 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { // } case <-clTx.Done(): if err := tx.Err(); err != nil { - log.Error().Err(err).Str("req", req.Method.String()).Msg("Client Transaction done with error") + slog.Error("Client Transaction done with error", "error", err, "req", req.Method.String()) } return case m := <-tx.Acks(): // Acks can not be send directly trough destination - log.Info().Str("m", m.StartLine()).Str("dst", dst).Msg("Proxing ACK") + slog.Info("Proxing ACK", "m", m.StartLine(), "dst", dst) m.SetDestination(dst) client.WriteRequest(m) @@ -203,21 +200,21 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { r := newCancelRequest(req) res, err := client.Do(ctx, r) if err != nil { - log.Error().Err(err).Str("req", req.Method.String()).Msg("Canceling transaction failed") + slog.Error("Canceling transaction failed", "err", err, "req", req.Method.String()) return } if res.StatusCode != 200 { - log.Error().Err(err).Str("req", req.Method.String()).Msg("Canceling transaction failed with non 200 code") + slog.Error("Canceling transaction failed with non 200 code", "err", err, "req", req.Method.String()) return } return } } - log.Error().Err(err).Str("req", req.Method.String()).Msg("Transaction done with error") + slog.Error("Transaction done with error", "err", err, "req", req.Method.String()) return } - log.Debug().Str("req", req.Method.String()).Msg("Transaction done") + slog.Debug("Transaction done", "req", req.Method.String()) return } } @@ -241,17 +238,17 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { addr := uri.Host + ":" + strconv.Itoa(uri.Port) registry.Add(uri.User, addr) - log.Debug().Msgf("Contact added %s -> %s", uri.User, addr) + slog.Debug("Contact added %s -> %s", "src", uri.User, "dst", addr) res := sip.NewResponseFromRequest(req, 200, "OK", nil) - // log.Debug().Msgf("Sending response: \n%s", res.String()) + // slog.Debug().Msgf("Sending response: \n%s", res.String()) // URI params must be reset or this should be regenetad cont.Address.UriParams = sip.NewParams() cont.Address.UriParams.Add("transport", req.Transport()) if err := tx.Respond(res); err != nil { - log.Error().Err(err).Msg("Sending REGISTER OK failed") + slog.Error("Sending REGISTER OK failed", "error", err) return } } @@ -267,7 +264,7 @@ func setupSipProxy(proxydst string, ip string) *sipgo.Server { } req.SetDestination(dst) if err := client.WriteRequest(req, sipgo.ClientRequestAddVia); err != nil { - log.Error().Err(err).Msg("Send failed") + slog.Error("Send failed", "error", err) reply(tx, req, 500, "") } } diff --git a/example/proxysip/main_test.go b/example/proxysip/main_test.go index 5b88a81..8b9e894 100644 --- a/example/proxysip/main_test.go +++ b/example/proxysip/main_test.go @@ -3,6 +3,7 @@ package main import ( "flag" "io" + "log/slog" "net" "os" "strings" @@ -12,9 +13,6 @@ import ( "github.com/emiago/sipgo/fakes" "github.com/emiago/sipgo/sip" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -174,29 +172,15 @@ func TestMain(m *testing.M) { debug := flag.Bool("debug", false, "") flag.Parse() - logruser := logrus.New() - formater := &logrus.TextFormatter{ - ForceColors: true, - FullTimestamp: true, - TimestampFormat: "2006-01-02 15:04:05.000", + var lvl slog.Level + if err := lvl.UnmarshalText([]byte(os.Getenv("LOG_LEVEL"))); err != nil { + lvl = slog.LevelWarn } - - formater.DisableColors = false - logruser.Formatter = formater - - logruser.SetOutput(os.Stderr) - // logruser.SetLevel(logrus.DebugLevel) - - log.Logger = zerolog.New(zerolog.ConsoleWriter{ - Out: os.Stdout, - TimeFormat: "2006-01-02 15:04:05.000", - }).With().Timestamp().Logger().Level(zerolog.WarnLevel) - if *debug { - logruser.SetLevel(logrus.TraceLevel) - log.Logger = log.Logger.With().Logger().Level(zerolog.DebugLevel) + lvl = slog.LevelDebug sip.SIPDebug = true } + slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: lvl}))) m.Run() } diff --git a/example/register/client/main.go b/example/register/client/main.go index 02bea4c..3fd60ce 100644 --- a/example/register/client/main.go +++ b/example/register/client/main.go @@ -4,14 +4,12 @@ import ( "context" "flag" "fmt" + "log/slog" "os" "strings" - "time" "github.com/emiago/sipgo" "github.com/emiago/sipgo/sip" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" "github.com/icholy/digest" ) @@ -28,27 +26,25 @@ func main() { // Make SIP Debugging available sip.SIPDebug = os.Getenv("SIP_DEBUG") != "" - zerolog.TimeFieldFormat = zerolog.TimeFormatUnixMicro - log.Logger = zerolog.New(zerolog.ConsoleWriter{ - Out: os.Stdout, - TimeFormat: time.StampMicro, - }).With().Timestamp().Logger().Level(zerolog.InfoLevel) - - if lvl, err := zerolog.ParseLevel(os.Getenv("LOG_LEVEL")); err == nil && lvl != zerolog.NoLevel { - log.Logger = log.Logger.Level(lvl) + var lvl slog.Level + if err := lvl.UnmarshalText([]byte(os.Getenv("LOG_LEVEL"))); err != nil { + lvl = slog.LevelInfo } + slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: lvl}))) // Setup UAC ua, err := sipgo.NewUA( sipgo.WithUserAgent(*user), ) if err != nil { - log.Fatal().Err(err).Msg("Fail to setup user agent") + slog.Error("Fail to setup user agent", "error", err) + os.Exit(1) } client, err := sipgo.NewClient(ua, sipgo.WithClientHostname(*inter)) if err != nil { - log.Fatal().Err(err).Msg("Fail to setup client handle") + slog.Error("Fail to setup client handle", "error", err) + os.Exit(1) } defer client.Close() @@ -63,26 +59,29 @@ func main() { // Send request and parse response // req.SetDestination(*dst) - log.Info().Msg(req.StartLine()) + slog.Info(req.StartLine()) ctx := context.Background() tx, err := client.TransactionRequest(ctx, req) if err != nil { - log.Fatal().Err(err).Msg("Fail to create transaction") + slog.Error("Fail to create transaction", "error", err) + os.Exit(1) } defer tx.Terminate() res, err := getResponse(tx) if err != nil { - log.Fatal().Err(err).Msg("Fail to get response") + slog.Error("Fail to get response", "error", err) + os.Exit(1) } - log.Info().Int("status", int(res.StatusCode)).Msg("Received status") + slog.Info("Received status", "status", int(res.StatusCode)) if res.StatusCode == 401 { // Get WwW-Authenticate wwwAuth := res.GetHeader("WWW-Authenticate") chal, err := digest.ParseChallenge(wwwAuth.Value()) if err != nil { - log.Fatal().Str("wwwauth", wwwAuth.Value()).Err(err).Msg("Fail to parse challenge") + slog.Error("Fail to parse challenge", "wwwauth", wwwAuth.Value(), "error", err) + os.Exit(1) } // Reply with digest @@ -100,21 +99,24 @@ func main() { ctx := context.Background() tx, err := client.TransactionRequest(ctx, newReq, sipgo.ClientRequestAddVia) if err != nil { - log.Fatal().Err(err).Msg("Fail to create transaction") + slog.Error("Fail to create transaction", "error", err) + os.Exit(1) } defer tx.Terminate() res, err = getResponse(tx) if err != nil { - log.Fatal().Err(err).Msg("Fail to get response") + slog.Error("Fail to get response", "error", err) + os.Exit(1) } } if res.StatusCode != 200 { - log.Fatal().Msg("Fail to register") + slog.Error("Fail to register") + os.Exit(1) } - log.Info().Msg("Client registered") + slog.Info("Client registered") } func getResponse(tx sip.ClientTransaction) (*sip.Response, error) { diff --git a/example/register/server/main.go b/example/register/server/main.go index 6478154..15f22bb 100644 --- a/example/register/server/main.go +++ b/example/register/server/main.go @@ -5,17 +5,15 @@ import ( "crypto/tls" "flag" "fmt" + "log/slog" + "net/http" + _ "net/http/pprof" "os" "strings" "time" "github.com/emiago/sipgo" "github.com/emiago/sipgo/sip" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" - - "net/http" - _ "net/http/pprof" "github.com/icholy/digest" ) @@ -31,15 +29,11 @@ func main() { // Make SIP Debugging available sip.SIPDebug = os.Getenv("SIP_DEBUG") != "" - zerolog.TimeFieldFormat = zerolog.TimeFormatUnixMicro - log.Logger = zerolog.New(zerolog.ConsoleWriter{ - Out: os.Stdout, - TimeFormat: time.StampMicro, - }).With().Timestamp().Logger().Level(zerolog.InfoLevel) - - if lvl, err := zerolog.ParseLevel(os.Getenv("LOG_LEVEL")); err == nil && lvl != zerolog.NoLevel { - log.Logger = log.Logger.Level(lvl) + var lvl slog.Level + if err := lvl.UnmarshalText([]byte(os.Getenv("LOG_LEVEL"))); err != nil { + lvl = slog.LevelInfo } + slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: lvl}))) registry := make(map[string]string) for _, c := range strings.Split(*creds, ",") { @@ -49,15 +43,17 @@ func main() { ua, err := sipgo.NewUA( sipgo.WithUserAgent("SIPGO"), - // sipgo.WithUserAgentIP(*extIP), + // sipgo.WithUserAgentIP(*extIP), ) if err != nil { - log.Fatal().Err(err).Msg("Fail to setup user agent") + slog.Error("Fail to setup user agent", "error", err) + os.Exit(1) } srv, err := sipgo.NewServer(ua) if err != nil { - log.Fatal().Err(err).Msg("Fail to setup server handle") + slog.Error("Fail to setup server handle", "error", err) + os.Exit(1) } ctx := context.TODO() @@ -85,7 +81,7 @@ func main() { cred, err := digest.ParseCredentials(h.Value()) if err != nil { - log.Error().Err(err).Msg("parsing creds failed") + slog.Error("parsing creds failed", "error", err) tx.Respond(sip.NewResponseFromRequest(req, 401, "Bad credentials", nil)) return } @@ -106,7 +102,7 @@ func main() { }) if err != nil { - log.Error().Err(err).Msg("Calc digest failed") + slog.Error("Calc digest failed", "error", err) tx.Respond(sip.NewResponseFromRequest(req, 401, "Bad credentials", nil)) return } @@ -115,11 +111,11 @@ func main() { tx.Respond(sip.NewResponseFromRequest(req, 401, "Unathorized", nil)) return } - log.Info().Str("username", cred.Username).Str("source", req.Source()).Msg("New client registered") + slog.Info("New client registered", "username", cred.Username, "source", req.Source()) tx.Respond(sip.NewResponseFromRequest(req, 200, "OK", nil)) }) - log.Info().Str("addr", *extIP).Msg("Listening on") + slog.Info("Listening on", "addr", *extIP) go func() { http.ListenAndServe(":6060", nil) @@ -130,15 +126,16 @@ func main() { cert, err := tls.LoadX509KeyPair(*tlscrt, *tlskey) if err != nil { - log.Fatal().Err(err).Msg("Fail to load x509 key and crt") + slog.Error("Fail to load x509 key and crt", "error", err) + os.Exit(1) } if err := srv.ListenAndServeTLS(ctx, *tran, *extIP, &tls.Config{Certificates: []tls.Certificate{cert}}); err != nil { - log.Info().Err(err).Msg("Listening stop") + slog.Info("Listening stop", "error", err) } return } if err := srv.ListenAndServe(ctx, *tran, *extIP); err != nil { - log.Error().Err(err).Msg("Failed to listen") + slog.Error("Failed to listen", "error", err) } } diff --git a/go.mod b/go.mod index 456d138..3551490 100644 --- a/go.mod +++ b/go.mod @@ -6,7 +6,6 @@ require ( github.com/gobwas/ws v1.3.2 github.com/google/uuid v1.6.0 github.com/icholy/digest v0.1.22 - github.com/rs/zerolog v1.33.0 github.com/satori/go.uuid v1.2.1-0.20181028125025-b2ce2384e17b github.com/stretchr/testify v1.9.0 ) @@ -17,8 +16,6 @@ require ( github.com/gobwas/pool v0.2.1 // indirect github.com/google/go-cmp v0.6.0 // indirect github.com/kr/pretty v0.3.1 // indirect - github.com/mattn/go-colorable v0.1.13 // indirect - github.com/mattn/go-isatty v0.0.20 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect github.com/rogpeppe/go-internal v1.12.0 // indirect golang.org/x/sys v0.24.0 // indirect diff --git a/go.sum b/go.sum index 481b720..ffe2dce 100644 --- a/go.sum +++ b/go.sum @@ -1,4 +1,3 @@ -github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -8,7 +7,6 @@ github.com/gobwas/pool v0.2.1 h1:xfeeEhW7pwmX8nuLVlqbzVc7udMDrwetjEv+TZIz1og= github.com/gobwas/pool v0.2.1/go.mod h1:q8bcK0KcYlCgd9e7WYLm9LpyS+YeLd8JVDW6WezmKEw= github.com/gobwas/ws v1.3.2 h1:zlnbNHxumkRvfPWgfXu8RBwyNR1x8wh9cf5PTOCqs9Q= github.com/gobwas/ws v1.3.2/go.mod h1:hRKAFb8wOxFROYNsT1bqfWnhX+b5MFeJM9r2ZSwg/KY= -github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/google/go-cmp v0.3.0/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= @@ -23,23 +21,13 @@ github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= -github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= -github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= -github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= -github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= -github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= -github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/pkg/diff v0.0.0-20210226163009-20ebb0f2a09e/go.mod h1:pJLUxLENpZxwdsKMEsNbx1VGcRFpLqf3715MtcvvzbA= github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= -github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs= github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8= github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4= -github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= -github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8= -github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= github.com/satori/go.uuid v1.2.1-0.20181028125025-b2ce2384e17b h1:gQZ0qzfKHQIybLANtM3mBXNUtOfsCFXeTsnBqCsx1KM= github.com/satori/go.uuid v1.2.1-0.20181028125025-b2ce2384e17b/go.mod h1:dA0hQrYB0VpLJoorglMZABFdXlWrHn1NEOzdhQKdks0= github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4= @@ -49,9 +37,7 @@ golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACk golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= -golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.24.0 h1:Twjiwq9dn6R1fQcyiK+wQyHWfaz/BJB+YIpzU/Cv3Xg= golang.org/x/sys v0.24.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= diff --git a/server.go b/server.go index 2d18814..b8d591c 100644 --- a/server.go +++ b/server.go @@ -6,13 +6,11 @@ import ( "crypto/x509" "fmt" "io" + "log/slog" "net" "strings" "github.com/emiago/sipgo/sip" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) var ( @@ -33,7 +31,7 @@ type Server struct { requestHandlers map[sip.RequestMethod]RequestHandler noRouteHandler RequestHandler - log zerolog.Logger + log *slog.Logger requestMiddlewares []func(r *sip.Request) responseMiddlewares []func(r *sip.Response) @@ -42,7 +40,7 @@ type Server struct { type ServerOption func(s *Server) error // WithServerLogger allows customizing server logger -func WithServerLogger(logger zerolog.Logger) ServerOption { +func WithServerLogger(logger *slog.Logger) ServerOption { return func(s *Server) error { s.log = logger return nil @@ -71,7 +69,7 @@ func newBaseServer(ua *UserAgent, options ...ServerOption) (*Server, error) { requestMiddlewares: make([]func(r *sip.Request), 0), responseMiddlewares: make([]func(r *sip.Response), 0), requestHandlers: make(map[sip.RequestMethod]RequestHandler), - log: log.Logger.With().Str("caller", "Server").Logger(), + log: slog.With("caller", "Server"), } for _, o := range options { if err := o(s); err != nil { @@ -99,7 +97,7 @@ func (srv *Server) ListenAndServe(ctx context.Context, network string, addr stri return } if err := connCloser.Close(); err != nil { - srv.log.Error().Err(err).Msg("Failed to close listener") + srv.log.Error("Failed to close listener", "error", err) } } @@ -181,7 +179,7 @@ func (srv *Server) ListenAndServeTLS(ctx context.Context, network string, addr s return } if err := connCloser.Close(); err != nil { - srv.log.Error().Err(err).Msg("Failed to close listener") + srv.log.Error("Failed to close listener", "error", err) } } @@ -386,11 +384,11 @@ func (srv *Server) getHandler(method sip.RequestMethod) (handler RequestHandler) } func (srv *Server) defaultUnhandledHandler(req *sip.Request, tx sip.ServerTransaction) { - srv.log.Warn().Msg("SIP request handler not found") + srv.log.Warn("SIP request handler not found") res := sip.NewResponseFromRequest(req, 405, "Method Not Allowed", nil) // Send response directly and let transaction terminate if err := srv.WriteResponse(res); err != nil { - srv.log.Error().Err(err).Msg("respond '405 Method Not Allowed' failed") + srv.log.Error("respond '405 Method Not Allowed' failed", "error", err) } } diff --git a/server_test.go b/server_test.go index 1a24cef..700d691 100644 --- a/server_test.go +++ b/server_test.go @@ -3,18 +3,18 @@ package sipgo import ( "fmt" "io" + "log/slog" "net" "os" "strings" "testing" "time" - "github.com/emiago/sipgo/fakes" - "github.com/emiago/sipgo/sip" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + + "github.com/emiago/sipgo/fakes" + "github.com/emiago/sipgo/sip" ) func testCreateMessage(t testing.TB, rawMsg []string) sip.Message { @@ -97,14 +97,11 @@ func createTestBye(t testing.TB, targetSipUri string, transport, addr string, ca } func TestMain(m *testing.M) { - log.Logger = zerolog.New(zerolog.ConsoleWriter{ - Out: os.Stdout, - TimeFormat: "2006-01-02 15:04:05.000", - }).With().Timestamp().Logger().Level(zerolog.WarnLevel) - - if lvl, err := zerolog.ParseLevel(os.Getenv("LOG_LEVEL")); err == nil { - log.Logger = log.Level(lvl) + var lvl slog.Level + if err := lvl.UnmarshalText([]byte(os.Getenv("LOG_LEVEL"))); err != nil { + lvl = slog.LevelWarn } + slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: lvl}))) sip.SIPDebug = os.Getenv("SIP_DEBUG") == "true" sip.TransactionFSMDebug = os.Getenv("TRANSACTION_DEBUG") == "true" m.Run() @@ -397,7 +394,7 @@ func ExampleServer_OnNoRoute() { res := sip.NewResponseFromRequest(req, 405, "Method Not Allowed", nil) // Send response directly and let transaction terminate if err := srv.WriteResponse(res); err != nil { - srv.log.Error().Err(err).Msg("respond '405 Method Not Allowed' failed") + srv.log.Error("respond '405 Method Not Allowed' failed", "error", err) } }) } diff --git a/sip/headers.go b/sip/headers.go index 4539444..4fa56dd 100644 --- a/sip/headers.go +++ b/sip/headers.go @@ -3,10 +3,9 @@ package sip import ( "fmt" "io" + "log/slog" "strconv" "strings" - - "github.com/rs/zerolog/log" ) const () @@ -1035,7 +1034,7 @@ func parseHeaderLazy[T any, HP headerPointerReceiver[T]](hs *headers, f func(hea } if err := f(hdr.Value(), h); err != nil { - log.Debug().Err(err).Msgf("Lazy header parsing of %s failed", hdr.Name()) + slog.Debug("Lazy header parsing failed", "header", hdr.Name(), "error", err) return false } return true diff --git a/sip/parser.go b/sip/parser.go index 19ce6f5..97d9c5e 100644 --- a/sip/parser.go +++ b/sip/parser.go @@ -5,12 +5,10 @@ import ( "errors" "fmt" "io" + "log/slog" "strconv" "strings" "sync" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) // The whitespace characters recognised by the Augmented Backus-Naur Form syntax @@ -48,7 +46,7 @@ func ParseMessage(msgData []byte) (Message, error) { // Parser is implementation of SIPParser // It is optimized with faster header parsing type Parser struct { - log zerolog.Logger + log *slog.Logger // HeadersParsers uses default list of headers to be parsed. Smaller list parser will be faster headersParsers mapHeadersParser } @@ -59,7 +57,7 @@ type ParserOption func(p *Parser) // Create a new Parser. func NewParser(options ...ParserOption) *Parser { p := &Parser{ - log: log.Logger, + log: slog.Default(), headersParsers: headersParsers, } @@ -71,7 +69,7 @@ func NewParser(options ...ParserOption) *Parser { } // WithServerLogger allows customizing parser logger -func WithParserLogger(logger zerolog.Logger) ParserOption { +func WithParserLogger(logger *slog.Logger) ParserOption { return func(p *Parser) { p.log = logger } diff --git a/sip/sip.go b/sip/sip.go index 1560ec6..1912540 100644 --- a/sip/sip.go +++ b/sip/sip.go @@ -2,9 +2,8 @@ package sip import ( "fmt" + "log/slog" "strings" - - "github.com/rs/zerolog/log" ) const ( @@ -25,20 +24,20 @@ func SIPDebugTracer(t SIPTracer) { siptracer = t } -func logSIPRead(transport string, laddr string, raddr string, sipmsg []byte) { +func logSIPRead(log *slog.Logger, transport string, laddr string, raddr string, sipmsg []byte) { if siptracer != nil { siptracer.SIPTraceRead(transport, laddr, raddr, sipmsg) return } - log.Debug().Msgf("%s read from %s <- %s:\n%s", transport, laddr, raddr, sipmsg) + log.Debug("read from", "local", laddr, "remote", raddr, "msg", sipmsg) } -func logSIPWrite(transport string, laddr string, raddr string, sipmsg []byte) { +func logSIPWrite(log *slog.Logger, transport string, laddr string, raddr string, sipmsg []byte) { if siptracer != nil { siptracer.SIPTraceWrite(transport, laddr, raddr, sipmsg) return } - log.Debug().Msgf("%s write to %s <- %s:\n%s", transport, laddr, raddr, sipmsg) + log.Debug("write to", "local", laddr, "remote", raddr, "msg", sipmsg) } // GenerateBranch returns random unique branch ID. diff --git a/sip/transaction.go b/sip/transaction.go index 0fdc247..79a8905 100644 --- a/sip/transaction.go +++ b/sip/transaction.go @@ -3,14 +3,13 @@ package sip import ( "errors" "fmt" + "log/slog" "reflect" "runtime" "strconv" "strings" "sync" "time" - - "github.com/rs/zerolog" ) var ( @@ -132,7 +131,7 @@ type baseTx struct { fsmAck *Request fsmCancel *Request - log zerolog.Logger + log *slog.Logger onTerminate FnTxTerminate } @@ -190,7 +189,7 @@ func (tx *baseTx) spinFsmUnsafe(in fsmInput) { if TransactionFSMDebug { fname := runtime.FuncForPC(reflect.ValueOf(tx.fsmState).Pointer()).Name() fname = fname[strings.LastIndex(fname, ".")+1:] - tx.log.Debug().Str("key", tx.key).Str("input", fsmString(i)).Str("state", fname).Msg("Changing transaction state") + tx.log.Debug("Changing transaction state", "key", tx.key, "input", fsmString(i), "state", fname) } i = tx.fsmState(i) } @@ -203,7 +202,7 @@ func (tx *baseTx) spinFsm(in fsmInput) { if TransactionFSMDebug { fname := runtime.FuncForPC(reflect.ValueOf(tx.fsmState).Pointer()).Name() fname = fname[strings.LastIndex(fname, ".")+1:] - tx.log.Debug().Str("key", tx.key).Str("input", fsmString(i)).Str("state", fname).Msg("Changing transaction state") + tx.log.Debug("Changing transaction state", "key", tx.key, "input", fsmString(i), "state", fname) } i = tx.fsmState(i) } diff --git a/sip/transaction_client_tx.go b/sip/transaction_client_tx.go index 1d89ca7..f324dce 100644 --- a/sip/transaction_client_tx.go +++ b/sip/transaction_client_tx.go @@ -2,10 +2,9 @@ package sip import ( "fmt" + "log/slog" "sync" "time" - - "github.com/rs/zerolog" ) type ClientTx struct { @@ -21,7 +20,7 @@ type ClientTx struct { closeOnce sync.Once } -func NewClientTx(key string, origin *Request, conn Connection, logger zerolog.Logger) *ClientTx { +func NewClientTx(key string, origin *Request, conn Connection, logger *slog.Logger) *ClientTx { tx := &ClientTx{} tx.key = key // tx.conn = tpl @@ -30,6 +29,7 @@ func NewClientTx(key string, origin *Request, conn Connection, logger zerolog.Lo tx.responses = make(chan *Response) tx.done = make(chan struct{}) tx.log = logger + tx.log = tx.log.With("tx", key) tx.origin = origin return tx @@ -39,7 +39,7 @@ func (tx *ClientTx) Init() error { tx.initFSM() if err := tx.conn.WriteMsg(tx.origin); err != nil { - tx.log.Debug().Err(err).Str("req", tx.origin.StartLine()).Msg("Fail to write request on init") + tx.log.Debug("Fail to write request on init", "req", tx.origin.StartLine(), "error", err) return wrapTransportError(err) } @@ -72,7 +72,7 @@ func (tx *ClientTx) Init() error { tx.spinFsmWithError(client_input_timer_b, fmt.Errorf("Timer_B timed out. %w", ErrTransactionTimeout)) }) tx.mu.Unlock() - tx.log.Debug().Str("tx", tx.Key()).Msg("Client transaction initialized") + tx.log.Debug("Client transaction initialized") return nil } @@ -157,11 +157,11 @@ func (tx *ClientTx) ack() { err := tx.conn.WriteMsg(ack) if err != nil { - tx.log.Error(). - Str("invite_request", tx.origin.Short()). - Str("invite_response", resp.Short()). - Str("cancel_request", ack.Short()). - Msgf("send ACK request failed: %s", err) + tx.log.Error("send ACK request failed", + "invite_request", tx.origin.Short(), + "invite_response", resp.Short(), + "cancel_request", ack.Short(), + "error", err) err := wrapTransportError(err) go tx.spinFsmWithError(client_input_transport_err, err) @@ -179,7 +179,7 @@ func (tx *ClientTx) resend() { err := tx.conn.WriteMsg(tx.origin) if err != nil { - tx.log.Debug().Err(err).Str("req", tx.origin.StartLine()).Msg("Fail to resend request") + tx.log.Debug("Fail to resend request", "req", tx.origin.StartLine(), "error", err) err := wrapTransportError(err) go tx.spinFsmWithError(client_input_transport_err, err) } @@ -199,7 +199,7 @@ func (tx *ClientTx) delete() { } if _, err := tx.conn.TryClose(); err != nil { - tx.log.Info().Err(err).Msg("Closing connection returned error") + tx.log.Info("Closing connection returned error", "error", err) } }) @@ -217,5 +217,5 @@ func (tx *ClientTx) delete() { tx.timer_d = nil } tx.mu.Unlock() - tx.log.Debug().Str("tx", tx.Key()).Msg("Client transaction destroyed") + tx.log.Debug("Client transaction destroyed") } diff --git a/sip/transaction_client_tx_fsm.go b/sip/transaction_client_tx_fsm.go index 1ed0e9c..f30b847 100644 --- a/sip/transaction_client_tx_fsm.go +++ b/sip/transaction_client_tx_fsm.go @@ -97,11 +97,11 @@ func (tx *ClientTx) inviteStateAccepted(s fsmInput) fsmInput { // received while the client INVITE state machine is in the "Calling" or // "Proceeding" states, it MUST transition to the "Accepted" state, pass // the 2xx response to the TU, and set Timer M to 64*T1 - tx.log.Debug().Msg("retransimission 2xx detected") + tx.log.Debug("retransimission 2xx detected") tx.fsmState, spinfn = tx.inviteStateAccepted, tx.actPassupRetransmission case client_input_transport_err: - tx.log.Warn().Msg("client transport error detected. Waiting for retransmission") + tx.log.Warn("client transport error detected. Waiting for retransmission") tx.fsmState, spinfn = tx.inviteStateAccepted, tx.actTranErrNoDelete case client_input_timer_m: tx.fsmState, spinfn = tx.inviteStateTerminated, tx.actDelete @@ -342,7 +342,7 @@ func (tx *ClientTx) actAckResend() fsmInput { if tx.fsmAck != nil { // ACK was sent. Now delay to prevent infinite loop as temporarly fix // This is not clear per RFC, but client could generate a lot requests in this case - tx.log.Error().Msg("ACK loop retransimission. Resending after T2") + tx.log.Error("ACK loop retransimission. Resending after T2") select { case <-tx.done: return FsmInputNone @@ -449,6 +449,6 @@ func (tx *ClientTx) passUpRetransmission() { case tx.responses <- lastResp: // TODO is T1 best here option? This can take Timer_M as 64*T1 case <-time.After(T1): - tx.log.Debug().Msg("skipped response. Retransimission") + tx.log.Debug("skipped response. Retransimission") } } diff --git a/sip/transaction_client_tx_test.go b/sip/transaction_client_tx_test.go index 4586573..f21571e 100644 --- a/sip/transaction_client_tx_test.go +++ b/sip/transaction_client_tx_test.go @@ -3,13 +3,14 @@ package sip import ( "bytes" "io" + "log/slog" "sync" "testing" "time" - "github.com/emiago/sipgo/fakes" - "github.com/rs/zerolog/log" "github.com/stretchr/testify/require" + + "github.com/emiago/sipgo/fakes" ) func TestClientTransactionInviteFSM(t *testing.T) { @@ -24,8 +25,9 @@ func TestClientTransactionInviteFSM(t *testing.T) { Reader: incoming, Writers: map[string]io.Writer{"127.0.0.99:5060": outgoing}, }, + log: slog.Default(), } - tx := NewClientTx("123", req, conn, log.Logger) + tx := NewClientTx("123", req, conn, slog.Default()) // CALLING STATE err := tx.Init() @@ -70,8 +72,9 @@ func TestClientTransactionFSM(t *testing.T) { Reader: incoming, Writers: map[string]io.Writer{"127.0.0.99:5060": outgoing}, }, + log: slog.Default(), } - tx := NewClientTx("123", req, conn, log.Logger) + tx := NewClientTx("123", req, conn, slog.Default()) err := tx.Init() require.NoError(t, err) @@ -97,8 +100,9 @@ func TestClientTransactionFSM(t *testing.T) { Reader: incoming, Writers: map[string]io.Writer{"127.0.0.99:5060": outgoing}, }, + log: slog.Default(), } - tx := NewClientTx("123", req, conn, log.Logger) + tx := NewClientTx("123", req, conn, slog.Default()) err := tx.Init() require.NoError(t, err) diff --git a/sip/transaction_layer.go b/sip/transaction_layer.go index 28837e8..d5824e8 100644 --- a/sip/transaction_layer.go +++ b/sip/transaction_layer.go @@ -3,9 +3,7 @@ package sip import ( "context" "fmt" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" + "log/slog" ) type RequestHandler func(req *Request, tx ServerTransaction) @@ -13,11 +11,11 @@ type UnhandledResponseHandler func(req *Response) type ErrorHandler func(err error) func defaultRequestHandler(r *Request, tx ServerTransaction) { - log.Info().Str("caller", "transactionLayer").Str("msg", r.Short()).Msg("Unhandled sip request. OnRequest handler not added") + slog.Info("Unhandled sip request. OnRequest handler not added", "caller", "transactionLayer", "msg", r.Short()) } func defaultUnhandledRespHandler(r *Response) { - log.Info().Str("caller", "transactionLayer").Str("msg", r.Short()).Msg("Unhandled sip response. UnhandledResponseHandler handler not added") + slog.Info("Unhandled sip response. UnhandledResponseHandler handler not added", "caller", "transactionLayer", "msg", r.Short()) } type TransactionLayer struct { @@ -28,7 +26,7 @@ type TransactionLayer struct { clientTransactions *transactionStore serverTransactions *transactionStore - log zerolog.Logger + log *slog.Logger } func NewTransactionLayer(tpl *TransportLayer) *TransactionLayer { @@ -40,7 +38,7 @@ func NewTransactionLayer(tpl *TransportLayer) *TransactionLayer { reqHandler: defaultRequestHandler, unRespHandler: defaultUnhandledRespHandler, } - txl.log = log.Logger.With().Str("caller", "transactionLayer").Logger() + txl.log = slog.With("caller", "transactionLayer") //Send all transport messages to our transaction layer tpl.OnMessage(txl.handleMessage) return txl @@ -68,7 +66,7 @@ func (txl *TransactionLayer) handleMessage(msg Message) { case *Response: go txl.handleResponse(msg) default: - txl.log.Error().Msg("unsupported message, skip it") + txl.log.Error("unsupported message, skip it") } } @@ -83,7 +81,7 @@ func (txl *TransactionLayer) handleRequest(req *Request) { // For now we only match INVITE key, err := makeServerTxKey(req, INVITE) if err != nil { - txl.log.Error().Err(err).Msg("Server tx make key failed") + txl.log.Error("Server tx make key failed", "error", err) return } @@ -91,13 +89,13 @@ func (txl *TransactionLayer) handleRequest(req *Request) { if exists { // If ok this should terminate this transaction if err := tx.Receive(req); err != nil { - txl.log.Error().Err(err).Msg("Server tx failed to receive req") + txl.log.Error("Server tx failed to receive req", "error", err) return } // Reuse connection and send 200 for CANCEL if err := tx.conn.WriteMsg(NewResponseFromRequest(req, StatusOK, "OK", nil)); err != nil { - txl.log.Error().Err(err).Msg("Failed to respond 200 for CANCEL") + txl.log.Error("Failed to respond 200 for CANCEL", "error", err) } return } @@ -106,14 +104,14 @@ func (txl *TransactionLayer) handleRequest(req *Request) { key, err := makeServerTxKey(req, "") if err != nil { - txl.log.Error().Err(err).Msg("Server tx make key failed") + txl.log.Error("Server tx make key failed", "error", err) return } tx, exists := txl.getServerTx(key) if exists { if err := tx.Receive(req); err != nil { - txl.log.Error().Err(err).Msg("Server tx failed to receive req") + txl.log.Error("Server tx failed to receive req", "error", err) } return } @@ -122,14 +120,14 @@ func (txl *TransactionLayer) handleRequest(req *Request) { // TODO: What if we are gettinb BYE and client closed connection conn, err := txl.tpl.GetConnection(req.Transport(), req.Source()) if err != nil { - txl.log.Error().Err(err).Msg("Server tx get connection failed") + txl.log.Error("Server tx get connection failed", "error", err) return } tx = NewServerTx(key, req, conn, txl.log) if err := tx.Init(); err != nil { - txl.log.Error().Err(err).Msg("Server tx init failed") + txl.log.Error("Server tx init failed", "error", err) return } // put tx to store, to match retransmitting requests later @@ -142,7 +140,7 @@ func (txl *TransactionLayer) handleRequest(req *Request) { func (txl *TransactionLayer) handleResponse(res *Response) { key, err := MakeClientTxKey(res) if err != nil { - txl.log.Error().Err(err).Msg("Client tx make key failed") + txl.log.Error("Client tx make key failed", "error", err) return } @@ -217,13 +215,13 @@ func (txl *TransactionLayer) Respond(res *Response) (*ServerTx, error) { func (txl *TransactionLayer) clientTxTerminate(key string) { if !txl.clientTransactions.drop(key) { - txl.log.Info().Str("key", key).Msg("Non existing client tx was removed") + txl.log.Info("Non existing client tx was removed", "key", key) } } func (txl *TransactionLayer) serverTxTerminate(key string) { if !txl.serverTransactions.drop(key) { - txl.log.Info().Str("key", key).Msg("Non existing server tx was removed") + txl.log.Info("Non existing server tx was removed", "key", key) } } @@ -248,7 +246,7 @@ func (txl *TransactionLayer) getServerTx(key string) (*ServerTx, bool) { func (txl *TransactionLayer) Close() { txl.clientTransactions.terminateAll() txl.serverTransactions.terminateAll() - txl.log.Debug().Msg("transaction layer closed") + txl.log.Debug("transaction layer closed") } func (txl *TransactionLayer) Transport() *TransportLayer { diff --git a/sip/transaction_server_tx.go b/sip/transaction_server_tx.go index e6ae076..aa07712 100644 --- a/sip/transaction_server_tx.go +++ b/sip/transaction_server_tx.go @@ -2,10 +2,9 @@ package sip import ( "fmt" + "log/slog" "sync" "time" - - "github.com/rs/zerolog" ) type ServerTx struct { @@ -26,7 +25,7 @@ type ServerTx struct { closeOnce sync.Once } -func NewServerTx(key string, origin *Request, conn Connection, logger zerolog.Logger) *ServerTx { +func NewServerTx(key string, origin *Request, conn Connection, logger *slog.Logger) *ServerTx { tx := new(ServerTx) tx.key = key tx.conn = conn @@ -36,6 +35,7 @@ func NewServerTx(key string, origin *Request, conn Connection, logger zerolog.Lo // tx.cancels = make(chan *Request) tx.done = make(chan struct{}) tx.log = logger + tx.log = tx.log.With("tx", key) tx.origin = origin tx.reliable = IsReliable(origin.Transport()) return tx @@ -66,12 +66,12 @@ func (tx *ServerTx) Init() error { ) // tx.Log().Trace("timer_1xx fired") if err := tx.Respond(trying); err != nil { - tx.log.Error().Err(err).Msg("send '100 Trying' response failed") + tx.log.Error("send '100 Trying' response failed", "error", err) } }) tx.mu.Unlock() } - tx.log.Debug().Str("tx", tx.Key()).Msg("Server transaction initialized") + tx.log.Debug("Server transaction initialized") return nil } @@ -136,7 +136,7 @@ func (tx *ServerTx) Acks() <-chan *Request { func (tx *ServerTx) ackSend(r *Request) { select { case <-tx.done: - tx.log.Warn().Str("callid", r.CallID().Value()).Msg("ACK missed") + tx.log.Warn("ACK missed", "callid", r.CallID().Value()) case tx.acks <- r: } } @@ -186,7 +186,7 @@ func (tx *ServerTx) OnCancel(f func(r *Request)) { } func (tx *ServerTx) Terminate() { - tx.log.Debug().Msg("Server transaction terminating") + tx.log.Debug("Server transaction terminating") tx.delete() } @@ -243,5 +243,5 @@ func (tx *ServerTx) delete() { tx.timer_1xx = nil } tx.mu.Unlock() - tx.log.Debug().Str("tx", tx.Key()).Msg("Server transaction destroyed") + tx.log.Debug("Server transaction destroyed") } diff --git a/sip/transaction_server_tx_fsm.go b/sip/transaction_server_tx_fsm.go index c290330..d1b3638 100644 --- a/sip/transaction_server_tx_fsm.go +++ b/sip/transaction_server_tx_fsm.go @@ -245,13 +245,13 @@ func (tx *ServerTx) actFinal() fsmInput { // Inform user of transport error func (tx *ServerTx) actTransErr() fsmInput { - tx.log.Debug().Err(tx.fsmErr).Msg("Transport error. Transaction will terminate") + tx.log.Debug("Transport error. Transaction will terminate", "error", tx.fsmErr) return server_input_delete } // Inform user of timeout error func (tx *ServerTx) actTimeout() fsmInput { - tx.log.Debug().Err(tx.fsmErr).Msg("Timed out. Transaction will terminate") + tx.log.Debug("Timed out. Transaction will terminate", "error", tx.fsmErr) return server_input_delete } @@ -270,7 +270,7 @@ func (tx *ServerTx) actRespondDelete() fsmInput { if err != nil { tx.fsmErr = wrapTransportError(err) - tx.log.Debug().Err(err).Msg("fail to actRespondDelete") + tx.log.Debug("fail to actRespondDelete", "error", err) return server_input_transport_err } @@ -312,7 +312,7 @@ func (tx *ServerTx) actCancel() fsmInput { if tx.onCancel != nil { tx.onCancel(r) } - tx.log.Debug().Msg("Passing 487 on CANCEL") + tx.log.Debug("Passing 487 on CANCEL") tx.fsmResp = NewResponseFromRequest(tx.origin, StatusRequestTerminated, "Request Terminated", nil) tx.fsmErr = ErrTransactionCanceled // For now only informative return server_input_user_300_plus @@ -350,7 +350,7 @@ func (tx *ServerTx) passResp() error { // tx.Log().Debug("actFinal") err := tx.conn.WriteMsg(lastResp) if err != nil { - tx.log.Debug().Err(err).Str("res", lastResp.StartLine()).Msg("fail to pass response") + tx.log.Debug("fail to pass response", "res", lastResp.StartLine(), "error", err) tx.fsmErr = wrapTransportError(err) return err } diff --git a/sip/transaction_server_tx_test.go b/sip/transaction_server_tx_test.go index 9a7df3d..6772c18 100644 --- a/sip/transaction_server_tx_test.go +++ b/sip/transaction_server_tx_test.go @@ -3,11 +3,12 @@ package sip import ( "bytes" "io" + "log/slog" "testing" - "github.com/emiago/sipgo/fakes" - "github.com/rs/zerolog/log" "github.com/stretchr/testify/require" + + "github.com/emiago/sipgo/fakes" ) func TestServerTransactionFSM(t *testing.T) { @@ -23,8 +24,9 @@ func TestServerTransactionFSM(t *testing.T) { Reader: incoming, Writers: map[string]io.Writer{"127.0.0.2:5060": outgoing}, }, + log: slog.Default(), } - tx := NewServerTx("123", req, conn, log.Logger) + tx := NewServerTx("123", req, conn, slog.Default()) err := tx.Init() require.NoError(t, err) @@ -38,8 +40,9 @@ func TestServerTransactionFSM(t *testing.T) { Reader: incoming, Writers: map[string]io.Writer{"127.0.0.2:5060": outgoing}, }, + log: slog.Default(), } - tx := NewServerTx("123", req, conn, log.Logger) + tx := NewServerTx("123", req, conn, slog.Default()) err := tx.Init() require.NoError(t, err) diff --git a/sip/transport_connection_pool.go b/sip/transport_connection_pool.go index aafb23e..38afd4f 100644 --- a/sip/transport_connection_pool.go +++ b/sip/transport_connection_pool.go @@ -2,10 +2,9 @@ package sip import ( "bytes" + "log/slog" "net" "sync" - - "github.com/rs/zerolog/log" ) type Connection interface { @@ -33,14 +32,19 @@ var bufPool = sync.Pool{ } type ConnectionPool struct { + log *slog.Logger // TODO consider sync.Map way with atomic checks to reduce mutex contention sync.RWMutex m map[string]Connection } -func NewConnectionPool() *ConnectionPool { +func NewConnectionPool(logger *slog.Logger) *ConnectionPool { + if logger == nil { + logger = slog.Default() + } return &ConnectionPool{ - m: make(map[string]Connection), + log: logger, + m: make(map[string]Connection), } } @@ -99,7 +103,7 @@ func (p *ConnectionPool) CloseAndDelete(c Connection, addr string) { ref, _ := c.TryClose() // Be nice. Saves from double closing if ref > 0 { if err := c.Close(); err != nil { - log.Warn().Err(err).Msg("Closing conection return error") + p.log.Warn("Closing connection return error", "error", err) } } delete(p.m, addr) @@ -128,7 +132,7 @@ func (p *ConnectionPool) Clear() { continue } if err := c.Close(); err != nil { - log.Warn().Err(err).Msg("Closing conection return error") + p.log.Warn("Closing connection return error", "error", err) } } // Remove all diff --git a/sip/transport_connection_pool_test.go b/sip/transport_connection_pool_test.go index ebf4ed3..1d2e4ff 100644 --- a/sip/transport_connection_pool_test.go +++ b/sip/transport_connection_pool_test.go @@ -1,16 +1,16 @@ package sip import ( + "log/slog" "net" + "os" "testing" "github.com/emiago/sipgo/fakes" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) func TestConnectionPool(t *testing.T) { - pool := NewConnectionPool() + pool := NewConnectionPool(slog.Default()) fakeConn := &fakes.TCPConn{ LAddr: net.TCPAddr{IP: net.ParseIP("127.0.0.1"), Port: 5060}, @@ -18,7 +18,7 @@ func TestConnectionPool(t *testing.T) { Reader: nil, Writer: nil, } - conn := &TCPConnection{Conn: fakeConn} + conn := &TCPConnection{Conn: fakeConn, log: slog.Default()} pool.Add(fakeConn.RAddr.String(), conn) @@ -29,8 +29,8 @@ func TestConnectionPool(t *testing.T) { } func BenchmarkConnectionPool(b *testing.B) { - log.Logger = log.Logger.Level(zerolog.WarnLevel) - pool := NewConnectionPool() + logger := slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelWarn})) + pool := NewConnectionPool(logger) for i := 0; i < b.N; i++ { conn := &TCPConnection{Conn: &fakes.TCPConn{ @@ -38,7 +38,7 @@ func BenchmarkConnectionPool(b *testing.B) { RAddr: net.TCPAddr{IP: net.ParseIP("127.0.0.2"), Port: 5060}, Reader: nil, Writer: nil, - }} + }, log: slog.Default()} a := &net.TCPAddr{ IP: net.IPv4('1', '2', '3', byte(i)), Port: 1000, diff --git a/sip/transport_layer.go b/sip/transport_layer.go index 7690c0f..a5c74e7 100644 --- a/sip/transport_layer.go +++ b/sip/transport_layer.go @@ -5,13 +5,11 @@ import ( "crypto/tls" "errors" "fmt" + "log/slog" "math/rand" "net" "sync" "time" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) var ( @@ -41,7 +39,7 @@ type TransportLayer struct { handlers []MessageHandler - log zerolog.Logger + log *slog.Logger // ConnectionReuse will force connection reuse when passing request ConnectionReuse bool @@ -66,21 +64,22 @@ func NewTransportLayer( ConnectionReuse: true, } - l.log = log.Logger.With().Str("caller", "transportlayer").Logger() + logger := slog.Default() + l.log = logger.With("caller", "transportlayer") if tlsConfig == nil { // Use empty tls config tlsConfig = &tlsEmptyConf - } + } // TODO consider this transports are configurable from outside // Make some default transports available. - l.udp = newUDPTransport(sipparser) - l.tcp = newTCPTransport(sipparser) + l.udp = newUDPTransport(sipparser, logger) + l.tcp = newTCPTransport(sipparser, logger) // TODO. Using default dial tls, but it needs to configurable via client - l.tls = newTLSTransport(sipparser, tlsConfig) - l.ws = newWSTransport(sipparser) + l.tls = newTLSTransport(sipparser, tlsConfig, logger) + l.ws = newWSTransport(sipparser, logger) // TODO. Using default dial tls, but it needs to configurable via client - l.wss = newWSSTransport(sipparser, tlsConfig) + l.wss = newWSSTransport(sipparser, tlsConfig, logger) // Fill map for fast access l.transports["udp"] = l.udp @@ -387,16 +386,16 @@ func (l *TransportLayer) ClientRequestConnection(ctx context.Context, req *Reque // DO NOT USE unspecified IP with client handle // switch { // case laddr.IP.IsUnspecified(): - // l.log.Warn().Msg("External Via IP address is unspecified for UDP. Using 127.0.0.1") + // l.log.Warn("External Via IP address is unspecified for UDP. Using 127.0.0.1") // viaHop.Host = "127.0.0.1" // TODO use resolve IP // } return c, nil } } */ - l.log.Debug().Str("addr", addr).Str("raddr", raddr.String()).Msg("Active connection not found") + l.log.Debug("Active connection not found", "addr", addr, "raddr", raddr) } - l.log.Debug().Str("host", viaHop.Host).Int("port", viaHop.Port).Str("network", network).Msg("Via header used for creating connection") + l.log.Debug("Via header used for creating connection", "host", viaHop.Host, "port", viaHop.Port, "network", network) c, err = transport.CreateConnection(ctx, laddr, raddr, l.handleMessage) if err != nil { @@ -433,7 +432,7 @@ func (l *TransportLayer) ClientRequestConnection(ctx context.Context, req *Reque func (l *TransportLayer) resolveAddr(ctx context.Context, network string, host string, addr *Addr) error { defer func(start time.Time) { if dur := time.Since(start); dur > 50*time.Millisecond { - l.log.Warn().Dur("dur", dur).Msg("DNS resolution is slow") + l.log.Warn("DNS resolution is slow", "dur", dur) } }(time.Now()) @@ -442,7 +441,7 @@ func (l *TransportLayer) resolveAddr(ctx context.Context, network string, host s if err == nil { return nil } - log.Warn().Str("host", host).Err(err).Msg("Doing SRV lookup failed.") + l.log.Warn("Doing SRV lookup failed", "host", host, "error", err) return l.resolveAddrIP(ctx, host, addr) } @@ -451,12 +450,12 @@ func (l *TransportLayer) resolveAddr(ctx context.Context, network string, host s return nil } - log.Info().Err(err).Msg("IP addr resolving failed, doing via dns SRV resolver...") + l.log.Info("IP addr resolving failed, doing via dns SRV resolver...", "error", err) return l.resolveAddrSRV(ctx, network, host, addr) } func (l *TransportLayer) resolveAddrIP(ctx context.Context, hostname string, addr *Addr) error { - l.log.Debug().Str("host", hostname).Msg("DNS Resolving") + l.log.Debug("DNS Resolving", "host", hostname) // Do local resolving ips, err := l.dnsResolver.LookupIPAddr(ctx, hostname) @@ -479,7 +478,7 @@ func (l *TransportLayer) resolveAddrIP(ctx context.Context, hostname string, add } func (l *TransportLayer) resolveAddrSRV(ctx context.Context, network string, hostname string, addr *Addr) error { - log := &l.log + log := l.log var proto string switch network { case "udp", "udp4", "udp6": @@ -490,7 +489,7 @@ func (l *TransportLayer) resolveAddrSRV(ctx context.Context, network string, hos proto = "tcp" } - log.Debug().Str("proto", proto).Str("host", hostname).Msg("Doing SRV lookup") + log.Debug("Doing SRV lookup", "proto", proto, "host", hostname) // The returned records are sorted by priority and randomized // by weight within a priority. @@ -499,7 +498,7 @@ func (l *TransportLayer) resolveAddrSRV(ctx context.Context, network string, hos return fmt.Errorf("fail to lookup SRV for %q: %w", hostname, err) } - log.Debug().Interface("addrs", addrs).Msg("SRV resolved") + log.Debug("SRV resolved", "addrs", addrs) record := addrs[0] ips, err := l.dnsResolver.LookupIP(ctx, "ip", record.Target) @@ -507,7 +506,7 @@ func (l *TransportLayer) resolveAddrSRV(ctx context.Context, network string, hos return err } - log.Debug().Interface("ips", ips).Str("target", record.Target).Msg("SRV resolved IPS") + log.Debug("SRV resolved IPS", "ips", ips, "target", record.Target) addr.IP = ips[0] addr.Port = int(record.Port) @@ -530,7 +529,7 @@ func (l *TransportLayer) getConnection(network, addr string) (Connection, error) return nil, fmt.Errorf("transport %s is not supported", network) } - l.log.Debug().Str("network", network).Str("addr", addr).Msg("getting connection") + l.log.Debug("getting connection", "network", network, "addr", addr) c, err := transport.GetConnection(addr) if err == nil && c == nil { return nil, fmt.Errorf("connection %q does not exist", addr) @@ -540,7 +539,7 @@ func (l *TransportLayer) getConnection(network, addr string) (Connection, error) } func (l *TransportLayer) Close() error { - l.log.Debug().Msg("Layer is closing") + l.log.Debug("Layer is closing") var werr error for _, t := range l.transports { if err := t.Close(); err != nil { diff --git a/sip/transport_tcp.go b/sip/transport_tcp.go index ed8660f..3855805 100644 --- a/sip/transport_tcp.go +++ b/sip/transport_tcp.go @@ -6,30 +6,26 @@ import ( "errors" "fmt" "io" + "log/slog" "net" "sync" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) // TCP transport implementation type transportTCP struct { - addr string - transport string - parser *Parser - log zerolog.Logger + addr string + parser *Parser + log *slog.Logger pool *ConnectionPool } -func newTCPTransport(par *Parser) *transportTCP { +func newTCPTransport(par *Parser, logger *slog.Logger) *transportTCP { p := &transportTCP{ - parser: par, - pool: NewConnectionPool(), - transport: TransportTCP, + parser: par, + pool: NewConnectionPool(logger), } - p.log = log.Logger.With().Str("caller", "transport").Logger() + p.log = logger.With("caller", "transport", "transport", "tcp") return p } @@ -37,9 +33,8 @@ func (t *transportTCP) String() string { return "transport" } -func (t *transportTCP) Network() string { - // return "tcp" - return t.transport +func (*transportTCP) Network() string { + return TransportTCP } func (t *transportTCP) Close() error { @@ -50,11 +45,11 @@ func (t *transportTCP) Close() error { // Serve is direct way to provide conn on which this worker will listen func (t *transportTCP) Serve(l net.Listener, handler MessageHandler) error { - t.log.Debug().Msgf("begin listening on %s %s", t.Network(), l.Addr().String()) + t.log.Debug("begin listening", "network", t.Network(), "addr", l.Addr()) for { conn, err := l.Accept() if err != nil { - t.log.Debug().Err(err).Msg("Fail to accept conenction") + t.log.Debug("Fail to accept connection", "error", err) return err } @@ -90,7 +85,7 @@ func (t *transportTCP) CreateConnection(ctx context.Context, laddr Addr, raddr A func (t *transportTCP) createConnection(ctx context.Context, laddr *net.TCPAddr, raddr *net.TCPAddr, handler MessageHandler) (Connection, error) { addr := raddr.String() - t.log.Debug().Str("raddr", addr).Msg("Dialing new connection") + t.log.Debug("Dialing new connection", "raddr", addr) d := net.Dialer{ LocalAddr: laddr, @@ -118,9 +113,11 @@ func (t *transportTCP) initConnection(conn net.Conn, raddr string, handler Messa // // conn.SetKeepAlive(true) // conn.SetKeepAlivePeriod(3 * time.Second) laddr := conn.LocalAddr().String() - t.log.Debug().Str("raddr", raddr).Msg("New connection") + log := t.log.With("raddr", raddr) + log.Debug("New connection") c := &TCPConnection{ Conn: conn, + log: log, refcount: 1 + IdleConnection, } t.pool.Add(laddr, c) @@ -142,11 +139,11 @@ func (t *transportTCP) readConnection(conn *TCPConnection, laddr string, raddr s num, err := conn.Read(buf) if err != nil { if errors.Is(err, net.ErrClosed) || errors.Is(err, io.EOF) { - t.log.Debug().Err(err).Msg("connection was closed") + t.log.Debug("connection was closed", "error", err) return } - t.log.Error().Err(err).Msg("Read error") + t.log.Error("Read error", "error", err) return } @@ -161,11 +158,11 @@ func (t *transportTCP) readConnection(conn *TCPConnection, laddr string, raddr s // One or 2 CRLF // https://datatracker.ietf.org/doc/html/rfc5626#section-3.5.1 if len(bytes.Trim(data, "\r\n")) == 0 { - t.log.Debug().Msg("Keep alive CRLF received") + t.log.Debug("Keep alive CRLF received") if datalen == 4 { // 2 CRLF is ping if _, err := conn.Write(data[:2]); err != nil { - t.log.Error().Err(err).Msg("Failed to pong keep alive") + t.log.Error("Failed to pong keep alive", "error", err) return } } @@ -185,14 +182,12 @@ func (t *transportTCP) parseStream(par *ParserStream, data []byte, src string, h msgs, err := par.ParseSIPStream(data) if err == ErrParseSipPartial { return + } else if err != nil { + t.log.Error("failed to parse", "error", err, "data", string(data)) + return } for _, msg := range msgs { - if err != nil { - t.log.Error().Err(err).Str("data", string(data)).Msg("failed to parse") - return - } - msg.SetTransport(t.Network()) msg.SetSource(src) handler(msg) @@ -203,7 +198,7 @@ func (t *transportTCP) parseStream(par *ParserStream, data []byte, src string, h func (t *transportTCP) parseFull(data []byte, src string, handler MessageHandler) { msg, err := t.parser.ParseSIP(data) //Very expensive operation if err != nil { - t.log.Error().Err(err).Str("data", string(data)).Msg("failed to parse") + t.log.Error("failed to parse", "error", err, "data", string(data)) return } @@ -214,6 +209,7 @@ func (t *transportTCP) parseFull(data []byte, src string, handler MessageHandler type TCPConnection struct { net.Conn + log *slog.Logger mu sync.RWMutex refcount int @@ -224,7 +220,7 @@ func (c *TCPConnection) Ref(i int) int { c.refcount += i ref := c.refcount c.mu.Unlock() - log.Debug().Str("ip", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("TCP reference increment") + c.log.Debug("TCP reference increment", "ip", c.LocalAddr(), "dst", c.RemoteAddr(), "ref", ref) return ref } @@ -232,7 +228,7 @@ func (c *TCPConnection) Close() error { c.mu.Lock() c.refcount = 0 c.mu.Unlock() - log.Debug().Str("ip", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", 0).Msg("TCP doing hard close") + c.log.Debug("TCP doing hard close", "ip", c.LocalAddr(), "dst", c.RemoteAddr(), "ref", 0) return c.Conn.Close() } @@ -241,17 +237,17 @@ func (c *TCPConnection) TryClose() (int, error) { c.refcount-- ref := c.refcount c.mu.Unlock() - log.Debug().Str("ip", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("TCP reference decrement") + c.log.Debug("TCP reference decrement", "ip", c.LocalAddr(), "dst", c.RemoteAddr(), "ref", ref) if ref > 0 { return ref, nil } if ref < 0 { - log.Warn().Str("ip", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("TCP ref went negative") + c.log.Warn("TCP ref went negative", "ip", c.LocalAddr(), "dst", c.RemoteAddr(), "ref", ref) return 0, nil } - log.Debug().Str("ip", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("TCP closing") + c.log.Debug("TCP closing", "ip", c.LocalAddr(), "dst", c.RemoteAddr(), "ref", ref) return ref, c.Conn.Close() } @@ -259,7 +255,7 @@ func (c *TCPConnection) Read(b []byte) (n int, err error) { // Some debug hook. TODO move to proper way n, err = c.Conn.Read(b) if SIPDebug { - logSIPRead("TCP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) + logSIPRead(c.log, "TCP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) } return n, err } @@ -268,7 +264,7 @@ func (c *TCPConnection) Write(b []byte) (n int, err error) { // Some debug hook. TODO move to proper way n, err = c.Conn.Write(b) if SIPDebug { - logSIPWrite("TCP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) + logSIPWrite(c.log, "TCP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) } return n, err } diff --git a/sip/transport_tls.go b/sip/transport_tls.go index bf992c7..8479192 100644 --- a/sip/transport_tls.go +++ b/sip/transport_tls.go @@ -4,9 +4,8 @@ import ( "context" "crypto/tls" "fmt" + "log/slog" "net" - - "github.com/rs/zerolog/log" ) var () @@ -22,9 +21,8 @@ type transportTLS struct { // newTLSTransport needs dialTLSConf for creating connections when dialing // tls.Config must not be nil -func newTLSTransport(par *Parser, dialTLSConf *tls.Config) *transportTLS { - tcptrans := newTCPTransport(par) - tcptrans.transport = TransportTLS //Override transport +func newTLSTransport(par *Parser, dialTLSConf *tls.Config, logger *slog.Logger) *transportTLS { + tcptrans := newTCPTransport(par, logger) p := &transportTLS{ transportTCP: tcptrans, } @@ -40,7 +38,7 @@ func newTLSTransport(par *Parser, dialTLSConf *tls.Config) *transportTLS { } return tls.Client(conn, config) } - p.log = log.Logger.With().Str("caller", "transport").Logger() + p.log = logger.With("caller", "transport", "transport", "tls") return p } @@ -48,6 +46,10 @@ func (t *transportTLS) String() string { return "transport" } +func (*transportTLS) Network() string { + return TransportTLS +} + // CreateConnection creates TLS connection for TCP transport func (t *transportTLS) CreateConnection(ctx context.Context, laddr Addr, raddr Addr, handler MessageHandler) (Connection, error) { hostname := raddr.Hostname @@ -73,7 +75,7 @@ func (t *transportTLS) CreateConnection(ctx context.Context, laddr Addr, raddr A } addr := traddr.String() - log.Debug().Str("raddr", addr).Msg("Dialing new connection") + t.log.Debug("Dialing new connection", "raddr", addr) // No resolving should happen here conn, err := netDialer.DialContext(ctx, "tcp", addr) if err != nil { diff --git a/sip/transport_udp.go b/sip/transport_udp.go index 91d0f6c..d708180 100644 --- a/sip/transport_udp.go +++ b/sip/transport_udp.go @@ -5,11 +5,9 @@ import ( "context" "errors" "fmt" + "log/slog" "net" "sync" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) var ( @@ -27,15 +25,15 @@ type transportUDP struct { parser *Parser pool *ConnectionPool - log zerolog.Logger + log *slog.Logger } -func newUDPTransport(par *Parser) *transportUDP { +func newUDPTransport(par *Parser, logger *slog.Logger) *transportUDP { p := &transportUDP{ parser: par, - pool: NewConnectionPool(), + pool: NewConnectionPool(logger), } - p.log = log.Logger.With().Str("caller", "transport").Logger() + p.log = logger.With("caller", "transport", "transport", "udp") return p } @@ -56,13 +54,14 @@ func (t *transportUDP) Close() error { // ServeConn is direct way to provide conn on which this worker will listen func (t *transportUDP) Serve(conn net.PacketConn, handler MessageHandler) error { - t.log.Debug().Msgf("begin listening on %s %s", t.Network(), conn.LocalAddr().String()) + t.log.Debug("begin listening", "network", t.Network(), "addr", conn.LocalAddr().String()) /* Multiple readers makes problem, which can delay writing response */ c := &UDPConnection{ PacketConn: conn, PacketAddr: conn.LocalAddr().String(), + log: t.log, Listener: true, } @@ -107,12 +106,13 @@ func (t *transportUDP) createConnection(ctx context.Context, laddr Addr, raddr A c := &UDPConnection{ PacketConn: udpconn, PacketAddr: udpconn.LocalAddr().String(), + log: t.log, // 1 ref for current return , 2 ref for reader refcount: 2 + IdleConnection, } addr := raddr.String() - t.log.Debug().Str("raddr", addr).Msg("New connection") + t.log.Debug("New connection", "raddr", addr) // Add in pool but as listen connection // Reason is that UDP connection can be reused. @@ -163,7 +163,7 @@ func (t *transportUDP) readUDPConnection(conn *UDPConnection, raddr string, ladd refcount: 2 + IdleConnection, } - t.log.Debug().Str("raddr", addr).Msg("New connected connection") + t.log.Debug("New connected connection", "raddr", addr) // Wrap it in reference t.pool.Add(addr, c) @@ -175,7 +175,7 @@ func (t *transportUDP) readUDPConnection(conn *UDPConnection, raddr string, ladd func (t *transportUDP) readListenerConnection(conn *UDPConnection, laddr string, handler MessageHandler) { buf := make([]byte, transportBufferSize) defer t.pool.CloseAndDelete(conn, laddr) - defer t.log.Debug().Str("addr", laddr).Msg("Read listener connection stopped") + defer t.log.Debug("Read listener connection stopped", "addr", laddr) var lastRaddr string // NOTE: consider to refactor, but for cleanup @@ -189,10 +189,10 @@ func (t *transportUDP) readListenerConnection(conn *UDPConnection, laddr string, num, raddr, err := conn.ReadFrom(buf) if err != nil { if errors.Is(err, net.ErrClosed) { - t.log.Debug().Str("addr", laddr).Err(err).Msg("Read connection closed") + t.log.Debug("Read connection closed", "addr", laddr, "error", err) return } - t.log.Error().Str("addr", laddr).Err(err).Msg("Read connection error") + t.log.Error("Read connection error", "addr", laddr, "error", err) return } @@ -217,16 +217,16 @@ func (t *transportUDP) readListenerConnection(conn *UDPConnection, laddr string, buf := make([]byte, transportBufferSize) raddr := conn.Conn.RemoteAddr().String() defer t.pool.CloseAndDelete(conn, raddr) - defer t.log.Debug().Str("raddr", raddr).Msg("Read connected connection stopped") + defer t.log.Debug("Read connected connection stopped", "raddr", raddr) for { num, err := conn.Read(buf) if err != nil { if errors.Is(err, net.ErrClosed) || errors.Is(err, io.EOF) { - t.log.Debug().Err(err).Msg("Read connection closed") + t.log.Debug("Read connection closed", "error", err) return } - t.log.Error().Err(err).Msg("Read connection error") + t.log.Error("Read connection error", "error", err) return } @@ -251,10 +251,10 @@ func (t *transportUDP) readListenerConnection(conn *UDPConnection, laddr string, if err != nil { if errors.Is(err, net.ErrClosed) { - t.log.Debug().Err(err).Msg("Read connection closed") + t.log.Debug("Read connection closed", "error", err) return } - t.log.Error().Err(err).Msg("Read UDP connection error") + t.log.Error("Read UDP connection error", "error", err) return } @@ -272,14 +272,14 @@ func (t *transportUDP) parseAndHandle(data []byte, src string, handler MessageHa if len(data) <= 4 { //One or 2 CRLF if len(bytes.Trim(data, "\r\n")) == 0 { - t.log.Debug().Msg("Keep alive CRLF received") + t.log.Debug("Keep alive CRLF received") return } } msg, err := t.parser.ParseSIP(data) //Very expensive operation if err != nil { - t.log.Error().Err(err).Str("data", string(data)).Msg("failed to parse") + t.log.Error("failed to parse", "error", err, "data", string(data)) return } @@ -298,6 +298,7 @@ type UDPConnection struct { Listener bool Conn net.Conn + log *slog.Logger mu sync.RWMutex refcount int @@ -309,7 +310,7 @@ func (c *UDPConnection) close() error { c.mu.Unlock() if c.Conn != nil { - log.Debug().Str("ip", c.LocalAddr().String()).Str("dst", c.Conn.RemoteAddr().String()).Int("ref", 0).Msg("UDP doing hard close") + c.log.Debug().Str("ip", c.LocalAddr().String()).Str("dst", c.Conn.RemoteAddr().String()).Int("ref", 0).Msg("UDP doing hard close") return c.Conn.Close() } @@ -318,7 +319,7 @@ func (c *UDPConnection) close() error { // Closing is done by read connection and it will return already error return nil } - log.Debug().Str("ip", c.LocalAddr().String()).Int("ref", 0).Msg("UDP listener doing hard close") + c.log.Debug().Str("ip", c.LocalAddr().String()).Int("ref", 0).Msg("UDP listener doing hard close") return c.PacketConn.Close() } @@ -359,13 +360,13 @@ func (c *UDPConnection) TryClose() (int, error) { return ref, nil } - log.Debug().Str("src", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("UDP reference decrement") + c.log.Debug().Str("src", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("UDP reference decrement") if ref > 0 { return ref, nil } if ref < 0 { - log.Warn().Str("src", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("UDP ref went negative") + c.log.Warn().Str("src", c.LocalAddr().String()).Str("dst", c.RemoteAddr().String()).Int("ref", ref).Msg("UDP ref went negative") return 0, nil } @@ -375,7 +376,7 @@ func (c *UDPConnection) TryClose() (int, error) { func (c *UDPConnection) Read(b []byte) (n int, err error) { n, err = c.Conn.Read(b) if SIPDebug { - logSIPRead("UDP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) + logSIPRead(c.log, "UDP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) } return n, err } @@ -383,7 +384,7 @@ func (c *UDPConnection) Read(b []byte) (n int, err error) { func (c *UDPConnection) Write(b []byte) (n int, err error) { n, err = c.Conn.Write(b) if SIPDebug { - logSIPWrite("UDP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) + logSIPWrite(c.log, "UDP", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b[:n]) } return n, err } @@ -392,7 +393,7 @@ func (c *UDPConnection) ReadFrom(b []byte) (n int, addr net.Addr, err error) { // Some debug hook. TODO move to proper way n, addr, err = c.PacketConn.ReadFrom(b) if SIPDebug && err == nil { - logSIPRead("UDP", c.PacketConn.LocalAddr().String(), addr.String(), b[:n]) + logSIPRead(c.log, "UDP", c.PacketConn.LocalAddr().String(), addr.String(), b[:n]) } return n, addr, err } @@ -401,7 +402,7 @@ func (c *UDPConnection) WriteTo(b []byte, addr net.Addr) (n int, err error) { // Some debug hook. TODO move to proper way n, err = c.PacketConn.WriteTo(b, addr) if SIPDebug && err == nil { - logSIPWrite("UDP", c.PacketConn.LocalAddr().String(), addr.String(), b[:n]) + logSIPWrite(c.log, "UDP", c.PacketConn.LocalAddr().String(), addr.String(), b[:n]) } return n, err } diff --git a/sip/transport_ws.go b/sip/transport_ws.go index 5af6241..50e662e 100644 --- a/sip/transport_ws.go +++ b/sip/transport_ws.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net" "net/http" "sync" @@ -13,9 +14,6 @@ import ( "github.com/gobwas/ws" "github.com/gobwas/ws/wsutil" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) var ( @@ -27,23 +25,23 @@ var ( // WS transport implementation type transportWS struct { parser *Parser - log zerolog.Logger + log *slog.Logger transport string pool *ConnectionPool dialer ws.Dialer } -func newWSTransport(par *Parser) *transportWS { +func newWSTransport(par *Parser, logger *slog.Logger) *transportWS { p := &transportWS{ parser: par, - pool: NewConnectionPool(), + pool: NewConnectionPool(logger), transport: TransportWS, dialer: ws.DefaultDialer, } p.dialer.Protocols = WebSocketProtocols - p.log = log.Logger.With().Str("caller", "transport").Logger() + p.log = logger.With("caller", "transport", "transport", "ws") return p } @@ -62,7 +60,7 @@ func (t *transportWS) Close() error { // Serve is direct way to provide conn on which this worker will listen func (t *transportWS) Serve(l net.Listener, handler MessageHandler) error { - t.log.Debug().Msgf("begin listening on %s %s", t.Network(), l.Addr().String()) + t.log.Debug("begin listening", "network", t.Network(), "addr", l.Addr().String()) // Prepare handshake header writer from http.Header mapping. // Some phones want to return this @@ -79,7 +77,7 @@ func (t *transportWS) Serve(l net.Listener, handler MessageHandler) error { if SIPDebug { u.OnHeader = func(key, value []byte) error { - log.Debug().Str(string(key), string(value)).Msg("non-websocket header:") + t.log.Debug().Str(string(key), string(value)).Msg("non-websocket header:") return nil } } @@ -87,19 +85,19 @@ func (t *transportWS) Serve(l net.Listener, handler MessageHandler) error { for { conn, err := l.Accept() if err != nil { - t.log.Error().Err(err).Msg("Failed to accept connection") + t.log.Error("Failed to accept connection", "error", err) return err } raddr := conn.RemoteAddr().String() - t.log.Debug().Str("addr", raddr).Msg("New connection accept") + t.log.Debug("New connection accept", "addr", raddr) _, err = u.Upgrade(conn) if err != nil { - t.log.Error().Err(err).Msg("Fail to upgrade") + t.log.Error("Fail to upgrade", "error", err) if err := conn.Close(); err != nil { - t.log.Error().Err(err).Msg("Closing connection failed") + t.log.Error("Closing connection failed", "error", err) } continue } @@ -112,9 +110,10 @@ func (t *transportWS) initConnection(conn net.Conn, raddr string, clientSide boo // // conn.SetKeepAlive(true) // conn.SetKeepAlivePeriod(3 * time.Second) laddr := conn.LocalAddr().String() - t.log.Debug().Str("raddr", raddr).Msg("New WS connection") + t.log.Debug("New WS connection", "raddr", raddr) c := &WSConnection{ Conn: conn, + log: t.log, refcount: 1 + IdleConnection, clientSide: clientSide, } @@ -131,7 +130,7 @@ func (t *transportWS) readConnection(conn *WSConnection, laddr string, raddr str // defer t.pool.Del(raddr) defer t.pool.Delete(laddr) defer t.pool.CloseAndDelete(conn, raddr) - defer t.log.Debug().Str("raddr", raddr).Msg("Websocket read connection stopped") + defer t.log.Debug("Websocket read connection stopped", "raddr", raddr) // Create stream parser context par := t.parser.NewSIPStream() @@ -140,17 +139,17 @@ func (t *transportWS) readConnection(conn *WSConnection, laddr string, raddr str num, err := conn.Read(buf) if err != nil { if errors.Is(err, net.ErrClosed) || errors.Is(err, io.EOF) { - t.log.Debug().Err(err).Msg("Read connection closed") + t.log.Debug("Read connection closed", "error", err) return } - t.log.Error().Err(err).Msg("Got TCP error") + t.log.Error("Got TCP error", "error", err) return } if num == 0 { // // What todo - log.Debug().Msg("Got no bytes, sleeping") + t.log.Debug("Got no bytes, sleeping") time.Sleep(100 * time.Millisecond) continue } @@ -165,7 +164,7 @@ func (t *transportWS) readConnection(conn *WSConnection, laddr string, raddr str if len(data) <= 4 { //One or 2 CRLF if len(bytes.Trim(data, "\r\n")) == 0 { - t.log.Debug().Msg("Keep alive CRLF received") + t.log.Debug("Keep alive CRLF received") continue } } @@ -179,7 +178,7 @@ func (t *transportWS) readConnection(conn *WSConnection, laddr string, raddr str func (t *transportWS) parseStream(par *ParserStream, data []byte, src string, handler MessageHandler) { msg, err := t.parser.ParseSIP(data) //Very expensive operation if err != nil { - t.log.Error().Err(err).Str("data", string(data)).Msg("failed to parse") + t.log.Error("failed to parse", "error", err, "data", string(data)) return } @@ -192,7 +191,7 @@ func (t *transportWS) parseStream(par *ParserStream, data []byte, src string, ha func (t *transportWS) parseFull(data []byte, src string, handler MessageHandler) { msg, err := t.parser.ParseSIP(data) //Very expensive operation if err != nil { - t.log.Error().Err(err).Str("data", string(data)).Msg("failed to parse") + t.log.Error("failed to parse", "error", err, "data", string(data)) return } @@ -239,11 +238,11 @@ func (t *transportWS) CreateConnection(ctx context.Context, laddr Addr, raddr Ad func (t *transportWS) createConnection(ctx context.Context, laddr *net.TCPAddr, raddr *net.TCPAddr, handler MessageHandler) (Connection, error) { addr := raddr.String() - t.log.Debug().Str("raddr", addr).Msg("Dialing new connection") + t.log.Debug("Dialing new connection", "raddr", addr) // How to define local interface if laddr != nil { - log.Error().Str("laddr", laddr.String()).Msg("Dialing with local IP is not supported on ws") + t.log.Error().Str("laddr", laddr.String()).Msg("Dialing with local IP is not supported on ws") } conn, _, _, err := t.dialer.Dial(ctx, "ws://"+addr) @@ -259,6 +258,7 @@ func (t *transportWS) createConnection(ctx context.Context, laddr *net.TCPAddr, type WSConnection struct { net.Conn + log *slog.Logger clientSide bool mu sync.RWMutex refcount int @@ -269,7 +269,7 @@ func (c *WSConnection) Ref(i int) int { c.refcount += i ref := c.refcount c.mu.Unlock() - log.Debug().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS reference increment") + c.log.Debug().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS reference increment") return ref } @@ -278,7 +278,7 @@ func (c *WSConnection) Close() error { c.mu.Lock() c.refcount = 0 c.mu.Unlock() - log.Debug().Str("ip", c.RemoteAddr().String()).Msg("WS doing hard close") + c.log.Debug().Str("ip", c.RemoteAddr().String()).Msg("WS doing hard close") return c.Conn.Close() } @@ -287,16 +287,16 @@ func (c *WSConnection) TryClose() (int, error) { c.refcount-- ref := c.refcount c.mu.Unlock() - log.Debug().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS reference decrement") + c.log.Debug().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS reference decrement") if ref > 0 { return ref, nil } if ref < 0 { - log.Warn().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS ref went negative") + c.log.Warn().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS ref went negative") return 0, nil } - log.Debug().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS closing") + c.log.Debug().Str("ip", c.RemoteAddr().String()).Int("ref", ref).Msg("WS closing") return ref, c.Conn.Close() } @@ -316,7 +316,7 @@ func (c *WSConnection) Read(b []byte) (n int, err error) { } if SIPDebug { - log.Debug().Str("caller", c.RemoteAddr().String()).Msgf("WS read connection header <- %s opcode=%d len=%d", c.Conn.RemoteAddr(), header.OpCode, header.Length) + c.log.Debug().Str("caller", c.RemoteAddr().String()).Msgf("WS read connection header <- %s opcode=%d len=%d", c.Conn.RemoteAddr(), header.OpCode, header.Length) } if header.OpCode.IsControl() { @@ -360,7 +360,7 @@ func (c *WSConnection) Read(b []byte) (n int, err error) { // header.Masked = false if SIPDebug { - logSIPRead("WS", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), data) + logSIPRead(c.log, "WS", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), data) } n += copy(b[n:], data) @@ -375,7 +375,7 @@ func (c *WSConnection) Read(b []byte) (n int, err error) { func (c *WSConnection) Write(b []byte) (n int, err error) { if SIPDebug { - logSIPWrite("WS", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b) + logSIPWrite(c.log, "WS", c.Conn.LocalAddr().String(), c.Conn.RemoteAddr().String(), b) } fs := ws.NewFrame(ws.OpText, true, b) diff --git a/sip/transport_wss.go b/sip/transport_wss.go index 4b79c8f..057b89f 100644 --- a/sip/transport_wss.go +++ b/sip/transport_wss.go @@ -4,12 +4,11 @@ import ( "context" "crypto/tls" "fmt" + "log/slog" "net" "net/url" "strconv" "time" - - "github.com/rs/zerolog/log" ) // TLS transport implementation @@ -21,8 +20,8 @@ type transportWSS struct { // newWSSTransport needs dialTLSConf for creating connections when dialing // tls.Config must not be nil -func newWSSTransport(par *Parser, dialTLSConf *tls.Config) *transportWSS { - tcptrans := newWSTransport(par) +func newWSSTransport(par *Parser, dialTLSConf *tls.Config, logger *slog.Logger) *transportWSS { + tcptrans := newWSTransport(par, logger) tcptrans.transport = TransportWSS // Set our TLS config p := &transportWSS{ @@ -42,7 +41,7 @@ func newWSSTransport(par *Parser, dialTLSConf *tls.Config) *transportWSS { } // p.tlsConf = dialTLSConf - p.log = log.Logger.With().Str("caller", "transport").Logger() + p.log = logger.With("caller", "transport", "transport", "wss") return p } @@ -53,7 +52,7 @@ func (t *transportWSS) String() string { // CreateConnection creates WSS connection for TCP transport // TODO Make this consisten with TCP func (t *transportWSS) CreateConnection(ctx context.Context, laddr Addr, raddr Addr, handler MessageHandler) (Connection, error) { - log := &t.log + log := t.log // Must have IP resolved if raddr.IP == nil { @@ -91,13 +90,13 @@ func (t *transportWSS) CreateConnection(ctx context.Context, laddr Addr, raddr A LocalAddr: tladdr, } - log.Debug().Str("raddr", traddr.String()).Msg("Dialing new connection") + log.Debug("Dialing new connection", "raddr", traddr.String()) conn, err := netDialer.DialContext(ctx, "tcp", traddr.String()) if err != nil { return nil, fmt.Errorf("dial TCP error: %w", err) } - log.Debug().Str("hostname", hostname).Msg("Setuping TLS connection") + log.Debug("Setting up TLS connection", "hostname", hostname) tlsConn := t.dialer.TLSClient(conn, hostname) u, err := url.ParseRequestURI("wss://" + addr) diff --git a/siptest/server_tx_recorder.go b/siptest/server_tx_recorder.go index 37c714f..7acb28b 100644 --- a/siptest/server_tx_recorder.go +++ b/siptest/server_tx_recorder.go @@ -1,9 +1,9 @@ package siptest import ( - "github.com/emiago/sipgo/sip" + "log/slog" - "github.com/rs/zerolog/log" + "github.com/emiago/sipgo/sip" ) // ServerTxRecorder wraps server transactions @@ -20,7 +20,7 @@ func NewServerTxRecorder(req *sip.Request) *ServerTxRecorder { panic(err) } conn := newConnRecorder() - stx := sip.NewServerTx(key, req, conn, log.Logger) + stx := sip.NewServerTx(key, req, conn, slog.Default()) if err := stx.Init(); err != nil { panic(err) }