Unable to apply a transaction log

[Former Member]

Hi,

With SA 16.0.0.1948, I'm having problem applying some transaction log.

We have a process that backup and truncate the transaction log every hour and then send the log on another server. On the other server, we have a copy of the DB and every X minutes, apply received logs. This process worked perfectly for years, but since we upgraded to SA16 from SA9 a few months ago, some logs cannot be applied because of the following error:

Error: Cannot open transaction log file -- Can't use log file "F:\\oiiq\\190176.log" since it has been used more recently than the database file

First thing I thought was that a log was missing (happened before), but after some checking this does not look like the case. Looked into the file backup.syb and no other backup was logged. I translated the last log successfully applied I noticed something strange, there is no checkpoint at the end, all the log I translated always had a checkpoint at the beginning and at the end. Also the log only contained about 20min of transactions. Another thing I noticed, usually when a log pass about 10k in size, once translated the resulted .sql file will be larger than the .log, in this case a 196k .log gile result in a 30k sql file, maybe it's nothing.

With all of this, I have the impression that log is missing or not applying some data.

I have the same problem on 3 completely different setup (client) and working ok on about 50 others.

Any thought ?

[VolkerBarth]

Just as a start: You can use DBLOG and DBTRAN to look for the starting and ending log offsets of both the database file and the transaction log(s) to check whether they will fit together (or at least whether they will NOT fit together).

If I understand your requirements correctly: Is that not better handled with the (old) live backup log feature - or HA, but that's another story...

[Former Member]

I checked the offsets they are ok until the last 'successful' log applied.

If I translate the log, there is 1 hour of transactions in the resulting sql and took note of the log starting and ending offset. After I apply the log, if I translate the same log, I only have about 20mins of transactions in the sql and the ending offset is not the same, way before the original ending offset.

It looks like the server is applying the log only to a certain point, but does not generate any error. Trying to apply the next log throw the error.

[VolkerBarth]

Sorry, I cannot explain that situation but others will be able to do so. As a mere hint: Is there a chance that the original log does contain a lot of uncommitted OPs (visible via DBTRAN -a) that could be ignored after the log has been applied.

Just to understand: How exactly are you doing the log backup (i.e. via the BACKUP statement or the dbbackup tool or based on the DbTools API? What options do you use? Are these different between v9 and v16?)

[Former Member]

The only difference I see if I include uncommitted OPs is a bunch of rollback through the file.

Backup of the log is done with the backup statement: "BACKUP DATABASE DIRECTORY 'D:\\DIR' WAIT BEFORE START WAIT AFTER END TRANSACTION LOG ONLY TRANSACTION LOG TRUNCATE", same command we used in v9.

I also tried to apply the logs with build 2043, same results.

[Former Member]

Mayb we can tell more if you show the offsets (from the dblog outputs) for these 3 files:

• the .db file (after the logs were applied as far as they can be)
• the .log file that was ?successfully applied?
• and the .log file(s) that throw the error

[Former Member]

Here are the offsets:

DB: 0352894219, relative: 0000109550
Log #1 start offset: 0353003769, end: 0353202127
Log #2 start offset: 0353202127, end: 0353240917

Error occur when trying to apply log #2

But, after applying log #1
DB: 0353003769, relative: 0000013396

After applying log #1, DB should have a starting + relative offset of 0353202127, but instead its 0353017165

[VolkerBarth]

IMHO, based on these offsets it's understandable that the engine refuses to apply log #2, as its offset range is beyond that of the database file (reaching up to 353017165). And that would explain the error message you got.

I would have expected that after successfully applying log #1, the db should start with offset 0353202127, and then log #2 would fit.

How exactly are you applying the logs?

EDIT: What does dbrv16 -o console.log tell when applying the logs (particular the "problematic one")?

[Former Member]

Here is the command I use:

dbsrv16 oiiq.db -ek key -a 344228.log (344228.log is log #1)

I also have a copy of the DB and about 10 prior logs, with those I also tried:

dbsrv16 oiiq.db -ek key -ar

all logs are applied correctly up to the same log with error.

Also copied files on another PC and applying the logs, still have the error.

Looks like at some point (offset 353017165) when applying log #1, the process just stop.

[Former Member]

Another thing, this is not the first time it's happened, occurred 3 times last week. Before looking more into the problem, to resolve the issue, I made a full backup of the DB and then restarted our hourly incremental backup. This worked for about 12 to 18 hours before being unable to apply an incremental backup again. This made me think there was a problem with our client server / system, but the exact same problem occurred with another client last Friday and a third client yesterday, each with their own servers.

[Former Member]

Nothing special, here the console when I apply the logs with -ar

I. 01/20 16:29:10. Transaction log: F:\\a\\344154.log...
I. 01/20 16:29:10. Starting checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Finished checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Starting checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Finished checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Starting checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Finished checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Starting checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Finished checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Starting checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Finished checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Transaction log: F:\\a\\344228.log...
I. 01/20 16:29:10. Starting checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:10. Finished checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:11. Starting checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:11. Finished checkpoint of "oiiq" (oiiq.db) at Tue Jan 20 2015 16:29
I. 01/20 16:29:11. Transaction log: F:\\a\\344292.log...
E. 01/20 16:29:11. Error: Cannot open transaction log file -- Can't use log file "F:\\a\\344292.log" since it has been used more recently than the database file

E. 01/20 16:29:11. Cannot open transaction log file -- Can't use log file "F:\\a\\344292.log" since it has been used more recently than the database file
I. 01/20 16:29:14. Database server shutdown due to startup error
I. 01/20 16:29:16. Database server stopped at Tue Jan 20 2015 16:29

344228.log is what I refered to log #1, 344292.log is log #2

[Former Member]

Volker is very correct about the way it is failing to recover with log#2.

It is also correct that -ar was invented for this kind of semi-automated recovery. So I suspect you are doing everything correctly up to (and past) the point of failure.

So unless there is an unknown problem with the -ar implmentation, I would suspect there was a problem with the server at the time it was writing the log that is only partially applying. What is not know is whether that is a bug or some sort of file system failure.

If you find the failures are around points where backups were being taken (and possibly failing for some reason or being cancelled) then you might want to get to an even higher build. You are in the range of builds where a parallel backup issue was detected (and since you are doing server side backups you are probably doing parallel backups). More specifically, this fix for CR#764973 was checked into the software just 3 builds higher than the one you are running.

Otherwise . . .

Translating the log and looking for operations around that offset (353017165) may show you some more details about what is going on inside that log. I would use dbtran -ek ... -z -a -sr for starters. {-sr if you are using publications in this database}

Of course, since you have found a way to 'repeat/reproduce' this I am assuming there is a pattern around this and it would be an issue we will want to investigate more deeply. If you can, do open up an incident so we can look into the files more closely to see what kind of issue we are faced with here.

I cannot think of any sort of log operation that would tell the server to just stop this way . . . so I am definitely leaning towards there being a bug here.

Do let us know if anything of interest shows up from you investigations.

[Former Member]

On the 2 DB I checked with this problem, transactions stop being applied at about the middle of the log, nothing common on the cases, just update being done, but on different tables.

I opened an incident with SAP, will see if they can find something.