Page 1 of 1
TM1 server registering with Admin server
Posted: Sun May 03, 2020 12:55 pm
by Wim Gielis
Hello all,
In one of our TM1 environments, we suddenly see an issue with weekly restarts on Sunday.
In fact, there are 2 models on 1 server, who should register themselves with 1 admin host.
On Sunday morning, there is an automatic restart of the big model - Task Scheduler executes a batch script that reads:
Code: Select all
@ECHO OFF
SET SERVICE=THE_SERVICE_NAME
( SC STOP %SERVICE% && SC start %SERVICE% ) || ( TIMEOUT /T 3600 /NOBREAK && SC start %SERVICE% )
The small model is not restarted at all.
Now, this setup runs fine for now about 5 years. 3 weeks ago the TM1 server unregistered with the TM1 admin server but did not register again.
So the TM1 models loads fine but does not send out a signal to the TM1 admin server. Therefore, users don't see the server. When manually stopping the service and starting again, the TM1 server can register fine and it's all good.
Does anyone have an idea what is going on ? I increased the logging from INFO to DEBUG, but I don't see any clear culprit. Searching for ERROR or a cursory look do not help, the word ERROR is not in the logs and I see nothing out of the ordinary anyway. The logs from 8.30 AM to 2 PM is about 45,000 lines so without any pointer that will be difficult.
Thanks for any pointers !
Wim
Re: TM1 server registering with Admin server
Posted: Sun May 03, 2020 1:02 pm
by Wim Gielis
Here's a small part from the logs, just before the UNREGISTER takes place:
Code: Select all
10504 DEBUG 2020-05-03 08:30:00,427 TM1.TM1AdmSvr RECEIVED PING: "MY_TM1_SERVICE","tcp","10.32.1.153","12347","1460","0","127.0.0.1","","1","1","tm1server","applixca.pem","","0","","0","","ipv4","42","0","1","https://HOST_MACHINE:8001","8001"
10504 DEBUG 2020-05-03 08:30:00,427 TM1.Server.Network internal_net_Recv select on: 772
10504 DEBUG 2020-05-03 08:30:00,427 TM1.Server.Network internal_net_Recv select returned: 1
10504 DEBUG 2020-05-03 08:30:00,427 TM1.Server.Memory al_FreePool - apifunc# "0" - pool# "0" - poolsize "37158.000000"
2188 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Memory al_OpenPool() - apifunc# "0" - pool# "185" - Address "0x0000000000590300"
2188 DEBUG 2020-05-03 08:30:01,551 TM1.Event mt_SetEvent: Set event 0x000000000000025C succeeded.
2192 DEBUG 2020-05-03 08:30:01,551 TM1.Event mt_WaitForMultipleObjects: Successful. Event 0 (0x000000000000025C) signalled.
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL SSL Connection accepted.
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Available ciphers:
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-RSA-AES256-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-DSS-AES256-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: AES256-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: EDH-RSA-DES-CBC3-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: EDH-DSS-DES-CBC3-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DES-CBC3-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-RSA-AES128-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-DSS-AES128-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: AES128-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Comm.SSL Cipher used for connection: Version: TLSv1/SSLv3, Name: DHE-RSA-AES256-SHA
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Network internal_net_Recv select on: 752
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Network internal_net_Recv select returned: 1
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Network.Detail Receive 15 bytes
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Network.Detail Send 8 bytes
7664 INFO 2020-05-03 08:30:01,551 TM1.TM1AdmSvr REQUEST TO UNREGISTER: success - MY_TM1_SERVICE
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Network internal_net_Recv select on: 752
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Network internal_net_Recv select returned: 1
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Network.Detail Receive 8 bytes
7664 DEBUG 2020-05-03 08:30:01,551 TM1.Server.Memory al_FreePool - apifunc# "0" - pool# "0" - poolsize "37158.000000"
2188 DEBUG 2020-05-03 08:30:02,892 TM1.Server.Memory al_OpenPool() - apifunc# "0" - pool# "185" - Address "0x0000000000590300"
2188 DEBUG 2020-05-03 08:30:02,892 TM1.Event mt_SetEvent: Set event 0x000000000000025C succeeded.
2192 DEBUG 2020-05-03 08:30:02,892 TM1.Event mt_WaitForMultipleObjects: Successful. Event 0 (0x000000000000025C) signalled.
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL SSL Connection accepted.
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Available ciphers:
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-RSA-AES256-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-DSS-AES256-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: AES256-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: EDH-RSA-DES-CBC3-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: EDH-DSS-DES-CBC3-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DES-CBC3-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-RSA-AES128-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: DHE-DSS-AES128-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher Version: TLSv1/SSLv3, Name: AES128-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Comm.SSL Cipher used for connection: Version: TLSv1/SSLv3, Name: DHE-RSA-AES256-SHA
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Server.Network internal_net_Recv select on: 764
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Server.Network internal_net_Recv select returned: 1
8796 DEBUG 2020-05-03 08:30:02,892 TM1.Server.Network.Detail Receive 176 bytes
Re: TM1 server registering with Admin server
Posted: Sun May 03, 2020 3:51 pm
by Wim Gielis
I did some more digging:
- I changed the timeout for restart from 3,600 seconds to 600 seconds (just for testing purposes).
- I created a new task in Task Scheduler to execute this task about half an hour ago, which is Sunday evening for me.
Guess what, TM1 stops and starts and registers itself with the TM1 admin server if I use this script and task.
The differences are:
- 600 sec of timeout instead of 3600
- Sunday evening instead of Sunday morning
- the model was not used since the last restart this afternoon. The Sunday morning restart was after a week of TM1 usage
- my user to create the task, I am admin on the machine though, and the current task was set up by an admin person at the customer (who will definitely not be less admin than me)
Does anyone have a clue ?
Re: TM1 server registering with Admin server
Posted: Mon May 04, 2020 3:46 am
by ykud
Anything interesting in Admin server log?
https://www.ibm.com/support/knowledgece ... 600ba.html
I'd put in debug for next weekend to see whether there was a comm error.
Anything interesting in the Windows Event log around the time? You should see Service Stop / Service start entries there, but maybe there's something else?
What version you're on? If it's 2.0.9, might be worth looking into what admin server 'sees' via rest api and 'adding' it again -- this might give you a better error log?
https://www.ibm.com/support/knowledgece ... pport.html
And the usual : was antivirus changed / updated in the last month and is now clever enough to 'kill some of these messages'?
Re: TM1 server registering with Admin server
Posted: Mon May 04, 2020 8:22 am
by Wim Gielis
Hi ykud,
Thanks !
In the admin server logging, there's a lot of entries if DEBUG is enabled, like I did. In this thread I wrote that I didn't see anything out of the ordinary. Unfortunately, I cannot compare with DEBUG outcomes of the period when it used to work, 3 weeks ago. DEBUG was already active last weekend and the files exist.
Windows Event log was checked too, it gives 2 messages related to the said service:
- 8.30 service stopped
- 9.30 service started
Only thing is, the service did not signal this fact to the admin server, it seems.
The version is really outdated and unsupported, it's TM1 10.2.2 FP4. So no help with IBM. But since this setup has been around forever I don't think it is different from what we now have as a setup.
I will ask IT about antivirus or anything else that changed since let's say last month.
Wim
Re: TM1 server registering with Admin server
Posted: Mon May 04, 2020 9:51 am
by Drg
So the model doesn’t appear on the admin host at all, or does it appear during a manual start?
For reliability, try on both servers (the host and model server) to start the tm1 configurator and re-save the model with the creation of cryptography. and restart the admin host with saving the config file.
We had such an error when traffic analyzers stood between the subnets and blocked it (which of course does not fit into the situation if the model is visible during a manual start).
In any case, the best option would be to check the traffic on both servers during different launches.
Good luck
Re: TM1 server registering with Admin server
Posted: Mon May 04, 2020 10:10 am
by Wim Gielis
Thank you Drg.
It’s all on 1 machine.
1 admin host and 2 TM1 models. A very small one (0.5 GB) and a bigger one (60 GB).
During manual restart, or even my test scheduled restart on Sunday evening, the TM1 server can notify the admin server.
But this went wrong on Sunday morning for the past 3 weeks. The 5 years before it worked without an issue.
Re: TM1 server registering with Admin server
Posted: Mon May 04, 2020 11:40 am
by tomok
A stupid question but you do have a SaveData chore executing before your batch file takes down the TM1 service, right? If you don't it will save the data during the takedown, which can take a while if the service has been up for a long time. Maybe this is why it works fine with the extra timeout.
Re: TM1 server registering with Admin server
Posted: Mon May 04, 2020 5:13 pm
by Drg
tomok wrote: ↑Mon May 04, 2020 11:40 am
A stupid question but you do have a SaveData chore executing before your batch file takes down the TM1 service, right? If you don't it will save the data during the takedown, which can take a while if the service has been up for a long time. Maybe this is why it works fine with the extra timeout.
In practice, quite a few people were faced with situations when the server simply could not repay without forcing the process to stop (taskkill / f), this happens if executecommand was started which did not end or if a big view was opened and the server issued a message about its suspension.
but as I understand the problem is broader than those windows event shows that the service is stopped? or in the process of stopping?
Re: TM1 server registering with Admin server
Posted: Wed May 06, 2020 8:44 pm
by Wim Gielis
tomok wrote: ↑Mon May 04, 2020 11:40 am
A stupid question but you do have a SaveData chore executing before your batch file takes down the TM1 service, right? If you don't it will save the data during the takedown, which can take a while if the service has been up for a long time. Maybe this is why it works fine with the extra timeout.
Hi Tom,
There's a savedata at 7.30 AM and it takes about 30 min usually. It's a daily chore. I will look in the server message log to see when then the save data stopped that morning. It could be that it clashes with the restart. Maybe because we went to summertime end of March... The restart is at 8.30 AM but this sounds like a possibility to check out !
Re: TM1 server registering with Admin server
Posted: Wed May 06, 2020 8:50 pm
by Wim Gielis
No, the Savedata was successful and surely before the restart. This was the situation last Sunday morning:
- 02.png (43.26 KiB) Viewed 7741 times
That will not be the problem either.
Re: TM1 server registering with Admin server
Posted: Sun May 10, 2020 10:19 am
by Wim Gielis
Today I rescheduled the restart to take place 3 hours later (through the same batch script), still on Sunday before noon. Now it runs fine. Will check back next week too. No idea why it ran fine in the morning for 5 years and now all of a sudden it gave a timing issue (or so it seems).
Re: TM1 server registering with Admin server
Posted: Sun May 10, 2020 11:24 am
by gtonkin
Anything is the event viewer during the old time window?
Any new scheduled tasks running, updates being applied, AV scans?
Re: TM1 server registering with Admin server
Posted: Sun May 17, 2020 11:36 am
by Wim Gielis
gtonkin wrote: ↑Sun May 10, 2020 11:24 am
Anything is the event viewer during the old time window?
Any new scheduled tasks running, updates being applied, AV scans?
Thanks all !
Confirmation: the automatic restart is again successful this Sunday. I only scheduled the restart 3 hours later compared to before.
A direct cause as to why the previous timing (8.30 AM) suddenly gives issues after 5 years, was not found, unfortunately.