Finalizer thread is hanged waiting for CEF thread

[RuiGarcia]

Hello, everyone!

Some of our users recently (in the last couple of months) started to report hang-line scenarios in our application that uses CEF.
This issue was reported in two very different versions of the framework:
Our most recent version uses: CEF 3.3396.1777.g636f29b / Chromium 67.0.3396.79
While the older version is still using: 1.1364.1123
Unfortunately, we were never able to reproduce the reported issue in-house, so the only analysis we were able to perform is based on dump files.

Digging into the information in the dump file using windbg we can see the finalizer thread is hanged waiting for another thread.
The finalizer thread has the stack below. It is currently cleaning up the RCW list and trying to transition to thread df0 in order to cleanup the COM object wrapped by the RCW at the head of the list.

Code: Select all

0:002> !mex.t -c
DbgID ThreadID      User Kernel Create Time (UTC)
2     2324 (0n8996) 46ms     0s 10/12/2018 04:06:17.627 PM
 # Call Site                                           Info
 0 ntdll!ZwWaitForMultipleObjects+0x14
 1 KERNELBASE!WaitForMultipleObjectsEx+0xfe
 2 combase!MTAThreadWaitForCall+0xbd
 3 combase!MTAThreadDispatchCrossApartmentCall+0x17e   Target ThreadID: 0xdf0
 4 combase!CSyncClientCall::SwitchAptAndDispatchCall+0x34a
 5 combase!CSyncClientCall::SendReceive2+0x42c
 6 combase!SyncClientCallRetryContext::SendReceiveWithRetry+0x25
 7 combase!CSyncClientCall::SendReceiveInRetryContext+0x25
 8 combase!DefaultSendReceive+0x65
 9 combase!CSyncClientCall::SendReceive+0x2f9
 a combase!CClientChannel::SendReceive+0x84
 b combase!NdrExtpProxySendReceive+0x4e
 c rpcrt4!Ndr64pSendReceive+0x239
 d rpcrt4!NdrpClientCall3+0x8e9
 e combase!ObjectStublessClient+0x13b
 f combase!ObjectStubless+0x42
10 combase!CObjectContext::InternalContextCallback+0x252
11 combase!CObjectContext::ContextCallback+0x7f
12 clr!CtxEntry::EnterContext+0x287
13 clr!RCW::EnterContext+0x43
14 clr!RCWCleanupList::ReleaseRCWListInCorrectCtx+0xd5
15 clr!RCWCleanupList::CleanupAllWrappers+0x33fb04
16 clr!SyncBlockCache::CleanupSyncBlocks+0xcf
17 clr!Thread::DoExtraWorkForFinalizer+0x200
18 clr!FinalizerThread::FinalizerThreadWorker+0x91
19 clr!ManagedThreadBase_DispatchInner+0x39
1a clr!ManagedThreadBase_DispatchMiddle+0x6c
1b clr!ManagedThreadBase_DispatchOuter+0x75
1c clr!ManagedThreadBase_NoADTransition+0x3e
1d clr!ManagedThreadBase::FinalizerBase+0x3e
1e clr!FinalizerThread::FinalizerThreadStart+0x126
1f clr!Thread::intermediateThreadProc+0x86
20 kernel32!BaseThreadInitThunk+0x14
21 ntdll!RtlUserThreadStart+0x21


While the other thread (0xdf0) has the stack below. That thread is blocked waiting on an IOCompletion port:

Code: Select all

0:017> !Mex.t -c -t 0xdf0
DbgID ThreadID      User Kernel Create Time (UTC)
17    df0 (0n3568) 375ms  187ms 10/12/2018 04:06:24.479
# Call Site
0 ntdll!ZwRemoveIoCompletion+0x14
1 KERNELBASE!GetQueuedCompletionStatus+0x53
2 libcef!base::MessagePumpForIO::GetIOItem+0x43
3 libcef!base::MessagePumpForIO::WaitForIOCompletion+0x9e
4 libcef!base::MessagePumpForIO::WaitForWork+0x65
5 libcef!base::MessagePumpForIO::DoRunLoop+0x13d
6 libcef!base::MessagePumpWin::Run+0x68
7 libcef!base::RunLoop::Run+0x31
8 libcef!content::BrowserProcessSubThread::IOThreadRun+0x24
9 libcef!base::Thread::ThreadMain+0x19c
a libcef!base::`anonymous namespace'::ThreadFunc+0xf4
b kernel32!BaseThreadInitThunk+0x14
c ntdll!RtlUserThreadStart+0x21


We're kind of struggling to go any further on this issue. It is clear that CEF is waiting for something to finish, and until that happens, the process is stuck.
It would be great if anyone could shed some light of what is happening.
If you need any other details, please do not hesitate.
Any help is appreciated.

[RuiGarcia]

Hello, again.

We still did not find the root cause on the reported behavior but right now we know a bit more that what we did in November.
Keep in mind this issue is only reproducing in some of our user machines. So far, no internal machine reproduced it.
Curiously, machines that reproduce it will reproduce the issue consistently, suggesting this may be cause by something environmental.

Still, we were able to correlate the hang occurrence with a failed request from CEF.
When tracing every single request that leaves the problematic machines we noticed the existence of some failed requests (both 404 and 502).
These are requests to some resources of the page being rendered inside CEF.

With no other clues available, we decided to prevent those resources references from existing in the page (invalid fonts/images), and to our surprise the issue no longer reproduces.
This is behavior is consistent:
- If the invalid resource is there, the application will always hang.
- If the invalid resource is removed from the page code, the application will always work correctly (no hang).
That is the only difference between tests.

So going back to the threads, it appears thread 0xdf0 is waiting for something related with this failed request.
Could it be waiting for the answer to that request? Why would a failed request cause this? Why doesn't the thread takes the 404/502 and goes away?

Is there anyone that can comment on these findings?
Any help will be greatly appreciated.

[magreenblatt]

Does the problem reproduce under the same consitions using Google Chrome at the same version?

[RuiGarcia]

Hi, magreenblatt.

Thank you for showing interest in this issue.

Unfortunately, I will not be able to reproduce the same scenario inside Chrome.
We leverage CEF OnBeforeResourceLoad to successfully load our pages (to handle requests to resources directly from the application binaries), which means the page will just not work.

Meanwhile, we received some more information from Microsoft (through a support case we currently have opened).
According to MS, libcef is not pumping messages (or at least not doing it often enough) which ultimately causes the finalizer thread to hang (like the one in the first post waiting in ZwRemoveIoCompletion).
Does this mean anything to you?

Thank you.

[magreenblatt]

With no other clues available, we decided to prevent those resources references from existing in the page (invalid fonts/images), and to our surprise the issue no longer reproduces.

How were you loading these invalid resources previously? Were you intercepting or modifying the requests with OnBeforeResourceLoad (or similar)? Or were they going out over the network stack with no interception/modification by your application?

[RuiGarcia]

These resources were being inadvertently produced in the page being loaded inside CEF.
They were never loaded before because they never existed.

We were generating these URLs that did not exist, so CEF was ultimately trying to fetch them from the network. We found that out from the Fiddler trace.
When we realized their existence, we acknowledged that they are unnecessary and could be cleaned up but we never expected them to be directly tied to the reported behavior.

All resources being loaded by CEF are in fact intercepted by OnBeforeResourceLoad.
We do this to attempt to serve some resources from a local library, but such resource doesn't have a match, we fallback to the network.

As I said before we have confirmation that both 404 (non existent resource) and 502 (invalid URL format) errors cause this, so probably any error does it.

[magreenblatt]

So, just to be clear, your OnBeforeResourceLoad implementation does nothing (does not intercept) the problematic 404/502 requests?

[RuiGarcia]

Hi, magreenblatt.

Sorry for taking so long to reply.
I probably should have used the 'Notify me when a reply is posted' option.
Still, we had some developments on this matter in the mean time.

Indeed we have the OnBeforeResourceLoad implemented.
That code is not simple, but for the failing scenario it actually is.
In one of the problematic patterns we detected, the Web View attempts to load an URL like this:

Code: Select all

https://%22+%20getamyglobalbasedomain%28%29%20+%20%22/Customer/Picture.aspx?UserId=%22%20+%20GetUserId()

As you might expect, this is an invalid URL. In our OnBeforeResourceLoad implementation, when we try to create an URI object for this uri string (using Uri.TryCreate) the method returns false so we also exit OnBeforeResourceLoad returning false. According to the documentation, this causes CEF to attempt to resolve the same URL. We also see that attempt in the Fiddler trace.

From what we are able to see from the dumps, the CEF thread responsible for handling resources is non pumping any messages.
This is the thread that runs the OnBeforeResourceLoad and calls the Uri.TryCreate which actually creates an STA COM object (through createRCWInternal).
The fact that this thread is not pumping any messages is preventing the finalizer thread from switching back to it, and effectively cleaning up those STA COM objects.

Who's responsible for creating the message pump here?
Should we do something within OnBeforeResourceLoad to deal with this scenario?
Or should CEF be calling CoInitializeEx before executing our code?

Can you please comment on this?
Your help is deeply appreciated.
Thank you.

[magreenblatt]

OnBeforeResourceLoad is called on the Chromium IO thread. You should not be performing potentially blocking operations on this thread. CEF provides a CefParseURL function that is safe to use from this thread.

[ndesktop]

If you still need to use the COM STA, create it in UI thread. Or create it in IO thread, marshal into UI thread, and call methods there.
Otherwise you might resort to QueueUserAPC + SignalObjectAndWait if you need to call a function on the UI thread and wait with timeout in IO thread.

Or you can use CEF callbacks