Phantomjs: PhantomJS 1.9.7 hangs intermittently

[afn]

I'm having an intermittent issue with phantomjs 1.9.7, where it occasionally hangs while trying to load a page. This occurs in the context of Poltergeist; see https://github.com/teampoltergeist/poltergeist/issues/375 for more background.

The symptom is that it never finishes loading the page. The output with --debug=true looks like this:

2014-05-15T22:58:46 [DEBUG] WebPage - updateLoadingProgress: 21
2014-05-15T22:58:46 [DEBUG] CookieJar - Saved "_closing_time_session=R3Npb2VTcDJCdVpmUW1YREczT0F0Um44MDJ1aW5vT3pTb21GNkxFdjJiUlBHV1RtMGV5SUFOaFlwUlhHaUw2eDZETnpDbEpYdkMyNEVYM3BtcGg5NlE9PS0tdVF0QUVZZ29QMVBDK2VnSTZQS3lhUT09--60c661c5317a96005a7d3a4ed9740257c174e01a; HttpOnly; domain=127.0.0.1; path=/"
2014-05-15T22:58:46 [DEBUG] CookieJar - Saved "browser.timezone=Etc%2FUTC; expires=Fri, 15-May-2015 22:58:46 GMT; domain=127.0.0.1; path=/"
2014-05-15T22:58:46 [DEBUG] Network - Resource request error: 99 ( "Connection to proxy refused" ) URL: "http://widget.uservoice.com/DQpcgONtvcxXS9T8bem0iw.js"

Note that the "Resource request error" is expected, because we set the proxy server to an invalid host (0.0.0.0) in order to avoid dependencies on hosts other than localhost. The bug occurs regardless of whether or not we do this, but we wanted to rule out external servers as a variable. When phantomjs is behaving normally, it prints the same output as above, followed by WebPage - updateLoadingProgress: 100.

In order to debug the problem, I recompiled phantomjs from source (62fbad4814df983c973511ded476c54dc09303c9) in debug mode.

Here are the backtraces of the currently running threads:

(gdb) info threads
  Id   Target Id         Frame
  5    Thread 0x7f5c04691700 (LWP 12361) "phantomjs" 0x00007f5c06d47d84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  4    Thread 0x7f5c03e90700 (LWP 12362) "QThread" 0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
  3    Thread 0x7f5c018e6700 (LWP 12367) "QThread" 0x00007f5c06d47d84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  2    Thread 0x7f5c02698700 (LWP 12564) "QThread" 0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
* 1    Thread 0x7f5c08d03740 (LWP 12360) "phantomjs" 0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6

(gdb) thread 1
[Switching to thread 1 (Thread 0x7f5c08d03740 (LWP 12360))]
#0  0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0  0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x0000000001d50e19 in qt_safe_select (nfds=10, fdread=0x3561c38, fdwrite=0x3561ed0, fdexcept=0x3562168, orig_timeout=0x7fff08787980) at kernel/qcore_unix.cpp:93
#2  0x0000000001d52ffa in QEventDispatcherUNIX::select (this=0x355beb0, nfds=10, readfds=0x3561c38, writefds=0x3561ed0, exceptfds=0x3562168, timeout=0x7fff08787980)
    at kernel/qeventdispatcher_unix.cpp:649
#3  0x000000000155b46c in QEventDispatcherQPA::select (this=0x355beb0, nfds=10, readfds=0x3561c38, writefds=0x3561ed0, exceptfds=0x3562168, timeout=0x7fff08787980)
    at kernel/qeventdispatcher_qpa.cpp:311
#4  0x0000000001d51a85 in QEventDispatcherUNIXPrivate::doSelect (this=0x3561a80, flags=..., timeout=0x7fff08787980) at kernel/qeventdispatcher_unix.cpp:223
#5  0x0000000001d53f86 in QEventDispatcherUNIX::processEvents (this=0x355beb0, flags=...) at kernel/qeventdispatcher_unix.cpp:936
#6  0x000000000155b16d in QEventDispatcherQPA::processEvents (this=0x355beb0, flags=...) at kernel/qeventdispatcher_qpa.cpp:246
#7  0x0000000001d20208 in QEventLoop::processEvents (this=0x7fff08787b20, flags=...) at kernel/qeventloop.cpp:149
#8  0x0000000001d20392 in QEventLoop::exec (this=0x7fff08787b20, flags=...) at kernel/qeventloop.cpp:200
#9  0x0000000001d230bb in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1221
#10 0x00000000014ed432 in QApplication::exec () at kernel/qapplication.cpp:3823
#11 0x0000000000424d4e in main (argc=8, argv=0x7fff08787dc8, envp=0x7fff08787e10) at main.cpp:121

(gdb) thread 2
[Switching to thread 2 (Thread 0x7f5c02698700 (LWP 12564))]
#0  0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0  0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x0000000001d50e19 in qt_safe_select (nfds=20, fdread=0x7f5bb401c6c8, fdwrite=0x7f5bb401c960, fdexcept=0x7f5bb401cbf8, orig_timeout=0x7f5c02697c50) at kernel/qcore_unix.cpp:93
#2  0x0000000001d52ffa in QEventDispatcherUNIX::select (this=0x7f5bb4001650, nfds=20, readfds=0x7f5bb401c6c8, writefds=0x7f5bb401c960, exceptfds=0x7f5bb401cbf8,
    timeout=0x7f5c02697c50) at kernel/qeventdispatcher_unix.cpp:649
#3  0x0000000001d51a85 in QEventDispatcherUNIXPrivate::doSelect (this=0x7f5bb401c510, flags=..., timeout=0x7f5c02697c50) at kernel/qeventdispatcher_unix.cpp:223
#4  0x0000000001d53f86 in QEventDispatcherUNIX::processEvents (this=0x7f5bb4001650, flags=...) at kernel/qeventdispatcher_unix.cpp:936
#5  0x0000000001d20208 in QEventLoop::processEvents (this=0x7f5c02697db0, flags=...) at kernel/qeventloop.cpp:149
#6  0x0000000001d20392 in QEventLoop::exec (this=0x7f5c02697db0, flags=...) at kernel/qeventloop.cpp:200
#7  0x0000000001c1586b in QThread::exec (this=0x4dc51a0) at thread/qthread.cpp:536
#8  0x0000000001c15a0a in QThread::run (this=0x4dc51a0) at thread/qthread.cpp:603
#9  0x0000000001c17fbb in QThreadPrivate::start (arg=0x4dc51a0) at thread/qthread_unix.cpp:338
#10 0x00007f5c06d43e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#11 0x00007f5c0625e3fd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#12 0x0000000000000000 in ?? ()

(gdb) thread 3
[Switching to thread 3 (Thread 0x7f5c018e6700 (LWP 12367))]
#0  0x00007f5c06d47d84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0  0x00007f5c06d47d84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x0000000001c195df in QWaitConditionPrivate::wait (this=0x38e58f0, time=18446744073709551615) at thread/qwaitcondition_unix.cpp:86
#2  0x0000000001c19389 in QWaitCondition::wait (this=0x38d9e50, mutex=0x38ce860, time=18446744073709551615) at thread/qwaitcondition_unix.cpp:158
#3  0x00000000004ea5e8 in WTF::ThreadCondition::wait(WTF::Mutex&) ()
#4  0x00000000004ea651 in WTF::ThreadCondition::timedWait(WTF::Mutex&, double) ()
#5  0x000000000110fcba in WTF::PassOwnPtr<WebCore::LocalStorageTask> WTF::MessageQueue<WebCore::LocalStorageTask>::waitForMessageFilteredWithTimeout<bool (WebCore::LocalStorageTask*)>(WTF::MessageQueueWaitResult&, bool (&)(WebCore::LocalStorageTask*), double) ()
#6  0x000000000110f81d in WTF::MessageQueue<WebCore::LocalStorageTask>::waitForMessage() ()
#7  0x000000000110f4d5 in WebCore::LocalStorageThread::threadEntryPoint() ()
#8  0x000000000110f4ac in WebCore::LocalStorageThread::threadEntryPointCallback(void*) ()
#9  0x0000000000e90863 in WTF::threadEntryPoint(void*) ()
#10 0x00000000004e9dbb in WTF::ThreadPrivate::run() ()
#11 0x0000000001c17fbb in QThreadPrivate::start (arg=0x389df40) at thread/qthread_unix.cpp:338
#12 0x00007f5c06d43e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#13 0x00007f5c0625e3fd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#14 0x0000000000000000 in ?? ()

(gdb) thread 4
[Switching to thread 4 (Thread 0x7f5c03e90700 (LWP 12362))]
#0  0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0  0x00007f5c06257763 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x0000000001d50d99 in qt_safe_select (nfds=8, fdread=0x7f5bfc000a98, fdwrite=0x7f5bfc000d30, fdexcept=0x7f5bfc000fc8, orig_timeout=0x0) at kernel/qcore_unix.cpp:83
#2  0x0000000001d52ffa in QEventDispatcherUNIX::select (this=0x7f5bfc0008c0, nfds=8, readfds=0x7f5bfc000a98, writefds=0x7f5bfc000d30, exceptfds=0x7f5bfc000fc8, timeout=0x0)
    at kernel/qeventdispatcher_unix.cpp:649
#3  0x0000000001d51a85 in QEventDispatcherUNIXPrivate::doSelect (this=0x7f5bfc0008e0, flags=..., timeout=0x0) at kernel/qeventdispatcher_unix.cpp:223
#4  0x0000000001d53f86 in QEventDispatcherUNIX::processEvents (this=0x7f5bfc0008c0, flags=...) at kernel/qeventdispatcher_unix.cpp:936
#5  0x0000000001d20208 in QEventLoop::processEvents (this=0x7f5c03e8fdb0, flags=...) at kernel/qeventloop.cpp:149
#6  0x0000000001d20392 in QEventLoop::exec (this=0x7f5c03e8fdb0, flags=...) at kernel/qeventloop.cpp:200
#7  0x0000000001c1586b in QThread::exec (this=0x35a2e40) at thread/qthread.cpp:536
#8  0x0000000001c15a0a in QThread::run (this=0x35a2e40) at thread/qthread.cpp:603
#9  0x0000000001c17fbb in QThreadPrivate::start (arg=0x35a2e40) at thread/qthread_unix.cpp:338
#10 0x00007f5c06d43e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#11 0x00007f5c0625e3fd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#12 0x0000000000000000 in ?? ()

(gdb) thread 5
[Switching to thread 5 (Thread 0x7f5c04691700 (LWP 12361))]
#0  0x00007f5c06d47d84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0  0x00007f5c06d47d84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00000000004e381b in WTF::TCMalloc_PageHeap::scavengerThread() ()
#2  0x00000000004e23ac in WTF::TCMalloc_PageHeap::runScavengerThread(void*) ()
#3  0x00007f5c06d43e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#4  0x00007f5c0625e3fd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#5  0x0000000000000000 in ?? ()

Any idea what's going wrong? I'll start digging into the source myself, but hopefully you're able to find the bug sooner than I. :)

Best,
Tony

[afn]

I added some extra debug output to the poltergeist scripts. From what I can tell, it calls open with a URL which starts the page load, and it never completes (not only does it not print the updateLoadingStatus message, but onLoadFinished is also not called).

[afn]

Poking around a bit in gdb...

set $pages = phantomInstance->m_pages.d
set $offset = $pages->begin
while $offset < $pages->end
  echo pages[
  output $offset
  echo ] = \ \

  set $webpage = (WebPage *) ((QPointer<WebPage> *) *(phantomInstance->m_pages.d.array+$offset))->o
  if $webpage == 0x0
    echo NULL
  else
    output *$webpage
  end

  echo \n
  set $offset = $offset + 1
end

Gives:

pages[0] = {<QObject> = {_vptr.QObject = 0x1dbe090, static staticMetaObject = {d = {superdata = 0x0, stringdata = 0x270f420 "QObject", data = 0x270f360, extradata = 0x345a1a0}}, static staticMetaObjectExtraData = {objects = 0x0, static_metacall = 0x1d3f4f2 <QObject::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>}, d_ptr = {d = 0x4487950}, static staticQtMetaObject = {d = {superdata = 0x0, stringdata = 0x271a2e0 "Qt", data = 0x2718000, extradata = 0x0}}}, <QWebFrame::PrintCallback> = {_vptr.PrintCallback = 0x1dbe120}, static staticMetaObject = {d = {superdata = 0x345a1c0, stringdata = 0x1dbd6a0 "WebPage", data = 0x1dbcf80, extradata = 0x1dbcd00}}, static staticMetaObjectExtraData = {objects = 0x0, static_metacall = 0x467248 <WebPage::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>}, m_customWebPage = 0x4487b70, m_networkAccessManager = 0x46a44b0, m_mainFrame = 0x46a16c0, m_currentFrame = 0x46a16c0, m_clipRect = {x1 = 0, y1 = 0, x2 = -1, y2 = -1}, m_scrollPosition = {xp = 0, yp = 0}, m_paperSize = {{d = 0x347dae0, e = 0x347dae0}}, m_libraryPath = {static null = {<No data fields>}, static shared_null = {ref = {_q_value = 4427}, alloc = 0, size = 0, data = 0x347db9a, clean = 0, simpletext = 0, righttoleft = 0, asciiCache = 0, capacity = 0, reserved = 0, array = {0}}, static shared_empty = {ref = {_q_value = 6}, alloc = 0, size = 0, data = 0x347dbba, clean = 0, simpletext = 0, righttoleft = 0, asciiCache = 0, capacity = 0, reserved = 0, array = {0}}, d = 0x46a5240, static codecForCStrings = 0x0}, m_inspector = 0x347da20, m_callbacks = 0x44990c0, m_navigationLocked = false, m_mousePos = {xp = 0, yp = 0}, m_ownsPages = true, m_loadingProgress = 0, m_shouldInterruptJs = false, m_cookieJar = 0x4499180}
pages[1] = NULL
pages[2] = NULL
pages[3] = NULL
pages[4] = NULL
pages[5] = NULL
pages[6] = NULL
pages[7] = NULL
pages[8] = NULL
pages[9] = NULL
pages[10] = NULL
pages[11] = NULL
pages[12] = NULL
pages[13] = NULL
pages[14] = NULL
pages[15] = NULL
pages[16] = NULL
pages[17] = NULL
pages[18] = NULL
pages[19] = NULL
pages[20] = NULL
pages[21] = NULL
pages[22] = NULL
pages[23] = NULL
pages[24] = NULL
pages[25] = NULL
pages[26] = NULL
pages[27] = NULL
pages[28] = NULL
pages[29] = NULL
pages[30] = {<QObject> = {_vptr.QObject = 0x1dbe090, static staticMetaObject = {d = {superdata = 0x0, stringdata = 0x270f420 "QObject", data = 0x270f360, extradata = 0x345a1a0}}, static staticMetaObjectExtraData = {objects = 0x0, static_metacall = 0x1d3f4f2 <QObject::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>}, d_ptr = {d = 0x6e7be10}, static staticQtMetaObject = {d = {superdata = 0x0, stringdata = 0x271a2e0 "Qt", data = 0x2718000, extradata = 0x0}}}, <QWebFrame::PrintCallback> = {_vptr.PrintCallback = 0x1dbe120}, static staticMetaObject = {d = {superdata = 0x345a1c0, stringdata = 0x1dbd6a0 "WebPage", data = 0x1dbcf80, extradata = 0x1dbcd00}}, static staticMetaObjectExtraData = {objects = 0x0, static_metacall = 0x467248 <WebPage::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>}, m_customWebPage = 0x7067430, m_networkAccessManager = 0x70bb4b0, m_mainFrame = 0x6f25c50, m_currentFrame = 0x6f25c50, m_clipRect = {x1 = 0, y1 = 0, x2 = -1, y2 = -1}, m_scrollPosition = {xp = 0, yp = 0}, m_paperSize = {{d = 0x347dae0, e = 0x347dae0}}, m_libraryPath = {static null = {<No data fields>}, static shared_null = {ref = {_q_value = 4427}, alloc = 0, size = 0, data = 0x347db9a, clean = 0, simpletext = 0, righttoleft = 0, asciiCache = 0, capacity = 0, reserved = 0, array = {0}}, static shared_empty = {ref = {_q_value = 6}, alloc = 0, size = 0, data = 0x347dbba, clean = 0, simpletext = 0, righttoleft = 0, asciiCache = 0, capacity = 0, reserved = 0, array = {0}}, d = 0x70bb290, static codecForCStrings = 0x0}, m_inspector = 0x6430313362343561, m_callbacks = 0x6d78d90, m_navigationLocked = false, m_mousePos = {xp = 0, yp = 0}, m_ownsPages = true, m_loadingProgress = 21, m_shouldInterruptJs = false, m_cookieJar = 0x4499180}

That last page is the one stuck with loadingProgress = 21.

Anything there look useful?

I was trying to dig in deeper but I'm getting stuck here:

(gdb) p $webpage->mainFrame()
$231 = (QWebFrame *) 0x6f25c50
(gdb) p *$webpage->mainFrame()
$232 = <incomplete type>

Looks like GDB doesn't have the symbols for the webkit code. Not sure why -- I can try to recompile phantomjs from scratch and see if maybe it's not passing "-g" when building webkit?

[afn]

I managed to get phantomjs compiled with debug symbols for everything (including webkit). I'm able to shed a bit more light onto what's happening, but it's still not entirely clear. So far the following appears to be true:

1. It hangs while trying to load http://127.0.0.1:53424/
2. There's one pending request to an image on the page, http://127.0.0.1:53424/assets/homepage_testimonial_pic_8.png
3. On the server side, I see a request for http://127.0.0.1:53424/assets/homepage_testimonial_pic_8.png at timestamp 1400703139. (Not clear whether or not the response was served.)
4. For some reason, it never completes this request.

I'd love it if someone with a deeper knowledge of the internals of webkit could take a look and let me know what else I should look at.

set $namp = * (QNetworkAccessManagerPrivate) *$webpage->mainFrame()->d->page->d->networkManager->d_ptr

(gdb) p $webpage->mainFrame()->d->frame->m_loader->m_isComplete
$99 = false
(gdb) p $webpage->mainFrame()->d->frame->m_loader->m_isLoadingMainResource
$100 = false

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requestCount
$104 = 1

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr
$194 = (WebCore::CachedResourceRequest *) 0xf578bbb8

(gdb) p * $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr
$195 = {<WTF::RefCounted<WebCore::CachedResourceRequest>> = {<WTF::RefCountedBase> = {
      m_refCount = 1}, <No data fields>}, <WebCore::SubresourceLoaderClient> = {
    _vptr.SubresourceLoaderClient = 0xa5303a8}, m_loader = {m_ptr = 0xf5448480},
  m_cachedResourceLoader = 0xf52f3090, m_resource = 0xf3f7e600, m_incremental = true,
  m_multipart = false, m_finishing = false}

response

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_responseTimestamp
$210 = 1400703139.3606279

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_response
$211 = {<WebCore::ResourceResponseBase> = {m_url = {m_string = {m_impl = {m_ptr = 0x0}}, m_isValid = false, m_protocolIsInHTTPFamily = false, m_schemeEnd = 0, m_userStart = 0, m_userEnd = 0, m_passwordEnd = 0, m_hostEnd = 0, m_portEnd = 0, m_pathAfterLastSlash = 0, m_pathEnd = 0, m_queryEnd = 0, m_fragmentEnd = 0}, m_mimeType = {m_impl = {m_ptr = 0x0}}, m_expectedContentLength = 0, m_textEncodingName = {m_impl = {m_ptr = 0x0}}, m_suggestedFilename = {m_impl = {m_ptr = 0x0}}, m_httpStatusCode = 0, m_httpStatusText = {m_impl = {m_ptr = 0x0}}, m_httpHeaderFields = {<WTF::HashMap<WTF::AtomicString, WTF::String, WTF::CaseFoldingHash, WTF::HashTraits<WTF::AtomicString>, WTF::HashTraits<WTF::String> >> = {m_impl = {static m_minTableSize = <optimized out>, static m_maxLoad = <optimized out>, static m_minLoad = <optimized out>, m_table = 0x0, m_tableSize = 0, m_tableSizeMask = 0, m_keyCount = 0, m_deletedCount = 0}}, <No data fields>}, m_lastModifiedDate = 0, m_wasCached = false, m_connectionID = 0, m_connectionReused = false, m_resourceLoadTiming = {m_ptr = 0x0}, m_resourceLoadInfo = {m_ptr = 0x0}, m_isNull = true, m_haveParsedCacheControlHeader = false, m_haveParsedAgeHeader = false, m_haveParsedDateHeader = false, m_haveParsedExpiresHeader = false, m_haveParsedLastModifiedHeader = false, m_cacheControlContainsNoCache = false, m_cacheControlContainsNoStore = false, m_cacheControlContainsMustRevalidate = false, m_cacheControlMaxAge = 0, m_age = 0, m_date = 0, m_expires = 0, m_lastModified = 0}, <No data fields>}

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_response->m_httpHeaderFields
$220 = {<WTF::HashMap<WTF::AtomicString, WTF::String, WTF::CaseFoldingHash, WTF::HashTraits<WTF::AtomicString>, WTF::HashTraits<WTF::String> >> = {m_impl = {static m_minTableSize = <optimized out>, static m_maxLoad = <optimized out>, static m_minLoad = <optimized out>, m_table = 0x0, m_tableSize = 0, m_tableSizeMask = 0, m_keyCount = 0, m_deletedCount = 0}}, <No data fields>}

request

(gdb) p *$webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_request
$214 = {<WTF::RefCounted<WebCore::CachedResourceRequest>> = {<WTF::RefCountedBase> = {m_refCount = 1}, <No data fields>}, <WebCore::SubresourceLoaderClient> = {_vptr.SubresourceLoaderClient = 0xa5303a8}, m_loader = {m_ptr = 0xf5448480}, m_cachedResourceLoader = 0xf52f3090, m_resource = 0xf3f7e600, m_incremental = true, m_multipart = false, m_finishing = false}

(gdb) x/120c $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_url.m_impl.m_ptr->m_data
0xf4f77be4:     104 'h' 0 '\000'        116 't' 0 '\000'        116 't' 0 '\000'        112 'p' 0 '\000'
0xf4f77bec:     58 ':'  0 '\000'        47 '/'  0 '\000'        47 '/'  0 '\000'        49 '1'  0 '\000'
0xf4f77bf4:     50 '2'  0 '\000'        55 '7'  0 '\000'        46 '.'  0 '\000'        48 '0'  0 '\000'
0xf4f77bfc:     46 '.'  0 '\000'        48 '0'  0 '\000'        46 '.'  0 '\000'        49 '1'  0 '\000'
0xf4f77c04:     58 ':'  0 '\000'        53 '5'  0 '\000'        51 '3'  0 '\000'        52 '4'  0 '\000'
0xf4f77c0c:     50 '2'  0 '\000'        52 '4'  0 '\000'        47 '/'  0 '\000'        97 'a'  0 '\000'
0xf4f77c14:     115 's' 0 '\000'        115 's' 0 '\000'        101 'e' 0 '\000'        116 't' 0 '\000'
0xf4f77c1c:     115 's' 0 '\000'        47 '/'  0 '\000'        104 'h' 0 '\000'        111 'o' 0 '\000'
0xf4f77c24:     109 'm' 0 '\000'        101 'e' 0 '\000'        112 'p' 0 '\000'        97 'a'  0 '\000'
0xf4f77c2c:     103 'g' 0 '\000'        101 'e' 0 '\000'        95 '_'  0 '\000'        116 't' 0 '\000'
0xf4f77c34:     101 'e' 0 '\000'        115 's' 0 '\000'        116 't' 0 '\000'        105 'i' 0 '\000'
0xf4f77c3c:     109 'm' 0 '\000'        111 'o' 0 '\000'        110 'n' 0 '\000'        105 'i' 0 '\000'
0xf4f77c44:     97 'a'  0 '\000'        108 'l' 0 '\000'        95 '_'  0 '\000'        112 'p' 0 '\000'
0xf4f77c4c:     105 'i' 0 '\000'        99 'c'  0 '\000'        95 '_'  0 '\000'        56 '8'  0 '\000'
0xf4f77c54:     46 '.'  0 '\000'        112 'p' 0 '\000'        110 'n' 0 '\000'        103 'g' 0 '\000'

===> http://127.0.0.1:53424/assets/homepage_testimonial_pic_8.png
     (confirmed that this resource loads immediately)

other

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_status
$224 = 1

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_type
$225 = 0

(gdb) p $webpage->mainFrame()->d->frame->m_doc.m_ptr->m_cachedResourceLoader.m_ptr->m_requests.m_impl.m_table[44].m_ptr->m_resource->m_preloadResult
$227 = 1

Is it normal for m_type to be zero?

[gtd]

I wish there was some way to elevate this bug and the fantastic debugging detail that @afn has provided above all the noise of other issues, the majority of which are very short on technical detail (eg. only a high-level language backtrace), and some significant portion of which is no doubt simple user error.

This issue is affecting a huge number of people, especially on popular ruby CIs, and appears to be a legit bug. I'd love to help in some way but my C skills are not going to quickly take me past what afn has done.

[afn]

@gtd Thanks for the +1.

For the time being, since I wasn't getting much traction with this issue, I've worked around the bug by having Capybara retry tests in the event of a Capybara::Poltgergeist::TimeoutError. See https://gist.github.com/afn/c04ccfe71d648763b306.

If we do get some interest on this bug, I'm more than happy to jump back in and help debug it further, but I'll need help from someone who is more intimately familiar with the phantomjs codebase than I.

[gkop]

:+1:, and thanks for your investigation @afn .

[AlreadyTalk]

Whit some tests, I detect what the my problem is. We can´t take a screenshot if the server its on the same machine.
I pass to explain. I try to take a screenshot from my machine (that is the server, its on development ) and it gives me the timeout. But if a try to take a screenshot from the same page, but its running on my associate machine, it works. I just don't now how to resolve this.
I'm using Poltergeist, Capybara and PhantomJS

[sdhull]

:+1: I don't have strong C skills, but this issue is constantly hindering my development cycle.

[c2c533c4f237]

Another +1 from me. I'm having to use a workaround, but I am worried it's causing further issues.

[pboling]

This is excellent. I will be able to retry my parallel spec setup again as this was the blocker. Thanks for the workaround @afn !

[Senjai]

@afn you are awesome.

[cyrilchampier]

+1

[rschooley]

This is still a problem.

[vitallium]

@rschooley could you please elaborate more on this? Version? 1.9.7? Try 1.9.8 or 2.0. OS?

[rschooley]

@Vitallium please see @afn's info, he has provided a comprehensive look at the issue. I am merely reporting that this still happens.

[bosunolanrewaju]

@Vitallium for me, the issue still exist. I'm using phamtomjs 1.9.8, OS 10.10 (Yosemite). I've tried everything stated here except the part of retrying the test after restarting phantomjs.

Using phantomjs 2.0 gives non-deterministic random test failures. Would love if anyone could offer help in getting this to work, most especially on CircleCI

[vitallium]

@andela-bolanrewaju could you please provide a minimal test case?

[vitallium]

@rschooley without a minimal _working_ test case I can't do much.

[rschooley]

@Vitallium I can't provide more than @afn already has, please see his verbose explanation

[RomanKapitonov]

The same issue for me
OS X Yosemite, phantom version 2.0
Phantomjs fails randomly when trying to visit a page

[lifeboatpres]

I rarely (less than 1% of the time) get a hang from PhantomJS when loading a page. I'm not waiting for the page to completely load; my short script tells it to assume the page is loaded after 8 seconds. I'm running PhantomJS 2.01 on Centos 6.6. I happened to get into a situation where it was hanging consistently on one site and I fixed it by calling PhantomJS with --debug=true. Note that once I had stopped the hanging problem, then I was able to get it to work at that same site without setting the debug option. Anyway, this is a workaround that may be useful to some people. (I redirect the massive amount of debug messages it produces to /dev/null.)

[jsarenik]

Hanging on CircleCI for me as well. Is there any progress? Was the main reason found yet? May I help? Thanks!

[dre-hh]

same issue here. visiting sites gives a timeout. However if you just ignore the error, the site is rendered correctly

[b6t]

+1 on Ubuntu 14.04, I have a script running every 2 hours, sometimes it closes properly and others it does not. Brings the cpu util up to 80% and i have to kill the hanging jobs b4 it, basically, locks the server up.

[oncletom]

I encounter some similar issue, a workaround:

timeout -k 5s 30s phantomjs script.js

It will force kill the process 5 seconds after a timeout of 30 seconds.

[vitallium]

Please upgrade to PhantomJS 2. 1.9.x is no longer supported, and known to have many crasher bugs that are fixed in 2 version.

[criticerz]

Upgrading to 2.1.1 fixed the timeout issue for me.

[jjb]

I still experience this issue with 2.1.1.