DCOM Garbage collection problem (Suspected)

From: Brian Price (brianp_at_appliedcs.com.au)
Date: 06/08/04 

Date: 7 Jun 2004 23:11:37 -0700

Hi all,

We have developed a Headless WinCE.NET based product that includes an
application that boots on start up. This application is implemented
using a number of Out-of-process COM servers working together.

Our problem is that when we did field tests the OS would boot, the
application would start up and a short period (matter of 10s of
seconds) later all of the COM servers would disappear. The only task
of our application left was the "service" task that was spawned
directly on boot via a call to CreateProcess().

We have been trying to reproduce this behaviour reliably in the
office. We now have a set that will reproduce it, but it takes between
20 and 100+ iterations before it fails. By adding debug logging code
to each of the COM servers and the service application, we have learnt
the following:

1. The service task still has COM pointers to the missing objects - it
uses CComPtr to manage the pointers. In other words, it has NOT
released it's references to the objects and so they should still
exist.
2. All of the COM servers are being shutdown in a controlled manner,
not by exceptions. All of our COM objects are built on ATL and their
FinalRelease() methods are being called.
3. Additional logging in two of the tasks is showing that their
IUnknown->Release() methods are being called until the object deletes
itself.

I have been trying to characterise the behaviour using a debug build
and the Platform Builder on a test device. As far as is practical, the
DUT and the field device load and operate the same software.

While doing one of these tests, a number of DEBUGCHK()s were hit
causing the debugger to be invoked several times. The interesting
thing that happened is that Cairole reported that it thought that the
client had died and so it was going to Run Down the Object (see PB
debug log below). However, the client was definitely still running.

Our application is started by an application (BootApp) that is started
by a registry key.
[HKEY_LOCAL_MACHINE\Init]
  "Launch70"="BootApp.exe"
  "Depend70"=hex:14,00

This means that it starts after device.exe starts and at approximately
the same time as services.exe.

My suspicion is that the DCOM object resolver which is used for
pinging clients is not initialised ( or possibly stable) when our
application starts up its COM servers. This leads to it erroneously
thinking that the clients had died and so does garbage collection.

My questions are
1. Is my analysis reasonable?
2. Is it feasible that DCOM garbage collection is causing my problem
of COM servers disappearing?
3. If so, is there any way to check that DCOM and its infrastructure
are up and running before launching COM servers? Or do I just have to
pause to allow the OS to stabilise before starting the application?

Thanks in Advance
Brian Price
Applied Controls

Start Platform Builder Debug Log
------------8<-----------------------
1108227 PID:81b02c92 TID:21946a76 0x81a92b88: 81b02c92.21946a76>
1108227 PID:81b02c92 TID:21946a76 0x81a92b88: Cairole:
1108227 PID:81b02c92 TID:21946a76 0x81a92b88: Running Down Object:
pStdId:42d80 pCtrlUnk:42a60
moid:{00000158-B3D2-40C5-0000-000007B0C540}
1108227 PID:81c80372 TID:41bb9dce 0x81bc96a0: OR: Set 00310B80's
client appears to have died
1108227 PID:e18c736e TID:41a848d6 0x81940000: e18c736e.41a848d6>
1108227 PID:e18c736e TID:41a848d6 0x81940000: Cairole:
1108227 PID:e18c736e TID:41a848d6 0x81940000: Running Down Object:
pStdId:43140 pCtrlUnk:42a60
moid:{0000016D-B418-40C5-0000-000007B0C540}
2058466 PID:81c80372 TID:61ae163e 0x818a6000: OR: Client specified
unknown OID(s). 00319010 082AFB68 082AFB78
3008723 PID:81c80372 TID:41bb9dce 0x81bc96a0: OR: Set 00318EF0's
client appears to have died
832533096 PID:61a94a86 TID:61a94db2 0x81950400: >>> Loading module
DBSERVER.EXE at address 0x14010000-0x1406C000

832533096 PID:81c80372 TID:c1c4406e 0x81a92000: Unknown: DEBUGCHK
failed in file d:\mckendric\private\dcom\ole32\dcomss\objex\wince\..\orclnt.cxx
at line 806

832533096 PID:81c80372 TID:c1c4406e 0x81a92000: OR: ping 00319010
failed 1912
833514617 PID:81c80372 TID:41786ce6 0x81b3baa8: Unknown: DEBUGCHK
failed in file d:\mckendric\private\dcom\ole32\dcomss\objex\wince\..\orclnt.cxx
at line 806

833514617 PID:81c80372 TID:41786ce6 0x81b3baa8: OR: ping 00319010
failed 1912
834498240 PID:81c80372 TID:61b8f6be 0x81974000: Console redirected to
COM1 for process 0x81C80372

834498240 PID:81c80372 TID:61b8f6be 0x81974000: 81c80372.61b8f6be>
834498240 PID:81c80372 TID:61b8f6be 0x81974000: Cairole: 834498240
PID:81c80372 TID:61b8f6be 0x81974000: GetServer returning
CO_E_SERVER_EXEC_FAILURE
834498240 PID:81c80372 TID:c1b3bef6 0x81aaa400: Unknown: DEBUGCHK
failed in file d:\mckendric\private\dcom\ole32\dcomss\objex\wince\..\orclnt.cxx
at line 806

834498240 PID:81c80372 TID:c1b3bef6 0x81aaa400: OR: ping 00319010
failed 1912
1966838558 PID:c1962f7e TID:c17ae54e 0x81a8f400: >>> Loading module
tlist.EXE at address 0x16010000-0x1603E000

1966838558 PID:81c80372 TID:c1b3bef6 0x81aaa400: OR: Process 00318270:
rundown status 0. 0 seconds for rundown, 1132340 waiting
1966838558 PID:81c80372 TID:c1b3bef6 0x81aaa400: Unknown: DEBUGCHK
failed in file d:\mckendric\private\dcom\ole32\dcomss\objex\wince\..\orclnt.cxx
at line 806

1966838558 PID:81c80372 TID:c1b3bef6 0x81aaa400: OR: ping 00319010
failed 1912
1966838558 PID:61a94a86 TID:61a94db2 0x81950400: Main thread in proc
61a94a86 (DBSERVER.EXE) faulted!

1966838558 PID:61a94a86 TID:61a94db2 0x81950400: Terminating process
61a94a86 (DBSERVER.EXE)!