Sql-server – Database was shutdown due to error 9001 in routine ‘XdesRMFull::CommitInternal’

sql serversql-server-2019

I have encountered this situation on one of our production server.
The database came backup and DBCC Check reported no errors.
Also, there were no other errors logged in Event Viewer.

I know I am behind 4 CU's for 2019 which I will be updating soon.

SQL Server: 58GB SQL Server Memory with plenty remaining for OS; 12core processor, running on SSD.

Database Recovery Model: SIMPLE

Version:
Microsoft SQL Server 2019 (RTM-CU4) (KB4548597) - 15.0.4033.1 (X64) Mar 14 2020 16:10:35 Copyright (C) 2019 Microsoft Corporation Enterprise Edition: Core-based Licensing (64-bit) on Windows Server 2019 Standard 10.0 <X64> (Build 17763: ) (Hypervisor)

The server is heavily loaded when a job runs(consumes more memory) and there is a TDE as well.

I have went through other articles like
Some Errors Are Not What They Seem
However, the error in those scenarios were 1117 (IO disk subsystem).

I am wondering how to really track this error – may be to engage MS Support guys as there is very little information on this and goes case by case!!
In our case , is it Memory? or TDE? or some corruption in log? Oh SQL!!

Log Details:

11/27/2020 05:55:57,spid67,Unknown,DBCC CHECKDB (DB1) WITH all_errormsgs<c/> no_infomsgs executed by domain\SqlAgt_Svc found 0 errors and repaired 0 errors. Elapsed time: 0 hours 0 minutes 1 seconds.  Internal database snapshot has split point LSN = 000002c3:00002e50:0001 and first LSN = 000002c3:00002e40:0001.
11/27/2020 05:25:38,spid75,Unknown,DBCC TRACEOFF 3604<c/> server process ID (SPID) 75. This is an informational message only; no user action is required.
11/27/2020 05:25:38,spid75,Unknown,DBCC TRACEON 3604<c/> server process ID (SPID) 75. This is an informational message only; no user action is required.
11/27/2020 05:04:02,spid54s,Unknown,Parallel redo is shutdown for database 'DB2' with worker pool size [6].
11/27/2020 05:04:02,spid54s,Unknown,Recovery completed for database DB2 (database ID 5) in 3 second(s) (analysis 1117 ms<c/> redo 308 ms<c/> undo 108 ms [system undo 0 ms<c/> regular undo 100 ms].) This is an informational message only. No user action is required.
11/27/2020 05:04:02,spid70s,Unknown,CHECKDB for database 'DB2' finished without errors on 2020-11-22 20:00:05.017 (local time). This is an informational message only; no user action is required.
11/27/2020 05:04:02,spid54s,Unknown,Recovery is writing a checkpoint in database 'DB2' (5). This is an informational message only. No user action is required.
11/27/2020 05:04:02,spid54s,Unknown,12 transactions rolled back in database 'DB2' (5:0). This is an informational message only. No user action is required.
11/27/2020 05:04:02,spid70s,Unknown,Recovery of database 'DB2' (5) is 12% complete (approximately 11 seconds remain). Phase 3 of 3. This is an informational message only. No user action is required.
11/27/2020 05:04:02,spid70s,Unknown,10 transactions rolled forward in database 'DB2' (5:0). This is an informational message only. No user action is required.
11/27/2020 05:04:02,spid70s,Unknown,Recovery of database 'DB2' (5) is 12% complete (approximately 11 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
11/27/2020 05:04:02,spid70s,Unknown,Recovery of database 'DB2' (5) is 3% complete (approximately 34 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
11/27/2020 05:04:00,spid70s,Unknown,Parallel redo is started for database 'DB2' with worker pool size [6].
11/27/2020 05:04:00,spid70s,Unknown,Starting up database 'DB2'.
11/27/2020 05:03:52,Logon,Unknown,Login failed for user 'sql_user'. Reason: Failed to open the explicitly specified database 'DB2'. [CLIENT: 10.1.0.116]
11/27/2020 05:03:52,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:1). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:25). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,Error during rollback. shutting down database (location: 1).
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:25). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:15). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:15). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:31). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:31). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:33). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:33). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:30). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:34). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:32). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:29). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:28). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:27). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 2.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:30). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:34). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:32). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:29). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:28). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2' (page (0:0) if any)<c/> an error occurred at log record ID (11603:2070928:27). Typically<c/> the specific failure is logged previously as an error in the operating system error log. Restore the database or file from a backup<c/> or repair the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 3314<c/> Severity: 21<c/> State: 3.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 5.
11/27/2020 05:03:48,spid30s,Unknown,Database DB2 was shutdown due to error 9001 in routine 'XdesRMFull::CommitInternal'. Restart for non-snapshot databases will be attempted after all connections to the database are aborted.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 16.
11/27/2020 05:03:48,spid68,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid68,Unknown,Error: 9001<c/> Severity: 21<c/> State: 16.
11/27/2020 05:03:48,spid30s,Unknown,The log for database 'DB2' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
11/27/2020 05:03:48,spid30s,Unknown,Error: 9001<c/> Severity: 21<c/> State: 4.
11/27/2020 05:03:48,spid69s,Unknown,There is insufficient system memory in resource pool 'internal' to run this query.
11/27/2020 05:03:48,spid69s,Unknown,Error: 701<c/> Severity: 17<c/> State: 123.
11/27/2020 05:03:48,spid8s,Unknown,An error occurred while processing log encryption. The process was recovered automatically. No user action is required.
11/27/2020 05:03:48,spid8s,Unknown,Lock request time out period exceeded.
11/27/2020 05:03:48,spid8s,Unknown,Error: 1222<c/> Severity: 16<c/> State: 55.
11/27/2020 00:00:17,spid44s,Unknown,This instance of SQL Server has been using a process ID of 5096 since 11/21/2020 7:42:00 PM (local) 11/22/2020 1:42:00 AM (UTC). This is an informational message only; no user action is required.
11/26/2020 00:00:07,spid67s,Unknown,This instance of SQL Server has been using a process ID of 5096 since 11/21/2020 7:42:00 PM (local) 11/22/2020 1:42:00 AM (UTC). This is an informational message only; no user action is required.
11/25/2020 11:46:46,spid60,Unknown,DBCC TRACEOFF 3604<c/> server process ID (SPID) 60. This is an informational message only; no user action is required.
11/25/2020 11:46:46,spid60,Unknown,DBCC TRACEON 3604<c/> server process ID (SPID) 60. This is an informational message only; no user action is required.
11/25/2020 00:00:02,spid27s,Unknown,This instance of SQL Server has been using a process ID of 5096 since 11/21/2020 7:42:00 PM (local) 11/22/2020 1:42:00 AM (UTC). This is an informational message only; no user action is required.

[EDIT-1]

At the time of error, Ola Hallengren Index Optimize job was running and has reported the following!!

Database context: [DB2] [SQLSTATE 01000]
Command: UPDATE STATISTICS [schema1].[table1] [_WA_Sys_00000009_08843BF2] [SQLSTATE 01000]
Comment: ObjectType: Table, IndexType: Column, Incremental: N, RowCount: 13228484, ModificationCounter: 215943 [SQLSTATE 01000]
Outcome: Succeeded [SQLSTATE 01000]
Duration: 00:00:00 [SQLSTATE 01000]
Date and time: 2020-11-27 05:03:43 [SQLSTATE 01000]
     [SQLSTATE 01000]
Date and time: 2020-11-27 05:03:45 [SQLSTATE 01000]
Database context: [DB2] [SQLSTATE 01000]
Command: ALTER INDEX [index1] ON [schema1].[table1] REBUILD WITH (SORT_IN_TEMPDB = OFF, ONLINE = OFF) [SQLSTATE 01000]
Comment: ObjectType: Table, IndexType: NonClustered, ImageText: No, NewLOB: No, FileStream: No, ColumnStore: No, AllowPageLocks: Yes, PageCount: 580560, Fragmentation: 95.1018 [SQLSTATE 01000]
Msg 0, Sev 0, State 1: Unspecified error occurred on SQL Server. Connection may have been terminated by the server. [SQLSTATE HY000]
Msg 596, Sev 21, State 1: Cannot continue the execution because the session is in the kill state. [SQLSTATE HY000]

[EDIT-2]

Worked with IT team and it seems like nothing was wrong at the time of error. Unable to find the actual root cause.

  1. Disk checks were good
  2. No 3rd party tool was taking backup or snapshots at that time
  3. Log Drive did not disconnect or there is no such info in the logs
  4. No errors on VM Host
  5. No OS reboot or SQL Service restarts

Edit-3

Installed latest Cumulative Update (CU8) on 5th and still we get the below every other day. (Got it on 7th, 8th so far)

spids
Date        12/8/2020 8:32:59 AM Error: 1222, Severity: 16, State: 55.
Date        12/8/2020 8:32:59 AM Lock request time out period exceeded
Date        12/8/2020 8:32:59 AM An error occurred while processing log encryption. The process was recovered automatically. No user action is required

Best Answer

You do not need to raise case with Microsoft for this. This seems more like storage/unexpected shutdown corruption issue which can be solved with good backup.

11/27/2020 05:03:48,spid68,Unknown,Error: 3314 Severity: 21 State: 5. 11/27/2020 05:03:48,spid68,Unknown,During undoing of a logged operation in database 'DB2'

The root cause of your issue is above message and this means that while SQL Server was trying to recover the database it performed redo and undo and during undoing of some operation it was not able to proceed as data which it was looking for is missing. Now since database cannot be recovered to a consistent state it will be in recovery pending state. Most likely cause of this is unexpected shutdown causing data corruption.

What should you do.

If you have good backup restore the database for it with different name. Before you restore you may also perform tail log backup of given database, I understand that log file is damaged and you might not be able to but give it a try. Also check status of drive on which the log file resides. Sometimes its drive not available is what can cause this issue.

Testing

If you want to do some testing then you can take damaged database in emergency mode and run checkdb. The output will tell you what is repair level required. Do testing only after you have database restored and working. Sometimes a simple checkdb with repair_rebuild does the trick and you might not loose any data at all and DB will be online and working.