Log every call through ILogger

Runs the sample. Generated for this page; it reads the connection string from the environment and first remakes the sample database from sample-schema.json.

using ArxSamples.DynamoDb;
using ArxSamples.DynamoDb.Operations.Create.AdvancedCases;

// The connection string comes from the environment, never from the code (see "Configure the connection").
var connectionString = Environment.GetEnvironmentVariable("ARX_SAMPLES_DYNAMODB")
    ?? throw new InvalidOperationException("Set the ARX_SAMPLES_DYNAMODB environment variable to your Amazon DynamoDB connection string.");

var dbContext = new SampleContext(connectionString);

// Every run starts from the sample data: this deletes and makes again what sample-schema.json lists
// (save the file in the project folder, see Get started).
await dbContext.Direct.ResetAsync();

await new Advanced6_LogEveryCall().RunAsync(dbContext);

The sample, as it is in the repository.

using System.Diagnostics;
using ARX.SDK;
using ARX.SDK.Query;
using ARX.SDK.Services;
using Microsoft.Extensions.Logging;
using static ArxSamples.DynamoDb.SampleOutput;

namespace ArxSamples.DynamoDb.Operations.Create.AdvancedCases;

/// <summary>
/// Log every ARX call through ILogger, in three scenarios: one line per call with its table and how long it took, a failed
/// call with its ARX code (and the exception logged where it is caught), and only the calls worth keeping in production.
/// </summary>
/// <remarks>
/// <para>ARX has no logger of its own and takes no logging package: every call is an activity of the <c>ARX.SDK</c>
/// ActivitySource. <c>ArxCallLog</c>, below, listens to those activities and writes one log line per call: copy it into
/// your application and give it the <c>ILogger</c> you already have (<c>ILogger&lt;T&gt;</c> from dependency injection),
/// once, at startup. Here a small logger prints to the console, so the sample's output stays in order.</para>
/// <para>A line names the operation and the table, never the values sent: what ARX logs is safe to keep. An exception's
/// message is written the same way, so it can be logged where it is caught.</para>
/// </remarks>
public sealed class Advanced6_LogEveryCall : ISample
{
    public string Name => "create-advanced-6-log-every-call";

    public string Title => "Log every call through ILogger";

    public async Task RunAsync(SampleContext dbContext)
    {
        ILogger logger = new ConsoleLineLogger();

        await Scenario1_OneLinePerCallAsync(dbContext.Service, logger);

        await Scenario2_AFailedCallAsync(dbContext.Service, logger);

        await Scenario3_OnlyWhatProductionNeedsAsync(dbContext.Service, logger);
    }

    /// <summary>1. Create, read and query a product: one Information line each, with the table and the time it took.</summary>
    private static async Task Scenario1_OneLinePerCallAsync(IArxDataService data, ILogger logger)
    {
        Step("1. One line per call");

        using var callLog = new ArxCallLog(logger);

        var product = new ArxEntity("product");
        product["sku"] = "SKU-D611";
        product["name"] = "Trail running shoe";

        ArxRecordId id = await data.CreateAsync(product);
        await data.RetrieveAsync("product", id);

        var query = new ArxQueryExpression("product");
        query.Criteria.AddCondition("sku", ArxConditionOperator.Equal, "SKU-D611");
        await data.RetrieveMultipleAsync(query);

        /* ===========================================================
         * [DIRECT QUERY CHECK]
         * -----------------------------------------------------------
         * SELECT "name" FROM "product" WHERE "sku" = 'SKU-D611'
         * -- Expect: 1 item, Trail running shoe.
         * ===========================================================
         */
    }

    /// <summary>2. A call that fails: the listener logs a Warning with its ARX code; the code that caught it logs the exception.</summary>
    private static async Task Scenario2_AFailedCallAsync(IArxDataService data, ILogger logger)
    {
        Step("2. A failed call, with its code");

        using var callLog = new ArxCallLog(logger);

        var nobody = new ArxEntity("product") { RecordId = ArxRecordId.Of("sku", "SKU-D699") };
        nobody["name"] = "Nobody";

        try
        {
            await data.UpdateAsync(nobody);
        }
        catch (ArxException exception) when (exception.Code == ArxErrorCode.RecordNotFound)
        {
            logger.LogError(exception, "Renaming product {Sku} failed: {Code}, transient: {IsTransient}",
                "SKU-D699", ArxException.FormatCode(exception.Code), exception.IsTransient);
        }

        /* ===========================================================
         * [DIRECT QUERY CHECK]
         * -----------------------------------------------------------
         * SELECT "sku" FROM "product" WHERE "sku" = 'SKU-D699'
         * -- Expect: no items (the update found no product to change).
         * ===========================================================
         */
    }

    /// <summary>3. In production, log failures only: a create that works writes nothing; an update that fails writes its line.</summary>
    private static async Task Scenario3_OnlyWhatProductionNeedsAsync(IArxDataService data, ILogger logger)
    {
        Step("3. Only what production needs");

        using var callLog = new ArxCallLog(logger, logSuccessfulCalls: false);

        var product = new ArxEntity("product");
        product["sku"] = "SKU-D612";
        product["name"] = "Hiking boot";
        await data.CreateAsync(product);

        Show("created Hiking boot: nothing logged");

        var gone = new ArxEntity("product") { RecordId = ArxRecordId.Of("sku", "SKU-D698") };
        gone["name"] = "Gone";

        try
        {
            await data.UpdateAsync(gone);
        }
        catch (ArxException exception) when (exception.Code == ArxErrorCode.RecordNotFound)
        {
            ShowError(exception);
        }

        /* ===========================================================
         * [DIRECT QUERY CHECK]
         * -----------------------------------------------------------
         * SELECT "name" FROM "product" WHERE "sku" = 'SKU-D612'
         * -- Expect: 1 item, Hiking boot.
         * ===========================================================
         */
    }

    /// <summary>
    /// Writes each ARX call to an ILogger: Information when it worked (unless turned off), Warning with its ARX code when
    /// it failed. Create one at startup with your application's logger and keep it for the application's lifetime.
    /// </summary>
    private sealed class ArxCallLog : IDisposable
    {
        private readonly ActivityListener _listener;

        public ArxCallLog(ILogger logger, bool logSuccessfulCalls = true)
        {
            _listener = new ActivityListener
            {
                ShouldListenTo = source => source.Name == ArxDiagnostics.SourceName,
                Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData,
                ActivityStopped = activity => Write(logger, activity, logSuccessfulCalls)
            };

            ActivitySource.AddActivityListener(_listener);
        }

        public void Dispose() => _listener.Dispose();

        private static void Write(ILogger logger, Activity activity, bool logSuccessfulCalls)
        {
            var milliseconds = Math.Round(activity.Duration.TotalMilliseconds, 1);

            if (activity.Status == ActivityStatusCode.Error)
            {
                logger.LogWarning("ARX {Call} failed with {Code} after {Milliseconds} ms", activity.DisplayName, activity.GetTagItem("arx.error.code"), milliseconds);
            }
            else if (logSuccessfulCalls)
            {
                logger.LogInformation("ARX {Call} took {Milliseconds} ms", activity.DisplayName, milliseconds);
            }
        }
    }

    /// <summary>The sample's stand-in for your application's logger: each entry on its own line, in order.</summary>
    private sealed class ConsoleLineLogger : ILogger
    {
        public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;

        public bool IsEnabled(LogLevel logLevel) => true;

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
            => Show($"{logLevel}: {formatter(state, exception)}" + (exception is null ? string.Empty : $" [{exception.GetType().Name}]"));
    }
}

What every sample is given: the connection string (and the ISample interface the samples implement).

namespace ArxSamples.DynamoDb;

/// <summary>One documentation sample: a scenario a real application has, shown end to end.</summary>
public interface ISample
{
    /// <summary>The name to run it alone: <c>dotnet run -- &lt;name&gt;</c>.</summary>
    string Name { get; }

    /// <summary>One line on what it shows.</summary>
    string Title { get; }

    Task RunAsync(SampleContext dbContext);
}

/// <summary>
/// What a sample is given. Every sample gets the connection string; the application's service and catalog
/// (SampleContext.Application.cs) and the plain AWS SDK read-back helper (SampleContext.Direct.cs) live in their own
/// files, so a sample needs only the files it uses.
/// </summary>
public sealed partial class SampleContext
{
    public SampleContext(string connectionString)
    {
        ConnectionString = connectionString;
    }

    public string ConnectionString { get; }
}

How the samples print: Step for each scenario, Show for what it did, ShowError for an error caught on purpose.

using ARX.SDK;

namespace ArxSamples.DynamoDb;

/// <summary>How the samples print: a numbered step for each scenario, then what it did.</summary>
public static class SampleOutput
{
    /// <summary>The start of a scenario: <c>Step("1. By the id Create returned")</c>.</summary>
    public static void Step(string text) => Console.WriteLine($"  > {text}");

    /// <summary>What the scenario did.</summary>
    public static void Show(string text) => Console.WriteLine($"      {text}");

    /// <summary>An ARX error the scenario caught on purpose.</summary>
    public static void ShowError(ArxException exception)
        => Console.WriteLine($"      caught {exception.GetType().Name}: {exception.Message}");
}

The application's DynamoDB client, model, schema catalog and ARX service, created once and shared by the samples.

using Amazon.DynamoDBv2;
using Amazon.Runtime;
using ARX.SDK.DynamoDb.Model;
using ARX.SDK.DynamoDb.Services;
using ARX.SDK.Services;

namespace ArxSamples.DynamoDb;

/// <summary>The application's DynamoDB client, model, catalog and ARX service, shared by the samples.</summary>
public sealed partial class SampleContext
{
    private IAmazonDynamoDB? _client;
    private ArxDynamoModel? _model;
    private ArxSchemaCatalog? _catalog;
    private ArxDynamoDbService? _service;

    /// <summary>
    /// The DynamoDB client for the endpoint the connection string names. Credentials come from the AWS SDK's own chain
    /// (environment, profile, role), never from code; DynamoDB Local on this machine accepts any, so a local endpoint
    /// without credentials in the environment gets placeholder ones.
    /// </summary>
    public IAmazonDynamoDB Client => _client ??= CreateClient(ConnectionString);

    /// <summary>How the entities are laid out (SampleModel.cs).</summary>
    public ArxDynamoModel Model => _model ??= SampleModel.Build();

    /// <summary>The ids, lookups and selection sets (SampleModel.cs).</summary>
    public ArxSchemaCatalog Catalog => _catalog ??= SampleModel.Catalog();

    /// <summary>One service for the whole application: it holds no connection.</summary>
    public ArxDynamoDbService Service => _service ??= new ArxDynamoDbService(Client, Model, Catalog);

    private static IAmazonDynamoDB CreateClient(string endpoint)
    {
        var config = new AmazonDynamoDBConfig { ServiceURL = endpoint, AuthenticationRegion = Environment.GetEnvironmentVariable("AWS_REGION") ?? "us-east-1" };
        var local = Uri.TryCreate(endpoint, UriKind.Absolute, out var uri) && (uri.IsLoopback || uri.Host == "localhost");

        return local && Environment.GetEnvironmentVariable("AWS_ACCESS_KEY_ID") == null
            ? new AmazonDynamoDBClient(new BasicAWSCredentials("local", "local"), config)
            : new AmazonDynamoDBClient(config);
    }
}

How the application lays out its entities in Amazon DynamoDB, and its schema catalog.

using ARX.SDK.DynamoDb.Model;
using ARX.SDK.Services;

namespace ArxSamples.DynamoDb;

/// <summary>
/// How the application lays out its entities in DynamoDB, in both designs, and its schema catalog.
/// </summary>
/// <remarks>
/// <para>
/// <b>A table per entity:</b> <c>product</c> has a table of its own, keyed by its <c>sku</c>; <c>lead</c> by its
/// <c>email</c>. The entity's attributes are the item's, keys included.
/// </para>
/// <para>
/// <b>A single table:</b> <c>crm</c> holds customers and their orders together. Each entity's keys are templates:
/// a customer is <c>PK = CUSTOMER#{customer_id}</c>, <c>SK = PROFILE</c>; an order shares its customer's partition,
/// <c>SK = ORDER#{order_number}</c>, so one query reads a customer with its orders. ARX writes the keys, the
/// <c>entity_type</c> attribute that tells the items apart, and the index keys (<c>GSI1</c>: orders by status and date).
/// </para>
/// <para>
/// <b>Write sharding:</b> <c>events</c> spreads the page views of one page over four partitions (a suffix from a hash of
/// the time), so a popular page doesn't overload one partition; ARX reads them back merged.
/// </para>
/// <para>
/// <b>The catalog</b> declares each entity's id (supplied: DynamoDB generates none, so ids come from the application),
/// the lookup from an order to its customer, the customer's display name and the order statuses.
/// </para>
/// </remarks>
public static class SampleModel
{
    public static ArxDynamoModel Build() => ArxDynamoModel.Create()
        .Table("product", partitionKey: "sku")
        .Table("lead", partitionKey: "email")
        .SingleTable("crm", "PK", "SK", crm => crm
            .Entity("customer", pk: "CUSTOMER#{customer_id}", sk: "PROFILE")
            .Entity("sales_order", pk: "CUSTOMER#{customer_id}", sk: "ORDER#{order_number}")
            .Index("GSI1", "GSI1PK", "GSI1SK")
            .EntityIndex("sales_order", "GSI1", pk: "STATUS#{status}", sk: "{ordered_on}"))
        .SingleTable("events", "PK", "SK", events => events
            .Entity("page_view", pk: "PAGE#{page}", sk: "VIEW#{viewed_at}"))
        .WriteSharding("page_view", shards: 4, by: "viewed_at")
        .Build();

    public static ArxSchemaCatalog Catalog() => ArxSchemaCatalog.Create()
        .Table("product", ArxIdColumn.Supplied<string>("sku"))
        .DisplayName("product", "name")
        .Table("lead", ArxIdColumn.Supplied<string>("email"))
        .Table("customer", ArxIdColumn.Supplied<string>("customer_id"))
        .DisplayName("customer", "name")
        .Table("sales_order", ArxIdColumn.Supplied<string>("order_number"))
        .Lookup("sales_order", "customer_id", "customer")
        .Table("page_view", ArxIdColumn.Supplied<string>("viewed_at"))
        .Add("OrderStatus", ArxSelectionSetKind.String, ("OPEN", "Open"), ("SHIPPED", "Shipped"), ("CANCELLED", "Cancelled"))
        .Build();
}

The plain AWSSDK.DynamoDBv2 read-back helper, for the samples that show what Amazon DynamoDB stored.

namespace ArxSamples.DynamoDb;

/// <summary>The plain AWS SDK outside ARX, for the samples that show what DynamoDB stored.</summary>
public sealed partial class SampleContext
{
    private DynamoDirectHelper? _direct;

    /// <summary>The plain AWS SDK outside ARX, used only to reset the tables and to show what was stored.</summary>
    public DynamoDirectHelper Direct => _direct ??= new DynamoDirectHelper(Client);
}

Plain AWSSDK.DynamoDBv2, not part of ARX: reads rows back so a sample can show what Amazon DynamoDB stored.

using System.Text.Json;
using Amazon.DynamoDBv2;
using Amazon.DynamoDBv2.Model;

namespace ArxSamples.DynamoDb;

/// <summary>
/// The plain AWS SDK, outside ARX: it resets the sample tables from Schema/sample-schema.json and runs the PartiQL
/// statements of the samples' checks. Samples never write through it.
/// </summary>
public sealed class DynamoDirectHelper
{
    private readonly IAmazonDynamoDB _client;

    public DynamoDirectHelper(IAmazonDynamoDB client)
    {
        _client = client;
    }

    /// <summary>
    /// The sample schema: Schema/sample-schema.json next to the program (the samples' own project), or sample-schema.json
    /// in the project folder (a sample copied from its page, as Get started says).
    /// </summary>
    private static string SchemaPath()
    {
        var candidates = new[]
        {
            Path.Combine(AppContext.BaseDirectory, "Schema", "sample-schema.json"),
            Path.Combine(Directory.GetCurrentDirectory(), "sample-schema.json"),
            Path.Combine(Directory.GetCurrentDirectory(), "Schema", "sample-schema.json")
        };

        return candidates.FirstOrDefault(File.Exists)
            ?? throw new FileNotFoundException("sample-schema.json isn't in the project folder: download it from the Get started page and save it next to Program.cs.");
    }

    /// <summary>
    /// Deletes and creates every table sample-schema.json lists, with its keys and indexes; no other table is touched. It
    /// runs only against DynamoDB Local (a localhost endpoint): set ARX_SAMPLES_ALLOW_REMOTE_RESET=1 to reset the sample
    /// tables of a real AWS account deliberately.
    /// </summary>
    public async Task ResetAsync()
    {
        var endpoint = _client.Config.ServiceURL ?? string.Empty;
        var local = Uri.TryCreate(endpoint, UriKind.Absolute, out var uri) && (uri.IsLoopback || uri.Host.Equals("localhost", StringComparison.OrdinalIgnoreCase));

        if (!local && Environment.GetEnvironmentVariable("ARX_SAMPLES_ALLOW_REMOTE_RESET") != "1")
        {
            throw new InvalidOperationException(
                $"The samples reset their tables (delete and create them), and the client points at '{(endpoint.Length == 0 ? "AWS" : endpoint)}', not DynamoDB Local. "
                + "Point it at http://localhost:8000 (or your DynamoDB Local port), or set ARX_SAMPLES_ALLOW_REMOTE_RESET=1 to reset the sample tables there.");
        }

        using var schema = JsonDocument.Parse(await File.ReadAllTextAsync(SchemaPath()));

        foreach (var table in schema.RootElement.GetProperty("tables").EnumerateArray())
        {
            var name = table.GetProperty("name").GetString()!;

            try
            {
                await _client.DeleteTableAsync(name);
            }
            catch (ResourceNotFoundException)
            {
            }

            var definitions = new Dictionary<string, string>();
            var keys = Keys(table, definitions);
            var request = new CreateTableRequest { TableName = name, KeySchema = keys, BillingMode = BillingMode.PAY_PER_REQUEST };

            if (table.TryGetProperty("indexes", out var indexes))
            {
                request.GlobalSecondaryIndexes = indexes.EnumerateArray().Select(index => new GlobalSecondaryIndex
                {
                    IndexName = index.GetProperty("name").GetString(),
                    KeySchema = Keys(index, definitions),
                    Projection = new Projection { ProjectionType = ProjectionType.ALL }
                }).ToList();
            }

            request.AttributeDefinitions = definitions.Select(x => new AttributeDefinition(x.Key, x.Value)).ToList();
            await _client.CreateTableAsync(request);
        }
    }

    private static List<KeySchemaElement> Keys(JsonElement table, Dictionary<string, string> definitions)
    {
        var keys = new List<KeySchemaElement>();
        var pk = table.GetProperty("partitionKey").GetString()!;
        definitions[pk] = table.TryGetProperty("partitionKeyType", out var pkType) ? pkType.GetString()! : "S";
        keys.Add(new KeySchemaElement(pk, KeyType.HASH));

        if (table.TryGetProperty("sortKey", out var sk))
        {
            definitions[sk.GetString()!] = table.TryGetProperty("sortKeyType", out var skType) ? skType.GetString()! : "S";
            keys.Add(new KeySchemaElement(sk.GetString(), KeyType.RANGE));
        }

        return keys;
    }

    /// <summary>The items a PartiQL statement finds, as JSON, one line each.</summary>
    public async Task<IReadOnlyList<string>> QueryAsync(string statement)
    {
        var response = await _client.ExecuteStatementAsync(new ExecuteStatementRequest { Statement = statement, ConsistentRead = true });
        return response.Items.Select(item => JsonSerializer.Serialize(item.ToDictionary(x => x.Key, x => x.Value.S ?? x.Value.N ?? (x.Value.IsBOOLSet ? x.Value.BOOL.ToString() : "…")))).ToList();
    }
}

  > 1. One line per call
      Information: ARX Create product took 37.7 ms
      Information: ARX Retrieve product took 17.3 ms
      Information: ARX RetrieveMultiple product took 50.8 ms
  > 2. A failed call, with its code
      Warning: ARX Update product failed with ARX2002 after 49.3 ms
      Error: Renaming product SKU-D699 failed: ARX2002 RecordNotFound, transient: False [ArxDatabaseException]
  > 3. Only what production needs
      created Hiking boot: nothing logged
      Warning: ARX Update product failed with ARX2002 after 4.1 ms
      caught ArxDatabaseException: ARX2002 RecordNotFound: Update of 'product': no item has the key.