Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

WebFilter(3.6-RC1): session attributes being lost/overwritten with old values using deferred-write by reading them #7291

Closed
dfex55 opened this issue Jan 11, 2016 · 9 comments

Comments

Projects
None yet
6 participants
@dfex55
Copy link

commented Jan 11, 2016

Assume two parallel http requests A and B, sticky-session set to false, deferred-write to true:

Time tick 1:
A: reads attributes X=1 and Y=1 from session

Time tick 2:
A: sets attribute X=2

Time tick 3:
B: reads attributes X=1 and Y=1 from session

Time tick 4:
B: sets attribute Y= 2

Time tick 5:
A: request finished. WebFilter "commits" session to distributed map

Note:
Distributed map contains X=2 and Y=1

Time tick 6:
B: request finished. WebFilter "commits" session to distributed map

The distributed map now contains Y=2 but again the old X=1 that was read by B but was never set. X=2 is overwritten and the data is lost.

The expected behavior is, that attributes which were only read and not modified, will not be written to the distributed map.

In general:
Reading attributes with deferred-write enabled, triggers a write operation for that value in the distributed map (maybe only, when another attribute was changed - not tested). All other changes to that value after the value was read, are overwritten.

Question regarding performance:
If you check many (lets say a few 10k values) session attributes via getAttribute (deferred-write is enabled), will all these values be written to the distributed map? It might be, that we are hitting this performance bug. Only 2-3 attributes are changed, but thousands are written to the map.

@mesutcelik

This comment has been minimized.

Copy link
Contributor

commented Jan 13, 2016

Hi @dfex55 ,

I am confused a bit here. When deferred-write=true, we only write dirty values to distributed map. If you see a different behavior, it should be a bug...
https://github.com/hazelcast/hazelcast/blob/master/hazelcast-wm/src/main/java/com/hazelcast/web/HazelcastHttpSession.java#L286

Can you reproduce the problem with a unit test?

@dfex55

This comment has been minimized.

Copy link
Author

commented Jan 14, 2016

First, I am sorry. Time tick 2 and 3 were wrong. They had to be swapped (original edited).

To reproduce you can use the following code pieces. It is not an unit test, but you can easily convert it to. For a unit test, there should be some kind of locking, so you are not depending on request start time and wait intervals.

A:

    Logger logger = LoggerFactory.getLogger(this.getClass());

    Integer x = (Integer) httpSession.getAttribute("x");
    Integer y = (Integer) httpSession.getAttribute("y");

    logger.debug("Request A, read from session: x: {}, y: {}", x, y);

    if (x == null) {
      x = 0;
    }
    x++;

    httpSession.setAttribute("x", x);

    logger.debug("Request A, setAttribute x: {}", x);

    Thread.sleep(5000);

B:

    Logger logger = LoggerFactory.getLogger(this.getClass());

    Integer x = (Integer) httpSession.getAttribute("x");
    Integer y = (Integer) httpSession.getAttribute("y");

    logger.debug("Request B, read from session: x: {}, y: {}", x, y);

    if (y == null) {
      y = 0;
    }
    y++;

    httpSession.setAttribute("y", y);

    logger.debug("Request B, setAttribute y: {}", y);

    Thread.sleep(5000);

To run manually:

  1. execute a request that runs A
  2. within the next seconds (max 5) execute a request that runs B

Repeat the steps above to check logging output.

Below is the output of three runs (sticky-session = false, deferred-write = true):

first run:

[#| 14.01.2016 09:29:43.880 | Connector+Servlet-Thread-Pool-22 | DEBUG A
Request A, read from session: x: 5, y: 7
|#]

[#| 14.01.2016 09:29:43.880 | Connector+Servlet-Thread-Pool-22 | DEBUG A
Request A, setAttribute x: 6
|#]



[#| 14.01.2016 09:29:46.089 | Connector+Servlet-Thread-Pool-16 | DEBUG B
Request B, read from session: x: 5, y: 7
|#]

[#| 14.01.2016 09:29:46.090 | Connector+Servlet-Thread-Pool-16 | DEBUG B
Request B, setAttribute y: 8
|#]

second run:

[#| 14.01.2016 09:30:37.364 | Connector+Servlet-Thread-Pool-16 | DEBUG A
Request A, read from session: x: 5, y: 8
|#]

[#| 14.01.2016 09:30:37.364 | Connector+Servlet-Thread-Pool-16 | DEBUG A
Request A, setAttribute x: 6
|#]




[#| 14.01.2016 09:30:39.416  | Connector+Servlet-Thread-Pool-17 | DEBUG B
Request B, read from session: x: 5, y: 8
|#]

[#| 14.01.2016 09:30:39.416 | Connector+Servlet-Thread-Pool-17 | DEBUG B
Request B, setAttribute y: 9
|#]

third run:

[#| 14.01.2016 09:31:59.748 | Connector+Servlet-Thread-Pool-19 | DEBUG A
Request A, read from session: x: 5, y: 9
|#]

[#| 14.01.2016 09:31:59.749 | Connector+Servlet-Thread-Pool-19 | DEBUG A
Request A, setAttribute x: 6
|#]



[#| 14.01.2016 09:32:01.490 | Connector+Servlet-Thread-Pool-20 | DEBUG B
Request B, read from session: x: 5, y: 9
|#]

[#| 14.01.2016 09:32:01.490 | Connector+Servlet-Thread-Pool-20 | DEBUG B
Request B, setAttribute y: 10
|#]

As you can see x is increased every time in A, but it is not written to or overwritten by B in the distributed map.

@dfex55

This comment has been minimized.

Copy link
Author

commented Jan 14, 2016

Same test without reading the unchanged attribute, everything is fine:

first run:
[#| 14.01.2016 10:07:09.837 | Connector+Servlet-Thread-Pool-20 | DEBUG A
Request A, read from session: x: 1
|#]

[#| 14.01.2016 10:07:09.838 | Connector+Servlet-Thread-Pool-20 | DEBUG A
Request A, setAttribute x: 2
|#]

[#| 14.01.2016 10:07:11.618 | Connector+Servlet-Thread-Pool-16 | DEBUG B
Request B, read from session: y: 3
|#]

[#| 14.01.2016 10:07:11.618 | Connector+Servlet-Thread-Pool-16 | DEBUG B
Request B, setAttribute y: 4
|#]

second run:

[#| 14.01.2016 10:07:20.561 | Connector+Servlet-Thread-Pool-22 | DEBUG A
Request A, read from session: x: 2
|#]

[#| 14.01.2016 10:07:20.561 | Connector+Servlet-Thread-Pool-22 | DEBUG A
Request A, setAttribute x: 3
|#]

[#| 14.01.2016 10:07:22.632 | Connector+Servlet-Thread-Pool-23 | DEBUG B
Request B, read from session: y: 4
|#]

[#| 14.01.2016 10:07:22.632 | Connector+Servlet-Thread-Pool-23 | DEBUG B
Request B, setAttribute y: 5
|#]

Code:

A:

    Logger logger = LoggerFactory.getLogger(this.getClass());

    Integer x = (Integer) httpSession.getAttribute("x");

    logger.debug("Request A, read from session: x: {}", x);

    if (x == null) {
      x = 0;
    }
    x++;

    httpSession.setAttribute("x", x);

    logger.debug("Request A, setAttribute x: {}", x);

    Thread.sleep(5000);

B:

    Logger logger = LoggerFactory.getLogger(this.getClass());

    Integer y = (Integer) httpSession.getAttribute("y");

    logger.debug("Request B, read from session: y: {}", y);

    if (y == null) {
      y = 0;
    }
    y++;

    httpSession.setAttribute("y", y);

    logger.debug("Request B, setAttribute y: {}", y);

    Thread.sleep(5000);
@dfex55

This comment has been minimized.

Copy link
Author

commented Jan 14, 2016

A little bit confusing to me is:

If you change the order (move sleep delay before setAttribute), everything is fine again with reading the unchanged attribute.

This is just for information as it might help you to find the bug.

A:

    Logger logger = LoggerFactory.getLogger(this.getClass());

    Integer x = (Integer) httpSession.getAttribute("x");
    Integer y = (Integer) httpSession.getAttribute("y");

    logger.debug("Request A, read from session: x: {}, y: {}", x, y);

    Thread.sleep(5000);

    if (x == null) {
      x = 0;
    }
    x++;

    httpSession.setAttribute("x", x);

    logger.debug("Request A, setAttribute x: {}", x);

B:

    Logger logger = LoggerFactory.getLogger(this.getClass());

    Integer x = (Integer) httpSession.getAttribute("x");
    Integer y = (Integer) httpSession.getAttribute("y");

    logger.debug("Request B, read from session: x: {}, y: {}", x, y);

    Thread.sleep(5000);

    if (y == null) {
      y = 0;
    }
    y++;

    httpSession.setAttribute("y", y);

    logger.debug("Request B, setAttribute y: {}", y);

first run:

[#| 14.01.2016 10:18:01.970 | Connector+Servlet-Thread-Pool-17 | A
Request A, read from session: x: 3, y: 5
|#]

[#| 14.01.2016 10:18:03.763 | Connector+Servlet-Thread-Pool-18 | B
Request B, read from session: x: 3, y: 5
|#]

[#| 14.01.2016 10:18:06.978  | Connector+Servlet-Thread-Pool-17 | A
Request A, setAttribute x: 4
|#]

[#| 14.01.2016 10:18:08.767 | Connector+Servlet-Thread-Pool-18 | B
Request B, setAttribute y: 6
|#]

second run


[#| 14.01.2016 10:18:27.461 | Connector+Servlet-Thread-Pool-20 | A
Request A, read from session: x: 4, y: 6
|#]

[#| 14.01.2016 10:18:29.443 | Connector+Servlet-Thread-Pool-23 | B
Request B, read from session: x: 4, y: 6
|#]

[#| 14.01.2016 10:18:32.468 | Connector+Servlet-Thread-Pool-20 | A
Request A, setAttribute x: 5
|#]

[#| 14.01.2016 10:18:34.450 | Connector+Servlet-Thread-Pool-23 | B
Request B, setAttribute y: 7
|#]

third run


[#| 14.01.2016 10:19:01.091 | Connector+Servlet-Thread-Pool-19 | A
Request A, read from session: x: 5, y: 7
|#]

[#| 14.01.2016 10:19:02.697 | Connector+Servlet-Thread-Pool-20 | B
Request B, read from session: x: 5, y: 7
|#]

[#| 14.01.2016 10:19:06.097 | Connector+Servlet-Thread-Pool-19 | A
Request A, setAttribute x: 6
|#]

[#| 14.01.2016 10:19:07.703 | Connector+Servlet-Thread-Pool-20 | B
Request B, setAttribute y: 8
|#]
@bilalyasar

This comment has been minimized.

Copy link
Collaborator

commented Jan 14, 2016

Hi dfex55,
Yes you are right, we have realised the issue.
Shortly i can explain the issue:
When one request comes to server, we are setting reload flags as true.
Then while getting attribute, if reload flag is true, we are getting attribute from distributed map.

So request A comes to server, changes X attribute.
Then request B comes and sets reload flags to true
When B executes getAttribute, it fetches from distributed map. ( Actually, it should have got from local)

We will send fix and unit test, but if you need hotfix and want to try in local you can change this line:
https://github.com/hazelcast/hazelcast/blob/master/hazelcast-wm/src/main/java/com/hazelcast/web/HazelcastHttpSession.java#L114

from: if (cacheEntry == null || cacheEntry.isReload()) {

to: if (cacheEntry == null || (cacheEntry.isReload() && !cacheEntry.isDirty()) ) {

@dfex55

This comment has been minimized.

Copy link
Author

commented Feb 2, 2016

When will the fix be released in a public release? 3.6 was released with the webfilter losing data having concurrent requests! (not that rare on webapps)

A little off topic but related:
There might be another data-loss on the specific programatic behavior of the webfilter. Assume deferred write and the following:

  1. Thread A begins request
  2. Thread A reads a "complex" attribute X (e.g. an ArrayList)
  3. Thread A calls setAttribute immediatly to trigger distribution after request finished
  4. Thread B begins request
  5. Thread B reads and sets attribute Y
  6. Thread B finished -> X and Y will be written to the distributed map because both are marked dirty
  7. Thread A adds values to the ArrayList from attribute X
  8. Thread A finished -> nothing will be written to the distributed map because it was done after B finished

As a result, the added value(s) to X (by thread A) will be lost.

This should be at least be mentioned in the documentation for the webfilter using deferred-write: It is mandatory to call setAttribute after "complex" objects are changed, to be sure changes will be distributed to the map.

@jnehlmeier

This comment has been minimized.

Copy link

commented Feb 15, 2016

Any progress here? Its pretty annoying behavior. Shouldn't this issue be assigned to milestone 3.6.1?

@mesutcelik mesutcelik added this to the 3.6.1 milestone Feb 15, 2016

@mesutcelik

This comment has been minimized.

Copy link
Contributor

commented Feb 15, 2016

Thanks @jnehlmeier ,
milestone set to 3.6.1

kobalski pushed a commit that referenced this issue Feb 18, 2016

İbrahim Gurses
Merge pull request #7536 from bilalyasar/fix-wm
Fix #7291 concurrent request in webfilter

@enesakar enesakar modified the milestones: 3.6.1, 3.6.2 Feb 26, 2016

@mesutcelik

This comment has been minimized.

Copy link
Contributor

commented Mar 11, 2016

fixed by #7536

@mesutcelik mesutcelik closed this Mar 11, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.