Issue 1033 in selenium: java.lang.IllegalStateException: unexpected command json={command:"getHtmlSource",target:"",value:""} in place before new command getEval could be added
codesite...@google.com
Owner: ----
Labels: Type-Defect Priority-Medium
New issue 1033 by tatjana.guentner: java.lang.IllegalStateException:
unexpected command json={command:"getHtmlSource",target:"",value:""} in
place before new command getEval could be added
http://code.google.com/p/selenium/issues/detail?id=1033
We have a lot of tests running every night and sometimes (last time quite
often) some tests fail due to the following error exception:
21:32:52.924 ERROR - Exception running 'getEval 'command on session
79b5f260ff1d4684bced54f9b3f3d801
java.lang.IllegalStateException: unexpected command
json={command:"getHtmlSource",target:"",value:""} in place before new
command getEval could be added
at
org.openqa.selenium.server.CommandQueue.doCommandWithoutWaitingForAResponse(CommandQueue.java:121)
at
org.openqa.selenium.server.CommandQueue.doCommand(CommandQueue.java:98)
at
org.openqa.selenium.server.FrameGroupCommandQueueSet.doCommand(FrameGroupCommandQueueSet.java:425)
at
org.openqa.selenium.server.commands.SeleniumCoreCommand.execute(SeleniumCoreCommand.java:35)
at
org.openqa.selenium.server.SeleniumDriverResourceHandler.doCommand(SeleniumDriverResourceHandler.java:562)
at
org.openqa.selenium.server.SeleniumDriverResourceHandler.handleCommandRequest(SeleniumDriverResourceHandler.java:370)
at
org.openqa.selenium.server.SeleniumDriverResourceHandler.handle(SeleniumDriverResourceHandler.java:129)
at org.openqa.jetty.http.HttpContext.handle(HttpContext.java:1530)
at org.openqa.jetty.http.HttpContext.handle(HttpContext.java:1482)
at org.openqa.jetty.http.HttpServer.service(HttpServer.java:909)
at
org.openqa.jetty.http.HttpConnection.service(HttpConnection.java:820)
at
org.openqa.jetty.http.HttpConnection.handleNext(HttpConnection.java:986)
at
org.openqa.jetty.http.HttpConnection.handle(HttpConnection.java:837)
at
org.openqa.jetty.http.SocketListener.handleConnection(SocketListener.java:245)
at
org.openqa.jetty.util.ThreadedServer.handle(ThreadedServer.java:357)
at
org.openqa.jetty.util.ThreadPool$PoolThread.run(ThreadPool.java:534)
Our Environment:
Ubuntu 8.04.4 LTS
:~/tmp/selenium-remote-control-1.0.3/selenium-server-1.0.3$ java -jar
selenium-server.jar
14:06:37.079 INFO - Java: Sun Microsystems Inc. 10.0-b23
14:06:37.083 INFO - OS: Linux 2.6.24-27-generic i386
14:06:37.091 INFO - v2.0 [a2], with Core v2.0 [a2]
14:06:37.207 INFO - RemoteWebDriver instances should connect to:
http://10.10.10.42:4444/wd/hub
14:06:37.207 INFO - Version Jetty/5.1.x
14:06:37.211 INFO - Started
HttpContext[/selenium-server/driver,/selenium-server/driver]
14:06:37.211 INFO - Started HttpContext[/selenium-server,/selenium-server]
Please have a look into it.
codesite...@google.com
Comment #1 on issue 1033 by tatjana.guentner:
json={command:"getHtmlSource",target:"",value:""} in place before new
command getEval could be added
http://code.google.com/p/selenium/issues/detail?id=1033
More background information:
Shortly before the "unexpected command" error occurred, a call to getEval
did not return within the socket timeout configured in the Java VM, so a
SocketTimeoutException occurs on the client side of getEval, but Selenium
continues to service the getEval() on the server side (probably blocking
there for an unknown reason).
So, reproduction:
1. client -> getEval -> server
2. server processes getEval, does not return within socket read timeout
3. client getEval interrupted, SocketTimeoutException thrown
4. server continues processing getEval (does not know the client is no
longer waiting)
5. in time, client sends another command on the same selenium session (in
our case getHtmlSource
6. server refuses to processes getHtmlSource, because getEval is not
finished yet.
Don't know what Selenium could do better here, but surely a better
exception message or the ability to cancel the last command would be needed.
java.lang.UnsupportedOperationException: Catch body broken: IOException
from cmd=getHtmlSource -> java.net.SocketTimeoutException: Read timed out
at
com.thoughtworks.selenium.HttpCommandProcessor.executeCommandOnServlet(HttpCommandProcessor.java:110)
at
com.thoughtworks.selenium.HttpCommandProcessor.doCommand(HttpCommandProcessor.java:86)
at
com.thoughtworks.selenium.HttpCommandProcessor.getString(HttpCommandProcessor.java:262)
at
testplan.auto.selenium.AutoSelenium$ExceptionInterceptionProxy.invoke(AutoSelenium.java:1174)
at $Proxy0.getString(Unknown Source)
at
testplan.auto.selenium.AutoSelenium$AutoCommandProcessor.getString(AutoSelenium.java:1518)
at
com.thoughtworks.selenium.DefaultSelenium.getEval(DefaultSelenium.java:443)
...
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:687)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:632)
at
sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1000)
at
java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:373)
at
com.thoughtworks.selenium.HttpCommandProcessor.getResponseCode(HttpCommandProcessor.java:144)
at
com.thoughtworks.selenium.HttpCommandProcessor.getCommandResponseAsString(HttpCommandProcessor.java:164)
at
com.thoughtworks.selenium.HttpCommandProcessor.executeCommandOnServlet(HttpCommandProcessor.java:104)
... 53 more
codesite...@google.com
Comment #2 on issue 1033 by tatjana.guentner:
json={command:"getHtmlSource",target:"",value:""} in place before new
command getEval could be added
http://code.google.com/p/selenium/issues/detail?id=1033
more information:
Shortly before the "unexpected command" error occurred, a call to getEval
did not return within the socket timeout configured in the Java VM, so a
SocketTimeoutException occurs on the client side of getEval, but Selenium
continues to service the getEval() on the server side (probably blocking
there for an unknown reason).
So, reproduction:
1. client -> getEval -> server
2. server processes getEval, does not return within socket read timeout
3. client getEval interrupted, SocketTimeoutException thrown
4. server continues processing getEval (does not know the client is no
longer waiting)
5. in time, client sends another command on the same selenium session (in
our case getHtmlSource
6. server refuses to processes getHtmlSource, because getEval is not
finished yet.
Don't know what Selenium could do better here, but surely a better
exception message or the ability to cancel the last command would be needed.
The stack trace below shows the SocketTimeoutException when getEval was
done (we are using a patch version of Selenium to do more logging at lines
marked <<xxPATCHxx,
but this should not cause any adverse effect, we are just passing commands
through.
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:687)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:632)
at
sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1000)
at
java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:373)
at
com.thoughtworks.selenium.HttpCommandProcessor.getResponseCode(HttpCommandProcessor.java:144)
at
com.thoughtworks.selenium.HttpCommandProcessor.getCommandResponseAsString(HttpCommandProcessor.java:164)
at
com.thoughtworks.selenium.HttpCommandProcessor.executeCommandOnServlet(HttpCommandProcessor.java:104)
at
com.thoughtworks.selenium.HttpCommandProcessor.doCommand(HttpCommandProcessor.java:86)
at
com.thoughtworks.selenium.HttpCommandProcessor.getString(HttpCommandProcessor.java:262)
at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
xxPATCHxx
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
<<<xxPATCHxx
at java.lang.reflect.Method.invoke(Method.java:597) <<xxPATCHxx
at
testplan.auto.selenium.AutoSelenium$ExceptionInterceptionProxy.invoke(AutoSelenium.java:1164)
<<xxPATCHxx
at $Proxy0.getString(Unknown Source) <<xxPATCHxx
at
testplan.auto.selenium.AutoSelenium$AutoCommandProcessor.getString(AutoSelenium.java:1518)
<<xxPATCHxx
at
com.thoughtworks.selenium.DefaultSelenium.getEval(DefaultSelenium.java:443)