none
COM+ services (ServicedComponent). RPC fails after 15 min on idle.

    Question

  • I'm facing a weird issue with COM+ RPC calls using .NET 2.0. Initially it works fine. I'm able to call "Execute" method, and everything is OK. But If I leave the client app for ~15 minutes idle and then try to execute the same method I receive and InvalidCastException:

        Unable to cast object of type 'System.__ComObject' to type 'IMyInterface'.

    What is more interesting I receive that exception on "Execute", not on MyClass object creation, but when try to call the "**Execute**" method. And what is even more interesting that - Retrying to call "**Execute**" works fine.


    Here is what I have (in pseudo code):

    1. Client Side:

            namespace Client
            {

              [Guid("8C359E46....")]
              public interface IClientClass
             {
                   public int MyFunction(int a, int b, int c, int d, string e);
             }

               [Guid("F399E46....")]
               [ClassInterface(ClassInterfaceType.None)]
               public  class ClientClass : IClientClass {
                   public int MyFunction(int a, int b, int c, int d, string e)
                   {
                         MiddleTier.MyClass cmd = new MiddleTier.MyClass();
                        try {
                              cmd.Execute(a, b,c, d, e); // Here I got InvalidCastException
                        catch(Exception ex) {
                            cmd.Execute(a, b,c, d, e); // AND THAT WORKS !!!
                        }
                    }
                }
            }

    2. Server Side:

            namespace MiddleTier {  
                [Guid("1061FDCF....")]           
                public interface IMyInterface
                {
                    int Execute(int a, int b, int c, int d, string e);
                }

                [Guid("F051FE7F....")]
                [ProgId("MyInterface")]
                [ClassInterface(ClassInterfaceType.None)]
                [ComponentAccessControl(true)]
                [SecureMethod]
                [SecurityRole("MyRole_1")]
                [SecurityRole("MyRole_3")]
                public class MyClass: ServicedComponent, IMyInterface
                {
                    public int Execute(int a, int b, int c, int d, string e)
                    {
                       do some stuff ... but I never get here
                    }
               }
        }

    Since as I said retrying fixes the problem I suppose something got lost in CLient<--> Comunication. Using the WireShark I traced the Network and found that one call from client to server is missing:
    Client:

        No.     Current Time                Time           Source                Destination           Protocol Length Info
         27 2017/319 03:44:02.469243    0.074277       172.68.51.18          172.68.32.43          DCERPC   242    Request: call_id: 11, Fragment: Single, opnum: 5, Ctx: 0
         28 2017/319 03:44:02.469719    0.074753       172.68.32.43          172.68.51.18          DCERPC   130    Response: call_id: 11, Fragment: Single, Ctx: 0    
         29 2017/319 03:44:02.481162    0.086196       172.68.51.18          172.68.32.43          ISystemActivator 822    RemoteCreateInstance request
         30 2017/319 03:44:02.482876    0.087910       172.68.32.43          172.68.51.18          ISystemActivator 1102   RemoteCreateInstance response

    That is missing in the server(call_id:5):

        31 2017/319 03:44:02.483569    0.088603       172.68.51.18                 172.68.32.43          DCERPC   258    Request: call_id: 5, Fragment: Single, opnum: 3, Ctx: 0

    And later we will receive Retransmission and Reset:

         32 2017/319 03:44:02.518367    0.123401       172.68.51.18          172.68.32.43          TCP      54     59068 → 49409 [ACK] Seq=885 Ack=5717 Win=1026 Len=0
         33 2017/319 03:44:02.534021    0.139055       172.68.51.18          172.68.32.43          TCP      54     59070 → 135 [ACK] Seq=3905 Ack=2887 Win=261632 Len=0
         34 2017/319 03:44:02.784041    0.389075       172.68.51.18          172.68.32.43          TCP      258    [TCP Retransmission] 58927 → 49313 [PSH, ACK] Seq=1 Ack=1 Win=1023 Len=204
         35 2017/319 03:44:03.393448    0.998482       172.68.51.18          172.68.32.43          TCP      258    [TCP Retransmission] 58927 → 49313 [PSH, ACK] Seq=1 Ack=1 Win=1023 Len=204
         36 2017/319 03:44:04.596544    2.201578       172.68.51.18          172.68.32.43          TCP      258    [TCP Retransmission] 58927 → 49313 [PSH, ACK] Seq=1 Ack=1 Win=1023 Len=204
         37 2017/319 03:44:07.002827    4.607861       172.68.51.18          172.68.32.43          TCP      258    [TCP Retransmission] 58927 → 49313 [PSH, ACK] Seq=1 Ack=1 Win=1023 Len=204
         38 2017/319 03:44:11.815440    9.420474       172.68.51.18          172.68.32.43          TCP      258    [TCP Retransmission] 58927 → 49313 [PSH, ACK] Seq=1 Ack=1 Win=1023 Len=204
         39 2017/319 03:44:13.941280    11.546314      172.68.51.18          172.68.32.43          TCP      54     59070 → 135 [FIN, ACK] Seq=3905 Ack=2887 Win=261632 Len=0
         40 2017/319 03:44:13.941734    11.546768      172.68.32.43          172.68.51.18          TCP      60     135 → 59070 [ACK] Seq=2887 Ack=3906 Win=131328 Len=0
         41 2017/319 03:44:13.941795    11.546829      172.68.32.43          172.68.51.18          TCP      60     135 → 59070 [FIN, ACK] Seq=2887 Ack=3906 Win=131328 Len=0
         42 2017/319 03:44:13.941813    11.546847      172.68.51.18          172.68.32.43          TCP      54     59070 → 135 [ACK] Seq=3906 Ack=2888 Win=261632 Len=0
         43 2017/319 03:44:21.425215    19.030249      172.68.51.18          172.68.32.43          TCP      54     58927 → 49313 [RST, ACK] Seq=205 Ack=1 Win=0 Len=0
         44 2017/319 03:44:21.425429    19.030463      172.68.51.18          172.68.32.43          TCP      54     58945 → 49313 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0

    2. Server Logs:

            7    2017/319 01:44:02.439476    0.010402    172.16.32.43     172.16.51.18    DCERPC    315    Bind_ack: call_id: 115, Fragment: Single, max_xmit: 5840 max_recv: 5840, 2 results: Acceptance, Negotiate ACK
            8    2017/319 01:44:02.448022    0.018948    172.16.51.18    172.16.32.43    DCERPC    274    Alter_context: call_id: 115, Fragment: Single, 1 context items: ISystemActivator V0.0 (32bit NDR)
            9    2017/319 01:44:02.448383    0.019309    172.16.32.43    172.16.51.18    DCERPC    159    Alter_context_resp: call_id: 115, Fragment: Single, max_xmit: 5840 max_recv: 5840, 1 results: Acceptance
            10    2017/319 01:44:02.460395    0.031321    172.16.51.18    172.16.32.43    ISystemActivator    870    RemoteCreateInstance request
            11    2017/319 01:44:02.461425    0.032351    172.16.32.43    172.16.51.18    ISystemActivator    1526    RemoteCreateInstance response

    **and here we should have call_id:5, but we don't**

            12    2017/319 01:44:02.468969    0.039895    172.16.51.18    172.16.32.43    TCP    60    59070 → 135 [ACK] Seq=3137 Ack=1839 Win=262656 Len=0
            13    2017/319 01:44:02.468970    0.039896    172.16.51.18    172.16.32.43    DCERPC    210    Request: call_id: 7, Fragment: Single, opnum: 3, Ctx: 0
            14    2017/319 01:44:02.469188    0.040114    172.16.32.43    172.16.51.18    DCERPC    194    Response: call_id: 7, Fragment: Single, Ctx: 0
            15    2017/319 01:44:02.480026    0.050952    172.16.51.18    172.16.32.43    DCERPC    210    Request: call_id: 8, Fragment: Single, opnum: 3, Ctx: 0
            16    2017/319 01:44:02.480367    0.051293    172.16.32.43    172.16.51.18    DCERPC    194    Response: call_id: 8, Fragment: Single, Ctx: 0
            17    2017/319 01:44:02.488802    0.059728    172.16.51.18    172.16.32.43    DCERPC    210    Request: call_id: 9, Fragment: Single, opnum: 3, Ctx: 0


     .......

    And one more item. If the function call was successful i see that in the network logs on both Server and CLient. Just timings are bit different.

        34    2017/319 02:53:14.716765    0.028642    172.68.51.18    172.68.32.43    DCERPC    2076    Bind: call_id: 4, Fragment: Single, 1 context items: IMyInterface V0.0 (32bit NDR)
        35    2017/319 02:53:14.717085    0.028962    172.68.32.43    172.68.51.18    TCP    60    49313 → 58945 [ACK] Seq=1 Ack=2023 Win=131328 Len=0
        34    2017/319 02:53:14.716765    0.028642    172.68.51.18    172.68.32.43    DCERPC    2076    Bind: call_id: 4, Fragment: Single, 1 context items: IMyInterface V0.0 (32bit NDR)
        35    2017/319 02:53:14.717085    0.028962    172.68.32.43    172.68.51.18    TCP    60    49313 → 58945 [ACK] Seq=1 Ack=2023 Win=131328 Len=0
        36    2017/319 02:53:14.717790    0.029667    172.68.32.43    172.68.51.18    DCERPC    287    Bind_ack: call_id: 4, Fragment: Single, max_xmit: 5840 max_recv: 5840, 1 results: Acceptance
        37    2017/319 02:53:14.718023    0.029900    172.68.51.18    172.68.32.43    DCERPC    270    Alter_context: call_id: 4, Fragment: Single, 1 context items: IMyInterface V0.0 (32bit NDR)
        38    2017/319 02:53:14.718546    0.030423    172.68.32.43    172.68.51.18    DCERPC    159    Alter_context_resp: call_id: 4, Fragment: Single, max_xmit: 5840 max_recv: 5840, 1 results: Acceptance
        39    2017/319 02:53:14.718752    0.030629    172.68.51.18    172.68.32.43    DCERPC    338    Request: call_id: 4, Fragment: Single, opnum: 7, Ctx: 1 IMyInterface V0
        40    2017/319 02:53:14.723022    0.034899    172.68.32.43    172.68.51.18    DCERPC    178    Response: call_id: 4, Fragment: Single, Ctx: 1 IMyInterface V0


    Any ideas are welcome.

                
    • Edited by Kalin Penchev Wednesday, November 22, 2017 11:14 AM Updated the Code with more details
    Wednesday, November 15, 2017 12:14 PM

All replies

  • Hi Kalin Penchev,

    To further help you about this issue, I am trying to invoke someone experienced to help look into this thread, this may take some time and as soon as we get any result, we will post back.

    Best Regards,

    Wendy


    MSDN Community Support
    Please remember to click "Mark as Answer" the responses that resolved your issue, and to click "Unmark as Answer" if not. This can be beneficial to other community members reading this thread. If you have any compliments or complaints to MSDN Support, feel free to contact MSDNFSF@microsoft.com.

    Monday, November 20, 2017 7:41 AM
    Moderator
  • Hi Kalin,

    Can you provide some codes of your application(not just pseudo codes) for us to test and figure out the problem?

    How do you keep your client 15 minutes on idle? Thread.Sleep?

    Please provide more information about your client and server.

    Thanks a lot,

    Charles He


    MSDN Community Support
    Please remember to click "Mark as Answer" the responses that resolved your issue, and to click "Unmark as Answer" if not. This can be beneficial to other community members reading this thread. If you have any compliments or complaints to MSDN Support, feel free to contact MSDNFSF@microsoft.com.


    Wednesday, November 22, 2017 7:33 AM
  • Hi Charles,

    I have Clients on Windows 7 and 10, Servers on Windows 8 and vice versa. E.g. that error occurs on several different environments. Firewalls are turned off on both sides.

    About the idle - No Thread.Sleep. I'm Just leaving the application opened for 15 minutes and then try to call the function again by UI action (E.g. from the menu).

    Unfortunately I'm not allowed to post a code on a public forum. That will violate my company policy.

    But the code is almost same as the one I have provided. Eg. just replace "MyClass", "IMyInterface"  and "MyFunction" with some more meaningful names you will have the same. But I updated the existing pseudo code by showing almost the exact code structure and also I put all types of attributes used.

    Regards,
    Kalin


    Wednesday, November 22, 2017 11:22 AM
  • Hi Kalin,

    Thanks for your updating.

    You said you leave the application opened for 15 minutes and then try to call the function again. So the object is created when your application starts or when you call the function? And your object lifetime is JIT or Object Polling?

    Thanks a lot,

    Charles He


    MSDN Community Support
    Please remember to click "Mark as Answer" the responses that resolved your issue, and to click "Unmark as Answer" if not. This can be beneficial to other community members reading this thread. If you have any compliments or complaints to MSDN Support, feel free to contact MSDNFSF@microsoft.com.


    Friday, November 24, 2017 11:12 AM
  • Hi Charles,

    The object is re-created every time just before usage. (See the code I've provided). Also the object that holds MyFunction is re-created every time just before usage.

    About the object lifetime - it is Object Polling.  The Poolsize is 1. Expiration timeout is 15 minutes. Lifetime Limit, Activation Limit and all other limits are 0. (I think those are default settings ).


    Regards,
    Kalin

    Monday, November 27, 2017 7:59 PM
  • Hi Kalin,

    I found a similar thread Unable to cast COM object of type exception. Although that question is about multithreading, there is also a comment says his scenario has nothing to do with threading. So I suggest that you have a try first and post your feedback here.

    Best Regards,

    Charles He


    MSDN Community Support
    Please remember to click "Mark as Answer" the responses that resolved your issue, and to click "Unmark as Answer" if not. This can be beneficial to other community members reading this thread. If you have any compliments or complaints to MSDN Support, feel free to contact MSDNFSF@microsoft.com.


    Tuesday, November 28, 2017 2:16 AM
  • Hi Charles.

    Thanks for your reply. Before sent a post here I googled during several days. I tried this and many other suggestions regarding to that issue, but they did not helped me. This one is related to multithreading and  looks like it appears every time and it does not have anything in common with my issue.

    For now I went with my workaround - e.g. with retrying the operation but this is not a solution and I need to solve that error.

    Regards,
    Kalin

    Wednesday, January 3, 2018 4:34 PM