diff --git a/examples/browse/browse_test.go b/examples/browse/browse_test.go index 5985cecb4..c262fe990 100644 --- a/examples/browse/browse_test.go +++ b/examples/browse/browse_test.go @@ -16,13 +16,14 @@ func TestBrowse(t *testing.T) { // start the server s := server.New( + ctx, server.EndPoint("localhost", 4840), ) populateServer(s) if err := s.Start(ctx); err != nil { t.Fatal(err) } - defer s.Close() + defer s.Close(ctx) // prepare the client c, err := opcua.NewClient("opc.tcp://localhost:4840") diff --git a/examples/server/NodeSet2_server/server.go b/examples/server/NodeSet2_server/server.go index dadfe8d4a..23ae53394 100644 --- a/examples/server/NodeSet2_server/server.go +++ b/examples/server/NodeSet2_server/server.go @@ -9,9 +9,10 @@ import ( "crypto/rsa" "crypto/tls" "encoding/xml" + "errors" "flag" "io" - "log" + "log/slog" "os" "os/signal" "time" @@ -20,6 +21,7 @@ import ( "github.com/gopcua/opcua/schema" "github.com/gopcua/opcua/server" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) var ( @@ -30,33 +32,18 @@ var ( gencert = flag.Bool("gen-cert", false, "Generate a new certificate") ) -type Logger int - -func (l Logger) Debug(msg string, args ...any) { - if l < 0 { - log.Printf(msg, args...) - } -} -func (l Logger) Info(msg string, args ...any) { - if l < 1 { - log.Printf(msg, args...) - } -} -func (l Logger) Warn(msg string, args ...any) { - if l < 2 { - log.Printf(msg, args...) - } -} -func (l Logger) Error(msg string, args ...any) { - if l < 3 { - log.Printf(msg, args...) - } -} - func main() { flag.BoolVar(&debug.Enable, "debug", false, "enable debug logging") flag.Parse() - log.SetFlags(0) + + ctx := ualog.New(context.Background(), ualog.WithHandler( + slog.NewJSONHandler(os.Stdout, func() *slog.HandlerOptions { + if debug.Enable { + return &slog.HandlerOptions{Level: slog.LevelDebug} + } + return nil + }()), + )) var opts []server.Option @@ -96,7 +83,7 @@ func main() { // be sure the hostname(s) also match the certificate the server is going to use. hostname, err := os.Hostname() if err != nil { - log.Fatalf("Error getting host name %v", err) + fatal(ctx, "error getting host name", err) } opts = append(opts, @@ -105,14 +92,6 @@ func main() { server.EndPoint(hostname, *port), ) - // the server.SetLogger takes a server.Logger interface. This interface is met by - // the slog.Logger{}. A simple wrapper could be made for other loggers if they don't already - // meet the interface. - logger := Logger(2) - opts = append(opts, - server.SetLogger(logger), - ) - // Here is an example of certificate generation. This is not necessary if you already have a certificate. if *gencert { // it is important that the certificate is generated with the correct hostname/IP address URIs @@ -125,29 +104,32 @@ func main() { c, k, err := GenerateCert(endpoints, 4096, time.Minute*60*24*365*10) if err != nil { - log.Fatalf("problem creating cert: %v", err) + fatal(ctx, "problem creating certificate", err) } err = os.WriteFile(*certfile, c, 0) if err != nil { - log.Fatalf("problem writing cert: %v", err) + fatal(ctx, "problem writing certificate", err) } err = os.WriteFile(*keyfile, k, 0) if err != nil { - log.Fatalf("problem writing key: %v", err) + fatal(ctx, "problem writing key", err) } - } var cert []byte if *gencert || (*certfile != "" && *keyfile != "") { - log.Printf("Loading cert/key from %s/%s", *certfile, *keyfile) + ualog.Info(ctx, "loading certificate and key from files", + ualog.String("cert", *certfile), + ualog.String("key", *keyfile), + ) + c, err := tls.LoadX509KeyPair(*certfile, *keyfile) if err != nil { - log.Printf("Failed to load certificate: %s", err) + ualog.Error(ctx, "failed to load certificate", ualog.Err(err)) } else { pk, ok := c.PrivateKey.(*rsa.PrivateKey) if !ok { - log.Fatalf("Invalid private key") + fatal(ctx, "invalid private key", errors.New("incorrect type")) } cert = c.Certificate[0] opts = append(opts, server.PrivateKey(pk), server.Certificate(cert)) @@ -157,7 +139,7 @@ func main() { // Now that all the options are set, create the server. // When the server is created, it will automatically create namespace 0 and populate it with // the core opc ua nodes. - s := server.New(opts...) + s := server.New(ctx, opts...) // Now we'll import our NodeSet2.xml file. // These files often create additional namespaces and reference them assuming they @@ -167,35 +149,45 @@ func main() { // first, we read the file and unmarshal it into a schema.UANodeSet struct. Then it can be imported file, err := os.Open("Opc.Ua.Di.NodeSet2.xml") if err != nil { - log.Fatalf("error opening nodeset file: %v", err) + fatal(ctx, "unable to open nodeset file", err) } + node_data, err := io.ReadAll(file) if err != nil { - log.Fatalf("error reading nodeset file: %v", err) + fatal(ctx, "unable to read nodeset file", err) } + var nodes schema.UANodeSet xml.Unmarshal(node_data, &nodes) - s.ImportNodeSet(&nodes) + s.ImportNodeSet(ctx, &nodes) // At this point you can lookup any specific node by its nodeid to add references or modify it or whatever // your heart desires node := s.Node(ua.NewNumericNodeID(1, 15044)) if node != nil { - log.Printf("Found node %v", node) + ualog.Info(ctx, "found node", ualog.Any("node", node)) } // Start the server - if err := s.Start(context.Background()); err != nil { - log.Fatalf("Error starting server, exiting: %s", err) + if err := s.Start(ctx); err != nil { + fatal(ctx, "unable to start server", err) } - defer s.Close() + defer s.Close(ctx) // catch ctrl-c and gracefully shutdown the server. sigch := make(chan os.Signal, 1) signal.Notify(sigch, os.Interrupt) defer signal.Stop(sigch) - log.Printf("Press CTRL-C to exit") + + ualog.Info(ctx, "press ctrl-c to exit") <-sigch - log.Printf("Shutting down the server...") + + ualog.Info(ctx, "shutting down server...") +} + +func fatal(ctx context.Context, reason string, err error) { + ualog.Error(ctx, "FATAL: "+reason, ualog.Err(err)) + time.Sleep(time.Second) + os.Exit(1) } diff --git a/examples/server/map_server/server.go b/examples/server/map_server/server.go index b4ce3a230..83162d794 100644 --- a/examples/server/map_server/server.go +++ b/examples/server/map_server/server.go @@ -13,8 +13,9 @@ import ( "context" "crypto/rsa" "crypto/tls" + "errors" "flag" - "log" + "log/slog" "os" "os/signal" "time" @@ -22,6 +23,7 @@ import ( "github.com/gopcua/opcua/id" "github.com/gopcua/opcua/server" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) var ( @@ -32,32 +34,10 @@ var ( gencert = flag.Bool("gen-cert", false, "Generate a new certificate") ) -type Logger int - -func (l Logger) Debug(msg string, args ...any) { - if l < 0 { - log.Printf(msg, args...) - } -} -func (l Logger) Info(msg string, args ...any) { - if l < 1 { - log.Printf(msg, args...) - } -} -func (l Logger) Warn(msg string, args ...any) { - if l < 2 { - log.Printf(msg, args...) - } -} -func (l Logger) Error(msg string, args ...any) { - if l < 3 { - log.Printf(msg, args...) - } -} - func main() { flag.Parse() - log.SetFlags(0) + + ctx := ualog.New(context.Background(), ualog.WithHandler(slog.NewJSONHandler(os.Stdout, nil))) var opts []server.Option @@ -97,7 +77,7 @@ func main() { // be sure the hostname(s) also match the certificate the server is going to use. hostname, err := os.Hostname() if err != nil { - log.Fatalf("Error getting host name %v", err) + fatal(ctx, "unable to get host name", err) } opts = append(opts, @@ -106,14 +86,6 @@ func main() { server.EndPoint(hostname, *port), ) - // the server.SetLogger takes a server.Logger interface. This interface is met by - // the slog.Logger{}. A simple wrapper could be made for other loggers if they don't already - // meet the interface and that is what we've done here. - logger := Logger(1) - opts = append(opts, - server.SetLogger(logger), - ) - // Here is an example of certificate generation. This is not necessary if you already have a certificate. if *gencert { // it is important that the certificate is generated with the correct hostname/IP address URIs @@ -126,29 +98,30 @@ func main() { c, k, err := GenerateCert(endpoints, 4096, time.Minute*60*24*365*10) if err != nil { - log.Fatalf("problem creating cert: %v", err) + fatal(ctx, "problem creating certificate", err) } err = os.WriteFile(*certfile, c, 0) if err != nil { - log.Fatalf("problem writing cert: %v", err) + fatal(ctx, "problem writing certificate", err) } err = os.WriteFile(*keyfile, k, 0) if err != nil { - log.Fatalf("problem writing key: %v", err) + fatal(ctx, "problem writing key", err) } - } var cert []byte if *gencert || (*certfile != "" && *keyfile != "") { - log.Printf("Loading cert/key from %s/%s", *certfile, *keyfile) + ualog.Info(ctx, "loading certificate and key from files", + ualog.String("cert", *certfile), ualog.String("key", *keyfile), + ) c, err := tls.LoadX509KeyPair(*certfile, *keyfile) if err != nil { - log.Printf("Failed to load certificate: %s", err) + ualog.Error(ctx, "failed to load certificate", ualog.Err(err)) } else { pk, ok := c.PrivateKey.(*rsa.PrivateKey) if !ok { - log.Fatalf("Invalid private key") + fatal(ctx, "invalid private key", errors.New("incorrect type")) } cert = c.Certificate[0] opts = append(opts, server.PrivateKey(pk), server.Certificate(cert)) @@ -158,15 +131,15 @@ func main() { // Now that all the options are set, create the server. // When the server is created, it will automatically create namespace 0 and populate it with // the core opc ua nodes. - s := server.New(opts...) + s := server.New(ctx, opts...) // Create some map namespaces. These are backed by go map[string]any // which may be more convenient for some use cases than the NodeNamespace which requires // your application's data structure to match the opcua node model. myMapNamespace1 := server.NewMapNamespace(s, "MyTestNamespace") - log.Printf("map namespace 1 added at index %d", myMapNamespace1.ID()) + ualog.Info(ctx, "map namespace 1 added", ualog.Uint32("index", uint32(myMapNamespace1.ID()))) myMapNamespace2 := server.NewMapNamespace(s, "SomeOtherNamespace") - log.Printf("map namespace 2 added at index %d", myMapNamespace2.ID()) + ualog.Info(ctx, "map namespace 2 added", ualog.Uint32("index", uint32(myMapNamespace1.ID()))) // fill them with data. myMapNamespace1.Data["Tag1"] = 123.4 @@ -193,13 +166,13 @@ func main() { // you can manually lock and change the value, then manually trigger the change notification myMapNamespace1.Mu.Lock() myMapNamespace1.Data["Tag2"] = num - myMapNamespace1.ChangeNotification("Tag2") + myMapNamespace1.ChangeNotification(ctx, "Tag2") myMapNamespace1.Mu.Unlock() if updates == 10 { // or you can do it with the built-in functions. // which handles the locking and triggering tag5 = !tag5 - myMapNamespace1.SetValue("Tag5", tag5) + myMapNamespace1.SetValue(ctx, "Tag5", tag5) updates = 0 } time.Sleep(time.Second) @@ -212,7 +185,10 @@ func main() { go func() { for { changed_key := <-myMapNamespace2.ExternalNotification - log.Printf("%s changed to %v", changed_key, myMapNamespace2.GetValue(changed_key)) + ualog.Info(ctx, "value changed", + ualog.String("key", changed_key), + ualog.Any("value", myMapNamespace2.GetValue(changed_key)), + ) } }() @@ -229,17 +205,25 @@ func main() { // Start the server // Note that you can add namespaces before or after starting the server. - if err := s.Start(context.Background()); err != nil { - log.Fatalf("Error starting server, exiting: %s", err) + if err := s.Start(ctx); err != nil { + fatal(ctx, "unable to start server", err) } - defer s.Close() + defer s.Close(ctx) // catch ctrl-c and gracefully shutdown the server. sigch := make(chan os.Signal, 1) signal.Notify(sigch, os.Interrupt) defer signal.Stop(sigch) - log.Printf("Press CTRL-C to exit") + + ualog.Info(ctx, "press ctrl-c to exit") <-sigch - log.Printf("Shutting down the server...") + + ualog.Info(ctx, "shutting down the server...") +} + +func fatal(ctx context.Context, reason string, err error) { + ualog.Error(ctx, "FATAL: "+reason, ualog.Err(err)) + time.Sleep(time.Second) + os.Exit(1) } diff --git a/examples/server/node_server/server.go b/examples/server/node_server/server.go index 0f5169f28..e4a41c8b7 100644 --- a/examples/server/node_server/server.go +++ b/examples/server/node_server/server.go @@ -8,8 +8,9 @@ import ( "context" "crypto/rsa" "crypto/tls" + "errors" "flag" - "log" + "log/slog" "os" "os/signal" "time" @@ -19,6 +20,7 @@ import ( "github.com/gopcua/opcua/server" "github.com/gopcua/opcua/server/attrs" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) var ( @@ -29,32 +31,18 @@ var ( gencert = flag.Bool("gen-cert", false, "Generate a new certificate") ) -type Logger int - -func (l Logger) Debug(msg string, args ...any) { - if l < 0 { - log.Printf(msg, args...) - } -} -func (l Logger) Info(msg string, args ...any) { - if l < 1 { - log.Printf(msg, args...) - } -} -func (l Logger) Warn(msg string, args ...any) { - if l < 2 { - log.Printf(msg, args...) - } -} -func (l Logger) Error(msg string, args ...any) { - if l < 3 { - log.Printf(msg, args...) - } -} func main() { flag.BoolVar(&debug.Enable, "debug", false, "enable debug logging") flag.Parse() - log.SetFlags(0) + + ctx := ualog.New(context.Background(), ualog.WithHandler( + slog.NewJSONHandler(os.Stdout, func() *slog.HandlerOptions { + if debug.Enable { + return &slog.HandlerOptions{Level: slog.LevelDebug} + } + return nil + }()), + )) var opts []server.Option @@ -94,7 +82,7 @@ func main() { // be sure the hostname(s) also match the certificate the server is going to use. hostname, err := os.Hostname() if err != nil { - log.Fatalf("Error getting host name %v", err) + fatal(ctx, "error getting host name", err) } opts = append(opts, @@ -103,14 +91,6 @@ func main() { server.EndPoint(hostname, *port), ) - // the server.SetLogger takes a server.Logger interface. This interface is met by - // the slog.Logger{}. A simple wrapper could be made for other loggers if they don't already - // meet the interface. - logger := Logger(1) - opts = append(opts, - server.SetLogger(logger), - ) - // Here is an example of certificate generation. This is not necessary if you already have a certificate. if *gencert { // it is important that the certificate is generated with the correct hostname/IP address URIs @@ -123,29 +103,31 @@ func main() { c, k, err := GenerateCert(endpoints, 4096, time.Minute*60*24*365*10) if err != nil { - log.Fatalf("problem creating cert: %v", err) + fatal(ctx, "problem creating certificate", err) } err = os.WriteFile(*certfile, c, 0644) if err != nil { - log.Fatalf("problem writing cert: %v", err) + fatal(ctx, "problem writing certificate", err) } err = os.WriteFile(*keyfile, k, 0600) if err != nil { - log.Fatalf("problem writing key: %v", err) + fatal(ctx, "problem writing key", err) } - } var cert []byte if *gencert || (*certfile != "" && *keyfile != "") { - log.Printf("Loading cert/key from %s/%s", *certfile, *keyfile) + ualog.Info(ctx, "loading certificate and key from files", + ualog.String("cert", *certfile), + ualog.String("key", *keyfile), + ) c, err := tls.LoadX509KeyPair(*certfile, *keyfile) if err != nil { - log.Printf("Failed to load certificate: %s", err) + ualog.Error(ctx, "failed to load certificate", ualog.Err(err)) } else { pk, ok := c.PrivateKey.(*rsa.PrivateKey) if !ok { - log.Fatalf("Invalid private key") + fatal(ctx, "invalid private key", errors.New("incorrect type")) } cert = c.Certificate[0] opts = append(opts, server.PrivateKey(pk), server.Certificate(cert)) @@ -155,7 +137,7 @@ func main() { // Now that all the options are set, create the server. // When the server is created, it will automatically create namespace 0 and populate it with // the core opc ua nodes. - s := server.New(opts...) + s := server.New(ctx, opts...) // add the namespaces to the server, and add a reference to them if desired. // here we are choosing to add the namespaces to the root/object folder @@ -166,15 +148,15 @@ func main() { // Start the server // Note that you can add namespaces before or after starting the server. - if err := s.Start(context.Background()); err != nil { - log.Fatalf("Error starting server, exiting: %s", err) + if err := s.Start(ctx); err != nil { + fatal(ctx, "unable to start server", err) } - defer s.Close() + defer s.Close(ctx) // Now we'll add a node namespace. This is a more traditional way to add nodes to the server // and is more in line with the opc ua node model, but may be more cumbersome for some use cases. nodeNS := server.NewNodeNameSpace(s, "NodeNamespace") - log.Printf("Node Namespace added at index %d", nodeNS.ID()) + ualog.Info(ctx, "node namespace added", ualog.Uint32("index", uint32(nodeNS.ID()))) // add the reference for this namespace's root object folder to the server's root object folder // but you can add a reference to whatever node(s) you need @@ -275,7 +257,7 @@ func main() { // we also need to let the node namespace know that the value has changed so it can trigger the change notification // and send the updated value to any subscribed clients. - nodeNS.ChangeNotification(var1.ID()) + nodeNS.ChangeNotification(ctx, var1.ID()) time.Sleep(time.Second) } @@ -289,7 +271,11 @@ func main() { changed_id := <-nodeNS.ExternalNotification node := nodeNS.Node(changed_id) value := node.Value().Value.Value() - log.Printf("%s changed to %v", changed_id.String(), value) + + ualog.Info(ctx, "value changed", + ualog.String("key", changed_id.String()), + ualog.Any("value", value), + ) } }() @@ -297,8 +283,16 @@ func main() { sigch := make(chan os.Signal, 1) signal.Notify(sigch, os.Interrupt) defer signal.Stop(sigch) - log.Printf("Press CTRL-C to exit") + + ualog.Info(ctx, "press ctrl-c to exit") <-sigch - log.Printf("Shutting down the server...") + + ualog.Info(ctx, "shutting down the server ...") +} + +func fatal(ctx context.Context, reason string, err error) { + ualog.Error(ctx, "FATAL: "+reason, ualog.Err(err)) + time.Sleep(time.Second) + os.Exit(1) } diff --git a/examples/server/server.go b/examples/server/server.go index f833c8c46..d55e712b6 100644 --- a/examples/server/server.go +++ b/examples/server/server.go @@ -7,9 +7,11 @@ package main import ( "context" "flag" - "log" + "os" + "time" "github.com/gopcua/opcua/uacp" + "github.com/gopcua/opcua/ualog" ) func main() { @@ -20,23 +22,26 @@ func main() { ctx := context.Background() - log.Printf("Listening on %s", *endpoint) l, err := uacp.Listen(ctx, *endpoint, nil) if err != nil { - log.Fatal(err) + fatal(ctx, "failed to listen for connections", err) } + + ualog.Info(ctx, "listening for connections", ualog.String("endpoint", *endpoint)) + c, err := l.Accept(ctx) if err != nil { - log.Fatal(err) + fatal(ctx, "failed to accept incoming connection", err) } defer c.Close() - log.Printf("conn %d: connection from %s", c.ID(), c.RemoteAddr()) + + ualog.Info(ctx, "connection received", ualog.Uint32("conn", c.ID()), ualog.Any("remote", c.RemoteAddr())) // listener, err := uacp.Listen(*endpoint, uint32(*bufsize)) // if err != nil { - // log.Fatal(err) + // ualog.Fatal(ctx, "", ualog.Err(err)) // } - // log.Printf("Started listening on %s.", listener.Endpoint()) + // ualog.Info(ctx, "started listening for connections", ualog.Any("endpoint", listener.Endpoint())) // cfg := uasc.NewServerConfig( // "http://opcfoundation.org/UA/SecurityPolicy#None", @@ -50,52 +55,57 @@ func main() { // conn, err := listener.Accept(ctx) // if err != nil { - // log.Print(err) + // ualog.Error(ctx, "listen failed", ualog.Err(err)) // return // } // defer func() { // conn.Close() - // log.Println("Successfully closed connection") + // ualog.Info(ctx, "successfully closed connection") // }() - // log.Printf("Successfully established connection with %v", conn.RemoteAddr()) + // ualog.Info(ctx, "successfully established connection", ualog.Any("remote", conn.RemoteAddr())) // secChan, err := uasc.ListenAndAcceptSecureChannel(ctx, conn, cfg) // if err != nil { - // log.Fatal(err) + // ualog.Fatal(ctx, "", ualog.Err(err)) // } // defer func() { // secChan.Close() - // log.Printf("Successfully closed secure channel with %v", conn.RemoteAddr()) + // ualog.Info(ctx, "successfully closed secure channel", ualog.Any("remote", conn.RemoteAddr())) // }() - // log.Printf("Successfully opened secure channel with %v", conn.RemoteAddr()) + // ualog.Info(ctx, "successfully opened secure channel", ualog.Any("remote", conn.RemoteAddr())) // sessCfg := uasc.NewServerSessionConfig(secChan) // session, err := uasc.ListenAndAcceptSession(ctx, secChan, sessCfg) // if err != nil { - // log.Fatal(err) + // ualog.Fatal(ctx, "", ualog.Err(err)) // } // defer func() { // session.Close() - // log.Printf("Successfully closed session with %v", conn.RemoteAddr()) + // ualog.Info(ctx, "successfully closed session", ualog.Any("remote", conn.RemoteAddr())) // }() - // log.Printf("Successfully activated session with %v", conn.RemoteAddr()) + // ualog.Info(ctx, "successfully activated session", ualog.Any("remote", conn.RemoteAddr())) // buf := make([]byte, 1024) // for { // n, err := session.ReadService(buf) // if err != nil { - // log.Printf("Couldn't read UASC: %s", err) + // ualog.Error(ctx, "couldn't read uasc", ualog.Err(err)) // continue // } - // log.Printf("Successfully received message: %x\n%s", buf[:n], utils.Wireshark(0, buf[:n])) - + // ualog.Info(ctx, "successfully received message", ualog.String("bytes", fmt.Sprintf("%x", buf[:n])), ualog.String("wireshark", utils.Wireshark(0, buf[:n]))) // srv, err := services.Decode(buf[:n]) // if err != nil { - // log.Printf("Couldn't decode received bytes as Service: %s", err) + // ualog.Error(ctx, "couldn't decode received bytes as Service", ualog.Err(err)) // continue // } - // log.Printf("Successfully decoded as Service: %v", srv) + // ualog.Info(ctx, "successfully decoded as Service", ualog.Any("service", srv)) // } // }() // } } + +func fatal(ctx context.Context, reason string, err error) { + ualog.Error(ctx, "FATAL: "+reason, ualog.Err(err)) + time.Sleep(time.Second) + os.Exit(1) +} diff --git a/examples/server_test/server.go b/examples/server_test/server.go index 468b512e4..a9c414036 100644 --- a/examples/server_test/server.go +++ b/examples/server_test/server.go @@ -8,14 +8,16 @@ import ( "context" "crypto/rsa" "crypto/tls" + "errors" "flag" - "log" + "log/slog" "os" "time" "github.com/gopcua/opcua/debug" "github.com/gopcua/opcua/server" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) var ( @@ -29,7 +31,16 @@ var ( func main() { flag.BoolVar(&debug.Enable, "debug", false, "enable debug logging") flag.Parse() - log.SetFlags(0) + + logger := slog.New(slog.NewJSONHandler(os.Stdout, func() *slog.HandlerOptions { + if debug.Enable { + return &slog.HandlerOptions{Level: slog.LevelDebug} + } + return nil + }())) + + logger = logger.With("foo", "bar") + ctx := ualog.New(context.Background(), ualog.WithLogger(logger)) var opts []server.Option @@ -55,7 +66,7 @@ func main() { ) hostname, err := os.Hostname() if err != nil { - log.Fatalf("Error getting host name %v", err) + fatal(ctx, "unable to get host name", err) } // not sure if a list of hostnames is better or adding endpoints to the options @@ -74,44 +85,48 @@ func main() { if *gencert { c, k, err := GenerateCert(endpoints, 4096, time.Minute*60*24*365*10) if err != nil { - log.Fatalf("problem creating cert: %v", err) + fatal(ctx, "problem creating certificate", err) } err = os.WriteFile(*certfile, c, 0) if err != nil { - log.Fatalf("problem writing cert: %v", err) + fatal(ctx, "problem writing certificate", err) } err = os.WriteFile(*keyfile, k, 0) if err != nil { - log.Fatalf("problem writing key: %v", err) + fatal(ctx, "problem writing key", err) } - } var cert []byte if *gencert || (*certfile != "" && *keyfile != "") { - log.Printf("Loading cert/key from %s/%s", *certfile, *keyfile) + ualog.Info(ctx, "loading certificate and key from files", ualog.String("cert", *certfile), ualog.String("key", *keyfile)) c, err := tls.LoadX509KeyPair(*certfile, *keyfile) if err != nil { - log.Printf("Failed to load certificate: %s", err) + ualog.Error(ctx, "failed to load certificate", ualog.Err(err)) } else { pk, ok := c.PrivateKey.(*rsa.PrivateKey) if !ok { - log.Fatalf("Invalid private key") + fatal(ctx, "invalid private key", errors.New("incorrect type")) } cert = c.Certificate[0] opts = append(opts, server.PrivateKey(pk), server.Certificate(cert)) } } - s := server.New(opts...) + s := server.New(ctx, opts...) // Create a new node namespace. You can add namespaces before or after starting the server. // Start the server - if err := s.Start(context.Background()); err != nil { - log.Fatalf("Error starting server, exiting: %s", err) + if err := s.Start(ctx); err != nil { + fatal(ctx, "unable to start server", err) } - defer s.Close() + defer s.Close(ctx) select {} +} +func fatal(ctx context.Context, reason string, err error) { + ualog.Error(ctx, "FATAL: "+reason, ualog.Err(err)) + time.Sleep(time.Second) + os.Exit(1) } diff --git a/server/attribute_service.go b/server/attribute_service.go index 689007077..ed1101c1c 100644 --- a/server/attribute_service.go +++ b/server/attribute_service.go @@ -1,9 +1,11 @@ package server import ( + "context" "time" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -14,11 +16,18 @@ type AttributeService struct { srv *Server } -// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.10.2 -func (s *AttributeService) Read(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) +func NewAttributeService(s *Server) *AttributeService { + return &AttributeService{ + srv: s, } +} + +var newAttributeServiceLogAttribute = newServiceLogAttributeCreatorForSet("attribute") + +// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.10.2 +func (s *AttributeService) Read(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newAttributeServiceLogAttribute("read")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.ReadRequest](r) if err != nil { @@ -27,9 +36,9 @@ func (s *AttributeService) Read(sc *uasc.SecureChannel, r ua.Request, reqID uint results := make([]*ua.DataValue, len(req.NodesToRead)) for i, n := range req.NodesToRead { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("read: node=%s attr=%s", n.NodeID, n.AttributeID) - } + ualog.Debug(ctx, "reading node", + ualog.Any(ualog.NodeIdKey, n.NodeID), ualog.Any("attr", n.AttributeID), + ) ns, err := s.srv.Namespace(int(n.NodeID.Namespace())) if err != nil { @@ -40,8 +49,7 @@ func (s *AttributeService) Read(sc *uasc.SecureChannel, r ua.Request, reqID uint } continue } - results[i] = ns.Attribute(n.NodeID, n.AttributeID) - + results[i] = ns.Attribute(ctx, n.NodeID, n.AttributeID) } response := &ua.ReadResponse{ @@ -53,20 +61,22 @@ func (s *AttributeService) Read(sc *uasc.SecureChannel, r ua.Request, reqID uint } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.10.3 -func (s *AttributeService) HistoryRead(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *AttributeService) HistoryRead(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newAttributeServiceLogAttribute("history read")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.HistoryReadRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.10.4 -func (s *AttributeService) Write(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { +func (s *AttributeService) Write(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newAttributeServiceLogAttribute("write")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.WriteRequest](r) if err != nil { @@ -77,18 +87,18 @@ func (s *AttributeService) Write(sc *uasc.SecureChannel, r ua.Request, reqID uin for i := range req.NodesToWrite { n := req.NodesToWrite[i] - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("write: node=%s attr=%v", n.NodeID, n.AttributeID) - } + ualog.Debug(ctx, "writing node", + ualog.Any(ualog.NodeIdKey, n.NodeID), ualog.Any("attr", n.AttributeID), + ) ns, err := s.srv.Namespace(int(n.NodeID.Namespace())) if err != nil { status[i] = ua.StatusBadNodeNotInView } - status[i] = ns.SetAttribute(n.NodeID, n.AttributeID, n.Value) - + status[i] = ns.SetAttribute(ctx, n.NodeID, n.AttributeID, n.Value) } + response := &ua.WriteResponse{ ResponseHeader: &ua.ResponseHeader{ Timestamp: time.Now(), @@ -103,18 +113,17 @@ func (s *AttributeService) Write(sc *uasc.SecureChannel, r ua.Request, reqID uin } return response, nil - } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.10.5 -func (s *AttributeService) HistoryUpdate(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *AttributeService) HistoryUpdate(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newAttributeServiceLogAttribute("history update")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.HistoryUpdateRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } diff --git a/server/channel_broker.go b/server/channel_broker.go index 89d09f008..fc1c89fca 100644 --- a/server/channel_broker.go +++ b/server/channel_broker.go @@ -10,6 +10,7 @@ import ( "github.com/gopcua/opcua/ua" "github.com/gopcua/opcua/uacp" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -32,10 +33,9 @@ type channelBroker struct { // msgChan is the common channel that all messages from all channels // get funneled into for handling msgChan chan *uasc.MessageBody - logger Logger } -func newChannelBroker(logger Logger) *channelBroker { +func newChannelBroker() *channelBroker { rng := mrand.New(mrand.NewSource(time.Now().UnixNano())) return &channelBroker{ endpoints: make(map[string]*ua.EndpointDescription), @@ -43,7 +43,6 @@ func newChannelBroker(logger Logger) *channelBroker { msgChan: make(chan *uasc.MessageBody), secureChannelID: uint32(rng.Int31()), secureTokenID: uint32(rng.Int31()), - logger: logger, } } @@ -75,40 +74,33 @@ func (c *channelBroker) RegisterConn(ctx context.Context, conn *uacp.Conn, local secureTokenID, ) if err != nil { - if c.logger != nil { - c.logger.Error("Error creating secure channel for new connection: %s", err) - } + ualog.Error(ctx, "could not create secure channel for new connection", ualog.Err(err)) return err } c.mu.Lock() c.s[secureChannelID] = sc - if c.logger != nil { - c.logger.Info("Registered new channel (id %d) now at %d channels", secureChannelID, len(c.s)) - } c.mu.Unlock() c.wg.Add(1) + + ctx = ualog.WithAttrs(ctx, ualog.Uint32("channel", secureChannelID)) + ualog.Info(ctx, "registered new channel", ualog.Int("count", len(c.s))) + outer: for { select { case <-ctx.Done(): // todo(fs): return error? - if c.logger != nil { - c.logger.Warn("Context done, closing Secure Channel %d", secureChannelID) - } + ualog.Warn(ctx, "context done, closing secure channel") break outer default: msg := sc.Receive(ctx) if msg.Err == io.EOF { - if c.logger != nil { - c.logger.Warn("Secure Channel %d closed", secureChannelID) - } + ualog.Warn(ctx, "secure channel closed") break outer } else if msg.Err != nil { - if c.logger != nil { - c.logger.Error("Secure Channel %d error: %s", secureChannelID, msg.Err) - } + ualog.Error(ctx, "secure channel error", ualog.Err(msg.Err)) break outer } // todo(fs): honor ctx @@ -126,7 +118,7 @@ outer: // Close gracefully closes all secure channels // todo(fs): use ctx -func (c *channelBroker) Close() error { +func (c *channelBroker) Close(ctx context.Context) error { var err error c.mu.Lock() for _, s := range c.s { @@ -140,12 +132,15 @@ func (c *channelBroker) Close() error { defer close(done) c.wg.Wait() }() + + channelExitTimeout := time.Duration(10 * time.Second) // todo(fs): magic number + select { case <-done: - case <-time.After(10 * time.Second): // todo(fs): magic number - if c.logger != nil { - c.logger.Error("CloseAll: timed out waiting for channels to exit") - } + case <-time.After(channelExitTimeout): + ualog.Error(ctx, "timed out waiting for channels to exit", + ualog.Duration("timeout", channelExitTimeout), + ) } return err diff --git a/server/discovery_service.go b/server/discovery_service.go index 7ba271a2d..2ebf33184 100644 --- a/server/discovery_service.go +++ b/server/discovery_service.go @@ -1,9 +1,11 @@ package server import ( + "context" "strings" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -14,11 +16,18 @@ type DiscoveryService struct { srv *Server } -// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.4.2 -func (s *DiscoveryService) FindServers(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) +func NewDiscoveryService(s *Server) *DiscoveryService { + return &DiscoveryService{ + srv: s, } +} + +var newDiscoveryServiceLogAttribute = newServiceLogAttributeCreatorForSet("discovery") + +// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.4.2 +func (s *DiscoveryService) FindServers(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newDiscoveryServiceLogAttribute("find servers")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.FindServersRequest](r) if err != nil { @@ -36,23 +45,22 @@ func (s *DiscoveryService) FindServers(sc *uasc.SecureChannel, r ua.Request, req } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.4.3 -func (s *DiscoveryService) FindServersOnNetwork(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *DiscoveryService) FindServersOnNetwork(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newDiscoveryServiceLogAttribute("find servers on network")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.FindServersOnNetworkRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.4.4 -func (s *DiscoveryService) GetEndpoints(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *DiscoveryService) GetEndpoints(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newDiscoveryServiceLogAttribute("get endpoints")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.GetEndpointsRequest](r) if err != nil { @@ -77,27 +85,27 @@ func (s *DiscoveryService) GetEndpoints(sc *uasc.SecureChannel, r ua.Request, re } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.4.5 -func (s *DiscoveryService) RegisterServer(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *DiscoveryService) RegisterServer(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newDiscoveryServiceLogAttribute("register server")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.RegisterServerRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.4.6 -func (s *DiscoveryService) RegisterServer2(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *DiscoveryService) RegisterServer2(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newDiscoveryServiceLogAttribute("register server 2")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.RegisterServer2Request](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } diff --git a/server/logging.go b/server/logging.go new file mode 100644 index 000000000..5c76b22aa --- /dev/null +++ b/server/logging.go @@ -0,0 +1,23 @@ +package server + +import ( + "context" + + "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" +) + +// logServiceRequest logs information about the incoming request at +// the DEBUG level. If the current logger's debug level is not enabled +// no log attribute will be allocated +func logServiceRequest(ctx context.Context, req ua.Request) { + ualog.DebugFunc(ctx, "handling service request", func() []ualog.Attr { return []ualog.Attr{ualog.Any("request", req)} }) +} + +// newServiceLogAttributeCreatorForSet is a utility function for wrapping a +// service's set and name in an attribte group for logging +func newServiceLogAttributeCreatorForSet(set string) func(string) ualog.Attr { + return func(service string) ualog.Attr { + return ualog.GroupAttrs("service", ualog.String("set", set), ualog.String("name", service)) + } +} diff --git a/server/method_service.go b/server/method_service.go index ce41a42b0..c0165904e 100644 --- a/server/method_service.go +++ b/server/method_service.go @@ -1,7 +1,10 @@ package server import ( + "context" + "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -12,15 +15,23 @@ type MethodService struct { srv *Server } -// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.11.2 -func (s *MethodService) Call(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) +func NewMethodService(s *Server) *MethodService { + return &MethodService{ + srv: s, } +} + +var newMethodServiceLogAttribute = newServiceLogAttributeCreatorForSet("method") + +// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.11.2 +func (s *MethodService) Call(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newMethodServiceLogAttribute("call")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.CallRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } diff --git a/server/monitored_item_service.go b/server/monitored_item_service.go index 149758c50..19c1953dc 100644 --- a/server/monitored_item_service.go +++ b/server/monitored_item_service.go @@ -1,6 +1,7 @@ package server import ( + "context" "errors" "slices" "sync" @@ -8,6 +9,7 @@ import ( "time" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -28,6 +30,17 @@ type MonitoredItemService struct { id uint32 } +func NewMonitoredItemService(sub *SubscriptionService) *MonitoredItemService { + return &MonitoredItemService{ + SubService: sub, + Items: make(map[uint32]*MonitoredItem), + Nodes: make(map[string][]*MonitoredItem), + Subs: make(map[uint32][]*MonitoredItem), + } +} + +var newMonitoredItemServiceLogAttribute = newServiceLogAttributeCreatorForSet("monitoreditem") + // function to get rid of all references to a specific Monitored Item (by ID number) func (s *MonitoredItemService) DeleteMonitoredItem(id uint32) { s.Mu.Lock() @@ -97,7 +110,7 @@ func (s *MonitoredItemService) DeleteSub(id uint32) { } } -func (s *MonitoredItemService) ChangeNotification(n *ua.NodeID) { +func (s *MonitoredItemService) ChangeNotification(ctx context.Context, n *ua.NodeID) { s.Mu.Lock() defer s.Mu.Unlock() @@ -118,20 +131,20 @@ func (s *MonitoredItemService) ChangeNotification(n *ua.NodeID) { val := new(ua.MonitoredItemNotification) val.ClientHandle = item.Req.RequestedParameters.ClientHandle if err != nil { - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Warn("error getting namespace %d: %v", n.Namespace(), err) - } + ualog.Warn(ctx, "error getting namespace", + ualog.Namespace(n.Namespace()), ualog.Err(err), + ) + val.Value = &ua.DataValue{} val.Value.Status = ua.StatusBad val.Value.EncodingMask |= ua.DataValueStatusCode item.Sub.NotifyChannel <- val continue } - dv := ns.Attribute(n, item.Req.ItemToMonitor.AttributeID) + dv := ns.Attribute(ctx, n, item.Req.ItemToMonitor.AttributeID) val.Value = dv item.Sub.NotifyChannel <- val } - } func (s *MonitoredItemService) NextID() uint32 { @@ -152,10 +165,9 @@ type MonitoredItem struct { } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.12.2 -func (s *MonitoredItemService) CreateMonitoredItems(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *MonitoredItemService) CreateMonitoredItems(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newMonitoredItemServiceLogAttribute("create")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.CreateMonitoredItemsRequest](r) if err != nil { @@ -169,9 +181,8 @@ func (s *MonitoredItemService) CreateMonitoredItems(sc *uasc.SecureChannel, r ua res := make([]*ua.MonitoredItemCreateResult, count) subID := req.SubscriptionID - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Debug("Creating monitored items for sub #%d", subID) - } + ualog.Debug(ctx, "creating monitored items", ualog.Uint32("sub", subID)) + s.SubService.Mu.Lock() sub, ok := s.SubService.Subs[subID] s.SubService.Mu.Unlock() @@ -179,7 +190,7 @@ func (s *MonitoredItemService) CreateMonitoredItems(sc *uasc.SecureChannel, r ua return nil, errors.New("sub doesn't exist") } - sess := s.SubService.srv.Session(req.RequestHeader) + sess := s.SubService.srv.Session(ctx, req.RequestHeader) if sub.Session.AuthTokenID.String() != sess.AuthTokenID.String() { return nil, errors.New("not your subscription, bro") } @@ -207,13 +218,13 @@ func (s *MonitoredItemService) CreateMonitoredItems(sc *uasc.SecureChannel, r ua } s.Subs[item.Sub.ID] = append(list, &item) - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Debug("Adding monitored item '%s' to sub #%d as %d->%d", - nodeid.String(), - subID, - item.ID, - itemreq.RequestedParameters.ClientHandle) - } + ualog.Debug(ctx, "adding monitored item to subscription", + ualog.Any(ualog.NodeIdKey, nodeid), + ualog.Uint32("sub", subID), + ualog.Uint32("item_id", item.ID), + ualog.Uint32("client", itemreq.RequestedParameters.ClientHandle), + ) + res[i] = &ua.MonitoredItemCreateResult{ StatusCode: ua.StatusOK, MonitoredItemID: item.ID, @@ -224,8 +235,7 @@ func (s *MonitoredItemService) CreateMonitoredItems(sc *uasc.SecureChannel, r ua // do an initial update for the nodeids in the background. // These lock the mutex so we can't do them inline here. // This will cause them to happen once we unlock. - go s.ChangeNotification(nodeid) - + go s.ChangeNotification(ctx, nodeid) } resp := &ua.CreateMonitoredItemsResponse{ @@ -242,27 +252,25 @@ func (s *MonitoredItemService) CreateMonitoredItems(sc *uasc.SecureChannel, r ua } return resp, nil - } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.12.3 -func (s *MonitoredItemService) ModifyMonitoredItems(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *MonitoredItemService) ModifyMonitoredItems(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newMonitoredItemServiceLogAttribute("modify")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.ModifyMonitoredItemsRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.12.4 -func (s *MonitoredItemService) SetMonitoringMode(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *MonitoredItemService) SetMonitoringMode(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newMonitoredItemServiceLogAttribute("set monitoring mode")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.SetMonitoringModeRequest](r) if err != nil { @@ -273,7 +281,7 @@ func (s *MonitoredItemService) SetMonitoringMode(sc *uasc.SecureChannel, r ua.Re results := make([]ua.StatusCode, len(req.MonitoredItemIDs)) - sess := s.SubService.srv.Session(req.RequestHeader) + sess := s.SubService.srv.Session(ctx, req.RequestHeader) for i := range req.MonitoredItemIDs { id := req.MonitoredItemIDs[i] @@ -303,27 +311,25 @@ func (s *MonitoredItemService) SetMonitoringMode(sc *uasc.SecureChannel, r ua.Re Results: results, DiagnosticInfos: []*ua.DiagnosticInfo{}, }, nil - } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.12.5 -func (s *MonitoredItemService) SetTriggering(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *MonitoredItemService) SetTriggering(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newMonitoredItemServiceLogAttribute("set triggering")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.SetTriggeringRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.12.6 -func (s *MonitoredItemService) DeleteMonitoredItems(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.SubService.srv.cfg.logger != nil { - s.SubService.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *MonitoredItemService) DeleteMonitoredItems(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newMonitoredItemServiceLogAttribute("delete")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.DeleteMonitoredItemsRequest](r) if err != nil { @@ -333,7 +339,7 @@ func (s *MonitoredItemService) DeleteMonitoredItems(sc *uasc.SecureChannel, r ua s.Mu.Lock() defer s.Mu.Unlock() - sess := s.SubService.srv.Session(req.RequestHeader) + sess := s.SubService.srv.Session(ctx, req.RequestHeader) results := make([]ua.StatusCode, len(req.MonitoredItemIDs)) for i := range req.MonitoredItemIDs { @@ -365,5 +371,4 @@ func (s *MonitoredItemService) DeleteMonitoredItems(sc *uasc.SecureChannel, r ua DiagnosticInfos: []*ua.DiagnosticInfo{}, } return response, nil - } diff --git a/server/namespace_map.go b/server/namespace_map.go index 875b1523f..eb609bfd6 100644 --- a/server/namespace_map.go +++ b/server/namespace_map.go @@ -1,12 +1,14 @@ package server import ( + "context" "sync" "time" "github.com/gopcua/opcua/id" "github.com/gopcua/opcua/server/attrs" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) // This namespaces give a convenient way to have data mapped to the OPC server @@ -26,6 +28,8 @@ type MapNamespace struct { ExternalNotification chan string id uint16 + + logAttributes ualog.Attr } // Get the value associated with key from the MapNamespace. @@ -40,17 +44,17 @@ func (s *MapNamespace) GetValue(key string) any { // update the value associated with a key and trigger the change notification // to the OPC server -func (s *MapNamespace) SetValue(key string, value any) { +func (s *MapNamespace) SetValue(ctx context.Context, key string, value any) { s.Mu.Lock() defer s.Mu.Unlock() s.Data[key] = value - s.ChangeNotification(key) + s.ChangeNotification(ctx, key) } // This function is used to notify OPC UA subscribers if a key was changed without using the // SetValue() function -func (s *MapNamespace) ChangeNotification(key string) { - s.srv.ChangeNotification(ua.NewStringNodeID(s.id, key)) +func (s *MapNamespace) ChangeNotification(ctx context.Context, key string) { + s.srv.ChangeNotification(ctx, ua.NewStringNodeID(s.id, key)) } func NewMapNamespace(srv *Server, name string) *MapNamespace { @@ -59,6 +63,7 @@ func NewMapNamespace(srv *Server, name string) *MapNamespace { name: name, Data: make(map[string]any), ExternalNotification: make(chan string), + logAttributes: ualog.GroupAttrs("namespace", ualog.String("name", name), ualog.String("type", "map")), } srv.AddNamespace(&mrw) return &mrw @@ -71,14 +76,14 @@ func (ns *MapNamespace) SetID(id uint16) { ns.id = id } -func (ns *MapNamespace) Browse(bd *ua.BrowseDescription) *ua.BrowseResult { +func (ns *MapNamespace) Browse(ctx context.Context, bd *ua.BrowseDescription) *ua.BrowseResult { ns.Mu.RLock() defer ns.Mu.RUnlock() - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Debug("BrowseRequest: id=%s mask=%08b\n", bd.NodeID, bd.ResultMask) - ns.srv.cfg.logger.Debug("Browse req for %s", bd.NodeID.String()) - } + ualog.Debug(ctx, "browse request for node", ns.logAttributes, + ualog.Any(ualog.NodeIdKey, bd.NodeID), ualog.Bitmask("mask", bd.ResultMask), + ) + if bd.NodeID.IntID() != id.RootFolder && bd.NodeID.IntID() != id.ObjectsFolder { refs := make([]*ua.ReferenceDescription, 0) return &ua.BrowseResult{ @@ -105,7 +110,6 @@ func (ns *MapNamespace) Browse(bd *ua.BrowseDescription) *ua.BrowseResult { StatusCode: ua.StatusGood, References: refs, } - } refs := make([]*ua.ReferenceDescription, len(ns.Data)) @@ -132,13 +136,13 @@ func (ns *MapNamespace) Browse(bd *ua.BrowseDescription) *ua.BrowseResult { StatusCode: ua.StatusGood, References: refs, } - } -func (ns *MapNamespace) Attribute(n *ua.NodeID, a ua.AttributeID) *ua.DataValue { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Debug("read: node=%s attr=%s", n.String(), a) - } +func (ns *MapNamespace) Attribute(ctx context.Context, n *ua.NodeID, a ua.AttributeID) *ua.DataValue { + ctx = ualog.WithAttrs(ctx, ns.logAttributes) + ualog.Debug(ctx, "read node attribute", + ualog.Any(ualog.NodeIdKey, n), ualog.Any("attr", a), + ) if n.IntID() != 0 { // this is not one of our normal tags. @@ -160,7 +164,6 @@ func (ns *MapNamespace) Attribute(n *ua.NodeID, a ua.AttributeID) *ua.DataValue } return attrval.Value - } dv := &ua.DataValue{ @@ -170,12 +173,9 @@ func (ns *MapNamespace) Attribute(n *ua.NodeID, a ua.AttributeID) *ua.DataValue } key := n.StringID() + ualog.Debug(ctx, "read request", ualog.String("key", key), ualog.Any("data", ns.Data)) var err error - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Debug("Read req for %s", key) - ns.srv.cfg.logger.Debug("'%s' Data at read: %v", ns.name, ns.Data) - } // because our data is native go types we don't have any of the ua "attributes" attached to it. // so depending on what attribute the client wants, we'll inspect the data and return the appropriate @@ -257,53 +257,39 @@ func (ns *MapNamespace) Attribute(n *ua.NodeID, a ua.AttributeID) *ua.DataValue case string: dv.Value, err = ua.NewVariant(ua.NewNumericNodeID(0, 12)) if err != nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("problem creating variant: %v", err) - } + ualog.Warn(ctx, "problem creating variant", ualog.Err(err)) } case int: // we can't use an int because it is of unspecified length. I'm going to use int64 so that we don't // have to worry about cutting data off. dv.Value, err = ua.NewVariant(ua.NewNumericNodeID(0, 6)) if err != nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("problem creating variant: %v", err) - } + ualog.Warn(ctx, "problem creating variant", ualog.Err(err)) } case int32: dv.Value, err = ua.NewVariant(ua.NewNumericNodeID(0, 6)) if err != nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("problem creating variant: %v", err) - } + ualog.Warn(ctx, "problem creating variant", ualog.Err(err)) } case float32: dv.Value, err = ua.NewVariant(ua.NewNumericNodeID(0, 10)) if err != nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("problem creating variant: %v", err) - } + ualog.Warn(ctx, "problem creating variant", ualog.Err(err)) } case float64: dv.Value, err = ua.NewVariant(ua.NewNumericNodeID(0, 11)) if err != nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("problem creating variant: %v", err) - } + ualog.Warn(ctx, "problem creating variant", ualog.Err(err)) } case bool: dv.Value, err = ua.NewVariant(ua.NewNumericNodeID(0, 1)) if err != nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("problem creating variant: %v", err) - } + ualog.Warn(ctx, "problem creating variant", ualog.Err(err)) } default: dv.Value, err = ua.NewVariant(ua.NewNumericNodeID(0, 24)) if err != nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("problem creating variant: %v", err) - } + ualog.Warn(ctx, "problem creating variant", ualog.Err(err)) } } @@ -323,25 +309,24 @@ func (ns *MapNamespace) Attribute(n *ua.NodeID, a ua.AttributeID) *ua.DataValue } if dv.Value == nil { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Warn("bad dv value") - } + ualog.Warn(ctx, "bad dv value") } else { - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Debug("Read '%s' = '%v' (%v)", key, dv.Value, dv.Value.Value()) - } + ualog.Debug(ctx, "read", + ualog.String("key", key), ualog.Any("variant", dv.Value), ualog.Any("value", dv.Value.Value()), + ) } return dv } -func (s *MapNamespace) SetAttribute(node *ua.NodeID, attr ua.AttributeID, val *ua.DataValue) ua.StatusCode { +func (s *MapNamespace) SetAttribute(ctx context.Context, node *ua.NodeID, attr ua.AttributeID, val *ua.DataValue) ua.StatusCode { + ctx = ualog.WithAttrs(ctx, s.logAttributes) + ualog.Debug(ctx, "write node attribute", ualog.Any(ualog.NodeIdKey, node), ualog.Any("attr", attr)) s.Mu.Lock() defer s.Mu.Unlock() - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("'%s' Data pre-write: %v", s.name, s.Data) - } + + ualog.Debug(ctx, "data pre-write", ualog.Any("data", s.Data)) key := node.StringID() @@ -353,7 +338,7 @@ func (s *MapNamespace) SetAttribute(node *ua.NodeID, attr ua.AttributeID, val *u } // notify the opc ua server the value has changed. - s.srv.ChangeNotification(node) + s.srv.ChangeNotification(ctx, node) // notify the non-opc application the value has changed. select { case s.ExternalNotification <- key: @@ -371,7 +356,6 @@ func (ns *MapNamespace) AddNode(n *Node) *Node { } func (ns *MapNamespace) Node(id *ua.NodeID) *Node { return nil - } func (ns *MapNamespace) Objects() *Node { oid := ua.NewNumericNodeID(ns.ID(), id.ObjectsFolder) @@ -392,8 +376,8 @@ func (ns *MapNamespace) Objects() *Node { nil, ) return n - } + func (ns *MapNamespace) Root() *Node { n := NewNode( ua.NewNumericNodeID(ns.ID(), id.RootFolder), @@ -406,5 +390,4 @@ func (ns *MapNamespace) Root() *Node { nil, ) return n - } diff --git a/server/namespace_node.go b/server/namespace_node.go index c6374d830..5821e350d 100644 --- a/server/namespace_node.go +++ b/server/namespace_node.go @@ -1,6 +1,7 @@ package server import ( + "context" "sync" "sync/atomic" "time" @@ -8,6 +9,7 @@ import ( "github.com/gopcua/opcua/id" "github.com/gopcua/opcua/server/attrs" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) // the base "node-centric" namespace @@ -21,6 +23,8 @@ type NodeNameSpace struct { nodeid_sequence uint32 ExternalNotification chan *ua.NodeID + + logAttributes ualog.Attr } func (ns *NodeNameSpace) GetNextNodeID() uint32 { @@ -37,6 +41,7 @@ func NewNodeNameSpace(srv *Server, name string) *NodeNameSpace { nodes: make([]*Node, 0), m: make(map[string]*Node), ExternalNotification: make(chan *ua.NodeID), + logAttributes: ualog.GroupAttrs("namespace", ualog.String("name", name), ualog.String("type", "node")), } srv.AddNamespace(ns) @@ -67,8 +72,8 @@ func NewNodeNameSpace(srv *Server, name string) *NodeNameSpace { // This function is to notify opc subscribers if a node was changed // without using the SetAttribute method -func (s *NodeNameSpace) ChangeNotification(nodeid *ua.NodeID) { - s.srv.ChangeNotification(nodeid) +func (s *NodeNameSpace) ChangeNotification(ctx context.Context, nodeid *ua.NodeID) { + s.srv.ChangeNotification(ctx, nodeid) } func (ns *NodeNameSpace) Name() string { @@ -112,7 +117,12 @@ func (as *NodeNameSpace) AddNewVariableStringNode(name string, value any) *Node return n } -func (as *NodeNameSpace) Attribute(id *ua.NodeID, attr ua.AttributeID) *ua.DataValue { +func (as *NodeNameSpace) Attribute(ctx context.Context, id *ua.NodeID, attr ua.AttributeID) *ua.DataValue { + ctx = ualog.WithAttrs(ctx, as.logAttributes) + ualog.Debug(ctx, "read node attribute", + ualog.Any(ualog.NodeIdKey, id), ualog.Any("attr", attr), + ) + n := as.Node(id) if n == nil { return &ua.DataValue{ @@ -193,14 +203,14 @@ func (as *NodeNameSpace) Root() *Node { return as.Node(RootFolder) } -func (ns *NodeNameSpace) Browse(bd *ua.BrowseDescription) *ua.BrowseResult { +func (ns *NodeNameSpace) Browse(ctx context.Context, bd *ua.BrowseDescription) *ua.BrowseResult { + ualog.Debug(ctx, "browse", ns.logAttributes, + ualog.Any(ualog.NodeIdKey, bd.NodeID), ualog.Bitmask("mask", bd.ResultMask), + ) + ns.mu.RLock() defer ns.mu.RUnlock() - if ns.srv.cfg.logger != nil { - ns.srv.cfg.logger.Debug("BrowseRequest: id=%s mask=%08b\n", bd.NodeID, bd.ResultMask) - } - n := ns.Node(bd.NodeID) if n == nil { return &ua.BrowseResult{StatusCode: ua.StatusBadNodeIDUnknown} @@ -216,7 +226,7 @@ func (ns *NodeNameSpace) Browse(bd *ua.BrowseDescription) *ua.BrowseResult { } // see if this is a ref the client was interested in. - if !suitableRef(ns.srv, bd, r) { + if !suitableRef(ctx, ns.srv, bd, r) { continue } @@ -244,7 +254,6 @@ func (ns *NodeNameSpace) Browse(bd *ua.BrowseDescription) *ua.BrowseResult { StatusCode: ua.StatusGood, References: refs, } - } func (ns *NodeNameSpace) ID() uint16 { @@ -254,7 +263,10 @@ func (ns *NodeNameSpace) ID() uint16 { func (ns *NodeNameSpace) SetID(id uint16) { ns.id = id } -func (as *NodeNameSpace) SetAttribute(id *ua.NodeID, attr ua.AttributeID, val *ua.DataValue) ua.StatusCode { +func (as *NodeNameSpace) SetAttribute(ctx context.Context, id *ua.NodeID, attr ua.AttributeID, val *ua.DataValue) ua.StatusCode { + ctx = ualog.WithAttrs(ctx, as.logAttributes) + ualog.Debug(ctx, "write node attribute", ualog.Any(ualog.NodeIdKey, id), ualog.Any("attr", attr)) + n := as.Node(id) if n == nil { return ua.StatusBadNodeIDUnknown @@ -268,7 +280,7 @@ func (as *NodeNameSpace) SetAttribute(id *ua.NodeID, attr ua.AttributeID, val *u if err != nil { return ua.StatusBadAttributeIDInvalid } - as.srv.ChangeNotification(id) + as.srv.ChangeNotification(ctx, id) select { case as.ExternalNotification <- id: default: diff --git a/server/namespaces.go b/server/namespaces.go index b56da9460..863b4d37c 100644 --- a/server/namespaces.go +++ b/server/namespaces.go @@ -5,6 +5,8 @@ package server import ( + "context" + "github.com/gopcua/opcua/id" "github.com/gopcua/opcua/ua" ) @@ -34,7 +36,7 @@ type NameSpace interface { // This is the function to list all available nodes to the client that is browsing. // The BrowseDescription has the root node of the browse and what kind of nodes the // client is looking for. The Browse Result should have the list of matching nodes. - Browse(req *ua.BrowseDescription) *ua.BrowseResult + Browse(ctx context.Context, req *ua.BrowseDescription) *ua.BrowseResult // ID and SetID are the namespace ID number of this namespace. When you add it to the server // with srv.AddNamespace(xxx) it will set these for you. @@ -44,6 +46,6 @@ type NameSpace interface { // These are the functions for reading and writing arbitrary attributes. The most common // is the value attribute, but many clients also read the datatype and description attributes. // as well as attributes related to array bounds - Attribute(*ua.NodeID, ua.AttributeID) *ua.DataValue - SetAttribute(*ua.NodeID, ua.AttributeID, *ua.DataValue) ua.StatusCode + Attribute(context.Context, *ua.NodeID, ua.AttributeID) *ua.DataValue + SetAttribute(context.Context, *ua.NodeID, ua.AttributeID, *ua.DataValue) ua.StatusCode } diff --git a/server/node.go b/server/node.go index 01e295200..1568093be 100644 --- a/server/node.go +++ b/server/node.go @@ -1,7 +1,7 @@ package server import ( - "log" + "fmt" "maps" "slices" "time" @@ -260,18 +260,19 @@ func (n *Node) SetDescription(text, locale string) { func (n *Node) DataType() *ua.ExpandedNodeID { if n == nil { - log.Printf("n was nil!") + fmt.Println("n was nil!") return ua.NewTwoByteExpandedNodeID(0) } - v := n.attr[ua.AttributeIDDataType] - if v == nil || v.Value.Value() == nil { + + v, ok := n.attr[ua.AttributeIDDataType] + if !ok || v == nil || v.Value.Value() == nil { // if we have a type definition, return that? for i := range n.refs { r := n.refs[i] if r.ReferenceTypeID == nil { - log.Printf("reftypeid was nil!") + fmt.Println("reftypeid was nil!") } - if r.ReferenceTypeID.IntID() == id.HasTypeDefinition && r.IsForward { + if r.ReferenceTypeID != nil && r.ReferenceTypeID.IntID() == id.HasTypeDefinition && r.IsForward { return r.NodeID } } @@ -298,7 +299,6 @@ func (n *Node) NodeClass() ua.NodeClass { return ua.NodeClass(int32(vui32)) } return ua.NodeClass(vi32) - } func (n *Node) AddObject(o *Node) *Node { @@ -386,5 +386,4 @@ func (n Node) Access(flag ua.AccessLevelType) bool { } } return true - } diff --git a/server/node_mgmt_service.go b/server/node_mgmt_service.go index 084f5e4f9..27bb6ea93 100644 --- a/server/node_mgmt_service.go +++ b/server/node_mgmt_service.go @@ -1,7 +1,10 @@ package server import ( + "context" + "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -12,54 +15,62 @@ type NodeManagementService struct { srv *Server } -// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.7.2 -func (s *NodeManagementService) AddNodes(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) +func NewNodeManagementService(s *Server) *NodeManagementService { + return &NodeManagementService{ + srv: s, } +} + +var newNodeMgmtServiceLogAttribute = newServiceLogAttributeCreatorForSet("nodemanagement") + +// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.7.2 +func (s *NodeManagementService) AddNodes(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newNodeMgmtServiceLogAttribute("add nodes")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.AddNodesRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.7.3 -func (s *NodeManagementService) AddReferences(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *NodeManagementService) AddReferences(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newNodeMgmtServiceLogAttribute("add references")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.AddReferencesRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.7.4 -func (s *NodeManagementService) DeleteNodes(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *NodeManagementService) DeleteNodes(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newNodeMgmtServiceLogAttribute("delete nodes")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.DeleteNodesRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.7.5 -func (s *NodeManagementService) DeleteReferences(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *NodeManagementService) DeleteReferences(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newNodeMgmtServiceLogAttribute("delete references")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.DeleteReferencesRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } diff --git a/server/nodeset2_import.go b/server/nodeset2_import.go index 6b77193c4..733b8f24d 100644 --- a/server/nodeset2_import.go +++ b/server/nodeset2_import.go @@ -1,23 +1,24 @@ package server import ( + "context" "fmt" - "log" "github.com/gopcua/opcua/schema" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) -func (srv *Server) ImportNodeSet(nodes *schema.UANodeSet) error { +func (srv *Server) ImportNodeSet(ctx context.Context, nodes *schema.UANodeSet) error { err := srv.namespacesImportNodeSet(nodes) if err != nil { return fmt.Errorf("problem creating namespaces: %w", err) } - err = srv.nodesImportNodeSet(nodes) + err = srv.nodesImportNodeSet(ctx, nodes) if err != nil { return fmt.Errorf("problem creating nodes: %w", err) } - err = srv.refsImportNodeSet(nodes) + err = srv.refsImportNodeSet(ctx, nodes) if err != nil { return fmt.Errorf("problem creating references: %w", err) } @@ -34,9 +35,9 @@ func (srv *Server) namespacesImportNodeSet(nodes *schema.UANodeSet) error { return nil } -func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { +func (srv *Server) nodesImportNodeSet(ctx context.Context, nodes *schema.UANodeSet) error { - log.Printf("New Node Set: %s", nodes.LastModifiedAttr) + ualog.Info(ctx, "new node set", ualog.String("last_modified", nodes.LastModifiedAttr)) reftypes := make(map[string]*schema.UAReferenceType) @@ -75,9 +76,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ns, err := srv.Namespace(int(nid.Namespace())) if err != nil { // This namespace doesn't exist. - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("Could Not Find Namespace %d", nid.Namespace()) - } + ualog.Warn(ctx, "could not find namespace", ualog.Namespace(nid.Namespace())) return err } ns.AddNode(n) @@ -109,9 +108,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ns, err := srv.Namespace(int(nid.Namespace())) if err != nil { // This namespace doesn't exist. - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("Could Not Find Namespace %d", nid.Namespace()) - } + ualog.Warn(ctx, "could not find namespace", ualog.Namespace(nid.Namespace())) return err } ns.AddNode(n) @@ -141,9 +138,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ns, err := srv.Namespace(int(nid.Namespace())) if err != nil { // This namespace doesn't exist. - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("Could Not Find Namespace %d", nid.Namespace()) - } + ualog.Warn(ctx, "could not find namespace", ualog.Namespace(nid.Namespace())) return err } ns.AddNode(n) @@ -172,9 +167,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ns, err := srv.Namespace(int(nid.Namespace())) if err != nil { // This namespace doesn't exist. - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("Could Not Find Namespace %d", nid.Namespace()) - } + ualog.Warn(ctx, "could not find namespace", ualog.Namespace(nid.Namespace())) return err } ns.AddNode(n) @@ -203,9 +196,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ns, err := srv.Namespace(int(nid.Namespace())) if err != nil { // This namespace doesn't exist. - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("Could Not Find Namespace %d", nid.Namespace()) - } + ualog.Warn(ctx, "could not find namespace", ualog.Namespace(nid.Namespace())) return err } ns.AddNode(n) @@ -234,9 +225,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ns, err := srv.Namespace(int(nid.Namespace())) if err != nil { // This namespace doesn't exist. - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("Could Not Find Namespace %d", nid.Namespace()) - } + ualog.Warn(ctx, "could not find namespace", ualog.Namespace(nid.Namespace())) return err } ns.AddNode(n) @@ -247,7 +236,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ot := nodes.UAObject[i] nid := ua.MustParseNodeID(ot.NodeIdAttr) if ot.NodeIdAttr == "i=85" { - log.Printf("doing objects.") + ualog.Info(ctx, "doing objects") } var attrs Attributes = make(map[ua.AttributeID]*ua.DataValue) attrs[ua.AttributeIDAccessRestrictions] = DataValueFromValue(ot.AccessRestrictionsAttr) @@ -269,9 +258,7 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { ns, err := srv.Namespace(int(nid.Namespace())) if err != nil { // This namespace doesn't exist. - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("Could Not Find Namespace %d", nid.Namespace()) - } + ualog.Warn(ctx, "could not find namespace", ualog.Namespace(nid.Namespace())) return err } ns.AddNode(n) @@ -279,9 +266,10 @@ func (srv *Server) nodesImportNodeSet(nodes *schema.UANodeSet) error { return nil } -func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { - log.Printf("New Node Set: %s", nodes.LastModifiedAttr) +func (srv *Server) refsImportNodeSet(ctx context.Context, nodes *schema.UANodeSet) error { + + ualog.Info(ctx, "new node set", ualog.String("last_modified", nodes.LastModifiedAttr)) failures := 0 reftypes := make(map[string]*schema.UAReferenceType) @@ -303,9 +291,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { aliasID := ua.MustParseNodeID(aliases[alias]) refnode := srv.Node(aliasID) if refnode == nil { - if srv.cfg.logger != nil { - srv.cfg.logger.Warn("error loading alias %s", alias) - } + ualog.Warn(ctx, "failed to load alias", ualog.String("alias", alias)) continue } rt := new(schema.UAReferenceType) @@ -322,9 +308,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { if !ok { reftypes[alias] = rt // sometimes they use browse name } else { - if srv.cfg.logger != nil { - srv.cfg.logger.Error("Duplicate reference type %s", alias) - } + ualog.Error(ctx, "duplicate reference type", ualog.String("alias", alias)) continue } @@ -332,12 +316,9 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { if !ok { reftypes[aliases[alias]] = rt // sometimes they use node id } else { - if srv.cfg.logger != nil { - srv.cfg.logger.Error("Duplicate reference type %s", aliases[alias]) - } + ualog.Error(ctx, "duplicate reference type", ualog.String("alias", aliases[alias])) continue } - } // the first thing we have to do is go thorugh and define all the nodes. @@ -348,7 +329,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { nodeid := ua.MustParseNodeID(rt.NodeIdAttr) node := srv.Node(nodeid) if node == nil { - log.Printf("Error loading node %s", rt.NodeIdAttr) + ualog.Error(ctx, "error loading node", ualog.String("id", rt.NodeIdAttr)) } for rid := range rt.References.Reference { @@ -356,7 +337,11 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { refnodeid := ua.MustParseNodeID(ref.Value) n := srv.Node(refnodeid) if n == nil { - log.Printf("can't find node %s as %s reference to %s", ref.Value, ref.ReferenceTypeAttr, rt.BrowseNameAttr) + ualog.Error(ctx, "unable to find node", + ualog.String("value", ref.Value), + ualog.String("ref_type", ref.ReferenceTypeAttr), + ualog.String("browse_name", rt.BrowseNameAttr), + ) failures++ continue } @@ -371,7 +356,6 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { n.AddRef(node, RefType(reftypeid.IntID()), !*ref.IsForwardAttr) } } - } // set up the data types. @@ -381,7 +365,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { node := srv.Node(nid) if nid.IntID() == 24 { - log.Printf("doing BaseDataType") + ualog.Info(ctx, "doing basedatatype") } for rid := range dt.References.Reference { @@ -389,7 +373,11 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { refnodeid := ua.MustParseNodeID(ref.Value) n := srv.Node(refnodeid) if n == nil { - log.Printf("can't find node %s as %s reference to %s", ref.Value, ref.ReferenceTypeAttr, dt.BrowseNameAttr) + ualog.Error(ctx, "unable to find node", + ualog.String("value", ref.Value), + ualog.String("ref_type", ref.ReferenceTypeAttr), + ualog.String("browse_name", dt.BrowseNameAttr), + ) failures++ continue } @@ -404,9 +392,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { if !reftypes[ref.ReferenceTypeAttr].SymmetricAttr { n.AddRef(node, RefType(reftypeid.IntID()), !*ref.IsForwardAttr) } - } - } // set up the object types @@ -420,7 +406,11 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { refnodeid := ua.MustParseNodeID(ref.Value) n := srv.Node(refnodeid) if n == nil { - log.Printf("can't find node %s as %s reference to %s", ref.Value, ref.ReferenceTypeAttr, ot.BrowseNameAttr) + ualog.Error(ctx, "unable to find node", + ualog.String("value", ref.Value), + ualog.String("ref_type", ref.ReferenceTypeAttr), + ualog.String("browse_name", ot.BrowseNameAttr), + ) failures++ continue } @@ -447,7 +437,11 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { refnodeid := ua.MustParseNodeID(ref.Value) n := srv.Node(refnodeid) if n == nil { - log.Printf("can't find node %s as %s reference to %s", ref.Value, ref.ReferenceTypeAttr, ot.BrowseNameAttr) + ualog.Error(ctx, "unable to find node", + ualog.String("value", ref.Value), + ualog.String("ref_type", ref.ReferenceTypeAttr), + ualog.String("browse_name", ot.BrowseNameAttr), + ) failures++ continue } @@ -460,9 +454,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { if !reftypes[ref.ReferenceTypeAttr].SymmetricAttr { n.AddRef(node, RefType(reftypeid.IntID()), !*ref.IsForwardAttr) } - } - } // set up the variables @@ -476,7 +468,11 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { refnodeid := ua.MustParseNodeID(ref.Value) n := srv.Node(refnodeid) if n == nil { - log.Printf("can't find node %s as %s reference to %s", ref.Value, ref.ReferenceTypeAttr, ot.BrowseNameAttr) + ualog.Error(ctx, "unable to find node", + ualog.String("value", ref.Value), + ualog.String("ref_type", ref.ReferenceTypeAttr), + ualog.String("browse_name", ot.BrowseNameAttr), + ) failures++ continue } @@ -489,9 +485,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { if !reftypes[ref.ReferenceTypeAttr].SymmetricAttr { n.AddRef(node, RefType(reftypeid.IntID()), !*ref.IsForwardAttr) } - } - } // set up the methods @@ -505,7 +499,11 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { refnodeid := ua.MustParseNodeID(ref.Value) n := srv.Node(refnodeid) if n == nil { - log.Printf("can't find node %s as %s reference to %s", ref.Value, ref.ReferenceTypeAttr, ot.BrowseNameAttr) + ualog.Error(ctx, "unable to find node", + ualog.String("value", ref.Value), + ualog.String("ref_type", ref.ReferenceTypeAttr), + ualog.String("browse_name", ot.BrowseNameAttr), + ) failures++ continue } @@ -519,7 +517,6 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { n.AddRef(node, RefType(reftypeid.IntID()), !*ref.IsForwardAttr) } } - } // set up the objects @@ -528,7 +525,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { nid := ua.MustParseNodeID(ot.NodeIdAttr) node := srv.Node(nid) if ot.NodeIdAttr == "i=84" { - log.Printf("doing root.") + ualog.Info(ctx, "doing root") } for rid := range ot.References.Reference { @@ -536,7 +533,11 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { refnodeid := ua.MustParseNodeID(ref.Value) n := srv.Node(refnodeid) if n == nil { - log.Printf("can't find node %s as %s reference to %s", ref.Value, ref.ReferenceTypeAttr, ot.BrowseNameAttr) + ualog.Error(ctx, "unable to find node", + ualog.String("value", ref.Value), + ualog.String("ref_type", ref.ReferenceTypeAttr), + ualog.String("browse_name", ot.BrowseNameAttr), + ) failures++ continue } @@ -549,9 +550,7 @@ func (srv *Server) refsImportNodeSet(nodes *schema.UANodeSet) error { if !reftypes[ref.ReferenceTypeAttr].SymmetricAttr { n.AddRef(node, RefType(reftypeid.IntID()), !*ref.IsForwardAttr) } - } - } return nil diff --git a/server/query_service.go b/server/query_service.go index d4d9712ce..8136efada 100644 --- a/server/query_service.go +++ b/server/query_service.go @@ -1,7 +1,10 @@ package server import ( + "context" + "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -12,28 +15,36 @@ type QueryService struct { srv *Server } -// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.9.3 -func (s *QueryService) QueryFirst(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) +func NewQueryService(s *Server) *QueryService { + return &QueryService{ + srv: s, } +} + +var newQueryServiceLogAttribute = newServiceLogAttributeCreatorForSet("query") + +// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.9.3 +func (s *QueryService) QueryFirst(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newQueryServiceLogAttribute("query first")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.QueryFirstRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.9.4 -func (s *QueryService) QueryNext(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *QueryService) QueryNext(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newQueryServiceLogAttribute("query next")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.QueryNextRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } diff --git a/server/server.go b/server/server.go index 48e816a39..3239ebdd7 100644 --- a/server/server.go +++ b/server/server.go @@ -9,7 +9,6 @@ import ( "crypto/rsa" "encoding/xml" "fmt" - "log" "net" "slices" "strings" @@ -20,6 +19,7 @@ import ( "github.com/gopcua/opcua/schema" "github.com/gopcua/opcua/ua" "github.com/gopcua/opcua/uacp" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uapolicy" ) @@ -68,8 +68,6 @@ type serverConfig struct { enabledAuth []authMode cap ServerCapabilities - - logger Logger } var capabilities = ServerCapabilities{ @@ -97,7 +95,7 @@ type security struct { // New returns an initialized OPC-UA server. // Call Start() afterwards to begin listening and serving connections -func New(opts ...Option) *Server { +func New(ctx context.Context, opts ...Option) *Server { cfg := &serverConfig{ cap: capabilities, applicationName: "GOPCUA", // override with the ServerName option @@ -105,9 +103,11 @@ func New(opts ...Option) *Server { productName: "gopcua OPC/UA Server", // override with the ProductName option softwareVersion: "0.0.0-dev", // override with the SoftwareVersion option } + for _, opt := range opts { - opt(cfg) + opt(ctx, cfg) } + url := "" if len(cfg.endpoints) != 0 { url = cfg.endpoints[0] @@ -116,8 +116,8 @@ func New(opts ...Option) *Server { s := &Server{ url: url, cfg: cfg, - cb: newChannelBroker(cfg.logger), - sb: newSessionBroker(cfg.logger), + cb: newChannelBroker(), + sb: newSessionBroker(), handlers: make(map[uint16]Handler), namespaces: []NameSpace{ NewNameSpace("http://opcfoundation.org/UA/"), // ns:0 @@ -153,9 +153,9 @@ func New(opts ...Option) *Server { n0.srv = s if !ok { // this should never happen because we just set namespace 0 to be a node namespace - log.Panic("Namespace 0 is not a node namespace!") + panic("namespace 0 is not a node namespace") } - s.ImportNodeSet(&nodes) + s.ImportNodeSet(ctx, &nodes) s.namespaces[0].AddNode(CurrentTimeNode()) s.namespaces[0].AddNode(NamespacesNode(s)) @@ -169,8 +169,8 @@ func New(opts ...Option) *Server { return s } -func (s *Server) Session(hdr *ua.RequestHeader) *session { - return s.sb.Session(hdr.AuthenticationToken) +func (s *Server) Session(ctx context.Context, hdr *ua.RequestHeader) *session { + return s.sb.Session(ctx, hdr.AuthenticationToken) } func (s *Server) Namespace(id int) (NameSpace, error) { @@ -188,8 +188,8 @@ func (s *Server) Namespaces() []NameSpace { return s.namespaces } -func (s *Server) ChangeNotification(n *ua.NodeID) { - s.MonitoredItemService.ChangeNotification(n) +func (s *Server) ChangeNotification(ctx context.Context, n *ua.NodeID) { + s.MonitoredItemService.ChangeNotification(ctx, n) } // for now, the address space of the server is split up into namespaces. @@ -209,7 +209,6 @@ func (s *Server) AddNamespace(ns NameSpace) int { if ns.ID() == 0 { return 0 - } return len(s.namespaces) - 1 @@ -256,13 +255,14 @@ func (s *Server) Start(ctx context.Context) error { if err != nil { return err } - log.Printf("Started listening on %v", s.URLs()) + + ualog.Info(ctx, "started listening", ualog.Any("urls", s.URLs())) s.initEndpoints() s.setServerState(ua.ServerStateRunning) if s.cb == nil { - s.cb = newChannelBroker(s.cfg.logger) + s.cb = newChannelBroker() } go s.acceptAndRegister(ctx, s.l) @@ -279,7 +279,7 @@ func (s *Server) setServerState(state ua.ServerState) { // Close gracefully shuts the server down by closing all open connections, // and stops listening on all endpoints -func (s *Server) Close() error { +func (s *Server) Close(ctx context.Context) error { s.setServerState(ua.ServerStateShutdown) // Close the listener, preventing new sessions from starting @@ -288,7 +288,7 @@ func (s *Server) Close() error { } // Shut down all secure channels and UACP connections - return s.cb.Close() + return s.cb.Close(ctx) } type temporary interface { @@ -306,26 +306,23 @@ func (s *Server) acceptAndRegister(ctx context.Context, l *uacp.Listener) { switch x := err.(type) { case *net.OpError: // socket closed. Cannot recover from this. - if s.cfg.logger != nil { - s.cfg.logger.Error("socket closed: %s", err) - } + ualog.Error(ctx, "socket closed", ualog.Err(err)) return case temporary: if x.Temporary() { continue } default: - if s.cfg.logger != nil { - s.cfg.logger.Error("error accepting connection: %s", err) - } + ualog.Error(ctx, "error accepting connection", ualog.Err(err)) continue } } go s.cb.RegisterConn(ctx, c, s.cfg.certificate, s.cfg.privateKey) - if s.cfg.logger != nil { - s.cfg.logger.Info("registered connection: %s", c.RemoteAddr()) - } + + ualog.Info(ctx, "registered connection", + ualog.String("remote", c.RemoteAddr().String()), + ) } } } @@ -333,33 +330,38 @@ func (s *Server) acceptAndRegister(ctx context.Context, l *uacp.Listener) { // monitorConnections reads messages off the secure channel connection and // sends the message to the service handler func (s *Server) monitorConnections(ctx context.Context) { + for ctx.Err() == nil { msg := s.cb.ReadMessage(ctx) if msg == nil { continue // ctx is likely done, ctx.Err will be non-nil } if msg.Err != nil { - if s.cfg.logger != nil { - s.cfg.logger.Error("monitorConnections: Error received: %s\n", msg.Err) - } + ualog.Error(ctx, "error received", + ualog.String("func", "monitorConnections"), + ualog.Err(msg.Err), + ) continue // todo(fs): close SC??? } if resp := msg.Response(); resp != nil { - if s.cfg.logger != nil { - s.cfg.logger.Error("monitorConnections: Server received response %T ???", resp) - } + ualog.Error(ctx, "server received response", ualog.Any("response", resp)) continue // todo(fs): close SC??? } - if s.cfg.logger != nil { - s.cfg.logger.Debug("monitorConnections: Received Message: %T", msg.Request()) - } + + ualog.Debug(ctx, "received message", + ualog.String("func", "monitorConnections"), + ualog.Any("request", msg.Request()), + ) + s.cb.mu.RLock() sc, ok := s.cb.s[msg.SecureChannelID] s.cb.mu.RUnlock() if !ok { // if the secure channel ID is 0, this is probably a open secure channel request. - if s.cfg.logger != nil && msg.SecureChannelID != 0 { - s.cfg.logger.Error("monitorConnections: Unknown SecureChannel: %d", msg.SecureChannelID) + if msg.SecureChannelID != 0 { + ualog.Error(ctx, "unknown secure channel", + ualog.Uint64("channel_id", uint64(msg.SecureChannelID)), + ) } continue } diff --git a/server/server_config.go b/server/server_config.go index bf5c6587b..464b522aa 100644 --- a/server/server_config.go +++ b/server/server_config.go @@ -5,31 +5,32 @@ package server import ( + "context" "crypto/rsa" "crypto/x509" "fmt" - "log" "strings" "time" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uapolicy" "github.com/gopcua/opcua/uasc" ) // Option is an option function type to modify the configuration. -type Option func(*serverConfig) +type Option func(context.Context, *serverConfig) // PrivateKey sets the RSA private key in the secure channel configuration. func PrivateKey(key *rsa.PrivateKey) Option { - return func(s *serverConfig) { + return func(_ context.Context, s *serverConfig) { s.privateKey = key } } // EndPointHostName adds an additional endpoint to the server based on the host name func EndPoint(host string, port int) Option { - return func(s *serverConfig) { + return func(_ context.Context, s *serverConfig) { if s.endpoints == nil { s.endpoints = make([]string, 0) } @@ -41,7 +42,7 @@ func EndPoint(host string, port int) Option { // Certificate sets the client X509 certificate in the secure channel configuration // and also detects and sets the ApplicationURI from the URI within the certificate func Certificate(cert []byte) Option { - return func(s *serverConfig) { + return func(_ context.Context, s *serverConfig) { s.certificate = cert // Extract the application URI from the certificate. @@ -58,7 +59,7 @@ func Certificate(cert []byte) Option { // EnableSecurity registers a new endpoint security mode to the server. // This will also register the security policy against each enabled auth mode func EnableSecurity(secPolicy string, secMode ua.MessageSecurityMode) Option { - return func(s *serverConfig) { + return func(ctx context.Context, s *serverConfig) { if !strings.HasPrefix(secPolicy, "http://opcfoundation.org/UA/SecurityPolicy#") { secPolicy = "http://opcfoundation.org/UA/SecurityPolicy#" + secPolicy } @@ -72,15 +73,16 @@ func EnableSecurity(secPolicy string, secMode ua.MessageSecurityMode) Option { } } if !ok { - log.Printf("error adding endpoint to config, %s is unsupported", secPolicy) + ualog.Error(ctx, "unable to add endpoint security mode to config", + ualog.String(ualog.ErrorKey, "unsupported policy"), + ualog.String("policy", secPolicy), + ) return } for _, sec := range s.enabledSec { if sec.secPolicy == secPolicy && sec.secMode == secMode { - if s.logger != nil { - s.logger.Warn("security policy already exists, skipping") - } + ualog.Warn(ctx, "security policy already exists, skipping") return } } @@ -98,13 +100,13 @@ func EnableSecurity(secPolicy string, secMode ua.MessageSecurityMode) Option { // All AuthModes except Anonymous require encryption by default, so EnableSecurity() // must also be called with at least one non-"None" SecurityPolicy func EnableAuthMode(tokenType ua.UserTokenType) Option { - return func(s *serverConfig) { + return func(ctx context.Context, s *serverConfig) { for _, a := range s.enabledAuth { if a.tokenType == tokenType { - if s.logger != nil { - s.logger.Warn("auth mode already registered, skipping") - } + ualog.Warn(ctx, "auth mode already registered, skipping", + ualog.String("mode", tokenType.String()), + ) return } } @@ -126,43 +128,25 @@ func defaultChannelConfig() *uasc.Config { } func ServerName(name string) Option { - return func(s *serverConfig) { + return func(_ context.Context, s *serverConfig) { s.applicationName = name } } func ManufacturerName(name string) Option { - return func(s *serverConfig) { + return func(_ context.Context, s *serverConfig) { s.manufacturerName = name } } func ProductName(name string) Option { - return func(s *serverConfig) { + return func(_ context.Context, s *serverConfig) { s.productName = name } } func SoftwareVersion(name string) Option { - return func(s *serverConfig) { + return func(_ context.Context, s *serverConfig) { s.softwareVersion = name } } - -// this logger interface is used to allow the user to provide their own logger -// it is compatible with slog.Logger -type Logger interface { - Debug(msg string, args ...any) - Error(msg string, args ...any) - Info(msg string, args ...any) - Warn(msg string, args ...any) -} - -// the server.SetLogger takes a server.Logger interface. This interface is met by -// slog.Logger{}. A simple wrapper could be made for other loggers if they don't already -// meet the interface. -func SetLogger(logger Logger) Option { - return func(s *serverConfig) { - s.logger = logger - } -} diff --git a/server/service_handlers.go b/server/service_handlers.go index 0b4708e41..b6b3e66f3 100644 --- a/server/service_handlers.go +++ b/server/service_handlers.go @@ -10,15 +10,16 @@ import ( "github.com/gopcua/opcua/id" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) -type Handler func(*uasc.SecureChannel, ua.Request, uint32) (ua.Response, error) +type Handler func(context.Context, *uasc.SecureChannel, ua.Request, uint32) (ua.Response, error) func (s *Server) initHandlers() { // s.registerHandlerFunc(id.ServiceFault_Encoding_DefaultBinary, handleServiceFault) - discovery := &DiscoveryService{s} + discovery := NewDiscoveryService(s) s.RegisterHandler(id.FindServersRequest_Encoding_DefaultBinary, discovery.FindServers) s.RegisterHandler(id.FindServersOnNetworkRequest_Encoding_DefaultBinary, discovery.FindServersOnNetwork) s.RegisterHandler(id.GetEndpointsRequest_Encoding_DefaultBinary, discovery.GetEndpoints) @@ -29,43 +30,40 @@ func (s *Server) initHandlers() { // s.registerHandlerFunc(id.OpenSecureChannelRequest_Encoding_DefaultBinary, handleOpenSecureChannel) // s.registerHandlerFunc(id.CloseSecureChannelRequest_Encoding_DefaultBinary, handleCloseSecureChannel) - session := &SessionService{s} + session := NewSessionService(s) s.RegisterHandler(id.CreateSessionRequest_Encoding_DefaultBinary, session.CreateSession) s.RegisterHandler(id.ActivateSessionRequest_Encoding_DefaultBinary, session.ActivateSession) s.RegisterHandler(id.CloseSessionRequest_Encoding_DefaultBinary, session.CloseSession) s.RegisterHandler(id.CancelRequest_Encoding_DefaultBinary, session.Cancel) - node := &NodeManagementService{s} + node := NewNodeManagementService(s) s.RegisterHandler(id.AddNodesRequest_Encoding_DefaultBinary, node.AddNodes) s.RegisterHandler(id.AddReferencesRequest_Encoding_DefaultBinary, node.AddReferences) s.RegisterHandler(id.DeleteNodesRequest_Encoding_DefaultBinary, node.DeleteNodes) s.RegisterHandler(id.DeleteReferencesRequest_Encoding_DefaultBinary, node.DeleteReferences) - view := &ViewService{s} + view := NewViewService(s) s.RegisterHandler(id.BrowseRequest_Encoding_DefaultBinary, view.Browse) s.RegisterHandler(id.BrowseNextRequest_Encoding_DefaultBinary, view.BrowseNext) s.RegisterHandler(id.TranslateBrowsePathsToNodeIDsRequest_Encoding_DefaultBinary, view.TranslateBrowsePathsToNodeIDs) s.RegisterHandler(id.RegisterNodesRequest_Encoding_DefaultBinary, view.RegisterNodes) s.RegisterHandler(id.UnregisterNodesRequest_Encoding_DefaultBinary, view.UnregisterNodes) - query := &QueryService{s} + query := NewQueryService(s) s.RegisterHandler(id.QueryFirstRequest_Encoding_DefaultBinary, query.QueryFirst) s.RegisterHandler(id.QueryNextRequest_Encoding_DefaultBinary, query.QueryNext) - attr := &AttributeService{s} + attr := NewAttributeService(s) s.RegisterHandler(id.ReadRequest_Encoding_DefaultBinary, attr.Read) s.RegisterHandler(id.HistoryReadRequest_Encoding_DefaultBinary, attr.HistoryRead) s.RegisterHandler(id.WriteRequest_Encoding_DefaultBinary, attr.Write) s.RegisterHandler(id.HistoryUpdateRequest_Encoding_DefaultBinary, attr.HistoryUpdate) - method := &MethodService{s} + method := NewMethodService(s) // s.registerHandler(id.CallMethodRequest_Encoding_DefaultBinary, method.CallMethod) // todo(fs): I think this is bogus s.RegisterHandler(id.CallRequest_Encoding_DefaultBinary, method.Call) - sub := &SubscriptionService{ - srv: s, - Subs: make(map[uint32]*Subscription), - } + sub := NewSubscriptionService(s) s.SubscriptionService = sub s.RegisterHandler(id.CreateSubscriptionRequest_Encoding_DefaultBinary, sub.CreateSubscription) s.RegisterHandler(id.ModifySubscriptionRequest_Encoding_DefaultBinary, sub.ModifySubscription) @@ -75,12 +73,7 @@ func (s *Server) initHandlers() { s.RegisterHandler(id.TransferSubscriptionsRequest_Encoding_DefaultBinary, sub.TransferSubscriptions) s.RegisterHandler(id.DeleteSubscriptionsRequest_Encoding_DefaultBinary, sub.DeleteSubscriptions) - item := &MonitoredItemService{ - SubService: sub, - Items: make(map[uint32]*MonitoredItem), - Nodes: make(map[string][]*MonitoredItem), - Subs: make(map[uint32][]*MonitoredItem), - } + item := NewMonitoredItemService(sub) s.MonitoredItemService = item // s.registerHandler(id.MonitoredItemCreateRequest_Encoding_DefaultBinary, item.MonitoredItemCreate) s.RegisterHandler(id.CreateMonitoredItemsRequest_Encoding_DefaultBinary, item.CreateMonitoredItems) @@ -101,9 +94,7 @@ func (s *Server) RegisterHandler(typeID uint16, h Handler) { } func (s *Server) handleService(ctx context.Context, sc *uasc.SecureChannel, reqID uint32, req ua.Request) { - if s.cfg.logger != nil { - s.cfg.logger.Debug("handleService: Got: %T\n", req) - } + ualog.Debug(ctx, "handling service request", ualog.Any("request", req)) var resp ua.Response var err error @@ -111,12 +102,10 @@ func (s *Server) handleService(ctx context.Context, sc *uasc.SecureChannel, reqI typeID := ua.ServiceTypeID(req) h, ok := s.handlers[typeID] if ok { - resp, err = h(sc, req, reqID) + resp, err = h(ctx, sc, req, reqID) } else { if typeID == 0 { - if s.cfg.logger != nil { - s.cfg.logger.Warn("unknown service %T. Did you call register?", req) - } + ualog.Warn(ctx, "unknown (potentially non registered) service", ualog.Any("request", req)) } err = ua.StatusBadServiceUnsupported } @@ -135,9 +124,7 @@ func (s *Server) handleService(ctx context.Context, sc *uasc.SecureChannel, reqI err = sc.SendResponseWithContext(ctx, reqID, resp) if err != nil { - if s.cfg.logger != nil { - s.cfg.logger.Warn("Error sending response: %s\n", err) - } + ualog.Warn(ctx, "unable to send response", ualog.Err(err)) } } diff --git a/server/session_broker.go b/server/session_broker.go index 6d2cd783f..dbaf737cb 100644 --- a/server/session_broker.go +++ b/server/session_broker.go @@ -1,6 +1,7 @@ package server import ( + "context" mrand "math/rand" "sync" "time" @@ -8,6 +9,7 @@ import ( "github.com/google/uuid" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" ) type session struct { @@ -30,14 +32,12 @@ type sessionBroker struct { mu sync.Mutex // s contains all sessions watched by the session broker - s map[string]*session - logger Logger + s map[string]*session } -func newSessionBroker(logger Logger) *sessionBroker { +func newSessionBroker() *sessionBroker { return &sessionBroker{ - s: make(map[string]*session), - logger: logger, + s: make(map[string]*session), } } @@ -55,29 +55,28 @@ func (sb *sessionBroker) NewSession() *session { return s } -func (sb *sessionBroker) Close(authToken *ua.NodeID) error { +func (sb *sessionBroker) Close(ctx context.Context, authToken *ua.NodeID) error { sb.mu.Lock() defer sb.mu.Unlock() if sb.s[authToken.String()] == nil { - if sb.logger != nil { - sb.logger.Warn("sessionBroker.Close: error looking up session %v", authToken) - } + ualog.Warn(ctx, "unable to close session", + ualog.String(ualog.ErrorKey, "error looking up session"), + ualog.Any("token", authToken), + ) } delete(sb.s, authToken.String()) return nil } -func (sb *sessionBroker) Session(authToken *ua.NodeID) *session { +func (sb *sessionBroker) Session(ctx context.Context, authToken *ua.NodeID) *session { sb.mu.Lock() defer sb.mu.Unlock() s := sb.s[authToken.String()] if s == nil { - if sb.logger != nil { - sb.logger.Warn("sessionBroker.Session: error looking up session %v", authToken) - } + ualog.Warn(ctx, "unable to lookup session", ualog.Any("token", authToken)) } return s diff --git a/server/session_service.go b/server/session_service.go index 8a6e1439d..dcac746f5 100644 --- a/server/session_service.go +++ b/server/session_service.go @@ -1,12 +1,13 @@ package server import ( + "context" "crypto/rand" - "log" "strings" "time" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -25,11 +26,18 @@ type SessionService struct { srv *Server } -// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.6.2 -func (s *SessionService) CreateSession(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) +func NewSessionService(s *Server) *SessionService { + return &SessionService{ + srv: s, } +} + +var newSessionServiceLogAttribute = newServiceLogAttributeCreatorForSet("session") + +// https://reference.opcfoundation.org/Core/Part4/v105/docs/5.6.2 +func (s *SessionService) CreateSession(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSessionServiceLogAttribute("create")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.CreateSessionRequest](r) if err != nil { @@ -47,7 +55,7 @@ func (s *SessionService) CreateSession(sc *uasc.SecureChannel, r ua.Request, req nonce := make([]byte, sessionNonceLength) if _, err := rand.Read(nonce); err != nil { - log.Printf("error creating session nonce") + ualog.Error(ctx, "failed to create session nonce", ualog.Err(err)) return nil, ua.StatusBadInternalError } sess.serverNonce = nonce @@ -55,7 +63,7 @@ func (s *SessionService) CreateSession(sc *uasc.SecureChannel, r ua.Request, req sig, alg, err := sc.NewSessionSignature(req.ClientCertificate, req.ClientNonce) if err != nil { - log.Printf("error creating session signature") + ualog.Error(ctx, "failed to create session signature", ualog.Err(err)) return nil, ua.StatusBadInternalError } @@ -88,32 +96,29 @@ func (s *SessionService) CreateSession(sc *uasc.SecureChannel, r ua.Request, req } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.6.3 -func (s *SessionService) ActivateSession(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SessionService) ActivateSession(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSessionServiceLogAttribute("activate")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.ActivateSessionRequest](r) if err != nil { return nil, err } - sess := s.srv.sb.Session(req.RequestHeader.AuthenticationToken) + sess := s.srv.sb.Session(ctx, req.RequestHeader.AuthenticationToken) if sess == nil { return nil, ua.StatusBadSessionIDInvalid } err = sc.VerifySessionSignature(sess.remoteCertificate, sess.serverNonce, req.ClientSignature.Signature) if err != nil { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Warn("error verifying session signature with nonce: %s", err) - } + ualog.Error(ctx, "failed to verify session signature", ualog.Err(err)) return nil, ua.StatusBadSecurityChecksFailed } nonce := make([]byte, sessionNonceLength) if _, err := rand.Read(nonce); err != nil { - log.Printf("error creating session nonce") + ualog.Error(ctx, "failed to create session nonce", ualog.Err(err)) return nil, ua.StatusBadInternalError } sess.serverNonce = nonce @@ -129,17 +134,16 @@ func (s *SessionService) ActivateSession(sc *uasc.SecureChannel, r ua.Request, r } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.6.4 -func (s *SessionService) CloseSession(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SessionService) CloseSession(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSessionServiceLogAttribute("close")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.CloseSessionRequest](r) if err != nil { return nil, err } - err = s.srv.sb.Close(req.RequestHeader.AuthenticationToken) + err = s.srv.sb.Close(ctx, req.RequestHeader.AuthenticationToken) if err != nil { return nil, ua.StatusBadSessionIDInvalid } @@ -153,14 +157,14 @@ func (s *SessionService) CloseSession(sc *uasc.SecureChannel, r ua.Request, reqI } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.6.5 -func (s *SessionService) Cancel(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SessionService) Cancel(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSessionServiceLogAttribute("cancel")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.CancelRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } diff --git a/server/subscription_service.go b/server/subscription_service.go index bb3c65e0b..cfa983ee2 100644 --- a/server/subscription_service.go +++ b/server/subscription_service.go @@ -6,6 +6,7 @@ import ( "time" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -19,8 +20,17 @@ type SubscriptionService struct { Subs map[uint32]*Subscription } +func NewSubscriptionService(s *Server) *SubscriptionService { + return &SubscriptionService{ + srv: s, + Subs: make(map[uint32]*Subscription), + } +} + +var newSubscriptionServiceLogAttribute = newServiceLogAttributeCreatorForSet("subscription") + // get rid of all references to a subscription and all monitored items that are pointed at this subscription. -func (s *SubscriptionService) DeleteSubscription(id uint32) { +func (s *SubscriptionService) DeleteSubscription(ctx context.Context, id uint32) { s.Mu.Lock() defer s.Mu.Unlock() @@ -38,14 +48,12 @@ func (s *SubscriptionService) DeleteSubscription(id uint32) { // ask the monitored item service to purge out any items that use this subscription s.srv.MonitoredItemService.DeleteSub(id) - } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.13.2 -func (s *SubscriptionService) CreateSubscription(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SubscriptionService) CreateSubscription(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSubscriptionServiceLogAttribute("create")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.CreateSubscriptionRequest](r) if err != nil { @@ -57,13 +65,14 @@ func (s *SubscriptionService) CreateSubscription(sc *uasc.SecureChannel, r ua.Re newsubid := uint32(len(s.Subs)) + 1 - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Info("New Sub %d for %v", newsubid, sc.RemoteAddr()) - } + ualog.Info(ctx, "new subscription created", + ualog.Uint32("sub", newsubid), + ualog.Any("remote", sc.RemoteAddr()), + ) sub := NewSubscription() sub.srv = s - sub.Session = s.srv.Session(r.Header()) + sub.Session = s.srv.Session(ctx, r.Header()) sub.Channel = sc sub.ID = newsubid sub.RevisedPublishingInterval = req.RequestedPublishingInterval @@ -72,7 +81,7 @@ func (s *SubscriptionService) CreateSubscription(sc *uasc.SecureChannel, r ua.Re s.Subs[newsubid] = sub sub.running = true - sub.Start() + sub.Start(ctx) resp := &ua.CreateSubscriptionResponse{ ResponseHeader: &ua.ResponseHeader{ @@ -92,10 +101,9 @@ func (s *SubscriptionService) CreateSubscription(sc *uasc.SecureChannel, r ua.Re } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.13.3 -func (s *SubscriptionService) ModifySubscription(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SubscriptionService) ModifySubscription(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSubscriptionServiceLogAttribute("modify")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.ModifySubscriptionRequest](r) if err != nil { @@ -108,34 +116,31 @@ func (s *SubscriptionService) ModifySubscription(sc *uasc.SecureChannel, r ua.Re } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.13.4 -func (s *SubscriptionService) SetPublishingMode(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SubscriptionService) SetPublishingMode(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSubscriptionServiceLogAttribute("set publishing mode")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.SetPublishingModeRequest](r) if err != nil { return nil, err } + // When this gets implemented, be sure to check the subscription session vs the request session! return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.13.5 -func (s *SubscriptionService) Publish(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Raw Publish req") - } +func (s *SubscriptionService) Publish(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSubscriptionServiceLogAttribute("publish")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.PublishRequest](r) if err != nil { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Error("ERROR: bad PublishRequest Struct") - } + ualog.Error(ctx, "bad PublishRequest struct", ualog.Err(err)) return nil, err } - session := s.srv.Session(req.RequestHeader) + session := s.srv.Session(ctx, req.RequestHeader) if session == nil { response := &ua.PublishResponse{ @@ -161,9 +166,7 @@ func (s *SubscriptionService) Publish(sc *uasc.SecureChannel, r ua.Request, reqI select { case session.PublishRequests <- PubReq{Req: req, ID: reqID}: default: - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Warn("Too many publish reqs.") - } + ualog.Warn(ctx, "too many publish requests") } // per opcua spec, we don't respond now. When data is available on the subscription, @@ -172,43 +175,42 @@ func (s *SubscriptionService) Publish(sc *uasc.SecureChannel, r ua.Request, reqI } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.13.6 -func (s *SubscriptionService) Republish(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SubscriptionService) Republish(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSubscriptionServiceLogAttribute("republish")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.RepublishRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.13.7 -func (s *SubscriptionService) TransferSubscriptions(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SubscriptionService) TransferSubscriptions(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSubscriptionServiceLogAttribute("transfer")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.TransferSubscriptionsRequest](r) if err != nil { return nil, err } + // When this gets implemented, be sure to check the subscription session vs the request session! return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.13.8 -func (s *SubscriptionService) DeleteSubscriptions(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *SubscriptionService) DeleteSubscriptions(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newSubscriptionServiceLogAttribute("delete")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.DeleteSubscriptionsRequest](r) if err != nil { return nil, err } - session := s.srv.Session(req.Header()) + session := s.srv.Session(ctx, req.Header()) s.Mu.Lock() defer s.Mu.Unlock() @@ -217,9 +219,7 @@ func (s *SubscriptionService) DeleteSubscriptions(sc *uasc.SecureChannel, r ua.R for i := range req.SubscriptionIDs { subid := req.SubscriptionIDs[i] - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Info("Subscription %d deleted by client", subid) - } + ualog.Info(ctx, "subscription deleted by client", ualog.Uint32("sub", subid)) sub, ok := s.Subs[subid] if !ok { results[i] = ua.StatusBadSubscriptionIDInvalid @@ -231,7 +231,7 @@ func (s *SubscriptionService) DeleteSubscriptions(sc *uasc.SecureChannel, r ua.R } // delete subscription gets the lock so we set them up to run in the background // once this function releases its lock - go s.DeleteSubscription(subid) + go s.DeleteSubscription(ctx, subid) results[i] = ua.StatusOK } return &ua.DeleteSubscriptionsResponse{ @@ -299,9 +299,9 @@ func (s *Subscription) Update(req *ua.ModifySubscriptionRequest) { s.RevisedMaxKeepAliveCount = req.RequestedMaxKeepAliveCount } -func (s *Subscription) Start() { - go s.run() - +func (s *Subscription) Start(ctx context.Context) { + ctx = ualog.WithAttrs(ctx, ualog.Uint32("sub", s.ID)) + go s.run(ctx) } func (s *Subscription) keepalive(pubreq PubReq) error { @@ -339,13 +339,11 @@ func (s *Subscription) keepalive(pubreq PubReq) error { // this function should be run as a go-routine and will handle sending data out // to the client at the correct rate assuming there are publish requests queued up. // if the function returns it deletes the subscription -func (s *Subscription) run() { +func (s *Subscription) run(ctx context.Context) { // if this go routine dies, we need to delete ourselves. defer func() { - if s.srv.srv.cfg.logger != nil { - s.srv.srv.cfg.logger.Info("Subscription %d shutting down.", s.ID) - } - s.srv.DeleteSubscription(s.ID) + ualog.Info(ctx, "subscription shutting down") + s.srv.DeleteSubscription(ctx, s.ID) }() keepalive_counter := 0 @@ -389,17 +387,13 @@ func (s *Subscription) run() { case pubreq := <-s.Session.PublishRequests: err := s.keepalive(pubreq) if err != nil { - if s.srv.srv.cfg.logger != nil { - s.srv.srv.cfg.logger.Warn("problem sending keepalive to subscription #%d: %v", s.ID, err) - } + ualog.Warn(ctx, "problem sending keepalive to subscription", ualog.Err(err)) return } default: lifetime_counter++ if lifetime_counter > int(s.RevisedLifetimeCount) { - if s.srv.srv.cfg.logger != nil { - s.srv.srv.cfg.logger.Warn("Subscription #%d timed out.", s.ID) - } + ualog.Warn(ctx, "subscription timed out") return } } @@ -430,9 +424,7 @@ func (s *Subscription) run() { // we had another tick without a publish request. lifetime_counter++ if lifetime_counter > int(s.RevisedLifetimeCount) { - if s.srv.srv.cfg.logger != nil { - s.srv.srv.cfg.logger.Warn("Subscription %d timed out.", s.ID) - } + ualog.Warn(ctx, "subscription timed out") return } } @@ -445,9 +437,9 @@ func (s *Subscription) run() { // per the spec, the sequence ID cannot be 0 s.SequenceID = 1 } - if s.srv.srv.cfg.logger != nil { - s.srv.srv.cfg.logger.Debug("Got publish req on sub #%d. Sequence %d", s.ID, s.SequenceID) - } + + ualog.Debug(ctx, "got publish request", ualog.Uint32("sequence", s.SequenceID)) + // then get all the tags and send them back to the client //for x := range pubreq.Req.SubscriptionAcknowledgements { @@ -495,15 +487,13 @@ func (s *Subscription) run() { } err := s.Channel.SendResponseWithContext(context.Background(), pubreq.ID, response) if err != nil { - if s.srv.srv.cfg.logger != nil { - s.srv.srv.cfg.logger.Error("problem sending channel response: %v", err) - s.srv.srv.cfg.logger.Error("Killing subscription %d", s.ID) - } + ualog.Error(ctx, "problem sending channel response", ualog.Err(err)) + ualog.Error(ctx, "killing subscription") return } - if s.srv.srv.cfg.logger != nil { - s.srv.srv.cfg.logger.Debug("Published %d items OK for %d", len(publishQueue), s.ID) - } + + ualog.Debug(ctx, "published items", ualog.Int("count", len(publishQueue))) + // wait till we've got a publish request. } } diff --git a/server/view_service.go b/server/view_service.go index 094d1ba24..ead5647bb 100644 --- a/server/view_service.go +++ b/server/view_service.go @@ -1,11 +1,13 @@ package server import ( + "context" "slices" "time" "github.com/gopcua/opcua/id" "github.com/gopcua/opcua/ua" + "github.com/gopcua/opcua/ualog" "github.com/gopcua/opcua/uasc" ) @@ -20,16 +22,23 @@ type ViewService struct { srv *Server } +func NewViewService(s *Server) *ViewService { + return &ViewService{ + srv: s, + } +} + +var newViewServiceLogAttribute = newServiceLogAttributeCreatorForSet("view") + // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.8.2 -func (s *ViewService) Browse(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { +func (s *ViewService) Browse(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newViewServiceLogAttribute("browse")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.BrowseRequest](r) if err != nil { return nil, err } - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("=== Browse incoming") - } resp := &ua.BrowseResponse{ ResponseHeader: &ua.ResponseHeader{ @@ -47,38 +56,30 @@ func (s *ViewService) Browse(sc *uasc.SecureChannel, r ua.Request, reqID uint32) for i := range req.NodesToBrowse { br := req.NodesToBrowse[i] - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug(" Browse of %s", br.NodeID.String()) - } + ualog.Debug(ctx, "browsing node", ualog.Any(ualog.NodeIdKey, br.NodeID)) + ns, err := s.srv.Namespace(int(br.NodeID.Namespace())) if err != nil { resp.Results[i] = &ua.BrowseResult{StatusCode: ua.StatusBad} continue } - resp.Results[i] = ns.Browse(br) + resp.Results[i] = ns.Browse(ctx, br) } return resp, nil - } -func suitableRef(srv *Server, desc *ua.BrowseDescription, ref *ua.ReferenceDescription) bool { +func suitableRef(ctx context.Context, srv *Server, desc *ua.BrowseDescription, ref *ua.ReferenceDescription) bool { if !suitableDirection(desc.BrowseDirection, ref.IsForward) { - if srv.cfg.logger != nil { - srv.cfg.logger.Debug("%v not suitable because of direction", ref) - } + ualog.Debug(ctx, "reference not suitable because of direction", ualog.Any("ref", ref)) return false } if !suitableRefType(srv, desc.ReferenceTypeID, ref.ReferenceTypeID, desc.IncludeSubtypes) { - if srv.cfg.logger != nil { - srv.cfg.logger.Debug("%v not suitable because of ref type", ref) - } + ualog.Debug(ctx, "reference not suitable because of type", ualog.Any("ref", ref)) return false } if desc.NodeClassMask > 0 && desc.NodeClassMask&uint32(ref.NodeClass) == 0 { - if srv.cfg.logger != nil { - srv.cfg.logger.Debug("%v not suitable because of node class", ref) - } + ualog.Debug(ctx, "reference not suitable because of node class", ualog.Any("ref", ref)) return false } return true @@ -137,53 +138,53 @@ func getSubRefs(srv *Server, nid *ua.NodeID) []*ua.NodeID { } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.8.3 -func (s *ViewService) BrowseNext(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *ViewService) BrowseNext(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newViewServiceLogAttribute("browse next")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.BrowseNextRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.8.4 -func (s *ViewService) TranslateBrowsePathsToNodeIDs(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *ViewService) TranslateBrowsePathsToNodeIDs(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newViewServiceLogAttribute("translate browse paths to node ids")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.TranslateBrowsePathsToNodeIDsRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.8.5 -func (s *ViewService) RegisterNodes(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *ViewService) RegisterNodes(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newViewServiceLogAttribute("register nodes")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.RegisterNodesRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } // https://reference.opcfoundation.org/Core/Part4/v105/docs/5.8.6 -func (s *ViewService) UnregisterNodes(sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { - if s.srv.cfg.logger != nil { - s.srv.cfg.logger.Debug("Handling %T", r) - } +func (s *ViewService) UnregisterNodes(ctx context.Context, sc *uasc.SecureChannel, r ua.Request, reqID uint32) (ua.Response, error) { + ctx = ualog.WithAttrs(ctx, newViewServiceLogAttribute("unregister nodes")) + logServiceRequest(ctx, r) req, err := safeReq[*ua.UnregisterNodesRequest](r) if err != nil { return nil, err } + return serviceUnsupported(req.RequestHeader), nil } diff --git a/tests/go/generate_cert.go b/tests/go/generate_cert.go index 0f19c155e..0ca558453 100644 --- a/tests/go/generate_cert.go +++ b/tests/go/generate_cert.go @@ -75,7 +75,7 @@ func GenerateCert(host string, rsaBits int, validFor time.Duration) (certPEM, ke derBytes, err := x509.CreateCertificate(rand.Reader, &template, &template, publicKey(priv), priv) if err != nil { - return nil, nil, fmt.Errorf("Failed to create certificate: %s", err) + return nil, nil, fmt.Errorf("failed to create certificate: %s", err) } return pem.EncodeToMemory(&pem.Block{Type: "CERTIFICATE", Bytes: derBytes}), pem.EncodeToMemory(pemBlockForKey(priv)), nil diff --git a/tests/go/server.go b/tests/go/server.go index 6f9c719e2..1d288f873 100644 --- a/tests/go/server.go +++ b/tests/go/server.go @@ -14,7 +14,7 @@ import ( "github.com/gopcua/opcua/ua" ) -func startServer() *server.Server { +func startServer(ctx context.Context) *server.Server { var opts []server.Option port := 4840 @@ -43,7 +43,7 @@ func startServer() *server.Server { server.EndPoint("localhost", port), ) - s := server.New(opts...) + s := server.New(ctx, opts...) root_ns, _ := s.Namespace(0) obj_node := root_ns.Objects() @@ -133,7 +133,7 @@ func startServer() *server.Server { // Create a new node namespace. You can add namespaces before or after starting the server. // Start the server - if err := s.Start(context.Background()); err != nil { + if err := s.Start(ctx); err != nil { log.Fatalf("Error starting server, exiting: %s", err) } return s diff --git a/tests/go/stats_test.go b/tests/go/stats_test.go index fc4db025a..9abf4e8c7 100644 --- a/tests/go/stats_test.go +++ b/tests/go/stats_test.go @@ -22,8 +22,8 @@ func TestStats(t *testing.T) { ctx := context.Background() - srv := startServer() - defer srv.Close() + srv := startServer(ctx) + defer srv.Close(ctx) c, err := opcua.NewClient("opc.tcp://localhost:4840", opcua.SecurityMode(ua.MessageSecurityModeNone)) require.NoError(t, err, "NewClient failed") diff --git a/ualog/attributes.go b/ualog/attributes.go new file mode 100644 index 000000000..6a46f2380 --- /dev/null +++ b/ualog/attributes.go @@ -0,0 +1,81 @@ +package ualog + +import ( + "log/slog" + "time" +) + +var ( + // ErrorKey is used as the key when ualog.Err creates a String attribute for err.Error() + ErrorKey string = "err" + // NodeIdKey should be used when logging the id of a ua.Node + // + // This avoids the use of "node", "node_id", "id" in different places. + NodeIdKey string = "node_id" +) + +// An Attr is a key-value pair +type Attr slog.Attr + +// Any returns an Attr for the supplied value +var Any = func(key string, value any) Attr { + return Attr(slog.Any(key, value)) +} + +// Bitmask wraps a log valuer that formats a bitmask on demand +var Bitmask = func(key string, value uint32) Attr { + return Attr(slog.Any(key, logmask{value: value})) +} + +// Duration returns an Attr for a [time.Duration] +var Duration = func(key string, value time.Duration) Attr { + return Attr(slog.Duration(key, value)) +} + +// Int converts an int to an int64 and returns an Attr with that value +var Int = func(key string, value int) Attr { + return Attr(slog.Int(key, value)) +} + +// Uint64 returns an Attr for a uint64 +var Uint64 = func(key string, value uint64) Attr { + return Attr(slog.Uint64(key, value)) +} + +// Uint32 converts a uint32 to a uint64 and returns an Attr for that value +var Uint32 = func(key string, value uint32) Attr { + return Uint64(key, uint64(value)) +} + +// String returns an Attr for a string value +var String = func(key, value string) Attr { + return Attr(slog.String(key, value)) +} + +// Namespace takes a namespace id and returns a Uint32 +// Attr with the key "namespace" +var Namespace = func(namespaceId uint16) Attr { + return Uint32("namespace", uint32(namespaceId)) +} + +// GroupAttrs returns a single Attr for a group consisting of +// the given Attrs +var GroupAttrs = func(key string, args ...Attr) Attr { + slogAttrs := make([]slog.Attr, 0, len(args)) + for argIdx := range len(args) { + slogAttrs = append(slogAttrs, slog.Attr(args[argIdx])) + } + + return Attr(slog.GroupAttrs(key, slogAttrs...)) +} + +// Err takes an error and returns a String attr with the key +// ualog.ErrorKey and the value given by err.Error(). If err +// is nil, the Attr value will be the empty string. +var Err = func(err error) Attr { + var errorMessage string + if err != nil { + errorMessage = err.Error() + } + return String(ErrorKey, errorMessage) +} diff --git a/ualog/config.go b/ualog/config.go new file mode 100644 index 000000000..f5743e219 --- /dev/null +++ b/ualog/config.go @@ -0,0 +1,45 @@ +package ualog + +import ( + "context" + "log/slog" +) + +type config struct { + logger *slog.Logger +} + +func newConfig() *config { + return &config{ + logger: slog.Default(), + } +} + +func newContextFromConfig(ctx context.Context, cfg *config) context.Context { + return newContext(ctx, cfg.logger) +} + +type option func(*config) + +// WithErrorKey replaces the default error message key with the supplied value +func WithErrorKey(key string) option { + return func(_ *config) { + ErrorKey = key + } +} + +// WithHandler allows ualog to create a new logger directly from the supplied +// [log/slog.Handler] +func WithHandler(h slog.Handler) option { + return func(c *config) { + c.logger = slog.New(h) + } +} + +// WithLogger is an option that can be used when the caller wants to create a new +// ualog logger based on an already decorated [log/slog.Logger] +func WithLogger(l *slog.Logger) option { + return func(c *config) { + c.logger = l + } +} diff --git a/ualog/context.go b/ualog/context.go new file mode 100644 index 000000000..8e0bc8799 --- /dev/null +++ b/ualog/context.go @@ -0,0 +1,24 @@ +package ualog + +import ( + "context" + "log/slog" +) + +type keyType struct{} + +var loggerKey = keyType{} + +func newContext(ctx context.Context, logger *slog.Logger, args ...any) context.Context { + return context.WithValue(ctx, loggerKey, logger.With(args...)) +} + +func fromContext(ctx context.Context) *slog.Logger { + logger, ok := ctx.Value(loggerKey).(*slog.Logger) + + if !ok { + return slog.Default() + } + + return logger +} diff --git a/ualog/doc.go b/ualog/doc.go new file mode 100644 index 000000000..e45546816 --- /dev/null +++ b/ualog/doc.go @@ -0,0 +1,14 @@ +/* +Package ualog works as a facade towards the underlying logging framework. + +It provides the opcua library with convenient structured logging, without exposing +the actual underlying logging framework to the library code. + +# Basics + +The ualog logger lives within the [context.Context] that is passed between functions +and is initialized by calling the ualog.New constructor that allows the instance to +be configured using the option pattern. If a logger isn't explicitly created, logging +will be performed using the current system default logger. +*/ +package ualog diff --git a/ualog/logger.go b/ualog/logger.go new file mode 100644 index 000000000..5c1d54fd4 --- /dev/null +++ b/ualog/logger.go @@ -0,0 +1,38 @@ +package ualog + +import ( + "context" + "log/slog" +) + +func New(ctx context.Context, opts ...option) context.Context { + cfg := newConfig() + + for _, opt := range opts { + opt(cfg) + } + + return newContextFromConfig(ctx, cfg) +} + +func log(ctx context.Context, logger *slog.Logger, level slog.Level, msg string, args ...Attr) { + switch len(args) { + case 0: + logger.LogAttrs(ctx, level, msg) + case 1: + logger.LogAttrs(ctx, level, msg, slog.Attr(args[0])) + case 2: + logger.LogAttrs(ctx, level, msg, slog.Attr(args[0]), slog.Attr(args[1])) + case 3: + logger.LogAttrs(ctx, level, msg, slog.Attr(args[0]), slog.Attr(args[1]), slog.Attr(args[2])) + case 4: + logger.LogAttrs(ctx, level, msg, slog.Attr(args[0]), slog.Attr(args[1]), slog.Attr(args[2]), slog.Attr(args[3])) + default: + slogAttrs := make([]slog.Attr, 0, len(args)) + for argIdx := range len(args) { + attr := slog.Attr(args[argIdx]) + slogAttrs = append(slogAttrs, attr) + } + logger.LogAttrs(ctx, level, msg, slogAttrs...) + } +} diff --git a/ualog/ualog.go b/ualog/ualog.go new file mode 100644 index 000000000..fd790fd89 --- /dev/null +++ b/ualog/ualog.go @@ -0,0 +1,57 @@ +package ualog + +import ( + "context" + "log/slog" +) + +// Debug forwards the provided message and attributes to the current logger +// iff its handler's debug level is enabled +func Debug(ctx context.Context, msg string, attrs ...Attr) { + logger := fromContext(ctx) + if logger.Handler().Enabled(ctx, slog.LevelDebug) { + log(ctx, fromContext(ctx), slog.LevelDebug, msg, attrs...) + } +} + +// DebugFunc forwards the provided message and attributes, retrieved from the attrs callback, +// to the current logger iff its handler's debug level is enabled. +// +// This debug method allows the deferal of log attribute creation to only happen when +// they will actually be used. The result is a reduced performace penalty in non debug modes. +func DebugFunc(ctx context.Context, msg string, attrs func() []Attr) { + logger := fromContext(ctx) + if logger.Handler().Enabled(ctx, slog.LevelDebug) { + log(ctx, logger, slog.LevelDebug, msg, attrs()...) + } +} + +// Error forwards the provided message and attributes to the current logger +func Error(ctx context.Context, msg string, attrs ...Attr) { + log(ctx, fromContext(ctx), slog.LevelError, msg, attrs...) +} + +// Info forwards the provided message and attributes to the current logger +func Info(ctx context.Context, msg string, attrs ...Attr) { + log(ctx, fromContext(ctx), slog.LevelInfo, msg, attrs...) +} + +// Warn forwards the provided message and attributes to the current logger +func Warn(ctx context.Context, msg string, attrs ...Attr) { + log(ctx, fromContext(ctx), slog.LevelWarn, msg, attrs...) +} + +// WithAttrs takes a context and decorates its current logger using the supplied +// ualog Attr values +func WithAttrs(ctx context.Context, attrs ...Attr) context.Context { + + if attrCount := len(attrs); attrCount > 0 { + logger := fromContext(ctx) + for attrIdx := range attrCount { + logger = logger.With(slog.Attr(attrs[attrIdx])) + } + ctx = newContext(ctx, logger) + } + + return ctx +} diff --git a/ualog/ualog_test.go b/ualog/ualog_test.go new file mode 100644 index 000000000..dbb09a91f --- /dev/null +++ b/ualog/ualog_test.go @@ -0,0 +1,74 @@ +package ualog_test + +import ( + "context" + "errors" + "log/slog" + "os" + + "github.com/gopcua/opcua/ualog" +) + +func ExampleNew() { + handler := slog.NewTextHandler(os.Stdout, testLogOpts()) + ctx := ualog.New(context.Background(), ualog.WithHandler(handler)) + + ualog.Info(ctx, "hello, world!") + + // Output: level=INFO msg="hello, world!" +} + +func ExampleNew_json() { + handler := slog.NewJSONHandler(os.Stdout, testLogOpts()) + ctx := ualog.New(context.Background(), ualog.WithHandler(handler)) + + ualog.Info(ctx, "hello, world!") + + // Output: {"level":"INFO","msg":"hello, world!"} +} + +func ExampleNew_fromlogger() { + handler := slog.NewJSONHandler(os.Stdout, testLogOpts()) + logger := slog.New(handler).With("foo", "bar") + + ctx := ualog.New(context.Background(), ualog.WithLogger(logger)) + + ualog.Info(ctx, "hello, world!") + + // Output: {"level":"INFO","msg":"hello, world!","foo":"bar"} +} + +func ExampleError() { + handler := slog.NewJSONHandler(os.Stdout, testLogOpts()) + ctx := ualog.New(context.Background(), ualog.WithHandler(handler)) + + err := errors.New("critical reactor core failure") + ualog.Error(ctx, "whoopsi daisies", ualog.Err(err)) + + // {"level":"ERROR","msg":"whoopsi daisies","err":"critical reactor core failure"} +} + +func ExampleWithErrorKey() { + handler := slog.NewTextHandler(os.Stdout, testLogOpts()) + ctx := ualog.New(context.Background(), ualog.WithHandler(handler), + ualog.WithErrorKey("oops"), + ) + + err := errors.New("unknown error") + ualog.Error(ctx, "something went wrong", ualog.Err(err)) + + // Output: level=ERROR msg="something went wrong" oops="unknown error" +} + +// testLogOpts returns a handler options instance that removes the time +// from log records to make the test output predictable +func testLogOpts() *slog.HandlerOptions { + return &slog.HandlerOptions{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey && len(groups) == 0 { + return slog.Attr{} + } + return a + }, + } +} diff --git a/ualog/valuers.go b/ualog/valuers.go new file mode 100644 index 000000000..948bb0422 --- /dev/null +++ b/ualog/valuers.go @@ -0,0 +1,19 @@ +package ualog + +import ( + "fmt" + "log/slog" +) + +// logmask implements the slog.LogValuer interface that makes it possible +// to defer the string formatting of the bitmask until it is actually +// requested by the logger +type logmask struct { + value uint32 +} + +func (m logmask) LogValue() slog.Value { + return slog.StringValue(fmt.Sprintf("%08d", m.value)) +} + +var _ slog.LogValuer = &logmask{}