AWS X-Ray, Dotnet Core 3.1, X-Ray Daemon Locally

Question

We are trying to get X-Ray trace data from a local dotnet core 3.1 app sending trace data to a local X-Ray Daemon. As a start, we've created a generic web api and added swagger (just to make testing easier).

Startup.cs

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.HttpsPolicy;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Microsoft.OpenApi.Models;
using Amazon.XRay.Recorder.Core;
using log4net;
using log4net.Config;
using System.Reflection;
using System.IO;
using Amazon;
using System.Net;
using Amazon.XRay.Recorder.Core.Internal.Utils;
using Amazon.XRay.Recorder.Core.Sampling.Local;

namespace AWS_XRay
{
    public class Startup
    {
        public static ILog log;
        static Startup() // create log4j instance
        {
            var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly());
            XmlConfigurator.Configure(logRepository, new FileInfo("log4net.config"));
            log = LogManager.GetLogger(typeof(Startup));
            AWSXRayRecorder.RegisterLogger(LoggingOptions.Log4Net);
        }

        public Startup(IConfiguration configuration)
        {
            Configuration = configuration;

            Environment.SetEnvironmentVariable("AWS_XRAY_DAEMON_ADDRESS", "127.0.0.1:2000");
            Environment.SetEnvironmentVariable("AWS_XRAY_CONTEXT_MISSING", "LOG_ERROR");
            var recorder = new AWSXRayRecorderBuilder().WithSamplingStrategy(newLocalizedSamplingStrategy("sampling-rules.json")).Build();
            AWSXRayRecorder.InitializeInstance(configuration, recorder);
        }

        public IConfiguration Configuration { get; }

        // This method gets called by the runtime. Use this method to add services to the container.
        public void ConfigureServices(IServiceCollection services)
        {
            services.AddControllers();

            // Register the Swagger generator, defining 1 or more Swagger documents
            services.AddSwaggerGen(c =>
            {
                c.SwaggerDoc("v1", new OpenApiInfo { Title = "My API", Version = "v1" });
            });
        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            app.UseXRay("WeatherForecast");
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }


            app.UseSwagger();

            app.UseSwaggerUI(c =>
            {
                c.SwaggerEndpoint("/swagger/v1/swagger.json", "My API V1");
                c.RoutePrefix = string.Empty;
            });

            app.UseHttpsRedirection();

            app.UseRouting();

            app.UseAuthorization();

            app.UseEndpoints(endpoints =>
            {
                endpoints.MapControllers();
            });
        }
    }
}

Then we decorated the controller with the relevant or what we think is relevant

WeatherController

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using Amazon.XRay.Recorder.Core;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;

namespace AWS_XRay.Controllers
{
    [ApiController]
    [Route("[controller]")]
    public class WeatherForecastController : ControllerBase
    {
        private static readonly string[] Summaries = new[]
        {
            "Freezing", "Bracing", "Chilly", "Cool", "Mild", "Warm", "Balmy", "Hot", "Sweltering", "Scorching"
        };

        private readonly ILogger<WeatherForecastController> _logger;

        public WeatherForecastController(ILogger<WeatherForecastController> logger)
        {
            _logger = logger;
        }


        [HttpGet]
        [Route("GetWeather")]
        public async Task<IActionResult> WeatherForecast()
        {
            AWSXRayRecorder.Instance.BeginSegment("weatherget"); // generates `TraceId` for you
            try
            {
                var rng = new Random();
                var result =  Enumerable.Range(1, 5).Select(index => new WeatherForecast
                {
                    Date = DateTime.Now.AddDays(index),
                    TemperatureC = rng.Next(-20, 55),
                    Summary = Summaries[rng.Next(Summaries.Length)]
                })
                .ToArray();
                // can create custom subsegments

                return Ok(result);
            }
            catch (Exception e)
            {
                AWSXRayRecorder.Instance.AddException(e);
                return StatusCode(500, e);

            }
            finally
            {
                AWSXRayRecorder.Instance.EndSegment();
            }
        }
    }
}

When running the application, looking at the logs. This is what we see...

*sdk-log.txt"

2020-04-14 16:04:21,740 [1] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Initializing with custom sampling configuration : sampling-rules.json
2020-04-14 16:04:22,035 [1] DEBUG Amazon.XRay.Recorder.Core.Internal.Utils.IPEndPointExtension - Determined that 127.0.0.1:2000 is an IP.
2020-04-14 16:04:22,039 [1] INFO Amazon.XRay.Recorder.Core.Internal.Utils.IPEndPointExtension - Using custom daemon address for UDP and TCP: 127.0.0.1:2000
2020-04-14 16:04:22,042 [1] DEBUG Amazon.XRay.Recorder.Core.Strategies.DefaultExceptionSerializationStrategy - Setting max stack frame size : 50
2020-04-14 16:04:22,073 [1] DEBUG Amazon.XRay.Recorder.Core.AWSXRayRecorderImpl - Context missing mode : RUNTIME_ERROR
2020-04-14 16:04:22,073 [1] DEBUG Amazon.XRay.Recorder.Core.AWSXRayRecorderImpl - AWS_XRAY_CONTEXT_MISSING environment variable is set to LOG_ERROR. Override local value.
2020-04-14 16:04:22,078 [1] DEBUG Amazon.XRay.Recorder.Core.Internal.Utils.IPEndPointExtension - Determined that 127.0.0.1:2000 is an IP.
2020-04-14 16:04:22,078 [1] INFO Amazon.XRay.Recorder.Core.Internal.Utils.IPEndPointExtension - Using custom daemon address for UDP and TCP: 127.0.0.1:2000
2020-04-14 16:04:22,078 [1] DEBUG Amazon.XRay.Recorder.Core.Strategies.DefaultExceptionSerializationStrategy - Setting max stack frame size : 50
2020-04-14 16:04:22,078 [1] DEBUG Amazon.XRay.Recorder.Core.AWSXRayRecorderImpl - Context missing mode : RUNTIME_ERROR
2020-04-14 16:04:22,078 [1] DEBUG Amazon.XRay.Recorder.Core.AWSXRayRecorderImpl - AWS_XRAY_CONTEXT_MISSING environment variable is set to LOG_ERROR. Override local value.
2020-04-14 16:04:22,078 [1] DEBUG Amazon.XRay.Recorder.Core.AWSXRayRecorder - Using custom X-Ray recorder.
2020-04-14 16:04:22,079 [1] DEBUG Amazon.XRay.Recorder.Core.AWSXRayRecorderImpl - Context missing mode : RUNTIME_ERROR
2020-04-14 16:04:22,080 [1] DEBUG Amazon.XRay.Recorder.Core.AWSXRayRecorderImpl - AWS_XRAY_CONTEXT_MISSING environment variable is set to LOG_ERROR. Override local value.
2020-04-14 16:04:22,899 [4] DEBUG Amazon.XRay.Recorder.Handlers.AspNetCore.Internal.AWSXRayMiddleware - Trace header doesn't exist or not valid : (). Injecting a new one.
2020-04-14 16:04:22,911 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = localhost, path = /index.html, method = GET
2020-04-14 16:04:23,393 [4] DEBUG Amazon.XRay.Recorder.Handlers.AspNetCore.Internal.AWSXRayMiddleware - Trace header doesn't exist or not valid : (). Injecting a new one.
2020-04-14 16:04:23,394 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = localhost, path = /swagger/v1/swagger.json, method = GET
2020-04-14 16:04:27,497 [4] DEBUG Amazon.XRay.Recorder.Handlers.AspNetCore.Internal.AWSXRayMiddleware - Trace header doesn't exist or not valid : (). Injecting a new one.
2020-04-14 16:04:27,499 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = localhost, path = /WeatherForecast/GetWeather, method = GET
2020-04-14 16:04:27,602 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = , path = , method = 
2020-04-14 16:04:29,740 [4] DEBUG Amazon.XRay.Recorder.Handlers.AspNetCore.Internal.AWSXRayMiddleware - Trace header doesn't exist or not valid : (). Injecting a new one.
2020-04-14 16:04:29,741 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = localhost, path = /WeatherForecast/GetWeather, method = GET
2020-04-14 16:04:29,745 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = , path = , method = 
2020-04-14 16:04:30,149 [13] DEBUG Amazon.XRay.Recorder.Handlers.AspNetCore.Internal.AWSXRayMiddleware - Trace header doesn't exist or not valid : (). Injecting a new one.
2020-04-14 16:04:30,150 [13] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = localhost, path = /WeatherForecast/GetWeather, method = GET
2020-04-14 16:04:30,152 [13] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = , path = , method = 
2020-04-14 16:04:30,346 [4] DEBUG Amazon.XRay.Recorder.Handlers.AspNetCore.Internal.AWSXRayMiddleware - Trace header doesn't exist or not valid : (). Injecting a new one.
2020-04-14 16:04:30,346 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = localhost, path = /WeatherForecast/GetWeather, method = GET
2020-04-14 16:04:30,349 [4] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = , path = , method = 
2020-04-14 16:04:30,517 [13] DEBUG Amazon.XRay.Recorder.Handlers.AspNetCore.Internal.AWSXRayMiddleware - Trace header doesn't exist or not valid : (). Injecting a new one.
2020-04-14 16:04:30,518 [13] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = localhost, path = /WeatherForecast/GetWeather, method = GET
2020-04-14 16:04:30,529 [13] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Found a matching rule : (hostToMatch=*, httpMethodToMatch=Get, urlPathToMatch=*, fixedTarget=0, rate=0, description=Weather) for host = , path = , method = 
2020-04-14 16:30:02,682 [1] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Initializing with custom sampling configuration : sampling-rules.json

Question 1

Based on the output in the config file, is there any trace data being sent to the daemon? We can't see any errors from the output, log level is set to DEBUG. Can't definitively say it is sending trace data to although no errors.

Daemon Config & Logs

cfg.yaml

# Maximum buffer size in MB (minimum 3). Choose 0 to use 1% of host memory.
TotalBufferSizeMB: 0
# Maximum number of concurrent calls to AWS X-Ray to upload segment documents.
Concurrency: 8
# Send segments to AWS X-Ray service in a specific region
Region: "eu-west-1"
# Change the X-Ray service endpoint to which the daemon sends segment documents.
Endpoint: "xray.eu-west-1.amazonaws.com"
Socket:
  # Change the address and port on which the daemon listens for UDP packets containing segment documents.
  UDPAddress: "127.0.0.1:2000"
  # Change the address and port on which the daemon listens for HTTP requests to proxy to AWS X-Ray.
  TCPAddress: "127.0.0.1:2000"
Logging:
  LogRotation: true
  # Change the log level, from most verbose to least: dev, debug, info, warn, error, prod (default).
  LogLevel: "dev"
  # Output logs to the specified file path.
  LogPath: "xray.log"
# Turn on local mode to skip EC2 instance metadata check.
LocalMode: true
# Amazon Resource Name (ARN) of the AWS resource running the daemon.
ResourceARN: ""
# Assume an IAM role to upload segments to a different account.
RoleARN: "************************"
# Disable TLS certificate verification.
NoVerifySSL: false
# Upload segments to AWS X-Ray through a proxy.
ProxyAddress: ""
# Daemon configuration file format version.
Version: 2

Looking at the log file

2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] Skipped telemetry data as no segments found
2020-04-14T16:35:40+02:00 [Debug] telemetry: done!
2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] Segment batch: done!
2020-04-14T16:35:40+02:00 [Debug] processor: done!
2020-04-14T16:35:40+02:00 [Debug] Trace segment: received: 0, truncated: 0, processed: 0
2020-04-14T16:35:40+02:00 [Debug] Shutdown finished. Current epoch in nanoseconds: 1586874940496183800
2020-04-14T16:35:42+02:00 [Info] Initializing AWS X-Ray daemon 3.2.0
2020-04-14T16:35:42+02:00 [Debug] Listening on UDP 127.0.0.1:2000
2020-04-14T16:35:42+02:00 [Info] Using buffer memory limit of 80 MB
2020-04-14T16:35:42+02:00 [Info] 1280 segment buffers allocated
2020-04-14T16:35:42+02:00 [Debug] Using Endpoint read from Config file: xray.eu-west-1.amazonaws.com
2020-04-14T16:35:42+02:00 [Debug] Using proxy address: 
2020-04-14T16:35:42+02:00 [Debug] Fetch region eu-west-1 from commandline/config file
2020-04-14T16:35:42+02:00 [Info] Using region: eu-west-1
2020-04-14T16:35:42+02:00 [Debug] ARN of the AWS resource running the daemon: 
2020-04-14T16:35:42+02:00 [Debug] No Metadata set for telemetry records
2020-04-14T16:35:42+02:00 [Debug] Using Endpoint: https://xray.eu-west-1.amazonaws.com
2020-04-14T16:35:42+02:00 [Debug] Telemetry initiated
2020-04-14T16:35:42+02:00 [Info] HTTP Proxy server using X-Ray Endpoint : xray.eu-west-1.amazonaws.com
2020-04-14T16:35:42+02:00 [Debug] Using Endpoint: https://xray.eu-west-1.amazonaws.com
2020-04-14T16:35:42+02:00 [Debug] Batch size: 50

Question 2

Looking at the log file of the daemon, the line Trace segment: received: 0, truncated: 0, processed: 0 seems to indicate that it never received trace data? Why not, what are we missing? I'm suspecting that we are not instrumenting the application properly, but not sure.

Answer 1

For anyone that's interested. Herewith the solution to the problem (actually multiple problems)

Step 1 - Startup File Code

        public Startup(IConfiguration configuration)
        {
            AWSXRayRecorder.InitializeInstance(configuration: Configuration); // Inititalizing Configuration object with X-Ray recorder
            AWSSDKHandler.RegisterXRayForAllServices(); // All AWS SDK requests will be traced
        }

        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
           
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }
            
            //Make sure this is after env.IsDevelopment()
            app.UseXRay("WeatherForecast");
            .....
        }

Make sure appsettings.json and sampling-rules.json mimic's the Sample App

Once the code runs, the log file of the app would look something like this.

I felt that the AWS.SDK package generates a lot of noise even when using the Sample App, which I omitted here. That said, DEBUG logs tend to be that way.

2020-04-15 11:34:04,262 [5] INFO Amazon.XRay.Recorder.Core.Internal.Utils.DaemonConfig - The given daemonAddress () is invalid, using default daemon UDP and TCP address 127.0.0.1:2000.
2020-04-15 11:34:04,368 [5] INFO Amazon.Runtime.Internal.RuntimePipelineCustomizerRegistry - Applying runtime pipeline customization X-Ray Registration Customization
2020-04-15 11:34:04,389 [5] INFO Amazon.XRay.Recorder.Core.Sampling.DefaultSamplingStrategy - No effective centralized sampling rule match. Fallback to local rules.
2020-04-15 11:34:04,390 [5] DEBUG Amazon.XRay.Recorder.Core.Sampling.Local.LocalizedSamplingStrategy - Can't match a rule for host = localhost, path = /index.html, method = GET
2020-04-15 11:34:04,573 [5] DEBUG **Amazon.XRay.Recorder.Core.Internal.Emitters.UdpSegmentEmitter - UDP Segment emitter endpoint: 127.0.0.1:2000.**

Ultimately, you are looking for the last line Amazon.XRay.Recorder.Core.Internal.Emitters.UdpSegmentEmitter - UDP Segment emitter endpoint: 127.0.0.1:2000.

Step 2 - Configure the Daemon

If you install the Daemon as a Windows Service locally. I ran into a couple of additional problems.

A - It doesn't put everything in one place and it doesn't look at the configuration file that it extracted. Unless you put the cfg.yaml file in System32.

B - The service probably won't have access to the .aws folder where the credentials are stored.

I fixed problems A, by doing the following (i'm sure you could achieve the same goal in multiple ways)

Since i'm not a powershell expert, I just moved the extracted content to a folder of my choosing and modified the service path in the registry to point to that folder as well as added the appropriate flags so that it logs to the location you expect as well as use the cfg.yaml file you expect.

regedit -> Computer\HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\AWSXRayDaemon

Set image path with flags -f for log file and -c for config file

C:\YOUR USER\.aws\aws-xray-daemon\xray.exe -f C:\YOUR USER\.aws\aws-xray-daemon\xray-daemon.log -c C:\YOUR USER\.aws\aws-xray-daemon\cfg.yaml

The last problem was the Daemon not having the appropriate permissions to access the credentials file inside the .aws folder.

Log file will look something like this

2020-04-15T09:35:54+02:00 [Debug] processor: sending partial batch
2020-04-15T09:35:54+02:00 [Debug] processor: segment batch size: 1. capacity: 50
2020-04-15T09:35:54+02:00 [Error] Unable to sign request: NoCredentialProviders: no valid providers in chain. Deprecated.
    For verbose messaging see aws.Config.CredentialsChainVerboseErrors
2020-04-15T09:35:54+02:00 [Error] Sending segment batch failed with: NoCredentialProviders: no valid providers in chain. Deprecated.
    For verbose messaging see aws.Config.CredentialsChainVerboseErrors

The NoCredentialProviders line indicates a permission issue.

I then modified the service to run as an administrator, which solved problem B.

daemon.log

2020-04-15T09:41:31+02:00 [Debug] Received request on HTTP Proxy server : /GetSamplingRules
2020-04-15T09:41:32+02:00 [Debug] processor: sending partial batch
2020-04-15T09:41:32+02:00 [Debug] processor: segment batch size: 1. capacity: 50
2020-04-15T09:41:33+02:00 [Debug] Received request on HTTP Proxy server : /GetSamplingRules
2020-04-15T09:41:33+02:00 [Info] Successfully sent batch of 1 segments (0.871 seconds)
2020-04-15T09:41:34+02:00 [Debug] processor: sending partial batch
2020-04-15T09:41:34+02:00 [Debug] processor: segment batch size: 1. capacity: 50
2020-04-15T09:41:34+02:00 [Info] Successfully sent batch of 1 segments (0.197 seconds)

You are looking for the line successfully sent batch as confirmation that the Daemon sent the trace to the X-Ray service.

Hope this helps someone.

Cheers

Answer 2

By looking at the daemon logs looks like trace data is not sent to the service. I think instrumentation could be the issue. I would recommend you to read this documentation for instrumentation (https://docs.aws.amazon.com/xray/latest/devguide/xray-sdk-dotnet.html). You might have to instrument outgoing HTTP calls, incoming http request and outgoing AWS SDK calls in order to see trace view of your application. Hope this helps!