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.MongoDb;
using ArxSamples.MongoDb.Operations.Create.AdvancedCases;

// The connection string comes from the environment, never from the code (see "Configure the connection").
var connectionString = Environment.GetEnvironmentVariable("ARX_SAMPLES_MONGODB")
    ?? throw new InvalidOperationException("Set the ARX_SAMPLES_MONGODB environment variable to your MongoDB 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.MongoDb.SampleOutput;

namespace ArxSamples.MongoDb.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 an account: 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 account = new ArxEntity("account");
        account["name"] = "Tailspin Toys";
        account["account_number"] = "ACC-M611";

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

        var query = new ArxQueryExpression("account");
        query.Criteria.AddCondition("account_number", ArxConditionOperator.Equal, "ACC-M611");
        await data.RetrieveMultipleAsync(query);

        /* ===========================================================
         * [DIRECT QUERY CHECK]
         * -----------------------------------------------------------
         * db.account.find({ account_number: "ACC-M611" }, { name: 1 })
         * -- Expect: 1 document, Tailspin Toys.
         * ===========================================================
         */
    }

    /// <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("account") { RecordId = ArxRecordId.Of("account_id", "000000000000000000000000") };
        nobody["name"] = "Nobody";

        try
        {
            await data.UpdateAsync(nobody);
        }
        catch (ArxException exception) when (exception.Code == ArxErrorCode.RecordNotFound)
        {
            logger.LogError(exception, "Renaming account {AccountId} failed: {Code}, transient: {IsTransient}",
                "000000000000000000000000", ArxException.FormatCode(exception.Code), exception.IsTransient);
        }

        /* ===========================================================
         * [DIRECT QUERY CHECK]
         * -----------------------------------------------------------
         * db.account.countDocuments({ name: "Nobody" })
         * -- Expect: 0 (the update found no account 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 account = new ArxEntity("account");
        account["name"] = "Wingtip Toys";
        account["account_number"] = "ACC-M612";
        await data.CreateAsync(account);

        Show("created Wingtip Toys: nothing logged");

        var gone = new ArxEntity("account") { RecordId = ArxRecordId.Of("account_id", "000000000000000000000000") };
        gone["name"] = "Gone";

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

        /* ===========================================================
         * [DIRECT QUERY CHECK]
         * -----------------------------------------------------------
         * db.account.find({ account_number: "ACC-M612" }, { name: 1 })
         * -- Expect: 1 document, Wingtip Toys.
         * ===========================================================
         */
    }

    /// <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.MongoDb;

/// <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 MongoDB driver 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.MongoDb;

/// <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 ARX service and its schema catalog, created once and shared by the samples.

using ARX.SDK.MongoDb.Services;
using ARX.SDK.Services;

namespace ArxSamples.MongoDb;

/// <summary>The application's ARX service and its schema catalog, shared by the real and advanced samples.</summary>
public sealed partial class SampleContext
{
    private ArxSchemaCatalog? _catalog;
    private ArxMongoDbService? _service;

    /// <summary>The application's schema catalog: collection ids, keys, lookups and selection sets (SampleCatalog.cs).</summary>
    public ArxSchemaCatalog Catalog => _catalog ??= SampleCatalog.Build();

    /// <summary>
    /// One service for the whole application. It shares one MongoDB client per connection string (a client is a
    /// connection pool), so make it once and keep it.
    /// </summary>
    public ArxMongoDbService Service => _service ??= new ArxMongoDbService(ConnectionString, Catalog);
}

The application's schema catalog: every table's id column and keys, and its selection sets.

using ARX.SDK.Services;

namespace ArxSamples.MongoDb;

/// <summary>An account's industry. Stored in account.industry as the enum's number.</summary>
public enum Industry
{
    Retail = 1,
    Manufacturing = 2,
    Healthcare = 3,
    Finance = 4,
    Technology = 5
}

/// <summary>
/// The application's schema catalog: every collection's id and keys, the lookups between collections, and every
/// picklist (selection set), defined once.
/// </summary>
/// <remarks>
/// <para>
/// <b>Ids.</b> On MongoDB the declared id is the document's <c>_id</c>, named in your code by the column you declare
/// (<c>account["account_id"]</c>). A generated string id is an ObjectId ARX makes before the insert and gives back as its
/// 24-character text; a generated Guid is one ARX makes; a supplied id is yours (a country code, a SKU). MongoDB has no
/// sequences, so a generated number isn't offered, and every document has an <c>_id</c>, so there is no NoIdColumn.
/// </para>
/// <para>
/// <b>Keys.</b> Business keys (an account number; a region and a SKU together) let Update, Delete and Retrieve find
/// documents by them. MongoDB enforces them with unique indexes: the sample database has one for each.
/// </para>
/// <para>
/// <b>Lookups.</b> MongoDB has no foreign keys, so the catalog says which field refers to which collection
/// (<c>.Lookup("contact", "account_id", "account")</c>). ARX stores the referenced id as it is stored there (an ObjectId)
/// and reads the field back as an <see cref="ArxEntityReference"/> with the referenced record's display name.
/// </para>
/// <para>
/// <b>Selection sets.</b> A field that only accepts a fixed list of codes: an account's status, a contact's preferred
/// channels (several codes, stored as an array). ARX checks every <see cref="ArxSelectionSetValue"/> against the catalog
/// before anything is sent and stores the codes themselves.
/// </para>
/// </remarks>
public static class SampleCatalog
{
    public static ArxSchemaCatalog Build() => ArxSchemaCatalog.Create()
        .Table("account", ArxIdColumn.Generated<string>("account_id"))
        .Key("account", "account_number")
        .DisplayName("account", "name")
        .Table("contact", ArxIdColumn.Generated<string>("contact_id"))
        .Key("contact", "email")
        .Lookup("contact", "account_id", "account")
        .DisplayName("contact", new[] { "first_name", "last_name" }, " ")
        .Table("country", ArxIdColumn.Supplied<string>("code"))
        .DisplayName("country", "name")
        .Table("product", ArxIdColumn.Supplied<string>("sku"))
        .DisplayName("product", "name")
        .Table("price_list", ArxIdColumn.Generated<string>("price_id"))
        .Key("price_list", "region", "sku")
        .Lookup("price_list", "region", "country")
        .Table("sales_order", ArxIdColumn.Generated<Guid>("order_id"))
        .Key("sales_order", "order_number")
        .Lookup("sales_order", "account_id", "account")
        .Table("activity_log", ArxIdColumn.Generated<string>("log_id"))
        .AddEnum<Industry>("Industry")
        .Add("AccountStatus", ArxSelectionSetKind.String, ("ACTIVE", "Active"), ("ON_HOLD", "On hold"), ("CLOSED", "Closed"))
        .Add("ContactChannels", ArxSelectionSetKind.String, ArxSelectionSetMultiplicity.Array, ("E", "Email"), ("P", "Phone"), ("S", "SMS"))
        .Build();
}

The plain MongoDB.Driver read-back helper, for the samples that show what MongoDB stored.

namespace ArxSamples.MongoDb;

/// <summary>The plain MongoDB driver outside the SDK, for the samples that show what MongoDB stored.</summary>
public sealed partial class SampleContext
{
    private MongoDirectHelper? _direct;

    /// <summary>The plain MongoDB driver outside the SDK, used only to reset the database and to show what was stored.</summary>
    public MongoDirectHelper Direct => _direct ??= new MongoDirectHelper(ConnectionString);
}

Plain MongoDB.Driver, not part of ARX: reads rows back so a sample can show what MongoDB stored.

using MongoDB.Bson;
using MongoDB.Driver;

namespace ArxSamples.MongoDb;

/// <summary>
/// The plain MongoDB driver, outside the SDK: it resets the sample database from Schema/sample-schema.json and shows
/// what was stored. Samples never write through it.
/// </summary>
public sealed class MongoDirectHelper
{
    private readonly IMongoDatabase _database;

    public MongoDirectHelper(string connectionString)
    {
        var url = MongoUrl.Create(connectionString);
        _database = new MongoClient(url).GetDatabase(url.DatabaseName ?? "arx_samples");
    }

    /// <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>Drops the sample database and makes its collections, indexes and validators again.</summary>
    public async Task ResetAsync()
    {
        var schema = BsonDocument.Parse(await File.ReadAllTextAsync(SchemaPath()));

        foreach (var collection in schema["collections"].AsBsonArray.Select(x => x.AsBsonDocument))
        {
            var name = collection["name"].AsString;

            // Only the collections the schema lists are dropped and made again: anything else in the database is left alone.
            await _database.DropCollectionAsync(name);
            var options = new CreateCollectionOptions<BsonDocument>();

            if (collection.TryGetValue("validator", out var validator))
            {
                options.Validator = validator.AsBsonDocument;
            }

            await _database.CreateCollectionAsync(name, options);

            foreach (var index in collection.GetValue("indexes", new BsonArray()).AsBsonArray.Select(x => x.AsBsonDocument))
            {
                var keys = index["keys"].AsBsonDocument;
                var indexOptions = new CreateIndexOptions<BsonDocument> { Unique = index.GetValue("unique", false).AsBoolean };

                if (index.GetValue("partial", false).AsBoolean)
                {
                    indexOptions.PartialFilterExpression = new BsonDocument(keys.Names.Select(x => new BsonElement(x, new BsonDocument("$exists", true))));
                }

                await _database.GetCollection<BsonDocument>(name).Indexes.CreateOneAsync(new CreateIndexModel<BsonDocument>(keys, indexOptions));
            }
        }
    }

    /// <summary>The stored documents a filter finds, as MongoDB's JSON, one line each.</summary>
    public async Task<IReadOnlyList<string>> FindAsync(string collection, string filterJson)
    {
        var documents = await _database.GetCollection<BsonDocument>(collection).Find(BsonDocument.Parse(filterJson)).ToListAsync();
        return documents.Select(x => x.ToJson()).ToList();
    }
}

  > 1. One line per call
      Information: ARX Create account took 93.4 ms
      Information: ARX Retrieve account took 54.2 ms
      Information: ARX RetrieveMultiple account took 8.6 ms
  > 2. A failed call, with its code
      Warning: ARX Update account failed with ARX2002 after 28.3 ms
      Error: Renaming account 000000000000000000000000 failed: ARX2002 RecordNotFound, transient: False [ArxException]
  > 3. Only what production needs
      created Wingtip Toys: nothing logged
      Warning: ARX Update account failed with ARX2002 after 2.1 ms
      caught ArxException: ARX2002 RecordNotFound: Update of 'account': no document matched the entity's id (field account_id).