Negative number of users in report!

There seems to be a problem with reporting in 2.0.1. The number of active users is not what we know it should be. And there are points in the graph where the number of users is negative.

Opening it up, there seems to be response bodies embedded in the log. Not sure if that’s supposed to be happening or not. Should it?

I would attach the simulation log in question, but thanks to the embedded response bodies, the file is 177M. I compressed it, but the Google Groups interface refuses to accept the file. Let me know if there is another way I can send the simulation.log to you.

There seems to be a problem with reporting in 2.0.1. The number of active
users is not what we know it should be. And there are points in the graph
where the number of users is negative.

Reproducer, please?

Opening it up, there seems to be response bodies embedded in the log. Not
sure if that's supposed to be happening or not. Should it?

The only reason I see for response bodies to end up in simulation.log is
failing check on full response bodyString (would get messages such as
"expected foo but got bar". Expected, then.

I would attach the simulation log in question, but thanks to the embedded
response bodies, the file is 177M. I compressed it, but the Google Groups
interface refuses to accept the file. Let me know if there is another way
I can send the simulation.log to you.

Google Drive, Dropbox, etc... But I don't expect to see much in there. I
would need a reproducer.

Not really possible to give you the whole script, as it hits resources that are not public. But here is the compressed simulation log (my email client is letting me attach it). It’s behavior suggests that as a good place to start looking. We had set it to ramp to 150 users over 75 seconds. If you generate a report from this log, you will notice the negative number of users towards the end. Notice the peak is never 150, like it should have been.

If I had to guess, I would postulate that there is a problem parsing the simulation log for a few of the requests. Probably related to the response bodies being in the logs. I’m just guessing, but maybe the parser is getting confused and slurping in too much, so it is missing some of the ramp-up, but manages to parse the ramp-down, hence the negative user count.

FYI, the code that is logging the response body looks like this:

.exec(

http(“Load Login Page - get session”)

.get("%s/authorize".format(baseUrl))

.queryParam(“client_id”, config.getString(“client_id”))

.queryParam(“scope”, scope)

.queryParam(“response_type”, “code”)

.queryParam(“redirect_uri”, config.getString(“redirectUrl”))

.queryParam(“state”, “init”)

.queryParam(“nonce”, “210643108”)

.queryParam(“display”, “page”)

.queryParam(“prompt”, “login”)

.header(“Content-Type”, “application/x-www-form-urlencoded”)

.check(css(“form input”, “value”).optional.saveAs(“sessionID”))

.check(status.in(200 to 302))

.check(header(“Location”).transform(location =>

location.indexOf(“code=”) match {

case -1 => “”

case i: Int => location.substring(i).split("&").find(_.startsWith(“code=”)).get.split("=")(1)

}

).optional.saveAs(“authCode”))

)

One thing that might be relevant is this bit of code (I did not do this, this is inherited code that I am working on replacing)

http

.baseURL(baseUrl)

.disableFollowRedirect

.extraInfoExtractor(extraInfo => List(extraInfo.response.body :: Nil)

Not sure why the extraInfoExtractor is there, or what (if anything) anyone is using it for. I’m going to experiment with commenting out that line and see if everything works as expected. I’ll let you know.

simulation.log.bz2 (3.66 MB)

So far, removing the .extraInfoExtractor returns sanity to the reporting. Wonder what they were thinking when they put that in there…

Debugging maybe.