Announcement

Collapse
No announcement yet.
X
  • Filter
  • Time
Clear All
new posts

    Real-time messaging: server message not received in client

    1. SmartGWT 6.1 power edition - (v11.1p_2017-09-28/PowerEdition Deployment 2017-09-28)
    2. Google Chrome Version 62.0.3202.75 (Official Build) (64-bit)

    When a message is sent from the server to the client, the message is not always received clientside. It seems that some messages are lost if they were sent during the reset of the connectionTTL.

    As we use this messaging tool in a wizard style component in order to show progress and allow next steps, omitting a message is unwanted behaviour.
    Could you please fix this problem or provide a workaround?

    Test case:

    Client code:
    Code:
    package test.client;
    
    import com.google.gwt.core.client.EntryPoint;
    import com.google.gwt.core.shared.GWT;
    import com.smartgwt.client.rpc.Messaging;
    import com.smartgwt.client.rpc.MessagingCallback;
    import com.smartgwt.client.widgets.HTMLFlow;
    
    /**
     * Entry point classes define <code>onModuleLoad()</code>.
     */
    public class Test implements EntryPoint {
    
        private HTMLFlow flow = new HTMLFlow("lost message test:");
    
        /**
         * This is the entry point method.
         */
    
        public void onModuleLoad() {
            flow.setWidth100();
            flow.setHeight100();
    
            CounterWrapper counter = new CounterWrapper();
            Messaging.subscribe("lostmessagetest", new MessagingCallback() {
                @Override
                public void execute(Object data) {
                    int number = Integer.parseInt(data.toString());
                    if (number > counter.counter + 1) {
                        flow.setContents(flow.getContents() + "<BR>" + data + " --> SKIPPED A NUMBER!");
                        GWT.log("Received data: " + number + " --> SKIPPED A NUMBER!");
                    } else {
                        GWT.log("Received data: " + number);
                    }
                    counter.counter = number;
                }
            });
    
            flow.draw();
        }
    
        private class CounterWrapper {
    
            private int counter;
        }
    }
    Server code:
    Code:
    package test.server;
    
    import java.io.IOException;
    
    import javax.servlet.ServletException;
    import javax.servlet.http.HttpServlet;
    import javax.servlet.http.HttpServletRequest;
    import javax.servlet.http.HttpServletResponse;
    
    import com.isomorphic.messaging.ISCMessage;
    import com.isomorphic.messaging.ISCMessageDispatcher;
    
    public class LostMessageTest extends HttpServlet {
    
        @Override
        public void doGet(HttpServletRequest request, HttpServletResponse response)
                throws ServletException, IOException {
            int i = 0;
            while (true) {
                try {
                    ISCMessageDispatcher.instance().deliver(new ISCMessage("lostmessagetest", i+""));
                    i++;
                    Thread.sleep(1000);
                } catch (Exception e) {
                    e.printStackTrace();
                }
            }
        }
    }
    Logging output:
    Code:
    ...
    ConsoleLogger.java:32 Received data: 133
    ConsoleLogger.java:32 Received data: 134
    ConsoleLogger.java:32 Received data: 135
    ConsoleLogger.java:32 Received data: 136
    ConsoleLogger.java:32 Received data: 137
    ConsoleLogger.java:32 Received data: 138
    ConsoleLogger.java:32 Received data: 139
    ConsoleLogger.java:32 Received data: 140
    ConsoleLogger.java:32 Received data: 141
    EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1509964567627&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_15&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
    ConsoleLogger.java:32 Received data: 142
    ConsoleLogger.java:32 Received data: 143
    ConsoleLogger.java:32 Received data: 144
    ConsoleLogger.java:32 Received data: 145
    ConsoleLogger.java:32 Received data: 146
    ConsoleLogger.java:32 Received data: 147
    ConsoleLogger.java:32 Received data: 148
    ConsoleLogger.java:32 Received data: 149
    ConsoleLogger.java:32 Received data: 150
    ConsoleLogger.java:32 Received data: 151
    EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1509964577647&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_16&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
    ConsoleLogger.java:32 Received data: 153 --> SKIPPED A NUMBER!
    ConsoleLogger.java:32 Received data: 154
    ConsoleLogger.java:32 Received data: 155
    ConsoleLogger.java:32 Received data: 156
    ConsoleLogger.java:32 Received data: 157
    ConsoleLogger.java:32 Received data: 158
    ConsoleLogger.java:32 Received data: 159
    ConsoleLogger.java:32 Received data: 160
    ConsoleLogger.java:32 Received data: 161
    ConsoleLogger.java:32 Received data: 162
    EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1509964588137&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_17&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
    ConsoleLogger.java:32 Received data: 164 --> SKIPPED A NUMBER!
    ConsoleLogger.java:32 Received data: 165
    ConsoleLogger.java:32 Received data: 166
    ConsoleLogger.java:32 Received data: 167
    ConsoleLogger.java:32 Received data: 168
    ConsoleLogger.java:32 Received data: 169
    ConsoleLogger.java:32 Received data: 170
    ConsoleLogger.java:32 Received data: 171
    ConsoleLogger.java:32 Received data: 172
    EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1509964599175&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_18&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
    ConsoleLogger.java:32 Received data: 174 --> SKIPPED A NUMBER!
    ConsoleLogger.java:32 Received data: 175
    ConsoleLogger.java:32 Received data: 176
    ConsoleLogger.java:32 Received data: 177
    ConsoleLogger.java:32 Received data: 178
    ConsoleLogger.java:32 Received data: 179
    ConsoleLogger.java:32 Received data: 180
    ConsoleLogger.java:32 Received data: 181
    ConsoleLogger.java:32 Received data: 182
    EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1509964609197&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_19&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
    ConsoleLogger.java:32 Received data: 183
    ConsoleLogger.java:32 Received data: 184
    ConsoleLogger.java:32 Received data: 185
    ConsoleLogger.java:32 Received data: 186
    ConsoleLogger.java:32 Received data: 187
    ConsoleLogger.java:32 Received data: 188
    ConsoleLogger.java:32 Received data: 189
    ConsoleLogger.java:32 Received data: 190
    ConsoleLogger.java:32 Received data: 191
    ConsoleLogger.java:32 Received data: 192
    EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1509964619214&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_20&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
    ConsoleLogger.java:32 Received data: 193
    ConsoleLogger.java:32 Received data: 194
    ConsoleLogger.java:32 Received data: 195
    ConsoleLogger.java:32 Received data: 196
    ConsoleLogger.java:32 Received data: 197
    ...
    In order to reproduce this issue more frequently, the messaging.connectionTTL was lowered to 10000ms. Increasing the TTL would make this problem appear less frequently, however this is not a complete solution for us.

    #2
    This definitely shouldn't happen (tm) and we're not reproducing this failure here with your code.

    For background, the way this works is: when messaging.connectionTTL is exhausted, a message is sent to the browser to force a reconnect. The original connection then idles (continuing to pass any inbound messages to the client) for messaging.clientReconnectWindow milliseconds (defaults to 2000 == 2 seconds). Only at the end of this period is the original connection torn down. However, if the client is unable to establish a new connection within this window, then messages can be dropped.

    Can you please test this out with a longer connectionTTL and see if the issue is resolved. If not, then we need some more information to track this down.

    1. What kind of application server are you using and what is the general network layout/latency.
    2. Which broker is backing the Messaging system in this case - is it the default:

    Code:
    messaging.dispatcherImplementer: com.isomorphic.messaging.LocalMessageDispatcher
    Or are you using JMS? If JMS, then which broker? Can you please put some timestamps on your log messages so we can have an idea of the delays involved?

    Thanks.

    Comment


      #3
      We've tried out different options for connectionTTL and clientReconnectWindow, but no solution so far.

      1. The problems occurs on both tomcat and jetty. In the test case we used localhost, so no latency.
      2. We use the default broker

      Here are some new logs with timestamps:
      Client logging:
      Code:
      ...
      11:49:02.273 Received data: 745
      11:49:03.274 Received data: 746
      11:49:04.281 Received data: 747
      11:49:05.280 Received data: 748
      11:49:06.285 Received data: 749
      11:49:07.285 Received data: 750
      11:49:08.286 Received data: 751
      11:49:09.290 Received data: 752
      11:49:10.294 Received data: 753
      11:49:11.297 Received data: 754
      11:49:11.319:DEBUG:HiddenFrame:isc_HiddenFrame_80:Destroyed isc_HiddenFrame_80
      11:49:11.319:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 192}
      11:49:11.321:DEBUG:Messaging:persistent server connection open - ttl: 10000ms, keepaliveDelay: 4000ms, connectTimeout: 10000ms.
      11:49:11.321:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 193}
      EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1510310941289&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_80&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
      11:49:12.302 Received data: 755
      11:49:13.306 Received data: 756
      11:49:14.307 Received data: 757
      11:49:15.312 Received data: 758
      11:49:16.314 Received data: 759
      11:49:17.319 Received data: 760
      11:49:18.324 Received data: 761
      11:49:19.328 Received data: 762
      11:49:20.330 Received data: 763
      11:49:21.343:DEBUG:HiddenFrame:isc_HiddenFrame_81:Destroyed isc_HiddenFrame_81
      11:49:21.344:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 194}
      11:49:21.345:DEBUG:Messaging:persistent server connection open - ttl: 10000ms, keepaliveDelay: 4000ms, connectTimeout: 10000ms.
      11:49:21.345:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 195}
      EventSource failed loading: GET "http://127.0.0.1:8888/test/sc/messaging?ts=1510310951306&isc_noLog=1&type=connect&connectionID=isc_HiddenFrame_81&subscribedChannels=%7B%0A%20%20%20%20lostmessagetest%3A%7B%0A%20%20%20%20%20%20%20%20subscriptionCallback%3Anull%0A%20%20%20%20%7D%0A%7D&eventStream=true".
      11:49:22.346:INFO:redraws:isc_HTMLFlow_0:Scheduling redraw (setContents)
      11:49:22.347:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 196}
      11:49:22.355 Received data: 765 --> SKIPPED A NUMBER!
      11:49:22.356:TMR8:DEBUG:drawing:clearRedrawQueue: [HTMLFlow ID:isc_HTMLFlow_0]
      11:49:22.357:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 197}
      11:49:22.358:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 198}
      11:49:22.359:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 199}
      11:49:22.360:TMR8:INFO:drawing:isc_HTMLFlow_0:$ra(): redrawing
      11:49:22.360:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 200}
      11:49:22.362:TMR8:INFO:sizing:isc_HTMLFlow_0:Specified size: 1680x831, drawn scroll size: 1680x36, border: 0x0, margin: 0x0, old size: 1680x18, reason: redraw
      11:49:22.363:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 201}
      11:49:22.364:TMR8:DEBUG:sizing:isc_HTMLFlow_0:clipHandle sizes: {scrollLeft: 0,scrollTop: 0,scrollWidth: 1680,scrollHeight: 831,clientWidth: undef,clientHeight: undef,offsetWidth: 1680,offsetHeight: 831,styleLeft: "0px",styleTop: "0px",styleWidth: "1680px",styleHeight: "831px",styleClip: ""}
      11:49:22.364:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB",packet: Obj,callback: null,sequence: 202}
      11:49:22.365:TMR8:DEBUG:sizing:isc_HTMLFlow_0:handle sizes: {scrollLeft: 0,scrollTop: 0,scrollWidth: 1680,scrollHeight: 36,clientWidth: undef,clientHeight: undef,offsetWidth: 1680,offsetHeight: 36,styleLeft: "",styleTop: "",styleWidth: "",styleHeight: "",styleClip: ""}
      11:49:22.365:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB", packet: Obj, callback: null, sequence: 203}
      11:49:22.366:TMR8:DEBUG:drawing:isc_HTMLFlow_0:Redraw() - Total time to redraw in DOM:6
      11:49:22.367:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB", packet: Obj, callback: null, sequence: 204}
      11:49:22.367:TMR8:DEBUG:redraws:clearRedrawQueue: 1 redraws (1 items), 11ms
      11:49:22.368:TMR8:DEBUG:MessagingDMISocket:isc_MessagingDMISocket_3:$139v: {sendChannel: "FA1CA2AB-367C-489C-A5DD-D40AC99C58FB", packet: Obj, callback: null, sequence: 205}
      11:49:23.340 Received data: 766
      11:49:24.345 Received data: 767
      11:49:25.348 Received data: 768
      11:49:26.353 Received data: 769
      11:49:27.353 Received data: 770
      11:49:28.355 Received data: 771
      11:49:29.356 Received data: 772
      ...
      Server logging:
      Code:
      ...
      11:49:02.270 Delivering message data: 745
      11:49:03.270 Delivering message data: 746
      11:49:04.274 Delivering message data: 747
      11:49:05.276 Delivering message data: 748
      11:49:06.281 Delivering message data: 749
      11:49:07.282 Delivering message data: 750
      11:49:08.282 Delivering message data: 751
      11:49:09.287 Delivering message data: 752
      11:49:10.290 Delivering message data: 753
      11:49:11.294 Delivering message data: 754
      11:49:12.298 Delivering message data: 755
      11:49:13.302 Delivering message data: 756
      11:49:14.303 Delivering message data: 757
      11:49:15.309 Delivering message data: 758
      11:49:16.310 Delivering message data: 759
      11:49:17.316 Delivering message data: 760
      11:49:18.320 Delivering message data: 761
      11:49:19.325 Delivering message data: 762
      11:49:20.326 Delivering message data: 763
      11:49:21.331 Delivering message data: 764
      11:49:22.333 Delivering message data: 765
      11:49:23.337 Delivering message data: 766
      11:49:24.341 Delivering message data: 767
      11:49:25.344 Delivering message data: 768
      11:49:26.349 Delivering message data: 769
      11:49:27.350 Delivering message data: 770
      11:49:28.350 Delivering message data: 771
      11:49:29.353 Delivering message data: 772
      ...

      Comment


        #4
        Ok, yeah, it looks like there is in fact regression. Specifically in EventSource mode. We will provide a new build either Monday or Tuesday that will definitely fix this. I'll provide an update on the thread here once it's available.

        Thanks for the detailed reporting - much appreciated.

        Comment


          #5
          Thanks for your patience. Please look for a fix in tomorrow's (Nov 16) build - available here: https://www.smartclient.com/builds/index.jsp

          Comment


            #6
            Thank you for the fix. The described problem is indeed solved for our test case.
            However in our main project the problem still occurs, although less frequently.

            Until we've narrowed it down to a new test case, we've implemented a workaround where we confirm the reception of a message with another message from client to server and server-side we cache our messages and resend them if there's no confirmation.

            Comment


              #7
              I've been trying to reproduce this, but without luck so far. We're very interested in figuring out what's going on here because, of course, reliable message delivery is extremely important. There are a couple of ways this can happen that's configuration or environment based though and I'd like to run through these with you to rule those out.

              The way we ensure messages are not lost between the server and the browser is by establishing a second concurrent message delivery channel before the first one is terminated. The following value, defined in framework.properties (wrapped in the core_isomorphic_rpc.jar) and overrideable via server.properties controls the length of time a connection stays open before it is rolled over automatically:

              Code:
              messaging.connectionTTL: 120000
              The value is in milliseconds, so that's 2 minutes. When this TTL is exhausted, the server tells the client to terminate the connection and waits for 2 seconds for the client to establish a parallel channel before dropping the original connection. The length of time that the server keeps the original connection open past the TTL is controlled by this config property:
              Code:
               messaging.clientReconnectWindow: 2000
              So that's 2 minutes. Now, if, in your environment, there is ever a case where it may take longer than 2 seconds to establish a connection, then messages can be lost. So one thing to try is to increase this window. There's no real harm to keeping the connections going in parallel except for the obvious additional resource consumption. During the time that multiple connections to the server exist, messages are delivered via both channels - creating duplicates. However, we have built-in de-duplication code that keeps a rotating list of unique message IDs and ensures that a message is delivered only once to your calling code.

              The other way that messages can be dropped is if something like a firewall cuts the existing connection before the original TTL expires. Client-side we detect this with a watchdog timer and re-establish, but in the meantime messages can be lost. This is why we cycle connections (and also because browsers will in some cases terminate an outstanding http connection that's been open "too long"). So you could try to shorten the connectionTTL and/or watch the network debugger to see if they're being cut.

              Comment

              Working...
              X