PopupButton + long polling push + assertions enabled = browser doing tons of requests

[lorenzobenvenuti]

Hi,

we are investigating some random push-related problems in our application; we tried to enable the JVM assertions to check if they could be related to the Vaadin session locking mechanism, but in this way we started seeing that the client performs hundreds of requests to host/app/PUSH/. After a bit of further investigation we found out it happens only if we add a PopupButton to the UI; I actually was able to replicate the issue in a simple UI:

@SuppressWarnings("serial")
@Theme("popupbuttonassertion")
@Push(transport=Transport.LONG_POLLING)
public class PopupbuttonassertionUI extends UI {

    @WebServlet(value = "/*", asyncSupported = true)
    @VaadinServletConfiguration(productionMode = false, ui = PopupbuttonassertionUI.class, widgetset = "com.example.popupbuttonassertion.widgetset.PopupbuttonassertionWidgetset")
    public static class Servlet extends VaadinServlet {
    }

    @Override
    protected void init(VaadinRequest request) {
        final VerticalLayout layout = new VerticalLayout();
        layout.setMargin(true);
        setContent(layout);

        PopupButton button = new PopupButton("Hi");
        button.setContent(new Label("Content"));
        layout.addComponent(button);
    }

}

We tried with versions 2.3.0 and 2.5.0. The unwanted requests come out only if we enable push and use the long polling transport mode.

While we don't mean to use assertions in production, we fear this problem may hide some unwanted behaviour even with assertions disabled.

Thank you,

lorenzo

[henrikerola]

I tried to reproduce this but didn't see that kind of behaviour.

[Artur-]

@lorenzobenvenuti What do the requests contain? Add ?debug and you should see, in the debug window, what RPCs are being sent to the server

[lorenzobenvenuti]

Hi Artur. When the issue described above is occurring (that is, enabling the JVM assertions and just booting the attached UI) the debug console it's pretty much impossibile to use since it keeps updating itself with new messages. The only way to read the message and scroll the window is stopping the AS: in this case this is what I found on the message log. As you can see it is somehow "periodic", as if the client is looping through the same request/response cycle.

141750ms    * Dumping state changes to the console
141750ms    UIDL: undefined
141759ms    Processing time was 19ms for 163 characters of JSON
141759ms    Referenced paintables: 3
141760ms    Received push message: for(;;);[{"syncId": 4650, "changes" : [], "state":{}, "types":{"11":"1"}, "hierarchy":{"11":[]}, "rpc" : [], "meta" : {"async":true}, "resources" : {}, "timings":[3945, 0]}]
141760ms    JSON parsing took 0ms
141760ms    Handling message from server
141763ms    * Handling resources from server
141769ms    * Handling type inheritance map from server
141770ms    Handling type mappings from server
141770ms    Handling resource dependencies
141771ms    * Handling meta information
141771ms    * Creating connectors (if needed)
141771ms    * Updating connector states
141772ms    * Handling locales
141772ms    * Updating connector hierarchy
141772ms    * Running @DelegateToWidget
141772ms    * Sending state change events
141773ms    * Passing UIDL to Vaadin 6 style connectors
141773ms    * Performing server to client RPC calls
141773ms    * Unregistered 0 connectors
141774ms    handleUIDLMessage: 2 ms
141774ms    * Dumping state changes to the console
141774ms    UIDL: undefined
141780ms    Processing time was 19ms for 163 characters of JSON
141781ms    Referenced paintables: 3
141810ms    Received push message: for(;;);[{"syncId": 4651, "changes" : [], "state":{}, "types":{"11":"1"}, "hierarchy":{"11":[]}, "rpc" : [], "meta" : {"async":true}, "resources" : {}, "timings":[3945, 0]}]
141812ms    JSON parsing took 1ms
141813ms    Handling message from server
141814ms    * Handling resources from server
141814ms    * Handling type inheritance map from server
141814ms    Handling type mappings from server
141815ms    Handling resource dependencies
141819ms    * Handling meta information
141819ms    * Creating connectors (if needed)
141820ms    * Updating connector states
141820ms    * Handling locales
141820ms    * Updating connector hierarchy
141820ms    * Running @DelegateToWidget
141821ms    * Sending state change events
141821ms    * Passing UIDL to Vaadin 6 style connectors
141821ms    * Performing server to client RPC calls
141821ms    * Unregistered 0 connectors
141822ms    handleUIDLMessage: 3 ms
141822ms    * Dumping state changes to the console
141822ms    UIDL: undefined
141823ms    Processing time was 12ms for 163 characters of JSON
141824ms    Referenced paintables: 3
141824ms    Received push message: for(;;);[{"syncId": 4652, "changes" : [], "state":{}, "types":{"11":"1"}, "hierarchy":{"11":[]}, "rpc" : [], "meta" : {"async":true}, "resources" : {}, "timings":[3945, 0]}]
141824ms    JSON parsing took 0ms
141825ms    Handling message from server
141825ms    * Handling resources from server
141825ms    * Handling type inheritance map from server
141828ms    Handling type mappings from server
141829ms    Handling resource dependencies
141829ms    * Handling meta information
141830ms    * Creating connectors (if needed)
141830ms    * Updating connector states
141831ms    * Handling locales
141831ms    * Updating connector hierarchy
141832ms    * Running @DelegateToWidget
141832ms    * Sending state change events
141833ms    * Passing UIDL to Vaadin 6 style connectors
141833ms    * Performing server to client RPC calls
141834ms    * Unregistered 0 connectors
141834ms    handleUIDLMessage: 5 ms
141834ms    * Dumping state changes to the console
141835ms    UIDL: undefined
141835ms    Processing time was 11ms for 163 characters of JSON
141836ms    Referenced paintables: 3
141841ms    No onClose was received before reconnect. Forcing state to closed.
141842ms    Reopening push connection
146844ms    Reopening push connection
151848ms    Reopening push connection
156852ms    Reopening push connection
161877ms    Reopening push connection

If I expand the "Reponse" entries of the network tab I can see just an empty "shared state" label.

Finally, here you have the requests captured using the Chrome network monitor.

Request headers:

GET /PopupButtonAssertion/PUSH/?v-uiId=3&v-csrfToken=e9248736-a8e7-4da1-9cb9-f8af855de345&X-Atmosphere-tracking-id=078df4ad-9885-4dbc-a7cc-d946db752675&X-Atmosphere-Framework=2.2.6.vaadin3-jquery&X-Atmosphere-Transport=long-polling&X-Atmosphere-TrackMessageSize=true&Content-Type=application%2Fjson%3B%20charset%3DUTF-8&X-atmo-protocol=true&_=1430298103715 HTTP/1.1
Host: localhost:8080
Connection: keep-alive
User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.118 Safari/537.36
Content-Type: application/json; charset=UTF-8
Accept: */*
Referer: http://localhost:8080/PopupButtonAssertion/?debug
Accept-Encoding: gzip, deflate, sdch
Accept-Language: en-US,en;q=0.8,it;q=0.6
Cookie: JSESSIONID=3356197D0C33C7F2E07F62C745DE5167; JSESSIONID=5nkqcjf7ec5b1j4ijj2t3el8n

Response headers:

HTTP/1.1 200 OK
Server: Apache-Coyote/1.1
X-Atmosphere-tracking-id: 078df4ad-9885-4dbc-a7cc-d946db752675
Expires: -1
Cache-Control: no-store, no-cache, must-revalidate
Pragma: no-cache
Content-Type: text/plain;charset=UTF-8
Transfer-Encoding: chunked
Date: Wed, 29 Apr 2015 09:01:42 GMT

Response:

173|for(;;);[{"syncId": 1207, "changes" : [], "state":{}, "types":{"11":"1"}, "hierarchy":{"11":[]}, "rpc" : [], "meta" : {"async":true}, "resources" : {}, "timings":[2666, 0]}]173|for(;;);[{"syncId": 1208, "changes" : [], "state":{}, "types":{"11":"1"}, "hierarchy":{"11":[]}, "rpc" : [], "meta" : {"async":true}, "resources" : {}, "timings":[2666, 0]}]

Please let me know if you need something else.

Thank you,

lorenzo

[deformedpepper]

Any update on this issue? I just discovered it too after enabling assertions. Sending these tons of request slows down the responsiveness of the browser.

After disabling "-ea" parameter everything is fine.

Using:
PopupButton 3.0.0
Vaadin 8.1.4 (also tested on 8.1.0)
Chrome 60.0