Improve the way the Go client logs messages (#125)

* Minor test updates
* Improve the way the Go client logs messages
* Minor comment
* Add test for log levels
* Correctly reset log writer
* Bump version

Author: Tim Middleton

Makefile

@@ -8,7 +8,7 @@
 # ----------------------------------------------------------------------------------------------------------------------
 
 # This is the version of the coherence-go-client
-VERSION ?=2.1.0
+VERSION ?=2.2.0
 CURRDIR := $(shell pwd)
 USER_ID := $(shell echo "`id -u`:`id -g`")
 

README.md

@@ -44,7 +44,7 @@ For local development, we recommend using the Coherence CE Docker image; it cont
 everything necessary for the client to operate correctly.
 
 ```bash
-docker run -d -p 1408:1408 -p 30000:30000 ghcr.io/oracle/coherence-ce:24.09.3
+docker run -d -p 1408:1408 -p 30000:30000 ghcr.io/oracle/coherence-ce:25.03.1
 ```
 
 ## Installation

coherence/common.go

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2024 Oracle and/or its affiliates.
+ * Copyright (c) 2022, 2025 Oracle and/or its affiliates.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * https://oss.oracle.com/licenses/upl.
  */
@@ -35,13 +35,13 @@ const (
 	envDisconnectTimeout  = "COHERENCE_SESSION_DISCONNECT_TIMEOUT"
 	envReadyTimeout       = "COHERENCE_READY_TIMEOUT"
 
-	// envSessionDebug enables session debug messages to be displayed.
+	// envSessionDebug enables session debug messages to be displayed. Deprecated, use COHERENCE_LOG_LEVEL=DEBUG instead.
 	envSessionDebug = "COHERENCE_SESSION_DEBUG"
 
-	// envMessageDebug enables message debug messages to be displayed.
+	// envMessageDebug enables message debug messages to be displayed. Deprecated, use COHERENCE_LOG_LEVEL=ALL instead.
 	envMessageDebug = "COHERENCE_MESSAGE_DEBUG"
 
-	// envResolverDebug enables resolver debug messages to be displayed.
+	// envResolverDebug enables resolver debug messages to be displayed. Deprecated, use COHERENCE_LOG_LEVEL=DEBUG instead.
 	envResolverDebug = "COHERENCE_RESOLVER_DEBUG"
 
 	// envResolverDebug sets the number of retries when the resolver fails.
@@ -50,6 +50,9 @@ const (
 	// envResolverDebug enables randomization of addresses returned by resolver
 	envResolverRandomize = "COHERENCE_RESOLVER_RANDOMIZE"
 
+	// the Coherence log level: 1 -> 5 (ERROR -> ALL)
+	envLogLevel = "COHERENCE_LOG_LEVEL"
+
 	// Integer.MAX_VALUE on Java
 	integerMaxValue = 2147483647
 

coherence/doc.go

@@ -99,6 +99,27 @@ You also have the ability to control maximum amount of time, in milliseconds, a
 without successfully reconnecting. For this you use the option [coherence.WithDisconnectTimeout] or the environment
 variable COHERENCE_SESSION_DISCONNECT_TIMEOUT.
 
+# Setting Log Levels
+
+The Coherence Go client supports setting the following log levels to change verbosity of messages output.
+The default level is 'INFO' and this can be changed by setting the environment variable COHERENCE_LOG_LEVEL to one of the following values:
+
+- ERROR
+
+- WARNING
+
+- INFO
+
+- DEBUG
+
+- ALL
+
+All messages at and above the level are displayed. For example setting to WARNING will only show ERROR and WARNING messages.
+Where as setting DEBUG, will show ERROR, WARNING, INFO and DEBUG messages.
+
+Note: Setting to ALL should only be used to diagnose issues as directed by Oracle Support. This level will
+output a large volume of messages.
+
 # Obtaining a NamedMap or NamedCache
 
 Once a session has been created, the [GetNamedMap](session, name, ...options) or [GetNamedCache](session, name, ...options)

coherence/log_level_test.go

@@ -0,0 +1,67 @@
+/*
+ * Copyright (c) 2025 Oracle and/or its affiliates.
+ * Licensed under the Universal Permissive License v 1.0 as shown at
+ * https://oss.oracle.com/licenses/upl.
+ */
+
+package coherence
+
+import (
+	"bytes"
+	"github.com/onsi/gomega"
+	"log"
+	"testing"
+)
+
+func TestErrorLogLevel(t *testing.T) {
+	runLogLevelTest(t, ERROR, ERROR, true)
+	runLogLevelTest(t, WARNING, ERROR, false)
+	runLogLevelTest(t, INFO, ERROR, false)
+	runLogLevelTest(t, DEBUG, ERROR, false)
+	runLogLevelTest(t, ALL, ERROR, false)
+
+	runLogLevelTest(t, ERROR, WARNING, true)
+	runLogLevelTest(t, WARNING, WARNING, true)
+	runLogLevelTest(t, INFO, WARNING, false)
+	runLogLevelTest(t, DEBUG, WARNING, false)
+	runLogLevelTest(t, ALL, WARNING, false)
+
+	runLogLevelTest(t, ERROR, INFO, true)
+	runLogLevelTest(t, WARNING, INFO, true)
+	runLogLevelTest(t, INFO, INFO, true)
+	runLogLevelTest(t, DEBUG, INFO, false)
+	runLogLevelTest(t, ALL, INFO, false)
+
+	runLogLevelTest(t, ERROR, DEBUG, true)
+	runLogLevelTest(t, WARNING, DEBUG, true)
+	runLogLevelTest(t, INFO, DEBUG, true)
+	runLogLevelTest(t, DEBUG, DEBUG, true)
+	runLogLevelTest(t, ALL, DEBUG, false)
+
+	runLogLevelTest(t, ERROR, ALL, true)
+	runLogLevelTest(t, WARNING, ALL, true)
+	runLogLevelTest(t, INFO, ALL, true)
+	runLogLevelTest(t, DEBUG, ALL, true)
+	runLogLevelTest(t, ALL, ALL, true)
+}
+
+func runLogLevelTest(t *testing.T, messageLevel, testLogLevel logLevel, expectOutput bool) {
+	g := gomega.NewWithT(t)
+	const message = "MESSAGE"
+
+	var buf bytes.Buffer
+
+	origOutput := log.Writer()
+	log.SetOutput(&buf)
+	defer log.SetOutput(origOutput)
+	setLogLevel(testLogLevel.String())
+
+	logMessage(messageLevel, message)
+	output := buf.String()
+
+	if expectOutput {
+		g.Expect(output).To(gomega.ContainSubstring(message))
+	} else {
+		g.Expect(output).To(gomega.Not(gomega.ContainSubstring(message)))
+	}
+}

coherence/named_map_client.go

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2024 Oracle and/or its affiliates.
+ * Copyright (c) 2022, 2025 Oracle and/or its affiliates.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * https://oss.oracle.com/licenses/upl.
  */
@@ -14,7 +14,6 @@ import (
 	"github.com/oracle/coherence-go-client/v2/coherence/extractors"
 	"github.com/oracle/coherence-go-client/v2/coherence/filters"
 	"github.com/oracle/coherence-go-client/v2/coherence/processors"
-	"log"
 	"sync"
 	"time"
 )
@@ -456,7 +455,7 @@ func (nm *NamedMapClient[K, V]) Release() {
 	if nm.baseClient.nearCacheListener != nil {
 		err := nm.RemoveListener(context.Background(), nm.baseClient.nearCacheListener.listener)
 		if err != nil {
-			log.Printf("unable to remove listener to near cache: %v", err)
+			logMessage(WARNING, "unable to remove listener to near cache: %v", err)
 		}
 	}
 
@@ -995,7 +994,7 @@ func newNamedMapReconnectListener[K comparable, V any](nm NamedMapClient[K, V])
 		// re-register listeners for the NamedMap
 		namedMap := convertNamedMapClient[K, V](&nm)
 		if err := reRegisterListeners[K, V](context.Background(), &namedMap, nm.baseClient); err != nil {
-			log.Println(err)
+			logMessage(WARNING, "unable to re-register listeners: %v", err)
 		}
 	})
 
@@ -1057,7 +1056,7 @@ func newNearNamedMapMapLister[K comparable, V any](nc NamedMapClient[K, V], cach
 	listener.listener.OnAny(func(e MapEvent[K, V]) {
 		err := processNearCacheEvent(nc.baseClient.nearCache, e)
 		if err != nil {
-			log.Println("Error processing near cache MapEvent", e)
+			logMessage(WARNING, "Error processing near cache MapEvent: %v", e)
 		}
 	})
 

coherence/resolver.go

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2024 Oracle and/or its affiliates.
+ * Copyright (c) 2022, 2025 Oracle and/or its affiliates.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * https://oss.oracle.com/licenses/upl.
  */
@@ -219,10 +219,13 @@ func parseNsLookupString(addresses string) ([]string, error) {
 }
 
 func checkResolverDebug() {
-	if getBoolValueFromEnvVarOrDefault(envResolverDebug, false) {
+	if getBoolValueFromEnvVarOrDefault(envResolverDebug, false) || currentLogLevel >= int(DEBUG) {
 		// enable session debugging
 		resolverDebug = func(s string, v ...any) {
 			logMessage(DEBUG, s, v...)
 		}
+		if currentLogLevel <= int(DEBUG) {
+			currentLogLevel = int(DEBUG)
+		}
 	}
 }

coherence/session.go

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022, 2024 Oracle and/or its affiliates.
+ * Copyright (c) 2022, 2025 Oracle and/or its affiliates.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * https://oss.oracle.com/licenses/upl.
  */
@@ -20,7 +20,6 @@ import (
 	"google.golang.org/grpc/credentials/insecure"
 	"google.golang.org/grpc/resolver"
 	"google.golang.org/grpc/status"
-	"log"
 	"os"
 	"reflect"
 	"strconv"
@@ -72,9 +71,8 @@ type Session struct {
 	connectMutex          sync.RWMutex         // mutes for connection attempts
 	firstConnectAttempted bool                 // indicates if the first connection has been attempted
 	hasConnected          bool                 // indicates if the session has ever connected
-	debug                 func(string, ...any) // a function to output debug messages
-	debugConnection       func(string, ...any) // a function to output debug messages for gRPCV1 connections
-	messageDebugMode      string               // either "on" or "full"
+	debug                 func(string, ...any) // a function to output DEBUG messages
+	debugConnection       func(string, ...any) // a function to output ALL messages for gRPCV1 connections
 	requestID             int64                // request id for gRPC v1
 	filterID              int64                // filter id for gRPC v1
 	v1StreamManagerCache  *streamManagerV1
@@ -192,24 +190,26 @@ func NewSession(ctx context.Context, options ...func(session *SessionOptions)) (
 	// ensure name resolver has been registered
 	resolver.Register(&nsLookupResolverBuilder{})
 
-	if getBoolValueFromEnvVarOrDefault(envSessionDebug, false) {
+	// set the coherenceLogLevel
+	setLogLevel(getStringValueFromEnvVarOrDefault(envLogLevel, "3"))
+
+	if getBoolValueFromEnvVarOrDefault(envSessionDebug, false) || currentLogLevel >= int(DEBUG) {
 		// enable session debugging
 		session.debug = func(format string, v ...any) {
 			logMessage(DEBUG, format, v...)
 		}
+		if currentLogLevel <= int(DEBUG) {
+			currentLogLevel = int(DEBUG)
+		}
 	}
 
 	messageDebug := getStringValueFromEnvVarOrDefault(envMessageDebug, "")
-	if messageDebug != "" {
+	if messageDebug != "" || currentLogLevel == int(ALL) {
 		// enable session debugging
 		session.debugConnection = func(s string, v ...any) {
-			msg := getLogMessage(DEBUG, s, v...)
-			if session.messageDebugMode == "on" && len(msg) > 256 {
-				msg = msg[:256]
-			}
-			log.Println(msg)
+			logMessage(DEBUG, s, v...)
 		}
-		session.messageDebugMode = messageDebug
+		currentLogLevel = int(ALL)
 	}
 
 	// apply any options
@@ -257,6 +257,37 @@ func NewSession(ctx context.Context, options ...func(session *SessionOptions)) (
 	return session, session.ensureConnection()
 }
 
+// setLogLevel sets the log level from the COHERENCE_LOG_LEVEL environment variable.
+func setLogLevel(envLevel string) {
+	var level int
+
+	// try to convert from integer first
+	if lvl, err := strconv.Atoi(envLevel); err == nil {
+		if lvl >= 1 && lvl <= 5 {
+			currentLogLevel = lvl
+			return
+		}
+	}
+
+	// fall-through, check for string values
+	switch envLevel {
+	case "ERROR":
+		level = 1
+	case "WARNING":
+		level = 2
+	case "INFO":
+		level = 3
+	case "DEBUG":
+		level = 4
+	case "ALL":
+		level = 5
+	default:
+		level = 3 // INFO
+	}
+
+	currentLogLevel = level
+}
+
 func getTimeoutValue(envVar, defaultValue, description string) (time.Duration, error) {
 	timeoutString := getStringValueFromEnvVarOrDefault(envVar, defaultValue)
 	timeout, err := strconv.ParseInt(timeoutString, 10, 64)
@@ -418,7 +449,7 @@ func (s *Session) Close() {
 			return newSessionLifecycleEvent(s, Closed)
 		})
 		if err != nil {
-			log.Printf("unable to close session %s %v", s.sessionID, err)
+			logMessage(WARNING, "unable to close session %s %v", s.sessionID, err)
 		}
 	} else {
 		defer s.mapMutex.Unlock()
@@ -753,7 +784,7 @@ func (s *SessionOptions) createTLSOption() (grpc.DialOption, error) {
 	// check if a tls.Config has been set and use this, otherwise continue to check for env and other options
 	if s.TlSConfig != nil {
 		if s.TlSConfig.InsecureSkipVerify {
-			log.Println(insecureWarning)
+			logMessage(WARNING, insecureWarning)
 		}
 		return grpc.WithTransportCredentials(credentials.NewTLS(s.TlSConfig)), nil
 	}
@@ -774,7 +805,7 @@ func (s *SessionOptions) createTLSOption() (grpc.DialOption, error) {
 
 	ignoreInvalidCerts := ignoreInvalidCertsEnv == "true"
 	if ignoreInvalidCerts {
-		log.Println(insecureWarning)
+		logMessage(WARNING, insecureWarning)
 	}
 	s.IgnoreInvalidCerts = ignoreInvalidCerts
 
@@ -801,7 +832,7 @@ func (s *SessionOptions) createTLSOption() (grpc.DialOption, error) {
 	if s.CaCertPath != "" {
 		cp = x509.NewCertPool()
 
-		log.Println("loading CA certificate")
+		logMessage(DEBUG, "loading CA certificate")
 		if err = validateFilePath(s.CaCertPath); err != nil {
 			return nil, err
 		}
@@ -817,7 +848,7 @@ func (s *SessionOptions) createTLSOption() (grpc.DialOption, error) {
 	}
 
 	if s.ClientCertPath != "" && s.ClientKeyPath != "" {
-		log.Println("loading client certificate and key, cert=", s.ClientCertPath, "key=", s.ClientKeyPath)
+		logMessage(DEBUG, "loading client certificate and key paths, cert=%s, key=%s", s.ClientCertPath, s.ClientKeyPath)
 		if err = validateFilePath(s.ClientCertPath); err != nil {
 			return nil, err
 		}

coherence/session_test.go

@@ -1,5 +1,5 @@
 /*
-* Copyright (c) 2022, 2024 Oracle and/or its affiliates.
+* Copyright (c) 2022, 2025 Oracle and/or its affiliates.
 * Licensed under the Universal Permissive License v 1.0 as shown at
 * https://oss.oracle.com/licenses/upl.
  */
@@ -9,7 +9,6 @@ package coherence
 import (
 	"context"
 	"github.com/onsi/gomega"
-	"os"
 	"strconv"
 	"testing"
 	"time"
@@ -22,8 +21,6 @@ func TestSessionValidation(t *testing.T) {
 		ctx = context.Background()
 	)
 
-	os.Setenv("COHERENCE_SESSION_DEBUG", "true")
-
 	_, err = NewSession(ctx, WithFormat("not-json"))
 	g.Expect(err).To(gomega.Equal(ErrInvalidFormat))