Fwd: Internal server error from standalone server

[Rajat Jindal]

Hi Selenium-Developers,

Didn't got any answer from selenium-users, so trying my luck here.

Can you please help me debug this issue more. probably a way to get more logs or stacktrace.

On Saturday, 26 July 2014 00:07:17 UTC-7, Rajat Jindal wrote:

Hi Selenium-users,

I have been trying to debug an issue with Selenium server where it intermittently throws 500 internal server error. On running the tests in debug mode, I observed that even when httpd.js running on Firefox return 200 OK, the selenium server for some reason is throwing 500.

There is no stack trace printing which is blocking me from debugging this more, and therefore I am seeking your help.

My setup is:

Selenium standalone server 2.42.0

Firefox 29.0

CentOS 6.3

Quote from logs:

------------------------

0:45:57.633 DEBUG - new HttpConnection:
Socket[addr=/127.0.0.1,port=40385,localport=4444]
00:45:57.633 DEBUG - REQUEST from SocketL...@0.0.0.0:4444:
POST /wd/hub/session/79fb1869-e37b-46d9-9472-81400c099e83/execute HTTP/1.1
TE: deflate,gzip;q=0.3
Connection: TE, close
Accept: application/json
Host: localhost:4444
User-Agent: libwww-perl/5.833
Content-Type: application/json; charset=utf-8
Content-Length: 81


00:45:57.633 DEBUG - Try HttpContext[/wd,/wd],0
00:45:57.633 DEBUG - RestishHandler
org.openqa.jetty.jetty.servlet.ServletHandler@483bf400
00:45:57.633 DEBUG - servlet=/hub/*=WebDriver remote server
00:45:57.633 DEBUG - session=null
00:45:57.633 DEBUG - Handling: POST
/session/79fb1869-e37b-46d9-9472-81400c099e83/execute
00:45:57.634 INFO - Executing: [execute script: return eval("var x =
window.document.readyState;  x; ");, []])
00:45:57.638 DEBUG - Executing: executeScript
[06a774b6-9a18-4365-9c74-3befdce1966f, executeScript {script=return eval("var x
= window.document.readyState;  x; ");, args=[]}]
00:45:57.638 DEBUG - CookieSpec selected: best-match
00:45:57.638 DEBUG - Auth cache not set in the context
00:45:57.638 DEBUG - Connection request: [route:
{}->http://127.0.0.1:7081][total kept alive: 0; route allocated: 0 of 2000;
total allocated: 0 of 2000]
00:45:57.694 DEBUG - Connection leased: [id: 630614][route:
{}->http://127.0.0.1:7081][total kept alive: 0; route allocated: 1 of 2000;
total allocated: 1 of 2000]
00:45:57.694 DEBUG - Opening connection {}->http://127.0.0.1:7081
00:45:57.695 DEBUG - Connecting to /127.0.0.1:7081
00:45:57.696 DEBUG - Executing request POST
/hub/session/06a774b6-9a18-4365-9c74-3befdce1966f/execute HTTP/1.1
00:45:57.697 DEBUG - Target auth state: UNCHALLENGED
00:45:57.697 DEBUG - Proxy auth state: UNCHALLENGED
00:45:57.697 DEBUG - http-outgoing-630614 >> POST
/hub/session/06a774b6-9a18-4365-9c74-3befdce1966f/execute HTTP/1.1
00:45:57.698 DEBUG - http-outgoing-630614 >> Content-Type: application/json;
charset=utf-8
00:45:57.698 DEBUG - http-outgoing-630614 >> Content-Length: 81
00:45:57.699 DEBUG - http-outgoing-630614 >> Host: 127.0.0.1:7081
00:45:57.699 DEBUG - http-outgoing-630614 >> Connection: Keep-Alive
00:45:57.699 DEBUG - http-outgoing-630614 >> User-Agent:
Apache-HttpClient/4.3.2 (java 1.5)
00:45:57.700 DEBUG - http-outgoing-630614 >> Accept-Encoding: gzip,deflate
00:45:57.700 DEBUG - http-outgoing-630614 >> "POST
/hub/session/06a774b6-9a18-4365-9c74-3befdce1966f/execute HTTP/1.1[\r][\n]"
00:45:57.700 DEBUG - http-outgoing-630614 >> "Content-Type: application/json;
charset=utf-8[\r][\n]"
00:45:57.701 DEBUG - http-outgoing-630614 >> "Content-Length: 81[\r][\n]"
00:45:57.701 DEBUG - http-outgoing-630614 >> "Host: 127.0.0.1:7081[\r][\n]"
00:45:57.701 DEBUG - http-outgoing-630614 >> "Connection: Keep-Alive[\r][\n]"
00:45:57.702 DEBUG - http-outgoing-630614 >> "User-Agent:
Apache-HttpClient/4.3.2 (java 1.5)[\r][\n]"
00:45:57.702 DEBUG - http-outgoing-630614 >> "Accept-Encoding:
gzip,deflate[\r][\n]"
00:45:57.702 DEBUG - http-outgoing-630614 >> "[\r][\n]"
00:45:57.703 DEBUG - http-outgoing-630614 >> "{"args":[],"script":"return
eval(\"var x = window.document.readyState;  x; \");"}"

00:45:58.669 DEBUG - http-outgoing-630614 << "HTTP/1.1 200 OK[\r][\n]"
00:45:58.670 DEBUG - http-outgoing-630614 << "content-type: application/json;
charset=UTF-8[\r][\n]"
00:45:58.670 DEBUG - http-outgoing-630614 << "connection: close[\r][\n]"
00:45:58.670 DEBUG - http-outgoing-630614 << "content-length: 105[\r][\n]"
00:45:58.670 DEBUG - http-outgoing-630614 << "server: httpd.js[\r][\n]"
00:45:58.670 DEBUG - http-outgoing-630614 << "date: Sat, 26 Jul 2014 00:45:58
GMT[\r][\n]"

00:45:58.670 DEBUG - http-outgoing-630614 << "[\r][\n]"
00:45:58.670 DEBUG - http-outgoing-630614 << HTTP/1.1 200 OK
00:45:58.671 DEBUG - http-outgoing-630614 << content-type: application/json;
charset=UTF-8
00:45:58.671 DEBUG - http-outgoing-630614 << connection: close
00:45:58.671 DEBUG - http-outgoing-630614 << content-length: 105
00:45:58.671 DEBUG - http-outgoing-630614 << server: httpd.js
00:45:58.671 DEBUG - http-outgoing-630614 << date: Sat, 26 Jul 2014 00:45:58
GMT

00:46:02.623 DEBUG - http-outgoing-630614: Shutdown connection
00:46:02.649 DEBUG - Connection discarded
00:46:02.649 DEBUG - http-outgoing-630614: Close connection
00:46:02.649 DEBUG - Connection released: [id: 630614][route:
{}->http://127.0.0.1:7081][total kept alive: 0; route allocated: 0 of 2000;
total allocated: 0 of 2000]

00:46:02.649 DEBUG - Exception: [06a774b6-9a18-4365-9c74-3befdce1966f,
executeScript {script=return eval("var x = window.document.readyState;  x; ");,
args=[]}]
00:46:03.641 DEBUG - Finished: POST
/session/79fb1869-e37b-46d9-9472-81400c099e83/execute
00:46:03.642 DEBUG - Handled by
org.openqa.jetty.jetty.servlet.ServletHandler@483bf400
00:46:03.642 DEBUG - RESPONSE:
HTTP/1.1 500 Internal Server Error
Date: Sat, 26 Jul 2014 00:45:57 GMT
Server: Jetty/5.1.x (Linux/2.6.32-279.22.1.el6.centos.plus.x86_64 amd64
java/1.8.0_05
Connection: close
Expires: Thu, 01 Jan 1970 00:00:00 GMT
Cache-Control: no-cache
Cache-Control: no-cache
Expires: Thu, 01 Jan 1970 00:00:00 GMT
Content-Length: 1432
Content-Type: application/json; charset=utf-8

[Rajat Jindal]

I am still seeing this problem with Webdriver 2.42.2. Randomly webdriver will start giving 500 server errors and from the logs I figure that actually the request to webdriver standalone server is getting timed out after 3 minutes.

When I started to see this error, I spent sometime debugging:

1. On accessing GET localhost:4444/wd/hub, I was told that we have three sessions open.
2. I could not identify which port firefox httpd is using for those sessions though, so I tried random ports starting from 7055. 
3. Found that 3 ports were still responding to me. 7055-7057.
4. On trying to access GET localhost:<port>/hub/status, it sent me successful response back with some non-important info.
5. On trying to get all sessions ids on those ports using GET localhost:<port>/hub/sessions, I got command not supported
1. Can you please tell me how can I get all sessions from firefox httpd.js
6. On trying the session id's I got from step #1 using: GET localhost:<port>/hub/session/<sessionid>, I got error that session id don't exist.

Any pointers on how to debug this problem will be highly appreciated as this is blocking our progress on automation using webdriver.