Unable to login to Visual Analytics 7.3 Web Interface

[MarkESmith]

Hey all,

I experienced a problem today with Visual Analytics, after I was notified by end-users that they could no longer log-in to the Visual Analytics web interface.

I tried myself to login, but the webpage would just sit there waiting for a response from the server after I clicked 'Submit'.

I could not rectify this problem until I restarted all the SAS servers (using the sas.servers shell script - we are running SAS on Linux). After the SAS servers restarted, I was then able to login without any issue. Naturally, the first place I started to look was the logs. Below are a couple excerpts from log files:

/opt/sas94/config/Lev1/Web/Logs/SASServer1_1/SASLogon9.4.log:

2019-03-28 13:20:46,724 [tomcat-http--9] ERROR com.sas.svcs.security.authentication.tickets.TicketsController - error.authentication.credentials.bad
org.jasig.cas.ticket.TicketCreationException: error.authentication.credentials.bad

2019-03-28 14:52:13,541 [tomcat-http--17] ERROR com.sas.svcs.security.authentication.tickets.TicketsController - service.not.authorized
org.jasig.cas.services.UnauthorizedServiceException: service.not.authorized

2019-03-28 14:57:48,033 [tomcat-http--37] ERROR org.jasig.cas.util.HttpClient - Read timed out
java.net.SocketTimeoutException: Read timed out

2019-03-28 15:04:57,975 [tomcat-http--42] ERROR com.sas.svcs.security.authentication.web.ServiceValidateController - TicketException generating ticket for: [callbackUrl: http://---.---.--:7980/SASVisualDataBuilder/j_spring_cas_security_proxyreceptor]
org.jasig.cas.ticket.TicketCreationException: error.authentication.credentials.bad

/opt/sas94/config/Lev1/Web/Logs/SASServer1_1/SASWorkflowServices9.4.log:

2019-03-28 14:29:36,073 [localhost-startStop-11] WARN [unknown] com.sas.services.session.SessionContext - Forced destruction of the session context by the Session Service. Session Context=c6e9db05ebcb3989:8c0b137:169410bff6b:-5a77
2019-03-28 14:29:36,090 [localhost-startStop-11] WARN [unknown] com.sas.services.session.SessionContext - Forced destruction of the session context by the Session Service. Session Context=c6e9db05ebcb3989:8c0b137:169410bff6b:-5a74
2019-03-28 14:37:11,094 [localhost-startStop-12] WARN [unknown] com.sas.services.session.SessionContext - Forced destruction of the session context by the Session Service. Session Context=0984e9a11770c629:36ef812a:169c591ffbf:-552c
2019-03-28 14:37:11,104 [localhost-startStop-12] WARN [unknown] com.sas.services.session.SessionContext - Forced destruction of the session context by the Session Service. Session Context=0984e9a11770c629:36ef812a:169c591ffbf:-5529
2019-03-28 15:00:27,562 [localhost-startStop-12] WARN [unknown] com.sas.services.session.SessionContext - Forced destruction of the session context by the Session Service. Session Context=aa6521b502c3500d:-cf6827e:169c5a2f91e:-5a9e
2019-03-28 15:00:27,578 [localhost-startStop-12] WARN [unknown] com.sas.services.session.SessionContext - Forced destruction of the session context by the Session Service. Session Context=aa6521b502c3500d:-cf6827e:169c5a2f91e:-5aa1

The logs from 'SASLogon9.4.log' seem suspect to me. From what I've gathered through pure observation, the following URL that it mentions is the address that credentials are sent to when you click 'Submit' when logging in and from the looks of it, it generates some sort of authentication ticket. That appears to be, if not the cause of the problem, at least a symptom:

http://---.---.--:7980/SASVisualDataBuilder/j_spring_cas_security_proxyreceptor

Does anyone have any idea what may have been the problem? Any ideas or other places to look (log files) would be greatly appreciated!

Thanks!

[Kalind_Patel]

Have you checked in /opt/sas94/config/Lev1/Web/WebAppServer/SASServer1_1/logs/server.log?

It will tell you the more about root cause.

[MarkESmith]

Thanks for the tip. I checked it out and see the following:

2019-03-28 15:00:30,689 WARN (localhost-startStop-14) [org.apache.catalina.loader.WebappClassLoaderBase] The web application [SASWIPServices] appears to have started a thread named [ActiveMQ Session Task-3] but has failed to stop it. This is very likely to create a memory leak.

2019-03-28 15:00:30,692 ERROR (localhost-startStop-14) [org.apache.catalina.loader.WebappClassLoaderBase] The web application [SASWIPServices] created a ThreadLocal with key of type [java.lang.InheritableThreadLocal] (value [java.lang.InheritableThreadLocal@5b0f0110]) and a value of type [com.sas.svcs.authentication.helper.LazySpringSecurityContext] (value [com.sas.svcs.authentication.helper.LazySpringSecurityContext@19569155]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.

2019-03-28 15:00:30,704 ERROR (localhost-startStop-14) [org.apache.catalina.loader.WebappClassLoaderBase] Found RMI Target with stub class class [com.sas.metadata.remote.MdObjectListImpl_Stub] and value [MdObjectListImpl_Stub[UnicastRef [liveRef: [endpoint:[----.--.--:35041](local),objID:[-cf6827e:169c5a2f91e:-412d, 8123884425826644874]]]]]. This RMI Target has been forcibly removed to prevent a memory leak.

There are many instances of all three of these messages (with various threads/targets) with the same timestamp. So to me it looks like many threads were created that couldn't be automatically stopped - and ultimately some sort of memory leak may have occurred? That's all well and good to know what happened, but this still doesn't really explain why this began in the first place. Anyone have any experience with error messages like these?

[MarkESmith]

I have experienced this same issue once again. Here's an excerpt below of log file:

/opt/sas94/config/Lev1/Web/WebAppServer/SASServer1_1/logs/server.log

2019-07-15 16:50:36,115 WARN (localhost-startStop-14) [org.apache.catalina.loader.WebappClassLoaderBase] The web application [SASWIPServices] appears to have started a thread named [Lock Grantor for sas.svcs.wip.DistributedLockService] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:503)
com.gemstone.gemfire.distributed.internal.locks.DLockGrantor$DLockGrantorThread.run(DLockGrantor.java:3632)
2019-07-15 16:50:36,115 ERROR (localhost-startStop-14) [org.apache.catalina.loader.WebappClassLoaderBase] The web application [SASWIPServices] created a ThreadLocal with key of type [java.lang.InheritableThreadLocal] (value [java.lang.InheritableThreadLocal@7370e549]) and a value of type [com.sas.svcs.authentication.helper.LazySpringSecurityContext] (value [com.sas.svcs.authentication.helper.LazySpringSecurityContext@d57267d]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.

I experienced the same symptoms as before - at first, SAS VisualAnalytics Hub would hang on the authentication of a user -- and eventually it would simply stop serving up the login page, not responding to requests at all (only the SAS VisualAnalytics Hub page would not respond, I could SSH into the server, view the environment manager, etc.)

Anyone have any experience with this problem?

[SASKiwi]

It seems you are having a number of problems with your SAS VA environment. If you haven't already done so I suggest you open a track with SAS Tech support as they are in the best position to diagnose your problems and find solutions.

In my experience resolving VA server problems can be tricky and may involve providing SAS with large server logs. This is beyond the scope of the SAS Community.