Unreliable logging in data factory pipelines

In this post I take a look at discrepancies between values obtained from data factory pipeline execution and those reported in activity logs.

I came across this situation when looking at a client's implementation of some data factory pipelines. For ease of reviewing pipeline run information, this client logs information about pipeline runs explicitly, in a database table.

The general pattern for a pipeline is to log its start, do the necessary work, then log its completion and outcome:

I've mocked this up in a simple Fabric data factory pipeline (above):

• the Log pipeline start activity calls a database stored procedure (SP) to write the pipeline's run ID and start time into a new log record
• the Wait activity takes the place of the actual work that a pipeline might perform
• the Log pipeline end activity calls another SP to update the pipeline's log record with the execution end time

The screenshot shows a Stored procedure activity calling a database SP named [dbo].[LogPipelineEnd] and passing two parameter values: the pipeline's run ID (@pipeline.RunId()) and the current date and time (@utcNow()). The stored procedure updates the log record created earlier in the pipeline like this:

CREATE PROCEDURE [dbo].[LogPipelineEnd] (
  @PipelineRunId CHAR(36)
, @EndDateTime DATETIME2(7)
)
AS
 
UPDATE dbo.PipelineRun
SET EndDateTime = @EndDateTime
WHERE PipelineRunId = @PipelineRunId;

When I run the pipeline, a new log record is created and updated. This screenshot shows the results of a pipeline run with ID ba8758fa-ee6c-4213-a7c8-80ee5bc24ee4:

…and here's the pipeline execution detail in Fabric:

Here's where I found something unexpected: the value of the EndDateTime parameter passed from Fabric isn't the value stored in the database table!

• The Fabric log indicates that the value 2025-03-01 16:55:54.4616379 was passed to the stored procedure.
• The database table contains the (different) value 2025-03-01 16:55:54.6366667.

So what's going on?

My first thought was that there might be something else happening between Fabric and the writing of the final record into my client's database table. Was there a post-update trigger causing the database record to be modified a second time? Could Fabric be introducing some precision error when converting the string returned by @utcNow() into a SQL DATETIME2(7)?

To investigate, I built a new pipeline to write a value into a simple database table. This pipeline use a Script activity to insert a row into a table with two attributes, PipelineRunId and LoggedDateTime:

Here's the table definition:

CREATE TABLE dbo.TestDateTime (
  PipelineRunId VARCHAR(50) NULL
, LoggedDateTime VARCHAR(50) NULL
)

No fancy types, no defaults, no constraints, no triggers… not very much at all, in fact.

And the result when I run this pipeline? The same thing! – the Fabric activity run claims to have executed one piece of SQL, but a different value shows up in the DB table.

Notice that in both examples, the timestamp written to the database is fractionally later than the timestamp shown in the activity log. Could the pipeline be evaluating the expression twice – once for the log, then again for execution?

utcNow() returns the current date and time, so is a natural example of a non-deterministic function – it is not guaranteed to return the same value at each evaluation. (In contrast, @pipeline.RunId() is deterministic in the context of a single pipeline run – in a given run, this function always returns the same value). If pipeline expressions were evaluated separately for logging and for execution, any non-deterministic expression would result in a discrepancy between the log and reality.

As it happens, utcNow() is not the only non-deterministic function available in the pipeline expression language – the rand() function returns a different random number at each evaluation. This pipeline goes a step further, writing a random number to the database:

…with the same outcome:

So now I'm pretty confident:

On one level – for example, knowing to the nearest fraction of a second when a pipeline activity ran – these differences aren't important, but:

• Trying to work out what was happening caused some confusion and required investigation – if you're reading this, hopefully I'll save you the same problem 🤞.
• In general, logs which tell you something different from what actually happened aren't helpful! At the very least you need to understand that you can't rely on an activity log to tell you accurately the runtime value of a non-deterministic expression.

Data Factory implementations in Fabric, Azure Synapse Analytics or Azure Data Factory appear to evaluate pipeline expressions twice – once for logging, once for execution. This means that:

• pipeline expressions using non-deterministic functions return different results for logging and execution
• log information reported from activities using non-deterministic functions may be unreliable.

Some follow-up questions which occurred to me and which may be of interest:

• You can see this behaviour in every data factory implementation – Microsoft Fabric, Azure Synapse Analytics and Azure Data Factory all do the same thing.
• This isn't a feature of database-related activities – for example, you can see the same thing using Fabric's Office 365 Outlook activity to send values built using non-deterministic expressions.
• This isn't a quirk of the Fabric/Synapse/ADF user experience – if you're using Log Analytics for ADF, the value you see in the activity input is the value emitted to the ADFActivity table.