Re: Strange q ev output
OK, which situation are we speaking of? If you are hitting MAXSCHEDSESSIONS limit, then the ANR2571W messages are appropriate (at least from what little I know of your setup). About the QUERY EVENT results; yes, those definitely don't look right. Some observations: - At 00:15:01 message ANR2578W is written indicating that the node missed its scheduled backup startup window. This should cause the scheduled start time to roll forward to 07/14/2004 23:15. - At 01:16:55 message ANR0482W is issued for session 383155. This session apparently started at 23:16-ish, two hours before. Back up your activity log review to include messages from the orignial scheduled start time of 07/13/2004 23:15. - At 01:36:34 session 384075 starts, apparently running a backup. How this could be, I do not know if we missed the startup window. Yet later on, we do get a message saying that the scheduled event ran successfully. Also note that this is the time that QUERY EVENT shows for actual start. - At 01:37:49 admin THIRD updates the schedule for this node. To me, this should cause the scheduled start time for this event to be 07/14/2004 01:37:49, yet subsequent QUERY EVENT shows it as 07/14/2004 23:15. Why that is, I do not know maybe the schedule record is somehow locked because a scheduled session (384075) is running? I do not have in-depth knowledge to answer this. It would appear that you only queried the activity log for messages containing this node name. Can you check the entire log for any other error messages that might have been issued around this time frame (including but not limited to ANRD)? - At 02:14:01 session 384075 ends. - At 02:14:02 message ANR2507I is issued indicating that the scheduled backup ran successfully. - At 02:14:02 session 384494 begins for this node. I think it is trying to run a scheduled event, but that is just a guess. - At 02:23:39 session 384574 begins for this node. - At 02:55:51 session 384574 ends. - At 02:55:52 session 384494 ends. - At 02:55:52 message ANR2507I is issued indicating that the scheduled backup ran successfully. This should cause QUERY EVENT to show an actual start time of 02:14:02, but why it's not there, I do not know. Again, look for messages around this timeframe that don't contain the node name to see if any other error messages might exist. Unfortunately in this informal forum, it is difficult for me to go into greater analytical depth with this problem, but something definitely doesn't seem right. You are on the right track in looking back at the activity log. As I said above, I suggest you review the entire log from 07/13/2004 23:15 and make notes of the sequence of events related to this node. Don't limit your search to just messages containing the node name, as you might miss out on some other server error messages. Also take a look at this node's dsmsched.log, dsmerror.log, and dsmwebcl.log files to help piece the sequence together. There is something odd going on here, but performing analysis like I've started above is a good step towards better understanding what might be going on. Ultimately you might need to open a problem with IBM technical support. Regards, Andy Andy Raibeck IBM Software Group Tivoli Storage Manager Client Development Internal Notes e-mail: Andrew Raibeck/Tucson/[EMAIL PROTECTED] Internet e-mail: [EMAIL PROTECTED] 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" <[EMAIL PROTECTED]> wrote on 07/15/2004 10:41:56: > I had noticed that the maximum sessions threshold had been hit, and I can > see that there is a correlation there. However, if the MAXSCHEDSESSIONS > parameter is working as designed and limiting the number of sessions, > wouldn't this effect essentialy be a bug? I can't imagine that this would > be an intended consequence of that situation occurring. I'm going to raise > the threshold for the moment and see what happens over the next couple of > days, but it appears to be more of a workaround than a solution. In > addition, we have been running on this TSM server since late January, and > have only been seeing the problem in our Solaris environment recently as > described below. Could there be some strange interrelationship between the > server and the V5 client code, the optionset, or the dsmcad to create this > situation? Those are the things that have been changed in that environment > recently. > > Thanks for your help! > > Kathleen > > > > > "Andrew Raibeck" > <[EMAIL PROTECTED] To: [EMAIL PROTECTED] > OM> cc: > Sent by: "ADSM: Subject: Re: Strange q ev output > Dist Stor &g
Re: Strange q ev output
I had noticed that the maximum sessions threshold had been hit, and I can see that there is a correlation there. However, if the MAXSCHEDSESSIONS parameter is working as designed and limiting the number of sessions, wouldn't this effect essentialy be a bug? I can't imagine that this would be an intended consequence of that situation occurring. I'm going to raise the threshold for the moment and see what happens over the next couple of days, but it appears to be more of a workaround than a solution. In addition, we have been running on this TSM server since late January, and have only been seeing the problem in our Solaris environment recently as described below. Could there be some strange interrelationship between the server and the V5 client code, the optionset, or the dsmcad to create this situation? Those are the things that have been changed in that environment recently. Thanks for your help! Kathleen "Andrew Raibeck" <[EMAIL PROTECTED]To: [EMAIL PROTECTED] OM> cc: Sent by: "ADSM: Subject: Re: Strange q ev output Dist Stor Manager" <[EMAIL PROTECTED] .EDU> 07/15/2004 12:39 PM Please respond to "ADSM: Dist Stor Manager" Kathleen, Have you taken a look at the ANR2571W message? That may be a key to this. Do "HELP ANR2571W" from the Admin CLI for info on this message, as it suggests some corrective actions you can take. Regards, Andy Andy Raibeck IBM Software Group Tivoli Storage Manager Client Development Internal Notes e-mail: Andrew Raibeck/Tucson/[EMAIL PROTECTED] Internet e-mail: [EMAIL PROTECTED] 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" <[EMAIL PROTECTED]> wrote on 07/15/2004 08:17:43: > 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/TimeMessage > > -- > 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) [snip for brevity]
Re: Strange q ev output
Kathleen, Have you taken a look at the ANR2571W message? That may be a key to this. Do "HELP ANR2571W" from the Admin CLI for info on this message, as it suggests some corrective actions you can take. Regards, Andy Andy Raibeck IBM Software Group Tivoli Storage Manager Client Development Internal Notes e-mail: Andrew Raibeck/Tucson/[EMAIL PROTECTED] Internet e-mail: [EMAIL PROTECTED] 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" <[EMAIL PROTECTED]> wrote on 07/15/2004 08:17:43: > 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/TimeMessage > > -- > 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) [snip for brevity]
Re: Strange q ev output
... ( 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" <[EMAIL PROTECTED]To: [EMAIL PROTECTED] 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/[EMAIL PROTECTED] Internet e-mail: [EMAIL PROTECTED] 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" <[EMAIL PROTECTED]> wrote on 07/14/2004 15:24:58: > > > > > Everything is below--thanks for looking at it! > > Kathleen > > > > > > > "Andrew Raibeck" > <[EMAIL PROTECTED]To: [EMAIL PROTECTED] > 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= q ev * * > > (See attached file: q.ev.zip)(this one is several hundred lines long) > > 2) dsmadmc -id=youradmin -pa= q sch > > Specify the domain and schedule name for one of the scheduled events > showing the goofy times. > > > Domain * Schedule NameAction Start Date/Time Duration > Period Day > - -- > -- --- > SOLHE2UNX108.2315.- Inc Bk 01/21/04 23:15:00 1 H > 1 D Any > SOL.ANY > > > 3) dsmadmc -id=youradmin -pa= 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/[EMAIL PROTECTED] > Internet e-mail: [EMAIL PROTECTED] > > 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" <[EMAIL PROTECTED]> wrote on 07/14/2004 > 14:51:41: > > > We've been seeing this for some time now, and haven't r
Re: Strange q ev output
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/[EMAIL PROTECTED] Internet e-mail: [EMAIL PROTECTED] 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" <[EMAIL PROTECTED]> wrote on 07/14/2004 15:24:58: > > > > > Everything is below--thanks for looking at it! > > Kathleen > > > > > > > "Andrew Raibeck" > <[EMAIL PROTECTED]To: [EMAIL PROTECTED] > 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= q ev * * > > (See attached file: q.ev.zip)(this one is several hundred lines long) > > 2) dsmadmc -id=youradmin -pa= q sch > > Specify the domain and schedule name for one of the scheduled events > showing the goofy times. > > > Domain * Schedule NameAction Start Date/Time Duration > Period Day > - -- > -- --- > SOLHE2UNX108.2315.- Inc Bk 01/21/04 23:15:00 1 H > 1 D Any > SOL.ANY > > > 3) dsmadmc -id=youradmin -pa= 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/[EMAIL PROTECTED] > Internet e-mail: [EMAIL PROTECTED] > > 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" <[EMAIL PROTECTED]> 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 > >
Re: Strange q ev output
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= q ev * * 2) dsmadmc -id=youradmin -pa= q sch Specify the domain and schedule name for one of the scheduled events showing the goofy times. 3) dsmadmc -id=youradmin -pa= show time Regards, Andy Andy Raibeck IBM Software Group Tivoli Storage Manager Client Development Internal Notes e-mail: Andrew Raibeck/Tucson/[EMAIL PROTECTED] Internet e-mail: [EMAIL PROTECTED] 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" <[EMAIL PROTECTED]> 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
Strange q ev output
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
