Dismiss Notice

Register now to be one of the first members of this SharePoint Community! Click here it just takes seconds!

Dismiss Notice
Welcome Guest from Country Flag

DistributedCOM Event Logs

Discussion in 'Official Microsoft News' started by Carlo_Colombo, Apr 12, 2017.

Thread Status:
Not open for further replies.
  1. Carlo_Colombo

    Carlo_Colombo Guest

    Blog Posts:
    0
    DistributedCOM (DCOM) events 10000-1010 and 10028-10030 are written to the System Event Log when a DCOM activation fails. You can find information on these events on the web, however this information is scattered across multiple places, often incomplete, sometimes incorrect.

    In this post, I’ll try to (hopefully) bring some clarity to the subject.

    Background


    When a client calls a COM activation API (CoGetClassObject, CoCreateInstanceEx, CoGetInstanceFromFile, CoGetInstanceFromIStorage, IMoniker::BindToObject) and the component to be activated is out-of-process, several things happen.

    The COM runtime (ole32.dll or combase.dll, running in the process that called the COM activation API) contacts the local RpcSs service (display name “Remote Procedure Call (RPC)”).

    RpcSs determines if the component should be activated remotely. If so, the local RpcSs service forwards the request to the RpcSs service of the remote machine.

    If not, RpcSs determines if the process that hosts that COM object is already running (RpcSs keeps internal data structures for every running DCOM server). If it is, it uses its endpoint to send the activation request to the process.

    If the DCOM Server is not running, RpcSs sends the request to the local DcomLaunch service (display name “DCOM Server Process Launcher”) to execute the DCOM server that will host the desired component. DcomLaunch uses the CreateProcessXxx() APIs, or StartService() if the DCOM server has been configured to run as a service.

    Note: DcomLaunch exists for security reasons: the RpcSs service runs under the “Network Service” account. This account does not have all the required permissions to create processes with different identities. Therefore, it defers these operations to DcomLaunch, that runs under the “Local System” account.

    A DCOM Server can be a DCOM EXE server or a surrogate, including a COM+ server application. RpcSs first looks up the to-be-activated CLSID in the COM+ catalog. If it is not in the COM+ catalog, RpcSss searches the registry. Through these searches, RpcSs ultimately knows the name of the executable that should host the to-be-activated component.

    Unlike COM server DLLs, which export the function DllGetClassObject to allow clients to get the class factories of the components hosted in the DLL, COM EXE servers must explicitly register their class factories by calling CoRegisterClassObject for each component it hosts. The RpcSs service maintains a local table, binding CLSIDs to running processes. The function CoRegisterClassObject() connects to the local RpcSs to add an entry to the table.

    Note: the server can also call CoRegisterClassObject() using the REGCLS_SUSPENDED flag for every component, then register them all with RpcSs with CoResumeClassObjects(). This is more efficient if the COM server hosts many components.

    As you can see, several things happen during COM activation. Consequently, several things can potentially go wrong. The RpcSs and DcomLaunch services write events to the System event log when this happens. The event source of all these events is “DistributedCOM”. The event ID identifies what exactly went wrong.

    In the next section, we are having a look at these events, explaining when, and under which circumstances, each of them occurs. In the last section, we’ll explain how to troubleshoot them.

    Note: what is being said in the following applies to Windows 10. Other versions of Windows, in many respects, will behave in the same or a similar way.

    Events


    As said in the previous section, when a process calls a COM Activation API, the activation request is passed on to the local RpcSs service and, if the DCOM Server must be started, further on to the DcomLaunch service.

    If the DCOM Server is configured to be run with the identity of the caller (Activate as Activator, or “The Launching User” in Component Services):

    [​IMG]

    DcomLaunch will impersonate the caller of the COM Activation API, then call CreateProcessAsUser to create the DCOM Server process under that same identity. If CreateProcessAsUser() fails, this event log is created:

    MessageId=10000 Severity=Error SymbolicName=EVENT_RPCSS_CREATEPROCESS_FAILURE

    Unable to start a DCOM Server: %3.

    The error:%n”%%%2″%nHappened while starting this command:%n%1

    If the DCOM Server is configured to be run with a specific identity (“This user” in Component Services):

    [​IMG]

    DcomLaunch will first call LogonUserExExW to get the access token. If it fails, DcomLaunch logs this error:

    MessageId=10004 Severity=Error SymbolicName=
    EVENT_RPCSS_RUNAS_CANT_LOGIN

    DCOM got error “%%%1” and was unable to logon %2%3

    in order to run the server:%n%4

    Next, DcomLaunch calls CreateProcessAsUser to launch the process. If CreateProcessAsUser() fails, this event log is created:

    MessageId=10001 Severity=Error SymbolicName=
    EVENT_RPCSS_RUNAS_CREATEPROCESS_FAILURE

    Unable to start a DCOM Server: %3 as %4/%5.

    The error:%n”%%%2″%nHappened while starting this command:%n%1

    If the DCOM Server is configured to run as a service, StartService is called to start the service if needed. If StartService() fails, this event log is created:

    MessageId=10005 Severity=Error SymbolicName=EVENT_RPCSS_START_SERVICE_FAILURE

    DCOM got error “%%%1” attempting to start the service %2 with arguments “%3”

    in order to run the server:%n%4

    The error reported in the log is obtained by calling GetLastError(), if StartService() returns FALSE.

    Note:if the service is disabled, StartService() will fail but the above event is not logged.

    If the DCOM Server is configured as a service, and the service is running, but returned CO_E_SERVER_STOPPING when asked to activate a component (meaning that the service is being stopped), then RpcSs queries the service status to check if it eventually reaches the SERVICE_STOPPED or SERVICE_RUNNING status. If this does not happen within 4 minutes, the following event is logged:

    MessageId=10029 Severity=Error SymbolicName=
    EVENT_RPCSS_STOP_SERVICE_FAILURE

    The activation of the CLSID %1 timed out waiting for the service %2 to stop.

    in order to run the server:%n%4

    In COM+, it is possible to configure the application to be started under a debugger:

    [​IMG]

    With this configuration in place, DcomLaunch calls CreateProcessAsUser for the specified debugger. Should CreateProcessAsUser() fail, the following event is logged:

    MessageId=10030 Severity=Error SymbolicName=
    EVENT_RPCSS_CREATEDEBUGGERPROCESS_FAILURE

    Unable to start a COM Server for debugging: %3.

    The error:%n”%%%2″%nHappened while starting this command:%n%1

    The %3 argument is the CLSID of the component that is being activated, whereas %1 represents the command line that was passed to CreateProcessAsUser() to launch the debugger.

    If, on the other hand, the component is configured for activation on a remote machine:

    [​IMG]

    the local RpcSs defers the activation to the remote RpcSs. In this case, the first step of the local RpcSs is to establish a connection (an RPC binding) with the remote RpcSs. The connection is tried in several ways, using cached and uncached RPC binding handles, using client-specified security (if the client provided it) or trying all the available authentication packages and, if all of them fail, trying to establish an unauthenticated connection.

    If none of the above succeeds, this event is logged:

    MessageId=10028 Severity=Error SymbolicName=
    EVENT_RPCSS_REMOTE_SIDE_UNAVAILABLE_WITH_CLIENT_INFO

    DCOM was unable to communicate with the computer %1 using any of the configured protocols; requested by PID %2 (%3)

    Note: in older versions of Windows, the event is 10009 (EVENT_RPCSS_REMOTE_SIDE_UNAVAILABLE). Unlike EVENT_RPCSS_REMOTE_SIDE_UNAVAILABLE_WITH_CLIENT_INFO, EVENT_RPCSS_REMOTE_SIDE_UNAVAILABLE does not contain the PID of the client process that called the COM activation API.

    If the connection to the remote RpcSs succeeds, but the activation fails, the local RpcSs reports the failure using the events:

    MessageId=10006 Severity=Error SymbolicName=
    EVENT_RPCSS_REMOTE_SIDE_ERROR

    DCOM got error “%%%1” from the computer %2 when attempting to

    activate the server:%n%3


    MessageId=10008 Severity=Error SymbolicName=
    EVENT_RPCSS_REMOTE_SIDE_ERROR_WITH_FILE

    DCOM got error “%%%1” from the computer %2 when attempting to

    activate the server:%n%3 with file %4.

    If the previous steps succeed, the DCOM Server is started successfully. There is an additional, important step: the DCOM server (an executable, a service or the DLLHOST.EXE surrogate) must register its class factories by calling CoRegisterClassObject. RpcSs waits for this to happen within a period of 2 minutes, otherwise it logs the following event in the event log:

    MessageId=10010 Severity=Error SymbolicName=EVENT_RPCSS_SERVER_START_TIMEOUT

    The server %1 did not register with DCOM within the required timeout.

    Note: all the event logs reported above are subject to filtering: if ActivationFailureLoggingLevel is 2, or if it is 0 and the activation API is called with CLSCTX_NO_FAILURE_LOG, no entry is written to the event log. The default value is 0, and usually clients do not use CLSCTX_NO_FAILURE_LOG, so failures are logged by default.

    Troubleshooting


    The troubleshooting is heavily dependent on the event ID.

    If the Event ID is

    MessageId=10004 Severity=Error SymbolicName=
    EVENT_RPCSS_RUNAS_CANT_LOGIN

    DCOM got error “%%%1” and was unable to logon %2%3

    in order to run the server:%n%4

    this means, as said in the previous section, that the DCOM Server is configured with RunAs identity, RpcSs called LogonUserExExW() for that identity, but it failed.

    The error logged (%1) is the value returned by GetLastError(), and it gives additional information about what went wrong.

    Additional troubleshooting steps include double-checking that the username and password configured for the DCOM Server’s identity are valid, and that the account has not been disabled. Beware, in particular, of expired passwords. The security event log (Security Audit) can be a valid help to further troubleshoot this issue.

    A set of events indicate that the process creation failed:

    MessageId=10000 Severity=Error SymbolicName=EVENT_RPCSS_CREATEPROCESS_FAILURE

    Unable to start a DCOM Server: %3.

    The error:%n”%%%2″%nHappened while starting this command:%n%1


    MessageId=10001 Severity=Error SymbolicName=
    EVENT_RPCSS_RUNAS_CREATEPROCESS_FAILURE

    Unable to start a DCOM Server: %3 as %4/%5.

    The error:%n”%%%2″%nHappened while starting this command:%n%1


    MessageId=10005 Severity=Error SymbolicName=EVENT_RPCSS_START_SERVICE_FAILURE

    DCOM got error “%%%1” attempting to start the service %2 with arguments “%3”

    in order to run the server:%n%4

    These events mean that CreateProcessAsUser()/StartService() failed. Follow these steps to troubleshoot:

    1. The event log reports the error. This is the value returned by GetLastError() after the CreateProcessAsUser()/StartService() APIs failed. Often the error gives a valuable hint at what the problem is (access denied, file not found, etc).
    2. The command is reported in the event log. Verify that the executable is in the specified location. If the executable was deleted, or moved to a different location without being re-registered, RpcSs will pass the wrong path to CreateProcessAsUser(). Re-registering the DCOM Server fixes this problem.
    3. Verify that the executable has all its required dependencies. Be aware that some dependencies might work with your logged-in user path, but might not work with the path of another account (including the System account).
    4. Try launching the executable manually from the command line, or starting the service manually – if this is not working, you can investigate this directly.
    5. Verify that the executable does not have an Image File Execution Options (IFEO) key. If it does have such a key, and it has a “Debugger” named value, verify that the debugger listed is on the system path. A common mistake is to enter the name of the debugger without the full path in the Debugger value, and the folder is not in the PATH environment variable. This will cause CreateProcessAsUser() call from DcomLaunch to fail, with GetLastError() returning ERROR_FILE_NOT_FOUND (2), which is reported in the event log.
    6. If the server is configured with RunAs (“This user”) or Activate-As-Activator (“The launching user”), verify that this identity has access to the server executable, and all its dependencies. If not, the error reported in events 10000, 10001 and 10005 will be access denied (5) The caller of the activation API will receive an E_ACCESSDENIED return value.
    7. If the DCOM Server is implemented as a service, additional considerations apply:
      1. Make sure that the service is not disabled.
      2. The service startup may have run into trouble. This is unlikely if you are using a surrogate or a service written with ATL, because these services have well-tested service startup code. The section Debugging a Service Application in the “Debugging Tools for Windows” help has information on how to debug the service startup.

    If none of the above resolves the issue, it is possible to get more information by debugging RpcSs and DcomLaunch directly. This is risky, however, because they are key operating system processes. Debugging in the usual way (say, for instance, by using Visual Studio) will almost certainly bring to a hang of the machine, or a crash. So, debugging is usually done by using a debugger like cdb.exe (part of the Debugging Tools for Windows) that does not have a user interface, and by using a debugger script that drives the debugger, thus never blocking the debugged process. This is an advanced scenario, I don’t recommend doing it unless you are really a debugging expert. If things get to this point, you may also get in touch with Microsoft Support for additional assistance.

    We discussed the error

    MessageId=10029 Severity=Error SymbolicName=
    EVENT_RPCSS_STOP_SERVICE_FAILURE

    The activation of the CLSID %1 timed out waiting for the service %2 to stop.

    in order to run the server:%n%4

    in some detail in the previous section. The real cause of this error is a service that presumably hung while stopping. You can take a dump of the process while it is in this state, and analyze it with WinDbg (also part of the Debugging Tools for Windows).


    Another set of events applies to remote activation failure. The most likely cause of this event:

    MessageId=10028 Severity=Error SymbolicName=
    EVENT_RPCSS_REMOTE_SIDE_UNAVAILABLE_WITH_CLIENT_INFO

    DCOM was unable to communicate with the computer %1 using any of the configured protocols; requested by PID %2 (%3)

    is that the remote machine is unreachable. It could be no longer available, turned off, or disconnected from the network.

    The event log reports the name of the remote computer, so you can double-check that it is reachable from the machine where the event is logged.

    It is possible that this event occurs because of a COM activation that is no longer needed or wanted. For instance, the destination machine may have been decommissioned and replaced with a machine having a different name. To modify the identification of the remote machine for the COM activation, let’s first keep in mind that this information can be specified either declaratively in Component Services, as shown in the picture in the previous section, or programmatically, by providing in the COSERVERINFO structure in the COM Activation API. Note that the event does not provide the CLSID of the component that we are trying to activate.

    The events

    MessageId=10006 Severity=Error SymbolicName=
    EVENT_RPCSS_REMOTE_SIDE_ERROR

    DCOM got error “%%%1” from the computer %2 when attempting to

    activate the server:%n%3


    MessageId=10008 Severity=Error SymbolicName=
    EVENT_RPCSS_REMOTE_SIDE_ERROR_WITH_FILE

    DCOM got error “%%%1” from the computer %2 when attempting to

    activate the server:%n%3 with file %4.

    indicate a remote activation failure. This means that the connection to the remote RpcSs could be established successfully, however the activation request itself, issued by the remote RpcSs, failed.

    Note that, in this case, the remote machine may or may not log an event. For instance, if the activation failure on the remote machine is caused by the CLSID not being registered, there won’t be any corresponding event logged on the remote machine. If, on the other hand, the component is registered on the remote machine, but the executable is not found, the remote machine will log an event. In this case, the combination of the local and remote event contribute to give the complete picture. For instance:

    Local:

    Log Name: System

    Source: Microsoft-Windows-DistributedCOM

    Date: 4/12/2017 12:05:14 PM

    Event ID: 10006

    Task Category: None

    Level: Error

    Keywords: Classic

    User: Xxxx

    Computer: Yyyy

    Description:

    DCOM got error “2147942402” from the computer Zzzz when attempting to activate the server:

    {02ACA2A3-51F7-48FD-9246-5D0A84102414}


    Remote:

    Log Name: System

    Source: Microsoft-Windows-DistributedCOM

    Date: 4/12/2017 12:05:14 PM

    Event ID: 10000

    Task Category: None

    Level: Error

    Keywords: Classic

    User: Xxxx

    Computer: Zzzz

    Description:

    Unable to start a DCOM Server: {02ACA2A3-51F7-48FD-9246-5D0A84102414}. The error:

    “2”

    Happened while starting this command:

    “D:DCOMServerx64ReleaseDCOMServer.exe” -Embedding



    Last, the event

    MessageId=10010 Severity=Error SymbolicName=EVENT_RPCSS_SERVER_START_TIMEOUT

    The server %1 did not register with DCOM within the required timeout.

    indicates that the DCOM Server was successfully started by DcomLaunch (CreateProcessAsUser()/StartService() succeeded), but it failed to register its class factories within 2 minutes. This is typically an indication of a problem happening in the startup of the DCOM Server.

    If we rule out trivial errors in the code of the DCOM Server (for instance, having a code path that causes CoRegisterClassObject() not to be called), the issue can be of 3 types:

    • Crash at process startup
    • Deadlock at process startup
    • Macroscopic slowness at process startup

    You can easily tell if we are in scenario A. by monitoring the lifetime of the DCOM server: we are in scenario A. if it starts up and terminates soon after. You can use the Task Manager or a tool like Process Explorer to determine this. Scenario A. can be further troubleshot by using a tool like Windows Error Reporting or ProcDump or another debugger specified as postmortem debugger, that takes a dump of the process when the crash occurs.

    If, on the other hand, the DCOM Server stays alive until the event 10010 is logged, that means that we are in scenarios B. or C. Keep in mind that, after logging the 10010 event log, RpcSs kills the process (except if the DCOM Server runs as a service), if it hasn’t already died. RpcSs does this for a very good reason: by killing the process, the next COM activation request for the same CLSID, or a different CLSID hosted in the same DCOM Server, will cause a new process to be created, instead of directing the call to a running process that presumably hung. If the issue is a “once in a while” one, this makes it much more likely for the next activation request to succeed. However, you need to keep this in mind, when debugging the DCOM Server startup: if you attach a debugger to the process, the debuggee will likely be killed while you are debugging! A better approach in this case is to take a dump of the process in the time interval from the process startup until the DCOM event 10010 is logged.

    You can take the memory dump with Task Manager:

    [​IMG]

    Whatever the scenario A., B. or C. above, you end up with a user-mode dump of the DCOM Server. This can be analyzed with a debugger like WinDbg to find out the cause of the crash or the hang.

    Continue reading...
     
Thread Status:
Not open for further replies.

Share This Page

LiveZilla Live Chat Software