ntbackup log differs from event viewer log?

[djc]

I wasn't sure which group would be best to post this to. I apologize if it's
inappropriate for some of these groups.

ntbackup's log indicates *all* is well for both the backup and verify.
However the event viewer's application log does not contain all the expected
ntbackup events (8000 start backup, 8001 end backup, 8008 start verify, 8009
end verify)?

The app log may show all the right 8000/8001 but then a start verify (8008)
with no matching end verify (8009)?, I've also seen log entries start
somewhere in the middle of the job? It does not start/stop in the same place
within the backup job every time, no pattern noticed.

in short, if ntbackup's log says all is well, is it? or is it known to have
issues? would the data from the application log be more reliable?


I am currently without a test server to do a full test restore of system
states and exchange data to ensure all is well. Although I am working on
getting one ASAP. Right now I'm hoping someone here can let me know if this
is normal or indication of a problem; or well-known issue.

 

[djc]

whoops.. didn't mean to post yet... wasn't done.

I also wanted to mention that all the ESE application log entries *do* show
up to indicate the exchange IS was backed up successfully.

So, ntbackup log says all is well, all ESE application log entries are
there, *not* all ntbackup application log entries are there, no errors
either. Test restores of directories/files were fine but I'm without a test
server right now and can't test restore system states and exchange IS.

are these descrepencies between ntbackup log file and application log
common? known issue?

any input is appreciated. Sorry for the long winded post.

 

[Pegasus \(MVP\)]

I wasn't sure which group would be best to post this to. I apologize if it's
inappropriate for some of these groups.

ntbackup's log indicates *all* is well for both the backup and verify.
However the event viewer's application log does not contain all the expected
ntbackup events (8000 start backup, 8001 end backup, 8008 start verify, 8009
end verify)?

The app log may show all the right 8000/8001 but then a start verify (8008)
with no matching end verify (8009)?, I've also seen log entries start
somewhere in the middle of the job? It does not start/stop in the same place
within the backup job every time, no pattern noticed.

in short, if ntbackup's log says all is well, is it? or is it known to have
issues? would the data from the application log be more reliable?


I am currently without a test server to do a full test restore of system
states and exchange data to ensure all is well. Although I am working on
getting one ASAP. Right now I'm hoping someone here can let me know if this
is normal or indication of a problem; or well-known issue.

It would be helpful if you posted one of the ntbackup logs
that you believe is incomplete, together with the text from
the Event Logger that you say contradicts the logs.

 

[djc]

Hi Pegasus, thanks for the reply.

Actually its the ntbackup log that does look complete, its the event viewer
application log that does not look complete. Here is a sample ntbackup log.
For brevity I deleted the 'skipped file' lines for some open files:

Backup Status
Operation: Backup
Active backup destination: DLT
Media name: "FRIDAY"

Backup of "D$"
Backup set #1 on media #1
Backup description: "FRIDAY FULL Backup"
Backup Type: Normal

Backup started on 7/28/2006 at 11:17 PM.
Backup completed on 7/28/2006 at 11:27 PM.
Directories: 558
Files: 3518
Bytes: 756,144,011
Time: 9 minutes and 25 seconds
Media name: "FRIDAY"

Backup of "D$"
Backup set #2 on media #1
Backup description: "FRIDAY FULL Backup"
Backup Type: Normal

Backup started on 7/28/2006 at 11:27 PM.
------- I deleted entries here for skipped files ---------------------
Backup completed on 7/29/2006 at 12:29 AM.
Directories: 292
Files: 35753
Skipped: 22
Bytes: 6,196,700,648
Time: 1 hour, 2 minutes, and 16 seconds
Media name: "FRIDAY"

Backup of "D: DriveD"
Backup set #3 on media #1
Backup description: "FRIDAY FULL Backup"
Backup Type: Normal

Backup started on 7/29/2006 at 12:29 AM.
Backup completed on 7/29/2006 at 12:55 AM.
Directories: 8328
Files: 35040
Bytes: 4,647,462,644
Time: 26 minutes and 1 second
Media name: "FRIDAY"

Backup of "EXCHANGE\Microsoft Information Store\First Storage Group"
Backup set #4 on media #1
Backup description: "FRIDAY FULL Backup"
Backup Type: Normal

Backup started on 7/29/2006 at 12:55 AM.
Backup completed on 7/29/2006 at 1:23 AM.
Directories: 4
Files: 8
Bytes: 11,773,060,180
Time: 28 minutes and 27 seconds
Media name: "FRIDAY"

Backup of "System State"
Backup set #5 on media #1
Backup description: "FRIDAY FULL Backup"
Backup Type: Copy

Backup started on 7/29/2006 at 1:23 AM.
Backup completed on 7/29/2006 at 1:27 AM.
Directories: 123
Files: 2238
Bytes: 287,896,033
Time: 3 minutes and 44 seconds

----------------------

Verify Status
Operation: Verify After Backup
Active backup destination: DLT

Verify of "\\EXCHANGE\D$"
Backup set #1 on media #1
Backup description: "FRIDAY FULL Backup"
Verify started on 7/29/2006 at 1:28 AM.
Verify completed on 7/29/2006 at 1:30 AM.
Directories: 558
Files: 3518
Different: 0
Bytes: 756,144,011
Time: 1 minute and 36 seconds

Verify of "\\SQL\D$"
Backup set #2 on media #1
Backup description: "FRIDAY FULL Backup"
Verify started on 7/29/2006 at 1:30 AM.
Verify completed on 7/29/2006 at 1:45 AM.
Directories: 292
Files: 35753
Different: 0
Bytes: 6,196,700,648
Time: 14 minutes and 54 seconds

Verify of "D:"
Backup set #3 on media #1
Backup description: "FRIDAY FULL Backup"
Verify started on 7/29/2006 at 1:45 AM.
Verify completed on 7/29/2006 at 1:56 AM.
Directories: 8328
Files: 35040
Different: 0
Bytes: 4,647,462,270
Time: 10 minutes and 55 seconds

Verify of "EXCHANGE\Microsoft Information Store\First Storage Group"
Backup set #4 on media #1
Backup description: "FRIDAY FULL Backup"
Verify started on 7/29/2006 at 1:56 AM.
Verify completed on 7/29/2006 at 2:22 AM.
Directories: 4
Files: 0
Different: 0
Bytes: 11,773,060,180
Time: 26 minutes and 36 seconds

Verify of "System State"
Backup set #5 on media #1
Backup description: "FRIDAY FULL Backup"
Verify started on 7/29/2006 at 2:22 AM.
Verify completed on 7/29/2006 at 2:23 AM.
Directories: 123
Files: 2238
Different: 0
Bytes: 287,896,033
Time: 34 seconds

----------------------

for this ntbackup log the matching event viewer application log entries went
like so:

the *first* ntbackup category event logged was a 8001 "End backup of
\\SQL\d$" (this is the second session, no entry for the first session at all
and no begining 8000 entry for \\sql\d$)

then if follows the expected 8000 (begin) / 8001 (end) entries for the rest
of the backup sessions matching the ntbackup log up until it starts the
verifies.

the first verify is logged 8008 "begin verify to \\exchange\d$" and 8009
"end verify to \\exchange\d$" but then the very next entry is an 8008 to
begin verify to system state and thats it. No more entries. No entries for
the other verify sessions that should have happened before the verify to
system state and no end verify for the system state session. As you can see
in ntbackup's log that I copy/pasted above it indicates *all* of the backups
and verifies occurred. Ntbackup's log times seem logical and they *do* match
the event viewers application log entries. The event viewers log is just
missing entries.

this is one example where the event viewer app log is missing the beginning,
some middle, and the end. Other times it is only missing the end, and the
missing items are not the same every time.

I should also note that on the exchange server itself all the appropriate
ESE application log entries are present indicating a successfull backup of
the exchange information store.

I wish I just had a test server so I can perform a full DR test restore. I'm
working on getting one but its not going well. I have tested the restore of
file data successfully, just not system states or the exchange information
store.

as far as these log discrepencies go, have you ever seen this happen?

 

[Pegasus \(MVP\)]

I suspect that you have one single ntbackup command that
performs both the backup and the verification steps. If so
then I expect one single entry in your Task Scheduler event
logger. In other words, I don't think anything is missing. In
general you should concentrate on the application log (in this
case backup??.log) and consult the Task Scheduler log only
if you have a problem.

 

[djc]

see inline:

I suspect that you have one single ntbackup command that
performs both the backup and the verification steps.

yes

If so

then I expect one single entry in your Task Scheduler event
logger. In other words, I don't think anything is missing. In
general you should concentrate on the application log (in this
case backup??.log) and consult the Task Scheduler log only
if you have a problem.

In my posts I have been refering to ntbackup.exe's logs (backup??.log) as
'ntbackup logs' and the other log I am refering to is the Application Log in
the Event Viewer. I have not refered to the Task Scheduler log anywhere?

I think if you reread this keeping the right logs in mind a completely
different picture would be painted.

Thanks again though, I do appreciate your help.

 

[Pegasus \(MVP\)]

You are right - I got sidetracked to the Task Scheduler log
instead of the Event Logger. However, I would still rely on
the backup logs (backup??.log) as the primary source of
information. If some entries are missing in the Event Logger
then this is probably because the author of ntbackup.exe
forgot to generate an event.

Ultimately it's what's on the tape that counts. To be sure
that you get what you expect you must restore some sample
folders at regular intervals, i.e. when you first set things up
and then perhaps twice each year.

 

[djc]

ok. Thanks again for the input.

You are right - I got sidetracked to the Task Scheduler log
instead of the Event Logger. However, I would still rely on
the backup logs (backup??.log) as the primary source of
information. If some entries are missing in the Event Logger
then this is probably because the author of ntbackup.exe
forgot to generate an event.

Ultimately it's what's on the tape that counts. To be sure
that you get what you expect you must restore some sample
folders at regular intervals, i.e. when you first set things up
and then perhaps twice each year.