Environment
Situation
Resolution
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%