====== Unreliable logging in data factory pipelines ======

{{tag> fabric synapse adf blog pipelines}}

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

<WRAP center round box>
**TL;DR**: 
  * Data Factory implementations in Fabric, Azure Synapse Analytics or Azure Data Factory evaluate pipeline expressions separately for logging and execution.
  * Log information reported from activities using non-deterministic functions may be unreliable.
</WRAP>

===== Background =====

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. 

==== Pipeline pattern ====

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

{{:fabric:logging_pipeline.png?nolink&650|}}

I've mocked this up in a simple [[https://learn.microsoft.com/en-us/fabric/data-factory/data-factory-overview#data-pipelines|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:

<code tsql>
CREATE PROCEDURE [dbo].[LogPipelineEnd] (
  @PipelineRunId CHAR(36)
, @EndDateTime DATETIME2(7)
)
AS

UPDATE dbo.PipelineRun
SET EndDateTime = @EndDateTime
WHERE PipelineRunId = @PipelineRunId;
</code>

==== Run the pipeline ==== 

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'':

{{:fabric:db_log_record.png?nolink&500|}}

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

{{:fabric:activity_input_record.png?nolink&650|}}

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?

===== Investigation =====
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'':

{{:fabric:write_test_date_time.png?nolink&650|}}

Here's the table definition:
<code tsql>CREATE TABLE dbo.TestDateTime (
  PipelineRunId VARCHAR(50) NULL
, LoggedDateTime VARCHAR(50) NULL
)
</code>
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.

{{:fabric:write_test_date_time_activity.png?nolink&650|}}

{{:fabric:write_test_date_time_dbtable.png?nolink&600|}}

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?

===== Non-deterministic functions =====
''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:

{{:fabric:write_test_date_time_rand.png?nolink&650|}}

...with the same outcome:

{{:fabric:write_test_date_time_rand_activity.png?nolink&650|}}

{{:fabric:write_test_date_time_rand_dbtable.png?nolink&500|}}

So now I'm pretty confident:
<WRAP center round tip 80%>
Pipeline expressions are evaluated at least **twice**: once to generate log information, and a second time for actual execution.
</WRAP>
===== Why do I care? =====

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.


===== Summary =====
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, [[https://learn.microsoft.com/en-us/azure/data-factory/concepts-pipelines-activities?tabs=data-factory|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 [[https://learn.microsoft.com/en-us/fabric/data-factory/outlook-activity|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 [[https://learn.microsoft.com/en-us/azure/data-factory/monitor-data-factory-reference#resource-logs|Log Analytics for ADF]], the value you see in the activity input is the value emitted to the ''ADFActivity'' table.

<WRAP center round box>
**Share**: If you found this article useful, please share it! ~~socialite:icon bluesky linkedin reddit facebook email~~
</WRAP>

~~DISCUSSION~~