How to solve ESE -566 Errors (JET_errDbTimeTooOld)

This post is circa 2014 and migrated from Wordpress

After having this issue at a customer, and finding the information on the internet to be a bit old (and haste) I wanted to post what occurred and how to solve it.

So over the weekend I had DR testing at a customer. They are running Exchange 2007 SP3RU8 on all servers, and for HA they have a two node Single Copy Cluster.

We did some maintenance on the cluster, and then attempted to fail over. After waiting about 3 minutes I decided to check (as a healthy cluster should fail over within 60–90 seconds). Afterwards, I saw three DB that refused to mount.

I reviewed the Event Viewer: System logs and saw this..

Event Type: Warning
Event Source: PartMgr
Event Category: None
Event ID: 59
Date:
Time:
User:
Computer: SCC-Node2
Description:
Disk 75 will not be used because it is a redundant path for disk 0.

Not really a warm fuzzy feeling, so I decided to fail back over to SCC-Node1. When that occurred I attempted to mount both of the databases that refused to mount (within Cluster Admin utility by bringing the IS Instance online) and failed. Once I looked within the Event Viewer: Application logs I saw a slew of these error messages:

Event Type: Error
Event Source: ESE
Event Category: Logging/Recovery
Event ID: 516
Date:
Time:
User: N/A
Computer: SCC-Node1
Description:
MSExchangeIS (6312) StorageGroup1: Database F:\database1\database1.edb: Page 231 (0x000000e7) failed verification due to a timestamp mismatch. The expected timestamp was 0xbedab929 but the actual timestamp on the page was 0xbedab403. Recovery/restore will fail with error -566. If this condition persists then please restore the database from a previous backup. This problem is likely due to faulty hardware “losing” one or more flushes on this page sometime in the past. Please contact your hardware vendor for further assistance diagnosing the problem.

and then a few of these:

Event Type: Error
Event Source: ESE
Event Category: Logging/Recovery
Event ID: 454
Date:
Time:
User: N/A
Computer: SCC-Node1
Description:
MSExchangeIS (4408) StorageGroup1: Database recovery/restore failed with unexpected error -566.

The first thing I checked was the health of the actual DB. To do this you should run the following:

1. Open the Command Prompt
2. Change directory to %programfiles%\Microsoft\Exchange Server\Bin
3. Run the ESEUTIL command (eseutil /mh <DriveLetter>:\Path_To_DB)

This command dumps the DB headers, and will give you two pieces of critical information you are looking for:

• State
• Log Required

Here is the output from the command I ran:

Initiating FILE DUMP mode…
Database: D:\Database1\Database1.edb

File Type: Database
Format ulMagic: 0x89abcdef
Engine ulMagic: 0x89abcdef
Format ulVersion: 0x620,12
Engine ulVersion: 0x620,12
Created ulVersion: 0x620,12
DB Signature: Create time:09/15/2010 16:58:36 Rand:2592704934 Computer:
cbDbPage: 8192
dbtime: 3888704209 (0xe7c8ead1)
State: Dirty Shutdown
Log Required: 1829641–1829643 (0x1beb09–0x1beb0b)

At this point, I know I am going to need to do some type of recovery that is going to require the logs in the “Log Required” section.

Before I continue, lets discuss what actually happened here based off what I see from my troubleshooting..

What would cause this:

Before fully understanding why this occurred you should understand how dbTime works and how the Information Store works. There is a good article here about the Information Store process, but to sum it up there is a Log Buffer that is within the memory. To help reduce I/O on your disk subsystem, transactions are written to the Log Buffer. The Log Buffer (being 1MB in size, since transaction logs are that size) then commits to a log when one of two things happen:

1. The DB is failing over, and needs to commit the transaction to memory. This could be due to node failure, turning the server off or HA testing
2. A hard transaction hits the DB (send / receive of email, ect)

When the log buffer needs to write, it writes using the Log Writer process.

To summarize, transactions are not written to the DB immediately but instead to the log buffer and then from the log buffer written from the log buffer utilizing the log writer to the DB.

As for the dbTime, when a new log is generated a unique database time is generated based off the log generation time. The dbTime can be higher than the actual current log time, which is normal. The dbTime is utilized more as a counter than an actual time stamp.

Why does this occur? When we perform DR (hard / soft recoveries) on a DB, the dbTime is examined to see if the log has been replayed or not.

Now to the actual root cause..

What it looked like was that when SCC-Node1 failed over to SCC-Node2, the disk subsystem was overwhelmed along with the network backbone for the SAN, thus causing a mismatch in the time. If you look at Error -566 utilizing the Exchange Error Tool you would see that this theory does match up to the actual error:

JET_errDbTimeTooOld esent98.h
# /* dbtime on page smaller than dbtimeBefore in record */

The question now is how to fix it..

The Fix:

Although the article above states you should run “ESEUTIL /P” I highly disagree with this. ESEUTIL /P should be ran only as a last resort. I was able to fix this quite quickly using ESEUTIL /R.

From our ESEUTIL /MH content above we know the DB is in a dirty shutdown state, and we wont be able to mount this until it is in a clean state. We see that he log required was 1829641–1829643 (0x1beb09–0x1beb0b). If you look at the log folder, you might be able to find these logs (they should exist — they were created, but the dbTime is “too old”). Look at the first three letters that start off on the log file. In my situation was E070. Remember that.

Lets go back to our command prompt that is already in the /Exchange Server/BIN folder. From there we would run the following command:

ESEUTIL /R E07 /l<driveletter>:\Log_Location

The reason I am selecting to replay the logs starting with E07 is because the formatting of the command (ESEUTIL /R Enn — Enn = the base log that needs to be replayed). Because I know Log 0x1beb09 = E0700001beb09, I should replay the logs for E07.

Monitor the process as it runs..

Initiating RECOVERY mode…

Logfile base name: E07

Log files: L:\LogLocation

System files: <current directory>

Performing soft recovery…

Restore Status (% complete)

0 10 20 30 40 50 60 70 80 90 100

| — — | — — | — — | — — | — — | — — | — — | — — | — — | — — |

……………………………………………

Once this is completed you should have no errors. Check out the status of your DB utilizing ESEUTIL /MH. The db should show a clean shutdown state with 0x0 logs required (meaning there are no logs that are required for the db to replay):

Initiating FILE DUMP mode…

Database: F:\NAData21\NAMailboxDatabase21.edb

File Type: Database

Format ulMagic: 0x89abcdef

Engine ulMagic: 0x89abcdef

Format ulVersion: 0x620,12

Engine ulVersion: 0x620,12

Created ulVersion: 0x620,12

DB Signature: Create time:09/15/2010 16:58:36 Rand:2592704934 Computer:

cbDbPage: 8192

dbtime: 4104664568 (0xf4a835f8)

State: Clean Shutdown

Log Required: 0–0 (0x0–0x0)

Once you have also replayed the logs, the dbTime log sequencing is also updated so that logs will be stamped once the DB is mounted.

Attempt to mount your database again and you should be good.

Any questions leave them below in the comments section.

(and for the Redditors who read this)

TL;DR: Don’t run ESEUTIL /P as your first step! /P = Panic = :( data loss! Run ESEUTIL /MH to get the status of the DB and then run ESEUTIL /R if you are able to find the logs / restore the logs.

-Adam F