How-to guide

Debug across processes with the log table

Source DataContextLoggingProvider/

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, so the table never holds SQL and 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.

Each row written while a train runs names that run in metadata_id, so one run's lines can be read on their own. Read What a row holds before planning a query around it: there is no timestamp and no train name, and a line written outside any run names none.

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, whose labels 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. metadata_id is indexed (ix_log_metadata_id).

metadata_id is the run on the logging call's async flow. ServiceTrain.Run records its row on the run's own flow, and the logger reads it when the call is made, so a line logged by a junction, by anything the junction awaits, or by a lifecycle hook names the run. A train run inside a junction names its own run, and the outer run's lines name it again once the inner run returns. A line logged before the run's row has an id, or on a flow that is not a run's (startup, a hosted service's own loop, a background writer such as the log writer itself), stores 0. Rows written by versions that did not fill the column store 0 too.

The scheduler's polling is not on that list. The manifest manager and the job dispatcher are service trains that record a trax.metadata row for every poll, so the lines their junctions log name that internal run. Metadata cleanup deletes those rows, as it does for the scheduler's other internal trains, and because there is no foreign key the log lines keep the id of a run that no longer exists. The same holds for any run whose row is deleted: a metadata_id with no matching trax.metadata row is a deleted run, not a corrupt one. Join with left join, not join, when you want those lines too.

Querying it

Connect psql (or any client) to the database the hosts share, with the connection string they use:

psql "host=localhost dbname=trax user=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 Canonical train naming). 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

metadata_id joins a row to its run, so one execution's lines come back on their own:

-- every line one run wrote, in order
select l.id, l.level, l.category, 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;

trax.metadata carries the train name, the external id, the timing and the host. For what happened around a run (a hosted service's lines, or rows written before metadata_id was filled), read the log rows on either side of it by id:

-- 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. trax.log reaches it through metadata_id.

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. So an absent row is not evidence that nothing was logged:

• 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