Improve the way the Go client logs messages

Author: Tim Middleton

Makefile

@@ -8,7 +8,7 @@
 # ----------------------------------------------------------------------------------------------------------------------
 
 # This is the version of the coherence-go-client
-VERSION ?=2.1.0
+VERSION ?=2.1.1
 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: 0 -> 5
+	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/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()
+
+	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,40 @@ 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() {
+	var (
+		level    int
+		envLevel = getStringValueFromEnvVarOrDefault(envLogLevel, "3")
+	)
+
+	// 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 +452,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 +787,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 +808,7 @@ func (s *SessionOptions) createTLSOption() (grpc.DialOption, error) {
 
 	ignoreInvalidCerts := ignoreInvalidCertsEnv == "true"
 	if ignoreInvalidCerts {
-		log.Println(insecureWarning)
+		logMessage(WARNING, insecureWarning)
 	}
 	s.IgnoreInvalidCerts = ignoreInvalidCerts
 
@@ -801,7 +835,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 +851,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))
 

coherence/v1client.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.
  */
@@ -26,15 +26,17 @@ import (
 // V1ProxyProtocol defines the types of proxy protocols such as "CacheService" or "QueueService".
 type V1ProxyProtocol string
 
-type logLevel string
+type logLevel int
 
 var (
-	INFO    logLevel = "INFO:"
-	WARNING logLevel = "WARN:"
-	ERROR   logLevel = "ERROR:"
-	DEBUG   logLevel = "DEBUG:"
-	RCV              = "RCV"
-	SND              = "SND"
+	ERROR   logLevel = 1
+	WARNING logLevel = 2
+	INFO    logLevel = 3 // Default
+	DEBUG   logLevel = 4
+	ALL     logLevel = 5 // all messages
+
+	// current log level
+	currentLogLevel int
 )
 
 const (
@@ -234,14 +236,34 @@ func (m *streamManagerV1) processResponseMessage(id int64, resp *responseMessage
 	m.processResponse(id, resp)
 }
 
+// logMessage logs a message only if the level <= currentLogLevel
 func logMessage(level logLevel, format string, args ...any) {
-	log.Println(getLogMessage(level, format, args...))
+	if int(level) <= currentLogLevel {
+		log.Println(getLogMessage(level, format, args...))
+	}
 }
 
 func getLogMessage(level logLevel, format string, args ...any) string {
 	return fmt.Sprintf("%v ", level) + fmt.Sprintf(format, args...)
 }
 
+func (l logLevel) String() string {
+	switch l {
+	case ERROR:
+		return "ERROR"
+	case WARNING:
+		return "WARNING"
+	case INFO:
+		return "INFO"
+	case DEBUG:
+		return "DEBUG"
+	case ALL:
+		return "DEBUG"
+	default:
+		return fmt.Sprintf("logLevel(%d)", int(l))
+	}
+}
+
 func (m *streamManagerV1) setServerInfo(r *pb1.InitResponse) {
 	m.serverVersion = r.GetVersion()
 	m.serverProtocolVersion = r.GetProtocolVersion()

test/e2e/queues/queues_test.go

@@ -639,9 +639,6 @@ func TestQueueDestroy(t *testing.T) {
 	g.Expect(err).ShouldNot(gomega.HaveOccurred())
 	defer session.Close()
 
-	t.Setenv("COHERENCE_SESSION_DEBUG", "true")
-	t.Setenv("COHERENCE_MESSAGE_DEBUG", "true")
-
 	runTestQueueDestroy(g, session, "destroy-q", coherence.Queue)
 	runTestQueueDestroy(g, session, "destroy-paged-q", coherence.PagedQueue)
 	runTestQueueDestroy(g, session, "destroy-dq", coherence.Dequeue)