This post is more than 5 years old
194 Posts
0
3447
September 1st, 2006 07:00
Backup stalls until it times-out
Greetings,
Environment:
Server & Client: RedHat Linux ES 3.6 running NW 7.2.1
We're having a problem with another client. This is a new client and has never worked during its scheduled nightly backup. The backup starts at 4 AM, runs the precmd to shut down the vendor's database (not sure what kind of database it is), and backs up the 4 filesystems finishing by 4:27 AM. At this point it stalls until 6 AM I think because Legato then times-out. The index is then written to tape, the pstcmd runs restarting the database, and the Legato backup exits with an error. This is the only client in the savegroup and no other backups are running at the time. For the group we changed the 'Client Retries' from 1 to 0 because the backups was stalling until 8 AM when it retried. When we try running the backup manually during the day and it runs fine.
On the client in savepnps.log we have:
09/01/06 04:01:17 preclntsave: All command(s) ran successfully.
09/01/06 06:00:19 pstclntsave: All savesets on the worklist are done.
09/01/06 06:00:20 pstclntsave: All command(s) ran successfully.
09/01/06 06:00:20 pstclntsave: Exited.
On the server in messages we have:
Sep 1 04:00:01 solegato2 logger: NetWorker savegroup: (info) starting Millennium (with 1 client(s))
Sep 1 06:00:39 solegato2 logger: NetWorker savegroup: (alert) Millennium completed, total 1 client(s), 0 Hostname(s) Unresolved, 1 Failed, 0 Succeeded. (csulib.ctstateu.edu Failed)
Sep 1 06:00:39 solegato2 logger: Start time: Fri Sep 1 04:00:00 2006
Sep 1 06:00:39 solegato2 logger: End time: Fri Sep 1 06:00:39 2006
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: --- Unsuccessful Save Sets ---
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: * csulib.ctstateu.edu:/iiidb Cannot determine status of the backup process. Use mminfo to determine job status.
Sep 1 06:00:39 solegato2 logger: * csulib.ctstateu.edu:/iiidb/software Cannot determine status of the backup process. Use mminfo to determine job status.
Sep 1 06:00:39 solegato2 logger: * csulib.ctstateu.edu:/iiidb/images Cannot determine status of the backup process. Use mminfo to determine job status.
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: --- Successful Save Sets ---
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: csulib.ctstateu.edu: /iii level=full, 1315 KB 00:00:02 30 files
Sep 1 06:00:39 solegato2 logger: solegato2.ctstateu.edu: index:csulib.ctstateu.edu level=full, 376 MB 00:00:35 198 files
On the server in daemon.log we have:
09/01/06 04:00:01 nsrd: savegroup info: starting Millennium (with 1 client(s))
09/01/06 04:01:23 nsrd: csulib.ctstateu.edu:/iiidb/software saving to pool 'Unix' (VZ1127L1)
09/01/06 04:01:26 nsrd: csulib.ctstateu.edu:/iii saving to pool 'Unix' (VZ1127L1)
09/01/06 04:01:26 nsrd: csulib.ctstateu.edu:/iiidb/images saving to pool 'Unix' (VZ1127L1)
09/01/06 04:01:28 nsrd: csulib.ctstateu.edu:/iii done saving to pool 'Unix' (VZ1127L1) 1314 KB
09/01/06 04:01:29 nsrd: csulib.ctstateu.edu:/iiidb saving to pool 'Unix' (VZ1127L1)
09/01/06 04:06:41 nsrd: csulib.ctstateu.edu:/iiidb/software done saving to pool 'Unix' (VZ1127L1) 786 MB
09/01/06 04:16:34 nsrd: csulib.ctstateu.edu:/iiidb done saving to pool 'Unix' (VZ1127L1) 3050 MB
09/01/06 04:26:28 nsrd: csulib.ctstateu.edu:/iiidb/images done saving to pool 'Unix' (VZ1127L1) 8899 MB
09/01/06 04:27:10 nsrd: write completion notice: Writing to volume VZ1127L1 complete
* csulib.ctstateu.edu:/iiidb/software Cannot determine status of the backup process. Use mminfo to determine job status.
* csulib.ctstateu.edu:/iiidb/images Cannot determine status of the backup process. Use mminfo to determine job status.
* csulib.ctstateu.edu:/iiidb Cannot determine status of the backup process. Use mminfo to determine job status.
09/01/06 06:00:22 nsrd: solegato2.ctstateu.edu:index:csulib.ctstateu.edu saving to pool 'Unix' (VZ1127L1)
09/01/06 06:00:39 nsrd: solegato2.ctstateu.edu:index:csulib.ctstateu.edu done saving to pool 'Unix' (VZ1127L1) 376 MB
09/01/06 06:00:39 nsrd: savegroup alert: Millennium completed, total 1 client(s), 0 Hostname(s) Unresolved, 1 Failed, 0 Succeeded. (csulib.ctstateu.edu Failed)
09/01/06 06:00:39 nsrd: runq: NSR group Millennium exited with return code 1.
09/01/06 06:01:18 nsrd: write completion notice: Writing to volume VZ1127L1 complete
I looked up the error in the Error Message Guide and followed the steps in the Resolution section as follows:
o I checked the status of the backups using mminfo and they appear completed:
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:23 786 MB 2482497747 cb full /iiidb/software
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:26 1315 KB 2465720534 cb full /iii
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:27 8899 MB 2448943318 cb full /iiidb/images
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:29 3050 MB 2432166105 cb full /iiidb
o I wrote a script that ran on both client & server during the backups which ping'd the other system once every mintue and all pings were successful.
o The disk containing the log file isn't full.
o The Networker Module binaries are installed.
The scripts that I wrote also listed the status of the Networker processes every minute. On the client just before and after the last filesystem is backed up we have:
Fri Sep 1 04:25:33 EDT 2006
+ ps -ef
+ grep -e nsr -e save -e mm
root 2781 1 0 Aug17 ? 00:00:00 /usr/sbin/nsrexecd
root 2784 2781 0 Aug17 ? 00:00:01 /usr/sbin/nsrexecd
root 28600 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28603 28600 22 04:00 ? 00:05:42 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb/images /iiidb/images
root 28955 1 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
Fri Sep 1 04:26:36 EDT 2006
+ ps -ef
+ grep -e nsr -e save -e mm -e hm7
root 2781 1 0 Aug17 ? 00:00:00 /usr/sbin/nsrexecd
root 2784 2781 0 Aug17 ? 00:00:01 /usr/sbin/nsrexecd
root 28600 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28955 1 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
The thing that I find odd here is the pstclntsave process. According to the manpage it is suppose to be a child process of preclntsave but it's not. It looks like an orphaned process. The preclntsave processes exist only for the 1st minute or so of the backup:
Fri Sep 1 04:01:20 EDT 2006
+ ps -ef
+ grep -e nsr -e save -e mm -e hm7
root 2781 1 0 Aug17 ? 00:00:00 /usr/sbin/nsrexecd
root 2784 2781 0 Aug17 ? 00:00:01 /usr/sbin/nsrexecd
root 28595 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28596 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28597 28595 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb/software /iiidb/software
root 28598 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28599 28596 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iii /iii
root 28600 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28601 28597 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28602 28599 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28603 28600 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb/images /iiidb/images
root 28604 28598 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb /iiidb
root 28605 28603 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28607 28604 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28955 28601 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
On the server up until it times out we have:
Fri Sep 1 05:59:43 EDT 2006
root 2798 1 0 Aug29 ? 00:00:01 /usr/sbin/nsrexecd
root 2799 2798 0 Aug29 ? 00:00:03 /usr/sbin/nsrexecd
root 2802 1 0 Aug29 ? 00:00:00 /usr/sbin/lgtolmd -p /nsr/lic -n 1
root 2805 1 0 Aug29 ? 00:00:27 /usr/sbin/nsrd
root 2811 2805 0 Aug29 ? 00:00:18 /usr/sbin/nsrmmdbd
root 2812 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrindexd
root 2945 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrmmd -n 1
root 2946 2805 0 Aug29 ? 00:00:27 /usr/sbin/nsrmmd -n 2
root 2947 2805 0 Aug29 ? 00:01:22 /usr/sbin/nsrmmd -n 3
root 2948 2805 1 Aug29 ? 01:11:46 /usr/sbin/nsrmmd -n 4
root 11598 2805 0 04:00 ? 00:00:00 /usr/sbin/savegrp Millennium
root 11610 11598 0 04:00 ? 00:00:00 /usr/sbin/nsrexec -c csulib.ctstateu.edu -a -- csulib.ctstateu.edu:/iiidb/software
root 11612 11598 0 04:00 ? 00:00:00 /usr/sbin/nsrexec -c csulib.ctstateu.edu -a -- csulib.ctstateu.edu:/iiidb
root 11613 11598 0 04:00 ? 00:00:00 /usr/sbin/nsrexec -c csulib.ctstateu.edu -a -- csulib.ctstateu.edu:/iiidb/images
Fri Sep 1 06:00:13 EDT 2006
root 2798 1 0 Aug29 ? 00:00:01 /usr/sbin/nsrexecd
root 2799 2798 0 Aug29 ? 00:00:03 /usr/sbin/nsrexecd
root 2802 1 0 Aug29 ? 00:00:00 /usr/sbin/lgtolmd -p /nsr/lic -n 1
root 2805 1 0 Aug29 ? 00:00:27 /usr/sbin/nsrd
root 2811 2805 0 Aug29 ? 00:00:18 /usr/sbin/nsrmmdbd
root 2812 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrindexd
root 2945 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrmmd -n 1
root 2946 2805 0 Aug29 ? 00:00:27 /usr/sbin/nsrmmd -n 2
root 2947 2805 0 Aug29 ? 00:01:22 /usr/sbin/nsrmmd -n 3
root 2948 2805 1 Aug29 ? 01:11:46 /usr/sbin/nsrmmd -n 4
root 11598 2805 0 04:00 ? 00:00:00 /usr/sbin/savegrp Millennium
root 5139 11598 0 06:00 ? 00:00:00 /usr/sbin/nsrexec -- csulib.ctstateu.edu:index
root 5140 2799 0 06:00 ? 00:00:00 /usr/sbin/nsrexecd
root 5141 5140 0 06:00 ? 00:00:00 /usr/sbin/save -s solegato2.ctstateu.edu -S -g Millennium -LL -f - -m solegato2.ctstateu.edu -V -l full -LL -q -W 78 -N index:9a299932
-00000004-44be704a-44da0bc9-092b0000-95980ec0 /nsr/index/csulib.ctstateu.edu
The precmd and pstcmd both finish with return code 0.
Sorry for the long post. Any ideas?
Thanks,
Vic
Environment:
Server & Client: RedHat Linux ES 3.6 running NW 7.2.1
We're having a problem with another client. This is a new client and has never worked during its scheduled nightly backup. The backup starts at 4 AM, runs the precmd to shut down the vendor's database (not sure what kind of database it is), and backs up the 4 filesystems finishing by 4:27 AM. At this point it stalls until 6 AM I think because Legato then times-out. The index is then written to tape, the pstcmd runs restarting the database, and the Legato backup exits with an error. This is the only client in the savegroup and no other backups are running at the time. For the group we changed the 'Client Retries' from 1 to 0 because the backups was stalling until 8 AM when it retried. When we try running the backup manually during the day and it runs fine.
On the client in savepnps.log we have:
09/01/06 04:01:17 preclntsave: All command(s) ran successfully.
09/01/06 06:00:19 pstclntsave: All savesets on the worklist are done.
09/01/06 06:00:20 pstclntsave: All command(s) ran successfully.
09/01/06 06:00:20 pstclntsave: Exited.
On the server in messages we have:
Sep 1 04:00:01 solegato2 logger: NetWorker savegroup: (info) starting Millennium (with 1 client(s))
Sep 1 06:00:39 solegato2 logger: NetWorker savegroup: (alert) Millennium completed, total 1 client(s), 0 Hostname(s) Unresolved, 1 Failed, 0 Succeeded. (csulib.ctstateu.edu Failed)
Sep 1 06:00:39 solegato2 logger: Start time: Fri Sep 1 04:00:00 2006
Sep 1 06:00:39 solegato2 logger: End time: Fri Sep 1 06:00:39 2006
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: --- Unsuccessful Save Sets ---
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: * csulib.ctstateu.edu:/iiidb Cannot determine status of the backup process. Use mminfo to determine job status.
Sep 1 06:00:39 solegato2 logger: * csulib.ctstateu.edu:/iiidb/software Cannot determine status of the backup process. Use mminfo to determine job status.
Sep 1 06:00:39 solegato2 logger: * csulib.ctstateu.edu:/iiidb/images Cannot determine status of the backup process. Use mminfo to determine job status.
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: --- Successful Save Sets ---
Sep 1 06:00:39 solegato2 logger:
Sep 1 06:00:39 solegato2 logger: csulib.ctstateu.edu: /iii level=full, 1315 KB 00:00:02 30 files
Sep 1 06:00:39 solegato2 logger: solegato2.ctstateu.edu: index:csulib.ctstateu.edu level=full, 376 MB 00:00:35 198 files
On the server in daemon.log we have:
09/01/06 04:00:01 nsrd: savegroup info: starting Millennium (with 1 client(s))
09/01/06 04:01:23 nsrd: csulib.ctstateu.edu:/iiidb/software saving to pool 'Unix' (VZ1127L1)
09/01/06 04:01:26 nsrd: csulib.ctstateu.edu:/iii saving to pool 'Unix' (VZ1127L1)
09/01/06 04:01:26 nsrd: csulib.ctstateu.edu:/iiidb/images saving to pool 'Unix' (VZ1127L1)
09/01/06 04:01:28 nsrd: csulib.ctstateu.edu:/iii done saving to pool 'Unix' (VZ1127L1) 1314 KB
09/01/06 04:01:29 nsrd: csulib.ctstateu.edu:/iiidb saving to pool 'Unix' (VZ1127L1)
09/01/06 04:06:41 nsrd: csulib.ctstateu.edu:/iiidb/software done saving to pool 'Unix' (VZ1127L1) 786 MB
09/01/06 04:16:34 nsrd: csulib.ctstateu.edu:/iiidb done saving to pool 'Unix' (VZ1127L1) 3050 MB
09/01/06 04:26:28 nsrd: csulib.ctstateu.edu:/iiidb/images done saving to pool 'Unix' (VZ1127L1) 8899 MB
09/01/06 04:27:10 nsrd: write completion notice: Writing to volume VZ1127L1 complete
* csulib.ctstateu.edu:/iiidb/software Cannot determine status of the backup process. Use mminfo to determine job status.
* csulib.ctstateu.edu:/iiidb/images Cannot determine status of the backup process. Use mminfo to determine job status.
* csulib.ctstateu.edu:/iiidb Cannot determine status of the backup process. Use mminfo to determine job status.
09/01/06 06:00:22 nsrd: solegato2.ctstateu.edu:index:csulib.ctstateu.edu saving to pool 'Unix' (VZ1127L1)
09/01/06 06:00:39 nsrd: solegato2.ctstateu.edu:index:csulib.ctstateu.edu done saving to pool 'Unix' (VZ1127L1) 376 MB
09/01/06 06:00:39 nsrd: savegroup alert: Millennium completed, total 1 client(s), 0 Hostname(s) Unresolved, 1 Failed, 0 Succeeded. (csulib.ctstateu.edu Failed)
09/01/06 06:00:39 nsrd: runq: NSR group Millennium exited with return code 1.
09/01/06 06:01:18 nsrd: write completion notice: Writing to volume VZ1127L1 complete
I looked up the error in the Error Message Guide and followed the steps in the Resolution section as follows:
o I checked the status of the backups using mminfo and they appear completed:
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:23 786 MB 2482497747 cb full /iiidb/software
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:26 1315 KB 2465720534 cb full /iii
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:27 8899 MB 2448943318 cb full /iiidb/images
VZ1127L1 csulib.ctstateu.edu 09/01/06 04:01:29 3050 MB 2432166105 cb full /iiidb
o I wrote a script that ran on both client & server during the backups which ping'd the other system once every mintue and all pings were successful.
o The disk containing the log file isn't full.
o The Networker Module binaries are installed.
The scripts that I wrote also listed the status of the Networker processes every minute. On the client just before and after the last filesystem is backed up we have:
Fri Sep 1 04:25:33 EDT 2006
+ ps -ef
+ grep -e nsr -e save -e mm
root 2781 1 0 Aug17 ? 00:00:00 /usr/sbin/nsrexecd
root 2784 2781 0 Aug17 ? 00:00:01 /usr/sbin/nsrexecd
root 28600 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28603 28600 22 04:00 ? 00:05:42 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb/images /iiidb/images
root 28955 1 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
Fri Sep 1 04:26:36 EDT 2006
+ ps -ef
+ grep -e nsr -e save -e mm -e hm7
root 2781 1 0 Aug17 ? 00:00:00 /usr/sbin/nsrexecd
root 2784 2781 0 Aug17 ? 00:00:01 /usr/sbin/nsrexecd
root 28600 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28955 1 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
The thing that I find odd here is the pstclntsave process. According to the manpage it is suppose to be a child process of preclntsave but it's not. It looks like an orphaned process. The preclntsave processes exist only for the 1st minute or so of the backup:
Fri Sep 1 04:01:20 EDT 2006
+ ps -ef
+ grep -e nsr -e save -e mm -e hm7
root 2781 1 0 Aug17 ? 00:00:00 /usr/sbin/nsrexecd
root 2784 2781 0 Aug17 ? 00:00:01 /usr/sbin/nsrexecd
root 28595 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28596 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28597 28595 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb/software /iiidb/software
root 28598 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28599 28596 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iii /iii
root 28600 2784 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 28601 28597 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28602 28599 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28603 28600 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb/images /iiidb/images
root 28604 28598 0 04:00 ? 00:00:00 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb /iiidb
root 28605 28603 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28607 28604 0 04:00 ? 00:00:00 /usr/bin/preclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
root 28955 28601 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu
On the server up until it times out we have:
Fri Sep 1 05:59:43 EDT 2006
root 2798 1 0 Aug29 ? 00:00:01 /usr/sbin/nsrexecd
root 2799 2798 0 Aug29 ? 00:00:03 /usr/sbin/nsrexecd
root 2802 1 0 Aug29 ? 00:00:00 /usr/sbin/lgtolmd -p /nsr/lic -n 1
root 2805 1 0 Aug29 ? 00:00:27 /usr/sbin/nsrd
root 2811 2805 0 Aug29 ? 00:00:18 /usr/sbin/nsrmmdbd
root 2812 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrindexd
root 2945 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrmmd -n 1
root 2946 2805 0 Aug29 ? 00:00:27 /usr/sbin/nsrmmd -n 2
root 2947 2805 0 Aug29 ? 00:01:22 /usr/sbin/nsrmmd -n 3
root 2948 2805 1 Aug29 ? 01:11:46 /usr/sbin/nsrmmd -n 4
root 11598 2805 0 04:00 ? 00:00:00 /usr/sbin/savegrp Millennium
root 11610 11598 0 04:00 ? 00:00:00 /usr/sbin/nsrexec -c csulib.ctstateu.edu -a -- csulib.ctstateu.edu:/iiidb/software
root 11612 11598 0 04:00 ? 00:00:00 /usr/sbin/nsrexec -c csulib.ctstateu.edu -a -- csulib.ctstateu.edu:/iiidb
root 11613 11598 0 04:00 ? 00:00:00 /usr/sbin/nsrexec -c csulib.ctstateu.edu -a -- csulib.ctstateu.edu:/iiidb/images
Fri Sep 1 06:00:13 EDT 2006
root 2798 1 0 Aug29 ? 00:00:01 /usr/sbin/nsrexecd
root 2799 2798 0 Aug29 ? 00:00:03 /usr/sbin/nsrexecd
root 2802 1 0 Aug29 ? 00:00:00 /usr/sbin/lgtolmd -p /nsr/lic -n 1
root 2805 1 0 Aug29 ? 00:00:27 /usr/sbin/nsrd
root 2811 2805 0 Aug29 ? 00:00:18 /usr/sbin/nsrmmdbd
root 2812 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrindexd
root 2945 2805 0 Aug29 ? 00:00:00 /usr/sbin/nsrmmd -n 1
root 2946 2805 0 Aug29 ? 00:00:27 /usr/sbin/nsrmmd -n 2
root 2947 2805 0 Aug29 ? 00:01:22 /usr/sbin/nsrmmd -n 3
root 2948 2805 1 Aug29 ? 01:11:46 /usr/sbin/nsrmmd -n 4
root 11598 2805 0 04:00 ? 00:00:00 /usr/sbin/savegrp Millennium
root 5139 11598 0 06:00 ? 00:00:00 /usr/sbin/nsrexec -- csulib.ctstateu.edu:index
root 5140 2799 0 06:00 ? 00:00:00 /usr/sbin/nsrexecd
root 5141 5140 0 06:00 ? 00:00:00 /usr/sbin/save -s solegato2.ctstateu.edu -S -g Millennium -LL -f - -m solegato2.ctstateu.edu -V -l full -LL -q -W 78 -N index:9a299932
-00000004-44be704a-44da0bc9-092b0000-95980ec0 /nsr/index/csulib.ctstateu.edu
The precmd and pstcmd both finish with return code 0.
Sorry for the long post. Any ideas?
Thanks,
Vic
0 events found
No Events found!
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
0
September 8th, 2006 05:00
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
1
September 1st, 2006 07:00
Do you get this every time? If yes, try backup without savepnpc and see if it runs. Thus you can see if savepnpc is related to the story or not.
I would suggest to start backup in debug level (actually start server in debug mode), start the backup and see what you get.
vsemaska
194 Posts
0
September 1st, 2006 08:00
According to mminfo all the savesets were successful so I don't why Legato says it's a failure.
Yes we do get this every time. We'll try running it tonight without savepnpc to see what happens.
As for debug mode. For the client are you referring to the 'Vebose' option in the nwadmin GUI? How do you start the server in debug mode?
Thanks for your help.
Vic
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
1
September 1st, 2006 08:00
a) shutdown server and run it manually with -DX (where X=1...)
b) get from support binary to enable debug modes on the fly
Usually you don't use these unless told by support. These tend to be really BIG. First give it a try without savepnpc. Group fails due to that mminfo message so the question is from where is that coming from. Support might have a patch for this so it would be good idea to involve them too. Then suggest them that having group running in debug mode might help and perhaps they will agree to it and give you tools from b) above.
vsemaska
194 Posts
0
September 1st, 2006 10:00
Thanks again for the help. We've called support and they 1st want us to leave savepnpc enabled but to change the 'Inactivity Timeout' field in the savegroup to 0 for some reason. We're going to give that a try tonight.
Vic
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
0
September 1st, 2006 12:00
What version of NW is on server and client?
vsemaska
194 Posts
0
September 1st, 2006 13:00
The inactivity timeout was set to 30. Thing is the backups finish around 4:27 AM but the timeout (if it is a timeout) doesn't occur until 6 AM. That's 1.5 hours later.
The version for Server & Client: NW 7.2.1
Vic
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
0
September 1st, 2006 13:00
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
0
September 1st, 2006 13:00
By looking it again it seems like NW problem not related to savepnpc. It looks that way according to savepnpc log - at the point when NW gave up and said "ask mminfo about saveset fate as I lost the record what is where and what is going on" we see that savepnpc reports both savesets to be done and pst command too (6am). This indicates that save was a problem (actually client-server communication that should exist for that). I'm not sure if it makes sense to test the same with 7.2.2 too, but I'm quite sure support might give you that suggestion soon. Actually it would be good thing to try. But without anything more in log it's going to be difficult without debug level to see what it is. At this point it could be few things. I guess you will need to run test by test day by day until problem is isoleted.
vsemaska
194 Posts
0
September 5th, 2006 07:00
The Inactivity Timer set to zero had no affect. The backup finsished like before. Next thing we tried was to remove the savepnpc from the Backup Command field and the backup still finsihed we the same times. I've added 'lsof -i' & 'netstat -a' to my scripts on both client & server for tonight's run. We'll see what we get.
Support hasn't suggested using debug mode yet. If we don't get anything from tonight's run I'll suggest that to them.
Vic
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
0
September 5th, 2006 08:00
I believe at this point, if no additional messages can be obtained, you will need to increase level of message report (and that usually means debug mode).
vsemaska
194 Posts
0
September 7th, 2006 08:00
We have been running scripts to monitor what's running on the client and it doesn't seem the savepnpc is the one that gets stuck but the pstclntsave. Here's what we see:
Thu Sep 7 04:27:04 EDT 2006
root 8880 1 0 Sep01 ? 00:00:00 /usr/sbin/nsrexecd
root 8881 8880 0 Sep01 ? 00:00:00 /usr/sbin/nsrexecd
root 20946 8881 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 20950 20946 21 04:00 ? 00:05:43 /usr/sbin/savepnpc -s solegato2.ctstateu.edu -g Millennium -LL -m csulib.ctstateu.edu -l full -q -W 78 -N /iiidb/images /iiidb/images
root 21176 1 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu + ping -c 1 solegato2.ctstateu.edu
Thu Sep 7 04:28:08 EDT 2006
root 8880 1 0 Sep01 ? 00:00:00 /usr/sbin/nsrexecd
root 8881 8880 0 Sep01 ? 00:00:00 /usr/sbin/nsrexecd
root 20946 8881 0 04:00 ? 00:00:00 /usr/sbin/nsrexecd
root 21176 1 0 04:01 ? 00:00:00 /usr/bin/pstclntsave -s solegato2.ctstateu.edu -g Millennium -c csulib.ctstateu.edu+ ping -c 1 solegato2.ctstateu.edu
At this point it hangs until 6AM. At that time pstclntsave finsihes and the savegroup ends.
The savepnpc runs a precmd that shuts down a database so there's no open or locked files. Also haven't see any hardware errors. We don't have truss on this server and I'd rather avoid loading more software for now.
Would running savegrp on the server at the command line with the -v & -D3 options help or should I try running savepnpc on the client at the command line?
Thanks,
Vic
ble1
6 Operator
•
14.4K Posts
•
56.2K Points
0
September 7th, 2006 11:00
vsemaska
194 Posts
0
September 8th, 2006 05:00
You are right, we tried it without savepnpc on Tues morning (Sep 5) and the problem remained. Thing is it has been real busy due to other problems this week and I've lost track of what we've done with this problem. The daemon.log for that shows this:
09/05/06 04:00:00 nsrd: savegroup info: starting Millennium (with 1 client(s))
09/05/06 04:00:03 nsrd: csulib.ctstateu.edu:/iii saving to pool 'Unix' (VZ1166L1)
09/05/06 04:00:03 nsrd: csulib.ctstateu.edu:/iiidb/images saving to pool 'Unix' (VZ1166L1)
09/05/06 04:00:03 nsrd: csulib.ctstateu.edu:/iiidb saving to pool 'Unix' (VZ1166L1)
09/05/06 04:00:04 nsrd: csulib.ctstateu.edu:/iiidb/software saving to pool 'Unix' (VZ1166L1)
09/05/06 04:00:06 nsrd: csulib.ctstateu.edu:/iii done saving to pool 'Unix' (VZ1166L1) 1669 KB
09/05/06 04:05:21 nsrd: csulib.ctstateu.edu:/iiidb/software done saving to pool 'Unix' (VZ1166L1) 786 MB
09/05/06 04:16:30 nsrd: csulib.ctstateu.edu:/iiidb done saving to pool 'Unix' (VZ1166L1) 3082 MB
09/05/06 04:26:06 nsrd: csulib.ctstateu.edu:/iiidb/images done saving to pool 'Unix' (VZ1166L1) 8954 MB
09/05/06 04:26:57 nsrd: write completion notice: Writing to volume VZ1166L1 complete
* csulib.ctstateu.edu:/iiidb/software Cannot determine status of the backup process. Use mminfo to determine job status.
* csulib.ctstateu.edu:/iiidb/images Cannot determine status of the backup process. Use mminfo to determine job status.
* csulib.ctstateu.edu:/iiidb save: Warning - `/iiidb/errlog/webpac.log' size grew during save
* csulib.ctstateu.edu:/iiidb save: Expected 3763060 bytes for `/iiidb/errlog/webpac.log', got 3763759 bytes
* csulib.ctstateu.edu:/iiidb save: Warning - `/iiidb/mysql/data/wam/wam_report.MYD' size grew during save
* csulib.ctstateu.edu:/iiidb save: Expected 99508312 bytes for `/iiidb/mysql/data/wam/wam_report.MYD', got 99508412 bytes
* csulib.ctstateu.edu:/iiidb save: Warning - `/iiidb/mysql/data/wam/wam_report.MYI' size grew during save
* csulib.ctstateu.edu:/iiidb save: Expected 327077888 bytes for `/iiidb/mysql/data/wam/wam_report.MYI', got 327095296 bytes
09/05/06 06:09:40 nsrd: solegato2.ctstateu.edu:index:csulib.ctstateu.edu saving to pool 'Unix' (VZ1166L1)
09/05/06 06:10:00 nsrd: solegato2.ctstateu.edu:index:csulib.ctstateu.edu done saving to pool 'Unix' (VZ1166L1) 411 MB
09/05/06 06:10:00 nsrd: savegroup alert: Millennium completed, total 1 client(s), 0 Hostname(s) Unresolved, 1 Failed, 0 Succeeded. (csulib.ctstateu.edu Failed)
09/05/06 06:10:00 nsrd: runq: NSR group Millennium exited with return code 1.
There's nothing in savepnpc.log on the client for that date so that verifies savepnpc wasn't used.
Now for the weird part. Earlier this week we were trying to figure out why the backup worked ever time we start it manually during the day via nwadmin and never at night as a scheduled backup. That's when we remembered that on the manual backups we enabled the Verbose option for the group via nwadmin to see if it showed something. So 3 nights ago we enabled verbose for the scheduled backup and it worked. To verify, 2 nights ago we turned verbose off and it failed. Last night we turned verbose back on and it worked again. For some reason turning on the Verbose option fixes the problem. Can't have it this way because it generates a huge daemon.log due to the thousands of files that are backed up.
We're thinking of doing one of the things that Luis suggested, take the pstcmd out of the .res file and run it as a cronjob to see what happens.
Vic
vsemaska
194 Posts
0
September 12th, 2006 06:00
Thanks for you suggestions but it's looking like it's not a firewall issue. The savegroup backs up 4 disks so we decided to try process of elimination. Remove one disk at a time and see if it still fails. We did get a successful backup when we removed one particular disk. We tried backing just that disk to see if it would still fail and it succeeded! So now were looking into if it's a combination of disks that's the problem.
Vic