Add support to custom log level through command line flag and environ…

…ment variable (#842)

* added log level through commnd line flag

* added changelog entry

* implemented own level enum and add err when not found the inputed log level

* changed log visibility to debug on some info logs

* changed test job to use debug log level

* running precommit

* adjusted log visibility levels to ensure is following the flag

* changed the behaviour on how default value is set

* removed not used levels and add comments to levels

* changed level to auto package and use Level as parameter on WithLogLevel

* changed type to log level, add validate method and enforce a type on withLogLevel method

* additional changelog message

* runned precommit

* changed levels to log preffix and simplified unmarshal

* change some descriptions and added ParseLogLevel test

* changed to use ParseLogLevel instead of Unmarshal

---------

Co-authored-by: Tyler Yahn <[email protected]>

.github/workflows/e2e/k8s/sample-job.yml

@@ -26,7 +26,7 @@ spec:
       - name: auto-instrumentation
         image: otel-go-instrumentation
         imagePullPolicy: IfNotPresent
-        command: ["/otel-go-instrumentation", "-global-impl"]
+        command: ["/otel-go-instrumentation", "-global-impl", "-log-level=debug"]
         env:
         - name: OTEL_GO_AUTO_TARGET_EXE
           value: /sample-app/main

CHANGELOG.md

@@ -12,6 +12,8 @@ OpenTelemetry Go Automatic Instrumentation adheres to [Semantic Versioning](http
 
 - Initial support for `trace-flags`. ([#868](https://github.com/open-telemetry/opentelemetry-go-instrumentation/pull/868))
 - Support `google.golang.org/grpc` `1.66.0-dev`. ([#872](https://github.com/open-telemetry/opentelemetry-go-instrumentation/pull/872))
+- Add support to log level through command line flag. ([#842](https://github.com/open-telemetry/opentelemetry-go-instrumentation/pull/842))
+- The `WithLogLevel` function and `LogLevel` type are added to set the log level for `Instrumentation`. ([#842](https://github.com/open-telemetry/opentelemetry-go-instrumentation/pull/842))
 
 ### Fixed
 

cli/main.go

@@ -68,8 +68,11 @@ func newLogger() logr.Logger {
 
 func main() {
 	var globalImpl bool
+	var logLevel string
 
 	flag.BoolVar(&globalImpl, "global-impl", false, "Record telemetry from the OpenTelemetry default global implementation")
+	flag.StringVar(&logLevel, "log-level", "", "Define log visibility level, default is `info`")
+
 	flag.Usage = usage
 	flag.Parse()
 
@@ -99,6 +102,16 @@ func main() {
 		instOptions = append(instOptions, auto.WithGlobal())
 	}
 
+	if logLevel != "" {
+		level, err := auto.ParseLogLevel(logLevel)
+		if err != nil {
+			logger.Error(err, "failed to parse log level")
+			return
+		}
+
+		instOptions = append(instOptions, auto.WithLogLevel(level))
+	}
+
 	inst, err := auto.NewInstrumentation(ctx, instOptions...)
 	if err != nil {
 		logger.Error(err, "failed to create instrumentation")

instrumentation.go

@@ -58,6 +58,8 @@ const (
 	// envOtelGlobalImplKey is the key for the environment variable value enabling to opt-in for the
 	// OpenTelemetry global implementation. It should be a boolean value.
 	envOtelGlobalImplKey = "OTEL_GO_AUTO_GLOBAL"
+	// envLogLevelKey is the key for the environment variable value containing the log level.
+	envLogLevelKey = "OTEL_LOG_LEVEL"
 )
 
 // Instrumentation manages and controls all OpenTelemetry Go
@@ -72,8 +74,17 @@ type Instrumentation struct {
 // binary or pid.
 var errUndefinedTarget = fmt.Errorf("undefined target Go binary, consider setting the %s environment variable pointing to the target binary to instrument", envTargetExeKey)
 
-func newLogger() logr.Logger {
-	zapLog, err := zap.NewProduction()
+func newLogger(logLevel LogLevel) logr.Logger {
+	level, logErr := zap.ParseAtomicLevel(logLevel.String())
+	if logErr != nil {
+		level, _ = zap.ParseAtomicLevel(LogLevelInfo.String())
+	}
+
+	config := zap.NewProductionConfig()
+
+	config.Level.SetLevel(level.Level())
+
+	zapLog, err := config.Build()
 
 	var logger logr.Logger
 	if err != nil {
@@ -83,6 +94,10 @@ func newLogger() logr.Logger {
 		logger = zapr.NewLogger(zapLog)
 	}
 
+	if logErr != nil {
+		logger.Error(logErr, "invalid log level; using LevelInfo instead", zap.Error(logErr), zap.String("input", logLevel.String()))
+	}
+
 	return logger
 }
 
@@ -92,14 +107,6 @@ func newLogger() logr.Logger {
 // If conflicting or duplicate options are provided, the last one will have
 // precedence and be used.
 func NewInstrumentation(ctx context.Context, opts ...InstrumentationOption) (*Instrumentation, error) {
-	// TODO: pass this in as an option.
-	//
-	// We likely want to use slog instead of logr in the longterm. Wait until
-	// that package has enough Go version support and then switch to that so we
-	// can expose it in an option.
-	logger := newLogger()
-	logger = logger.WithName("Instrumentation")
-
 	c, err := newInstConfig(ctx, opts)
 	if err != nil {
 		return nil, err
@@ -108,6 +115,11 @@ func NewInstrumentation(ctx context.Context, opts ...InstrumentationOption) (*In
 		return nil, err
 	}
 
+	// We likely want to use slog instead of logr in the longterm. Wait until
+	// that package has enough Go version support
+	logger := newLogger(c.logLevel)
+	logger = logger.WithName("Instrumentation")
+
 	pa := process.NewAnalyzer(logger)
 	pid, err := pa.DiscoverProcessID(ctx, &c.target)
 	if err != nil {
@@ -179,6 +191,7 @@ type instConfig struct {
 	additionalResAttrs []attribute.KeyValue
 	globalImpl         bool
 	loadIndicator      chan struct{}
+	logLevel           LogLevel
 }
 
 func newInstConfig(ctx context.Context, opts []InstrumentationOption) (instConfig, error) {
@@ -209,6 +222,10 @@ func newInstConfig(ctx context.Context, opts []InstrumentationOption) (instConfi
 		c.sampler = trace.AlwaysSample()
 	}
 
+	if c.logLevel == logLevelUndefined {
+		c.logLevel = LogLevelInfo
+	}
+
 	return c, err
 }
 
@@ -347,9 +364,10 @@ var lookupEnv = os.LookupEnv
 //   - OTEL_SERVICE_NAME (or OTEL_RESOURCE_ATTRIBUTES): sets the service name
 //   - OTEL_TRACES_EXPORTER: sets the trace exporter
 //   - OTEL_GO_AUTO_GLOBAL: enables the OpenTelemetry global implementation
+//   - OTEL_LOG_LEVEL: sets the log level
 //
 // This option may conflict with [WithTarget], [WithPID], [WithTraceExporter],
-// [WithServiceName] and [WithGlobal] if their respective environment variable is defined.
+// [WithServiceName], [WithGlobal] and [WithLogLevel] if their respective environment variable is defined.
 // If more than one of these options are used, the last one provided to an
 // [Instrumentation] will be used.
 //
@@ -383,6 +401,16 @@ func WithEnv() InstrumentationOption {
 				c.globalImpl = boolVal
 			}
 		}
+		if l, ok := lookupEnv(envLogLevelKey); ok {
+			var e error
+			level, e := ParseLogLevel(l)
+
+			if e == nil {
+				c.logLevel = level
+			}
+
+			err = errors.Join(err, e)
+		}
 		return c, err
 	})
 }
@@ -490,3 +518,17 @@ func WithLoadedIndicator(indicator chan struct{}) InstrumentationOption {
 		return c, nil
 	})
 }
+
+// WithLogLevel returns an [InstrumentationOption] that will configure
+// an [Instrumentation] to use the provided logging level.
+func WithLogLevel(level LogLevel) InstrumentationOption {
+	return fnOpt(func(ctx context.Context, c instConfig) (instConfig, error) {
+		if err := level.validate(); err != nil {
+			return c, err
+		}
+
+		c.logLevel = level
+
+		return c, nil
+	})
+}

instrumentation_test.go

@@ -82,6 +82,21 @@ func TestWithEnv(t *testing.T) {
 		require.NoError(t, err)
 		assert.Equal(t, name, c.serviceName)
 	})
+
+	t.Run("OTEL_LOG_LEVEL", func(t *testing.T) {
+		const name = "debug"
+		mockEnv(t, map[string]string{"OTEL_LOG_LEVEL": name})
+
+		c, err := newInstConfig(context.Background(), []InstrumentationOption{WithEnv()})
+		require.NoError(t, err)
+		assert.Equal(t, LogLevelDebug, c.logLevel)
+
+		const wrong = "invalid"
+
+		mockEnv(t, map[string]string{"OTEL_LOG_LEVEL": wrong})
+		_, err = newInstConfig(context.Background(), []InstrumentationOption{WithEnv()})
+		require.Error(t, err)
+	})
 }
 
 func TestOptionPrecedence(t *testing.T) {
@@ -172,6 +187,28 @@ func TestWithResourceAttributes(t *testing.T) {
 	})
 }
 
+func TestWithLogLevel(t *testing.T) {
+	t.Run("With Valid Input", func(t *testing.T) {
+		c, err := newInstConfig(context.Background(), []InstrumentationOption{WithLogLevel("error")})
+
+		require.NoError(t, err)
+
+		assert.Equal(t, LogLevelError, c.logLevel)
+
+		c, err = newInstConfig(context.Background(), []InstrumentationOption{WithLogLevel(LogLevelInfo)})
+
+		require.NoError(t, err)
+
+		assert.Equal(t, LogLevelInfo, c.logLevel)
+	})
+
+	t.Run("Will Validate Input", func(t *testing.T) {
+		_, err := newInstConfig(context.Background(), []InstrumentationOption{WithLogLevel("invalid")})
+
+		require.Error(t, err)
+	})
+}
+
 func mockEnv(t *testing.T, env map[string]string) {
 	orig := lookupEnv
 	t.Cleanup(func() { lookupEnv = orig })

internal/pkg/instrumentation/manager.go

@@ -137,7 +137,7 @@ func (m *Manager) FilterUnusedProbes(target *process.TargetDetails) {
 		}
 
 		if !funcsFound {
-			m.logger.Info("no functions found for probe, removing", "name", name)
+			m.logger.V(1).Info("no functions found for probe, removing", "name", name)
 			delete(m.probes, name)
 		}
 	}
@@ -172,13 +172,13 @@ func (m *Manager) Run(ctx context.Context, target *process.TargetDetails) error
 	for {
 		select {
 		case <-ctx.Done():
-			m.logger.Info("shutting down all probes due to context cancellation")
+			m.logger.V(1).Info("shutting down all probes due to context cancellation")
 			err := m.cleanup(target)
 			err = errors.Join(err, ctx.Err())
 			m.closingErrors <- err
 			return nil
 		case <-m.done:
-			m.logger.Info("shutting down all probes due to signal")
+			m.logger.V(1).Info("shutting down all probes due to signal")
 			err := m.cleanup(target)
 			m.closingErrors <- err
 			return nil
@@ -205,23 +205,23 @@ func (m *Manager) load(target *process.TargetDetails) error {
 
 	// Load probes
 	for name, i := range m.probes {
-		m.logger.Info("loading probe", "name", name)
+		m.logger.V(0).Info("loading probe", "name", name)
 		err := i.Load(exe, target)
 		if err != nil {
 			m.logger.Error(err, "error while loading probes, cleaning up", "name", name)
 			return errors.Join(err, m.cleanup(target))
 		}
 	}
 
-	m.logger.Info("loaded probes to memory", "total_probes", len(m.probes))
+	m.logger.V(1).Info("loaded probes to memory", "total_probes", len(m.probes))
 	return nil
 }
 
 func (m *Manager) mount(target *process.TargetDetails) error {
 	if target.AllocationDetails != nil {
-		m.logger.Info("Mounting bpffs", "allocations_details", target.AllocationDetails)
+		m.logger.V(1).Info("Mounting bpffs", "allocations_details", target.AllocationDetails)
 	} else {
-		m.logger.Info("Mounting bpffs")
+		m.logger.V(1).Info("Mounting bpffs")
 	}
 	return bpffs.Mount(target)
 }
@@ -233,7 +233,7 @@ func (m *Manager) cleanup(target *process.TargetDetails) error {
 		err = errors.Join(err, i.Close())
 	}
 
-	m.logger.Info("Cleaning bpffs")
+	m.logger.V(1).Info("Cleaning bpffs")
 	return errors.Join(err, bpffs.Cleanup(target))
 }
 

internal/pkg/instrumentation/probe/probe.go

@@ -149,7 +149,7 @@ func (i *Base[BPFObj, BPFEvent]) buildObj(exec *link.Executable, td *process.Tar
 		links, err := up.Fn(up.Sym, exec, td, obj)
 		if err != nil {
 			if up.Optional {
-				i.Logger.Info("failed to attach optional uprobe", "probe", i.ID, "symbol", up.Sym, "error", err)
+				i.Logger.V(1).Info("failed to attach optional uprobe", "probe", i.ID, "symbol", up.Sym, "error", err)
 				continue
 			}
 			return nil, err
@@ -175,7 +175,7 @@ func (i *Base[BPFObj, BPFEvent]) Run(dest chan<- *Event) {
 		}
 
 		if record.LostSamples != 0 {
-			i.Logger.Info("perf event ring buffer full", "dropped", record.LostSamples)
+			i.Logger.V(1).Info("perf event ring buffer full", "dropped", record.LostSamples)
 			continue
 		}
 
@@ -211,7 +211,7 @@ func (i *Base[BPFObj, BPFEvent]) Close() error {
 		err = errors.Join(err, c.Close())
 	}
 	if err == nil {
-		i.Logger.Info("Closed", "Probe", i.ID)
+		i.Logger.V(1).Info("Closed", "Probe", i.ID)
 	}
 	return err
 }

internal/pkg/opentelemetry/controller.go

@@ -51,11 +51,11 @@ func (c *Controller) getTracer(pkg string) trace.Tracer {
 // Trace creates a trace span for event.
 func (c *Controller) Trace(event *probe.Event) {
 	for _, se := range event.SpanEvents {
-		c.logger.Info("got event", "kind", event.Kind.String(), "pkg", event.Package, "attrs", se.Attributes, "traceID", se.SpanContext.TraceID().String(), "spanID", se.SpanContext.SpanID().String())
+		c.logger.V(1).Info("got event", "kind", event.Kind.String(), "pkg", event.Package, "attrs", se.Attributes, "traceID", se.SpanContext.TraceID().String(), "spanID", se.SpanContext.SpanID().String())
 		ctx := context.Background()
 
 		if se.SpanContext == nil {
-			c.logger.Info("got event without context - dropping")
+			c.logger.V(1).Info("got event without context - dropping")
 			return
 		}
 

internal/pkg/process/allocate.go

@@ -48,7 +48,7 @@ func Allocate(logger logr.Logger, pid int) (*AllocationDetails, error) {
 	}
 
 	mapSize := uint64(os.Getpagesize() * nCPU * 8)
-	logger.Info(
+	logger.V(1).Info(
 		"Requesting memory allocation",
 		"size", mapSize,
 		"page size", os.Getpagesize(),
@@ -59,7 +59,7 @@ func Allocate(logger logr.Logger, pid int) (*AllocationDetails, error) {
 		return nil, err
 	}
 
-	logger.Info(
+	logger.V(1).Info(
 		"mmaped remote memory",
 		"start_addr", fmt.Sprintf("0x%x", addr),
 		"end_addr", fmt.Sprintf("0x%x", addr+mapSize),
@@ -81,7 +81,7 @@ func remoteAllocate(logger logr.Logger, pid int, mapSize uint64) (uint64, error)
 	}
 
 	defer func() {
-		logger.Info("Detaching from process", "pid", pid)
+		logger.V(0).Info("Detaching from process", "pid", pid)
 		err := program.Detach()
 		if err != nil {
 			logger.Error(err, "Failed to detach ptrace", "pid", pid)
@@ -91,7 +91,7 @@ func remoteAllocate(logger logr.Logger, pid int, mapSize uint64) (uint64, error)
 	if err := program.SetMemLockInfinity(); err != nil {
 		logger.Error(err, "Failed to set memlock on process")
 	} else {
-		logger.Info("Set memlock on process successfully")
+		logger.V(1).Info("Set memlock on process successfully")
 	}
 
 	fd := -1

internal/pkg/process/analyze.go

@@ -103,7 +103,7 @@ func (a *Analyzer) Analyze(pid int, relevantFuncs map[string]interface{}) (*Targ
 		return nil, err
 	}
 	for _, fn := range funcs {
-		a.logger.Info("found function", "function_name", fn)
+		a.logger.V(1).Info("found function", "function_name", fn)
 	}
 
 	result.Functions = funcs
@@ -145,7 +145,7 @@ func (a *Analyzer) findFunctions(elfF *elf.File, relevantFuncs map[string]interf
 	result, err := binary.FindFunctionsUnStripped(elfF, relevantFuncs)
 	if err != nil {
 		if errors.Is(err, elf.ErrNoSymbols) {
-			a.logger.Info("No symbols found in binary, trying to find functions using .gosymtab")
+			a.logger.V(1).Info("No symbols found in binary, trying to find functions using .gosymtab")
 			return binary.FindFunctionsStripped(elfF, relevantFuncs)
 		}
 		return nil, err