hi, me again ...
i know i have to eventually dig deeper about this but i really don't know
what is happening here, i'm slowly assuming that ther is some client
scheduler bug :-) hmm maybe it's because the client version is a bit low :-)
5.1.1.0 ... below is sample output of dsmsched.log for 2 nodes from 2
different servers with very similar schedules, they started corectly
everything is fine ... the preshedule script started and is running
(currently in cp process) but in "q event" it shows me that is missed ...
which is not ...
08/24/06 01:42:20 --- SCHEDULEREC QUERY BEGIN
08/24/06 01:42:20 --- SCHEDULEREC QUERY END
08/24/06 01:42:20 Next operation scheduled:
08/24/06
01:42:20 ------------------------------------------------------------
08/24/06 01:42:20 Schedule Name: TCIS_OLB_SCHED01
08/24/06 01:42:20 Action: Incremental
08/24/06 01:42:20 Objects: /db/tcis/olb/
08/24/06 01:42:20 Options: -preschedulecmd="su - oracle -c
/db/tcis/olb/doob"
08/24/06 01:42:20 Server Window Start: 02:30:00 on 08/24/06
08/24/06
01:42:20 ------------------------------------------------------------
08/24/06 01:42:20 Scheduler has been stopped.
08/24/06 02:30:22 Scheduler has been started by Dsmcad.
08/24/06 02:30:22 Querying server for next scheduled event.
08/24/06 02:30:22 Node Name: TCIS
08/24/06 02:30:22 Session established with server TSM01: AIX-RS/6000
08/24/06 02:30:22 Server Version 5, Release 3, Level 3.1
08/24/06 02:30:22 Server date/time: 08/24/06 02:34:21 Last access:
08/24/06 01:46:19
08/24/06 02:30:22 --- SCHEDULEREC QUERY BEGIN
08/24/06 02:30:22 --- SCHEDULEREC QUERY END
08/24/06 02:30:22 Next operation scheduled:
08/24/06
02:30:22 ------------------------------------------------------------
08/24/06 02:30:22 Schedule Name: TCIS_OLB_SCHED01
08/24/06 02:30:22 Action: Incremental
08/24/06 02:30:22 Objects: /db/tcis/olb/
08/24/06 02:30:22 Options: -preschedulecmd="su - oracle -c
/db/tcis/olb/doob"
08/24/06 02:30:22 Server Window Start: 02:30:00 on 08/24/06
08/24/06
02:30:22 ------------------------------------------------------------
08/24/06 02:30:22
Executing scheduled command now.
08/24/06 02:30:22
Executing Operating System command or script:
su - oracle -c /db/tcis/olb/doob
BUT : 08/24/06 02:30:00,,TCIS_OLB_SCHED01,TCIS,Missed
in actlog ...
08/24/06 01:46:19 ANR0403I Session 25240 ended for node TCIS
(HPUX).(SESSION: 25240)
08/24/06 01:46:19 ANR0406I Session 25251 started for node TCIS (HPUX)
(Tcp/Ip tobija.vipnet.hr(50996)).(SESSION: 25251)
08/24/06 01:46:19 ANR0403I Session 25251 ended for node TCIS
(HPUX).(SESSION: 25251)
08/24/06 02:34:21 ANR0406I Session 25290 started for node TCIS (HPUX)
(Tcp/Ip tobija.vipnet.hr(58403)).(SESSION: 25290)
08/24/06 03:30:01 ANR2578W Schedule TCIS_OLB_SCHED01 in domain CIS_PD
for
node TCIS has missed its scheduled start up
window.
08/24/06 03:34:29 ANR0482W Session 25290 for node TCIS (HPUX)
terminated -
idle for more than 60 minutes.(SESSION: 25290)
and ...
08/23/06 16:59:57 --- SCHEDULEREC QUERY BEGIN
08/23/06 16:59:57 --- SCHEDULEREC QUERY END
08/23/06 16:59:57 Next operation scheduled:
08/23/06
16:59:57 ------------------------------------------------------------
08/23/06 16:59:57 Schedule Name: PCIS_OLB_SCHED01
08/23/06 16:59:57 Action: Incremental
08/23/06 16:59:57 Objects: /db/pcis/olb/
08/23/06 16:59:57 Options: -preschedulecmd="su - oracle -c
/db/pcis/olb/doob"
08/23/06 16:59:57 Server Window Start: 23:49:00 on 08/23/06
08/23/06
16:59:57 ------------------------------------------------------------
08/23/06 16:59:57 Scheduler has been stopped.
08/23/06 23:51:58 Scheduler has been started by Dsmcad.
08/23/06 23:51:58 Querying server for next scheduled event.
08/23/06 23:51:58 Node Name: PCIS
08/23/06 23:51:58 Session established with server TSM01: AIX-RS/6000
08/23/06 23:51:58 Server Version 5, Release 3, Level 3.1
08/23/06 23:51:58 Server date/time: 08/23/06 23:55:57 Last access:
08/23/06 17:03:56
08/23/06 23:51:58 --- SCHEDULEREC QUERY BEGIN
08/23/06 23:51:58 --- SCHEDULEREC QUERY END
08/23/06 23:51:58 Next operation scheduled:
08/23/06
23:51:58 ------------------------------------------------------------
08/23/06 23:51:58 Schedule Name: PCIS_OLB_SCHED01
08/23/06 23:51:58 Action: Incremental
08/23/06 23:51:58 Objects: /db/pcis/olb/
08/23/06 23:51:58 Options: -preschedulecmd="su - oracle -c
/db/pcis/olb/doob"
08/23/06 23:51:58 Server Window Start: 23:49:00 on 08/23/06
08/23/06
23:51:58 ------------------------------------------------------------
08/23/06 23:51:58
Executing scheduled command now.
08/23/06 23:51:58
Executing Operating System command or script:
su - oracle -c /db/pcis/olb/doob
BUT : 08/23/06 23:49:00,,PCIS_OLB_SCHED01,PCIS,Missed
in actlog everything i found about PCIS_OLB_SCHED01 is ...
08/24/06 00:49:01 ANR2578W Schedule PCIS_OLB_SCHED01 in domain CIS_PD
for
node PCIS has missed its scheduled start up
window.
08/24/06 00:56:10 ANR0482W Session 25128 for node PCIS (HPUX)
terminated -
idle for more than 60 minutes.(SESSION: 25128)
does it have something to do with DURATION parameter ?
i'm would be thankful on every clue, i know it's practicaly imposible to
know why this happened without detailed log and other stuff investigation
but the thing is that on server is everything fine , the most confusing
thing is that as i showed it before that the schedule works fine and it does
it job but it's showing as missed which is very nasty to see when SOX
control is underway :-)
for example ... another node, another server , another schedule with
preschedulecmd ... very long export (21 hour) , okay we have 1 longer ,
around 30-35 :-)
log:
08/17/06 00:27:09 Node Name: BSCS
08/17/06 00:27:09 Session established with server TSM01: AIX-RS/6000
08/17/06 00:27:09 Server Version 5, Release 3, Level 3.1
08/17/06 00:27:09 Server date/time: 08/17/06 00:31:09 Last access:
08/16/06 17:57:04
08/17/06 00:27:09 --- SCHEDULEREC QUERY BEGIN
08/17/06 00:27:09 --- SCHEDULEREC QUERY END
08/17/06 00:27:09 Next operation scheduled:
08/17/06
00:27:09 ------------------------------------------------------------
08/17/06 00:27:09 Schedule Name: BSCS_OLB_SCHED01
08/17/06 00:27:09 Action: Incremental
08/17/06 00:27:09 Objects: /db/bscs81/olb/bscs8/
08/17/06 00:27:09 Options: -preschedulecmd="su - oracle -c
/db/bscs81/olb/bscs8/doob" -su=yes
08/17/06 00:27:09 Server Window Start: 00:25:00 on 08/17/06
08/17/06
00:27:09 ------------------------------------------------------------
08/17/06 00:27:09
Executing scheduled command now.
08/17/06 00:27:09
Executing Operating System command or script:
su - oracle -c /db/bscs81/olb/bscs8/doob
08/17/06 21:10:40 Finished command. Return code is: 0
08/17/06 21:10:40 Session established with server TSM01: AIX-RS/6000
08/17/06 21:10:40 Server Version 5, Release 3, Level 3.1
08/17/06 21:10:40 Server date/time: 08/17/06 21:14:39 Last access:
08/17/06 00:31:09
08/17/06 21:10:40 --- SCHEDULEREC OBJECT BEGIN BSCS_OLB_SCHED01 08/17/06
00:25:00
08/17/06 21:10:40 Incremental backup of volume '/db/bscs81/olb/bscs8/'
08/17/06 21:11:02 Normal File--> 28,835,848,192
/db/bscs81/olb/bscs8/BILLIMAGE_01.dbf ** Unsuccessful **
08/17/06 21:11:02 ANS1114I Waiting for mount of offline media.
08/17/06 22:19:05 Retry # 1 Normal File--> 28,835,848,192
/db/bscs81/olb/bscs8/BILLIMAGE_01.dbf [Sent]
.
.
.
and so on ...
.
.
.8/18/06 23:19:31 Successful incremental backup of
'/db/bscs81/olb/bscs8/*'
08/18/06 23:19:32 --- SCHEDULEREC STATUS BEGIN
08/18/06 23:19:32 Total number of objects inspected: 144
08/18/06 23:19:32 Total number of objects backed up: 132
08/18/06 23:19:32 Total number of objects updated: 0
08/18/06 23:19:32 Total number of objects rebound: 0
08/18/06 23:19:32 Total number of objects deleted: 0
08/18/06 23:19:32 Total number of objects expired: 0
08/18/06 23:19:32 Total number of objects failed: 0
08/18/06 23:19:32 Total number of bytes transferred: 804.96 GB
08/18/06 23:19:32 Data transfer time: 37,623.07 sec
08/18/06 23:19:32 Network data transfer rate: 22,434.89 KB/sec
08/18/06 23:19:32 Aggregate data transfer rate: 8,966.92 KB/sec
08/18/06 23:19:32 Objects compressed by: 0%
08/18/06 23:19:32 Elapsed processing time: 26:08:51
08/18/06 23:19:32 --- SCHEDULEREC STATUS END
08/18/06 23:19:32 --- SCHEDULEREC OBJECT END BSCS_OLB_SCHED01 08/17/06
00:25:00
08/18/06 23:19:32 Scheduled event 'BSCS_OLB_SCHED01' completed
successfully.
08/18/06 23:19:32 Sending results for scheduled event 'BSCS_OLB_SCHED01'.
08/18/06 23:19:32 Results sent to server for scheduled event
'BSCS_OLB_SCHED01'.
08/18/06 23:19:32 ANS1483I Schedule log pruning started.
08/18/06 23:19:32 ANS1484I Schedule log pruning finished successfully.
so the schedule finished okay but in event log:
08/17/06 00:25:00 BSCS_OLB_SCH- BSCS
Missed
ED01
dsm.sys from this last example
SERVERNAME bscs
* ENABLELANFREE yes
COMMmethod TCPip
TCPPort 1500
* LANFREETCPPort 1511
TCPServeraddress axptsm01.vipnet.hr
* LANFREETCPServeraddress mihael.vipnet.hr
NodeName bscs
inclexcl /usr/local/etc/inclexcl.bscs
Mailprog /usr/bin/mail root
Schedlogname /var/adm/dsmsched_X.bscs
Schedlogretention 7 D
ERRORLOGNAM /var/adm/dsmerror_bscs.log
errorlogretention 7 D
QUERYSCHED 8
MANAGEDSERVICES schedule webclient
PASSWORDACCESS Generate
i know this is very long read, sorry ... if i found anything new i'll come
forward, okay ?
thanks a lot
goran
|
