Skip to content
This repository has been archived by the owner on Nov 29, 2018. It is now read-only.

getText() can fail on 'found' element with InterruptedException #2913

Open
lukeis opened this issue Mar 3, 2016 · 20 comments
Open

getText() can fail on 'found' element with InterruptedException #2913

lukeis opened this issue Mar 3, 2016 · 20 comments

Comments

@lukeis
Copy link
Member

lukeis commented Mar 3, 2016

Originally reported on Google Code with ID 2913

Se 2.13 & Firefox 3.6.23

I'll work towards a reproduction, but here is a stack trace on the RemoteWebDriver
side of a divide:

java.lang.InterruptedException
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown
Source)
    at java.util.concurrent.FutureTask$Sync.innerGet(Unknown Source)
    at java.util.concurrent.FutureTask.get(Unknown Source)
    at org.openqa.selenium.remote.server.DefaultSession.execute(DefaultSession.java:139)
    at org.openqa.selenium.remote.server.handler.WebDriverHandler.handle(WebDriverHandler.java:44)
    at org.openqa.selenium.remote.server.rest.ResultConfig.handle(ResultConfig.java:188)
    at org.openqa.selenium.remote.server.DriverServlet.handleRequest(DriverServlet.java:573)
    at org.openqa.selenium.remote.server.DriverServlet.doGet(DriverServlet.java:503)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at org.openqa.selenium.remote.server.DriverServlet.service(DriverServlet.java:477)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.openqa.jetty.jetty.servlet.ServletHolder.handle(ServletHolder.java:428)
    at org.openqa.jetty.jetty.servlet.ServletHandler.dispatch(ServletHandler.java:677)
    at org.openqa.jetty.jetty.servlet.ServletHandler.handle(ServletHandler.java:568)
    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:243)
    at org.openqa.jetty.util.ThreadedServer.handle(ThreadedServer.java:357)
    at org.openqa.jetty.util.ThreadPool$PoolThread.run(ThreadPool.java:534)

The page in question is part static, and par dynamic (automatically loading immediately
after the initial page load).

The widget in question is found during the initial page load, but modified (somehow)
by the async stage.  findElement works just fine (with a waitFor).  getText() fails,
and one the browser side issues the exception above.  

By the time the exception arrives over the wire to the test-script side, it's been
wrapped in a totally generic WebDriverException.

- Paul

Reported by paul@hammant.org on 2011-11-22 22:42:50

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Reported by barancev on 2011-11-23 10:07:19

  • Labels added: Component-WebDriver, Lang-Java

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

This seems to happen not only on getText requests but also other situations.
Here's an occurrence of it during findElement:

10:15:24.843 INFO - Executing: [find element: By.selector: .automation-phone] at URL:
/session/1332436487875/element)
10:15:24.843 WARN - Exception thrown
java.lang.InterruptedException
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown
Source)
    at java.util.concurrent.FutureTask$Sync.innerGet(Unknown Source)
    at java.util.concurrent.FutureTask.get(Unknown Source)
    at org.openqa.selenium.remote.server.DefaultSession.execute(DefaultSession.java:139)
    at org.openqa.selenium.remote.server.handler.WebDriverHandler.handle(WebDriverHandler.java:44)
    at org.openqa.selenium.remote.server.rest.ResultConfig.handle(ResultConfig.java:196)
    at org.openqa.selenium.remote.server.DriverServlet.handleRequest(DriverServlet.java:577)
    at org.openqa.selenium.remote.server.DriverServlet.doPost(DriverServlet.java:528)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.openqa.selenium.remote.server.DriverServlet.service(DriverServlet.java:500)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.openqa.jetty.jetty.servlet.ServletHolder.handle(ServletHolder.java:428)
    at org.openqa.jetty.jetty.servlet.ServletHandler.dispatch(ServletHandler.java:677)
    at org.openqa.jetty.jetty.servlet.ServletHandler.handle(ServletHandler.java:568)
    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:243)
    at org.openqa.jetty.util.ThreadedServer.handle(ThreadedServer.java:357)
    at org.openqa.jetty.util.ThreadPool$PoolThread.run(ThreadPool.java:534)
10:15:24.843 WARN - Exception: null
10:15:25.359 INFO - Command request: captureScreenshot[c:\job_assets\shot_18.png, ]
on session 1332436487875
10:15:25.718 INFO - Got result: OK on session 1332436487875

Platform info:

10:14:47.531 INFO - Java: Sun Microsystems Inc. 20.6-b01
10:14:47.531 INFO - OS: Windows XP 5.1 x86
10:14:47.609 INFO - v2.18.0, with Core v2.18.0. Built from revision 15704

Reported by santiycr on 2012-03-22 18:26:26

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

v2.20 of Selenium - right Santiago?

I'm also seeing StaleElementReferenceException similarly failing.  I mean Failing on
the getText() immediately following a lookup.  Refer http://stackoverflow.com/questions/4846454/selenium-webdriver-staleelementreferenceexception
and similar.

Reported by paul@hammant.org on 2012-03-22 18:30:56

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Still haven't gotten of report of a user using 2.20.0, but I'd be surprised if it's
not there as I didn't see any commits related to this issue in the changelog.
Paul, did you repro in 2.20.0?

Reported by santiycr on 2012-03-22 18:41:12

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

At the bottom of http://code.google.com/p/selenium/issues/detail?id=2915 I have a script
that reproduces that one publically, and the issue is still in there for 2.20.  I feel
they are related somehow.

Reported by paul@hammant.org on 2012-03-22 18:56:02

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

With v2.20, I think the issue now manifests itself as:

    WebDriverException: Unable to get element text ...

All we did is findElement(id("foo")).getText(), and it barfs for out JavaServerFaces
app 1/4.  

If we slow the test down, or employ one of the waitFor strategies we can overcome it,
but it's curious.  The Element in question is not written dynamically.  The browser
is not slow (it, the runner, the tomcat instance, and the embedded H2 database are
all localhost). The machine is not resource constrained.


Reported by paul@hammant.org on 2012-03-22 21:51:34

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

OK, so the "Unable to get element text" is IE only (GetElementTextCommandHandler.h,
line 75). 

Reported by paul@hammant.org on 2012-03-23 14:23:00

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Just to confirm, we've seen these happen more commonly recently in our service. Our
customers report being unable to reproduce it reliably:

08:38:58.781 INFO - Executing: [find element: By.id: order_cc_user_id] at URL: /session/1334935956796/element)
08:38:58.781 WARN - Exception thrown
java.lang.InterruptedException
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown
Source)
    at java.util.concurrent.FutureTask$Sync.innerGet(Unknown Source)
    at java.util.concurrent.FutureTask.get(Unknown Source)
    at org.openqa.selenium.remote.server.DefaultSession.execute(DefaultSession.java:139)
    at org.openqa.selenium.remote.server.handler.WebDriverHandler.handle(WebDriverHandler.java:44)
    at org.openqa.selenium.remote.server.rest.ResultConfig.handle(ResultConfig.java:196)
    at org.openqa.selenium.remote.server.DriverServlet.handleRequest(DriverServlet.java:580)
    at org.openqa.selenium.remote.server.DriverServlet.doPost(DriverServlet.java:531)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.openqa.selenium.remote.server.DriverServlet.service(DriverServlet.java:503)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.openqa.jetty.jetty.servlet.ServletHolder.handle(ServletHolder.java:428)
    at org.openqa.jetty.jetty.servlet.ServletHandler.dispatch(ServletHandler.java:677)
    at org.openqa.jetty.jetty.servlet.ServletHandler.handle(ServletHandler.java:568)
    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:243)
    at org.openqa.jetty.util.ThreadedServer.handle(ThreadedServer.java:357)
    at org.openqa.jetty.util.ThreadPool$PoolThread.run(ThreadPool.java:534)
08:38:58.781 WARN - Exception: null

Reported by santiycr on 2012-04-22 17:59:14

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

I saw this exception happening every now and then in our CI environment. I believe we're
using selenium-server 2.21.0. This happens mostly with FireFox driver, but fine with
Chrome driver, IE sometimes has this issue too.

ANy update on this? I'd really like to know what the root cause might be and what I
can do on my automation side to eliminate it.

Reported by shirleyFeTroubleShoot on 2012-08-24 18:05:42

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Also seeing in 2.25  FF16

Reported by manasatr on 2013-03-05 21:34:59

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Hi!

According to http://stackoverflow.com/questions/4268457/future-get-gets-interrupted-always-with-an-interruptedexception
the reason of InterruptedException is that thread of future.get() is interrupted :)
before or during get()

But at least in source of 2.32 i have no many points of interruptions:
* session is interrupted by own interrupt() method
* requestHandler is interrupted by own stop() method
* [already commented] expirySessionCleaner interrupt session - this is commented about
year ago and according to last comment should be skipped.

i can't find who make this.

mye this coment helps.

Reported by a.u.savchuk on 2013-04-18 21:47:03

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Hi,

I can confirm this with Version v2.33.0, with Core v2.33.0. Built from revision 4e90c97.

Browser/Plattform: Windows 2008 Internet Explorer 9.0.8112.16421 

java.lang.InterruptedException
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown
Source)
    at java.util.concurrent.FutureTask$Sync.innerGet(Unknown Source)
    at java.util.concurrent.FutureTask.get(Unknown Source)
    at org.openqa.selenium.remote.server.DefaultSession.execute(DefaultSession.java:176)
    at org.openqa.selenium.remote.server.handler.WebDriverHandler.handle(WebDriverHandler.java:43)
    at org.openqa.selenium.remote.server.rest.ResultConfig.handle(ResultConfig.java:205)
    at org.openqa.selenium.remote.server.JsonHttpRemoteConfig.handleRequest(JsonHttpRemoteConfig.java:192)
    at org.openqa.selenium.remote.server.DriverServlet.handleRequest(DriverServlet.java:201)
    at org.openqa.selenium.remote.server.DriverServlet.doGet(DriverServlet.java:158)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at org.openqa.selenium.remote.server.DriverServlet.service(DriverServlet.java:139)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.openqa.jetty.jetty.servlet.ServletHolder.handle(ServletHolder.java:428)
    at org.openqa.jetty.jetty.servlet.ServletHandler.dispatch(ServletHandler.java:677)
    at org.openqa.jetty.jetty.servlet.ServletHandler.handle(ServletHandler.java:568)
    at org.openqa.jetty.http.HttpContext.handle(HttpContext.java:1526)
    at org.openqa.jetty.http.HttpContext.handle(HttpContext.java:1479)
    at org.openqa.jetty.http.HttpServer.service(HttpServer.java:914)
    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:243)
    at org.openqa.jetty.util.ThreadedServer.handle(ThreadedServer.java:357)
    at org.openqa.jetty.util.ThreadPool$PoolThread.run(ThreadPool.java:534)

Reported by mjeanrichard on 2013-07-30 06:10:26

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Reported by a.u.savchuk on 2013-08-15 19:12:43

  • Labels added: Component-Grid

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

We are also seeing it on FF 24  , mac 10.8.5.


[remote server] java.util.concurrent.locks.AbstractQueuedSynchronizer():-1:in `acquireSharedInterruptibly'
[remote server] java.util.concurrent.FutureTask$Sync():-1:in `innerGet'
[remote server] java.util.concurrent.FutureTask():-1:in `get'
[remote server] org.openqa.selenium.remote.server.DefaultSession(DefaultSession.java):176:in
`execute'
[remote server] org.openqa.selenium.remote.server.handler.WebDriverHandler(WebDriverHandler.java):43:in
`handle'
[remote server] org.openqa.selenium.remote.server.rest.ResultConfig(ResultConfig.java):205:in
`handle'
[remote server] org.openqa.selenium.remote.server.JsonHttpRemoteConfig(JsonHttpRemoteConfig.java):192:in
`handleRequest'
[remote server] org.openqa.selenium.remote.server.DriverServlet(DriverServlet.java):201:in
`handleRequest'
[remote server] org.openqa.selenium.remote.server.DriverServlet(DriverServlet.java):167:in
`doPost'
[remote server] javax.servlet.http.HttpServlet(HttpServlet.java):727:in `service'
[remote server] org.openqa.selenium.remote.server.DriverServlet(DriverServlet.java):139:in
`service'
[remote server] javax.servlet.http.HttpServlet(HttpServlet.java):820:in `service'
[remote server] org.openqa.jetty.jetty.servlet.ServletHolder(ServletHolder.java):428:in
`handle'
[remote server] org.openqa.jetty.jetty.servlet.ServletHandler(ServletHandler.java):677:in
`dispatch'
[remote server] org.openqa.jetty.jetty.servlet.ServletHandler(ServletHandler.java):568:in
`handle'
[remote server] org.openqa.jetty.http.HttpContext(HttpContext.java):1526:in `handle'
[remote server] org.openqa.jetty.http.HttpContext(HttpContext.java):1479:in `handle'
[remote server] org.openqa.jetty.http.HttpServer(HttpServer.java):914:in `service'
[remote server] org.openqa.jetty.http.HttpConnection(HttpConnection.java):820:in `service'
[remote server] org.openqa.jetty.http.HttpConnection(HttpConnection.java):986:in `handleNext'
[remote server] org.openqa.jetty.http.HttpConnection(HttpConnection.java):837:in `handle'
[remote server] org.openqa.jetty.http.SocketListener(SocketListener.java):243:in `handleConnection'
[remote server] org.openqa.jetty.util.ThreadedServer(ThreadedServer.java):357:in `handle'
[remote server] org.openqa.jetty.util.ThreadPool$PoolThread(ThreadPool.java):534:in
`run'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/response.rb:51:in
`assert_ok'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/response.rb:15:in
`initialize'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/http/common.rb:59:in
`new'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/http/common.rb:59:in
`create_response'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/http/default.rb:66:in
`request'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/http/common.rb:40:in
`call'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/bridge.rb:634:in
`raw_execute'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/bridge.rb:612:in
`execute'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/remote/bridge.rb:118:in
`setImplicitWaitTimeout'
/export/home/tester/.gem/ruby/1.8/ruby/1.8/gems/selenium-webdriver-2.35.0/lib/selenium/webdriver/common/timeouts.rb:14:in
`implicit_wait='
/export/home/tester/workspace/src/gui-tests/UITestFramework/selenium/base/linkedin_page_element.rb:768:in
`is_element_present'

Reported by manasatr on 2013-11-01 18:58:14

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Are there any updates on this? We are getting this issue every 10 or so build on our
CI environment. We have this issue with the firefox and chrome drivers.

Reported by james.a.pace on 2014-04-04 08:45:27

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

I am seeing this same issue returned from Sauce Labs, which is running 2.40.0.

Based on my analysis of the source code for that version, I see four possible suspects
that may have issued the interrupt:
 1. org.openqa.jetty.util.ThreadPool$PoolThread.poolClosing, line 470
 2. org.openqa.jetty.http.HttpConnection.close, line 277
 3. org.openqa.jetty.http.HttpTunnel$Copy.run, line 255
 4. org.openqa.grid.web.servlet.handler.RequestHandler.stop, line 257.

This is my first time reviewing the source code, so it's difficult for me to understand
which of these is most likely the culprit, or if there is some reason one or more of
these can be ruled out. However, I'm fairly confident that other usages of Thread.interrupt
in the selenium-server module (and its dependencies) can be ruled out.


Reported by technology@emergenttree.com on 2014-09-19 04:20:05

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Are you able to reproduce this reliably?

Reported by paul@hammant.org on 2014-09-19 04:24:29

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

After further review, (#3) HttpTunnel does not apply because we would have a stack frame
for HttpTunnel.handle.  Also (#4) grid.RequestHandler does not apply because we would
see a stack from for grid.DriverServlet, and instead we see remote.server.DriverServlet,
which is unrelated.  

It looks like (#2) HttpConnection.close might be ruled out because it is only called
by HttpConnection.destroy or by nio.SocketChannelListener.  Since the stack frame shows
SocketListener is in use rather than SocketChannelListener, then that's not a possible
source, and HttpConnection.destroy is only called otherwise by AJP (which is not in
use) and in its own handle() method, but after disassociateThread has set the field
to null.  Now, there is the possibility that (due to some concurrency bug) the HttpConnection
instance is associated with multiple threads, but that's a pretty far-fetched scenario
based on pure speculation.

That leaves the poolClosing (#1) as the likely culprit, which occurs when SocketListener.stop
is called, which occurs when HttpServer.doStop is called, which occurs if the Selenium
server process is being stopped, through whatever means.  

Therefore, my conclusion is that this exception will be sent to the RemoteWebDriver
client when an action is in progress at the time the RemoteWebDriver server is being
shutdown.  In this circumstance, I don't see that there are a lot of options -- the
server can return this exception, or it could silently close the connection, or I guess
it could wait a little while, but it can't wait forever for the action to complete,
or an administrator will forcibly terminate the process, which would silently reset
the connection.

What would be interesting to know is if this exception is being sent to clients when
the server is not in the process of shutting down.  In that case, either my analysis
is wrong, or the only possibility left is some concurrency bug in the Jetty SocketListener/HttpConnection
code, but again, I highly doubt this is the case.

TL;DR:

If you see this error, check to see if the RemoteWebDriver server was in the process
of shutting down.  If it wasn't, then it would be helpful to report your observations
of the state of the server that returned this exception.

Reported by technology@emergenttree.com on 2014-09-19 05:13:12

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Paul, I'm not in control of the servers that are producing this exception, since I'm
getting these responses from Sauce Labs.  I will follow up with Sauce Labs to understand
why I am getting this fairly frequently, and if I gain any useful information, then
hopefully I can report it back here.

Reported by technology@emergenttree.com on 2014-09-19 05:16:34

@lukeis
Copy link
Member Author

lukeis commented Mar 3, 2016

Reported by luke.semerau on 2015-09-17 17:44:26

  • Labels added: Restrict-AddIssueComment-Commit

@SeleniumHQ SeleniumHQ locked and limited conversation to collaborators Mar 4, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

1 participant