Process not stopping when error is encountered

jspencer · 8 February 2017 19:39

In my 2nd step of a process, I’m executing DBUp to run some database scripts. I intentionally set one of the scripts to fail to examine the error handling of Octopus Deploy. I was expecting the process to stop execution at Step 2. However, if you examine my log file (towards the end of the log ) you can see Step 3 still starts and finishes. Can explain what I am missing to halt the process should an error occurs?

== Success: Step 2: Execute DB Scripts ==
13:35:24 Verbose | Execute DB Scripts completed
|
| Success: sedidevlab01 (IIS)
13:35:19 Verbose | Octopus Server version: 3.8.2+Branch.master.Sha.697625fc79096635afccb7c9bfd219dbd05868d8
13:35:19 Verbose | Environment Information:
| OperatingSystem: Microsoft Windows NT 6.2.9200.0
| OsBitVersion: x64
| Is64BitProcess: True
| CurrentUser: SEDIAD\octserv
| MachineName: SEDIOCT
| ProcessorCount: 4
| CurrentDirectory: C:\Windows\system32
| TempDirectory: C:\Users\octserv\AppData\Local\Temp
| HostProcessName: Octopus.Server
13:35:19 Info | Unpacking Calamari version 3.6.30 to 'C:\Octopus\Calamari\Local\3.6.30’
13:35:20 Verbose | Cleaning up old versions of Calamari…
13:35:20 Verbose | Keeping only latest Calamari version 3.6.30…
13:35:21 Verbose | Octopus Deploy: Calamari version 3.6.30+Branch.master.Sha.02e2db4c0ee368d3e5e41c7959ecb01e6bcb4aaf
13:35:21 Verbose | Environment Information:
13:35:21 Verbose | OperatingSystem: Microsoft Windows NT 6.2.9200.0
13:35:21 Verbose | OsBitVersion: x64
13:35:21 Verbose | Is64BitProcess: True
13:35:21 Verbose | CurrentUser: SEDIAD\octserv
13:35:21 Verbose | MachineName: SEDIOCT
13:35:21 Verbose | ProcessorCount: 4
13:35:21 Verbose | CurrentDirectory: C:\Octopus\Work\20170208183520-3
13:35:21 Verbose | TempDirectory: C:\Users\octserv\AppData\Local\Temp
13:35:21 Verbose | HostProcessName: Calamari
13:35:21 Verbose | Executing 'C:\Octopus\Work\20170208183520-3\Script.ps1’
13:35:22 Verbose | Name Value
13:35:22 Verbose | ---- -----
13:35:22 Verbose | PSVersion 4.0
13:35:22 Verbose | WSManStackVersion 3.0
13:35:22 Verbose | SerializationVersion 1.1.0.1
13:35:22 Verbose | CLRVersion 4.0.30319.42000
13:35:22 Verbose | BuildVersion 6.3.9600.17400
13:35:22 Verbose | PSCompatibleVersions {1.0, 2.0, 3.0, 4.0}
13:35:22 Verbose | PSRemotingProtocolVersion 2.2
13:35:22 Verbose | PowerShell Environment Information:
13:35:22 Verbose | OperatingSystem: Microsoft Windows NT 6.3.9600.0
13:35:22 Verbose | OsBitVersion: x64
13:35:22 Verbose | Is64BitProcess: True
13:35:22 Verbose | CurrentUser: SEDIAD\octserv
13:35:22 Verbose | MachineName: SEDIOCT
13:35:22 Verbose | ProcessorCount: 4
13:35:22 Verbose | CurrentDirectory: C:\Octopus\Work\20170208183520-3
13:35:22 Verbose | TempDirectory: C:\Users\octserv\AppData\Local\Temp
13:35:22 Verbose | HostProcessName: powershell
13:35:22 Verbose | TotalPhysicalMemory: 16776756 KB
13:35:22 Verbose | AvailablePhysicalMemory: 13771288 KB
13:35:22 Info | Beginning database upgrade
13:35:22 Info | Fetching list of already executed scripts.
13:35:22 Info | Executing SQL Server script '1 Test.sql’
13:35:22 Info | Executing SQL Server script '2 Test.sql’
13:35:22 Info | Executing SQL Server script '3 Test.sql’
13:35:22 Info | Executing SQL Server script '4 Test.sql’
13:35:22 Info | SQL exception has occured in script: '4 Test.sql’
13:35:22 Info | Script block number: 0; Block line 1; Message:
13:35:22 Info | System.Data.SqlClient.SqlException (0x80131904): There is already an object named ‘ZZZTEST’ in the database.
13:35:22 Info | at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) 13:35:22 Info | at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) 13:35:22 Info | at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) 13:35:22 Info | at System.Data.SqlClient.SqlCommand.RunExecuteNonQueryTds(String methodName, Boolean async, Int32 timeout, Boolean asyncWrite) 13:35:22 Info | at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
13:35:22 Info | at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
13:35:22 Info | at DbUp.Support.SqlServer.SqlScriptExecutor.<>c__DisplayClass15_0.b__1(Func1 dbCommandFactory) 13:35:22 Info | at DbUp.Engine.Transactions.NoTransactionStrategy.Execute(Action1 action)
13:35:22 Info | at DbUp.Engine.Transactions.DatabaseConnectionManager.ExecuteCommandsWithManagedConnection(Action1 action) 13:35:22 Info | at DbUp.Support.SqlServer.SqlScriptExecutor.Execute(SqlScript script, IDictionary2 variables)
13:35:22 Info | ClientConnectionId:2133dc39-96a0-4bec-9437-1627917a6f43
13:35:22 Info | Error Number:2714,State:6,Class:16
13:35:22 Info | Upgrade failed due to an unexpected exception:
13:35:22 Info | System.Data.SqlClient.SqlException (0x80131904): There is already an object named ‘ZZZTEST’ in the database.
13:35:22 Info | at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) 13:35:22 Info | at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) 13:35:22 Info | at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) 13:35:22 Info | at System.Data.SqlClient.SqlCommand.RunExecuteNonQueryTds(String methodName, Boolean async, Int32 timeout, Boolean asyncWrite) 13:35:22 Info | at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
13:35:22 Info | at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
13:35:22 Info | at DbUp.Support.SqlServer.SqlScriptExecutor.<>c__DisplayClass15_0.b__1(Func1 dbCommandFactory) 13:35:22 Info | at DbUp.Engine.Transactions.NoTransactionStrategy.Execute(Action1 action)
13:35:22 Info | at DbUp.Engine.Transactions.DatabaseConnectionManager.ExecuteCommandsWithManagedConnection(Action1 action) 13:35:22 Info | at DbUp.Support.SqlServer.SqlScriptExecutor.Execute(SqlScript script, IDictionary2 variables)
13:35:22 Info | at DbUp.Engine.UpgradeEngine.PerformUpgrade()
13:35:22 Info | ClientConnectionId:2133dc39-96a0-4bec-9437-1627917a6f43
13:35:22 Info | Error Number:2714,State:6,Class:16
13:35:23 Verbose | Updating manifest with output variables
|
| == Success: Step 3: Restart Application Pool ==
13:35:27 Verbose | Restart Application Pool completed

Vanessa_Love · 9 February 2017 02:29

Hi John,

Thanks for getting in touch! If you see from your logs the ‘failure’ is returning as an Info message. Octopus will treat Warnings and Errors correctly and mark the deployment in accordance, but if they are info then they will not be treated any differently than a regular log message.
You will have to return errors as errors.

Please let me know if you would like this explained further or examples provided.
Vanessa

jspencer · 9 February 2017 16:54

Hi Vanessa, can you provided a few examples? I"m new to Powershell.

Dalmiro · 10 February 2017 19:48

Hi John,

Like Vanessa pointed out, Octopus doesn’t seem to be recognizing this as an error, reason why the messages show up as info instead of error. The console app should be passing the exception to the PS script that invokes it, and the latter should be sending the error to Octopus. I’m wondering which part of that process is not quite working.

Could you try invoking the DBUp console up like this:

$DBUPexe = "" #Full path of your DBUp console.

& $DBUPexe

If($LASTEXITCODE -ne 0){
    throw "Something went running [$DBUpexe]"
}

Let me know how that goes.

Dalmiro

jspencer · 10 February 2017 19:56

Thanks for the reply. I implemented something very similar as your suggested. I put everything in a try catch and added a check to see the results. Here is what I did to get octopus deploy to recognize an error occurred during an execution of the database scripts.

try{
…
…
$upgradeResult = $dbUp.Build().PerformUpgrade()
if($upgradeResult.Successful -eq 0)
{
throw $upgradeResult.Error.Message
}
}
catch
{
exit 1
}

Thanks for your assistance.

Dalmiro · 10 February 2017 20:00

So you are using the DBUp library straight from Powershell and not through a console app. I wonder if that’s why the error code isn’t being passed properly?

Glad to hear your workaround is doing the job