TestProject Forum

TestProject Agent in OpenShift

Hi

We have a OpenShift environment where I deployed the agent by following:

Both Chrome and Firefox deploy is good.
On the other hand, TestProject agent comes upp and the log shows:
2021-08-18 12:34:54.940 [INFO ] i.t.a.f.c.a.a Authenticating with TestProject…
2021-08-18 12:34:54.942 [INFO ] i.t.a.s.c Requesting authenticating token…
2021-08-18 12:34:55.440 [INFO ] i.t.a.s.c Authenticated successfully

But later after a while, it crashes:
2021-08-18 12:41:16.344 [INFO ] i.t.a.f.c.a.a Authenticating with TestProject…
2021-08-18 12:41:16.432 [INFO ] i.t.a.s.c Requesting authenticating token…
2021-08-18 12:41:18.241 [ERROR] i.t.a.s.c Failed to acquire access token - security issue

Full log:

2021-08-18 12:01:14.042 [INFO ] i.t.a.Program                            *** AGENT MANAGER - START ***
2021-08-18 12:01:15.463 [INFO ] i.t.a.h                                  TestProject Agent 3.1.0 (90f1a15b4) on Linux
2021-08-18 12:01:15.554 [INFO ] i.t.a.h                                  Running under user ? (?) of type Unknown with Guest privileges
2021-08-18 12:01:15.554 [INFO ] i.t.a.h                                  Running inside docker testproject-agent-67dcfb9f67-6znjp
2021-08-18 12:01:15.559 [INFO ] i.t.a.h                                  No X11 available - headless mode.
2021-08-18 12:01:16.032 [INFO ] i.t.a.h                                  Working folder: /opt/testproject/agent
2021-08-18 12:01:16.033 [INFO ] i.t.a.h                                  Data folder: /var/testproject/agent
2021-08-18 12:01:16.039 [INFO ] i.t.a.h                                  Agent IP addresses: 10.129.9.10
2021-08-18 12:01:18.052 [INFO ] i.t.a.m.c.a                              Running in docker - ADB version querying will be skipped.
2021-08-18 12:01:18.052 [INFO ] i.t.a.m.c.a                              Detected Java [13-ea]
2021-08-18 12:01:18.053 [INFO ] i.t.a.m.c.a                              Detected DotNet [2.2.8]
2021-08-18 12:01:18.055 [INFO ] i.t.a.m.c.b                              Searching for installed browsers...
2021-08-18 12:01:18.132 [INFO ] i.t.a.m.c.b                              Getting external browser version via http://chrome:4444/wd/hub 
2021-08-18 12:01:21.541 [INFO ] i.t.a.m.c.b                              External CHROME version is 92.0.4515.107
2021-08-18 12:01:21.687 [INFO ] i.t.a.m.c.b                              Getting external browser version via http://firefox:4444/wd/hub 
2021-08-18 12:01:27.777 [INFO ] i.t.a.m.c.b                              External FIREFOX version is 90.0.2
2021-08-18 12:01:29.454 [INFO ] i.t.a.m.c.b                              Finished detecting installed browsers.
2021-08-18 12:01:29.456 [INFO ] i.t.a.m.c.a                              Running in docker - drivers detection will be skipped.
2021-08-18 12:01:29.636 [INFO ] i.t.a.m.b                                Starting gRPC Server on port localhost:36709
2021-08-18 12:01:30.534 [INFO ] i.t.a.m.Q                                Runtime information saved
2021-08-18 12:01:30.534 [INFO ] i.t.a.h                                  Agent initialization is complete.
2021-08-18 12:01:30.547 [INFO ] i.t.a.w.b                                Starting Web Server...
2021-08-18 12:01:30.547 [INFO ] i.t.a.w.b                                Starting internal web server...
2021-08-18 12:01:30.640 [INFO ] i.t.a.m.M                                Checking Agent's connectivity with the outside world...
2021-08-18 12:01:31.164 [INFO ] i.t.a.m.M                                Agent failed communicating with the outside world.
2021-08-18 12:01:31.231 [INFO ] i.t.a.f.c.a.k                            Direct connection is not possible, proxy is needed?
2021-08-18 12:01:31.232 [INFO ] i.t.a.m.J                                Trying to discover proxy...
2021-08-18 12:01:31.340 [INFO ] i.t.a.m.J                                Discovered HTTP proxy 10.132.90.21:3128
2021-08-18 12:01:31.340 [INFO ] i.t.a.m.J                                Configured HTTP proxy 10.132.90.21:3128
2021-08-18 12:01:31.343 [INFO ] i.t.a.m.M                                Checking Agent's connectivity with the outside world...
2021-08-18 12:01:31.344 [INFO ] i.t.a.m.J                                Trying to discover proxy...
2021-08-18 12:01:31.344 [INFO ] i.t.a.m.J                                Discovered HTTP proxy 10.132.90.21:3128
2021-08-18 12:01:31.345 [INFO ] i.t.a.m.J                                Configured HTTP proxy 10.132.90.21:3128
2021-08-18 12:01:33.137 [INFO ] i.t.a.m.M                                Connection established successfully.
2021-08-18 12:01:33.137 [INFO ] i.t.a.f.c.a.k                            External connectivity is possible, proceeding to Authentication...
2021-08-18 12:01:33.139 [INFO ] i.t.a.f.c.a.a                            Trying to load Agent remote identity...
2021-08-18 12:01:33.141 [INFO ] i.t.a.f.c.a.a                            Agent is registered as [AF TestProject Agent - OpenShift] (BohQ3VIWw0exzeoL4uj_9Q), proceeding to authentication...
2021-08-18 12:01:33.144 [INFO ] i.t.a.f.c.a.a                            Authenticating with TestProject...
2021-08-18 12:01:33.233 [INFO ] i.t.a.s.c                                Requesting authenticating token...
2021-08-18 12:01:33.840 [ERROR] i.t.a.s.c                                Failed to acquire access token - security issue
org.apache.oltu.oauth2.common.exception.OAuthProblemException: invalid_grant, Invalid user credentials
	at org.apache.oltu.oauth2.common.exception.OAuthProblemException.error(OAuthProblemException.java:59)
	at org.apache.oltu.oauth2.client.validator.OAuthClientValidator.validateErrorResponse(OAuthClientValidator.java:63)
	at org.apache.oltu.oauth2.client.validator.OAuthClientValidator.validate(OAuthClientValidator.java:48)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.validate(OAuthClientResponse.java:127)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:96)
	at org.apache.oltu.oauth2.client.response.OAuthAccessTokenResponse.init(OAuthAccessTokenResponse.java:65)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:101)
	at org.apache.oltu.oauth2.client.response.OAuthAccessTokenResponse.init(OAuthAccessTokenResponse.java:60)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:120)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponseFactory.createCustomResponse(OAuthClientResponseFactory.java:82)
	at org.apache.oltu.oauth2.client.URLConnectionClient.execute(URLConnectionClient.java:111)
	at io.testproject.agent.security.d.accessToken(TestProjectAgent:31)
	at io.testproject.agent.security.c.c(TestProjectAgent:141)
	at io.testproject.agent.fsm.cloud.a.b.a(TestProjectAgent:125)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at io.testproject.agent.c.d.run(TestProjectAgent:33)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:830)
2021-08-18 12:01:33.841 [INFO ] i.t.a.f.c.a.a                            Request token attempt 1 failed, retrying in 1 second...
2021-08-18 12:01:34.841 [INFO ] i.t.a.s.c                                Requesting authenticating token...
2021-08-18 12:01:34.927 [ERROR] i.t.a.s.c                                Failed to acquire access token - security issue
org.apache.oltu.oauth2.common.exception.OAuthProblemException: invalid_grant, Invalid user credentials
	at org.apache.oltu.oauth2.common.exception.OAuthProblemException.error(OAuthProblemException.java:59)
	at org.apache.oltu.oauth2.client.validator.OAuthClientValidator.validateErrorResponse(OAuthClientValidator.java:63)
	at org.apache.oltu.oauth2.client.validator.OAuthClientValidator.validate(OAuthClientValidator.java:48)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.validate(OAuthClientResponse.java:127)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:96)
	at org.apache.oltu.oauth2.client.response.OAuthAccessTokenResponse.init(OAuthAccessTokenResponse.java:65)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:101)
	at org.apache.oltu.oauth2.client.response.OAuthAccessTokenResponse.init(OAuthAccessTokenResponse.java:60)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:120)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponseFactory.createCustomResponse(OAuthClientResponseFactory.java:82)
	at org.apache.oltu.oauth2.client.URLConnectionClient.execute(URLConnectionClient.java:111)
	at io.testproject.agent.security.d.accessToken(TestProjectAgent:31)
	at io.testproject.agent.security.c.c(TestProjectAgent:141)
	at io.testproject.agent.fsm.cloud.a.b.a(TestProjectAgent:125)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at io.testproject.agent.c.d.run(TestProjectAgent:33)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:830)
2021-08-18 12:01:34.931 [INFO ] i.t.a.f.c.a.a                            Request token attempt 1 failed, retrying in 2 second...
2021-08-18 12:01:35.931 [INFO ] i.t.a.s.c                                Requesting authenticating token...
2021-08-18 12:01:36.031 [ERROR] i.t.a.s.c                                Failed to acquire access token - security issue
org.apache.oltu.oauth2.common.exception.OAuthProblemException: invalid_grant, Invalid user credentials
	at org.apache.oltu.oauth2.common.exception.OAuthProblemException.error(OAuthProblemException.java:59)
	at org.apache.oltu.oauth2.client.validator.OAuthClientValidator.validateErrorResponse(OAuthClientValidator.java:63)
	at org.apache.oltu.oauth2.client.validator.OAuthClientValidator.validate(OAuthClientValidator.java:48)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.validate(OAuthClientResponse.java:127)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:96)
	at org.apache.oltu.oauth2.client.response.OAuthAccessTokenResponse.init(OAuthAccessTokenResponse.java:65)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:101)
	at org.apache.oltu.oauth2.client.response.OAuthAccessTokenResponse.init(OAuthAccessTokenResponse.java:60)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponse.init(OAuthClientResponse.java:120)
	at org.apache.oltu.oauth2.client.response.OAuthClientResponseFactory.createCustomResponse(OAuthClientResponseFactory.java:82)
	at org.apache.oltu.oauth2.client.URLConnectionClient.execute(URLConnectionClient.java:111)
	at io.testproject.agent.security.d.accessToken(TestProjectAgent:31)
	at io.testproject.agent.security.c.c(TestProjectAgent:141)
	at io.testproject.agent.fsm.cloud.a.b.a(TestProjectAgent:125)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at io.testproject.agent.c.d.run(TestProjectAgent:33)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:830)
2021-08-18 12:01:36.032 [INFO ] i.t.a.f.c.a.a                            Request token attempt 1 failed, retrying in 3 second...
2021-08-18 12:01:37.032 [WARN ] i.t.a.f.c.a.a                            Failed to authenticate identity, might have been deleted from the server, deleting identity files...
2021-08-18 12:01:37.032 [WARN ] i.t.a.s.IdentityManager                  Deleting agent identity file: id.dat
2021-08-18 12:01:37.033 [INFO ] i.t.a.f.c.a.a                            Agent is running in docker, and since the identity is invalid, will stop now...
2021-08-18 12:01:37.036 [INFO ] i.t.a.h                                  Stopping...
2021-08-18 12:01:37.036 [INFO ] i.t.a.h                                  Stopping Identity Server client...
2021-08-18 12:01:37.037 [INFO ] i.t.a.h                                  Stopping internal web server...
2021-08-18 12:01:37.038 [INFO ] i.t.a.f.c.d                              Agent state machine stopped.
2021-08-18 12:01:38.949 [INFO ] i.t.a.w.b                                Web server started on http://localhost:8585 
2021-08-18 12:01:39.047 [INFO ] i.t.a.h                                  Stopping other servers (Selenium & Appium)...
2021-08-18 12:01:39.049 [INFO ] i.t.a.a.a.c.a                            Stopping ADB...
2021-08-18 12:01:39.055 [INFO ] i.t.a.a.a.c.a                            ADB Stopped.
2021-08-18 12:01:39.058 [INFO ] i.t.a.h                                  All modules stopped.
2021-08-18 12:01:39.062 [INFO ] i.t.a.s.IdentityManager                  Agent is offline, can't obtain remote identity
2021-08-18 12:01:39.062 [INFO ] i.t.a.m.w.b                              Configuring concurrent workers amount: 1
2021-08-18 12:01:39.062 [INFO ] i.t.a.f.l.d                              Agent state machine stopped.
2021-08-18 12:01:39.131 [INFO ] i.t.a.Program                            Agent will exit with code: 0
2021-08-18 12:01:39.132 [INFO ] i.t.a.Program                            *** AGENT MANAGER - STOP ***

Hi!
It seems stable now once I removed the following bit from the yaml file. Since the Chrome and Firefox pods were up and running, I didn’t need the ‘livenessProbe’ block!

livenessProbe: 
            exec:
              command:
              - /bin/sh
              - -c              
              - curl -sSL http://chrome:4444/wd/hub/status | jq -r '.value.ready' | grep "true" || exit 1              
            initialDelaySeconds: 30
            periodSeconds: 5

Have the same problem, the agent is running on EKS (Amazon Managed k8s cluster).
Removing liveness probe didn’t help in my case, is there any other solution to resolve this problem ?

Hi @Valdemar I wish I had any other solution!
Does your agent show up in your account ‘Agents’ list?
If it does, what is the ‘Status’?

I’ve noticed the agent status become Disconnected after a while, when I deploy on Docker environment!
But it’s stable and stays Ready since I deployed in OpenShift - Kubernet (by removing livenessProbe).
Mysterious issue!

Yes, the Status is showing ready but I’ve noticed that pod is restarted after failed authentication attempt (the same error thread that you mentioned). It causing the agent to be re registered and the agent removed from TestProject job.

We used the latest agent version, so I’ve downgraded to previous, will see if it help