search

selenodium / selenodium-grid

Selenium Hub/Grid reimplementation in NodeJS
Apache License 2.0
8 stars 3 forks source link

Could not create session because of error: [object Object] #30

Closed TheFifthFreedom closed 9 years ago

TheFifthFreedom commented 9 years ago

Sorry I didn't check-in with you sooner @arikon - https://github.com/selenodium/selenodium-grid/pull/14 did indeed fix the node registration issue I was experiencing! I've been fiddling around since then trying to run a very basic test against a browser via selenodium:

from selenium import webdriver
from selenium.webdriver.common.keys import Keys
from selenium.webdriver.common.desired_capabilities import DesiredCapabilities

driver = webdriver.Remote(
    command_executor='http://localhost:4444/wd/hub',
    desired_capabilities=DesiredCapabilities.CHROME)
driver.get('http://www.google.com')
html = driver.page_source
print (html)
driver.close()

after having registered a node using Selenium's standalone server. However it seems that selenodium is unable to create a new session after placing a request to the requestServlet. I traced the session creation calls from there (Registry.js -> SessionQueue.js -> NodeSet.js -> Node.js -> NodeSlot.js) which gets me to this piece of code:

getNewSession: function(req) {
        var self = this;
        if (self.isLocked()) {
            log.debug('Slot on node with ID=%s is locked, skip', self.node.getId());
            return q(null);
        }

        // match capabilities
        var caps = req.capabilities;
        if (!self.hasCapability(caps)) {
            log.debug('Capabilities for slot on node with ID=%s do not match', self.node.getId());
            log.debug('* desired capabilities: %j', caps);
            log.debug('* slot capabilities: %j', self.caps);
            return q(null);
        }

        this.lock();

        req = extend({retries: 2}, req);
        return self.getDriver().getNewSessionFromNode(req, self.node)
            .catch(function(err) {
                // unlock node on session opening error
                self.unlock();
                return q.reject(err);
            })
            .then(function(res) {
                // save session on success
                self.session = new Session(self, res.sessionId, res.capabilities, res.desiredCapabilities);
                return self.session;
            });
    },

Now it appears the session declaration and allocation is never taken, which leads me to believe that getNewSessionFromNode is not fulfilled. That function is called in CommonImpl.js:

getNewSessionFromNode: function(req, node) {
        var self = this,
            caps = self.getRequestCapabilities(req);

        // send open session request
        return self.proxyRequestToNode(req, node)
            .then(function(res) {
                // process response
                console.log('hello');
                return self.parseProxyResponse(res);
            })
            .spread(function(sessionId, resCaps) {
                return {
                    sessionId: sessionId,
                    capabilities: resCaps,
                    desiredCapabilities: caps
                }
            })
            .catch(function(err) {
                log.debug('Error ocured during session opening on node with ID=%s', node.getId());
                log.debug(err.stack || err);
                return q.reject(err);
            });
    },

And again, here it looks like it's self.proxyRequestToNode(req, node) that isn't being fulfilled. But the only thing that this function does is call apps.processJsonBody from http-apps.js, and nothing something to be wrong there, as it returns exactly what it should:

{ version: [ 1, 1 ],
  method: 'GET',
  path: '/grid/api/proxy?id=http://10.211.101.57:5555',
  _pathInfo: null,
  scriptName: '',
  scheme: 'http',
  hostname: '10.211.101.57',
  port: 4444,
  host: '10.211.101.57:4444',
  remoteHost: '::ffff:10.211.101.57',
  remotePort: 54457,
  url: 'http://10.211.101.57:4444/grid/api/proxy?id=http://10.211.101.57:5555',
  body: 
   { read: [Function],
     forEach: [Function],
     close: [Function],
     node: 
      { _readableState: [Object],
        readable: false,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        socket: [Object],
        connection: [Object],
        httpVersion: '1.1',
        complete: true,
        headers: [Object],
        trailers: {},
        _pendings: [],
        _pendingIndex: 0,
        url: '/grid/api/proxy?id=http://10.211.101.57:5555',
        method: 'GET',
        statusCode: null,
        client: [Object],
        _consuming: true,
        _dumped: false,
        httpVersionMajor: 1,
        httpVersionMinor: 1,
        upgrade: false,
        pipe: [Function],
        addListener: [Function],
        on: [Function],
        pause: [Function],
        resume: [Function],
        read: [Function] } },
  headers: 
   { host: '10.211.101.57:4444',
     connection: 'Keep-Alive',
     'user-agent': 'Apache-HttpClient/4.3.6 (java 1.5)',
     'accept-encoding': 'gzip,deflate' },
  node: 
   { _readableState: 
      { highWaterMark: 16384,
        buffer: [],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: false,
        ended: true,
        endEmitted: true,
        reading: false,
        calledRead: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        objectMode: false,
        defaultEncoding: 'utf8',
        ranOut: false,
        awaitDrain: 0,
        readingMore: false,
        decoder: null,
        encoding: null },
     readable: false,
     domain: null,
     _events: 
      { error: [Object],
        end: [Object],
        data: [Function],
        readable: [Function],
        close: [Function] },
     _maxListeners: 10,
     socket: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: true,
        onend: [Function],
        destroyed: false,
        errorEmitted: false,
        bytesRead: 190,
        _bytesDispatched: 0,
        _pendingData: null,
        _pendingEncoding: '',
        server: [Object],
        _idleTimeout: 60000,
        _idleNext: [Object],
        _idlePrev: [Object],
        _idleStart: 1428094579248,
        parser: [Object],
        ondata: [Function],
        _peername: [Object],
        _httpMessage: [Object] },
     connection: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: true,
        onend: [Function],
        destroyed: false,
        errorEmitted: false,
        bytesRead: 190,
        _bytesDispatched: 0,
        _pendingData: null,
        _pendingEncoding: '',
        server: [Object],
        _idleTimeout: 60000,
        _idleNext: [Object],
        _idlePrev: [Object],
        _idleStart: 1428094579248,
        parser: [Object],
        ondata: [Function],
        _peername: [Object],
        _httpMessage: [Object] },
     httpVersion: '1.1',
     complete: true,
     headers: 
      { host: '10.211.101.57:4444',
        connection: 'Keep-Alive',
        'user-agent': 'Apache-HttpClient/4.3.6 (java 1.5)',
        'accept-encoding': 'gzip,deflate' },
     trailers: {},
     _pendings: [],
     _pendingIndex: 0,
     url: '/grid/api/proxy?id=http://10.211.101.57:5555',
     method: 'GET',
     statusCode: null,
     client: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: true,
        onend: [Function],
        destroyed: false,
        errorEmitted: false,
        bytesRead: 190,
        _bytesDispatched: 0,
        _pendingData: null,
        _pendingEncoding: '',
        server: [Object],
        _idleTimeout: 60000,
        _idleNext: [Object],
        _idlePrev: [Object],
        _idleStart: 1428094579248,
        parser: [Object],
        ondata: [Function],
        _peername: [Object],
        _httpMessage: [Object] },
     _consuming: true,
     _dumped: false,
     httpVersionMajor: 1,
     httpVersionMinor: 1,
     upgrade: false,
     pipe: [Function],
     addListener: [Function],
     on: [Function],
     pause: [Function],
     resume: [Function],
     read: [Function] },
  nodeRequest: 
   { _readableState: 
      { highWaterMark: 16384,
        buffer: [],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: false,
        ended: true,
        endEmitted: true,
        reading: false,
        calledRead: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        objectMode: false,
        defaultEncoding: 'utf8',
        ranOut: false,
        awaitDrain: 0,
        readingMore: false,
        decoder: null,
        encoding: null },
     readable: false,
     domain: null,
     _events: 
      { error: [Object],
        end: [Object],
        data: [Function],
        readable: [Function],
        close: [Function] },
     _maxListeners: 10,
     socket: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: true,
        onend: [Function],
        destroyed: false,
        errorEmitted: false,
        bytesRead: 190,
        _bytesDispatched: 0,
        _pendingData: null,
        _pendingEncoding: '',
        server: [Object],
        _idleTimeout: 60000,
        _idleNext: [Object],
        _idlePrev: [Object],
        _idleStart: 1428094579248,
        parser: [Object],
        ondata: [Function],
        _peername: [Object],
        _httpMessage: [Object] },
     connection: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: true,
        onend: [Function],
        destroyed: false,
        errorEmitted: false,
        bytesRead: 190,
        _bytesDispatched: 0,
        _pendingData: null,
        _pendingEncoding: '',
        server: [Object],
        _idleTimeout: 60000,
        _idleNext: [Object],
        _idlePrev: [Object],
        _idleStart: 1428094579248,
        parser: [Object],
        ondata: [Function],
        _peername: [Object],
        _httpMessage: [Object] },
     httpVersion: '1.1',
     complete: true,
     headers: 
      { host: '10.211.101.57:4444',
        connection: 'Keep-Alive',
        'user-agent': 'Apache-HttpClient/4.3.6 (java 1.5)',
        'accept-encoding': 'gzip,deflate' },
     trailers: {},
     _pendings: [],
     _pendingIndex: 0,
     url: '/grid/api/proxy?id=http://10.211.101.57:5555',
     method: 'GET',
     statusCode: null,
     client: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: true,
        onend: [Function],
        destroyed: false,
        errorEmitted: false,
        bytesRead: 190,
        _bytesDispatched: 0,
        _pendingData: null,
        _pendingEncoding: '',
        server: [Object],
        _idleTimeout: 60000,
        _idleNext: [Object],
        _idlePrev: [Object],
        _idleStart: 1428094579248,
        parser: [Object],
        ondata: [Function],
        _peername: [Object],
        _httpMessage: [Object] },
     _consuming: true,
     _dumped: false,
     httpVersionMajor: 1,
     httpVersionMinor: 1,
     upgrade: false,
     pipe: [Function],
     addListener: [Function],
     on: [Function],
     pause: [Function],
     resume: [Function],
     read: [Function] },
  nodeConnection: 
   { _connecting: false,
     _handle: 
      { fd: 17,
        writeQueueSize: 0,
        owner: [Circular],
        onread: [Function: onread],
        reading: true },
     _readableState: 
      { highWaterMark: 16384,
        buffer: [],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: false,
        ended: false,
        endEmitted: false,
        reading: true,
        calledRead: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        objectMode: false,
        defaultEncoding: 'utf8',
        ranOut: false,
        awaitDrain: 0,
        readingMore: false,
        decoder: null,
        encoding: null },
     readable: true,
     domain: null,
     _events: 
      { end: [Object],
        finish: [Function: onSocketFinish],
        _socketEnd: [Function: onSocketEnd],
        drain: [Function: ondrain],
        timeout: [Object],
        error: [Function],
        close: [Object] },
     _maxListeners: 10,
     _writableState: 
      { highWaterMark: 16384,
        objectMode: false,
        needDrain: false,
        ending: false,
        ended: false,
        finished: false,
        decodeStrings: false,
        defaultEncoding: 'utf8',
        length: 0,
        writing: false,
        sync: true,
        bufferProcessing: false,
        onwrite: [Function],
        writecb: null,
        writelen: 0,
        buffer: [] },
     writable: true,
     allowHalfOpen: true,
     onend: [Function],
     destroyed: false,
     errorEmitted: false,
     bytesRead: 190,
     _bytesDispatched: 0,
     _pendingData: null,
     _pendingEncoding: '',
     server: 
      { domain: null,
        _events: [Object],
        _maxListeners: 10,
        _connections: 3,
        connections: [Getter/Setter],
        _handle: [Object],
        _usingSlaves: false,
        _slaves: [],
        allowHalfOpen: true,
        httpAllowHalfOpen: true,
        timeout: 120000,
        destroy: [Function],
        _connectionKey: '6::::4444' },
     _idleTimeout: 60000,
     _idleNext: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: true,
        onend: [Function],
        destroyed: false,
        errorEmitted: false,
        bytesRead: 336,
        _bytesDispatched: 0,
        _pendingData: null,
        _pendingEncoding: '',
        server: [Object],
        _idleTimeout: 60000,
        _idleNext: [Object],
        _idlePrev: [Circular],
        _idleStart: 1428094576218,
        parser: [Object],
        ondata: [Function],
        _peername: [Object],
        _httpMessage: [Object] },
     _idlePrev: { _idleNext: [Circular], _idlePrev: [Object] },
     _idleStart: 1428094579248,
     parser: 
      { _headers: [],
        _url: '',
        onHeaders: [Function: parserOnHeaders],
        onHeadersComplete: [Function: parserOnHeadersComplete],
        onBody: [Function: parserOnBody],
        onMessageComplete: [Function: parserOnMessageComplete],
        socket: [Circular],
        incoming: [Object],
        maxHeaderPairs: 2000,
        onIncoming: [Function] },
     ondata: [Function],
     _peername: { address: '::ffff:10.211.101.57', family: 'IPv6', port: 54457 },
     _httpMessage: 
      { domain: null,
        _events: [Object],
        _maxListeners: 10,
        output: [],
        outputEncodings: [],
        writable: true,
        _last: false,
        chunkedEncoding: false,
        shouldKeepAlive: true,
        useChunkedEncodingByDefault: true,
        sendDate: true,
        _hasBody: true,
        _trailer: '',
        finished: false,
        _hangupClose: false,
        socket: [Circular],
        connection: [Circular] } },
  query: { id: 'http://10.211.101.57:5555' },
  pathname: '/grid/api/proxy' }

Do you have any ideas @arikon ?

arikon commented 9 years ago

@TheFifthFreedom Could you please show me the configuration file of the node?

What protocol is it using: WebDriver or Selenium (it should be seleniumProtocol property in the capabilities item)?

TheFifthFreedom commented 9 years ago

Of course - here it is:

{"class":"org.openqa.grid.common.RegistrationRequest","configuration":
{"proxy":"org.openqa.grid.selenium.proxy.DefaultRemoteProxy","role":"node","hub":"http://localhost:4444/grid/register","port":5555,"remoteHost":"http://192.168.0.20:5555","host":"192.168.0.20","maxSession":5,"hubHost":"localhost","registerCycle":5000,"hubPort":4444,"url":"http://192.168.0.20:5555","register":true},"capabilities":
[{"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"},
{"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"},
{"seleniumProtocol":"Selenium","browserName":"*iexplore","maxInstances":1,"platform":"MAC"},
{"seleniumProtocol":"WebDriver","browserName":"firefox","maxInstances":5,"platform":"MAC"},
{"seleniumProtocol":"WebDriver","browserName":"chrome","maxInstances":5,"platform":"MAC"},
{"seleniumProtocol":"WebDriver","browserName":"internet explorer","maxInstances":1,"platform":"MAC"}]}

which is the default configuration you get when you start the node using the standalone selenium java server via java -jar selenium-standalone.jar -role node -hub http://my-computer-ip:4444/grid/register. I see entries that use both Selenium as protocol and WebDriver for the same browser, but considering the spelling I believe WebDriver is used when specifying Chrome of Firefox in a DesiredCapabilities set.

arikon commented 9 years ago

@TheFifthFreedom Try to remove capabilities with seleniumProtocol=Selenium and let me know if it helps.

I'm planning to write integration tests using real WebDriver client and real Selenium nodes in addition to the unit test in #22.

TheFifthFreedom commented 9 years ago

As you suggested, I wrote a custom node configuration JSON without any seleniumProtocol=Selenium capabilities:

{
  "capabilities":
      [
        {
          "browserName": "firefox",
          "maxInstances": 5,
          "seleniumProtocol": "WebDriver"
        },
        {
          "browserName": "chrome",
          "maxInstances": 5,
          "seleniumProtocol": "WebDriver"
        },
        {
          "browserName": "internet explorer",
          "maxInstances": 1,
          "seleniumProtocol": "WebDriver"
        }
      ],
  "configuration":
  {
    "proxy": "org.openqa.grid.selenium.proxy.DefaultRemoteProxy",
    "maxSession": 5,
    "port": 5555,
    "host": ip,
    "register": true,
    "registerCycle": 5000,
    "hubPort": 4444,
    "hubHost": ip
  }
}

and started the node with it using java -jar selenium-server-standalone.jar -role node -nodeConfig nodeconfig.json. However, it doesn't seem to have made a difference - the same error pops up: [warn]: Could not create session because of error: [object Object].

arikon commented 9 years ago

@TheFifthFreedom Thanks! I will look into it. Already started to make integration testing infrastructure #35.

arikon commented 9 years ago

@TheFifthFreedom Could you try code from pull request #36? There should be real response from node in console instead of [object Object].

If it won't help, post more a bit more of logs here.

TheFifthFreedom commented 9 years ago

You were right @arikon : we've got a bit more to go on with the additions you made in https://github.com/selenodium/selenodium-grid/pull/36. Here's what the error looks like now:

[warn]: Could not create session because of error:
TypeError: Converting circular structure to JSON
    at Object.stringify (native)
    at /Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/driver/CommonImpl.js:40:58
From previous event:
    at module.exports.inherit.getNewSessionFromNode (/Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/driver/CommonImpl.js:39:19)
    at inherit.getNewSession (/Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/registry/NodeSlot.js:54:33)
    at /Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/registry/Node.js:113:25
    at /Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/q-async.js:22:14

Now at first glance it seems like there is a circular reference in the err from CommonImpl.js' getNewSessionFromNode:

getNewSessionFromNode: function(req, node) {
        var self = this,
            caps = self.getRequestCapabilities(req);

        // send open session request
        return self.proxyRequestToNode(req, node)
            .then(function(res) {
                // process response
                return self.parseProxyResponse(res);
            })
            .spread(function(sessionId, resCaps) {
                return {
                    sessionId: sessionId,
                    capabilities: resCaps,
                    desiredCapabilities: caps
                }
            })
            .catch(function(err) {
                var e = err.stack || err.message || JSON.stringify(err);
                log.debug('Error occured during session opening on node with ID=%s', node.getId());
                log.debug(e);
                return q.reject(err);
            });
    }

which means that when JSON.stringify(err) is called, the circular reference cannot be converted. Now there are ways to enable JSON to handle circular references (I'm thinking of https://github.com/WebReflection/circular-json), but this might not be the way to go, considering circular references can often simply be caused by errors and not what was originally intended to happen. So here's the err in question:

{ status: 500,
  version: '1.1',
  headers: 
   { date: 'Mon, 06 Apr 2015 15:40:35 GMT',
     server: 'Jetty/5.1.x (Mac OS X/10.10.2 x86_64 java/1.7.0_71',
     connection: 'close',
     expires: 'Thu, 01 Jan 1970 00:00:00 GMT',
     'cache-control': 'no-cache',
     'content-type': 'text/html',
     'content-length': '1237' },
  node: 
   { _readableState: 
      { highWaterMark: 16384,
        buffer: [],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: false,
        ended: true,
        endEmitted: false,
        reading: false,
        calledRead: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        objectMode: false,
        defaultEncoding: 'utf8',
        ranOut: false,
        awaitDrain: 0,
        readingMore: true,
        decoder: null,
        encoding: null },
     readable: true,
     domain: null,
     _events: 
      { end: [Object],
        error: [Object],
        data: [Function],
        readable: [Function] },
     _maxListeners: 10,
     socket: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        onend: null,
        destroyed: false,
        errorEmitted: false,
        bytesRead: 1496,
        _bytesDispatched: 328,
        _pendingData: null,
        _pendingEncoding: '',
        parser: null,
        _httpMessage: [Object],
        ondata: null },
     connection: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        onend: null,
        destroyed: false,
        errorEmitted: false,
        bytesRead: 1496,
        _bytesDispatched: 328,
        _pendingData: null,
        _pendingEncoding: '',
        parser: null,
        _httpMessage: [Object],
        ondata: null },
     httpVersion: '1.1',
     complete: true,
     headers: 
      { date: 'Mon, 06 Apr 2015 15:40:35 GMT',
        server: 'Jetty/5.1.x (Mac OS X/10.10.2 x86_64 java/1.7.0_71',
        connection: 'close',
        expires: 'Thu, 01 Jan 1970 00:00:00 GMT',
        'cache-control': 'no-cache',
        'content-type': 'text/html',
        'content-length': '1237' },
     trailers: {},
     _pendings: [],
     _pendingIndex: 0,
     url: '',
     method: null,
     statusCode: 500,
     client: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        onend: null,
        destroyed: false,
        errorEmitted: false,
        bytesRead: 1496,
        _bytesDispatched: 328,
        _pendingData: null,
        _pendingEncoding: '',
        parser: null,
        _httpMessage: [Object],
        ondata: null },
     _consuming: true,
     _dumped: false,
     httpVersionMajor: 1,
     httpVersionMinor: 1,
     upgrade: false,
     req: 
      { domain: null,
        _events: [Object],
        _maxListeners: 10,
        output: [],
        outputEncodings: [],
        writable: true,
        _last: true,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: true,
        sendDate: false,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _hangupClose: false,
        socket: [Object],
        connection: [Object],
        agent: [Object],
        socketPath: undefined,
        method: 'POST',
        path: '/wd/hub/session',
        _headers: [Object],
        _headerNames: [Object],
        _header: 'POST /wd/hub/session HTTP/1.1\r\naccept-encoding: identity\r\nconnection: close\r\ncontent-type: application/json;charset=UTF-8\r\naccept: application/json\r\ncontent-length: 111\r\nuser-agent: Python-urllib/3.4\r\nhost: 127.0.0.1:4444\r\n\r\n',
        _headerSent: true,
        parser: null,
        res: [Circular] },
     pipe: [Function],
     addListener: [Function],
     on: [Function],
     pause: [Function],
     resume: [Function],
     read: [Function] },
  nodeResponse: 
   { _readableState: 
      { highWaterMark: 16384,
        buffer: [],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: false,
        ended: true,
        endEmitted: false,
        reading: false,
        calledRead: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        objectMode: false,
        defaultEncoding: 'utf8',
        ranOut: false,
        awaitDrain: 0,
        readingMore: true,
        decoder: null,
        encoding: null },
     readable: true,
     domain: null,
     _events: 
      { end: [Object],
        error: [Object],
        data: [Function],
        readable: [Function] },
     _maxListeners: 10,
     socket: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        onend: null,
        destroyed: false,
        errorEmitted: false,
        bytesRead: 1496,
        _bytesDispatched: 328,
        _pendingData: null,
        _pendingEncoding: '',
        parser: null,
        _httpMessage: [Object],
        ondata: null },
     connection: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        onend: null,
        destroyed: false,
        errorEmitted: false,
        bytesRead: 1496,
        _bytesDispatched: 328,
        _pendingData: null,
        _pendingEncoding: '',
        parser: null,
        _httpMessage: [Object],
        ondata: null },
     httpVersion: '1.1',
     complete: true,
     headers: 
      { date: 'Mon, 06 Apr 2015 15:40:35 GMT',
        server: 'Jetty/5.1.x (Mac OS X/10.10.2 x86_64 java/1.7.0_71',
        connection: 'close',
        expires: 'Thu, 01 Jan 1970 00:00:00 GMT',
        'cache-control': 'no-cache',
        'content-type': 'text/html',
        'content-length': '1237' },
     trailers: {},
     _pendings: [],
     _pendingIndex: 0,
     url: '',
     method: null,
     statusCode: 500,
     client: 
      { _connecting: false,
        _handle: [Object],
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        onend: null,
        destroyed: false,
        errorEmitted: false,
        bytesRead: 1496,
        _bytesDispatched: 328,
        _pendingData: null,
        _pendingEncoding: '',
        parser: null,
        _httpMessage: [Object],
        ondata: null },
     _consuming: true,
     _dumped: false,
     httpVersionMajor: 1,
     httpVersionMinor: 1,
     upgrade: false,
     req: 
      { domain: null,
        _events: [Object],
        _maxListeners: 10,
        output: [],
        outputEncodings: [],
        writable: true,
        _last: true,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: true,
        sendDate: false,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _hangupClose: false,
        socket: [Object],
        connection: [Object],
        agent: [Object],
        socketPath: undefined,
        method: 'POST',
        path: '/wd/hub/session',
        _headers: [Object],
        _headerNames: [Object],
        _header: 'POST /wd/hub/session HTTP/1.1\r\naccept-encoding: identity\r\nconnection: close\r\ncontent-type: application/json;charset=UTF-8\r\naccept: application/json\r\ncontent-length: 111\r\nuser-agent: Python-urllib/3.4\r\nhost: 127.0.0.1:4444\r\n\r\n',
        _headerSent: true,
        parser: null,
        res: [Circular] },
     pipe: [Function],
     addListener: [Function],
     on: [Function],
     pause: [Function],
     resume: [Function],
     read: [Function] },
  nodeConnection: 
   { _connecting: false,
     _handle: 
      { fd: 16,
        writeQueueSize: 0,
        owner: [Circular],
        onread: [Function: onread],
        reading: true },
     _readableState: 
      { highWaterMark: 16384,
        buffer: [],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: false,
        ended: false,
        endEmitted: false,
        reading: true,
        calledRead: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        objectMode: false,
        defaultEncoding: 'utf8',
        ranOut: false,
        awaitDrain: 0,
        readingMore: false,
        decoder: null,
        encoding: null },
     readable: true,
     domain: null,
     _events: 
      { end: [Object],
        finish: [Function: onSocketFinish],
        _socketEnd: [Function: onSocketEnd],
        free: [Function],
        close: [Object],
        agentRemove: [Function],
        drain: [Function: ondrain],
        error: [Function: socketErrorListener],
        connect: undefined },
     _maxListeners: 10,
     _writableState: 
      { highWaterMark: 16384,
        objectMode: false,
        needDrain: false,
        ending: false,
        ended: false,
        finished: false,
        decodeStrings: false,
        defaultEncoding: 'utf8',
        length: 0,
        writing: false,
        sync: false,
        bufferProcessing: false,
        onwrite: [Function],
        writecb: null,
        writelen: 0,
        buffer: [] },
     writable: true,
     allowHalfOpen: false,
     onend: null,
     destroyed: false,
     errorEmitted: false,
     bytesRead: 1496,
     _bytesDispatched: 328,
     _pendingData: null,
     _pendingEncoding: '',
     parser: null,
     _httpMessage: 
      { domain: null,
        _events: [Object],
        _maxListeners: 10,
        output: [],
        outputEncodings: [],
        writable: true,
        _last: true,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: true,
        sendDate: false,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _hangupClose: false,
        socket: [Circular],
        connection: [Circular],
        agent: [Object],
        socketPath: undefined,
        method: 'POST',
        path: '/wd/hub/session',
        _headers: [Object],
        _headerNames: [Object],
        _header: 'POST /wd/hub/session HTTP/1.1\r\naccept-encoding: identity\r\nconnection: close\r\ncontent-type: application/json;charset=UTF-8\r\naccept: application/json\r\ncontent-length: 111\r\nuser-agent: Python-urllib/3.4\r\nhost: 127.0.0.1:4444\r\n\r\n',
        _headerSent: true,
        parser: null,
        res: [Object] },
     ondata: null },
  body: 
   { read: [Function],
     forEach: [Function],
     close: [Function],
     node: 
      { _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _maxListeners: 10,
        socket: [Object],
        connection: [Object],
        httpVersion: '1.1',
        complete: true,
        headers: [Object],
        trailers: {},
        _pendings: [],
        _pendingIndex: 0,
        url: '',
        method: null,
        statusCode: 500,
        client: [Object],
        _consuming: true,
        _dumped: false,
        httpVersionMajor: 1,
        httpVersionMinor: 1,
        upgrade: false,
        req: [Object],
        pipe: [Function],
        addListener: [Function],
        on: [Function],
        pause: [Function],
        resume: [Function],
        read: [Function] } } }

And it seems there are indeed repeating patterns, such as this one:

_connecting: false,
_handle: [Object],
_readableState: [Object],
readable: true,
domain: null,
_events: [Object],
_maxListeners: 10,
_writableState: [Object],
writable: true,
allowHalfOpen: false,
onend: null,
destroyed: false,
errorEmitted: false,
bytesRead: 1496,
_bytesDispatched: 328,
_pendingData: null,
_pendingEncoding: '',
parser: null,
_httpMessage: [Object],
ondata: null }

whose values may differ, but whose set of keys appear more than once. That's probably the cause of the error. There are other places where that structure conversion happens unchecked, like in SessionQueue.js:

process: function() {
        var self = this;
        return q(self.requests.toArray())
            .invoke('map', function(req) {
                var newSessionWaitTimeout = self.config.newSessionWaitTimeout || DEFAULT_NEW_SESSION_WAIT_TIMEOUT,
                    now = (new Date()).getTime(),
                    waitTime = now - req.since,
                    msg;

                if (self.config.throwOnCapabilityNotPresent && !self.nodes.hasCapability(req.req.capabilities)) {
                    msg = util.format('Cannot find capabilities for request (%s):\n%j', req.getId(), req.req.capabilities);
                } else if (newSessionWaitTimeout > -1 && waitTime >= newSessionWaitTimeout) {
                    msg = util.format('Request timed out waiting for a node to become available (%s)', req.getId());
                }

                if (msg) {
                    // reject previously saved defer
                    req.defer.reject(new Error(msg));
                    log.warn(msg);

                    // remove pending request from the list as timed out
                    self.removeRequest(req);
                    return;
                }

                return self.nodes.getNewSession(req.req)
                    .then(function(session) {
                        if (!session) {
                            return;
                        }

                        // resolve previously saved defer with newly created session
                        req.defer.resolve(session);

                        // remove pending request from the list as resolved
                        self.removeRequest(req);
                    })
                    .catch(function(err) {
                        var e = err.stack || err.message;
                        log.warn('Could not create session because of error:\n%s', e);
                    });
            })
            .all();
    }

Still though, this issue appears within the error handling of CommonImpl.js to deal with errors in session creation. Simply removing the JSON.stringify statements wouldn't result in the successful creation of a session yet.

arikon commented 9 years ago

@TheFifthFreedom Could you please try another fix from pr #36? There should be readable error from node in the console.

PS: btw do you have jabber account?

TheFifthFreedom commented 9 years ago

Yep - here's what I get this time:

[warn]: Could not create session because of error:
Error: Node responded with an error:
<html>
<head>
<title>Error 500 Read timed out</title>
</head>
<body>
<h2>HTTP ERROR: 500</h2><pre>Read timed out</pre>
<p>RequestURI=/wd/hub/session</p>
<p><i><small><a href="http://jetty.mortbay.org">Powered by Jetty://</a></small></i></p>

</body>
</html>
    at /Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/driver/CommonImpl.js:54:41
From previous event:
    at /Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/driver/CommonImpl.js:51:22
From previous event:
    at module.exports.inherit.getNewSessionFromNode (/Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/driver/CommonImpl.js:40:19)
    at inherit.getNewSession (/Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/registry/NodeSlot.js:54:33)
    at /Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/registry/Node.js:113:25
    at /Users/lmazou/Downloads/selenodium-grid-feature-session-creation-error/lib/q-async.js:22:14

And I do have jabber as a matter of fact! I'll send you my handle via private message.

arikon commented 9 years ago

@TheFifthFreedom So, the problem is with node. Could you post related node's logs here?

TheFifthFreedom commented 9 years ago

Here's the whole log from selenium-grid.log:

2015-04-07T14:15:06-0400 <info> log.js:54 Hub is listening on http://localhost:4444
2015-04-07T14:15:20-0400 <debug> log.js:60 ::ffff:127.0.0.1:59860 -->     GET /grid/api/hub HTTP/1.1
2015-04-07T14:15:20-0400 <debug> log.js:60 ::ffff:127.0.0.1:59860 <== 200 GET /grid/api/hub HTTP/1.1 -
2015-04-07T14:15:21-0400 <debug> log.js:60 ::ffff:127.0.0.1:59860 -->     POST /grid/register HTTP/1.1
2015-04-07T14:15:21-0400 <debug> log.js:60 Started monitoring for node with ID=http://192.168.0.20:5555; 5000ms interval
2015-04-07T14:15:21-0400 <info> log.js:54 Registered node with ID=http://192.168.0.20:5555
2015-04-07T14:15:21-0400 <debug> log.js:60 ::ffff:127.0.0.1:59860 <== 200 POST /grid/register HTTP/1.1 -
2015-04-07T14:15:26-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:15:26-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:15:26-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:15:26-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:15:31-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:15:31-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:15:31-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:15:31-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:15:36-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:15:36-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:15:36-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:15:36-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:15:41-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:15:41-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:15:41-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:15:41-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:15:46-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:15:46-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:15:46-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:15:46-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:15:51-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:15:51-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:15:51-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:15:51-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:15:56-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:15:56-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:15:56-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:15:56-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:01-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:01-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:01-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:01-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:06-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:06-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:06-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:06-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:11-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:11-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:11-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:11-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:15-0400 <debug> log.js:60 ::ffff:127.0.0.1:59930 -->     POST /wd/hub/session HTTP/1.1
2015-04-07T14:16:15-0400 <debug> log.js:60 Trying to open session for node with ID=http://192.168.0.20:5555
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:16:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:16:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:16:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*iexplore","maxInstances":1,"platform":"MAC"}
2015-04-07T14:16:16-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:16-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:16-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:16-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:21-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:21-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:21-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:21-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:26-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:26-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:26-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:26-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:31-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:31-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:31-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:31-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:36-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:36-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:36-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:36-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:41-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:41-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:41-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:41-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:46-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:46-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:46-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:46-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:51-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:51-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:51-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:51-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:16:56-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:16:56-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:16:56-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:16:56-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:01-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:01-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:01-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:01-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:06-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:06-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:06-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:06-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:11-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:11-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:11-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:11-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:15-0400 <debug> log.js:60 Error occured during session opening on node with ID=http://192.168.0.20:5555
2015-04-07T14:17:15-0400 <debug> log.js:60 Node responded with an error:
<html>
<head>
<title>Error 500 Read timed out</title>
</head>
<body>
<h2>HTTP ERROR: 500</h2><pre>Read timed out</pre>
<p>RequestURI=/wd/hub/session</p>
<p><i><small><a href="http://jetty.mortbay.org">Powered by Jetty://</a></small></i></p>

</body>
</html>

2015-04-07T14:17:15-0400 <warn> log.js:66 Could not create session because of error:
Error: Node responded with an error:
<html>
<head>
<title>Error 500 Read timed out</title>
</head>
<body>
<h2>HTTP ERROR: 500</h2><pre>Read timed out</pre>
<p>RequestURI=/wd/hub/session</p>
<p><i><small><a href="http://jetty.mortbay.org">Powered by Jetty://</a></small></i></p>

</body>
</html>
    at /Users/Laurent/Downloads/selenodium-grid-dev/lib/driver/CommonImpl.js:54:41
From previous event:
    at /Users/Laurent/Downloads/selenodium-grid-dev/lib/driver/CommonImpl.js:51:22
From previous event:
    at module.exports.inherit.getNewSessionFromNode (/Users/Laurent/Downloads/selenodium-grid-dev/lib/driver/CommonImpl.js:40:19)
    at inherit.getNewSession (/Users/Laurent/Downloads/selenodium-grid-dev/lib/registry/NodeSlot.js:54:33)
    at /Users/Laurent/Downloads/selenodium-grid-dev/lib/registry/Node.js:113:25
    at /Users/Laurent/Downloads/selenodium-grid-dev/lib/q-async.js:22:14
2015-04-07T14:17:15-0400 <debug> log.js:60 Trying to open session for node with ID=http://192.168.0.20:5555
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"}
2015-04-07T14:17:15-0400 <debug> log.js:60 Capabilities for slot on node with ID=http://192.168.0.20:5555 do not match
2015-04-07T14:17:15-0400 <debug> log.js:60 * desired capabilities: {"version":"","browserName":"firefox","platform":"ANY","javascriptEnabled":true}
2015-04-07T14:17:15-0400 <debug> log.js:60 * slot capabilities: {"seleniumProtocol":"Selenium","browserName":"*iexplore","maxInstances":1,"platform":"MAC"}
2015-04-07T14:17:16-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:16-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:16-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:16-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:21-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:21-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:21-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:21-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:26-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:26-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:26-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:26-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:31-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:31-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:31-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:31-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:36-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:36-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:36-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:36-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:41-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:41-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check
2015-04-07T14:17:41-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 -->     GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1
2015-04-07T14:17:41-0400 <debug> log.js:60 ::ffff:127.0.0.1:59866 <== 200 GET /grid/api/proxy?id=http://192.168.0.20:5555 HTTP/1.1 -
2015-04-07T14:17:46-0400 <debug> log.js:60 Checking status of node with ID=http://192.168.0.20:5555; timeout 2000ms
2015-04-07T14:17:46-0400 <debug> log.js:60 Node with ID=http://192.168.0.20:5555 returned 200 on status check

Until you submit another request to selenodium, the GET requests for node status lookup loop as you would expect. Interestingly, it looks like one of the reasons why a session cannot be instantiated and the request eventually times out is because the desiredCapabilities do not match, despite the fact that they should. In case you need them, here is the error trace for the job I sent to selenodium:

Laurents-iMac:Desktop Laurent$ python3 test.py
Traceback (most recent call last):
  File "test.py", line 7, in <module>
    desired_capabilities=DesiredCapabilities.FIREFOX)
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/site-packages/selenium/webdriver/remote/webdriver.py", line 73, in __init__
    self.start_session(desired_capabilities, browser_profile)
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/site-packages/selenium/webdriver/remote/webdriver.py", line 121, in start_session
    'desiredCapabilities': desired_capabilities,
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/site-packages/selenium/webdriver/remote/webdriver.py", line 173, in execute
    self.error_handler.check_response(response)
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/site-packages/selenium/webdriver/remote/errorhandler.py", line 136, in check_response
    raise exception_class(value)
selenium.common.exceptions.WebDriverException: Message: Error: Socket timed out after 60 seconds

As well as the job itself:

from selenium import webdriver
from selenium.webdriver.common.keys import Keys
from selenium.webdriver.common.desired_capabilities import DesiredCapabilities

driver = webdriver.Remote(
   command_executor='http://localhost:4444/wd/hub',
   desired_capabilities=DesiredCapabilities.FIREFOX)
driver.get("http://www.google.com")
#html = driver.execute_script('return document.body.innerHTML;')
html = driver.page_source
print (html)
driver.close()

which uses the Python wrapper for Selenium WebDriver. The selenium node which was started using selenium's standalone server remains however completely unchanged:

Laurents-iMac:Desktop Laurent$ java -jar selenium-server-standalone-2.44.0.jar -role node -hub http://localhost:4444/grid.register
14:15:20.689 INFO - Launching a selenium grid node
14:15:20.945 INFO - Java: Oracle Corporation 25.25-b02
14:15:20.945 INFO - OS: Mac OS X 10.10 x86_64
14:15:20.949 INFO - v2.44.0, with Core v2.44.0. Built from revision 76d78cf
14:15:20.981 INFO - Default driver org.openqa.selenium.ie.InternetExplorerDriver registration is skipped: registration capabilities Capabilities [{ensureCleanSession=true, browserName=internet explorer, version=, platform=WINDOWS}] does not match with current platform: MAC
14:15:20.996 INFO - RemoteWebDriver instances should connect to: http://127.0.0.1:5555/wd/hub
14:15:20.997 INFO - Version Jetty/5.1.x
14:15:20.998 INFO - Started HttpContext[/selenium-server,/selenium-server]
14:15:21.015 INFO - Started org.openqa.jetty.jetty.servlet.ServletHandler@319b92f3
14:15:21.015 INFO - Started HttpContext[/wd,/wd]
14:15:21.015 INFO - Started HttpContext[/selenium-server/driver,/selenium-server/driver]
14:15:21.015 INFO - Started HttpContext[/,/]
14:15:21.017 INFO - Started SocketListener on 0.0.0.0:5555
14:15:21.017 INFO - Started org.openqa.jetty.jetty.Server@4fe3c938
14:15:21.034 INFO - using the json request : {"class":"org.openqa.grid.common.RegistrationRequest","configuration":{"proxy":"org.openqa.grid.selenium.proxy.DefaultRemoteProxy","role":"node","hub":"http://localhost:4444/grid.register","port":5555,"remoteHost":"http://192.168.0.20:5555","host":"192.168.0.20","maxSession":5,"hubHost":"localhost","registerCycle":5000,"hubPort":4444,"url":"http://192.168.0.20:5555","register":true},"capabilities":[{"seleniumProtocol":"Selenium","browserName":"*firefox","maxInstances":5,"platform":"MAC"},{"seleniumProtocol":"Selenium","browserName":"*googlechrome","maxInstances":5,"platform":"MAC"},{"seleniumProtocol":"Selenium","browserName":"*iexplore","maxInstances":1,"platform":"MAC"},{"seleniumProtocol":"WebDriver","browserName":"firefox","maxInstances":5,"platform":"MAC"},{"seleniumProtocol":"WebDriver","browserName":"chrome","maxInstances":5,"platform":"MAC"},{"seleniumProtocol":"WebDriver","browserName":"internet explorer","maxInstances":1,"platform":"MAC"}]}
14:15:21.035 INFO - Starting auto register thread. Will try to register every 5000 ms.
14:15:21.035 INFO - Registering the node to hub :http://localhost:4444/grid/register
^C14:22:54.983 INFO - Shutting down...
arikon commented 9 years ago

@TheFifthFreedom Hmm. It is interesting. Will look into it later.

Here I wrote integration tests using wd library on node.js: https://github.com/selenodium/selenodium-grid/pull/35 And they work fine. You should try it your self.

arikon commented 9 years ago

@TheFifthFreedom Where is Firefox is installed on your machine?

TheFifthFreedom commented 9 years ago

Interestingly, the integration tests you wrote using wd in https://github.com/selenodium/selenodium-grid/pull/35 work beautifully. I even tried to borrow your test-integration/conf-node.json node config file you created for that test and pass it to a selenium node created via Selenium's java standalone server, to no avail. My Firefox is exactly where you would expect: in /Applications/Firefox.app. I even tried switching to Chrome in the DesiredCapabilities of my test (Chrome also being in Applications/Google Chrome.app and chromedriver being added to $path) - I'm still timing out :(

arikon commented 9 years ago

@TheFifthFreedom What versions do you use?

TheFifthFreedom commented 9 years ago

Firefox: 37.0.1 Chrome: 41.0.2272.118 Selenium Server: 2.45.0 standalone Chromedriver: 2.14

Each is up-to-date I believe...

TheFifthFreedom commented 9 years ago

Have you had any luck on your side running tests using Selenium's Client and WebDriver language bindings for Python, Ruby, Java etc.?

arikon commented 9 years ago

@TheFifthFreedom Sorry for late response. I thought, I sent comment already.

Could you help me create such a test (in Python, for example) in a separate repository on in a gist?

TheFifthFreedom commented 9 years ago

Of course! Here it is: https://gist.github.com/TheFifthFreedom/bcccf1e2eb8a5da05975 I quickly wrote it using Python's unittest. If you run it against the standard selenium server + node combination, it should run without a hitch. However, when using selenodium, you should see a socket timeout error.

arikon commented 9 years ago

@TheFifthFreedom Thanks! I've reproduced problem. Looking into it.

arikon commented 9 years ago

@TheFifthFreedom Could you please post here output of node -e 'console.log(process.versions)'?

TheFifthFreedom commented 9 years ago

Here's what I get:

{ http_parser: '1.0',
  node: '0.10.9',
  v8: '3.14.5.9',
  ares: '1.9.0-DEV',
  uv: '0.10.9',
  zlib: '1.2.3',
  modules: '11',
  openssl: '1.0.1e' }
arikon commented 9 years ago

@TheFifthFreedom I've got the same results for the latest node =(

{ http_parser: '1.0',
  node: '0.10.38',
  v8: '3.14.5.9',
  ares: '1.9.0-DEV',
  uv: '0.10.36',
  zlib: '1.2.8',
  modules: '11',
  openssl: '1.0.1m' }
arikon commented 9 years ago

I think the problem is somewhere near q-io/http module. But can't figure out where it is exactly.

arikon commented 9 years ago

@TheFifthFreedom I've found the root of the problem. The fix is on the way.

arikon commented 9 years ago

@TheFifthFreedom Could you try again with the latest dev code?

TheFifthFreedom commented 9 years ago

You did it! The node now instantiates a browser instance as it should - impressive stuff figuring that out @arikon . I did run into a issue running that Gist still, but it's an unrelated one, so I'll open a separate issue for it.