Higher sampling overrides do not work

[morngaraf]

Expected behavior

Higher sampling values should override lower default sampling. (Please correct me if my understanding of this section is wrong)

Actual behavior

Only default sampling is taken into account.

To Reproduce

Steps to reproduce the behavior:

1. Create sample controller:

   @RestController
   public class SampleController {
       private final String ALERT_KEY = "trigger-alert";
       Logger logger = LoggerFactory.getLogger(SampleController.class);
   
       @GetMapping("/sample-check")
       public String check() {
           MDC.put(ALERT_KEY, String.valueOf(true));
           logger.info("nice info message");
           MDC.remove(ALERT_KEY);
           return "cool response";
       }
   }
   

2. Configure sampling

   "sampling": {
     "percentage": 10
   },
   "preview": {
     "sampling": {
       "overrides": [
         {
           "attributes": [
             {
               "key": "trigger-alert",
               "value": "true",
               "matchType": "strict"
             }
           ],
           "percentage": 100
         }
       ]
     }
   }
   

3. Start app, send several GET /sample-check requests, check logs / fiddler / appinsights for what was captured.

System information

• SDK Version: agent 3.2.3, Java 17
• OS type and version: Windows 10 x64, 21H1, 19043.1348
• Using spring-boot? - yes, 2.5.6
• Additional relevant libraries (with version, if applicable): configured spring-boot to use log4j2 instead of default logback (probably irrelevant, though I didn't try with default)

Logs

1. Logs with default sampling set to 100 and overriden with 0:

   Windows 10 10.0, architecture: amd64-64 2021-11-24T02:16:32,074 INFO [http-nio-8080-exec-1] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:16:32.105+03:00 DEBUG c.m.a.a.internal.exporter.Exporter - exporting span: SpanDataImpl{...}, name=/sample-check, kind=SERVER, startEpochNanos=1637709391996079200, attributes={http.flavor="1.1", http.host="localhost:8080", http.method="GET", http.response_content_length=13, http.scheme="http", http.server_name="localhost", http.status_code=200, http.target="/sample-check", http.url="http://localhost:8080/sample-check", net.peer.ip="127.0.0.1", net.peer.port=64053, net.transport="ip_tcp", thread.id=63}, events=[], links=[], status=ImmutableStatusData{statusCode=UNSET, description=}, endEpochNanos=1637709392100524600, hasEnded=true, totalRecordedEvents=0, totalRecordedLinks=0, totalAttributeCount=14} Windows 10 10.0, architecture: amd64-64 2021-11-24T02:16:32,886 INFO [http-nio-8080-exec-2] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:16:32.902+03:00 DEBUG c.m.a.a.internal.exporter.Exporter - exporting span: SpanDataImpl{...}, name=/sample-check, kind=SERVER, startEpochNanos=1637709392886658800, attributes={http.flavor="1.1", http.host="localhost:8080", http.method="GET", http.response_content_length=13, http.scheme="http", http.server_name="localhost", http.status_code=200, http.target="/sample-check", http.url="http://localhost:8080/sample-check", net.peer.ip="127.0.0.1", net.peer.port=64054, net.transport="ip_tcp", thread.id=64}, events=[], links=[], status=ImmutableStatusData{statusCode=UNSET, description=}, endEpochNanos=1637709392888634300, hasEnded=true, totalRecordedEvents=0, totalRecordedLinks=0, totalAttributeCount=14} Windows 10 10.0, architecture: amd64-64 2021-11-24T02:16:33,558 INFO [http-nio-8080-exec-3] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:16:33.574+03:00 DEBUG c.m.a.a.internal.exporter.Exporter - exporting span: SpanDataImpl{...}, name=/sample-check, kind=SERVER, startEpochNanos=1637709393558917100, attributes={http.flavor="1.1", http.host="localhost:8080", http.method="GET", http.response_content_length=13, http.scheme="http", http.server_name="localhost", http.status_code=200, http.target="/sample-check", http.url="http://localhost:8080/sample-check", net.peer.ip="127.0.0.1", net.peer.port=64055, net.transport="ip_tcp", thread.id=65}, events=[], links=[], status=ImmutableStatusData{statusCode=UNSET, description=}, endEpochNanos=1637709393562505500, hasEnded=true, totalRecordedEvents=0, totalRecordedLinks=0, totalAttributeCount=14}

   3 requests, 100% of requests are exported, no logs exported, i.e. zero sampling works.

2. Logs with default set to 10 and overriden with 100 (as in the steps to reproduce):

   2021-11-24 02:31:49.697+03:00 DEBUG c.m.a.a.internal.exporter.Exporter - exporting span: SpanDataImpl{...}, name=nice info message, kind=INTERNAL, startEpochNanos=1637710309688572900, attributes={applicationinsights.internal.log=true, applicationinsights.internal.log_level="INFO", applicationinsights.internal.logger_name="...SampleController", applicationinsights.internal.operation_name="GET /sample-check", thread.id=63, trigger-alert="true"}, events=[], links=[], status=ImmutableStatusData{statusCode=UNSET, description=}, endEpochNanos=1637710309688584400, hasEnded=true, totalRecordedEvents=0, totalRecordedLinks=0, totalAttributeCount=7} Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:49,697 INFO [http-nio-8080-exec-1] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:49.713+03:00 DEBUG c.m.a.a.internal.exporter.Exporter - exporting span: SpanDataImpl{}, name=/sample-check, kind=SERVER, startEpochNanos=1637710309604170400, attributes={http.flavor="1.1", http.host="localhost:8080", http.method="GET", http.response_content_length=13, http.scheme="http", http.server_name="localhost", http.status_code=200, http.target="/sample-check", http.url="http://localhost:8080/sample-check", net.peer.ip="127.0.0.1", net.peer.port=64161, net.transport="ip_tcp", thread.id=63}, events=[], links=[], status=ImmutableStatusData{statusCode=UNSET, description=}, endEpochNanos=1637710309706744300, hasEnded=true, totalRecordedEvents=0, totalRecordedLinks=0, totalAttributeCount=14} 2021-11-24 02:31:50.401+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:50,401 INFO [http-nio-8080-exec-2] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:51.213+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:51,213 INFO [http-nio-8080-exec-3] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:51.916+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:51,916 INFO [http-nio-8080-exec-4] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:52.979+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:52,979 INFO [http-nio-8080-exec-5] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:53.666+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:53,666 INFO [http-nio-8080-exec-6] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:54.432+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:54,432 INFO [http-nio-8080-exec-7] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:55.182+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:55,182 INFO [http-nio-8080-exec-8] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:55.885+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:55,885 INFO [http-nio-8080-exec-9] c.v.a.s.SampleController ALERT:true : nice info message 2021-11-24 02:31:56.619+03:00 DEBUG c.m.a.a.internal.sampling.AiSampler - Item HTTP GET sampled out Windows 10 10.0, architecture: amd64-64 2021-11-24T02:31:56,619 INFO [http-nio-8080-exec-9] c.v.a.s.SampleController ALERT:true : nice info message

   10 requests, 10 logs, 1 (10%, as expected) request exported, 1 (10%, instead of 100% expected) log entry exported.

[trask]

hi @morngaraf, so sorry for the late reply.

In your example above, do you want the 100% sampling rate to apply to the request that the log is emitted inside of, or do you want the 100% sampling rate to apply just to the log itself?