Transaction deadlock during restore

Question

I am working on PS script to restore database backups and I have following SQL script that I am running from PS Invoke-SQLcmd command:

USE master
GO
ALTER DATABASE mydatabase SET SINGLE_USER WITH ROLLBACK IMMEDIATE
GO
ALTER DATABASE mydatabase SET OFFLINE WITH ROLLBACK IMMEDIATE
GO
RESTORE DATABASE mydatabase
FROM DISK = 'Z:\bak\mydatabase.bak'
WITH REPLACE
GO

ALTER DATABASE mydatabase SET RECOVERY SIMPLE
GO
ALTER DATABASE mydatabase SET ONLINE
GO
ALTER DATABASE mydatabase SET MULTI_USER WITH ROLLBACK IMMEDIATE
GO

As you can see I am switching database to single mode and even making it offline before restore operation. However from time to time I am getting error like:

Transaction (Process ID 61) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

I am not an expert in database deadlocks and I have no idea how to secure my script to prevent this kind of errors. Do you know what is happening that something blocks restore operation when db is in single mode and offline?

UPDATE Changed script like:

USE master
GO
ALTER DATABASE mydatabase SET SINGLE_USER WITH ROLLBACK IMMEDIATE
GO

RESTORE DATABASE mydatabase
FROM DISK = 'Z:\bak\mydatabase.bak'
WITH REPLACE, RECOVERY
GO

ALTER DATABASE mydatabase SET RECOVERY SIMPLE
GO
ALTER DATABASE mydatabase SET MULTI_USER WITH ROLLBACK IMMEDIATE
GO

I turned on dbcc trace and got following logs:

Date,Source,Severity,Message
02/05/2019 07:34:06,spid37s,Unknown,inputbuf
02/05/2019 07:34:06,spid37s,Unknown,executionStack
02/05/2019 07:34:06,spid37s,Unknown,process id=process2bdbf8ca8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=1317 schedulerid=3 kpid=10904 status=suspended spid=53 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=1900-01-01T00:00:00 lastbatchcompleted=1900-01-01T00:00:00 lastattention=1900-01-01T00:00:00 clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER hostpid=0 loginname=testuser isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:34:06,spid37s,Unknown,process-list
02/05/2019 07:34:06,spid37s,Unknown,deadlock victim=process2bdbf8ca8
02/05/2019 07:34:06,spid37s,Unknown,deadlock-list
02/05/2019 07:34:06,spid7s,Unknown,waiter id=process2bdef24e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,waiter-list
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner-list
02/05/2019 07:34:06,spid7s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:34:06,spid7s,Unknown,waiter id=process2ff031848 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,waiter-list
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner-list
02/05/2019 07:34:06,spid7s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:34:06,spid7s,Unknown,waiter id=process2f4f5eca8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,waiter-list
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner-list
02/05/2019 07:34:06,spid7s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:34:06,spid7s,Unknown,waiter id=process2bdbf8ca8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,waiter-list
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner-list
02/05/2019 07:34:06,spid7s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:34:06,spid7s,Unknown,waiter id=process2bb01a8c8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,waiter-list
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner-list
02/05/2019 07:34:06,spid7s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:34:06,spid7s,Unknown,waiter id=process2f4f0c8c8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,waiter-list
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f64604e8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner-list
02/05/2019 07:34:06,spid7s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:34:06,spid7s,Unknown,waiter id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,waiter-list
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f4f0c8c8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2bdbf8ca8 mode=X requestType=wait
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2bdbf8ca8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner id=process2f4f0c8c8 mode=S
02/05/2019 07:34:06,spid7s,Unknown,owner-list
02/05/2019 07:34:06,spid7s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:34:06,spid7s,Unknown,resource-list
02/05/2019 07:34:06,spid7s,Unknown,WITH REPLACE
02/05/2019 07:34:06,spid7s,Unknown,FROM DISK = 'Z:\bak\mydatabase.bak'
02/05/2019 07:34:06,spid7s,Unknown,RESTORE DATABASE mydatabase
02/05/2019 07:34:06,spid7s,Unknown,inputbuf
02/05/2019 07:34:06,spid7s,Unknown,unknown
02/05/2019 07:34:06,spid7s,Unknown,frame procname=unknown line=2 stmtstart=4 stmtend=326 sqlhandle=0x010001006bf7d11c709f1b7f0200000000000000000000000000000000000000000000000000000000000000
02/05/2019 07:34:06,spid7s,Unknown,executionStack
02/05/2019 07:34:06,spid7s,Unknown,process id=process2bdef24e8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=128 schedulerid=1 kpid=10208 status=suspended spid=58 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=2019-02-05T07:34:06.133 lastbatchcompleted=2019-02-05T07:34:06.107 lastattention=1900-01-01T00:00:00.107 clientapp=.Net SqlClient Data Provider hostname=BUILD_SERVER hostpid=3268 loginname=mydomain\admin isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:34:06,spid7s,Unknown,inputbuf
02/05/2019 07:34:06,spid7s,Unknown,executionStack
02/05/2019 07:34:06,spid7s,Unknown,process id=process2ff031848 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=1875 schedulerid=4 kpid=7928 status=background spid=37 sbid=0 ecid=0 priority=0 trancount=0
02/05/2019 07:34:06,spid7s,Unknown,inputbuf
02/05/2019 07:34:06,spid7s,Unknown,executionStack
02/05/2019 07:34:06,spid7s,Unknown,process id=process2f4f5eca8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=625 schedulerid=4 kpid=14180 status=background spid=39 sbid=0 ecid=0 priority=0 trancount=0
02/05/2019 07:34:06,spid7s,Unknown,inputbuf
02/05/2019 07:34:06,spid7s,Unknown,executionStack
02/05/2019 07:34:06,spid7s,Unknown,process id=process2bdbf8ca8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=1809 schedulerid=3 kpid=10904 status=suspended spid=53 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=1900-01-01T00:00:00 lastbatchcompleted=1900-01-01T00:00:00 lastattention=1900-01-01T00:00:00 clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER hostpid=0 loginname=testuser isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:34:06,spid7s,Unknown,inputbuf
02/05/2019 07:34:06,spid7s,Unknown,executionStack
02/05/2019 07:34:06,spid7s,Unknown,process id=process2bb01a8c8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=625 schedulerid=3 kpid=6816 status=background spid=31 sbid=0 ecid=0 priority=0 trancount=0
02/05/2019 07:34:06,spid7s,Unknown,inputbuf
02/05/2019 07:34:06,spid7s,Unknown,executionStack
02/05/2019 07:34:06,spid7s,Unknown,process id=process2f4f0c8c8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=273 schedulerid=2 kpid=9004 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=1900-01-01T00:00:00 lastbatchcompleted=1900-01-01T00:00:00 lastattention=1900-01-01T00:00:00 clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER hostpid=0 loginname=testuser isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:34:06,spid7s,Unknown,inputbuf
02/05/2019 07:34:06,spid7s,Unknown,executionStack
02/05/2019 07:34:06,spid7s,Unknown,process id=process2f64604e8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=1875 schedulerid=2 kpid=11588 status=background spid=36 sbid=0 ecid=0 priority=0 trancount=0
02/05/2019 07:34:06,spid7s,Unknown,process-list
02/05/2019 07:34:06,spid7s,Unknown,deadlock victim=process2f64604e8
02/05/2019 07:34:06,spid7s,Unknown,deadlock-list
02/05/2019 07:34:06,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:06,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:34:04,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:04,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:34:04,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:04,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:34:04,spid22s,Unknown,waiter id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:04,spid22s,Unknown,waiter-list
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2bb01a8c8 mode=X requestType=wait
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2bb01a8c8 mode=S
02/05/2019 07:34:04,spid22s,Unknown,owner-list
02/05/2019 07:34:04,spid22s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=U
02/05/2019 07:34:04,spid22s,Unknown,waiter id=process2ff031c28 mode=X requestType=convert
02/05/2019 07:34:04,spid22s,Unknown,waiter-list
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2f64604e8 mode=X requestType=wait
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2bb01a8c8 mode=X requestType=wait
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2bb01a8c8 mode=S
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2f64604e8 mode=S
02/05/2019 07:34:04,spid22s,Unknown,owner-list
02/05/2019 07:34:04,spid22s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=U
02/05/2019 07:34:04,spid22s,Unknown,waiter id=process2bb01a8c8 mode=X requestType=wait
02/05/2019 07:34:04,spid22s,Unknown,waiter-list
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2ff031c28 mode=X requestType=convert
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2ff031c28 mode=S
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2ff031c28 mode=U
02/05/2019 07:34:04,spid22s,Unknown,owner id=process2ff031c28 mode=S
02/05/2019 07:34:04,spid22s,Unknown,owner-list
02/05/2019 07:34:04,spid22s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=U
02/05/2019 07:34:04,spid22s,Unknown,resource-list
02/05/2019 07:34:04,spid22s,Unknown,inputbuf
02/05/2019 07:34:04,spid22s,Unknown,executionStack
02/05/2019 07:34:04,spid22s,Unknown,process id=process2f64604e8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=840 schedulerid=2 kpid=11588 status=suspended spid=53 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=1900-01-01T00:00:00 lastbatchcompleted=1900-01-01T00:00:00 lastattention=1900-01-01T00:00:00 clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER hostpid=0 loginname=testuser isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:34:04,spid22s,Unknown,WITH REPLACE
02/05/2019 07:34:04,spid22s,Unknown,FROM DISK = 'Z:\bak\mydatabase.bak'
02/05/2019 07:34:04,spid22s,Unknown,RESTORE DATABASE mydatabase
02/05/2019 07:34:04,spid22s,Unknown,inputbuf
02/05/2019 07:34:04,spid22s,Unknown,unknown
02/05/2019 07:34:04,spid22s,Unknown,frame procname=unknown line=2 stmtstart=4 stmtend=326 sqlhandle=0x010001006bf7d11c709f1b7f0200000000000000000000000000000000000000000000000000000000000000
02/05/2019 07:34:04,spid22s,Unknown,executionStack
02/05/2019 07:34:04,spid22s,Unknown,process id=process2ff031c28 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=2222 schedulerid=4 kpid=9444 status=suspended spid=76 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=2019-02-05T07:33:56.687 lastbatchcompleted=2019-02-05T07:33:56.657 lastattention=1900-01-01T00:00:00.657 clientapp=.Net SqlClient Data Provider hostname=BUILD_SERVER hostpid=3268 loginname=mydomain\admin isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:34:04,spid22s,Unknown,inputbuf
02/05/2019 07:34:04,spid22s,Unknown,executionStack
02/05/2019 07:34:04,spid22s,Unknown,process id=process2bb01a8c8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=1364 schedulerid=3 kpid=6816 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=1900-01-01T00:00:00 lastbatchcompleted=1900-01-01T00:00:00 lastattention=1900-01-01T00:00:00 clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER hostpid=0 loginname=testuser isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:34:04,spid22s,Unknown,process-list
02/05/2019 07:34:04,spid22s,Unknown,deadlock victim=process2bb01a8c8
02/05/2019 07:34:04,spid22s,Unknown,deadlock-list
02/05/2019 07:34:03,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:03,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:34:02,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:02,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:34:01,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:01,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:34:01,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:01,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:34:00,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:34:00,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:59,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:59,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:59,spid35s,Unknown,waiter id=process2f4f0c8c8 mode=X requestType=wait
02/05/2019 07:33:59,spid35s,Unknown,waiter-list
02/05/2019 07:33:59,spid35s,Unknown,owner id=process2bdbf8ca8 mode=X requestType=wait
02/05/2019 07:33:59,spid35s,Unknown,owner id=process2bdbf8ca8 mode=S
02/05/2019 07:33:59,spid35s,Unknown,owner-list
02/05/2019 07:33:59,spid35s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:33:59,spid35s,Unknown,waiter id=process2bdbf8ca8 mode=X requestType=wait
02/05/2019 07:33:59,spid35s,Unknown,waiter-list
02/05/2019 07:33:59,spid35s,Unknown,owner id=process2f4f0c8c8 mode=X requestType=wait
02/05/2019 07:33:59,spid35s,Unknown,owner id=process2f4f0c8c8 mode=S
02/05/2019 07:33:59,spid35s,Unknown,owner-list
02/05/2019 07:33:59,spid35s,Unknown,databaselock subresource=FULL dbid=6 dbname=unknown lockPartition=0 id=lock2bcae4680 mode=S
02/05/2019 07:33:59,spid35s,Unknown,resource-list
02/05/2019 07:33:59,spid35s,Unknown,inputbuf
02/05/2019 07:33:59,spid35s,Unknown,executionStack
02/05/2019 07:33:59,spid35s,Unknown,process id=process2f4f0c8c8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=461 schedulerid=2 kpid=9004 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=1900-01-01T00:00:00 lastbatchcompleted=1900-01-01T00:00:00 lastattention=1900-01-01T00:00:00 clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER hostpid=0 loginname=testuser isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:33:59,spid35s,Unknown,inputbuf
02/05/2019 07:33:59,spid35s,Unknown,executionStack
02/05/2019 07:33:59,spid35s,Unknown,process id=process2bdbf8ca8 taskpriority=0 logused=10000 waitresource=DATABASE: 6:0  waittime=461 schedulerid=3 kpid=10904 status=suspended spid=53 sbid=0 ecid=0 priority=0 trancount=0 lastbatchstarted=1900-01-01T00:00:00 lastbatchcompleted=1900-01-01T00:00:00 lastattention=1900-01-01T00:00:00 clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER hostpid=0 loginname=testuser isolationlevel=read committed (2) xactid=0 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
02/05/2019 07:33:59,spid35s,Unknown,process-list
02/05/2019 07:33:59,spid35s,Unknown,deadlock victim=process2bdbf8ca8
02/05/2019 07:33:59,spid35s,Unknown,deadlock-list
02/05/2019 07:33:58,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:58,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:57,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:57,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:56,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:56,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:55,Logon,Unknown,Login failed for user 'testuser'. Reason: Failed to open the explicitly specified database 'mydatabase'. [CLIENT: 11.11.11.11]
02/05/2019 07:33:55,Logon,Unknown,Error: 18456<c/> Severity: 14<c/> State: 38.
02/05/2019 07:33:53,spid76,Unknown,Setting database option SINGLE_USER to ON for database 'mydatabase'.
02/05/2019 07:33:03,spid65,Unknown,DBCC TRACEON 1222<c/> server process ID (SPID) 65. This is an informational message only; no user action is required.

I pasted some logs, but I do not have idea where is actually a deadlock. I will appreciate any hints.

UPDATE 2

If I restart SQL services before restore, then problem disappears. But after some minutes I am getting the same error and following query:

SELECT
    [er].[session_id],
    [es].[program_name],
    'xxx', --[est].text,
    DB_NAME([er].[database_id]),
    'xxx', --[eqp].[query_plan],
    [er].[cpu_time]
FROM sys.dm_exec_requests [er]
INNER JOIN sys.dm_exec_sessions [es] ON
    [es].[session_id] = [er].[session_id]
OUTER APPLY sys.dm_exec_sql_text ([er].[sql_handle]) [est]
OUTER APPLY sys.dm_exec_query_plan ([er].[plan_handle]) [eqp]
WHERE
    [es].[is_user_process] = 1
    AND [er].[last_Wait_type] = N'SOS_SCHEDULER_YIELD'
ORDER BY
    [er].[session_id];
GO

gives me:

+------------+--------------------------------------+------------------+------------------+------------------+----------+
| session_id |             program_name             | (No column name) | (No column name) | (No column name) | cpu_time |
+------------+--------------------------------------+------------------+------------------+------------------+----------+
|         63 | Microsoft JDBC Driver for SQL Server | xxx              | mydatabase       | xxx              |       17 |
|         74 | Microsoft JDBC Driver for SQL Server | xxx              | mydatabase       | xxx              |      316 |
+------------+--------------------------------------+------------------+------------------+------------------+----------+

How it is possible that even I switch db to single mode, some processes are blocking it?

UPDATE 3

As per comments I added following trigger to db server:

USE [master]
GO

SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

create trigger [ddl_tr_alter_database]  
on all server with execute as 'sa' 
for alter_database   
as 
    set nocount on;
    insert dbo.ddl_hist (tsql_) 
    select EVENTDATA().value('(/EVENT_INSTANCE/TSQLCommand/CommandText)[1]','nvarchar(max)')  

GO

ENABLE TRIGGER [ddl_tr_alter_database] ON ALL SERVER
GO

The table looks following after two failed restores:

+----+-------------------------+----------------+-------------------------------------------------------------------+
| id |           dt            |     user_      |                               tsql_                               |
+----+-------------------------+----------------+-------------------------------------------------------------------+
|  1 | 2019-02-13 09:23:39.443 | mydomain\admin | ALTER DATABASE mydatabase SET SINGLE_USER WITH ROLLBACK IMMEDIATE |
|  2 | 2019-02-13 09:30:45.080 | mydomain\admin | ALTER DATABASE mydatabase SET MULTI_USER WITH ROLLBACK IMMEDIATE  |
|  3 | 2019-02-13 10:14:52.740 | mydomain\admin | ALTER DATABASE mydatabase SET SINGLE_USER WITH ROLLBACK IMMEDIATE |
|  4 | 2019-02-13 10:20:19.337 | mydomain\admin | ALTER DATABASE mydatabase SET RECOVERY SIMPLE                     |
|  5 | 2019-02-13 10:20:19.370 | mydomain\admin | ALTER DATABASE mydatabase SET MULTI_USER WITH ROLLBACK IMMEDIATE  |
|  6 | 2019-02-13 10:51:34.380 | mydomain\admin | ALTER DATABASE mydatabase SET SINGLE_USER WITH ROLLBACK IMMEDIATE |
|  7 | 2019-02-13 10:55:57.597 | mydomain\admin | ALTER DATABASE mydatabase SET RECOVERY SIMPLE                     |
|  8 | 2019-02-13 10:55:57.630 | mydomain\admin | ALTER DATABASE mydatabase SET MULTI_USER WITH ROLLBACK IMMEDIATE  |
|  9 | 2019-02-13 12:32:55.430 | mydomain\admin | ALTER DATABASE mydatabase SET SINGLE_USER WITH ROLLBACK IMMEDIATE |
+----+-------------------------+----------------+-------------------------------------------------------------------+

See what happend:

║ ID = 1, 2    ║ Started script to restore database, so at first switching db to the single_mode. Script failed because of restore operation. By next 7 minutes I was trying to restart SQL Service, switch back to the multi_user mode etc. And finaly I could switch to multi_user at 2019-02-13 09:30:45.080 
║ ID = 3, 4, 5 ║ Started and finished successfully script for restoring db                                                                                                                                                                                                                                       
║ ID = 6, 7, 8 ║ Started and finished successfully script for restoring db                                                                                                                                                                                                                                       
║ ID = 9, 10   ║ Issue occurrs again as in ID = 1, 2

UPDATE 4

@@Version is Microsoft SQL Server 2014 - 12.0.4100.1 (X64) Apr 20 2015 17:29:27 Copyright (c) Microsoft Corporation Standard Edition (64-bit) on Windows NT 6.3 <X64> (Build 9600: ) (Hypervisor)

You have 2 other processes:clientapp=Microsoft JDBC Driver for SQL Server hostname=APPSERVER loginname=testuser that are trying to execute ALTER DATABASE. What exactly they are trying to do? — sepupic, Feb 5, 2019 at 15:01
I just update the question, please check it. Regarding your question - i am not sure, seems that these're some application processes. And unfortunately I cannot share these queries. I'm not sure why something is block db once it's set to single mode. Some pending system processes that have to be killed? — bontade, Feb 5, 2019 at 18:11
Your update gives no useful information. We need the commands of these 2 processes to understand what's going on. Those processes wait for X on the same database, my guess they are doing ALTER DATABASE, but if you cannot niether confirm nor deny it it's impossible to help you — sepupic, Feb 6, 2019 at 7:03
No, you are wrong. If you look at the resource list you'll see that they are waiting for X lock on the same database: mode=X requestType=wait. It's not required for doing just SELECT, it's required to do ALTER DATABASE — sepupic, Feb 11, 2019 at 14:32
I posted ddl-trigger text to catch your ALTER DATABASE statements. I checked the default trace and even when there are ALTER DATABASE events, there is no T-SQL text for them, so they are not informative — sepupic, Feb 13, 2019 at 8:23

Kin Shah · Accepted Answer · 2019-02-04 19:39:19Z

There is no point in taking db into single user mode and then making it offline. background service like sql agent might try to connect to the db.

If you want to get more details of what process is getting deadlock then you can enable TF 1222 (dbcc traceon (1222, -1) ) and then disable it (dbcc traceoff (1222, -1)) or use Event notification (link to my script)

Just ALTER DATABASE mydatabase SET OFFLINE WITH ROLLBACK IMMEDIATE, restore the db with recovery.

Edit:

I am working on PS script to restore database backups

Have a look at dbatools (community driven PowerShell module to automate database development and administration). You can check the code on github. This way you can learn and contribute back.

sepupic · Accepted Answer · 2019-02-14 12:55:14Z

You can use the following code to catch your ALTER DATABASE statements launched by your application server:

use master;

create table dbo.ddl_hist(
    [id] [int] identity(1,1) not null,
    [dt] [datetime] null,
    [user_] [varchar](40) null,
    [tsql_] [varchar](1000) null,
 constraint [pk_ddl_hist] primary key clustered ([id]))
go

alter table dbo.ddl_hist add  default (getdate()) for [dt]
go

alter table dbo.ddl_hist add  default (original_login()) for [user_]
go


alter trigger ddl_tr_alter_database  
on all server   
with execute as 'sa' 
for alter_database   
as 
    set nocount on;
    insert dbo.ddl_hist (tsql_) 
    select EVENTDATA().value('(/EVENT_INSTANCE/TSQLCommand/CommandText)[1]','nvarchar(max)')  
go

UPDATE

If the ddl-trigger did not catch what we wanted you can set up event session that will catch waits:

CREATE EVENT SESSION [TestSession] ON SERVER 
ADD EVENT sqlos.wait_info(
    ACTION(sqlserver.client_app_name,sqlserver.nt_username,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_stack)
    WHERE ([sqlserver].[client_app_name]=N'MYAPP')
    )
ADD TARGET package0.event_file(SET filename=N'C:\tmp1\TestSession')
WITH (MAX_MEMORY=4096 KB, EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)

You can start/stop the session from SSMS and you can parse the trace to find out X-locks:

with t as
(
 select
  cast(event_data as xml) as event_data
 from
  sys.fn_xe_file_target_read_file(N'C:\tmp1\TestSession*.xel', null, null, null)
)
select
 e.n.value('(action[@name = "sql_text"]/value)[1]', 'nvarchar(max)'),
 e.n.query('.')
from
 t cross apply
 t.event_data.nodes('/event[data[@name = "wait_type"]/text/text() = "LCK_M_X"]') e(n)

Thanks. I updated the post with the results from this table. — bontade, Feb 13, 2019 at 12:47
You did not catch ALTER DATABASE executed by testuser. In your deadlock there were 3 processes: 1 executed under mydomain\admin (restore) and 2 others under testuser. We still don't know what is the code executed by testuser. I suppose it executes ALTER DATABASE as it waits for exclusive database lock. For now you did not catch the code executed by testuser — sepupic, Feb 13, 2019 at 12:58
I updated my answer with event session code that you can use to catch what code executes your application server while it's waiting for X-lock on a database — sepupic, Feb 14, 2019 at 12:56
This is very strange. We have a confirmation that it is Microsoft JDBC Driver for SQL Server that requests X on a database, but there is no way to see what it executes. Can you permit to use Profiler in this environment? To filter out all the queries sent by testuser as login, Microsoft JDBC Driver for SQL Server as application name — sepupic, Feb 15, 2019 at 10:17
Ok, it's not RTM, even if SP1 is not a maximum, you can upgrade to SP3. It seems like a bug so you can contact MS support, or you can try to change your restore script with deadlock_priority = high — sepupic, Feb 18, 2019 at 7:30

KASQLDBA · Accepted Answer · 2019-02-13 05:27:02Z

0

In addition to Kin answer, if there is a stop for not using trace flags , you can check the inbuilt system health session within extended events. View the target data and then do a grouping on the events. You will see deadlocks being captured within event called xml_deadlock_report with all needed info.

Also what I do during restore if single user does not work and you find there is this one app from one login keeps connecting, I will remove it's mapping from restored DB and later map it back. Dirty but works for me.

answered Feb 13, 2019 at 5:27

KASQLDBA

7,1296 gold badges26 silver badges52 bronze badges

1

>>>You will see deadlocks being captured within event called xml_deadlock_report with all needed info<<< The deadlock graph is already captured. But it contains no info about other 2 sessions input buffer
– sepupic
Feb 13, 2019 at 13:42

Add a comment |

Stack Exchange Network

Transaction deadlock during restore

3 Answers 3

Your Answer

Not the answer you're looking for? Browse other questions tagged
sql-server
sql-server-2014
restore
deadlock
or ask your own question.

Linked

Hot Network Questions

Transaction deadlock during restore

3 Answers 3

Your Answer

Sign up or log in

Post as a guest

Not the answer you're looking for? Browse other questions tagged sql-serversql-server-2014restoredeadlock or ask your own question.

Linked

Related

Hot Network Questions

Not the answer you're looking for? Browse other questions tagged
sql-server
sql-server-2014
restore
deadlock
or ask your own question.