Logging and tracing

Every public operation of every provider (Create, Retrieve, Update, Delete, their Multiple forms, Execute, the server check) is one activity of the ARX.SDK ActivitySource and one measurement of the ARX.SDK Meter (ArxDiagnostics.SourceName). A call that makes other calls inside it is counted once.

What	Value
Activity name	The operation and the table: Create account, RetrieveMultiple product
Activity kind	Client
Tags	db.system.name (the database), db.operation.name, db.collection.name (the table), arx.provider
On failure	Status Error, arx.error.code (ARX2002), and error.type: the ARX code, cancelled for a cancelled call, or the type of any other exception
Metrics	arx.operation.duration (seconds) and arx.operation.errors, tagged with the database, operation, table and provider, and error.type on a failure

Names are recorded, never the values a call sends or reads, so what ARX records is safe to keep in logs. Without a listener, a call costs one check.

An ActivityListener turns those activities into log lines. The "Log every call through ILogger" sample of each provider has a class, ArxCallLog, to copy into your application: it listens to the ARX.SDK source and writes one line per call to the ILogger you give it, Information when the call worked and Warning, with its ARX code, when it failed:

Information: ARX Create account took 4.2 ms
Warning: ARX Update account failed with ARX2002 after 1.9 ms

Create it once, at startup, with your application's logger (ILogger<T> from dependency injection), and keep it for the application's lifetime: disposing it stops the logging. The lines are structured ({Call}, {Code}, {Milliseconds}), so a log store can filter and count them.

The samples, one per provider: PostgreSQL, SQL Server, MySQL, MongoDB, DynamoDB.

One line per call is useful while you develop, and a lot in production, where one request can make several calls. Common choices:

• Failures only: the sample's logSuccessfulCalls: false. A call that worked writes nothing; one that failed writes its Warning.
• Successful calls at Debug: change LogInformation to LogDebug, and let the log level decide.
• Slow calls: write a successful call only when activity.Duration is over a threshold you choose.

Counting and timing every call is the metrics' job (below), not the log's.

Where your code catches an ArxException, log it with what it carries: Code (ArxException.FormatCode(code) gives ARX2002 RecordNotFound), Category, IsTransient, EntityName and AttributeName where known, the database's own code (SqlState or NativeCode), and the driver's exception as InnerException. ARX writes its messages without the values sent, so Message can go to the log as it is. The driver's exception can quote them (MySQL and MongoDB repeat a duplicate key's value), so log the message and the codes rather than the exception object, whose ToString() includes the inner one:

catch (ArxException exception) when (exception.Code == ArxErrorCode.UniqueViolation)
{
    logger.LogError("Renaming account {AccountId} failed: {Code} {NativeCode}, transient: {IsTransient}. {Message}",
        accountId, ArxException.FormatCode(exception.Code), exception.NativeCode, exception.IsTransient, exception.Message);
}

Pass the exception itself (logger.LogError(exception, …)) only where the values in it may be logged, for example in development.

What each code means, and which ones to retry: Errors in practice.

With OpenTelemetry, add the source and the meter; ARX's calls then appear in your traces, under the request that made them, and in your metrics:

builder.Services.AddOpenTelemetry()
    .WithTracing(tracing => tracing.AddSource(ArxDiagnostics.SourceName))
    .WithMetrics(metrics => metrics.AddMeter(ArxDiagnostics.SourceName));

The "Set the service up for production" samples read the same activities and metrics with a plain ActivityListener and MeterListener, without any package. More on running ARX in production: Running in production.

Below ARX, each database driver has its own logging and diagnostics: Npgsql, Microsoft.Data.SqlClient, MySqlConnector, the MongoDB driver and the AWS SDK. They see the statements sent and, in some, the parameter values when you turn that on. Configure them as their own documentation says, and keep value logging off in production.

ARX has no API that returns its SQL; the driver or the database shows it. Every value is a parameter ($1, @p0), so a statement shows placeholders, and the values only where you turn their logging on.

PostgreSQL: Npgsql logs each command through Microsoft.Extensions.Logging, under the category Npgsql.Command, at Debug level. Turn it on once, before the first connection:

using Microsoft.Extensions.Logging;
using Npgsql;

NpgsqlLoggingConfiguration.InitializeLogging(
    LoggerFactory.Create(builder => builder.AddConsole().SetMinimumLevel(LogLevel.Debug)),
    parameterLoggingEnabled: false);   // true shows the values too: never in production

A create then logs, for example, Executing command: INSERT INTO "account" ("name", "city", "employee_count") VALUES ($1, $2, $3) RETURNING "id". (AddConsole is in the Microsoft.Extensions.Logging.Console package.)

SQL Server: the statements are in the server's plan cache: SELECT t.text FROM sys.dm_exec_query_stats s CROSS APPLY sys.dm_exec_sql_text(s.sql_handle) t, or capture them with an Extended Events session on sql_batch_completed.

MySQL: performance_schema keeps a digest per statement shape: SELECT DIGEST_TEXT, COUNT_STAR FROM performance_schema.events_statements_summary_by_digest ORDER BY LAST_SEEN DESC.

MongoDB: the database profiler records the operations: db.setProfilingLevel(2), then db.system.profile.find() (set it back to 0 afterwards).

DynamoDB: there is no SQL; ARX sends the AWS API's requests (PutItem, Query, TransactWriteItems) through the IAmazonDynamoDB client you create, so the AWS SDK's own logging shows them.