LASR servers not starting (VA)

[Lukas852]

Hello,

we have newly deployed Visual Analytics and after some testing i found out LASR servers are down.

When i try to start them, i get Failed message and the Last Action Log (accessible through right-clicking one of the servers) says this:

EXCEPTION (SASJob PreCode) .  com.sas.svcs.jobexecution.client.TaskExecutionException: com.sas.services.connection.FatalConnectionFactoryException: The application could not log on to the server "VA_SERVERhostname.domain:8591".

At first i thought the problem is with firewall blocking port 8591. 

But then i checked the connectivity from other servers (metadata, compute, midtier) to VA server on port 8591 and it was working (sending messages through ncat on port 8591 in linux).

Trying netstat -vatn | grep 8591 gives no results.

Based on this i assume that firewall isnt blocking port 8591, but rather there is nothing listening on port 8591 on VA server. In that case im confused by the error message - its trying to connect to port that is not listening?

Best regards,

Lukas.

[alexal]

@Lukas852 ,

What account did you use to login to the SAS Visual Analytics Administration Console?

[Lukas852]

I used sasadm@saspw account, and also my personal internal account with admin privileges. Both with same outcome.

[alexal]

@Lukas852 ,

You can use internal accounts only if SAS Token Authentication was enabled on the workspace server. Otherwise, you have to use an external account that was added to the metadata server and has all of the required permissions. 

[Lukas852]

Token authentication is enabled and i also tried to run in with external account.

Digging into it more, i discoved that problem is hidden in pooled workspace, workspace and stored process servers not able to start.

As shown in the Object Spawner log during startup:

2019-06-14T02:08:50,731 TRACE [00000031] :dot_sas - Installing Operator protocol handler.
2019-06-14T02:08:50,732 INFO [00000031] :dot_sas - Reserved IPv6 port 8581 for administrator listen (connection 2).
2019-06-14T02:08:50,732 TRACE [00000031] :dot_sas - Installing Bridge protocol handler.
2019-06-14T02:08:50,732 INFO [00000031] :dot_sas - Reserved IPv6 port 8451 for server listen (connection 3).
2019-06-14T02:08:50,732 TRACE [00000031] :dot_sas - Server Operating System Services - usdotpl6gh1 (A528E8VX.AY00000L) is associated with listen port 8451.
2019-06-14T02:08:50,732 INFO [00000031] :dot_sas - Reserved IPv6 port 8701 for server listen (connection 4).
2019-06-14T02:08:52,980 INFO [00000031] :dot_sas - Access denied.
2019-06-14T02:08:52,980 WARN [00000031] :dot_sas - The credentials specified for the SASAppVA - Pooled Workspace Server (A528E8VX.AY00000N) server definition failed to authenticate. Therefore this server definition will not be included.
2019-06-14T02:08:52,981 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d520] Unregistered
2019-06-14T02:08:52,981 DEBUG [00000031] :dot_sas - Closed listen (connection 4).
2019-06-14T02:08:52,981 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d520] Connection destroyed
2019-06-14T02:08:52,981 INFO [00000031] :dot_sas - Reserved IPv6 port 8601 for server listen (connection 5).
2019-06-14T02:08:52,981 INFO [00000031] :dot_sas - Reserved IPv6 port 8611 for server listen (connection 6).
2019-06-14T02:08:52,981 INFO [00000031] :dot_sas - Reserved IPv6 port 8621 for server listen (connection 7).
2019-06-14T02:08:52,981 INFO [00000031] :dot_sas - Reserved IPv6 port 8631 for server listen (connection 8).
2019-06-14T02:08:54,479 INFO [00000031] :dot_sas - Access denied.
2019-06-14T02:08:54,479 WARN [00000031] :dot_sas - The credentials specified for the SASAppVA - Stored Process Server (A528E8VX.AY00000O) server definition failed to authenticate. Therefore this server definition will not be included.
2019-06-14T02:08:54,479 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d520] Unregistered
2019-06-14T02:08:54,479 DEBUG [00000031] :dot_sas - Closed listen (connection 5).
2019-06-14T02:08:54,479 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d520] Connection destroyed
2019-06-14T02:08:54,479 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d660] Unregistered
2019-06-14T02:08:54,479 DEBUG [00000031] :dot_sas - Closed listen (connection 6).
2019-06-14T02:08:54,479 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d660] Connection destroyed
2019-06-14T02:08:54,479 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d7a0] Unregistered
2019-06-14T02:08:54,480 DEBUG [00000031] :dot_sas - Closed listen (connection 7).
2019-06-14T02:08:54,480 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d7a0] Connection destroyed
2019-06-14T02:08:54,480 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d8e0] Unregistered
2019-06-14T02:08:54,480 DEBUG [00000031] :dot_sas - Closed listen (connection 8).
2019-06-14T02:08:54,480 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d8e0] Connection destroyed
2019-06-14T02:08:54,480 INFO [00000031] :dot_sas - Reserved IPv6 port 8591 for server listen (connection 9).
2019-06-14T02:08:56,251 INFO [00000031] :dot_sas - Access denied.
2019-06-14T02:08:56,251 WARN [00000031] :dot_sas - The credentials specified for the SASAppVA - Workspace Server (A528E8VX.AY00000P) server definition failed to authenticate. Therefore this server definition will not be included.
2019-06-14T02:08:56,252 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d8e0] Unregistered
2019-06-14T02:08:56,252 DEBUG [00000031] :dot_sas - Closed listen (connection 9).
2019-06-14T02:08:56,252 DEBUG [00000031] :dot_sas - Bridge PE [7ff36438d8e0] Connection destroyed
2019-06-14T02:08:56,252 TRACE [00000031] :dot_sas - Installing Connect Back protocol handler.
2019-06-14T02:08:56,252 INFO [00000031] :dot_sas - Reserved IPv6 port 39425 for launched server connect back listen (connection 10).
2019-06-14T02:08:56,252 INFO [00000031] :dot_sas - Activated listen on IPv6 port 39425 (connection 10).
2019-06-14T02:08:56,252 WARN [00000031] :dot_sas - The SASAppVA - Logical Pooled Workspace Server (A528E8VX.AW00000C) cluster does not contain any valid server definitions. Therefore this cluster definition will not be included.
2019-06-14T02:08:56,252 WARN [00000031] :dot_sas - The SASAppVA - Logical Stored Process Server (A528E8VX.AW00000D) cluster does not contain any valid server definitions. Therefore this cluster definition will not be included.
2019-06-14T02:08:56,252 WARN [00000031] :dot_sas - The SASAppVA - Logical Workspace Server (A528E8VX.AW00000E) cluster does not contain any valid server definitions. Therefore this cluster definition will not be included.
2019-06-14T02:08:56,252 INFO [00000031] :dot_sas - Activated listen on IPv6 port 8451 (connection 3).
2019-06-14T02:08:56,253 INFO [00000031] :dot_sas - Activated listen on IPv6 port 8581 (connection 2).
2019-06-14T02:08:56,253 DEBUG [00000031] :dot_sas - IOM NEW ObjectSpawner (compRef:7ff360512640, comp:7ff36052a960)
2019-06-14T02:08:56,253 DEBUG [00000031] :dot_sas - IOM CALL svcGetOption(): opt=PROTOCOL value=bridge
2019-06-14T02:08:56,253 DEBUG [00000031] :dot_sas - IOM CALL {

I found SAS explanation on this error saying that the credentials for user starting the server (in this case dot_sassrv) are invalid.

Thing is, dot_sassrv is LDAP user in our environment, and the same user is used to start SAS Campaign Management servers, which work just fine. (We have CM server, VA server, midtier server, and metadata server used for both CM and VA.)

Hence i fail to see how the credentials are wrong.

[alexal]

@Lukas852 ,

dot_sas is acting as your sassrv account? If so, did you add his password to the metadata server?

[Lukas852]

No,

sas = dot_sas

sassrv = dot_sassrv

Yes, i have the user in metadata:

Like i said earlier, same metadata is used for other SAS software running on different server (Campaign Management) and servers there start just fine.

But for some reason VA server cant autenticate dot_sassrv user.

I did authentication check as said in this note http://support.sas.com/kb/39/891.html for user dot_sassrv.

On metadata server it was ok:

20190618-09:25:28 Authenticating user dot_sassrv via pam
20190618-09:25:28 KRB5CCNAME was not set; we'll see if something happens later
20190618-09:25:28 Processing message 1 of 1
20190618-09:25:28 PAM prompted for hidden input; assuming it wants a password
20190618-09:25:28 Prompt text: Password:
20190618-09:25:28 PAM conversation succeeded
20190618-09:25:28 pam_setcred: explicitly reinitializing PAM credentials
20190618-09:25:28 Getting user's group memberships
20190618-09:25:28 User dot_sassrv in 1 groups.
20190618-09:25:28 Authenticated user dot_sassrv (pam).

On VA server it failed:

20190618-09:39:10 Authenticating user dot_sassrv via pam
20190618-09:39:10 KRB5CCNAME was not set; we'll see if something happens later
20190618-09:39:10 Processing message 1 of 1
20190618-09:39:10 PAM prompted for hidden input; assuming it wants a password
20190618-09:39:10 Prompt text: Password:
20190618-09:39:10 PAM conversation succeeded
20190618-09:39:11 Processing message 1 of 1
20190618-09:39:11 PAM wanted to tell us some information: Account locked due to 119 failed logins
20190618-09:39:11 PAM conversation succeeded
20190618-09:39:11 Processing message 1 of 1
20190618-09:39:11 PAM prompted for hidden input; assuming it wants a password
20190618-09:39:11 Prompt text: Password:
20190618-09:39:11 PAM conversation succeeded
20190618-09:39:13 pam_authenticate failed: Permission denied
20190618-09:39:13 User dot_sassrv did not authenticate. Reason: 'Permission denied' (pam)
20190618-09:39:13 Request failed: 'Permission denied'

The user is LDAP user, i can log on with him to linux (VA server).

I dont understand how is could be locked as said in the log.

Are there any other credentials saved somewhere for VA server?