Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add support to custom log level through command line flag and environment variable #842

Open
wants to merge 16 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion .github/workflows/e2e/k8s/sample-job.yml
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 2 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
13 changes: 13 additions & 0 deletions cli/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -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()

Expand Down Expand Up @@ -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")
Expand Down
64 changes: 53 additions & 11 deletions instrumentation.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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 {
Expand All @@ -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
}

Expand All @@ -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
Expand All @@ -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 {
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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.
//
Expand Down Expand Up @@ -383,6 +401,16 @@ func WithEnv() InstrumentationOption {
c.globalImpl = boolVal
}
}
if l, ok := lookupEnv(envLogLevelKey); ok {
RonFed marked this conversation as resolved.
Show resolved Hide resolved
var e error
level, e := ParseLogLevel(l)

if e == nil {
c.logLevel = level
}

err = errors.Join(err, e)
}
return c, err
})
}
Expand Down Expand Up @@ -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) {
MrAlias marked this conversation as resolved.
Show resolved Hide resolved
if err := level.validate(); err != nil {
return c, err
}

c.logLevel = level

return c, nil
})
}
37 changes: 37 additions & 0 deletions instrumentation_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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 })
Expand Down
16 changes: 8 additions & 8 deletions internal/pkg/instrumentation/manager.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
}
Expand Down Expand Up @@ -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
Expand All @@ -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)
}
Expand All @@ -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))
}

Expand Down
6 changes: 3 additions & 3 deletions internal/pkg/instrumentation/probe/probe.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
}

Expand Down Expand Up @@ -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
}
Expand Down
4 changes: 2 additions & 2 deletions internal/pkg/opentelemetry/controller.go
Original file line number Diff line number Diff line change
Expand Up @@ -52,11 +52,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
}

Expand Down
8 changes: 4 additions & 4 deletions internal/pkg/process/allocate.go
Original file line number Diff line number Diff line change
Expand Up @@ -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(),
Expand All @@ -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),
Expand All @@ -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)
Expand All @@ -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
Expand Down
4 changes: 2 additions & 2 deletions internal/pkg/process/analyze.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
Loading
Loading