Number of recorded requests decreases without being explicitly cleared.

[rcolombo]

Edit: Please make sure to view my below post which includes a script that reproduces the problem and makes it more clear what the issue is.

I am trying to diagnose an issue I am having right now where the number of recorded requests on MockServer begins to decrease as more expectations are added.

I'm running about 100 different tests that all set up different expectations on MockServer. MockServer is running within docker on a remote server and has access to 8GB of memory. I am running it with the default configuration settings, and I am setting up ~170 expectations in total.

It seems to me that MockServer is losing track of recorded requests. To test this, I added the following 2 lines of code to be called after each of my tests run (java):

HttpRequest[] allRequest = mockServerClient.retrieveRecordedRequests(request());
Expectation[] allExpectations = mockServerClient.retrieveActiveExpectations(request());
System.out.println("TOTAL EXPECTATIONS: " + allExpectations.length + ", RECORDED REQUESTS: " + allRequest.length);

I've noticed that the amount of recorded requests continuously increases to above 100 until I've reached 53 total expectations. Once I cross 53 expectations, the number of recorded requests starts dropping, and continues to drop for every test. I eventually hit a steady state of about 15 recorded requests once I get to ~150 expectations.

Example output:

TOTAL EXPECTATIONS: 50, RECORDED REQUESTS: 106
 - 
TOTAL EXPECTATIONS: 51, RECORDED REQUESTS: 108
 - 
TOTAL EXPECTATIONS: 52, RECORDED REQUESTS: 110
-
TOTAL EXPECTATIONS: 53, RECORDED REQUESTS: 108
 - 
TOTAL EXPECTATIONS: 54, RECORDED REQUESTS: 101
 - 
TOTAL EXPECTATIONS: 54, RECORDED REQUESTS: 101
 - 
TOTAL EXPECTATIONS: 56, RECORDED REQUESTS: 89

This behavior leads me to believe that there is some type of setting in MockServer so that it starts clearing out recorded requests once a certain threshold is hit. However I have been unable to find anything like this in the documentation.

When I run my tests serially, this isn't much of an issue. I am guessing that the oldest recorded requests are dropped first, so the currently running test always has access to the requests it cares about.

The problem lies in running my tests in parallel. When I run my tests in parallel, the cache of expectations/requests fills up much faster and recorded requests start getting dropped before I am able to verify that they were actually called.

I can get around this issue somewhat by clearing a test's expectations and logs once the test finishes, but this only gets me so far. Once I reach a certain level of parallelization, I am not able to clear out the expectations fast enough because the tests must finish first.

Finally, I have looked at the memory usage of my docker container, and it is high but not outrageous. I am using about 1GB of memory in total, and my server has 8GB.

Thank you James. Let me know if I can provide you with any more information.

[rcolombo]

Hi James,

I wanted to provide more detail about this error so I wrote a bash script that reproduces it. The script simply loops 150 times, and on each loop creates a new expectation with a unique path and then issues a request to that path. I print out the number of expectations and requests at the end of each loop, and have pasted the output below as well.

Bash script:

#!/bin/bash

SERVER=$1
PORT=$2

for i in `seq 1 150`
do
  post_data="{
    \"httpRequest\": {
      \"method\": \"GET\",
      \"path\": \"/api/test/${i}\"
    },
    \"httpResponse\": {
      \"body\": \"foo\",
      \"statusCode\": 200
    }
  }"

  curl -v -X PUT "http://${SERVER}:${PORT}/expectation" -d "${post_data}"
  curl -s -X GET "http://${SERVER}:${PORT}/api/test/${i}" > /dev/null

  active_expectations_count=`curl -v -s -X PUT "http://${SERVER}:${PORT}/mockserver/retrieve?type=ACTIVE_EXPECTATIONS" | jq length`
  recorded_requests_count=`curl -v -X PUT "http://${SERVER}:${PORT}/mockserver/retrieve?type=REQUESTS" | jq length`
  echo "EXPECTATIONS: $active_expectations_count, REQUESTS: $recorded_requests_count"
done

Output:

EXPECTATIONS: 1, REQUESTS: 1
EXPECTATIONS: 2, REQUESTS: 2
EXPECTATIONS: 3, REQUESTS: 3
EXPECTATIONS: 4, REQUESTS: 4
EXPECTATIONS: 5, REQUESTS: 5
EXPECTATIONS: 6, REQUESTS: 6
EXPECTATIONS: 7, REQUESTS: 7
EXPECTATIONS: 8, REQUESTS: 8
EXPECTATIONS: 9, REQUESTS: 9
EXPECTATIONS: 10, REQUESTS: 10
EXPECTATIONS: 11, REQUESTS: 11
EXPECTATIONS: 12, REQUESTS: 12
EXPECTATIONS: 13, REQUESTS: 13
EXPECTATIONS: 14, REQUESTS: 14
EXPECTATIONS: 15, REQUESTS: 15
EXPECTATIONS: 16, REQUESTS: 16
EXPECTATIONS: 17, REQUESTS: 17
EXPECTATIONS: 18, REQUESTS: 18
EXPECTATIONS: 19, REQUESTS: 19
EXPECTATIONS: 20, REQUESTS: 20
EXPECTATIONS: 21, REQUESTS: 21
EXPECTATIONS: 22, REQUESTS: 22
EXPECTATIONS: 23, REQUESTS: 23
EXPECTATIONS: 24, REQUESTS: 24
EXPECTATIONS: 25, REQUESTS: 25
EXPECTATIONS: 26, REQUESTS: 26
EXPECTATIONS: 27, REQUESTS: 27
EXPECTATIONS: 28, REQUESTS: 28
EXPECTATIONS: 29, REQUESTS: 29
EXPECTATIONS: 30, REQUESTS: 30
EXPECTATIONS: 31, REQUESTS: 31
EXPECTATIONS: 32, REQUESTS: 32
EXPECTATIONS: 33, REQUESTS: 33
EXPECTATIONS: 34, REQUESTS: 34
EXPECTATIONS: 35, REQUESTS: 35
EXPECTATIONS: 36, REQUESTS: 36
EXPECTATIONS: 37, REQUESTS: 37
EXPECTATIONS: 38, REQUESTS: 38
EXPECTATIONS: 39, REQUESTS: 39
EXPECTATIONS: 40, REQUESTS: 40
EXPECTATIONS: 41, REQUESTS: 41
EXPECTATIONS: 42, REQUESTS: 42
EXPECTATIONS: 43, REQUESTS: 43
EXPECTATIONS: 44, REQUESTS: 44
EXPECTATIONS: 45, REQUESTS: 45
EXPECTATIONS: 46, REQUESTS: 46
EXPECTATIONS: 47, REQUESTS: 47
EXPECTATIONS: 48, REQUESTS: 48
EXPECTATIONS: 49, REQUESTS: 49
EXPECTATIONS: 50, REQUESTS: 50
EXPECTATIONS: 51, REQUESTS: 51
EXPECTATIONS: 52, REQUESTS: 52
EXPECTATIONS: 53, REQUESTS: 53
EXPECTATIONS: 54, REQUESTS: 54
EXPECTATIONS: 55, REQUESTS: 55
EXPECTATIONS: 56, REQUESTS: 56
EXPECTATIONS: 57, REQUESTS: 57
EXPECTATIONS: 58, REQUESTS: 58
EXPECTATIONS: 59, REQUESTS: 52
EXPECTATIONS: 60, REQUESTS: 49
EXPECTATIONS: 61, REQUESTS: 46
EXPECTATIONS: 62, REQUESTS: 44
EXPECTATIONS: 63, REQUESTS: 43
EXPECTATIONS: 64, REQUESTS: 41
EXPECTATIONS: 65, REQUESTS: 40
EXPECTATIONS: 66, REQUESTS: 39
EXPECTATIONS: 67, REQUESTS: 37
EXPECTATIONS: 68, REQUESTS: 36
EXPECTATIONS: 69, REQUESTS: 36
EXPECTATIONS: 70, REQUESTS: 35
EXPECTATIONS: 71, REQUESTS: 34
EXPECTATIONS: 72, REQUESTS: 33
EXPECTATIONS: 73, REQUESTS: 32
EXPECTATIONS: 74, REQUESTS: 32
EXPECTATIONS: 75, REQUESTS: 31
EXPECTATIONS: 76, REQUESTS: 31
EXPECTATIONS: 77, REQUESTS: 30
EXPECTATIONS: 78, REQUESTS: 29
EXPECTATIONS: 79, REQUESTS: 29
EXPECTATIONS: 80, REQUESTS: 28
EXPECTATIONS: 81, REQUESTS: 28
EXPECTATIONS: 82, REQUESTS: 27
EXPECTATIONS: 83, REQUESTS: 27
EXPECTATIONS: 84, REQUESTS: 27
EXPECTATIONS: 85, REQUESTS: 26
EXPECTATIONS: 86, REQUESTS: 26
EXPECTATIONS: 87, REQUESTS: 25
EXPECTATIONS: 88, REQUESTS: 25
EXPECTATIONS: 89, REQUESTS: 25
EXPECTATIONS: 90, REQUESTS: 24
EXPECTATIONS: 91, REQUESTS: 24
EXPECTATIONS: 92, REQUESTS: 24
EXPECTATIONS: 93, REQUESTS: 23
EXPECTATIONS: 94, REQUESTS: 23
EXPECTATIONS: 95, REQUESTS: 23
EXPECTATIONS: 96, REQUESTS: 23
EXPECTATIONS: 97, REQUESTS: 22
EXPECTATIONS: 98, REQUESTS: 22
EXPECTATIONS: 99, REQUESTS: 22
EXPECTATIONS: 100, REQUESTS: 22
EXPECTATIONS: 101, REQUESTS: 21
EXPECTATIONS: 102, REQUESTS: 21
EXPECTATIONS: 103, REQUESTS: 21
EXPECTATIONS: 104, REQUESTS: 21
EXPECTATIONS: 105, REQUESTS: 20
EXPECTATIONS: 106, REQUESTS: 20
EXPECTATIONS: 107, REQUESTS: 20
EXPECTATIONS: 108, REQUESTS: 20
EXPECTATIONS: 109, REQUESTS: 20
EXPECTATIONS: 110, REQUESTS: 19
EXPECTATIONS: 111, REQUESTS: 19
EXPECTATIONS: 112, REQUESTS: 19
EXPECTATIONS: 113, REQUESTS: 19
EXPECTATIONS: 114, REQUESTS: 19
EXPECTATIONS: 115, REQUESTS: 18
EXPECTATIONS: 116, REQUESTS: 18
EXPECTATIONS: 117, REQUESTS: 18
EXPECTATIONS: 118, REQUESTS: 18
EXPECTATIONS: 119, REQUESTS: 18
EXPECTATIONS: 120, REQUESTS: 18
EXPECTATIONS: 121, REQUESTS: 17
EXPECTATIONS: 122, REQUESTS: 17
EXPECTATIONS: 123, REQUESTS: 17
EXPECTATIONS: 124, REQUESTS: 17
EXPECTATIONS: 125, REQUESTS: 17
EXPECTATIONS: 126, REQUESTS: 17
EXPECTATIONS: 127, REQUESTS: 17
EXPECTATIONS: 128, REQUESTS: 16
EXPECTATIONS: 129, REQUESTS: 16
EXPECTATIONS: 130, REQUESTS: 16
EXPECTATIONS: 131, REQUESTS: 16
EXPECTATIONS: 132, REQUESTS: 16
EXPECTATIONS: 133, REQUESTS: 16
EXPECTATIONS: 134, REQUESTS: 16
EXPECTATIONS: 135, REQUESTS: 16
EXPECTATIONS: 136, REQUESTS: 15
EXPECTATIONS: 137, REQUESTS: 15
EXPECTATIONS: 138, REQUESTS: 15
EXPECTATIONS: 139, REQUESTS: 15
EXPECTATIONS: 140, REQUESTS: 15
EXPECTATIONS: 141, REQUESTS: 15
EXPECTATIONS: 142, REQUESTS: 15
EXPECTATIONS: 143, REQUESTS: 15
EXPECTATIONS: 144, REQUESTS: 15
EXPECTATIONS: 145, REQUESTS: 14
EXPECTATIONS: 146, REQUESTS: 14
EXPECTATIONS: 147, REQUESTS: 14
EXPECTATIONS: 148, REQUESTS: 14
EXPECTATIONS: 149, REQUESTS: 14
EXPECTATIONS: 150, REQUESTS: 14

As you can see, once I reach a certain amount of expectations/requests, MockServer begins forgetting about requests that previously came through. The number of requests that MockServer drops per loop starts out pretty high (6), but then seems to taper off as the program runs.

---

One more thing to note. I tested just making 1 expectation, and hammering it with 500 requests. The amount of recorded requests in MockServer increased to 400, and then capped off at 400.

So it appears that A) There is an upper limit of 400 recorded requests and B) Something about creating 50+ expectations causes requests to start being deleted.

[rcolombo]

I believe I found a workaround for this issue by changing the logLevel from INFO to ERROR. I have now sent up to 500 expectations without having recorded requests drop.

I'm not sure why the logLevel should matter for this, but it appears that it does.

LogLevel info was writing a ton of data to disk (>3GB) and using lots of CPU. Perhaps that has something to do with it.

[jamesdbloom]

This is caused by the explosion of log entries created when there are so many expectations. For example if there are 150 expectations and 150 requests that is typically 150 151 = 22,650 log entries. This is because with so many expectations when you submit a request there are lots of log entries stating the request did not match. Given the log was limited to 2,000 entries (which was too low) your script easily reached the point where the oldest log entries where being removed from the log. This was limited to avoid issues with memory growing constantly, however the limits were too low. Currently the default max expectations is 1,000 and the size of the log was limited to 2 1,000 = 2,000.

*I have now separated the log limit size as a separate configuration property and increased the default to 5,00 5,000 = 25,000,000. I have also increased the default maximum number of expectations to 5,000.**

With this new value I have run your script up to 700 iterations and the memory used is only 55 MB and the number of requests does not drop. I have also run it up to 1500 iterations and the memory used is 78 MB and the number of requests does not drop.

I think this should have completely resolved your issues now. The changes will be available in the SNAPSHOT version (once the build completes) and will be in the next release. In the meantime you could increase the maximum expectations by setting the -Dmockserver.maxExpectations=... system property or using the ConfigurationProperties.maxExpectations(int ...) method.

[rcolombo]

Thanks @jamesdbloom !

[narras-oss]

Please provide the fix version