Tracking a standard backup in the AGENT log file

  • 7019967
  • 08-Oct-2008
  • 29-Aug-2017

Environment

Reload (all versions)

Situation

How to follow a standard backup in the Agent log file.

Resolution

This tid will go through the logging of a standard backup

The job was manually submitted

[I] [9103] DATE: Wed_Oct_08 [ GRE_MAILER ] Kind of an ugly logfile, but still useful! (TIME:08:00:39) [I] [9103] DATE: Wed_Oct_08 [ GRE_MAILER ] Finished Mail Actions (TIME:08:00:39) [I] DATE: Wed_Oct_08  [GWAVA Reload Agent] Processing Run File TIME: 08:09:49 Filename: /opt/beginfinite/reload/proc/stack/gre_running_process.bin Run Job Description ------------------------------------ Profile = po1 Operator = Administration Menu Operator Starting Process = gre_dbs ------------------------------------

Lists the contents of the profile configuration file

po1.conf <BEGIN>----------------------- (the contents of the config file) po1.conf <END>-------------------------

Disk space is checked before the job will continue.  The default is 90%, if that space is exceded then the job will stop at this point. 

[I] DATE: Wed_Oct_08 TIME: 08:09:49 PROFILE:  - GRE_DBS Was Launched By Another Process [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Confirming Available Disk Space [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Disk Space Not To Exceed: 90% [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Raw Disk Space Check Output -----------------------------------

Filesystem           1K-blocks      Used Available Use% Mounted on /dev/sda2            154138904 133652464  20486440  87% /

----------------------------------- [S] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Disk space check can be skipped by setting Disk Space Threshold to 0 (zero). [S] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - If the last line of the Log File is this one, then set Disk Space Threshold to 0 (zero)

[I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Disk space used = 87 % [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Disk space required = 90 % [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Sufficient Disk Space is Available [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Remaining Disk Space Percentage 3 % [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Starting Database Backup [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Profile = PO1 [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Profile Description = po1 [I] DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - Process Retry Attempts = [ 0 ] -----------------------------------

The first files backed up are the user databases.  The umount is ran before the mount in case any mount still exist.  Then the mounts to the live user databases are created so we can back up the databases.

[I] DATE: Wed_Oct_08 TIME: 08:09:56 PROFILE: PO1 - [GRE_DBS] Creating Backup Structure [I] DATE: Wed_Oct_08 TIME: 08:09:56 PROFILE: PO1 - [GRE_DBS_OFUSER] Disconnecting from profile: po1

Wed_Oct_08: [GRE_NCP_UMNT] Removing mapping 1 for: po1 08:09:56 umount: /data/po1/po3/povolmap: not found umount: /mnt/reload/profiles/po1/po3/povolmap: not mounted DATE: Wed_Oct_08 [GRE_NCP_UMNT] Finished Removing mapping for: po1 (TIME: 08:09:56) [I] DATE: Wed_Oct_08 TIME: 08:09:56 PROFILE: PO1 - FUNCTION_START_PO_CONNECTIVITY Start [I] DATE: Wed_Oct_08 TIME: 08:09:56 PROFILE: PO1 - [GRE_DBS_OFUSER] Connecting to profile: po1 [ GRE_NCP_MNT ] Using Alternative Stack File DATE: Wed_Oct_08  [GRE_NCP_MNT] Mapping to server for: po1 (TIME: 08:09:57) DATE: Wed_Oct_08  [GRE_NCP_MNT] Successful map for: po1 (TIME: 08:09:57) DATE: Wed_Oct_08 [GRE_NCP_MNT] Finished mapping for: po1 08:09:57 /data/po1/po3/podbcopy ofuser

A connection is made to each file, then the files are backed up.

[I] DATE: Wed_Oct_08 TIME: 08:10:04 PROFILE: PO1 - Connecting to Live User Database for backup user3lv.db [I] DATE: Wed_Oct_08 TIME: 08:10:04 PROFILE: PO1 - Connecting to Live User Database for backup user6i1.db [I] DATE: Wed_Oct_08 TIME: 08:10:04 PROFILE: PO1 - Connecting to Live User Database for backup userflc.db .... [I] DATE: Wed_Oct_08 TIME: 08:10:20 PROFILE: PO1 - [GRE_DBS_OFUSER] Starting DBCOPY of User Databases

The files are copied from the production system to the source directory, then copied to the destination directory.

Source Directory: /data/po1/po3/podbcopy Destination Directory: /data/po1/backups/creating/3

The db count that Reload has backed up is compared the count on the production system to verify accuracy of the backup.

[I] DATE: Wed_Oct_08 TIME: 08:10:36 PROFILE: PO1 - [GRE_DBS_CHECK_OFUSER] Live post office OFUSER database count: 6 [I] DATE: Wed_Oct_08 TIME: 08:10:36 PROFILE: PO1 - [GRE_DBS_CHECK_OFUSER] Backed up OFUSER database count: 6

After the user databases are completed, the user database indexes are backed  up. 

[I] DATE: Wed_Oct_08 TIME: 08:10:36 PROFILE: PO1 - [GRE_DBS_OFUSER] Success, DBCOPY Completed Correctly [I] DATE: Wed_Oct_08 TIME: 08:10:36 PROFILE: PO1 - [GRE_DBS_INDEX] Starting Backup of OFUSER INDEX Directory

The BLOBS (offiles) are backed up, and will run simultaneously with the user database's indexes files.

[I] DATE: Wed_Oct_08 TIME: 08:10:38 PROFILE: PO1 - Starting OFFILES Directory (BLOBS) Backup [I] DATE: Wed_Oct_08 TIME: 08:10:38 PROFILE: PO1 - Profile = PO1

A symbolic link is created for each of the directories under offiles, and then the files are backed up.

create symbolic link `/data/po1/po5/poblobscopy/offiles/fd0' to `/data/po1/po5/polive/offiles/fd0' create symbolic link `/data/po1/po5/poblobscopy/offiles/fd1' to `/data/po1/po5/polive/offiles/fd1' create symbolic link `/data/po1/po5/poblobscopy/offiles/fd10' to `/data/po1/po5/polive/offiles/fd10' ... [784] Copying: /data/po1/po5/poblobscopy/offiles/fd28 [784] Copying: /data/po1/po5/poblobscopy/offiles/fd29 [784] Copying: /data/po1/po5/poblobscopy/offiles/fd30 [784] Copying: /data/po1/po5/poblobscopy/offiles/fd31 ...

The final step is creating the post office, and this occurs after all the backups are successful.

[I] DATE: Wed_Oct_08 TIME: 08:11:41 PROFILE: PO1 - [GRE_SPURGE] Handing off processing to GRE_PO_CREATE ... [I] DATE: Wed_Oct_08 [GRE_PO_CREATE] Success, PO Create Completed Processing Correctly TIME: 08:11:56

In the event log, the job start and completion sections may be easier to track down.  I would recommend checking the the EVENT log first to get the time, then go to the AGENT log to the time from the EVENT log.

event log: DATE: Wed_Oct_08 TIME: 08:09:50 PROFILE: PO1 - STARTING JOB FOR PROFILE: PO1

DATE: Wed_Oct_08 TIME: 08:11:56 PROFILE: PO1 - FINISHED JOB FOR PROFILE: PO1 DATE: Wed_Oct_08 TIME: 08:11:56 PROFILE: PO1 - JOB TYPE: STANDARD (INCREMENTAL) BACKUP DATE: Wed_Oct_08 TIME: 08:11:57 PROFILE: PO1 - TOTAL TIME TO FINISH: 2 Minutes 7 Seconds DATE: Wed_Oct_08 TIME: 08:11:57 PROFILE: PO1 - DISK SPACE IN USE AT JOB END: 87%

Additional Information

This article was originally published in the GWAVA knowledgebase as article ID 463.