[processor/tailsampling] invert_match not given precedence when inside and policy

[jamesrwhite]

Component(s)

processor/tailsampling

What happened?

Description

From my understanding of the tailsamplingprocessor README whenever an "inverted not sample" decision is made that trace should not be sampled, regardless of any other policies. Specifically it states:

Each policy will result in a decision, and the processor will evaluate them to make a final decision:

• When there's an "inverted not sample" decision, the trace is not sampled;
• When there's a "sample" decision, the trace is sampled;
• When there's a "inverted sample" decision and no "not sample" decisions, the trace is sampled;
• In all other cases, the trace is NOT sampled

The "inverted not sample" decision having the highest precedence seems to be confirmed by how this is actually implemented here.

Based upon that I have been trying to put together a policy similar to the following:

• If a trace has a certain attribute AND it only contains 1 span → do not sample it
• For all other traces → sample them

In practice our policy is more complicated than this but I've simplified it as much as possible for the purpose of explaining this issue.

The policy looks like this in config:

- name: ignore-single-span-traces-from-certain-jobs
  type: and
  and:
    and_sub_policy:
      - name: not-boring-job
        type: string_attribute
        string_attribute:
          key: job
          values: ["boring"]
          invert_match: true
      - name: at-least-two-spans
        type: span_count
        span_count:
          min_spans: 2
- name: always-sample
  type: always_sample

What I'm finding in practice though is that traces with the job attribute set to boring that only contain a single span are still being sampled. Unless I'm misunderstanding how the tail sampling processor is working this seems like a bug to me.

I debugged this a bit by adding several extra log statements into the processor to see what decisions it was making on each policy and I believe the issue lies in how AND policies handled not sampled decisions here.

As you can see regardless of whether the decision is NotSampled or InvertNotSampled it always returns NotSampled. This is problematic because a NotSampled decision won't take precedence over a Sampled decision so any InverNotSampled decision that occurs within an AND policy is effectively getting downgraded to a NotSampled decision.

If it's useful for confirming this behaviour these were the extra log statements I added:

diff --git a/processor/tailsamplingprocessor/processor.go b/processor/tailsamplingprocessor/processor.go
index b0a5850400..edf36cf931 100644
--- a/processor/tailsamplingprocessor/processor.go
+++ b/processor/tailsamplingprocessor/processor.go
@@ -256,6 +256,10 @@ func (tsp *tailSamplingSpanProcessor) samplingPolicyOnTick() {
    trace.DecisionTime = time.Now()

    decision := tsp.makeDecision(id, trace, &metrics)
+   tsp.logger.Info("Tail Sampling Decision",
+     zap.Int64("spans", trace.SpanCount.Load()),
+     zap.Int32("sampled", int32(decision)),
+   )
    tsp.telemetry.ProcessorTailSamplingSamplingDecisionTimerLatency.Record(tsp.ctx, int64(time.Since(startTime)/time.Microsecond))
    tsp.telemetry.ProcessorTailSamplingSamplingTraceDroppedTooEarly.Add(tsp.ctx, metrics.idNotFoundOnMapCount)
    tsp.telemetry.ProcessorTailSamplingSamplingPolicyEvaluationError.Add(tsp.ctx, metrics.evaluateErrorCount)
@@ -309,6 +313,10 @@ func (tsp *tailSamplingSpanProcessor) makeDecision(id pcommon.TraceID, trace *sa
        tsp.telemetry.ProcessorTailSamplingCountSpansSampled.Add(ctx, trace.SpanCount.Load(), p.attribute, decisionToAttribute[decision])
      }

+     tsp.logger.Info("Sampling policy decision",
+       zap.Int32("decision", int32(decision)),
+       zap.String("policy", p.name),
+     )
      samplingDecision[decision] = true
    }
  }
@@ -317,10 +325,13 @@ func (tsp *tailSamplingSpanProcessor) makeDecision(id pcommon.TraceID, trace *sa
  switch {
  case samplingDecision[sampling.InvertNotSampled]:
    finalDecision = sampling.NotSampled
+   tsp.logger.Info("Setting finalDecision to NotSampled via InvertNotSampled")
  case samplingDecision[sampling.Sampled]:
    finalDecision = sampling.Sampled
+   tsp.logger.Info("Setting finalDecision to Sampled via Sampled")
  case samplingDecision[sampling.InvertSampled] && !samplingDecision[sampling.NotSampled]:
    finalDecision = sampling.Sampled
+   tsp.logger.Info("Setting finalDecision to Sampled via InvertSampled && !NotSampled")
  }

  return finalDecision

I believe the fix for this would be to return the decision so either the NotSampled or InvertNotSampled are returned respectively. I have tested this and it seems to fix the problem.

I've made those changes in a branch here: main...jamesrwhite:opentelemetry-collector-contrib:fix-and-policy-invert-not-sampled.

I'm happy to open a PR with the above changes if you agree that's the correct fix, also if you need any more information please let me know.

Thanks!

Steps to Reproduce

• Run collector with attached config
• Run sample application

from opentelemetry import trace

tracer = trace.get_tracer('worker')

print('Starting worker..')
with tracer.start_as_current_span('worker') as span:
	span.set_attribute('job', 'boring')
	print('Done')

$ OTEL_SERVICE_NAME=service.worker opentelemetry-instrument python app.py

• Review collector logs and see that trace is sampled

Expected Result

Trace is not sampled.

Actual Result

Trace is sampled.

Collector version

0.102.0-dev

Environment information

Environment

OS: MacOS 14.5
Go: 1.21.0
Python: 3.12.4

❯ go env
GO111MODULE=''
GOARCH='arm64'
GOBIN='/Users/james.white/.local/share/mise/installs/go/1.21.0/bin'
GOCACHE='/Users/james.white/Library/Caches/go-build'
GOENV='/Users/james.white/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/james.white/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/james.white/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/james.white/.local/share/mise/installs/go/1.21.0/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/james.white/.local/share/mise/installs/go/1.21.0/go/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.21.0'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/james.white/Code/otel/opentelemetry-collector-contrib-fork/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/96/_bvls_n53qg78rl760qw21lm0000gq/T/go-build997096154=/tmp/go-build -gno-record-gcc-switches -fno-common'

OpenTelemetry Collector configuration

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: :4317
      http:
        endpoint: :4318

exporters:
  debug:
    verbosity: detailed

processors:
  tail_sampling:
    policies:
      - name: ignore-single-span-traces-from-certain-jobs
        type: and
        and:
          and_sub_policy:
            - name: not-boring-job
              type: string_attribute
              string_attribute:
                key: job
                values: ["boring"]
                invert_match: true
            - name: at-least-two-spans
              type: span_count
              span_count:
                min_spans: 2
      - name: always-sample
        type: always_sample

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [tail_sampling]
      exporters: [debug]

Log output

$ make run
cd ./cmd/otelcontribcol && GO111MODULE=on go run --race . --config ../../local/config.yaml
# github.com/open-telemetry/opentelemetry-collector-contrib/cmd/otelcontribcol
ld: warning: ignoring duplicate libraries: '-lproc'
2024-06-19T11:59:29.405+0100	info	service@v0.102.2-0.20240617165252-f88ce7a687ba/service.go:115	Setting up own telemetry...
2024-06-19T11:59:29.405+0100	info	service@v0.102.2-0.20240617165252-f88ce7a687ba/telemetry.go:96	Serving metrics	{"address": ":8888", "level": "Normal"}
2024-06-19T11:59:29.405+0100	info	exporter@v0.102.2-0.20240617165252-f88ce7a687ba/exporter.go:280	Development component. May change in the future.	{"kind": "exporter", "data_type": "traces", "name": "debug"}
2024-06-19T11:59:29.406+0100	info	service@v0.102.2-0.20240617165252-f88ce7a687ba/service.go:182	Starting otelcontribcol...	{"Version": "0.102.0-dev", "NumCPU": 10}
2024-06-19T11:59:29.406+0100	info	extensions/extensions.go:34	Starting extensions...
2024-06-19T11:59:29.406+0100	warn	internal@v0.102.2-0.20240617165252-f88ce7a687ba/warning.go:42	Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks. Enable the feature gate to change the default and remove this warning.	{"kind": "receiver", "name": "otlp", "data_type": "traces", "documentation": "https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks", "feature gate ID": "component.UseLocalHostAsDefaultHost"}
2024-06-19T11:59:29.407+0100	info	otlpreceiver@v0.102.2-0.20240617165252-f88ce7a687ba/otlp.go:102	Starting GRPC server	{"kind": "receiver", "name": "otlp", "data_type": "traces", "endpoint": ":4317"}
2024-06-19T11:59:29.407+0100	warn	internal@v0.102.2-0.20240617165252-f88ce7a687ba/warning.go:42	Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks. Enable the feature gate to change the default and remove this warning.	{"kind": "receiver", "name": "otlp", "data_type": "traces", "documentation": "https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks", "feature gate ID": "component.UseLocalHostAsDefaultHost"}
2024-06-19T11:59:29.407+0100	info	otlpreceiver@v0.102.2-0.20240617165252-f88ce7a687ba/otlp.go:152	Starting HTTP server	{"kind": "receiver", "name": "otlp", "data_type": "traces", "endpoint": ":4318"}
2024-06-19T11:59:29.407+0100	info	service@v0.102.2-0.20240617165252-f88ce7a687ba/service.go:208	Everything is ready. Begin running and processing data.
2024-06-19T11:59:29.407+0100	warn	localhostgate/featuregate.go:63	The default endpoints for all servers in components will change to use localhost instead of 0.0.0.0 in a future version. Use the feature gate to preview the new default.	{"feature gate ID": "component.UseLocalHostAsDefaultHost"}
2024-06-19T13:38:26.131+0100	info	TracesExporter	{"kind": "exporter", "data_type": "traces", "name": "debug", "resource spans": 1, "spans": 1}
2024-06-19T13:38:26.133+0100	info	ResourceSpans #0
Resource SchemaURL:
Resource attributes:
     -> telemetry.sdk.language: Str(python)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.25.0)
     -> service.name: Str(service.worker)
     -> telemetry.auto.version: Str(0.46b0)
ScopeSpans #0
ScopeSpans SchemaURL:
InstrumentationScope worker
Span #0
    Trace ID       : 92776c0eb3c2a56cab8827066d03b4c3
    Parent ID      :
    ID             : e295a5bacda12b5a
    Name           : worker
    Kind           : Internal
    Start time     : 2024-06-19 12:37:55.499827 +0000 UTC
    End time       : 2024-06-19 12:37:55.499846 +0000 UTC
    Status code    : Unset
    Status message :
Attributes:
     -> job: Str(boring)
	{"kind": "exporter", "data_type": "traces", "name": "debug"}

Additional context

This is related to support being added for invert_match in AND policies in #9768

[github-actions]

Pinging code owners:

• processor/tailsampling: @jpkrohling

See Adding Labels via Comments if you do not have permissions to add labels yourself.

[jpkrohling]

@jamesrwhite, thank you for the detailed report! I agree with your assessment: the and policy should definitely return the original decision there. I looked at the branch with the proposal and I would definitely like to review and merge a PR with that code.

[jamesrwhite]

@jpkrohling thanks for taking a look at this so soon, I'll open a PR shortly 👍

[crobert-1]

It looks like this was resolved by #33671, but please correct me if I'm missing something.