Error forwarding the new session

[finspin]

I have the following setup:

• running multiple containers of selenium hub on the same host
• each container running on a different port
• run test A on hub 1
• run test B on hub 2
• Docker version 1.11.0
• docker-compose version 1.8.1

Once the containers are up and running, this is the output of docker ps

17:31:02,500 INFO  - CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
17:31:02,500 INFO  - ab2d99d40c4f selenium/node-chrome-debug:3.0.1-aluminum "/opt/bin/entry_point" 6 seconds ago Up 1 seconds 0.0.0.0:32905->5900/tcp 1478619050087_chromenode_1
17:31:02,500 INFO  - 875884860b6a selenium/node-firefox-debug:2.53.1-beryllium "/opt/bin/entry_point" 7 seconds ago Up 3 seconds 0.0.0.0:32904->5900/tcp 1478619050087_firefoxnode_1
17:31:02,500 INFO  - 41cbfd06b201 selenium/hub:3.0.1-aluminum "/opt/bin/entry_point" 11 seconds ago Up 7 seconds 0.0.0.0:32903->4444/tcp 1478619050087_seleniumhub_1
17:31:02,500 INFO  - ea38707efc36 selenium/node-chrome-debug:3.0.1-aluminum "/opt/bin/entry_point" 15 seconds ago Up 12 seconds 0.0.0.0:32902->5900/tcp 1478619045173_chromenode_1
17:31:02,500 INFO  - e1877b094cc7 selenium/node-firefox-debug:2.53.1-beryllium "/opt/bin/entry_point" 15 seconds ago Up 13 seconds 0.0.0.0:32901->5900/tcp 1478619045173_firefoxnode_1
17:31:02,500 INFO  - 18878c35caec selenium/hub:3.0.1-aluminum "/opt/bin/entry_point" 16 seconds ago Up 14 seconds 0.0.0.0:32900->4444/tcp 1478619045173_seleniumhub_1

The problem is that sometimes one of the tests fails with the following error. As far as I can tell it's always the test that has been launched as second that fails.

17:31:10,941 INFO  - [17:31:10] I/hosted - Using the selenium server at http://0.0.0.0:32903/wd/hub
17:31:10,942 INFO  - [17:31:10] I/launcher - Running 1 instances of WebDriver
17:31:11,538 INFO  - [17:31:11] E/launcher - Error forwarding the new session Empty pool of VM for setup Capabilities [{count=1, browserName=chrome}]
17:31:11,538 INFO  - [17:31:11] E/launcher - WebDriverError: Error forwarding the new session Empty pool of VM for setup Capabilities [{count=1, browserName=chrome}]

docker-compose.yml

seleniumhub:
  image: selenium/hub:3.0.1-aluminum
  environment:
    - GRID_MAX_SESSION=10
    - GRID_BROWSER_TIMEOUT=100000
    - GRID_TIMEOUT=90000
    - GRID_NEW_SESSION_WAIT_TIMEOUT=300000
  ports:
    - 4444`

chromenode:
    image: selenium/node-chrome-debug:3.0.1-aluminum
    ports:
      - 5900
    environment:
      - NODE_MAX_SESSION=10
      - NODE_MAX_INSTANCES=10
    links:
      - seleniumhub:hub
    volumes:
      - /dev/shm:/dev/shm`

firefoxnode:
  # using version 2 of firefox because version 3 crashes
  image: selenium/node-firefox-debug:2.53.1-beryllium
  ports:
    - 5900
  environment:
    - NODE_MAX_SESSION=10
    - NODE_MAX_INSTANCES=10
  links:
    - seleniumhub:hub

[ddavison]

error forwarding the new session. sounds like at least one of the nodes cannot connect to the grid. the max session and max instances stuff was implemented with really no benchmarking - so we really don't know how they react. when you connect to the hub, are you able to see that it can support chrome and firefox?

[finspin]

@ddavison Unfortunately I can't access the hub UI since these tests are run on a CI server which doesn't support VNC at the moment. What tried now was to remove all env variables so my docker-compose.yml looks like the one below (running only 1 instance of each browser). I got a few successful runs but then tests started failing randomly again.

seleniumhub:
  image: selenium/hub:3.0.1-aluminum
  ports:
    - 4444

chromenode:
  image: selenium/node-chrome-debug:3.0.1-aluminum
  ports:
    - 5900
  links:
    - seleniumhub:hub
  volumes:
    - /dev/shm:/dev/shm

firefoxnode:
  # using version 2 of firefox because version 3 crashes
  image: selenium/node-firefox-debug:2.53.1-beryllium
  ports:
    - 5900
  links:
    - seleniumhub:hub

[finspin]

Is it possible that node tries to connect to the hub while hub is not ready yet? But then, why would it only happen only with the hub that is launched as second.

[finspin]

Here are the logs from the hub and the chromenode containers on which failing test was running. As far as I can tell they don't seem to indicate any issue.

hub:

starting selenium hub with configuration:

{
  "host": null,
  "port": 4444,
  "prioritizer": null,
  "capabilityMatcher": "org.openqa.grid.internal.utils.DefaultCapabilityMatcher",
  "throwOnCapabilityNotPresent": true,
  "newSessionWaitTimeout": -1,
  "jettyMaxThreads": -1,
  "nodePolling": 5000,
  "cleanUpCycle": 5000,
  "timeout": 30000,
  "browserTimeout": 0,
  "maxSession": 5,
  "unregisterIfStillDownAfter": 30000
}
20:26:18.366 INFO - Selenium build info: version: '3.0.1', revision: '1969d75'
20:26:18.393 INFO - Launching Selenium Grid hub
2016-11-08 20:26:20.638:INFO::main: Logging initialized @4751ms
20:26:20.678 INFO - Will listen on 4444
2016-11-08 20:26:20.813:INFO:osjs.Server:main: jetty-9.2.15.v20160210
2016-11-08 20:26:20.940:INFO:osjsh.ContextHandler:main: Started o.s.j.s.ServletContextHandler@10b48321{/,null,AVAILABLE}
2016-11-08 20:26:21.306:INFO:osjs.ServerConnector:main: Started ServerConnector@221af3c0{HTTP/1.1}{0.0.0.0:4444}
2016-11-08 20:26:21.306:INFO:osjs.Server:main: Started @5419ms
20:26:21.309 INFO - Nodes should register to http://172.17.0.5:4444/grid/register/
20:26:21.309 INFO - Selenium Grid hub is up and running
20:26:29.908 INFO - Got a request to create a new session: Capabilities [{count=1, browserName=chrome}]
20:26:30.724 INFO - Registered a node http://172.17.0.6:5555
20:26:31.119 INFO - Registered a node http://172.17.0.7:5555

chromenode:

Waiting xvfb...
08/11/2016 12:26:24 passing arg to libvncserver: -rfbport
08/11/2016 12:26:24 passing arg to libvncserver: 5900
08/11/2016 12:26:24 -usepw: found /root/.vnc/passwd
08/11/2016 12:26:24 x11vnc version: 0.9.13 lastmod: 2011-08-10  pid: 95
08/11/2016 12:26:24 Using X display :99.0
08/11/2016 12:26:24 rootwin: 0x25c reswin: 0x200001 dpy: 0x26647d0
08/11/2016 12:26:24 
08/11/2016 12:26:24 ------------------ USEFUL INFORMATION ------------------
08/11/2016 12:26:24 X DAMAGE available on display, using it for polling hints.
08/11/2016 12:26:24   To disable this behavior use: '-noxdamage'
08/11/2016 12:26:24 
08/11/2016 12:26:24   Most compositing window managers like 'compiz' or 'beryl'
08/11/2016 12:26:24   cause X DAMAGE to fail, and so you may not see any screen
08/11/2016 12:26:24   updates via VNC.  Either disable 'compiz' (recommended) or
08/11/2016 12:26:24   supply the x11vnc '-noxdamage' command line option.
08/11/2016 12:26:24 
08/11/2016 12:26:24 Wireframing: -wireframe mode is in effect for window moves.
08/11/2016 12:26:24   If this yields undesired behavior (poor response, painting
08/11/2016 12:26:24   errors, etc) it may be disabled:
08/11/2016 12:26:24    - use '-nowf' to disable wireframing completely.
08/11/2016 12:26:24    - use '-nowcr' to disable the Copy Rectangle after the
08/11/2016 12:26:24      moved window is released in the new position.
08/11/2016 12:26:24   Also see the -help entry for tuning parameters.
08/11/2016 12:26:24   You can press 3 Alt_L's (Left "Alt" key) in a row to 
08/11/2016 12:26:24   repaint the screen, also see the -fixscreen option for
08/11/2016 12:26:24   periodic repaints.
08/11/2016 12:26:24 
08/11/2016 12:26:24 XFIXES available on display, resetting cursor mode
08/11/2016 12:26:24   to: '-cursor most'.
08/11/2016 12:26:24   to disable this behavior use: '-cursor arrow'
08/11/2016 12:26:24   or '-noxfixes'.
08/11/2016 12:26:24 using XFIXES for cursor drawing.
08/11/2016 12:26:24 GrabServer control via XTEST.
08/11/2016 12:26:24 
08/11/2016 12:26:24 Scroll Detection: -scrollcopyrect mode is in effect to
08/11/2016 12:26:24   use RECORD extension to try to detect scrolling windows
08/11/2016 12:26:24   (induced by either user keystroke or mouse input).
08/11/2016 12:26:24   If this yields undesired behavior (poor response, painting
08/11/2016 12:26:24   errors, etc) it may be disabled via: '-noscr'
08/11/2016 12:26:24   Also see the -help entry for tuning parameters.
08/11/2016 12:26:24   You can press 3 Alt_L's (Left "Alt" key) in a row to 
08/11/2016 12:26:24   repaint the screen, also see the -fixscreen option for
08/11/2016 12:26:24   periodic repaints.
08/11/2016 12:26:24 
08/11/2016 12:26:24 XKEYBOARD: number of keysyms per keycode 7 is greater
08/11/2016 12:26:24   than 4 and 51 keysyms are mapped above 4.
08/11/2016 12:26:24   Automatically switching to -xkb mode.
08/11/2016 12:26:24   If this makes the key mapping worse you can
08/11/2016 12:26:24   disable it with the "-noxkb" option.
08/11/2016 12:26:24   Also, remember "-remap DEAD" for accenting characters.
08/11/2016 12:26:24 
08/11/2016 12:26:24 X FBPM extension not supported.
08/11/2016 12:26:24 X display is not capable of DPMS.
08/11/2016 12:26:24 --------------------------------------------------------
08/11/2016 12:26:24 
08/11/2016 12:26:24 Default visual ID: 0x21
PORT=5900
08/11/2016 12:26:24 Read initial data from X display into framebuffer.
08/11/2016 12:26:24 initialize_screen: fb_depth/fb_bpp/fb_Bpl 24/32/5440
08/11/2016 12:26:24 
08/11/2016 12:26:24 X display :99.0 is 32bpp depth=24 true color
08/11/2016 12:26:24 
08/11/2016 12:26:24 Listening for VNC connections on TCP port 5900
08/11/2016 12:26:24 Listening for VNC connections on TCP6 port 5900
08/11/2016 12:26:24 listen6: bind: Address already in use
08/11/2016 12:26:24 Not listening on IPv6 interface.
08/11/2016 12:26:24 
08/11/2016 12:26:24 Xinerama is present and active (e.g. multi-head).
08/11/2016 12:26:24 Xinerama: number of sub-screens: 1
08/11/2016 12:26:24 Xinerama: no blackouts needed (only one sub-screen)
08/11/2016 12:26:24 
08/11/2016 12:26:24 fb read rate: 1956 MB/sec
08/11/2016 12:26:24 fast read: reset -wait  ms to: 10
08/11/2016 12:26:24 fast read: reset -defer ms to: 10
08/11/2016 12:26:24 The X server says there are 10 mouse buttons.
08/11/2016 12:26:24 screen setup finished.
08/11/2016 12:26:24 

The VNC desktop is:      ce9ee12885e0:0

******************************************************************************
Have you tried the x11vnc '-ncache' VNC client-side pixel caching feature yet?

The scheme stores pixel data offscreen on the VNC viewer side for faster
retrieval.  It should work with any VNC viewer.  Try it by running:

    x11vnc -ncache 10 ...

One can also add -ncache_cr for smooth 'copyrect' window motion.
More info: http://www.karlrunge.com/x11vnc/faq.html#faq-client-caching

Failed to read: session.ignoreBorder
Setting default value
Failed to read: session.forcePseudoTransparency
Setting default value
Failed to read: session.colorsPerChannel
Setting default value
Failed to read: session.doubleClickInterval
Setting default value
Failed to read: session.tabPadding
Setting default value
Failed to read: session.styleOverlay
Setting default value
Failed to read: session.slitlistFile
Setting default value
Failed to read: session.appsFile
Setting default value
Failed to read: session.tabsAttachArea
Setting default value
Failed to read: session.cacheLife
Setting default value
Failed to read: session.cacheMax
Setting default value
Failed to read: session.autoRaiseDelay
Setting default value
Failed to read: session.ignoreBorder
Setting default value
Failed to read: session.forcePseudoTransparency
Setting default value
Failed to read: session.colorsPerChannel
Setting default value
Failed to read: session.doubleClickInterval
Setting default value
Failed to read: session.tabPadding
Setting default value
Failed to read: session.styleOverlay
Setting default value
Failed to read: session.slitlistFile
Setting default value
Failed to read: session.appsFile
Setting default value
Failed to read: session.tabsAttachArea
Setting default value
Failed to read: session.cacheLife
Setting default value
Failed to read: session.cacheMax
Setting default value
Failed to read: session.autoRaiseDelay
Setting default value
12:26:27.580 INFO - Selenium build info: version: '3.0.1', revision: '1969d75'
12:26:27.596 INFO - Launching a Selenium Grid node
2016-11-08 12:26:30.087:INFO::main: Logging initialized @6432ms
Failed to read: session.screen0.opaqueMove
Setting default value
Failed to read: session.screen0.fullMaximization
Setting default value
Failed to read: session.screen0.maxIgnoreIncrement
Setting default value
Failed to read: session.screen0.maxDisableMove
Setting default value
Failed to read: session.screen0.maxDisableResize
Setting default value
Failed to read: session.screen0.workspacewarping
Setting default value
Failed to read: session.screen0.showwindowposition
Setting default value
Failed to read: session.screen0.autoRaise
Setting default value
Failed to read: session.screen0.clickRaises
Setting default value
Failed to read: session.screen0.defaultDeco
Setting default value
Failed to read: session.screen0.tab.placement
Setting default value
Failed to read: session.screen0.windowMenu
Setting default value
Failed to read: session.screen0.noFocusWhileTypingDelay
Setting default value
Failed to read: session.screen0.workspaces
Setting default value
Failed to read: session.screen0.edgeSnapThreshold
Setting default value
Failed to read: session.screen0.window.focus.alpha
Setting default value
Failed to read: session.screen0.window.unfocus.alpha
Setting default value
Failed to read: session.screen0.menu.alpha
Setting default value
Failed to read: session.screen0.menuDelay
Setting default value
Failed to read: session.screen0.tab.width
Setting default value
Failed to read: session.screen0.tooltipDelay
Setting default value
Failed to read: session.screen0.allowRemoteActions
Setting default value
Failed to read: session.screen0.clientMenu.usePixmap
Setting default value
Failed to read: session.screen0.tabs.usePixmap
Setting default value
Failed to read: session.screen0.tabs.maxOver
Setting default value
Failed to read: session.screen0.tabs.intitlebar
Setting default value
Failed to read: session.screen0.focusModel
Setting default value
Failed to read: session.screen0.tabFocusModel
Setting default value
Failed to read: session.screen0.focusNewWindows
Setting default value
Failed to read: session.screen0.focusSameHead
Setting default value
Failed to read: session.screen0.rowPlacementDirection
Setting default value
Failed to read: session.screen0.colPlacementDirection
Setting default value
Failed to read: session.screen0.windowPlacement
Setting default value
Failed to read: session.ignoreBorder
Setting default value
Failed to read: session.forcePseudoTransparency
Setting default value
Failed to read: session.colorsPerChannel
Setting default value
Failed to read: session.doubleClickInterval
Setting default value
Failed to read: session.tabPadding
Setting default value
Failed to read: session.styleOverlay
Setting default value
Failed to read: session.slitlistFile
Setting default value
Failed to read: session.appsFile
Setting default value
Failed to read: session.tabsAttachArea
Setting default value
Failed to read: session.cacheLife
Setting default value
Failed to read: session.cacheMax
Setting default value
Failed to read: session.autoRaiseDelay
Setting default value
Failed to read: session.screen0.opaqueMove
Setting default value
Failed to read: session.screen0.fullMaximization
Setting default value
Failed to read: session.screen0.maxIgnoreIncrement
Setting default value
Failed to read: session.screen0.maxDisableMove
Setting default value
Failed to read: session.screen0.maxDisableResize
Setting default value
Failed to read: session.screen0.workspacewarping
Setting default value
Failed to read: session.screen0.showwindowposition
Setting default value
Failed to read: session.screen0.autoRaise
Setting default value
Failed to read: session.screen0.clickRaises
Setting default value
Failed to read: session.screen0.defaultDeco
Setting default value
Failed to read: session.screen0.tab.placement
Setting default value
Failed to read: session.screen0.windowMenu
Setting default value
Failed to read: session.screen0.noFocusWhileTypingDelay
Setting default value
Failed to read: session.screen0.workspaces
Setting default value
Failed to read: session.screen0.edgeSnapThreshold
Setting default value
Failed to read: session.screen0.window.focus.alpha
Setting default value
Failed to read: session.screen0.window.unfocus.alpha
Setting default value
Failed to read: session.screen0.menu.alpha
Setting default value
Failed to read: session.screen0.menuDelay
Setting default value
Failed to read: session.screen0.tab.width
Setting default value
Failed to read: session.screen0.tooltipDelay
Setting default value
Failed to read: session.screen0.allowRemoteActions
Setting default value
Failed to read: session.screen0.clientMenu.usePixmap
Setting default value
Failed to read: session.screen0.tabs.usePixmap
Setting default value
Failed to read: session.screen0.tabs.maxOver
Setting default value
Failed to read: session.screen0.tabs.intitlebar
Setting default value
Failed to read: session.screen0.focusModel
Setting default value
Failed to read: session.screen0.tabFocusModel
Setting default value
Failed to read: session.screen0.focusNewWindows
Setting default value
Failed to read: session.screen0.focusSameHead
Setting default value
Failed to read: session.screen0.rowPlacementDirection
Setting default value
Failed to read: session.screen0.colPlacementDirection
Setting default value
Failed to read: session.screen0.windowPlacement
Setting default value
12:26:30.162 INFO - Driver provider org.openqa.selenium.ie.InternetExplorerDriver registration is skipped:
 registration capabilities Capabilities [{ensureCleanSession=true, browserName=internet explorer, version=, platform=WINDOWS}] does not match the current platform LINUX
12:26:30.162 INFO - Driver provider org.openqa.selenium.edge.EdgeDriver registration is skipped:
 registration capabilities Capabilities [{browserName=MicrosoftEdge, version=, platform=WINDOWS}] does not match the current platform LINUX
12:26:30.162 INFO - Driver class not found: com.opera.core.systems.OperaDriver
12:26:30.162 INFO - Driver provider com.opera.core.systems.OperaDriver registration is skipped:
Unable to create new instances on this machine.
12:26:30.162 INFO - Driver class not found: com.opera.core.systems.OperaDriver
12:26:30.162 INFO - Driver provider com.opera.core.systems.OperaDriver is not registered
12:26:30.168 INFO - Driver provider org.openqa.selenium.safari.SafariDriver registration is skipped:
 registration capabilities Capabilities [{browserName=safari, version=, platform=MAC}] does not match the current platform LINUX
2016-11-08 12:26:30.298:INFO:osjs.Server:main: jetty-9.2.15.v20160210
Failed to read: session.screen0.slit.acceptKdeDockapps
Setting default value
Failed to read: session.screen0.slit.autoHide
Setting default value
Failed to read: session.screen0.slit.maxOver
Setting default value
Failed to read: session.screen0.slit.placement
Setting default value
Failed to read: session.screen0.slit.alpha
Setting default value
Failed to read: session.screen0.slit.onhead
Setting default value
Failed to read: session.screen0.slit.layer
Setting default value
2016-11-08 12:26:30.370:INFO:osjsh.ContextHandler:main: Started o.s.j.s.ServletContextHandler@1622f1b{/,null,AVAILABLE}
Failed to read: session.screen0.toolbar.autoHide
Setting default value
Failed to read: session.screen0.toolbar.maxOver
Setting default value
Failed to read: session.screen0.toolbar.visible
Setting default value
Failed to read: session.screen0.toolbar.alpha
Setting default value
Failed to read: session.screen0.toolbar.layer
Setting default value
Failed to read: session.screen0.toolbar.onhead
Setting default value
Failed to read: session.screen0.toolbar.placement
Setting default value
Failed to read: session.screen0.toolbar.height
Setting default value
Failed to read: session.screen0.iconbar.mode
Setting default value
Failed to read: session.screen0.iconbar.alignment
Setting default value
Failed to read: session.screen0.iconbar.iconWidth
Setting default value
Failed to read: session.screen0.iconbar.iconTextPadding
Setting default value
Failed to read: session.screen0.iconbar.usePixmap
Setting default value
2016-11-08 12:26:30.595:INFO:osjs.ServerConnector:main: Started ServerConnector@21de60b4{HTTP/1.1}{0.0.0.0:5555}
2016-11-08 12:26:30.595:INFO:osjs.Server:main: Started @6940ms
12:26:30.595 INFO - Selenium Grid node is up and ready to register to the hub
12:26:30.633 INFO - Starting auto registration thread. Will try to register every 5000 ms.
12:26:30.633 INFO - Registering the node to the hub: http://172.17.0.5:4444/grid/register
12:26:30.727 INFO - The node is registered to the hub and ready to use
12:26:41.034 INFO - SessionCleaner initialized with insideBrowserTimeout 0 and clientGoneTimeout 1800000 polling every 180000

[finspin]

Actually, I think I found the issue. It seems like tests are launched about 1 second before node is registered to the hub. Here are the timestamps from the test (ignore hours, the time on CI server and in container doesn't match).

Node registered: 12:26:30.727
Error forwarding session: 22:26:29,933

22:26:29,477 INFO  - [22:26:29] I/hosted - Using the selenium server at http://0.0.0.0:32951/wd/hub
22:26:29,477 INFO  - [22:26:29] I/launcher - Running 1 instances of WebDriver
22:26:29,933 INFO  - [22:26:29] E/launcher - Error forwarding the new session Empty pool of VM for setup Capabilities [{count=1, browserName=chrome}]
22:26:29,933 INFO  - [22:26:29] E/launcher - WebDriverError: Error forwarding the new session Empty pool of VM for setup Capabilities [{count=1, browserName=chrome}]

Is there some recommended practice to handle these timing issues?

[ddavison]

have two steps:

1. Launch Hub / Nodes
2. Launch tests

just as you said, sounds like you ahve the steps bundled:

1. launch hub /nodes; launch tests

i'd recommend separating them somehow.

or, having a middle-layer script that waits until the hub / nodes are running

[finspin]

I do have 2 separate steps. It seems to me that docker-compose reports all containers as up and running but the node is not yet registered at that point.

[ddavison]

that's very likely. there's a delay, but a very minimal one between when the hub gets up and the nodes connect. i don't believe there's anything we can do to this repository to fix this though 😕

[finspin]

Would it be an option to implement health check for node images? https://docs.docker.com/engine/reference/builder/#/healthcheck

[finspin]

I'm trying to figure out how to do an automated check to make sure that a node (or multiple nodes) is registered with a hub. Any ideas?

[elgalu]

Try active wait:

# Wait for a chrome node
while ! (curl -sSL "http://localhost:4444/grid/console" | grep -i chrome) >/dev/null 2>&1; do echo -n "."; sleep 0.2; done

# Wait for a firefox node
while ! (curl -sSL "http://localhost:4444/grid/console" | grep -i firefox) >/dev/null 2>&1; do echo -n "."; sleep 0.2; done

[finspin]

Thanks @elgalu , that seems to work, I got a few green builds now. I had to do a slight modification, grep -i chrome instead of grep -i chrome_binary. I'm using hub version 3 so the string might have changed.

This is a workaround but I believe the root cause is this variable:

throwOnCapabilityNotPresent : true

I'm considering submitting a pull request to allow setting this variable value to true. Currently, it's hardcoded https://github.com/SeleniumHQ/docker-selenium/blob/15870375bd65e00d82424dcb4b250a2f46695207/Hub/generate_config

Would that be OK to allow passing this variable while setting it to true by default?

[diemol]

@finspin That variable is now configurable.
Can you check it again please?