Repository: mcollina/autocannon
Pull request #262 (2020-06-08 20:18:49)

fix: onResponse sequence
### What's in there?

- [x] fix for `request.onResponse()` when cycling over requests array

In my previous PR #261, I misunderstood how `http-parser-js` works, and I introduced an issue.
Assuming a server which returns "hello" on POST and "world" on GET, and the following request array:
```js
[{
  method: 'POST'
  onResponse(status, body) {
    console.log('POST', body)
  }
}, {
  method: 'GET'
}]
```

would produce output:
```bash
POST hello
POST world
```

The reason is because when a request has `onResponse()`, httpClient goes to next request on body received event, instead of message complete event. I thought body event was issued after message complete, which is completely wrong.

I've restored previous sequence, which is going to next request on message complete event, regardless of the request type.

Finally, http client will now keep a reference to requests instead of letting requestIterator knowing which request is current. This is a much more robust solution, but I'm still wondering about pipelining.

[here](https://github.com/mcollina/autocannon/compare/v4.6.0...feugy:master#diff-addcc55ebd241c58acd481fdd02b3b7a) is a comparison with 4.6.0, which helps understanding the changes better.


### Notes to reviewers

Peformance for nominal case is roughly the same:
```bash
damiensiminonfeugas|(v5.0.0):~/dev/nearform/autocannon$ node autocannon.js http://localhost:3000
Running 10s test @ http://localhost:3000
10 connections

┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬──────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max      │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼──────────┤
│ Latency │ 0 ms │ 0 ms │ 0 ms  │ 0 ms │ 0.01 ms │ 0.07 ms │ 10.96 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴──────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬──────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg      │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Req/Sec   │ 37279   │ 37279   │ 47967   │ 48447   │ 46738.91 │ 3132.87 │ 37261   │
├───────────┼─────────┼─────────┼─────────┼─────────┼──────────┼─────────┼─────────┤
│ Bytes/Sec │ 4.14 MB │ 4.14 MB │ 5.32 MB │ 5.38 MB │ 5.19 MB  │ 348 kB  │ 4.14 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴──────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

514k requests in 11.04s, 57.1 MB read
damiensiminonfeugas|(v5.0.0):~/dev/nearform/autocannon$ git checkout master
Previous HEAD position was 2bab2af Bumped v5.0.0
Switched to branch 'master'
Your branch is up to date with 'origin/master'.
damiensiminonfeugas|master:~/dev/nearform/autocannon$ node autocannon.js http://localhost:3000
Running 10s test @ http://localhost:3000
10 connections

┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬─────────┐
│ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max     │
├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼─────────┤
│ Latency │ 0 ms │ 0 ms │ 0 ms  │ 0 ms │ 0.01 ms │ 0.05 ms │ 7.54 ms │
└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴─────────┘
┌───────────┬─────────┬─────────┬────────┬─────────┬──────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%    │ 97.5%   │ Avg      │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼────────┼─────────┼──────────┼─────────┼─────────┤
│ Req/Sec   │ 41759   │ 41759   │ 47679  │ 48191   │ 47070.55 │ 1738.44 │ 41728   │
├───────────┼─────────┼─────────┼────────┼─────────┼──────────┼─────────┼─────────┤
│ Bytes/Sec │ 4.63 MB │ 4.63 MB │ 5.3 MB │ 5.35 MB │ 5.23 MB  │ 194 kB  │ 4.63 MB │
└───────────┴─────────┴─────────┴────────┴─────────┴──────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

518k requests in 11.04s, 57.5 MB read

```


Patch:
diff --git a/lib/httpClient.js b/lib/httpClient.js
index 57cd389..0aafade 100644
--- a/lib/httpClient.js
+++ b/lib/httpClient.js
@@ -87,15 +87,6 @@ function Client (opts) {
     this.resData[this.cer].headers = opts
   }
 
-  const emitAndMove = () => {
-    const resp = this.resData[this.cer]
-    this.emit('response', resp.headers.statusCode, resp.bytes, resp.duration)
-    resp.bytes = 0
-    this.cer = this.cer === pipelining - 1 ? 0 : this.cer++
-    this.requestIterator.nextRequest()
-    this._doRequest(this.cer)
-  }
-
   this.parser[HTTPParser.kOnBody] = (body, start, len) => {
     this.emit('body', body)
     const bodyString = '' + body.slice(start, start + len)
@@ -107,23 +98,22 @@ function Client (opts) {
     }
 
     const resp = this.resData[this.cer]
-    if (this.requestIterator.expectsBody()) {
-      this.requestIterator.recordBody(resp.headers.statusCode, bodyString)
-      emitAndMove()
-    }
+    this.requestIterator.recordBody(resp.req, resp.headers.statusCode, bodyString)
   }
 
   this.parser[HTTPParser.kOnMessageComplete] = () => {
-    const end = process.hrtime(this.resData[this.cer].startTime)
-    this.resData[this.cer].duration = end[0] * 1e3 + end[1] / 1e6
+    const resp = this.resData[this.cer]
+    const end = process.hrtime(resp.startTime)
+    resp.duration = end[0] * 1e3 + end[1] / 1e6
 
     if (!this.destroyed && this.reconnectRate && this.reqsMade % this.reconnectRate === 0) {
       return this._resetConnection()
     }
 
-    if (!this.requestIterator.expectsBody()) {
-      emitAndMove()
-    }
+    this.emit('response', resp.headers.statusCode, resp.bytes, resp.duration)
+    resp.bytes = 0
+    this.cer = this.cer === pipelining - 1 ? 0 : this.cer++
+    this._doRequest(this.cer)
   }
 
   this._connect()
@@ -172,6 +162,10 @@ Client.prototype._doRequest = function (rpi) {
       return this.destroy()
     }
     this.emit('request')
+    if (this.reqsMade > 0) {
+      this.requestIterator.nextRequest()
+    }
+    this.resData[rpi].req = this.requestIterator.currentRequest
     this.resData[rpi].startTime = process.hrtime()
     this.conn.write(this.getRequestBuffer())
     this.timeoutTicker.reschedule(this.timeout)
diff --git a/lib/requestIterator.js b/lib/requestIterator.js
index 3f41a50..db972af 100644
--- a/lib/requestIterator.js
+++ b/lib/requestIterator.js
@@ -81,13 +81,9 @@ RequestIterator.prototype.rebuildRequest = function () {
   }
 }
 
-RequestIterator.prototype.expectsBody = function () {
-  return this.currentRequest && typeof this.currentRequest.onResponse === 'function'
-}
-
-RequestIterator.prototype.recordBody = function (status, body) {
-  if (this.expectsBody()) {
-    this.currentRequest.onResponse(status, body, this.context)
+RequestIterator.prototype.recordBody = function (request, status, body) {
+  if (request && typeof request.onResponse === 'function') {
+    request.onResponse(status, body, this.context)
   }
 }
 


Test patch:
diff --git a/test/httpClient.test.js b/test/httpClient.test.js
index 7b7b238..967419f 100644
--- a/test/httpClient.test.js
+++ b/test/httpClient.test.js
@@ -546,9 +546,12 @@ test('client exposes response bodies and statuses', (t) => {
   opts.method = 'POST'
   opts.requests = [
     {
-      body: 'hello world again',
+      body: 'hello world!',
       onResponse: (status, body) => responses.push({ status, body })
     },
+    {
+      body: 'hello world again'
+    },
     {
       method: 'GET',
       onResponse: (status, body) => responses.push({ status, body })
@@ -563,19 +566,47 @@ test('client exposes response bodies and statuses', (t) => {
     switch (number) {
       case 1:
         t.same(client.getRequestBuffer(),
-          Buffer.from(`POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 17\r\n\r\nhello world again`),
+          Buffer.from(`POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 12\r\n\r\nhello world!`),
           'first request')
+        t.deepEqual(responses, [{
+          status: 200,
+          body: 'hello!'
+        }])
         break
       case 2:
         t.same(client.getRequestBuffer(),
-          Buffer.from(`GET / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\n\r\n`),
+          Buffer.from(`POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 17\r\n\r\nhello world again`),
           'second request')
         t.deepEqual(responses, [{
           status: 200,
           body: 'hello!'
+        }])
+        break
+      case 3:
+        t.same(client.getRequestBuffer(),
+          Buffer.from(`GET / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\n\r\n`),
+          'third request')
+        t.deepEqual(responses, [{
+          status: 200,
+          body: 'hello!'
+        }, {
+          status: 200,
+          body: 'world!'
+        }])
+        break
+      case 4:
+        t.same(client.getRequestBuffer(),
+          Buffer.from(`POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 12\r\n\r\nhello world!`),
+          'first request')
+        t.deepEqual(responses, [{
+          status: 200,
+          body: 'hello!'
         }, {
           status: 200,
           body: 'world!'
+        }, {
+          status: 200,
+          body: 'hello!'
         }])
         client.destroy()
         t.end()
diff --git a/test/requestIterator.test.js b/test/requestIterator.test.js
index 7595650..9614f07 100644
--- a/test/requestIterator.test.js
+++ b/test/requestIterator.test.js
@@ -211,14 +211,14 @@ test('request iterator should invoke onResponse callback when set', (t) => {
   ]
 
   const iterator = new RequestIterator(opts)
-  iterator.recordBody(200, 'ok')
+  iterator.recordBody(iterator.currentRequest, 200, 'ok')
   iterator.nextRequest()
-  iterator.recordBody(500, 'ignored')
+  iterator.recordBody(iterator.currentRequest, 500, 'ignored')
   iterator.nextRequest()
-  iterator.recordBody(201, '')
+  iterator.recordBody(iterator.currentRequest, 201, '')
   // will reset the iterator
   iterator.nextRequest()
-  iterator.recordBody(200, 'ok')
+  iterator.recordBody(iterator.currentRequest, 200, 'ok')
 })
 
 test('request iterator should properly mutate requests if a setupRequest function is located', (t) => {