search

aerokube / selenoid

Selenium Hub successor running browsers within containers. Scalable, immutable, self hosted Selenium-Grid on any platform with single binary.
https://aerokube.com/selenoid/latest/
Apache License 2.0
2.57k stars 322 forks source link

Logs about queued jobs #656

Closed baudren closed 5 years ago

baudren commented 5 years ago

Hello,

I am running a test calling a selenoid grid, from NodeJS with webdriver.io. The test gets queued, and I don't find an indication as to what is preventing the grid to fulfill the request.

As a consequence, subsequent tests are blocked, probably because of priority (the grid wants to fulfill the first to enter the grid).

Is there a way to find out what is blocking the grid from working? Enabling the logs only cover session activity, but no session is created - it stays in the queue.

Thank you in advance for you help, and please find more details below.

I am running a selenoid grid without the configuration manager, with the following command line

docker run -d --name selenoid -p 4444:4444 -v /var/run/docker.sock:/var/run/docker.sock -v $OUTPUTDIR/:/etc/selenoid/:ro -v $VIDEO/:/opt/selenoid/video/ -v $LOGS/:/opt/selenoid/logs/ -e DOCKER_API
_VERSION=1.24 -e OVERRIDE_HOME=${PWD} -e OVERRIDE_VIDEO_OUTPUT_DIR=$VIDEO/ aerokube/selenoid -limit $LIMIT -conf /etc/selenoid/browsers.json -video-output-dir /opt/selenoid/video/ -video-recorder-image se
lenoid/video-recorder:latest -log-output-dir /opt/selenoid/logs -save-all-logs

the browsers.json file:

{
    "chrome": {
        "versions": {
            "70.0": {
                "image": "selenoid/vnc:chrome_70.0",
                "port": "4444",
                "path": "/",
                "tmpfs": {
                    "/tmp": "size=128m"
                },
                "shmSize": 536870912
            }
        },
        "default": "70.0"
    }
}

And the capabilities I am requesting. If I use these capabilities from a python script, the tests run, but from a NodeJS script (with webdriver.io) it fails

    "browserName": "chrome",
    "version": "70.0",
    "enableVNC": True,
    "enableVideo": True,
    "videoScreenSize": "1600x900",
vania-pooh commented 5 years ago

@baudren could take a look what's inside Selenoid logs?

$ docker logs selenoid
baudren commented 5 years ago

@vania-pooh yes, here they are. It starts by a session that worked (called from Python), then is followed by a request from webdriverio that never got accepted.

2019/01/23 09:46:02 [-] [NEW_REQUEST] [unknown] [10.10.112.22]
2019/01/23 09:46:02 [-] [NEW_REQUEST_ACCEPTED] [unknown] [10.10.112.22]
2019/01/23 09:46:02 [26] [LOCATING_SERVICE] [chrome] [70.0]
2019/01/23 09:46:02 [26] [USING_DOCKER] [chrome] [70.0]
2019/01/23 09:46:02 [26] [CREATING_CONTAINER] [selenoid/vnc:chrome_70.0]
2019/01/23 09:46:02 [26] [STARTING_CONTAINER] [selenoid/vnc:chrome_70.0] [dfbadfe012bcdc72bd76bfa836e5c42fef70642c4e3747156bec0d58aed1ec68]
2019/01/23 09:46:03 [26] [CONTAINER_STARTED] [selenoid/vnc:chrome_70.0] [dfbadfe012bcdc72bd76bfa836e5c42fef70642c4e3747156bec0d58aed1ec68] [0.52s]
2019/01/23 09:46:03 [26] [CREATING_VIDEO_CONTAINER] [selenoid/video-recorder:latest]
2019/01/23 09:46:03 [26] [STARTING_VIDEO_CONTAINER] [selenoid/video-recorder:latest] [827da6b868f1dd18ad7136bb75e7f40850f209120d9bba6faa309218d5c1f87d]
2019/01/23 09:46:03 [26] [VIDEO_CONTAINER_STARTED] [selenoid/video-recorder:latest] [827da6b868f1dd18ad7136bb75e7f40850f209120d9bba6faa309218d5c1f87d] [0.34s]
2019/01/23 09:46:03 [26] [SERVICE_STARTED] [selenoid/vnc:chrome_70.0] [dfbadfe012bcdc72bd76bfa836e5c42fef70642c4e3747156bec0d58aed1ec68] [0.00s]
2019/01/23 09:46:03 [26] [PROXY_TO] [dfbadfe012bcdc72bd76bfa836e5c42fef70642c4e3747156bec0d58aed1ec68] [http://172.17.0.4:4444/]
2019/01/23 09:46:03 [26] [SESSION_ATTEMPTED] [http://172.17.0.4:4444/] [1]
2019/01/23 09:46:04 [26] [SESSION_CREATED] [8c996a313b89cd5a3e47b96cad6bea01] [1] [1.75s]
2019/01/23 09:46:11 [33] [SESSION_DELETED] [8c996a313b89cd5a3e47b96cad6bea01]
2019/01/23 09:46:11 [26] [STOPPING_VIDEO_CONTAINER] [827da6b868f1dd18ad7136bb75e7f40850f209120d9bba6faa309218d5c1f87d]
2019/01/23 09:46:12 [26] [STOPPED_VIDEO_CONTAINER] [827da6b868f1dd18ad7136bb75e7f40850f209120d9bba6faa309218d5c1f87d]
2019/01/23 09:46:12 [26] [REMOVING_CONTAINER] [dfbadfe012bcdc72bd76bfa836e5c42fef70642c4e3747156bec0d58aed1ec68]
2019/01/23 09:46:13 [26] [CONTAINER_REMOVED] [dfbadfe012bcdc72bd76bfa836e5c42fef70642c4e3747156bec0d58aed1ec68]
2019/01/23 09:46:21 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:46:21 [-] [NEW_REQUEST_ACCEPTED] [unknown] [10.10.124.47]
2019/01/23 09:46:22 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:46:22 [-] [NEW_REQUEST_ACCEPTED] [unknown] [10.10.124.47]
2019/01/23 09:46:36 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:46:36 [-] [NEW_REQUEST_ACCEPTED] [unknown] [10.10.124.47]
2019/01/23 09:46:36 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:46:36 [-] [NEW_REQUEST_ACCEPTED] [unknown] [10.10.124.47]
2019/01/23 09:55:53 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:55:53 [-] [NEW_REQUEST_ACCEPTED] [unknown] [10.10.124.47]
2019/01/23 09:55:53 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:56:02 [-] [CLIENT_DISCONNECTED] [unknown] [10.10.124.47] [8.780034326s]
2019/01/23 09:56:23 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:57:23 [-] [CLIENT_DISCONNECTED] [unknown] [10.10.124.47] [1m0.00115778s]
2019/01/23 09:57:24 [-] [NEW_REQUEST] [unknown] [10.10.124.47]
2019/01/23 09:57:46 [-] [NEW_REQUEST] [unknown] [10.10.112.22]
2019/01/23 09:58:24 [-] [CLIENT_DISCONNECTED] [unknown] [10.10.124.47] [1m0.004744081s]
2019/01/23 11:12:37 [-] [NEW_REQUEST] [unknown] [10.10.124.53]
vania-pooh commented 5 years ago

@baudren what is your -limit value? Selenoid queues sessions on top of this value.

baudren commented 5 years ago

I have a limit of 5. I performed more tests, and what we see is that all these sessions that are "ACCEPTED" (9:46:21 in the log above) go on and saturate the "pending" jobs. Little by little, they arrive at the limit, and then after that, the next jobs are queued, as expected.

So the question is rather: why are the jobs stuck in pending state? Is there a way to see what selenoid is waiting for?

vania-pooh commented 5 years ago

@baudren pending means Docker container is being created. What is your Docker storage driver?

baudren commented 5 years ago

It's running overlay2. But tests triggered from a python webdriver run fine, which means that the grid is able to start those containers. Could it be a compatibility issue with the versions of the selenium clients we are using?

vania-pooh commented 5 years ago

@baudren certainly. Selenium currently has 2 protocol implementations: JSONWire (old one) and W3C (new). They differ in JSON data format transferred in every HTTP request. Currently all browsers and clients are migrating to W3C spec but some JS clients (e.g. admc/wd) are known to not fully support the spec. Regarding webdriver.io - make sure you are using a modern version, e.g. 4.10+ or even 5.

baudren commented 5 years ago

@vania-pooh Yes, that was it. We were running with webdriver.io version 4.14.0, and it failed, but with the newest version 5 (tested with 5.4.1), it runs smoothly. However this means upgrading quite a lot of things on our side because the syntax changed so much between those two versions.

Still, on the selenoid side, is there no mechanism to drop these sort of requests that can never be fulfilled? Is there an option we can add to make this happen?

Thank you in any case for your very prompt support, it's appreciated!

Cheers

vania-pooh commented 5 years ago

@baudren Selenoid is just proxying requests to respective webdriver instance and we intentionally do not implement any sort of request processing like done in Selenium server to not kill performance.

baudren commented 5 years ago

Ok, thank you for the clarification.

After further tests, it turned out that we were missing the option protocol: 'https' in our configuration file (wdio.conf.js). Somehow the calls were properly relayed to the grid, but then failed later. So it still works with Webdriver.io 4.14.0, no need to go to 5.0+.

In any case, thank you again for your feedback, and your nice software!

Cheers