ADSM-L

ANR2576W An attempt was made to update an event record for a scheduled operation which has already been executed

2003-02-18 08:02:44
Subject: ANR2576W An attempt was made to update an event record for a scheduled operation which has already been executed
From: PAC Brion Arnaud <Arnaud.Brion AT PANALPINA DOT COM>
To: ADSM-L AT VM.MARIST DOT EDU
Date: Tue, 18 Feb 2003 14:01:50 +0100
Hi list !

Could someone help me with that one : I get a client node (win2k) for
which TSM reports following message every night :

02/18/03 03:29:01 ANR2576W An attempt was made to update an event record
for a scheduled operation which has already been executed - multiple
client schedulers may be active for node PAC2K340. 

I'm certain that no multiple schedulers are started on this node, but
from my analyse of the logs, I believe that, as soon as the node has
finished it's backup, the session hangs, due to network problem, and
when restarted becomes the same schedule again, and repeats the work.
Some logs, to make it clearer :

TSM activity log :

18.02.2003 00:32:06  ANR2561I Schedule prompter contacting PAC2K340
(session
                      1369418) to start a scheduled operation.
18.02.2003 00:32:10  ANR0406I Session 1369423 started for node PAC2K340
(WinNT)
                      (Tcp/Ip xxx.xxx.xxx.xxx(1401)).
18.02.2003 00:37:35  ANR0406I Session 1369771 started for node PAC2K340
(WinNT)
                      (Tcp/Ip xxx.xxx.xxx.xxx(1405)).
18.02.2003 00:40:41  ANE4987E (Session: 1369771, Node: PAC2K340)  Error
                      processing 'xxxxxx': the object is in use
                      by another process

... skipped blah-blah

18.02.2003 01:03:14  ANR0482W Session 1369423 for node PAC2K340 (WinNT)
                      terminated - idle for more than 15 minutes.
18.02.2003 01:13:47  ANR0406I Session 1371466 started for node PAC2K340
(WinNT)
                      (Tcp/Ip xxx.xxx.xxx.xxx(1423)).
18.02.2003 01:29:12  ANR0482W Session 1371466 for node PAC2K340 (WinNT)
                      terminated - idle for more than 15 minutes.
18.02.2003 01:32:54  ANR0406I Session 1372430 started for node PAC2K340
(WinNT)
                      (Tcp/Ip xxx.xxx.xxx.xxx(1430)).
18.02.2003 01:48:50  ANE4952I (Session: 1372430, Node: PAC2K340)  Total
number
                      of objects inspected:   26,680
18.02.2003 01:48:50  ANE4954I (Session: 1372430, Node: PAC2K340)  Total
number
                      of objects backed up:    2,255
18.02.2003 01:48:50  ANE4958I (Session: 1372430, Node: PAC2K340)  Total
number
                      of objects updated:          2
18.02.2003 01:48:50  ANE4960I (Session: 1372430, Node: PAC2K340)  Total
number
                      of objects rebound:          0
18.02.2003 01:48:50  ANE4957I (Session: 1372430, Node: PAC2K340)  Total
number
                      of objects deleted:          0
18.02.2003 01:48:50  ANE4970I (Session: 1372430, Node: PAC2K340)  Total
number
                      of objects expired:      1,207
18.02.2003 01:48:50  ANE4959I (Session: 1372430, Node: PAC2K340)  Total
number
                      of objects failed:          11
18.02.2003 01:48:50  ANE4961I (Session: 1372430, Node: PAC2K340)  Total
number
                      of bytes transferred:     1.72 GB
18.02.2003 01:48:50  ANE4963I (Session: 1372430, Node: PAC2K340)  Data
transfer
                      time:                2,994.31 sec
18.02.2003 01:48:50  ANE4966I (Session: 1372430, Node: PAC2K340)
Network data
                      transfer rate:          603.65 KB/sec
18.02.2003 01:48:50  ANE4967I (Session: 1372430, Node: PAC2K340)
Aggregate
                      data transfer rate:        392.95 KB/sec
18.02.2003 01:48:50  ANE4968I (Session: 1372430, Node: PAC2K340)
Objects
                      compressed by:                    6%
18.02.2003 01:48:50  ANE4964I (Session: 1372430, Node: PAC2K340)
Elapsed
                      processing time:            00:03:39
18.02.2003 01:48:53  ANR0403I Session 1369771 ended for node PAC2K340
(WinNT).
18.02.2003 02:25:35  ANR0406I Session 1374418 started for node PAC2K340
(WinNT)
                      (Tcp/Ip xxx.xxx.xxx.xxx(1083)).
18.02.2003 02:26:09  ANR0406I Session 1374443 started for node PAC2K340
(WinNT)
                      (Tcp/Ip xxx.xxx.xxx.xxx(1101)).

...skipped blah-blah

18.02.2003 02:29:53  ANE4952I (Session: 1374418, Node: PAC2K340)  Total
number
                      of objects inspected:   26,666
18.02.2003 02:29:53  ANE4954I (Session: 1374418, Node: PAC2K340)  Total
number
                      of objects backed up:    2,078
18.02.2003 02:29:53  ANE4958I (Session: 1374418, Node: PAC2K340)  Total
number
                      of objects updated:          3
18.02.2003 02:29:53  ANE4960I (Session: 1374418, Node: PAC2K340)  Total
number
                      of objects rebound:          0
18.02.2003 02:29:53  ANE4957I (Session: 1374418, Node: PAC2K340)  Total
number
                      of objects deleted:          0
18.02.2003 02:29:53  ANE4970I (Session: 1374418, Node: PAC2K340)  Total
number
                      of objects expired:          3
18.02.2003 02:29:53  ANE4959I (Session: 1374418, Node: PAC2K340)  Total
number
                      of objects failed:           9
18.02.2003 02:29:53  ANE4961I (Session: 1374418, Node: PAC2K340)  Total
number
                      of bytes transferred:   153.77 MB
18.02.2003 02:29:53  ANE4963I (Session: 1374418, Node: PAC2K340)  Data
transfer
                      time:                   13.58 sec
18.02.2003 02:29:53  ANE4966I (Session: 1374418, Node: PAC2K340)
Network data
                      transfer rate:        11,594.00 KB/sec
18.02.2003 02:29:53  ANE4967I (Session: 1374418, Node: PAC2K340)
Aggregate
                      data transfer rate:        612.87 KB/sec
18.02.2003 02:29:53  ANE4968I (Session: 1374418, Node: PAC2K340)
Objects
                      compressed by:                   39%
18.02.2003 02:29:53  ANE4964I (Session: 1374418, Node: PAC2K340)
Elapsed
                      processing time:            00:00:16
18.02.2003 02:29:58  ANR0403I Session 1374443 ended for node PAC2K340
(WinNT).
18.02.2003 02:30:00  ANR2507I Schedule BACKUP_NT for domain NT started
at
                      02/18/03 00:30:00 for node PAC2K340 completed
                      successfully at 02/18/03 02:30:00.
18.02.2003 02:30:00  ANR0403I Session 1374418 ended for node PAC2K340
(WinNT).
18.02.2003 02:30:08  ANR0406I Session 1374618 started for node PAC2K340
(WinNT)
                      (Tcp/Ip xxx.xxx.xxx.xxx(1137)).
18.02.2003 02:30:09  ANR0403I Session 1374618 ended for node PAC2K340
(WinNT).
18.02.2003 03:29:01  ANR2507I Schedule BACKUP_NT for domain NT started
at
                      02/18/03 00:30:00 for node PAC2K340 completed
                      successfully at 02/18/03 03:29:01.
18.02.2003 03:29:01  ANR2576W An attempt was made to update an event
record for
                      a scheduled operation which has already been
executed -
                      multiple client schedulers may be active for node
                      PAC2K340.

On node's side :

Dsmsched.log :

02/18/2003 00:32:09 TCP/IP accepted connection from server.
02/18/2003 00:32:09 Querying server for next scheduled event.
02/18/2003 00:32:09 Node Name: PAC2K340
02/18/2003 00:32:11 Session established with server ADSM-PAC:
AIX-RS/6000
02/18/2003 00:32:11   Server Version 4, Release 2, Level 3.1
02/18/2003 00:32:11   Server date/time: 02/18/2003 00:32:07  Last
access: 02/17/2003 16:57:23

02/18/2003 00:32:11 --- SCHEDULEREC QUERY BEGIN
02/18/2003 00:32:11 --- SCHEDULEREC QUERY END
02/18/2003 00:32:11 Next operation scheduled:
02/18/2003 00:32:11
------------------------------------------------------------
02/18/2003 00:32:11 Schedule Name:         BACKUP_NT
02/18/2003 00:32:11 Action:                Incremental
02/18/2003 00:32:11 Objects:               
02/18/2003 00:32:11 Options:               
02/18/2003 00:32:11 Server Window Start:   00:30:00 on 02/18/2003
02/18/2003 00:32:11
------------------------------------------------------------
02/18/2003 00:32:11 
Executing scheduled command now.
02/18/2003 00:32:11 --- SCHEDULEREC OBJECT BEGIN BACKUP_NT 02/18/2003
00:30:00
02/18/2003 00:32:11 Incremental backup of volume 'xxx'
02/18/2003 00:32:11 Incremental backup of volume 'xxx'

.... Skipped blah-blah

02/18/2003 00:47:33 ANS1898I ***** Processed    24,500 files *****
02/18/2003 01:13:30 Normal File-->       341,997,349 xxxxx [Sent]      
02/18/2003 01:13:31 ANS1809E Session is lost; initializing session
reopen procedure.
02/18/2003 01:13:48 ... successful
02/18/2003 01:13:48 Preparing System Object -> COM+ DatabaseNormal
File-->       341,960,712 xxxxx [Sent]      
02/18/2003 01:32:36 ANS1809E Session is lost; initializing session
reopen procedure.
02/18/2003 01:32:56 ... successful
02/18/2003 01:40:12 Normal File-->       432,281,071 xxxxx [Sent]  
  
.... Skipped blah-blah

02/18/2003 01:48:51 Successful incremental backup of 'RSM Database'

02/18/2003 01:48:51 --- SCHEDULEREC STATUS BEGIN
02/18/2003 01:48:51 Total number of objects inspected:   26,680
02/18/2003 01:48:51 Total number of objects backed up:    2,255
02/18/2003 01:48:51 Total number of objects updated:          2
02/18/2003 01:48:51 Total number of objects rebound:          0
02/18/2003 01:48:51 Total number of objects deleted:          0
02/18/2003 01:48:51 Total number of objects expired:      1,207
02/18/2003 01:48:51 Total number of objects failed:          11
02/18/2003 01:48:51 Total number of bytes transferred:     1.72 GB
02/18/2003 01:48:51 Data transfer time:                2,994.31 sec
02/18/2003 01:48:51 Network data transfer rate:          603.65 KB/sec
02/18/2003 01:48:51 Aggregate data transfer rate:        392.95 KB/sec
02/18/2003 01:48:51 Objects compressed by:                    6%
02/18/2003 01:48:51 Elapsed processing time:           00:03:39
02/18/2003 01:48:51 --- SCHEDULEREC STATUS END
02/18/2003 01:48:51 --- SCHEDULEREC OBJECT END BACKUP_NT 02/18/2003
00:30:00
02/18/2003 01:48:51 Scheduled event 'BACKUP_NT' completed successfully.
02/18/2003 01:48:51 Sending results for scheduled event 'BACKUP_NT'.
02/18/2003 02:22:31 

>>>>>> Process Interrupted!!  Severing connection. <<<<<<
02/18/2003 02:22:32 Will attempt to send results for BACKUP_NT again in
1 hour.
02/18/2003 02:25:34 Querying server for next scheduled event.
02/18/2003 02:25:34 Node Name: PAC2K340
02/18/2003 02:25:36 Session established with server ADSM-PAC:
AIX-RS/6000
02/18/2003 02:25:36   Server Version 4, Release 2, Level 3.1
02/18/2003 02:25:36   Server date/time: 02/18/2003 02:25:33  Last
access: 02/18/2003 01:32:54

02/18/2003 02:25:36 --- SCHEDULEREC QUERY BEGIN
02/18/2003 02:25:36 --- SCHEDULEREC QUERY END
02/18/2003 02:25:36 Next operation scheduled:
02/18/2003 02:25:36
------------------------------------------------------------
02/18/2003 02:25:36 Schedule Name:         BACKUP_NT
02/18/2003 02:25:36 Action:                Incremental
02/18/2003 02:25:36 Objects:               
02/18/2003 02:25:36 Options:               
02/18/2003 02:25:36 Server Window Start:   00:30:00 on 02/18/2003
02/18/2003 02:25:36
------------------------------------------------------------
02/18/2003 02:25:36 
Executing scheduled command now.
02/18/2003 02:25:37 --- SCHEDULEREC OBJECT BEGIN BACKUP_NT 02/18/2003
00:30:00
02/18/2003 02:25:37 Incremental backup of volume 'xxxx'

...skipped blah-blah

02/18/2003 02:29:54 Successful incremental backup of 'RSM Database'

02/18/2003 02:29:54 --- SCHEDULEREC STATUS BEGIN
02/18/2003 02:29:54 Total number of objects inspected:   26,666
02/18/2003 02:29:54 Total number of objects backed up:    2,078
02/18/2003 02:29:54 Total number of objects updated:          3
02/18/2003 02:29:54 Total number of objects rebound:          0
02/18/2003 02:29:54 Total number of objects deleted:          0
02/18/2003 02:29:54 Total number of objects expired:          3
02/18/2003 02:29:54 Total number of objects failed:           9
02/18/2003 02:29:54 Total number of bytes transferred:   153.77 MB
02/18/2003 02:29:54 Data transfer time:                   13.58 sec
02/18/2003 02:29:54 Network data transfer rate:        11,594.00 KB/sec
02/18/2003 02:29:54 Aggregate data transfer rate:        612.87 KB/sec
02/18/2003 02:29:54 Objects compressed by:                   39%
02/18/2003 02:29:54 Elapsed processing time:           00:00:16
02/18/2003 02:29:54 --- SCHEDULEREC STATUS END
02/18/2003 02:29:54 --- SCHEDULEREC OBJECT END BACKUP_NT 02/18/2003
00:30:00
02/18/2003 02:29:54 Scheduled event 'BACKUP_NT' completed successfully.
02/18/2003 02:29:54 Sending results for scheduled event 'BACKUP_NT'.
02/18/2003 02:30:01 Results sent to server for scheduled event
'BACKUP_NT'.

02/18/2003 02:30:01 ANS1483I Schedule log pruning started.
02/18/2003 02:30:05 Schedule Log Prune: 27089 lines processed.  2352
lines pruned.
02/18/2003 02:30:05 ANS1484I Schedule log pruning finished successfully.
02/18/2003 02:30:05 Querying server for next scheduled event.
02/18/2003 02:30:05 Node Name: PAC2K340
02/18/2003 02:30:10 Session established with server ADSM-PAC:
AIX-RS/6000
02/18/2003 02:30:10   Server Version 4, Release 2, Level 3.1
02/18/2003 02:30:10   Server date/time: 02/18/2003 02:30:04  Last
access: 02/18/2003 02:26:09

02/18/2003 02:30:10 --- SCHEDULEREC QUERY BEGIN
02/18/2003 02:30:10 --- SCHEDULEREC QUERY END
02/18/2003 02:30:10 Next operation scheduled:
02/18/2003 02:30:10
------------------------------------------------------------
02/18/2003 02:30:10 Schedule Name:         BACKUP_NT
02/18/2003 02:30:10 Action:                Incremental
02/18/2003 02:30:10 Objects:               
02/18/2003 02:30:10 Options:               
02/18/2003 02:30:10 Server Window Start:   00:30:00 on 02/19/2003
02/18/2003 02:30:10
------------------------------------------------------------
02/18/2003 02:30:10 Waiting to be contacted by the server.  

Dsmerror.log :

02/18/2003 01:13:31 TcpRead(): recv(): errno = 10053
02/18/2003 01:13:31 sessRecvVerb: Error -50 from call to 'readRtn'.
02/18/2003 01:13:31 ANS1809E Session is lost; initializing session
reopen procedure.
02/18/2003 01:13:31 ANS1809E Session is lost; initializing session
reopen procedure.
02/18/2003 01:13:48 ANS1810E TSM session has been reestablished.
02/18/2003 01:32:35 TcpRead(): recv(): errno = 10053
02/18/2003 01:32:35 sessRecvVerb: Error -50 from call to 'readRtn'.
02/18/2003 01:32:35 ANS1809E Session is lost; initializing session
reopen procedure.
02/18/2003 01:32:36 ANS1809E Session is lost; initializing session
reopen procedure.
02/18/2003 01:32:55 ANS1810E TSM session has been reestablished.
02/18/2003 01:41:02 ANS1115W File 'xxxxx' excluded by Include/Exclude
list
02/18/2003 01:41:02 ANS1115W File 'xxxxx' excluded by Include/Exclude
list
02/18/2003 01:41:02 ANS1115W File 'xxxxx' excluded by Include/Exclude
list
02/18/2003 01:41:02 ANS1115W File 'xxxxx' excluded by Include/Exclude
list
02/18/2003 01:41:03 ANS1115W File 'xxxxx' excluded by Include/Exclude
list
02/18/2003 02:22:31 ConsoleEventHandler(): Caught Shutdown console event
.
02/18/2003 02:22:31 ConsoleEventHandler(): Cleaning up and terminating
Process ...
02/18/2003 02:22:31 Error 6 killing thread 1268.
02/18/2003 02:22:31 ConsoleEventHandler(): Caught Shutdown console event
.
02/18/2003 02:22:31 ConsoleEventHandler(): Cleaning up and terminating
Process ...
02/18/2003 02:22:32 TcpRead(): recv(): errno = 10053
02/18/2003 02:22:32 sessRecvVerb: Error -50 from call to 'readRtn'.
02/18/2003 02:22:32 SendSchedResult: Received rc: -50 trying to receive
ConfirmResp verb

On server side the schedule looks like this :
NT BACKUP_NT Inc Bk 08/04/00 00:30:00 3 H 1 D Any

Did anyone face this kind of problem before, and if yes, how did you
troubleshoot it ?
Thanks in advance !
Arnaud
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
| Arnaud Brion, Panalpina Management Ltd., IT Group     |
| Viaduktstrasse 42, P.O. Box, 4002 Basel - Switzerland |
| Phone: +41 61 226 19 78 / Fax: +41 61 226 17 01       | 
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=

<Prev in Thread] Current Thread [Next in Thread>
  • ANR2576W An attempt was made to update an event record for a scheduled operation which has already been executed, PAC Brion Arnaud <=