Migration fails to complete with transaction error

worldspawn commented 3 months ago

Describe the bug On only one environment we are unable to migrate our latest script. The script itself appears to run but then it chokes in "InsertScriptRun"

To Reproduce Unsure of the cause. Same migration worked on all our other environments. We can also run the script itself against the target env (with a rollback) with no issues. The script contains no BEGIN TRAN/ROLLBACK or anything transaction related.

Expected behavior My database is grated

Screenshots

Desktop (please complete the following information):

OS: Linux/Windows
Version: 1.7.2 and 1.8.0

Additional context command run:

grate --connstring "Data Source=tcp:redacted,1433;Initial Catalog=redacted;Persist Security Info=False;User ID=redacted;Password=redacted;Pooling=True;Min Pool Size=50;Max Pool Size=500;MultipleActiveResultSets=True;Encrypt=True;TrustServerCertificate=False;ConnectRetryCount=20" --trx --env "PROD" -f main --schema RoundhousE --commandtimeout 900 -v Verbose

Verbose log output:

Initializing connections.
Running grate v1.8.0 (build date 07/25/2024 17:13:32) against tcp:redacted,1433 - redacted.
Looking in main for scripts to run.
Please press enter when ready to kick...

The change_drop (output) folder is: C:\Users\critc\AppData\Local\grate\migrations\redacted\tcp_redacted.net_1433\2024-08-14T11_12_31.7684860_10_00
================================================================================
Setup, Backup, Create/Restore/Drop
================================================================================
================================================================================
Grate Structure
================================================================================
SQL:
SELECT table_name FROM INFORMATION_SCHEMA.TABLES
WHERE
LOWER(TABLE_SCHEMA) = LOWER('RoundhousE') AND
LOWER(TABLE_NAME) = LOWER('Version')

Parameters: (null)
SQL:
SELECT table_name FROM INFORMATION_SCHEMA.TABLES
WHERE
LOWER(TABLE_SCHEMA) = LOWER('RoundhousE') AND
LOWER(TABLE_NAME) = LOWER('GrateScriptsRun')

Parameters: (null)
SQL: SELECT 1 FROM RoundhousE.[GrateScriptsRun] WHERE script_name = '02_create_scripts_run_table.sql'
Parameters: (null)
SQL:
SELECT table_name FROM INFORMATION_SCHEMA.TABLES
WHERE
LOWER(TABLE_SCHEMA) = LOWER('RoundhousE') AND
LOWER(TABLE_NAME) = LOWER('Version')

Parameters: (null)
SQL:
SELECT table_name FROM INFORMATION_SCHEMA.TABLES
WHERE
LOWER(TABLE_SCHEMA) = LOWER('RoundhousE') AND
LOWER(TABLE_NAME) = LOWER('GrateScriptsRun')

Parameters: (null)
SQL: SELECT 1 FROM RoundhousE.[GrateScriptsRun] WHERE script_name = '02_create_scripts_run_table.sql'
Parameters: (null)
================================================================================
Versioning
================================================================================
SQL:
SELECT
TOP 1

version
FROM RoundhousE.[Version]
ORDER BY id DESC

Parameters: (null)
 Migrating redacted from version 0.0.0.1 to 0.0.0.1.
 Versioning redacted database with version 0.0.0.1.
================================================================================
Migration Scripts
================================================================================
Skipping 'BeforeMigration', beforeMigration does not exist.
Skipping 'AlterDatabase', alterDatabase does not exist.
Skipping 'Run Before Update', runBeforeUp does not exist.

Looking for Update scripts in "main\up". These should be one time only scripts.
--------------------------------------------------------------------------------
 Skipped 201912191046000_DeleteOldPermissions.sql - No changes were found to run.
 Skipped 202006030000000_CreateUserLookupTable.sql - No changes were found to run.
 Skipped 202006040000000_PopulateUserLookupTable.sql - No changes were found to run.
 Skipped 202008240000000_AuditLogTable.sql - No changes were found to run.
 Skipped 202010310000000_ChangeIssueBookIdColumnType.sql - No changes were found to run.
 Skipped 202011180000000_ALTERUserProfilesTable.sql - No changes were found to run.
 Skipped 202011190000000_ALTERProjectsTable.sql - No changes were found to run.
 Skipped 202103110000000_ALTERPermissionsTable.sql - No changes were found to run.
 Skipped 202202080000000_CREATEMeasureScalesV2Table.sql - No changes were found to run.
 Skipped 202202150000000_INSERT-default-scales.sql - No changes were found to run.
 Skipped 202204070000000_update-default-scales.sql - No changes were found to run.
 Skipped 202205310000000_CREATE-WorkspaceTables.sql - No changes were found to run.
 Skipped 202206010000000_ALTER-ProjectsTable-Add-WorkspaceId.sql - No changes were found to run.
 Skipped 202206020000000_alter-issues-add-visibility-column.sql - No changes were found to run.
 Skipped 202206240000000_CREATE-WorkspaceInvites-Table.sql - No changes were found to run.
 Skipped 202206241000000_CREATE-Workspace-Indexes.sql - No changes were found to run.
 Skipped 202206242000000_Migrate-Orgs-to-Workspaces.sql - No changes were found to run.
 Skipped 202207110000000_AddBookStateTables.sql - No changes were found to run.
 Skipped 202207130000000_IncludeBookStatusInQueries.sql - No changes were found to run.
 Skipped 202208160000000_AddRevisionAssignee.sql - No changes were found to run.
 Skipped 202209210000000_WorkspaceMemberAccessLevel.sql - No changes were found to run.
 Skipped 202210030000000_WorkspaceMemberAccessLevelCorrectionAgain.sql - No changes were found to run.
 Skipped 202210140000000_CreateStatusDefaultsFlag.sql - No changes were found to run.
 Skipped 202210190000000_WorkspaceMemberDefaultProjectRole.sql - No changes were found to run.
 Skipped 202210260000000_WorkspaceDefaultProjectAccessLevel.sql - No changes were found to run.
 Skipped 202211070000000_WorkspaceHasProfilePicture.sql - No changes were found to run.
 Skipped 202211070000000_WorkspaceMemberDefaultProjectRole_ChangeToString.sql - No changes were found to run.
 Skipped 202211210000000_DefaultStatusColorLength.sql - No changes were found to run.
 Skipped 202211290000000_OrganizationHasProfilePicture.sql - No changes were found to run.
 Skipped 202301130000000_OrganizationUsersUnique.sql - No changes were found to run.
 Skipped 202301180000000_RemoveOwnerIdFromProjects.sql - No changes were found to run.
 Skipped 202302090000000_OrganizationUsersRoleAsString.sql - No changes were found to run.
 Skipped 202303220000000_DropOrganizationIdFromProjectsAndWorkspaceUsers.sql - No changes were found to run.
 Skipped 202307310357000_FlattenDocument.sql - No changes were found to run.
 Skipped 202308150000000_AddDocAndRevisionIndices.sql - No changes were found to run.
 Skipped 202308210000000_FixIsInteractive.sql - No changes were found to run.
 Skipped 202308220000000_OrganizationDomains.sql - No changes were found to run.
 Skipped 202308222117000_CreateProjectIdWorkspacePermIndices.sql - No changes were found to run.
 Skipped 202308250000000_TagRefactor.sql - No changes were found to run.
 Skipped 202308252100000_FlattenDisciplines.sql - No changes were found to run.
 Skipped 202308280000000_MigrateOrgFields.sql - No changes were found to run.
 Skipped 202309010000000_SetIsInteractive.sql - No changes were found to run.
 Skipped 202309260000000_Layers.sql - No changes were found to run.
 Skipped 202310010000000_AlterProjectNameUnicode.sql - No changes were found to run.
 Skipped 202311010000000_UserReference.sql - No changes were found to run.
 Skipped 202311150000000_DropAuditLogTable.sql - No changes were found to run.
 Skipped 202311231320600_IndexCustomerIdAndSubscriptionId.sql - No changes were found to run.
 Skipped 202312051300000_PendingEmailChanges.sql - No changes were found to run.
 Skipped 202331002113600_AddMissingProjectsIndex.sql - No changes were found to run.
 Skipped 202401081030000_DocumentRevisionCounter.sql - No changes were found to run.
 Skipped 202402151030000_FlagDemoUser.sql - No changes were found to run.
 Skipped 202402200945000_SeedSegment.sql - No changes were found to run.
 Skipped 202402241020000_ApiKeys.sql - No changes were found to run.
 Skipped 202403011028000_CREATE-BookCommentsTable.sql - No changes were found to run.
 Skipped 202403071400000_AlterWorkspaceAndOrganizationNameUnicode.sql - No changes were found to run.
 Skipped 202403191109000_ApiKeysChange.sql - No changes were found to run.
 Skipped 202403191248000_ApiKeysTokenLength.sql - No changes were found to run.
 Skipped 202404131248000_ApiSymmetricKey.sql - No changes were found to run.
 Skipped 202404181300000_Webhooks.sql - No changes were found to run.
 Skipped 202405060000000_ApiRateCallState.sql - No changes were found to run.
 Skipped 202405230000000_ApiRateCallStateAddWebhookCount.sql - No changes were found to run.
 Skipped 202407011500000_WebhooksDropLabel.sql - No changes were found to run.
SQL:
SELECT 1 FROM  RoundhousE.[ScriptsRun] WITH (NOLOCK)
WHERE script_name = @scriptName
Parameters: { scriptName = 202408021444000_BookStatusToGuid.sql }
  Running '202408021444000_BookStatusToGuid.sql'.
[SQL] Running (on connection 'Default', transaction handling 'Default'):
--revision

ALTER TABLE Revisions
DROP CONSTRAINT FK_Revisions_BookStatus

UPDATE Revisions
SET BookStatusId = SUBSTRING(BookStatusId, 1, 8) + '-' + SUBSTRING(BookStatusId, 9, 4) + '-' + SUBSTRING(BookStatusId, 13, 4) + '-' +
        SUBSTRING(BookStatusId, 17, 4) + '-' + SUBSTRING(BookStatusId, 21, 12)
WHERE BookStatusId IS NOT NULL

ALTER TABLE Revisions
ALTER COLUMN BookStatusId uniqueidentifier NULL

-- book status

ALTER TABLE BookStatus
DROP CONSTRAINT PK_BookStatus

UPDATE BookStatus
SET Id = SUBSTRING(Id, 1, 8) + '-' + SUBSTRING(Id, 9, 4) + '-' + SUBSTRING(Id, 13, 4) + '-' +
        SUBSTRING(Id, 17, 4) + '-' + SUBSTRING(Id, 21, 12)
WHERE CHARINDEX('-', Id) > -1

ALTER TABLE BookStatus
ALTER COLUMN Id uniqueidentifier NOT NULL

ALTER TABLE BookStatus
ADD CONSTRAINT PK_BookStatus PRIMARY KEY (Id)

-- final

ALTER TABLE Revisions
ADD CONSTRAINT [FK_Revisions_BookStatus] FOREIGN KEY([BookStatusId])
    REFERENCES dbo.BookStatus (Id) ON DELETE SET NULL
SQL: --revision

ALTER TABLE Revisions
DROP CONSTRAINT FK_Revisions_BookStatus

UPDATE Revisions
SET BookStatusId = SUBSTRING(BookStatusId, 1, 8) + '-' + SUBSTRING(BookStatusId, 9, 4) + '-' + SUBSTRING(BookStatusId, 13, 4) + '-' +
        SUBSTRING(BookStatusId, 17, 4) + '-' + SUBSTRING(BookStatusId, 21, 12)
WHERE BookStatusId IS NOT NULL

ALTER TABLE Revisions
ALTER COLUMN BookStatusId uniqueidentifier NULL

-- book status

ALTER TABLE BookStatus
DROP CONSTRAINT PK_BookStatus

UPDATE BookStatus
SET Id = SUBSTRING(Id, 1, 8) + '-' + SUBSTRING(Id, 9, 4) + '-' + SUBSTRING(Id, 13, 4) + '-' +
        SUBSTRING(Id, 17, 4) + '-' + SUBSTRING(Id, 21, 12)
WHERE CHARINDEX('-', Id) > -1

ALTER TABLE BookStatus
ALTER COLUMN Id uniqueidentifier NOT NULL

ALTER TABLE BookStatus
ADD CONSTRAINT PK_BookStatus PRIMARY KEY (Id)

-- final

ALTER TABLE Revisions
ADD CONSTRAINT [FK_Revisions_BookStatus] FOREIGN KEY([BookStatusId])
    REFERENCES dbo.BookStatus (Id) ON DELETE SET NULL
Recording 202408021444000_BookStatusToGuid.sql script ran on tcp:redacted,1433 - redacted.
SQL:
INSERT INTO RoundhousE.[ScriptsRun]
(version_id, script_name, text_of_script, text_hash, one_time_script, entry_date, modified_date, entered_by)
VALUES (@versionId, @scriptName, @sql, @hash, @runOnce, @now, @now, @usr)
Parameters: Dapper.DynamicParameters
Skipping 'Permissions', permissions does not exist.
Skipping 'AfterMigration', afterMigration does not exist.
An error occurred: Migration failed due to the following errors:

 * The transaction associated with the current connection has completed but has not been disposed.  The transaction must be disposed before the connection can be used to execute SQL statements.
grate.Exceptions.MigrationFailed: Migration failed due to the following errors:

 * The transaction associated with the current connection has completed but has not been disposed.  The transaction must be disposed before the connection can be used to execute SQL statements.
 ---> System.InvalidOperationException: The transaction associated with the current connection has completed but has not been disposed.  The transaction must be disposed before the connection can be used to execute SQL statements.
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.CheckEnlistedTransactionBinding()
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteRPC(SqlCommand cmd, IList`1 rpcArray, Int32 timeout, Boolean inSchema, SqlNotificationRequest notificationRequest, TdsParserStateObject stateObj, Boolean isCommandProc, Boolean sync, TaskCompletionSource`1 completion, Int32 startRpc, Int32 startParam)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method)
   at Microsoft.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String methodName)
   at Microsoft.Data.SqlClient.SqlCommand.BeginExecuteNonQueryInternal(CommandBehavior behavior, AsyncCallback callback, Object stateObject, Int32 timeout, Boolean inRetry, Boolean asyncWrite)
   at Microsoft.Data.SqlClient.SqlCommand.BeginExecuteNonQueryAsync(AsyncCallback callback, Object stateObject)
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<InternalExecuteNonQueryAsync>b__193_0(AsyncCallback callback, Object stateObject)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncImpl(Func`3 beginMethod, Func`2 endFunction, Action`1 endAction, Object state, TaskCreationOptions creationOptions)
   at System.Threading.Tasks.TaskFactory`1.FromAsync(Func`3 beginMethod, Func`2 endMethod, Object state)
   at Microsoft.Data.SqlClient.SqlCommand.InternalExecuteNonQueryAsync(CancellationToken cancellationToken)
--- End of stack trace from previous location ---
   at Dapper.SqlMapper.ExecuteImplAsync(IDbConnection cnn, CommandDefinition command, Object param) in /_/Dapper/SqlMapper.Async.cs:line 662
   at grate.Migration.AnsiSqlDatabase.ExecuteAsync(IDbConnection conn, String sql, Object parameters) in /home/runner/work/grate/grate/src/grate.core/Migration/AnsiSqlDatabase.cs:line 650
   at grate.Migration.AnsiSqlDatabase.InsertScriptRun(String scriptName, String sql, String hash, Boolean runOnce, Int64 versionId, TransactionHandling transactionHandling) in /home/runner/work/grate/grate/src/grate.core/Migration/AnsiSqlDatabase.cs:line 568
   at grate.Migration.DbMigrator.RunTheActualSql(String sql, String scriptName, MigrationType migrationType, Int64 versionId, ConnectionType connectionType, TransactionHandling transactionHandling) in /home/runner/work/grate/grate/src/grate.core/Migration/DbMigrator.cs:line 309
   at grate.Migration.DbMigrator.<>c__DisplayClass28_0.<<RunSql>g__LogAndRunSql|0>d.MoveNext() in /home/runner/work/grate/grate/src/grate.core/Migration/DbMigrator.cs:line 94
--- End of stack trace from previous location ---
   at grate.Migration.DbMigrator.RunSql(String sql, String scriptName, MigrationsFolder folder, Int64 versionId, GrateEnvironment environment, ConnectionType connectionType, TransactionHandling transactionHandling) in /home/runner/work/grate/grate/src/grate.core/Migration/DbMigrator.cs:line 154
   at grate.Migration.GrateMigrator.Process(DirectoryInfo root, MigrationsFolder folder, String changeDropFolder, Int64 versionId, ConnectionType connectionType, TransactionHandling transactionHandling) in /home/runner/work/grate/grate/src/grate.core/Migration/GrateMigrator.cs:line 418
   at grate.Migration.GrateMigrator.LogAndProcess(DirectoryInfo root, MigrationsFolder folder, String changeDropFolder, Int64 versionId, ConnectionType connectionType, TransactionHandling transactionHandling) in /home/runner/work/grate/grate/src/grate.core/Migration/GrateMigrator.cs:line 388
   at grate.Migration.GrateMigrator.Migrate() in /home/runner/work/grate/grate/src/grate.core/Migration/GrateMigrator.cs:line 166
   --- End of inner exception stack trace ---
   at grate.Migration.GrateMigrator.Migrate() in /home/runner/work/grate/grate/src/grate.core/Migration/GrateMigrator.cs:line 204
   at grate.Commands.MigrateCommand.<>c__DisplayClass0_0.<<-ctor>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.NamingConventionBinder.CommandHandler.GetExitCodeAsync(Object returnValue, InvocationContext context)

worldspawn commented 3 months ago

It ran successfully with transactions off.

Konkaku597 commented 1 month ago

@worldspawn I am also getting this error; any solutions other than to run with transactions off?

Jackietf commented 1 month ago

We had the same issue and it seems to be the TransactionScope default timeout of 1 minute being hit. See System.Transaction defaults from source code and TransactionManager.DefaultTimeout Property.

Changing the default timeout to something higher when creating the new TransactionScope worked for us: use one of the constructors taking a timespan TransactionScope Constructors in place of the one on line 139 in GrateMigrator.cs. Could for example be

GrateMigrator.cs:137-140
if (runInTransaction)
{
    // with timeout of 5 minutes
    scope = new TransactionScope(TransactionScopeOption.Required, new TimeSpan(0,5,0), TransactionScopeAsyncFlowOption.Enabled);
    // original
    scope = new TransactionScope(TransactionScopeAsyncFlowOption.Enabled);
}

Note that if the argument to the constructor is greater than the DefaultMaxTimeout of 10 minutes then the DefaultMaxTimeout will be used. This can however be overwritten (without reflection hacks) since they added a setter to TransactionManager.DefaultMaxTimeout (and DefaultTimeout) in 71703.

Perhaps this transaction issue in grate can be fixed by adding an additional parameter similar to the current commandtimeout and admincommandtimeout that controls the default transaction timeout. It is conterintuitive that running grate as a transaction will timeout for all migrations taking > 60s, even in cases where the commandtimeout is > 60s.

emilsaj commented 1 month ago

We experience the same issue as @Jackietf describes.

Spift commented 1 month ago

Thanks for sharing @Jackietf, I'm running into the same issue.

erikbra / grate

Migration fails to complete with transaction error #572