Sql-server – Transaction deadlock during restore

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)

Best Answer

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.

Best Answer

Related Solutions

Sql-server – Login failed for user Error: 18456 State: 10

SQL Server – Create Login and User for Single Schema Access

Related Question