Logging Script Output with DbUp

In today’s post, we will be going over how to log script output during a DbUp run. If you are new to this series of posts or DbUp in general you might find the following post helpful to review.

Database Migrations with DbUp
Code-based Database Migrations with DbUp
Always Run Migrations with DbUp

Enable Script Output Logging

I will be using the always run migrations we covered last weekend to simplify testing, but the concepts are the same for normal migrations. The change to enable script output logging is a single line added to our upgrader setup as you can see with the highlighted line in the following code.

var alwaysRunUpgrader =
    DeployChanges.To
                 .SqlDatabase(connectionString)
                 .WithScriptsAndCodeEmbeddedInAssembly(Assembly.GetExecutingAssembly(), 
                                                       f => f.Contains(".AlwaysRun."))
                 .JournalTo(new NullJournal())
                 .LogToConsole()
                 .LogScriptOutput()
                 .Build();

Running the application will result in something like the following. Notice the records affected line which is the output from our migration.

Beginning database upgrade
Checking whether journal table exists..
Fetching list of already executed scripts.
No new scripts need to be executed - completing.
Beginning database upgrade
Executing Database Server script 'DbupTest.Scripts.AlwaysRun.Everytime.sql'
RecordsAffected: 0

Upgrade successful
Success!

Improve the Script Output

So the above is great for a simple migration that has a single statement, but for more complex migrations it might be helpful to use PRINT statements to provide more information. Let’s tweak our script to print the start and end times of the execution. The following is the sample script (and yes I know it would never actually update anything).

PRINT CONVERT(VarChar, GETDATE(), 121)  + ' Start every time';

UPDATE Application.Cities SET CityName = 'Nothing' WHERE 1 = 0;

PRINT CONVERT(VarChar, GETDATE(), 121)  +  + ' End every time';

The above migration results in the following output.

Beginning database upgrade
Checking whether journal table exists..
Fetching list of already executed scripts.
No new scripts need to be executed - completing.
Beginning database upgrade
Executing Database Server script 'DbupTest.Scripts.AlwaysRun.Everytime.sql'
2020-08-05 06:15:21.877 Start every time

2020-08-05 06:15:21.877 End every time

RecordsAffected: 0

Upgrade successful
Success!

The prints are helpful, but the records affected is noise in this case, especially since it is the records affected for the last statement and does print per SQL statement. To suppress the records affected message we and use SET NOCOUNT ON in our script like the following.

SET NOCOUNT ON;

PRINT CONVERT(VarChar, GETDATE(), 121)  + ' Start every time with NoCount ON';

UPDATE Application.Cities SET CityName = 'Nothing' WHERE 1 = 0;

PRINT CONVERT(VarChar, GETDATE(), 121)  +  + ' End every time with NoCount ON';

SET NOCOUNT OFF;

And as you can see in the following we got a cleaner output.

Beginning database upgrade
Checking whether journal table exists..
Fetching list of already executed scripts.
No new scripts need to be executed - completing.
Beginning database upgrade
Executing Database Server script 'DbupTest.Scripts.AlwaysRun.Everytime.sql'
2020-08-05 06:38:18.863 Start every time

2020-08-05 06:38:18.863 End every time

Upgrade successful
Success!

Wrapping Up

Logging the output of scripts can be really helpful at times, but if you are going to use it as we saw above it is important to make sure and plan what that output is going to look like. Having 500 instances of the number of records affected isn’t necessarily helpful.

---

Also published on Medium.