TImeout during Account deletion

Ben_Heilman · 2 March 2018 23:55

We were experiencing 503 responses during Acccount deletion. We fixed this by setting the release retention to 15 days instead of umlimited. The query below is likely the cause, as it is a very expensive way of inspecting schema-less objects inside a RMDS

2/26/2018 12:00:21 PM -06:00 [Error] Unhandled error on request: http://deploy.rallytools.net/api/accounts/sshkeypair-deployer-nightlyneptune 0b3629172e274436a6cf4de6de9bb7b7 by jenkins : Exception occured while executing a reader for SELECT * FROM dbo.[DeploymentProcess] WHERE ([JSON] LIKE @accid) ORDER BY [Id]
System.Exception: Exception occured while executing a reader for SELECT * FROM dbo.[DeploymentProcess] WHERE ([JSON] LIKE @accid) ORDER BY [Id] —> System.Data.SqlClient.SqlException: Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding. —> System.ComponentModel.Win32Exception: The wait operation timed out
— End of inner exception stack trace —
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TrySetMetaData(_SqlMetaDataSet metaData, Boolean moreInfo) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData() at System.Data.SqlClient.SqlDataReader.get_MetaData() at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption) at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at Nevermore.Transient.IDbCommandExtensions.<>c__DisplayClass5_0.b__0()
at Nevermore.Transient.RetryPolicy.ExecuteAction[TResult](Func1 func) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) --- End of inner exception stack trace --- at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, String operationName) at Nevermore.RelationalTransaction.<Stream>d__401.MoveNext()
at System.Linq.Enumerable.WhereSelectEnumerableIterator2.MoveNext() at System.Linq.Enumerable.WhereSelectEnumerableIterator2.MoveNext()
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.RelationshipBuilder2.FindUsages(IRelationalTransaction transaction, Object from, List1 referencingDocuments)
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.FindReferences[TDocument](IRelationalTransaction transaction, TDocument document)
at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.CheckForVetoRules(TModel model) at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.Execute()
at Octopus.Server.Web.Infrastructure.Api.Responder1.ExecuteRegistered() at Octopus.Server.Web.Infrastructure.Api.Responder1.Respond(TDescriptor options, NancyContext context)
at System.Dynamic.UpdateDelegates.UpdateAndExecute3[T0,T1,T2,TRet](CallSite site, T0 arg0, T1 arg1, T2 arg2)
at Octopus.Server.Web.Infrastructure.OctopusNancyModule.<>c__DisplayClass14_0.<get_Routes>b__1(Object x)
at Nancy.Routing.Route.<>c__DisplayClass4.b__3(Object parameters, CancellationToken context)

Alex.Rolley · 5 March 2018 03:58

Hi Ben,

Thanks for getting in touch!

Are you able to let me know which version of Octopus that you are using? The issue that your are describing seems very similar to this one which was resolved in 2018.2.7.

If you are on a newer version we can continue looking, otherwise if you can update that would be greatly appreciated.

I look forward to hearing from you shortly,

Regards,
Alex

Ben_Heilman · 21 March 2018 18:33

Well, we upgraded to 2018.3.4, now the timeout occurs querying a different table:

Unhandled error on request: Exception occured while executing a reader for SELECT * FROM dbo.[VariableSet] WHERE ([JSON] LIKE @accid) ORDER BY [Id] System.Exception: Exception occured while executing a reader for SELECT * FROM dbo.[VariableSet] WHERE ([JSON] LIKE @accid) ORDER BY [Id] —> System.Data.SqlClient.SqlException: Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding. —> System.ComponentModel.Win32Exception: The wait operation timed out
— End of inner exception stack trace —
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TrySetMetaData(_SqlMetaDataSet metaData, Boolean moreInfo) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData() at System.Data.SqlClient.SqlDataReader.get_MetaData() at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption) at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at Nevermore.Transient.IDbCommandExtensions.<>c__DisplayClass5_0.b__0()
at Nevermore.Transient.RetryPolicy.ExecuteAction[TResult](Func1 func) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) --- End of inner exception stack trace --- at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, String operationName) at Nevermore.RelationalTransaction.<Stream>d__401.MoveNext()
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.RelationshipBuilder2.FindUsages(IRelationalTransaction transaction, Object from, List1 referencingDocuments)
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.FindReferences[TDocument](IRelationalTransaction transaction, TDocument document)
at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.CheckForVetoRules(TModel model) at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.Execute()
at Octopus.Server.Web.Infrastructure.Api.Responder1.ExecuteRegistered() at Octopus.Server.Web.Infrastructure.Api.Responder1.Respond(TDescriptor options, NancyContext context)
at System.Dynamic.UpdateDelegates.UpdateAndExecute3[T0,T1,T2,TRet](CallSite site, T0 arg0, T1 arg1, T2 arg2)
at Octopus.Server.Web.Infrastructure.OctopusNancyModule.<>c__DisplayClass14_0.<get_Routes>b__1(Object x)
at Nancy.Routing.Route.<>c__DisplayClass4.b__3(Object parameters, CancellationToken context)
March 21st 2018 13:28:46Error
Unhandled error on request: http://deploy.rallytools.net/api/accounts/sshkeypair-deployer-benstest ae5ac1346820425e9856e2fa79fd6282 by ben.heilman : Exception occured while executing a reader for SELECT * FROM dbo.[VariableSet] WHERE ([JSON] LIKE @accid) ORDER BY [Id] System.Exception: Exception occured while executing a reader for SELECT * FROM dbo.[VariableSet] WHERE ([JSON] LIKE @accid) ORDER BY [Id] —> System.Data.SqlClient.SqlException: Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding. —> System.ComponentModel.Win32Exception: The wait operation timed out
— End of inner exception stack trace —
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TrySetMetaData(_SqlMetaDataSet metaData, Boolean moreInfo) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData() at System.Data.SqlClient.SqlDataReader.get_MetaData() at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption) at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at Nevermore.Transient.IDbCommandExtensions.<>c__DisplayClass5_0.b__0()
at Nevermore.Transient.RetryPolicy.ExecuteAction[TResult](Func1 func) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) --- End of inner exception stack trace --- at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, String operationName) at Nevermore.RelationalTransaction.<Stream>d__401.MoveNext()
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.RelationshipBuilder2.FindUsages(IRelationalTransaction transaction, Object from, List1 referencingDocuments)
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.FindReferences[TDocument](IRelationalTransaction transaction, TDocument document)
at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.CheckForVetoRules(TModel model) at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.Execute()
at Octopus.Server.Web.Infrastructure.Api.Responder1.ExecuteRegistered() at Octopus.Server.Web.Infrastructure.Api.Responder1.Respond(TDescriptor options, NancyContext context)
at System.Dynamic.UpdateDelegates.UpdateAndExecute3[T0,T1,T2,TRet](CallSite site, T0 arg0, T1 arg1, T2 arg2)
at Octopus.Server.Web.Infrastructure.OctopusNancyModule.<>c__DisplayClass14_0.<get_Routes>b__1(Object x)
at Nancy.Routing.Route.<>c__DisplayClass4.b__3(Object parameters, CancellationToken context)
March 21st 2018 13:29:50Error
Unhandled error on request: http://deploy.rallytools.net/api/accounts/sshkeypair-deployer-nightlyneptune 54aa4cec6b8b4d9e8099804c578c7612 by ben.heilman : Exception occured while executing a reader for SELECT * FROM dbo.[VariableSet] WHERE ([JSON] LIKE @accid) ORDER BY [Id] System.Exception: Exception occured while executing a reader for SELECT * FROM dbo.[VariableSet] WHERE ([JSON] LIKE @accid) ORDER BY [Id] —> System.Data.SqlClient.SqlException: Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding. —> System.ComponentModel.Win32Exception: The wait operation timed out
— End of inner exception stack trace —
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TrySetMetaData(_SqlMetaDataSet metaData, Boolean moreInfo) at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData() at System.Data.SqlClient.SqlDataReader.get_MetaData() at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption) at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at Nevermore.Transient.IDbCommandExtensions.<>c__DisplayClass5_0.b__0()
at Nevermore.Transient.RetryPolicy.ExecuteAction[TResult](Func1 func) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) --- End of inner exception stack trace --- at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, RetryPolicy commandRetryPolicy, RetryPolicy connectionRetryPolicy, String operationName) at Nevermore.Transient.IDbCommandExtensions.ExecuteReaderWithRetry(IDbCommand command, String operationName) at Nevermore.RelationalTransaction.<Stream>d__401.MoveNext()
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.RelationshipBuilder2.FindUsages(IRelationalTransaction transaction, Object from, List1 referencingDocuments)
at Octopus.Core.Persistence.Indexes.DeletionDocumentUsageFinder.FindReferences[TDocument](IRelationalTransaction transaction, TDocument document)
at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.CheckForVetoRules(TModel model) at Octopus.Server.Web.Infrastructure.Api.DeleteOnBackgroundResponseDescriptor2.Responder.Execute()
at Octopus.Server.Web.Infrastructure.Api.Responder1.ExecuteRegistered() at Octopus.Server.Web.Infrastructure.Api.Responder1.Respond(TDescriptor options, NancyContext context)
at System.Dynamic.UpdateDelegates.UpdateAndExecute3[T0,T1,T2,TRet](CallSite site, T0 arg0, T1 arg1, T2 arg2)
at Octopus.Server.Web.Infrastructure.OctopusNancyModule.<>c__DisplayClass14_0.<get_Routes>b__1(Object x)
at Nancy.Routing.Route.<>c__DisplayClass4.b__3(Object parameters, CancellationToken context)

Ben_Heilman · 21 March 2018 20:25

57%20PM
This is probably related

Ben_Heilman · 21 March 2018 22:54

Performed some SQL surgery. Remove Ids like these from the dbo.variablesets table:
variableset-Projects-9-s-2808-4YDJS
variableset-Deployments-116592