I have seen this exact same problem. Running 5.1.1.0 server and 5.1.1.0 client. W2K platform. I have had this problem for weeks and weeks
I could not figure it out either.. Presumably a bug?? -----Original Message----- From: PAC Brion Arnaud [mailto:[EMAIL PROTECTED]] Sent: 18 February 2003 13:02 To: [EMAIL PROTECTED] Subject: ANR2576W An attempt was made to update an event record for a scheduled operation which has already been executed 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 | =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=