CAD service logging repeatedly during backups?

PREDATAR Control23

When you said you upgraded the server to 8.1, do you mean the Windows server that has the client, or the actual TSM Server? If the latter, upgrade the client as per:
Check dsmwebcl.log, just in case there are errors reported for CAD which would cause it to keep waking up the scheduler.

Also, it would be worth while to upgrade that client to 7.1.6 (or 8.1.0), just in case it's a defect. It would also bring you back into a support release.
And check the dsmwebcl.log as well to see what CAD is doing.
 
PREDATAR Control23

OK I think I may have figured it out, but I wont know for sure till the backups run tonight.
I set schedmode to ANY on server, noticed the client logs said it was not allowing a prompted backup. Which is odd because the old server I am migrating from had schedmode set any.
I changed server to schedulemode prompted and I saw the constant communications fall off the actlog and the cad services with the problem stop.

Strange.
 
PREDATAR Control23

well this is weird, setting it to prompted seemed to fix it, but as soon as the backup kicked off last night I get the issue again

The actlog looks like this from the moment it kicks off a backup (backup completes successfully) till about 8am


x86-64) (Tcp/Ip NODENAME.domain.com(40548)). (SESSION: 89804)
06/19/2017 23:25:07 ANR0403I Session 89804 ended for node NODENAME (Linux
x86-64). (SESSION: 89804)
06/19/2017 23:25:38 ANR0406I Session 89807 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40550)). (SESSION: 89807)
06/19/2017 23:25:38 ANR0403I Session 89807 ended for node NODENAME (Linux
x86-64). (SESSION: 89807)
06/19/2017 23:26:10 ANR0406I Session 89810 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40552)). (SESSION: 89810)
06/19/2017 23:26:10 ANR0403I Session 89810 ended for node NODENAME (Linux
x86-64). (SESSION: 89810)
06/19/2017 23:26:51 ANR0406I Session 89815 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40554)). (SESSION: 89815)
06/19/2017 23:26:51 ANR0403I Session 89815 ended for node NODENAME (Linux
x86-64). (SESSION: 89815)
06/19/2017 23:27:22 ANR0406I Session 89817 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40556)). (SESSION: 89817)
06/19/2017 23:27:22 ANR0403I Session 89817 ended for node NODENAME (Linux
x86-64). (SESSION: 89817)
06/19/2017 23:27:53 ANR0406I Session 89822 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40558)). (SESSION: 89822)
06/19/2017 23:27:53 ANR0403I Session 89822 ended for node NODENAME (Linux
x86-64). (SESSION: 89822)
06/19/2017 23:28:25 ANR0406I Session 89826 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40562)). (SESSION: 89826)
06/19/2017 23:28:25 ANR0403I Session 89826 ended for node NODENAME (Linux
x86-64). (SESSION: 89826)
06/19/2017 23:28:56 ANR0406I Session 89830 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40564)). (SESSION: 89830)
06/19/2017 23:28:56 ANR0403I Session 89830 ended for node NODENAME (Linux
x86-64). (SESSION: 89830)
06/19/2017 23:29:27 ANR0406I Session 89834 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40566)). (SESSION: 89834)
06/19/2017 23:29:27 ANR0403I Session 89834 ended for node NODENAME (Linux
x86-64). (SESSION: 89834)
06/19/2017 23:30:08 ANR0406I Session 89839 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40580)). (SESSION: 89839)
06/19/2017 23:30:08 ANR0403I Session 89839 ended for node NODENAME (Linux
x86-64). (SESSION: 89839)
06/19/2017 23:30:40 ANR0406I Session 89843 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40582)). (SESSION: 89843)
06/19/2017 23:30:40 ANR0403I Session 89843 ended for node NODENAME (Linux
x86-64). (SESSION: 89843)
06/19/2017 23:31:11 ANR0406I Session 89850 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40584)). (SESSION: 89850)
06/19/2017 23:31:11 ANR0403I Session 89850 ended for node NODENAME (Linux
x86-64). (SESSION: 89850)
06/19/2017 23:31:42 ANR0406I Session 89854 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40586)). (SESSION: 89854)
06/19/2017 23:31:42 ANR0403I Session 89854 ended for node NODENAME (Linux
x86-64). (SESSION: 89854)
06/19/2017 23:32:14 ANR0406I Session 89857 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40588)). (SESSION: 89857)
06/19/2017 23:32:14 ANR0403I Session 89857 ended for node NODENAME (Linux
x86-64). (SESSION: 89857)
06/19/2017 23:32:55 ANR0406I Session 89862 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40590)). (SESSION: 89862)
06/19/2017 23:32:55 ANR0403I Session 89862 ended for node NODENAME (Linux
x86-64). (SESSION: 89862)
06/19/2017 23:33:26 ANR0406I Session 89865 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40592)). (SESSION: 89865)
06/19/2017 23:33:26 ANR0403I Session 89865 ended for node NODENAME (Linux
x86-64). (SESSION: 89865)
06/19/2017 23:33:57 ANR0406I Session 89868 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40594)). (SESSION: 89868)
06/19/2017 23:33:57 ANR0403I Session 89868 ended for node NODENAME (Linux
x86-64). (SESSION: 89868)
06/19/2017 23:34:29 ANR0406I Session 89871 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40596)). (SESSION: 89871)
06/19/2017 23:34:29 ANR0403I Session 89871 ended for node NODENAME (Linux
x86-64). (SESSION: 89871)
06/19/2017 23:35:00 ANR0406I Session 89875 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40598)). (SESSION: 89875)
06/19/2017 23:35:00 ANR0403I Session 89875 ended for node NODENAME (Linux
x86-64). (SESSION: 89875)
06/19/2017 23:35:31 ANR0406I Session 89879 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40612)). (SESSION: 89879)
06/19/2017 23:35:31 ANR0403I Session 89879 ended for node NODENAME (Linux
x86-64). (SESSION: 89879)
06/19/2017 23:36:12 ANR0406I Session 89883 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40614)). (SESSION: 89883)
06/19/2017 23:36:12 ANR0403I Session 89883 ended for node NODENAME (Linux
x86-64). (SESSION: 89883)
06/19/2017 23:36:44 ANR0406I Session 89886 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40616)). (SESSION: 89886)
06/19/2017 23:36:44 ANR0403I Session 89886 ended for node NODENAME (Linux
x86-64). (SESSION: 89886)
06/19/2017 23:37:15 ANR0406I Session 89890 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40618)). (SESSION: 89890)
06/19/2017 23:37:15 ANR0403I Session 89890 ended for node NODENAME (Linux
x86-64). (SESSION: 89890)
06/19/2017 23:37:46 ANR0406I Session 89893 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40620)). (SESSION: 89893)
06/19/2017 23:37:46 ANR0403I Session 89893 ended for node NODENAME (Linux
x86-64). (SESSION: 89893)
06/19/2017 23:38:17 ANR0406I Session 89896 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40622)). (SESSION: 89896)
06/19/2017 23:38:17 ANR0403I Session 89896 ended for node NODENAME (Linux
x86-64). (SESSION: 89896)
06/19/2017 23:38:59 ANR0406I Session 89900 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40628)). (SESSION: 89900)
06/19/2017 23:38:59 ANR0403I Session 89900 ended for node NODENAME (Linux
x86-64). (SESSION: 89900)
06/19/2017 23:39:30 ANR0406I Session 89903 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40630)). (SESSION: 89903)
06/19/2017 23:39:30 ANR0403I Session 89903 ended for node NODENAME (Linux
x86-64). (SESSION: 89903)
06/19/2017 23:40:01 ANR0406I Session 89906 started for node NODENAME (Linux
x86-64) (Tcp/Ip NODENAME.domain.com(40644)). (SESSION: 89906)
06/19/2017 23:40:01 ANR0403I Session 89906 ended for node NODENAME (Linux .....


I can only assume this is something on the server, as the TSM server as that is the only part that has changed in this configuration.
I tried to update the client and it started backing up NFS shares for some reason, even tho the dsm.sys clearly says DOMAIN ALL-LOCAL so the customer wanted to revert back to the known good client.

Any thoughts ? Its like the client isn't getting the reply back it is requesting and just initiates another session but I have no idea what its looking for as it does have the schedule and the backup is working
 
PREDATAR Control23

dsm.sys file for one of the nodes doing this


SErvername SERVERNAME


TXNBYTELIMIT 50176K 

PASSWORDACCESS GENERATE 

TCPBUFFSIZE 64 

NODENAME NODENAME 

COMMmethod TCPip 

TCPPORT 1500 

TCPCLIENTADDRESS xxx.xx.xx.xxx

TCPCLIENTPORT 1501 

TCPServeraddress NEW SERVERNAME

PASSWORDAccess generate 

SCHEDMODE PRompted 

HTTPport 1581 

SCHEDLOGRetention N 

ERRORLOGRetention 60 D 

MANAGEDSERVICES schedule webclient 

WEBPORTS 2123 2124 

INCLEXCL "/opt/tivoli/tsm/client/ba/bin/dsm_exclude_files.excl"
 
PREDATAR Control23

Don't see any errors in dsmwebcl.log just it repeating this session over and over
 
PREDATAR Control23

Its full of this

06/19/2017 14:43:19 (dsmcad) Next operation scheduled:
06/19/2017 14:43:19 (dsmcad) ------------------------------------------------------------
06/19/2017 14:43:19 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 14:43:19 (dsmcad) Action: Incremental
06/19/2017 14:43:19 (dsmcad) Objects:
06/19/2017 14:43:19 (dsmcad) Options:
06/19/2017 14:43:19 (dsmcad) Server Window Start: 19:00:00 on 06/19/2017
06/19/2017 14:43:19 (dsmcad) ------------------------------------------------------------
06/19/2017 14:43:19 (dsmcad) Waiting to be contacted by the server.
06/19/2017 19:00:15 (dsmcad) Executing scheduled command now.
06/19/2017 19:03:27 (dsmcad) Next operation scheduled:
06/19/2017 19:03:27 (dsmcad) ------------------------------------------------------------
06/19/2017 19:03:27 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 19:03:27 (dsmcad) Action: Incremental
06/19/2017 19:03:27 (dsmcad) Objects:
06/19/2017 19:03:27 (dsmcad) Options:
06/19/2017 19:03:27 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 19:03:27 (dsmcad) ------------------------------------------------------------
06/19/2017 19:03:27 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:10:17 (dsmcad) Executing scheduled command now.
06/19/2017 22:10:23 (dsmcad) Next operation scheduled:
06/19/2017 22:10:23 (dsmcad) ------------------------------------------------------------
06/19/2017 22:10:23 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:10:23 (dsmcad) Action: Incremental
06/19/2017 22:10:23 (dsmcad) Objects:
06/19/2017 22:10:23 (dsmcad) Options:
06/19/2017 22:10:23 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:10:23 (dsmcad) ------------------------------------------------------------
06/19/2017 22:10:23 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:10:43 (dsmcad) Executing scheduled command now.
06/19/2017 22:10:45 (dsmcad) Next operation scheduled:
06/19/2017 22:10:45 (dsmcad) ------------------------------------------------------------
06/19/2017 22:10:45 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:10:45 (dsmcad) Action: Incremental
06/19/2017 22:10:45 (dsmcad) Objects:
06/19/2017 22:10:45 (dsmcad) Options:
06/19/2017 22:10:45 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:10:45 (dsmcad) ------------------------------------------------------------
06/19/2017 22:10:45 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:11:15 (dsmcad) Executing scheduled command now.
06/19/2017 22:11:16 (dsmcad) Next operation scheduled:
06/19/2017 22:11:16 (dsmcad) ------------------------------------------------------------
06/19/2017 22:11:16 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:11:16 (dsmcad) Action: Incremental
06/19/2017 22:11:16 (dsmcad) Objects:
06/19/2017 22:11:16 (dsmcad) Options:
06/19/2017 22:11:16 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:11:16 (dsmcad) ------------------------------------------------------------
06/19/2017 22:11:16 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:11:56 (dsmcad) Executing scheduled command now.
06/19/2017 22:11:57 (dsmcad) Next operation scheduled:
06/19/2017 22:11:57 (dsmcad) ------------------------------------------------------------
06/19/2017 22:11:57 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:11:57 (dsmcad) Action: Incremental
06/19/2017 22:11:57 (dsmcad) Objects:
06/19/2017 22:11:57 (dsmcad) Options:
06/19/2017 22:11:57 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:11:57 (dsmcad) ------------------------------------------------------------
06/19/2017 22:11:57 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:12:27 (dsmcad) Executing scheduled command now.
06/19/2017 22:12:28 (dsmcad) Next operation scheduled:
06/19/2017 22:12:28 (dsmcad) ------------------------------------------------------------
06/19/2017 22:12:28 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:12:28 (dsmcad) Action: Incremental
06/19/2017 22:12:28 (dsmcad) Objects:
06/19/2017 22:12:28 (dsmcad) Options:
06/19/2017 22:12:28 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:12:28 (dsmcad) ------------------------------------------------------------
06/19/2017 22:12:28 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:12:58 (dsmcad) Executing scheduled command now.
06/19/2017 22:13:00 (dsmcad) Next operation scheduled:
06/19/2017 22:13:00 (dsmcad) ------------------------------------------------------------
06/19/2017 22:13:00 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:13:00 (dsmcad) Action: Incremental
06/19/2017 22:13:00 (dsmcad) Objects:
06/19/2017 22:13:00 (dsmcad) Options:
06/19/2017 22:13:00 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:13:00 (dsmcad) ------------------------------------------------------------
06/19/2017 22:13:00 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:13:30 (dsmcad) Executing scheduled command now.
06/19/2017 22:13:31 (dsmcad) Next operation scheduled:
06/19/2017 22:13:31 (dsmcad) ------------------------------------------------------------
06/19/2017 22:13:31 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:13:31 (dsmcad) Action: Incremental
06/19/2017 22:13:31 (dsmcad) Objects:
06/19/2017 22:13:31 (dsmcad) Options:
06/19/2017 22:13:31 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:13:31 (dsmcad) ------------------------------------------------------------
06/19/2017 22:13:31 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:14:01 (dsmcad) Executing scheduled command now.
06/19/2017 22:14:02 (dsmcad) Next operation scheduled:
06/19/2017 22:14:02 (dsmcad) ------------------------------------------------------------
06/19/2017 22:14:02 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:14:02 (dsmcad) Action: Incremental
06/19/2017 22:14:02 (dsmcad) Objects:
06/19/2017 22:14:02 (dsmcad) Options:
06/19/2017 22:14:02 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:14:02 (dsmcad) ------------------------------------------------------------
06/19/2017 22:14:02 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:14:32 (dsmcad) Executing scheduled command now.
06/19/2017 22:14:33 (dsmcad) Next operation scheduled:
06/19/2017 22:14:33 (dsmcad) ------------------------------------------------------------
06/19/2017 22:14:33 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:14:33 (dsmcad) Action: Incremental
06/19/2017 22:14:33 (dsmcad) Objects:
06/19/2017 22:14:33 (dsmcad) Options:
06/19/2017 22:14:33 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:14:33 (dsmcad) ------------------------------------------------------------
06/19/2017 22:14:33 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:15:13 (dsmcad) Executing scheduled command now.
06/19/2017 22:15:15 (dsmcad) Next operation scheduled:
06/19/2017 22:15:15 (dsmcad) ------------------------------------------------------------
06/19/2017 22:15:15 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:15:15 (dsmcad) Action: Incremental
06/19/2017 22:15:15 (dsmcad) Objects:
06/19/2017 22:15:15 (dsmcad) Options:
06/19/2017 22:15:15 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
06/19/2017 22:15:15 (dsmcad) ------------------------------------------------------------
06/19/2017 22:15:15 (dsmcad) Waiting to be contacted by the server.
06/19/2017 22:15:45 (dsmcad) Executing scheduled command now.
06/19/2017 22:15:46 (dsmcad) Next operation scheduled:
06/19/2017 22:15:46 (dsmcad) ------------------------------------------------------------
06/19/2017 22:15:46 (dsmcad) Schedule Name: SCHEDULE1
06/19/2017 22:15:46 (dsmcad) Action: Incremental
06/19/2017 22:15:46 (dsmcad) Objects:
06/19/2017 22:15:46 (dsmcad) Options:
06/19/2017 22:15:46 (dsmcad) Server Window Start: 19:00:00 on 06/20/2017
 
PREDATAR Control23

It's really odd. I'd upgrade the client to a supported level and open a problem ticket with IBM if I were you. Supported are 6.4.0 or later, but 7.1.0 and later after September.
 
PREDATAR Control23

Ok this is ever more weird. If I set the schedule for noon, I restart the cad and it finds the new schedule, does NOT loop like the problem I posted, runs its backup and completes and acts completely normal. I don't think this has anything to do with the cad or the scheduler at all. Its also not happening to all nodes, only a specific few.

Is there ANYTHING server that is a time based setting that could allow/force a client to poll ?

Marclay that's for the help, but I cant upgrade until IBM gets the client NFS automount issue fixed (projected 8.1.2) Kind of stuck in a hard place here. If I log a ticket I know they are going to tell me to upgrade the client first thing. I guess I will just have to log it and go through the explanation.
 
PREDATAR Control23

I wonder if file permissions could somehow cause this
 
PREDATAR Control23

SERVER_1 = DOMAIN_A SCHED_A (Linux)
Backup finished 19:02
Logging issue: 22:10:19 - 8:15 (10 hours)

SERVER_2 = DOMAIN_A SCHED_B (Linux)
Backup finished 20:05
Logging issue: 22:10 - 8:09 (10 hours)

SERVER_3 = DOMAIN_A SCHED_B (Linux)
Backup finsihed 20:03
Logging issue 20:04 - 5:59 (10 hours)

SERVER_4 =DOMAIN_C SCHED_C (Solaris)
Backup finished 00:38
Logging issue 00:38 - 8:09 (8 hours)
 
PREDATAR Control23

IBM isnt getting anywhere with this.

I pointed the backups to the original TSM server, and having the SAME problem, but noticed the logging occurs according to the schedules defined on the new server??!! Its like the CAD is holding on to the schedules and not "flushing" them out.
 
Top