Well, I'm glad you asked me to look at the activity log more closely--it
appears to be having a bigger impact than I'd realized. The activity log
shows that the backup which should have been scheduled for 23:15 last night
in fact did not run. One point which may be helpful is that only recently
did we see Solaris clients affected by this. Up until then, I've only ever
observed it with Windows clients. We did recently upgrade our Solaris
client code, and implemented the CAD and client option sets at the same
time. We are now using these on Windows, Solaris, and Netware clients--and
we see this behavior everywhere but the Netware clients.
Kathleen
Date/Time Message
--------------------
----------------------------------------------------------
07/14/04 00:15:01 ANR2578W Schedule HE2UNX108.2315.SOL.ANY in domain SOL
for
node HE2UNX108 has missed its scheduled start up
window.
07/14/04 00:16:33 ANR0406I Session 383572 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60644)).
(SESSION:
383572)
07/14/04 00:16:33 ANR2571W Scheduled session from node HE2UNX108 (SUN
SOLARIS) has been denied, scheduled sessions are not
currently available. (SESSION: 383572)
07/14/04 00:16:33 ANR0403I Session 383572 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 383572)
07/14/04 00:36:33 ANR0406I Session 383627 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60655)).
(SESSION:
383627)
07/14/04 00:36:33 ANR2571W Scheduled session from node HE2UNX108 (SUN
SOLARIS) has been denied, scheduled sessions are not
currently available. (SESSION: 383627)
07/14/04 00:36:33 ANR0403I Session 383627 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 383627)
07/14/04 00:56:33 ANR0406I Session 383766 started for node HE2UNX108
(SUN
more... (<ENTER> to continue, 'C' to cancel)
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60660)).
(SESSION:
383766)
07/14/04 00:56:33 ANR2571W Scheduled session from node HE2UNX108 (SUN
SOLARIS) has been denied, scheduled sessions are not
currently available. (SESSION: 383766)
07/14/04 00:56:33 ANR0403I Session 383766 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 383766)
07/14/04 01:16:33 ANR0406I Session 383930 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60665)).
(SESSION:
383930)
07/14/04 01:16:33 ANR2571W Scheduled session from node HE2UNX108 (SUN
SOLARIS) has been denied, scheduled sessions are not
currently available. (SESSION: 383930)
07/14/04 01:16:33 ANR0403I Session 383930 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 383930)
07/14/04 01:16:55 ANR0482W Session 383155 for node HE2UNX108 ()
terminated -
idle for more than 120 minutes. (SESSION: 1062)
07/14/04 01:36:34 ANR0406I Session 384075 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60668)).
(SESSION:
384075)
07/14/04 01:37:49 ANR2017I Administrator THIRD issued command: UPDATE
SCHEDULE SOL HE2UNX108.2315.SOL.ANY startt=now
(SESSION:
more... (<ENTER> to continue, 'C' to cancel)
383713)
07/14/04 01:37:49 ANR2502I Schedule HE2UNX108.2315.SOL.ANY updated in
policy
domain SOL. (SESSION: 383713)
07/14/04 01:43:14 ANR0406I Session 384161 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60671)).
(SESSION:
384161)
07/14/04 02:14:00 ANR0403I Session 384161 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 384161)
07/14/04 02:14:01 ANE4952I (Session: 384075, Node: HE2UNX108) Total
number
of objects inspected: 64,951(SESSION: 384075)
07/14/04 02:14:01 ANE4954I (Session: 384075, Node: HE2UNX108) Total
number
of objects backed up: 139(SESSION: 384075)
07/14/04 02:14:01 ANE4958I (Session: 384075, Node: HE2UNX108) Total
number
of objects updated: 0(SESSION: 384075)
07/14/04 02:14:01 ANE4960I (Session: 384075, Node: HE2UNX108) Total
number
of objects rebound: 0(SESSION: 384075)
07/14/04 02:14:01 ANE4957I (Session: 384075, Node: HE2UNX108) Total
number
of objects deleted: 0(SESSION: 384075)
07/14/04 02:14:01 ANE4970I (Session: 384075, Node: HE2UNX108) Total
number
of objects expired: 31(SESSION: 384075)
07/14/04 02:14:01 ANE4959I (Session: 384075, Node: HE2UNX108) Total
number
of objects failed: 0(SESSION: 384075)
more... (<ENTER> to continue, 'C' to cancel)
07/14/04 02:14:01 ANE4961I (Session: 384075, Node: HE2UNX108) Total
number
of bytes transferred: 21.30 MB(SESSION: 384075)
07/14/04 02:14:01 ANE4963I (Session: 384075, Node: HE2UNX108) Data
transfer
time: 1,663.89 sec(SESSION: 384075)
07/14/04 02:14:01 ANE4966I (Session: 384075, Node: HE2UNX108) Network
data
transfer rate: 13.11 KB/sec(SESSION:
384075)
07/14/04 02:14:01 ANE4967I (Session: 384075, Node: HE2UNX108) Aggregate
data transfer rate: 9.70 KB/sec(SESSION:
384075)
07/14/04 02:14:01 ANE4968I (Session: 384075, Node: HE2UNX108) Objects
compressed by: 0%(SESSION: 384075)
07/14/04 02:14:01 ANE4964I (Session: 384075, Node: HE2UNX108) Elapsed
processing time: 00:37:27(SESSION: 384075)
07/14/04 02:14:02 ANR2507I Schedule HE2UNX108.2315.SOL.ANY for domain
SOL
started at 07/14/04 23:15:00 for node HE2UNX108
completed
successfully at 07/14/04 02:14:02. (SESSION: 384075)
07/14/04 02:14:02 ANR0403I Session 384075 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 384075)
07/14/04 02:14:02 ANR0406I Session 384494 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60679)).
(SESSION:
384494)
07/14/04 02:23:39 ANR0406I Session 384574 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60680)).
(SESSION:
more... (<ENTER> to continue, 'C' to cancel)
384574)
07/14/04 02:55:51 ANR0403I Session 384574 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 384574)
07/14/04 02:55:52 ANE4952I (Session: 384494, Node: HE2UNX108) Total
number
of objects inspected: 64,950(SESSION: 384494)
07/14/04 02:55:52 ANE4954I (Session: 384494, Node: HE2UNX108) Total
number
of objects backed up: 45(SESSION: 384494)
07/14/04 02:55:52 ANE4958I (Session: 384494, Node: HE2UNX108) Total
number
of objects updated: 0(SESSION: 384494)
07/14/04 02:55:52 ANE4960I (Session: 384494, Node: HE2UNX108) Total
number
of objects rebound: 0(SESSION: 384494)
07/14/04 02:55:52 ANE4957I (Session: 384494, Node: HE2UNX108) Total
number
of objects deleted: 0(SESSION: 384494)
07/14/04 02:55:52 ANE4970I (Session: 384494, Node: HE2UNX108) Total
number
of objects expired: 0(SESSION: 384494)
07/14/04 02:55:52 ANE4959I (Session: 384494, Node: HE2UNX108) Total
number
of objects failed: 0(SESSION: 384494)
07/14/04 02:55:52 ANE4961I (Session: 384494, Node: HE2UNX108) Total
number
of bytes transferred: 7.86 MB(SESSION: 384494)
07/14/04 02:55:52 ANE4963I (Session: 384494, Node: HE2UNX108) Data
transfer
time: 1,882.76 sec(SESSION: 384494)
07/14/04 02:55:52 ANE4966I (Session: 384494, Node: HE2UNX108) Network
data
more... (<ENTER> to continue, 'C' to cancel)
transfer rate: 4.27 KB/sec(SESSION:
384494)
07/14/04 02:55:52 ANE4967I (Session: 384494, Node: HE2UNX108) Aggregate
data transfer rate: 3.20 KB/sec(SESSION:
384494)
07/14/04 02:55:52 ANE4968I (Session: 384494, Node: HE2UNX108) Objects
compressed by: 0%(SESSION: 384494)
07/14/04 02:55:52 ANE4964I (Session: 384494, Node: HE2UNX108) Elapsed
processing time: 00:41:50(SESSION: 384494)
07/14/04 02:55:52 ANR2507I Schedule HE2UNX108.2315.SOL.ANY for domain
SOL
started at 07/14/04 01:37:49 for node HE2UNX108
completed
successfully at 07/14/04 02:55:52. (SESSION: 384494)
07/14/04 02:55:53 ANR0403I Session 384494 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 384494)
07/14/04 02:55:53 ANR0406I Session 384704 started for node HE2UNX108
(SUN
SOLARIS) (Tcp/Ip he2unx108.fhlmc.com(60687)).
(SESSION:
384704)
07/14/04 02:55:53 ANR0403I Session 384704 ended for node HE2UNX108 (SUN
SOLARIS). (SESSION: 384704)
07/14/04 17:39:36 ANR2017I Administrator ADSMADMIN issued command:
UPDATE
SCHEDULE SOL HE2UNX108.2315.SOL.ANY startt=23:15:00
(SESSION: 388573)
07/14/04 17:39:36 ANR2502I Schedule HE2UNX108.2315.SOL.ANY updated in
policy
domain SOL. (SESSION: 388573)
more... (<ENTER> to continue, 'C' to cancel)
07/14/04 18:21:11 ANR2017I Administrator KATHLEEN issued command: QUERY
SCHEDULE sol he2unx108.2315.sol.any (SESSION:
389109)
"Andrew Raibeck"
<storman AT US DOT IBM.C To: ADSM-L AT
VM.MARIST DOT EDU
OM> cc:
Sent by: "ADSM: Subject: Re: Strange q ev output
Dist Stor
Manager"
<[email protected]
.EDU>
07/14/2004 08:58
PM
Please respond to
"ADSM: Dist Stor
Manager"
Kathleen,
Thanks for the info, I agree that this is very strange.
I'm wondering if QUERY EVENT is putting the actual start date in the
scheduled start date field. For example, given:
07/14/04 23:15:00 07/14/04 01:36:34 HE2UNX108.23- HE2UNX108 Completed
15.SOL.ANY
I wonder if it should be more like this:
07/13/04 23:15:00 07/14/04 01:36:34 HE2UNX108.23- HE2UNX108 Completed
15.SOL.ANY
(i.e. should the first column show 07/13/04 instead of 07/14/04).
Can you review your activity log for early morning today (14 July) and
check whether the timestamps in the ACTUAL START field coincide with the
activity log? For example, check to see if node E2UNX108 actualy started
its scheduled backup this morning at 1:36:34 AM this morning.
Alternatively, I don't see a future event for this schedule, just the
completed event. I'm also thinking that maybe the scheduled start time of
07/14/04 23:15:00 reflects the future event (tonight) and the actual start
time of 07/14/04 01:36:34 represent last night's event, and this record is
a "melding" of last night's and tonight's events.
Let us know what your activity log shows, and if those actual start times
synch up with this mornings activity log records.
Regards,
Andy
Andy Raibeck
IBM Software Group
Tivoli Storage Manager Client Development
Internal Notes e-mail: Andrew Raibeck/Tucson/IBM@IBMUS
Internet e-mail: storman AT us.ibm DOT com
The only dumb question is the one that goes unasked.
The command line is your friend.
"Good enough" is the enemy of excellence.
"ADSM: Dist Stor Manager" <ADSM-L AT VM.MARIST DOT EDU> wrote on 07/14/2004
15:24:58:
>
>
>
>
> Everything is below--thanks for looking at it!
>
> Kathleen
>
>
>
>
>
>
> "Andrew Raibeck"
> <storman AT US DOT IBM.C To: ADSM-L AT VM.MARIST
> DOT EDU
> OM> cc:
> Sent by: "ADSM: Subject: Re: Strange q
ev output
> Dist Stor
> Manager"
> <[email protected]
> .EDU>
>
>
> 07/14/2004 06:01
> PM
> Please respond to
> "ADSM: Dist Stor
> Manager"
>
>
>
>
>
>
> Curious. No, TSM is not psychic, as far as I know.
>
> Can you post the *complete* output from the following:
>
> 1) dsmadmc -id=youradmin -pa=xxxx q ev * *
>
> (See attached file: q.ev.zip)(this one is several hundred lines
long)
>
> 2) dsmadmc -id=youradmin -pa=xxxx q sch <domain> <schedname>
>
> Specify the domain and schedule name for one of the scheduled events
> showing the goofy times.
>
>
> Domain * Schedule Name Action Start Date/Time Duration
> Period Day
> ------------ - ---------------- ------ --------------------
--------
> ------ ---
> SOL HE2UNX108.2315.- Inc Bk 01/21/04 23:15:00 1
H
> 1 D Any
> SOL.ANY
>
>
> 3) dsmadmc -id=youradmin -pa=xxxx show time
>
> Current Date and Time on the Server
> ----------------------------------------
> 07/14/04 18:23:24
> UTC (GMT) Date/Time is: 07/14/04 22:23:24
> Last Noted Date/Time is: 07/14/04 18:09:34
>
> Regards,
>
> Andy
>
> Andy Raibeck
> IBM Software Group
> Tivoli Storage Manager Client Development
> Internal Notes e-mail: Andrew Raibeck/Tucson/IBM@IBMUS
> Internet e-mail: storman AT us.ibm DOT com
>
> The only dumb question is the one that goes unasked.
> The command line is your friend.
> "Good enough" is the enemy of excellence.
>
> "ADSM: Dist Stor Manager" <ADSM-L AT VM.MARIST DOT EDU> wrote on 07/14/2004
> 14:51:41:
>
> > We've been seeing this for some time now, and haven't really done
> anything
> > about it as it doesn't seem to affect actual backup success in any
way.
> > But it is rather odd, and it's appearing more frequently now. Running
a
> q
> > ev command at around 17:40 on 7/14 (in other words, just a few minutes
> ago)
> > brings up the following:
> >
> >
> >
> > 07/14/04 23:15:00 07/14/04 01:36:34 HE2UNX108.23- HE2UNX108
> > Completed
> > 15.SOL.ANY
> > 07/14/04 23:15:00 HE2UNX109.23- HE2UNX109
> > Future
> > 15.SOL.ANY
> > 07/14/04 23:15:00 07/14/04 01:36:25 HE2UNX111.23- HE2UNX111
> > Completed
> > 15.SOL.ANY
> > 07/14/04 23:15:00 07/14/04 01:36:29 HE2UNX112.23- HE2UNX112
> > Completed
> >
> > Is TSM psychic? How does it know that these events, which are
scheduled
> > for several hours in the future, will complete successfully? We're
> running
> > TSM 5.2.2.0 on AIX 5.2, but I also used to see this intermittently on
a
> 5.1
> > version of TSM on AIX 4.3.
> >
> > Has anyone ever seen this, or heard what causes it?
> >
> > Thanks,
> >
> > Kathleen
>
>
> [attachment "q.ev.zip" deleted by Andrew Raibeck/Tucson/IBM]
|
