Random verify failures but the GUI is reporting success

DBA_DaveDBA_Dave Posts: 31
edited October 9, 2007 10:44AM in SQL Backup Previous Versions
Last night SQL Backup reported two verify failures. The GUI is reporting that the files successfully verified.

Random failures I understand - I'm running Windows, but telling me that something succeeded when it in fact failed is extremely troubling.

Can we get this fixed? It is really, really important to know when a verify job failed.




Here is one example:

(I forwarded the full report to support@redgate.com)

9/25/2007 12:49:49 AM: Backing up CAE2 (full database) to:
9/25/2007 12:49:49 AM: o:\BACKUP\Tue\FULL_SQL65TEST400_CAE2_2007.Sep.25.004949.sqb

9/25/2007 12:49:49 AM: BACKUP DATABASE [CAE2] TO DISK = 'o:\BACKUP\<DATETIME ddd>\<AUTO>.sqb' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', VERIFY, ERASEFILES_ATSTART = 8, MAILTO = 'drutledge@snl.com', COMPRESSION = 2, THREADCOUNT = 3

9/25/2007 12:49:50 AM: Database size : 23.688 MB
9/25/2007 12:49:50 AM: Compressed data size: 1.859 MB
9/25/2007 12:49:50 AM: Compression rate : 92.15%

Processed 936 pages for database 'CAE2', file 'CAE2_Data' on file 1.
Processed 4 pages for database 'CAE2', file 'CAE2_Log' on file 1.
BACKUP DATABASE successfully processed 940 pages in 0.194 seconds (39.661 MB/sec).
9/25/2007 12:49:51 AM:
9/25/2007 12:49:51 AM: Validating files:
9/25/2007 12:49:51 AM: o:\BACKUP\Tue\FULL_SQL65TEST400_CAE2_2007.Sep.25.004949.sqb
9/25/2007 12:49:51 AM:
9/25/2007 12:49:51 AM: RESTORE VERIFYONLY FROM DISK = 'o:\BACKUP\Tue\FULL_SQL65TEST400_CAE2_2007.Sep.25.004949.sqb'

The backup set on file 1 is valid.

9/25/2007 12:49:51 AM: Backing up Calcs (full database) to:
9/25/2007 12:49:51 AM: o:\BACKUP\Tue\FULL_SQL65TEST400_Calcs_2007.Sep.25.004951.sqb

9/25/2007 12:49:51 AM: BACKUP DATABASE [Calcs] TO DISK = 'o:\BACKUP\<DATETIME ddd>\<AUTO>.sqb' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', VERIFY, ERASEFILES_ATSTART = 8, MAILTO = 'drutledge@snl.com', COMPRESSION = 2, THREADCOUNT = 3

9/25/2007 1:06:43 AM: Database size : 44.003 GB
9/25/2007 1:06:43 AM: Compressed data size: 12.991 GB
9/25/2007 1:06:43 AM: Compression rate : 70.48%

Processed 5436576 pages for database 'Calcs', file 'Calcs_Data' on file 1.
Processed 2 pages for database 'Calcs', file 'Calcs_Log' on file 1.
BACKUP DATABASE successfully processed 5436578 pages in 1010.591 seconds (44.069 MB/sec).
9/25/2007 1:06:43 AM:
9/25/2007 1:06:43 AM: Validating files:
9/25/2007 1:06:43 AM: o:\BACKUP\Tue\FULL_SQL65TEST400_Calcs_2007.Sep.25.004951.sqb
9/25/2007 1:06:43 AM:
9/25/2007 1:06:43 AM: RESTORE VERIFYONLY FROM DISK = 'o:\BACKUP\Tue\FULL_SQL65TEST400_Calcs_2007.Sep.25.004951.sqb'

9/25/2007 1:13:14 AM: Thread 0 error:
Process terminated unexpectedly. Error code: -2139684860

Device index out of range: 9
9/25/2007 1:13:14 AM: Thread 1 error:
Failed to service command. Error code: -2139684860
Process terminated unexpectedly. Error code: -2139684860

Device index out of range: 9
9/25/2007 1:13:14 AM: Thread 2 error:
Failed to service command. Error code: -2139684860
Process terminated unexpectedly. Error code: -2139684860

Device index out of range: 9

SQL error 3013: SQL error 3013: VERIFY DATABASE is terminating abnormally.
SQL error 3203: SQL error 3203: Read on "SQLBACKUP_9471928C-55CC-45A2-9FDB-93946137FC8D" failed: 995(The I/O operation has been aborted because of either a thread exit or an application request.)
9/25/2007 1:13:14 AM: Validation of all backup files failed.


I ran the job myself and it passed:

EXECUTE master..sqlbackup
'-SQL "RESTORE VERIFYONLY FROM DISK = ''o:\BACKUP\Tue\FULL_SQL65TEST400_Calcs_2007.Sep.25.004951.sqb''" -E'


SQL Backup v5.1.0.2781
Verifying file:
o:\BACKUP\Tue\FULL_SQL65TEST400_Calcs_2007.Sep.25.004951.sqb

The backup set on file 1 is valid.
SQL Backup process ended.



(7 row(s) affected)


(7 row(s) affected)

name value
exitcode 0
sqlerrorcode 0
filename001 o:\BACKUP\Tue\FULL_SQL65TEST400_Calcs_2007.Sep.25.004951.sqb
Dave Rutledge
Database Administrator
SNL Financial LC
· Share on Twitter

Comments

  • David SmithDavid Smith Posts: 13
    Same thing happened with one of our backups this morning....
    At least the MAILTO_ONERROR worked and we got notified. But the GUI showing all is well isn't so great.

    David


    SQL Backup log file
    27/09/2007 1:00:00 a.m.: Backing up db1 (full database) to:
    27/09/2007 1:00:00 a.m.: F:\sqlbackup\db1\db1_db_20070927010000.sqb
    27/09/2007 1:00:00 a.m.: \\svr1\shipping\nzsql2005-1\db1\db1_db_20070927010000.sqb

    27/09/2007 1:00:00 a.m.: BACKUP DATABASE [db1] TO DISK = 'F:\sqlbackup\db1\db1_db_<DATETIME yyyymmddhhnnss>.sqb' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', INIT, MIRRORFILE = '\\svr1\shipping\nzsql2005-1\db1\db1_db_<DATETIME yyyymmddhhnnss>.sqb', VERIFY, ERASEFILES = 2, MAILTO_ONERROR = 'servers@site.com', COPYTO = '\\svr2\nzsql2005-1\db1\', FILEOPTIONS = 5, COMPRESSION = 2, THREADCOUNT = 2

    27/09/2007 1:55:43 a.m.: Database size : 151.517 GB
    27/09/2007 1:55:43 a.m.: Compressed data size: 52.078 GB
    27/09/2007 1:55:43 a.m.: Compression rate : 65.63%

    Processed 9811848 pages for database 'db1', file 'db1_Data' on file 1.
    Processed 6655760 pages for database 'db1', file 'db1_data2' on file 1.
    Processed 110168 pages for database 'db1', file 'db1_clientdata' on file 1.
    Processed 640920 pages for database 'db1', file 'db1_mailheader' on file 1.
    Processed 13645 pages for database 'db1', file 'db1_Log' on file 1.
    BACKUP DATABASE successfully processed 17232341 pages in 3340.114 seconds (42.264 MB/sec).
    27/09/2007 1:56:14 a.m.:
    27/09/2007 1:56:14 a.m.: Validating files:
    27/09/2007 1:56:14 a.m.: F:\sqlbackup\db1\db1_db_20070927010000.sqb
    27/09/2007 1:56:14 a.m.:
    27/09/2007 1:56:14 a.m.: RESTORE VERIFYONLY FROM DISK = 'F:\sqlbackup\db1\db1_db_20070927010000.sqb'

    27/09/2007 1:58:35 a.m.: Thread 0 error:

    Device index out of range: 238
    27/09/2007 1:58:35 a.m.: Thread 1 error:

    Device index out of range: 238

    SQL error 3013: SQL error 3013: VERIFY DATABASE is terminating abnormally.
    SQL error 3203: SQL error 3203: Read on "SQLBACKUP_5D7C1B82-8F55-493D-9E16-BE14DBCA9B17" failed: 995(error not found)
    27/09/2007 1:58:36 a.m.: Validation of all backup files failed.
    27/09/2007 1:58:36 a.m.: Mail sent successfully to: servers@site.com
    · Share on Twitter
  • Jason CookJason Cook Posts: 185
    Hi,
    If possible, could you perform the following query on the instance that created the backup:
    master..sqbdata 'SELECT * from backuphistory 
  WHERE dbname = ''&lt;db_name&gt;'' AND backup_start &gt; ''2007-09-27'' 
  AND backup_start &lt; ''2007-09-28'' ';

    This communicates with the server components internal data store, and should return one or more rows of data which relate to the backups performed during this timeframe (adjust the dates as necessary).

    For the row that relates to the failed backup, could you copy the entire row, and paste it into an email and send it to me at jason.cook@red-gate.com please? Of particular interest is the values "verified", "code" and "sqlerrorcode" - which relate to the backup state and verification state respectively.

    Thanks,
    Jason
    · Share on Twitter
  • DBA_DaveDBA_Dave Posts: 31
    The query returned 0 rows.
    Dave Rutledge
    Database Administrator
    SNL Financial LC
    · Share on Twitter
  • Jason CookJason Cook Posts: 185
    Hi DBA_Dave,
    In your case, you'll need to use the following (the 27th - 28th date range was for the other David):
    master..sqbdata 'SELECT * from backuphistory
  WHERE dbname = ''&lt;db_name&gt;'' AND backup_start &gt; ''2007-09-25''
  AND backup_start &lt; ''2007-09-26'' ';

    What I'm interested in is the values of "verified", "code" and "sqlerrorcode" for the backup in question, since they are what determine to the SQL Backup GUI whether it was verified or not.

    Thanks,
    Jason
    · Share on Twitter
  • DBA_DaveDBA_Dave Posts: 31
    master..sqbdata 'SELECT * from backuphistory
    WHERE dbname = ''CALCS'' AND backup_start > ''2007-09-27''
    AND backup_start < ''2007-09-28'' ';

    14341 {0038C556-4401-4ECA-AC1F-92316DAB1CF3} 2007-09-27 00:48:16.547 2007-09-27 01:05:14.533 D Calcs 0 70.456802 2 1016 47314042880 13978082816 43.943001 3 1 SNL\sqltestservices 1 0 0

    master..sqbdata 'SELECT * from backuphistory
    WHERE dbname = ''CAE2'' AND backup_start > ''2007-09-27''
    AND backup_start < ''2007-09-28'' ';

    14340 {0567A3BD-4B23-45DE-8B9B-1820E808923C} 2007-09-27 00:48:14.000 2007-09-27 00:48:16.343 D CAE2 0 92.222542 2 1 24838144 1931776 33.608002 3 1 SNL\sqltestservices 1 0 0
    14425 {8ACD6D0F-5E62-484B-A585-2D5633CEFE23} 2007-09-27 08:00:10.637 2007-09-27 08:00:13.293 L CAE2 0 97.795761 3 0 1835008 40448 3.5079999 3 1 SNL\sqltestservices 1 0 0
    14447 {52FB7B3B-CF4C-4786-98D7-76943308BA2C} 2007-09-27 08:30:09.050 2007-09-27 08:30:10.833 L CAE2 0 99.008415 3 0 1703936 16896 0.02 3 1 SNL\sqltestservices 1 0 0
    14469 {E80DBC5C-DEF2-4CBC-B459-297349CE2561} 2007-09-27 09:00:12.217 2007-09-27 09:00:14.327 L CAE2 0 99.03846 3 0 1703936 16384 0.003 3 1 SNL\sqltestservices 1 0 0
    14491 {C4CA9F3B-68B2-4992-8106-ADD97CCE3F17} 2007-09-27 09:30:15.993 2007-09-27 09:30:17.930 L CAE2 0 99.008415 3 0 1703936 16896 2.0000001E-3 3 1 SNL\sqltestservices 1 0 0
    14513 {8464A5FD-467A-4488-AB65-2A0408964059} 2007-09-27 10:00:17.713 2007-09-27 10:00:19.903 L CAE2 0 99.008415 3 0 1703936 16896 1.7999999E-2 3 1 SNL\sqltestservices 1 0 0
    14535 {BC8C49F2-9109-488B-8DF5-EB992C4729BB} 2007-09-27 10:30:19.190 2007-09-27 10:30:20.910 L CAE2 0 99.008415 3 0 1703936 16896 2.8000001E-2 3 1 SNL\sqltestservices 1 0 0
    14557 {A51C0AFF-E0C1-4506-B051-E0522F7D8362} 2007-09-27 11:00:14.060 2007-09-27 11:00:16.620 L CAE2 0 99.008415 3 0 1703936 16896 0.003 3 1 SNL\sqltestservices 1 0 0
    14579 {8E350CD8-E9C7-485A-93B0-12D9E40EDBA7} 2007-09-27 11:30:09.223 2007-09-27 11:30:10.817 L CAE2 0 99.008415 3 0 1703936 16896 2.6000001E-2 3 1 SNL\sqltestservices 1 0 0
    14601 {F155873F-8F95-4551-B5F0-8A4E919C4201} 2007-09-27 12:00:17.967 2007-09-27 12:00:20.903 L CAE2 0 99.008415 3 0 1703936 16896 2.0000001E-3 3 1 SNL\sqltestservices 1 0 0
    14623 {D5B5957E-A35B-43E6-B1A0-A0593D63E40B} 2007-09-27 12:30:14.520 2007-09-27 12:30:16.367 L CAE2 0 99.008415 3 0 1703936 16896 4.9999999E-3 3 1 SNL\sqltestservices 1 0 0
    14645 {374361F6-649A-467F-8BC0-CD75807414F2} 2007-09-27 13:00:13.297 2007-09-27 13:00:14.983 L CAE2 0 99.008415 3 0 1703936 16896 0.025 3 1 SNL\sqltestservices 1 0 0
    14667 {98E6BC69-CAB8-4E5F-B058-830AC1685869} 2007-09-27 13:30:20.100 2007-09-27 13:30:22.757 L CAE2 0 99.008415 3 0 1703936 16896 6.0000001E-3 3 1 SNL\sqltestservices 1 0 0
    14689 {93FD66F9-AEAC-453C-A24B-7A37E37FC3E8} 2007-09-27 14:00:14.703 2007-09-27 14:00:16.703 L CAE2 0 99.008415 3 0 1703936 16896 0.021 3 1 SNL\sqltestservices 1 0 0
    14711 {B416921E-E907-4EF4-B52C-7AACB6F8B8D4} 2007-09-27 14:30:12.273 2007-09-27 14:30:14.257 L CAE2 0 99.008415 3 0 1703936 16896 0.025 3 1 SNL\sqltestservices 1 0 0
    14733 {5408F497-9E89-423C-BAE1-20E68DD41D66} 2007-09-27 15:00:18.093 2007-09-27 15:00:19.983 L CAE2 0 99.008415 3 0 1703936 16896 0.003 3 1 SNL\sqltestservices 1 0 0
    14755 {341F87CE-8B62-441B-BF31-08C31736E9DC} 2007-09-27 15:30:12.117 2007-09-27 15:30:14.057 L CAE2 0 99.008415 3 0 1703936 16896 0.024 3 1 SNL\sqltestservices 1 0 0
    14777 {1EF302E3-C0C0-46BC-A70A-C2D01C030440} 2007-09-27 16:00:16.377 2007-09-27 16:00:18.593 L CAE2 0 99.008415 3 0 1703936 16896 0.003 3 1 SNL\sqltestservices 1 0 0
    14799 {D6D16F56-7160-4E0A-9C63-57B68969C624} 2007-09-27 16:30:11.320 2007-09-27 16:30:13.070 L CAE2 0 99.008415 3 0 1703936 16896 1.7000001E-2 3 1 SNL\sqltestservices 1 0 0
    14821 {FD1ACA29-7C80-4CEB-BE51-303164F6F57F} 2007-09-27 17:00:12.847 2007-09-27 17:00:15.407 L CAE2 0 99.008415 3 0 1703936 16896 4.0000002E-3 3 1 SNL\sqltestservices 1 0 0
    14843 {64115890-F378-403C-B055-7AF57FCFCF0C} 2007-09-27 17:30:22.870 2007-09-27 17:30:26.477 L CAE2 0 99.008415 3 0 1703936 16896 6.0000001E-3 3 1 SNL\sqltestservices 1 0 0
    Dave Rutledge
    Database Administrator
    SNL Financial LC
    · Share on Twitter
Sign In or Register to comment.