Delphix Fails to Load an ASE Transaction Log Due to ASE Error 4305 (KBA1771)
Applicable Delphix Versions
All
Issue
Delphix may fail to load a transaction log during ValidatedSync (a background process that is responsible for loading transaction logs into the staging database) due to ASE error 4305. Reviewing the Delphix debug logs, we see the error as follows:
[2018-08-18 01:17:41,841][ERROR][ase.staging.impl.worker.ASEValidatedSyncWorker#execute:749][Worker-ASEValidatedSyncWorker.7][] Error during validated sync run: exception.db.asestagingdb.stagingdb.load_transaction.failed {FACETSxc|ASE_STAGING_DB|fido.delphix.com|delphix_vdb|4305: Specified file 'dump device' is out of sequence. Current time stamp is Aug 18 2018 12:30:00:086AM while dump was from Aug 18 2018 1:14:36:013AM.
}
When loading transaction logs, ASE validates the database's current time stamp to the time stamp of the log being loaded. If there is a gap, this indicates that there is a log missing and ASE fails the "LOAD TRANSACTION" command with error 4305.
Often this happens when a transaction threshold procedure fires twice within one minute and overwrites an existing transaction log, especially if the transaction log's physical file name is not unique enough. For example, if the transaction log follows a naming convention where the file name is formatted down to the minute "database_name.yymmddhhmm".
Troubleshooting
In versions up to Delphix 5.2 a generic alert will be raised indicating the ValidatedSync process failed to load a log. For example:
Date Aug 28, 2018 10:21 AM Title Validated sync failed for dSource Target FACETSxc Details Validated sync failed for dSource "FACETSxc". For dSource "FACETSxc", failed to load a source transaction dump User Action Make sure that the SAP ASE instance "ASE_STAGING_DB" on the staging host "fido.delphix.com" is up, the user "sa" has privileges to load a transaction dump on the host, the staging host "fido.delphix.com" has enough resources, and then try the operation again.
Due to this generic alert, it would be necessary to "grep" the Delphix debug logs for error 4305 to confirm the cause for the failure.
Starting in Delphix version 5.3 and higher, the alert will include the actual ASE 4305 error.
You can view the staging database's current time stamp and compare that to the time stamps in each of the transaction logs leading up to the error to find the one with the gap. In the following example, the Delphix staging database named "dx9Nt1aw735rfFtQAL83n9_daisy" has a current time stamp of "18-08-28 08:35:51.630" whereas the transaction log shows that its beginning time stamp is "Aug 28 2018 9:10:07:123". So there is a gap between "08:35:51.630" and "09:10:07:123".
1> select name, convert(varchar(32),dumptrdate,40) from sysdatabases where name = 'dx9Nt1aw735rfFtQAL83n9_daisy' 2> go name ------------------------------------------------------------ ---------------------------------------------------------------- dx9Nt1aw735rfFtQAL83n9_daisy 18-08-28 08:35:51.630000 1> load tran daisy from "/home/sybase/dump/daisy.tran.8_28:10:20" with headeronly 2> go | grep "sequence dates" Log begins on page 2622; checkpoint RID=Rid pageid = 0xa3e; row num = 0xd; previous BEGIN XACT RID=(Rid pageid = 0xa3e; row num = 0x2); sequence dates: (old=Aug 28 2018 9:10:07:123AM, new=Aug 28 2018 9:10:10:123AM);
Resolution
To get Delphix to start automatically loading transaction logs again through the ValidatedSync process, it is necessary to click the camera icon and ask Delphix to load the "Most recent Existing Full Backup" or "Specific Existing Full Backups" that was created after the transaction log that caused the gap.
To avoid the issue, ensure that the physical transaction log file name is unique enough that it does not get overwritten should a transaction log threshold fire in rapid succession. For example:
CREATE PROCEDURE dbo.sp_dumptran @dbname varchar(30) as declare @dt varchar(16) select @dt=CONVERT(varchar(16), str_replace(CONVERT(varchar(8), GETDATE(),112)+CONVERT(varchar(11), GETDATE(), 20), ':', null)) declare @dumpcmd varchar(200) select @dumpcmd = 'dump tran '+@dbname+' to "/dumpdir/FACETSxc_'+@dbname+'_'+@dt+'_1of1.trn" with compression = 100, ' + 'file = "' + '"' + newid() + '"'
NOTE: In this example, it also utilizes the "newid()" function to generate a unique internal dump file name. Normally ASE generates the internal dump file name automatically. It is usually unique but since the format of the name includes the number of seconds since midnight, if you issue two "DUMP" commands in the same batch of commands the name may not be unique:
DUMP DATABASE daisy TO "/dumpdir/daisy.full.180828.10:47" DUMP TRAN daisy TO "/dumpdir/daisy.full.180828.10:48" GO
Delphix relies on the internal dump name to be unique so that it can group individual stripes of a dump together to form the correct "LOAD TRAN" or "LOAD DATABASE" statement.
Additional Information
A future release of Delphix will support the ASE dump history file which should negate the need for the uniqueness of the internal dump file name because the dump history file makes it easy to identify which individual files are stripes belonging to a particular dump.