一、现象
1、2台SQLServer使用事物日志传送的方式做的灾备,具体配置如下:
数据库数量:1
数据库大小:85G
主库备份作业频率:每5分钟备份一次
备库cop也作业频率:每5分钟执行一次
备库还原作业频率:每5分钟执行一次
备库的模式是:备用模式(在还原备份时断开数据库用户的连接)
2、主库的备份作业正常,备库的copy作业正常,备库的restore作业也没有报错,但是作业里面的步骤有错误,如下:
2020-05-12 09:25:05.95 The restore operation was successful. Secondary ID: 'f89cf291-924f-4dc2-adce-bd6e4cfb636d'
2020-05-12 09:25:05.95 *** Error: Could not log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.95 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.95 *** Error: Could not cleanup history.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.95 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.95 ----- END OF TRANSACTION LOG RESTORE -----
消息
ot log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.92 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.92 Skipping log backup file 'F: rans_logceb_im_20200512011500.trn' for secondary database 'ceb_im' because the file could not be verified.
2020-05-12 09:25:05.92 *** Error: Could not log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.92 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.92 *** Error: An error occurred restoring the database access mode.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.92 *** Error: ExecuteScalar 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.92 *** Error: Could not log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.92 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.92 *** Error: Could not apply log backup file 'F: rans_logceb_im_20200512012000.trn' to secondary database 'ceb_im'.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.92 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.92 *** Error: Could not log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.92 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.92 Skipping log backup file 'F: rans_logceb_im_20200512012000.trn' for secondary database 'ceb_im' because the file could not be verified.
2020-05-12 09:25:05.92 *** Error: Could not log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.92 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.93 The restore operation was successful. Secondary Database: 'ceb_im', Number of log backup files restored: 0
2020-05-12 09:25:05.93 *** Error: Could not log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.93 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。(System.Data) ***
2020-05-12 09:25:05.93 Deleting old log backup files. Primary Database: 'ceb_im'
2020-05-12 09:25:05.93 *** Error: Could not log history/error message.(Microsoft.SqlServer.Management.LogShipping) ***
2020-05-12 09:25:05.93 *** Error: ExecuteNonQuery 要求已打开且可用的连接。连接的当前状态为已关闭。
二、问题分析
1、备库的状态应该是“备用/只读”,但是有一天突然变成了“正在还原”,查看主库上的备份作业执行正常,查看备库上copy和restore作业执行正常,没有报错;
2、查看存放日志备份的共享文件夹,发现2边文件保持一致,并且还在不断备份和copy新的文件过来,所以备份和copy的作业应该没有问题;
3、查看restore的作业,虽然作业执行成功了,但是里面有Error错误,发现还在还原几天前的日志文件,问题应该出现这个restore作业;
4、根据系统视图restorehistory查看还原历史,发现最后一次还原是4月25号,找到这个日志备份,手动还原,能还原成功,LSN号能衔接上,如下:
命令: select * from msdb.dbo.restorehistory order by restore_date desc
5、查看事物日志传送的状态,发现最后一个文件的滞后时间达到8234min;
三、处理方法
1、把主库的完整备份重新备份一次,在备库上还原即可,下次restore作业就会接着最新的备份LSN继续还原了。
2、或者重新搭建事物日志同步。
四、总结
1、出现这种问题,就是某一次日志接不上了,restore作业在日志备份的文件夹,一直在找对应的备份找不到,导致滞后了,加上我们的频率是5分钟,太频繁,所以每次执行restore作业的时候,大部分的时间用在Skipping log backup file了,还没找到正确的备份,就得开始下一次作业了,导致出现了这种死循环,一直找不到正确的日志备份。
2、至于为什么日志会接不上了? 为什么每次restore作业会Skipping log,遍历的方式来找正确的日志?还没找到原因。