Double backup

rbvdberg · August 23, 2010 8:46AM

This morning I found that SQLBackup made 2 consecutive transaction log backups, though SQL Server only ran 1 backup job. Since both backups were started in the same second and we use the auto name feature, the second backup was written over the first backup. Therefore, we're missing the first transaction log backup. We're using Redgate 6.4.

Any thoughts on how to prevent this?

petey · August 23, 2010 10:56PM

Could you please run the following query:

SELECT a.backup_start_date, b.physical_device_name, b.device_type, a.first_lsn, a.last_lsn
FROM msdb..backupset a 
INNER JOIN msdb..backupmediafamily b ON a.media_set_id = b.media_set_id
WHERE a.type = 'L'
  AND a.database_name = &lt;your database name&gt;
  AND a.backup_start_date &gt; '2010-08-23'
  AND a.backup_start_date &lt; '2010-08-23 12:00'
ORDER BY a.backup_start_date

and post here the relevant rows for the duplicate backups, and also the rows for the prior and subsequent backups?

Thanks.

rbvdberg · August 24, 2010 2:37AM

Hello Peter,

Here are the relevant rows:

2010-08-22 03:12:39.000 \\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\LOG_ROME_ACC_dbsExodus_20100822_031238.sqb 7 305000009615400001 305000009615400001
2010-08-22 05:12:38.000 \\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\LOG_ROME_ACC_dbsExodus_20100822_051238.sqb 7 305000009615400001 305000009616100001
2010-08-22 05:12:38.000 \\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\LOG_ROME_ACC_dbsExodus_20100822_051238.sqb 7 305000009616100001 305000009616100001
2010-08-22 07:12:38.000 \\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\LOG_ROME_ACC_dbsExodus_20100822_071238.sqb 7 305000009616100001 305000009616100001

petey · August 24, 2010 3:30AM

Thanks for sending the details. That confirms that there were indeed 2 transaction log backups that started at the same time.

Could you please post the contents of the SQL Backup log files for both those backups? The default folder where the logs are stored is C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance name> on Windows 2003 and older, and C:\ProgramData\Red Gate\SQL Backup\Log\<instance name> for Windows Vista and newer.

rbvdberg · August 24, 2010 5:05AM

Hello Peter,

This is the contents of log 1:
SQL Backup log file 6.4.0.56

-SQL "BACKUP LOGS [dbsExodus] TO DISK = '\\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', PASSWORD = 'XXXXXXXXXX', KEYSIZE = 256, ERASEFILES = 2, COMPRESSION = 1, THREADS = 1 "

ERRORS AND WARNINGS

8/22/2010 5:12:38 AM: Backing up dbsExodus (transaction log) on ROME_ACC instance to:
8/22/2010 5:12:38 AM: \\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\LOG_ROME_ACC_dbsExodus_20100822_051238.sqb

8/22/2010 5:12:38 AM: Warning 462: Short passwords may not be secure.
8/22/2010 5:12:38 AM: BACKUP LOG [dbsExodus] TO VIRTUAL_DEVICE = 'SQLBACKUP_8D78215C-B741-4123-BF5E-3B54B25DC0F7' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (dbsExodus), 8/22/2010 5:12:38 AM', DESCRIPTION = N'Backup on 8/22/2010 5:12:38 AM Server: DBS-VR1274\ROME_ACC Database: dbsExodus', FORMAT

8/22/2010 5:12:38 AM: Backup data size : 640.000 KB
8/22/2010 5:12:38 AM: Compressed data size: 4.000 KB
8/22/2010 5:12:38 AM: Compression rate : 99.38%

8/22/2010 5:12:38 AM: Processed 1 pages for database 'dbsExodus', file 'dbsExodus_Log_1' on file 1.
8/22/2010 5:12:38 AM: BACKUP LOG successfully processed 1 pages in 0.022 seconds (0.162 MB/sec).

And this is the contents of the second log file:

SQL Backup log file 6.4.0.56

-SQL "BACKUP LOGS [dbsExodus] TO DISK = '\\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\<AUTO>' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', PASSWORD = 'XXXXXXXXXX', KEYSIZE = 256, ERASEFILES = 2, COMPRESSION = 1, THREADS = 1 "

ERRORS AND WARNINGS

8/22/2010 5:12:38 AM: Backing up dbsExodus (transaction log) on ROME_ACC instance to:
8/22/2010 5:12:38 AM: \\hwnafvab1\sqllog03\DBS-VR1274\ROME_ACC\dbsExodus\LOG_ROME_ACC_dbsExodus_20100822_051238.sqb

8/22/2010 5:12:38 AM: Warning 462: Short passwords may not be secure.
8/22/2010 5:12:38 AM: BACKUP LOG [dbsExodus] TO VIRTUAL_DEVICE = 'SQLBACKUP_B850A1C3-10D1-4749-9AD7-D5B822754F07' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (dbsExodus), 8/22/2010 5:12:38 AM', DESCRIPTION = N'Backup on 8/22/2010 5:12:38 AM Server: DBS-VR1274\ROME_ACC Database: dbsExodus', FORMAT

8/22/2010 5:12:38 AM: Backup data size : 512.000 KB
8/22/2010 5:12:38 AM: Compressed data size: 4.000 KB
8/22/2010 5:12:38 AM: Compression rate : 99.22%

8/22/2010 5:12:38 AM: Processed 0 pages for database 'dbsExodus', file 'dbsExodus_Log_1' on file 1.
8/22/2010 5:12:38 AM: BACKUP LOG successfully processed 0 pages in 0.002 seconds (0.000 MB/sec).

And yes, we'll be fixing the password strength sometime in the future...

petey · August 24, 2010 6:39AM

Were these backups ran using SQL Server Agent jobs?

Thanks.

rbvdberg · August 24, 2010 6:41AM

Hello Peter,

Yes. We use some custom code to call SQLBackup, but yes, we do this from a SQL Server agent job.

petey · August 24, 2010 6:53AM

Any idea how the SQL Server Agent job ran twice, or did the code decide to run the same backup for that database twice? SQL Backup did not run the backup twice within its same process, otherwise there would only have been one log file with details of 2 backup processes. If you have two log files, it means 2 distinct backup processes were started.

A workaround may be to add the milisecond element to the <AUTO> naming convention file e.g.

<TYPE>_<DATABASE>_<DATETIME yyyymmdd_hhnnsszzzz>

rbvdberg · August 24, 2010 8:48AM

Hello Peter,

I have no idea why we have two backups. I only see one job in the job history, and our custom code does sometimes decide to run another backup (after specific error codes), but always after a 10 second delay (WAITFOR DELAY '000:00:10').

Double backup

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk