Randomly terminated selenium sessions

[LKay]

Zalenium Image Version(s):

• 3.11.0h

Docker Version:

• 17.12.0-ce

If using docker-compose, version:

• 1.18.0

OS:

• OSX High Mountain

Docker Command to start Zalenium:

docker-compose.yml:

  selenium:
    image: elgalu/selenium:3.11.0-p7

  zalenium:
    image: dosel/zalenium:3.11.0h
    privileged: true
    volumes:
      - "/var/run/docker.sock:/var/run/docker.sock"
      - "$WORKSPACE/test/artifacts/$BUILD_NUMBER/video:/home/seluser/videos"
      - "$WORKSPACE/test/artifacts/$BUILD_NUMBER/images:/home/seluser/images"
      - "/dev/shm:/dev/shm"
    ports:
      - "4444:4444"
    command: >
      start --screenWidth 1280
            --screenHeight 720
            --videoRecordingEnabled true
            --timeZone "Asia/Tokyo"
            --keepOnlyFailedTests false
            --maxTestSessions 5
            --desiredContainers 2

Expected Behavior -

Test are stable and run consistently.

Actual Behavior -

I get similar errors a lot:

ERROR: Session [984fb99878d582ddc1ec3a27c28caab8da8684c4] not available and is not among the last 1000 terminated sessions.
Active sessions are[ext. key f6e09e0ddb874aed284a15a043658d813f6d67f8, ext. key 54fe74ad5dc8d24ff0119ee3448567e5d11a8e2c, ext. key fb01f3d21cc6a3de8317e131684c7887b286bc1a, ab991a65-2a1c-4299-b414-7d03dddbf9d0 (int. key, remote not contacted yet.)]

The problem occurs almost all the time when I set parallel testing having more than one session at the time during test run but also occurs quite often when only single session is active.

This seems to be happening randomly using both built in browser nodes and/or testing against cloud services making testing totally unstable.

[diemol]

Hi @LKay,

I have seen that error before when the PHP bindings were being used, is that the case?

If not, it would be helpful if you can give us a way to reproduce the issue, so we can find a way to fix it.

[LKay]

In my current case I'm using NodeJS bindings. I tried core selenium-webdriver at first and now I use Webdriver.IO. I can share my config base for it if that helps: wdio.conf.js. It contains some more complex logic for tests repeating that we have to perform due to stability issues, but it doesn't affect the issue in place.

[diemol]

I was checking the WebDriverIO configuration and I don't see anything strange... Would it be possible to get the full Zalenium logs? Like that we could see when the session was created and find out if the node was killed for any reason.

In addition, are you running tests in parallel? If so, how many? I ask because the other reason I've seen similar errors is when not so many resources are available and then sometimes the browsers cannot start properly.

[LKay]

Yes, I'm trying to run tests in parallel but not to a massive extend, though. I have set maximum of 5 concurrent sessions, which is not very big amount. Running instance of docker definitely has enough resources available to handle that much. About quantity of tests then I currently have about a 100 test cases across maybe 20 test suites.

What kind of Zelenium logs do you need and how should I provide it to you?

[diemol]

Sorry for the late reply, the normal Zalenium log, all the output you see after docker run... is executed.

[LKay]

The logs are huge due to log level, but let me paste here just the errors I noticed:

13:54:49.043 [Forwarding ext. key d8eda3cecbaff8565aac4bec7ad52a1d to http://172.20.0.8:40000/wd/hub at 1:54:48 PM] INFO  d.z.e.z.c.DockerContainerClient - http://172.20.0.8:40000 [bash, -c, notify 'Zalenium', 'Card Form should validate address form', --icon=/home/seluser/images/message.png]
13:55:08.892 [qtp1991278377-29] ERROR o.o.g.w.s.handler.RequestHandler - cannot forward the request No System TLS
java.lang.AssertionError: No System TLS
at okhttp3.internal.Util.assertionError(Util.java:482)
at okhttp3.OkHttpClient.systemDefaultTrustManager(OkHttpClient.java:292)
at okhttp3.OkHttpClient.<init>(OkHttpClient.java:252)
at okhttp3.OkHttpClient$Builder.build(OkHttpClient.java:914)
at org.openqa.selenium.remote.internal.OkHttpClient$Factory.createClient(OkHttpClient.java:163)
at org.openqa.grid.internal.BaseGridRegistry.getHttpClient(BaseGridRegistry.java:52)
at org.openqa.grid.internal.BaseRemoteProxy.getHttpClient(BaseRemoteProxy.java:434)
at org.openqa.grid.internal.TestSession.getClient(TestSession.java:212)
at org.openqa.grid.internal.TestSession.sendRequestToNode(TestSession.java:428)
at org.openqa.grid.internal.TestSession.forward(TestSession.java:237)
at org.openqa.grid.web.servlet.handler.RequestHandler.forwardRequest(RequestHandler.java:99)
at org.openqa.grid.web.servlet.handler.RequestHandler.process(RequestHandler.java:133)
at org.openqa.grid.web.servlet.DriverServlet.process(DriverServlet.java:86)
at org.openqa.grid.web.servlet.DriverServlet.doPost(DriverServlet.java:70)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.seleniumhq.jetty9.servlet.ServletHolder.handle(ServletHolder.java:860)
at org.seleniumhq.jetty9.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1650)
at io.prometheus.client.filter.MetricsFilter.doFilter(MetricsFilter.java:170)
at org.seleniumhq.jetty9.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
at org.seleniumhq.jetty9.servlet.ServletHandler.doHandle(ServletHandler.java:533)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
at org.seleniumhq.jetty9.servlet.ServletHandler.doScope(ServletHandler.java:473)
at org.seleniumhq.jetty9.server.session.SessionHandler.doScope(SessionHandler.java:1564)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
at org.seleniumhq.jetty9.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
at org.seleniumhq.jetty9.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.seleniumhq.jetty9.server.handler.StatisticsHandler.handle(StatisticsHandler.java:169)
at org.seleniumhq.jetty9.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at org.seleniumhq.jetty9.server.Server.handle(Server.java:530)
at org.seleniumhq.jetty9.server.HttpChannel.handle(HttpChannel.java:347)
at org.seleniumhq.jetty9.server.HttpConnection.onFillable(HttpConnection.java:256)
at org.seleniumhq.jetty9.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
at org.seleniumhq.jetty9.io.FillInterest.fillable(FillInterest.java:102)
at org.seleniumhq.jetty9.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
at org.seleniumhq.jetty9.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
at org.seleniumhq.jetty9.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
at org.seleniumhq.jetty9.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.seleniumhq.jetty9.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
at org.seleniumhq.jetty9.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.security.KeyStoreException: problem accessing trust storejava.security.cert.CertificateException: Unable to initialize, java.io.IOException: DerInputStream.getLength(): lengthTag=124, too big.
at sun.security.ssl.TrustManagerFactoryImpl.engineInit(TrustManagerFactoryImpl.java:74)
at javax.net.ssl.TrustManagerFactory.init(TrustManagerFactory.java:250)
at okhttp3.OkHttpClient.systemDefaultTrustManager(OkHttpClient.java:284)
... 44 common frames omitted
13:55:09.096 [Terminate Test Session int id: [28ca7b18-a0d2-4329-b443-22a1f98bb3bd] ext id: [f11b2418-3ed0-4218-9002-71c62502c537] container: [dff6153fe22184993beb8d99f3126f7cb8c707ca7d0ac6d005d94bcd358b7ccf]] INFO  d.z.e.z.p.DockerSeleniumRemoteProxy - dff6153fe22184993beb8d99f3126f7cb8c707ca7d0ac6d005d94bcd358b7ccf AFTER_SESSION command received. Cleaning up node for reuse, used 3 of max 5

Recently I get a lot of these:

 message: Session [d8eda3cecbaff8565aac4bec7ad52a1d] was terminated due to FORWARDING_TO_NODE_FAILED

[diemol]

It seems you were having this same issue #491

And this was fixed in a release done 3 days ago https://github.com/zalando/zalenium/releases/tag/3.12.0c

So please test again with that newer version. I am going to close the issue since it was the same one as the mentioned above, but if you find a new problem, please don't doubt to create a new issue.

[LKay]

I tested that with the most recent version of the image 3.12.0c and the above error is not showing anymore in the logs but session are still being randomly terminated yet because of different reason:

Session [f89a5cd1c476b3c2f645885a85a02bb2] was terminated due to ORPHAN

Notice change from FORWARDING_TO_NODE_FAILED to ORPHAN. The test runner goes through few tests then hangs for a while and this happens.

[diemol]

Could you please provide the Zalenium log for this error?

[diemol]

Closing this issue since we didn't get more feedback from the OP.

If the issue still persists please create a new issue with updated data/info.

[rakeshnambiar]

@diemol I have the same issue on zalenium:3.14.0g and the reason I am using this old tag is to avoid the known issue FORWARDING_TO_NODE_FAILED. Please advise.