Debugging with the Log Table

With AddDataContextLogging() enabled, DataContextLoggingProvider is registered as an ILoggerProvider and log calls are persisted to the trax.log table. Three things filter what lands there: the configured minimum level, the category blacklist, and one category dropped unconditionally ahead of both, Microsoft.EntityFrameworkCore.Database.Command. That last one is worth knowing before you go looking for SQL in this table, because no configuration brings it back. An API host and a scheduler pointed at the same database write into the same table, so one psql session reads both instead of two console streams being correlated by hand.

What it does not give you is per-execution correlation. Read What a row holds before planning a query around it: there is no timestamp, no train name, and the column that would tie a row to a train run is never written.

What a row holds

Three things about that shape catch people out.

The level labels are lowercase. LogLevel is mapped to the trax.log_level Postgres enum declared in migration 002_log.sql, and the labels there are information, error and the rest. level = 'Error' matches nothing. The enum is ordered by severity, so level >= 'error' is the range comparison you want.

There is no timestamp column. id is the insert order and the only time axis the table has, which is why every query below orders by it. The primary key on id was dropped by migration 004_log_pkey.sql and restored by 021_log_performance.sql, which also added the ix_log_metadata_id index; 018_bigint_ids.sql widened id and metadata_id from integer.

metadata_id is always 0. Log.Create builds a row from level, message, category, event id and exception, and nothing on the write path sets MetadataId, whose setter is private. The index on the column, the dashboard's metadata detail page and the GraphQL logs query's metadataId filter are all wired for a correlation nothing produces.

Querying it

docker exec -it trax_database psql -U trax -d trax

-- recent activity
select id, level, category, message
from trax.log order by id desc limit 20;
 
-- failures only
select id, category, message, exception
from trax.log where level >= 'error' order by id desc limit 20;
 
-- everything one component logged
select id, level, message from trax.log
where category = 'MyApp.Trains.Combat.ResolveCombatTrain'
order by id desc limit 20;
 
-- free text, which is what stands in for a train filter
select id, level, category, message from trax.log
where message ilike '%order-4417%' order by id desc limit 50;

category is the ILogger category, which is the implementation type's FullName. That is the opposite convention from metadata.name, which stores the interface FullName (see Train Discovery). Filtering the log table by the interface name finds nothing, and filtering trax.metadata by the class name finds nothing.

Correlating a row with a train

The only link the schema offers is metadata_id, and since it is never written, the join returns nothing:

-- correct, and empty, until metadata_id is populated
select l.id, l.level, l.message
from trax.log l
join trax.metadata m on m.id = l.metadata_id
where m.external_id = '<external-id>'
order by l.id;

What works instead is to find the run in trax.metadata, which does carry the train name, the external id, the timing and the host, and then read the log rows on either side of it:

-- one train's history, from the table that actually stores the train name
select id, external_id, name, train_state, start_time, end_time, host_name
from trax.metadata
where name = 'MyApp.Trains.Combat.IResolveCombatTrain'
order by id desc limit 20;
 
-- a single execution: the metadata row is the whole record of it
select external_id, train_state, failure_junction, failure_reason, failure_exception,
       stack_trace, start_time, end_time
from trax.metadata where external_id = '<external-id>';
 
-- the log rows written around that run, narrowed by id range
select id, level, category, message from trax.log
where id between 128400 and 128900
order by id;

external_id is the identifier that survives a process boundary: an API writes it into trax.work_queue when it queues work and the scheduler carries it onto the trax.metadata row it creates. It never reaches trax.log.

Related tables

What the log table does not survive

DataContextLoggingProvider buffers into a bounded channel of 4096 and writes batches of up to 256 as entries arrive. When the host stops it writes what is already queued, waiting up to five seconds; only entries still queued after that are lost. A few consequences worth knowing before you treat an absent row as evidence:

• The channel is DropOldest, so a burst larger than the buffer silently discards the oldest entries.
• Every entry is made storable before it is queued: a NUL character is removed from the message, category, exception and stack trace, and a field cut to its column length is cut on a character boundary, never through the middle of an emoji. The message keeps 4000 UTF-16 units, the category 500, the exception message 2000 and the stack trace 4000.
• When a batch still fails, its entries are written one at a time, so an entry the database refuses costs its own line and not the rest of the batch. An entry that fails on its own is dropped rather than retried, on the grounds that a logging failure should not take the host down.

Console and structured logging providers still run alongside this one. The database table is the convenient shared view, not the system of record.

SDK Reference

AddDataContextLogging | Metadata