Repository: mcollina/autocannon
Pull request #282 (2020-09-10 12:01:15)

feat: report many pipeline resets
This is a follow up of #281 
Now, request iterator resets when some of its `setupRequest()` returning falsey value (previously it the pipeline was simply crashing).

But this may actually obfuscate bugs of the tested service: often `setupRequest()` fails as the previous response did not contained expected data.

This PR simply displays how many times the pipeline reseted, so users could decide whether it is intended or not.

```shell
┌─────────┬────────┬────────┬────────┬────────┬───────────┬───────────┬────────────┐
│ Stat    │ 2.5%   │ 50%    │ 97.5%  │ 99%    │ Avg       │ Stdev     │ Max        │
├─────────┼────────┼────────┼────────┼────────┼───────────┼───────────┼────────────┤
│ Latency │ 121 ms │ 624 ms │ 890 ms │ 914 ms │ 541.06 ms │ 237.32 ms │ 1002.16 ms │
└─────────┴────────┴────────┴────────┴────────┴───────────┴───────────┴────────────┘
┌───────────┬────────┬────────┬────────┬────────┬────────┬─────────┬────────┐
│ Stat      │ 1%     │ 2.5%   │ 50%    │ 97.5%  │ Avg    │ Stdev   │ Min    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Req/Sec   │ 218    │ 218    │ 372    │ 479    │ 356.5  │ 70.29   │ 218    │
├───────────┼────────┼────────┼────────┼────────┼────────┼─────────┼────────┤
│ Bytes/Sec │ 190 kB │ 190 kB │ 372 kB │ 465 kB │ 369 kB │ 67.3 kB │ 190 kB │
└───────────┴────────┴────────┴────────┴────────┴────────┴─────────┴────────┘

Req/Bytes counts sampled once per second.

10k requests in 28.09s, 10.3 MB read
18 errors (0 timeouts)
request pipeline was resetted 4 times

```

_Note:_ I know `test/progressTracker.test.stub.js` isn't part of the test suite, but as I've changed it to troubleshoot the feature, I though it would be fine to keep a new test in it.
The feature is properly covered in `est/httpClient.test.js` and `test/run.test.js` test files.

_Edit:_ this PR actually unveiled some flaws in the previous implementation.
Reseting request pipeline the way I did is wrong, as it may leave `currentRequest.requestBuffer` to `null`.

This new version fixes the flaw, and also handle a specific case where the very first `setupRequest()` fails. In this situation, we can not reset pipeline (or it'll never end), and we must exit on an error.


Patch:
diff --git a/README.md b/README.md
index 0048844..292ece7 100644
--- a/README.md
+++ b/README.md
@@ -342,6 +342,7 @@ The results object emitted by `done` and passed to the `autocannon()` callback h
 * `connections`: The amount of connections used (value of `opts.connections`).
 * `pipelining`: The number of pipelined requests used per connection (value of `opts.pipelining`).
 * `non2xx`: The number of non-2xx response status codes received.
+* `resets`: How many times the requests pipeline was reset due to `setupRequest` returning a falsey value.
 
 The histogram objects for `requests`, `latency` and `throughput` are [hdr-histogram-percentiles-obj](https://github.com/thekemkid/hdr-histogram-percentiles-obj) objects and have this shape:
 
@@ -371,6 +372,7 @@ The events a `Client` can emit are listed here:
     * `statusCode`: The http status code of the response.
     * `resBytes`: The response byte length.
     * `responseTime`: The time taken to get a response for the initiating the request.
+* `reset`: Emitted when the requests pipeline was reset due to `setupRequest` returning a falsey value.
 
 Example using the autocannon events and the client API and events:
 
diff --git a/lib/httpClient.js b/lib/httpClient.js
index 74cb341..1a54139 100644
--- a/lib/httpClient.js
+++ b/lib/httpClient.js
@@ -171,6 +171,9 @@ Client.prototype._doRequest = function (rpi) {
     this.emit('request')
     if (this.reqsMade > 0) {
       this.requestIterator.nextRequest()
+      if (this.requestIterator.resetted) {
+        this.emit('reset')
+      }
     }
     this.resData[rpi].req = this.requestIterator.currentRequest
     this.resData[rpi].startTime = process.hrtime()
diff --git a/lib/progressTracker.js b/lib/progressTracker.js
index 0108a88..bc759a4 100644
--- a/lib/progressTracker.js
+++ b/lib/progressTracker.js
@@ -131,6 +131,9 @@ function track (instance, opts) {
     if (result.mismatches) {
       logToStream(`${format(result.mismatches)} requests with mismatched body`)
     }
+    if (result.resets) {
+      logToStream(`request pipeline was resetted ${format(result.resets)} ${result.resets === 1 ? 'time' : 'times'}`)
+    }
   })
 
   function logToStream (msg) {
diff --git a/lib/requestIterator.js b/lib/requestIterator.js
index 9bebacb..d758b9f 100644
--- a/lib/requestIterator.js
+++ b/lib/requestIterator.js
@@ -9,6 +9,7 @@ function RequestIterator (opts) {
     return new RequestIterator(opts)
   }
 
+  this.resetted = false
   this.context = {}
   this.reqDefaults = opts
   this.requestBuilder = requestBuilder(opts)
@@ -18,6 +19,7 @@ function RequestIterator (opts) {
 inherits(RequestIterator, Object)
 
 RequestIterator.prototype.nextRequest = function () {
+  this.resetted = false
   ++this.currentRequestIndex
   // when looping over available request, clear context for a fresh start
   if (this.currentRequestIndex === this.requests.length) {
@@ -27,10 +29,7 @@ RequestIterator.prototype.nextRequest = function () {
   this.currentRequest = this.requests[this.currentRequestIndex]
   // only builds if it has dynamic setup
   if (this.reqDefaults.idReplacement || typeof this.currentRequest.setupRequest === 'function') {
-    if (!this.rebuildRequest()) {
-      // when setupRequest returned falsey, reset
-      this.currentRequestIndex = -1
-    }
+    this.rebuildRequest()
   }
   return this.currentRequest
 }
@@ -42,6 +41,7 @@ RequestIterator.prototype.nextRequestBuffer = function () {
 }
 
 RequestIterator.prototype.setRequests = function (newRequests) {
+  this.resetted = false
   this.requests = newRequests || [{}]
   this.currentRequestIndex = 0
   // build all request which don't have dynamic setup, except if it's the first one
@@ -77,12 +77,20 @@ RequestIterator.prototype.setRequest = function (newRequest) {
 
 RequestIterator.prototype.rebuildRequest = function () {
   let data
+  this.resetted = false
   if (this.currentRequest) {
     data = this.requestBuilder(this.currentRequest, this.context)
     if (data) {
       this.currentRequest.requestBuffer = this.reqDefaults.idReplacement
         ? Buffer.from(data.toString().replace(/\[<id>\]/g, hyperid()))
         : data
+    } else if (this.currentRequestIndex === 0) {
+      // when first request fails to build, we can not reset pipeline, or it'll never end
+      throw new Error('First setupRequest() failed did not returned valid request. Stopping')
+    } else {
+      this.currentRequestIndex = this.requests.length - 1
+      this.nextRequest()
+      this.resetted = true
     }
   }
   return data
diff --git a/lib/run.js b/lib/run.js
index a106cb4..93f8fa4 100644
--- a/lib/run.js
+++ b/lib/run.js
@@ -90,6 +90,7 @@ function _run (opts, cb, tracker) {
   let totalBytes = 0
   let totalRequests = 0
   let totalCompletedRequests = 0
+  let resets = 0
   const amount = opts.amount
   let stop = false
   let restart = true
@@ -183,7 +184,8 @@ function _run (opts, cb, tracker) {
         finish: new Date(),
         connections: opts.connections,
         pipelining: opts.pipelining,
-        non2xx: statusCodes[0] + statusCodes[2] + statusCodes[3] + statusCodes[4]
+        non2xx: statusCodes[0] + statusCodes[2] + statusCodes[3] + statusCodes[4],
+        resets: resets
       }
       result.latency.totalCount = latencies.totalCount
       result.requests.sent = totalRequests
@@ -208,6 +210,7 @@ function _run (opts, cb, tracker) {
           totalBytes = 0
           totalRequests = 0
           totalCompletedRequests = 0
+          resets = 0
           statusCodes.fill(0)
           requests.reset()
           latencies.reset()
@@ -246,6 +249,7 @@ function _run (opts, cb, tracker) {
       client.on('response', onResponse)
       client.on('connError', onError)
       client.on('mismatch', onExpectMismatch)
+      client.on('reset', () => { resets++ })
       client.on('timeout', onTimeout)
       client.on('request', () => { totalRequests++ })
       client.on('done', onDone)


Test patch:
diff --git a/test/httpClient.test.js b/test/httpClient.test.js
index 9015f93..cd9813d 100644
--- a/test/httpClient.test.js
+++ b/test/httpClient.test.js
@@ -593,6 +593,53 @@ test('client should have 2 different requests it iterates over', (t) => {
   })
 })
 
+test('client should emit reset when request iterator has reset', (t) => {
+  t.plan(1)
+  const server = helper.startServer()
+  const opts = server.address()
+
+  const requests = [
+    {
+      method: 'POST',
+      body: 'hello world again'
+    },
+    {
+      method: 'POST',
+      body: 'modified',
+      // falsey result will reset
+      setupRequest: () => {}
+    },
+    {
+      method: 'POST',
+      body: 'never used'
+    }
+  ]
+
+  const client = new Client(opts)
+  client.setRequests(requests)
+  client.on('reset', () => {
+    client.destroy()
+    t.end()
+  })
+  client.on('response', () => {
+    t.same(client.getRequestBuffer().toString(), makeResponseFromBody({ server, ...requests[0] }), 'first request was okay')
+  })
+})
+
+test('client should stop when first setupRequest() fails', (t) => {
+  t.plan(1)
+  const server = helper.startServer()
+  const opts = server.address()
+
+  const client = new Client(opts)
+  t.throws(
+    () => client.setRequests([{ method: 'GET', setupRequest: () => {} }]),
+    'First setupRequest() failed did not returned valid request. Stopping'
+  )
+  client.destroy()
+  t.end()
+})
+
 test('client exposes response bodies and statuses', (t) => {
   const server = helper.startServer({
     body: ({ method }) => method === 'POST' ? 'hello!' : 'world!'
diff --git a/test/progressTracker.test.stub.js b/test/progressTracker.test.stub.js
index c7f9c45..fc4be71 100644
--- a/test/progressTracker.test.stub.js
+++ b/test/progressTracker.test.stub.js
@@ -67,3 +67,30 @@ test('should log mismatches', t => {
   })
   t.pass()
 })
+
+test('should log resets', t => {
+  const server = helper.startServer()
+  const instance = autocannon({
+    url: `http://localhost:${server.address().port}`,
+    connections: 1,
+    amount: 10,
+    requests: [
+      { method: 'GET' },
+      {
+        method: 'GET',
+        // falsey result will reset
+        setupRequest: () => {}
+      },
+      { method: 'GET' }
+    ]
+  }, console.log)
+
+  setTimeout(() => {
+    instance.stop()
+    t.end()
+  }, 2000)
+  autocannon.track(instance, {
+    renderProgressBar: true
+  })
+  t.pass()
+})
diff --git a/test/requestIterator.test.js b/test/requestIterator.test.js
index dca7f76..de2a7b2 100644
--- a/test/requestIterator.test.js
+++ b/test/requestIterator.test.js
@@ -275,7 +275,7 @@ test('request iterator should properly mutate requests if a setupRequest functio
 })
 
 test('request iterator should reset when setupRequest returns nothing', (t) => {
-  t.plan(6)
+  t.plan(12)
 
   const opts = server.address()
   opts.method = 'POST'
@@ -283,40 +283,60 @@ test('request iterator should reset when setupRequest returns nothing', (t) => {
   let i = 0
 
   opts.requests = [
+    { method: 'GET' },
     {
       body: 'hello world',
-      setupRequest: req => {
-        req.body += i++
-        return i > 2 ? null : req
-      }
+      setupRequest: req => ++i >= 2 ? null : req
     },
-    {
-      method: 'GET'
-    }
+    { method: 'PUT' }
   ]
 
-  const request1Res = `POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 12\r\n\r\nhello world0`
-  const request2Res = `GET / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\n\r\n`
-  const request3Res = `POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 12\r\n\r\nhello world1`
+  const requestGET = `GET / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\n\r\n`
+  const requestPUT = `PUT / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\n\r\n`
+  const requestPOST = `POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 11\r\n\r\nhello world`
 
   const iterator = new RequestIterator(opts)
-  // first POST, i becomes 1
-  t.same(iterator.currentRequest.requestBuffer.toString(), request1Res, 'request 1 was okay')
+  t.is(iterator.resetted, false)
+  // first GET, i is 0
+  t.same(iterator.currentRequest.requestBuffer.toString(), requestGET, 'request 1 was okay')
   iterator.nextRequest()
-  // first GET, is is 1
-  t.same(iterator.currentRequest.requestBuffer.toString(), request2Res, 'request 2 was okay')
+  // first POST, i becomes 1
+  t.is(iterator.resetted, false)
+  t.same(iterator.currentRequest.requestBuffer.toString(), requestPOST, 'request 2 was okay')
   iterator.nextRequest()
-  // second POST, is becomes 2
-  t.same(iterator.currentRequest.requestBuffer.toString(), request3Res, 'request 3 was okay')
+  // first PUT, i is 1
+  t.is(iterator.resetted, false)
+  t.same(iterator.currentRequest.requestBuffer.toString(), requestPUT, 'request 3 was okay')
   iterator.nextRequest()
-  // second GET, is is 2
-  t.same(iterator.currentRequest.requestBuffer.toString(), request2Res, 'request 4 was okay')
+  // second GET, i is 1
+  t.is(iterator.resetted, false)
+  t.same(iterator.currentRequest.requestBuffer.toString(), requestGET, 'request 4 was okay')
   iterator.nextRequest()
-  // third POST: because is was 2, pipeline is reset. no GET, and we reuse latest POST
-  t.same(iterator.currentRequest.requestBuffer.toString(), request3Res, 'request 5 was okay')
+  // second POST, i becomes 2, pipeline is reset
+  t.is(iterator.resetted, true)
+  t.same(iterator.currentRequest.requestBuffer.toString(), requestGET, 'request 5 was okay')
   iterator.nextRequest()
-  // first POST: is is higher than 2, we keep reseting pipeline, and reusing request body
-  t.same(iterator.currentRequest.requestBuffer.toString(), request3Res, 'request 6 was okay')
+  // third POST, i becomes 3, pipeline is reset
+  t.is(iterator.resetted, true)
+  t.same(iterator.currentRequest.requestBuffer.toString(), requestGET, 'request 6 was okay')
+})
+
+test('request iterator should throw when first setupRequest returns nothing', (t) => {
+  t.plan(4)
+
+  const opts = server.address()
+  opts.method = 'POST'
+
+  let i = 0
+  opts.requests = [{ body: 'hello world', setupRequest: req => ++i > 1 ? null : req }]
+  const requestPOST = `POST / HTTP/1.1\r\nHost: localhost:${server.address().port}\r\nConnection: keep-alive\r\nContent-Length: 11\r\n\r\nhello world`
+
+  const iterator = new RequestIterator(opts)
+  t.is(iterator.resetted, false)
+  // first POST, i is 0
+  t.same(iterator.currentRequest.requestBuffer.toString(), requestPOST, 'request 1 was okay')
+  t.throws(() => iterator.nextRequest(), 'First setupRequest() failed did not returned valid request. Stopping')
+  t.is(iterator.resetted, false)
 })
 
 test('request iterator should maintain context while looping on requests', (t) => {
diff --git a/test/run.test.js b/test/run.test.js
index 3b5773d..fe1dec4 100644
--- a/test/run.test.js
+++ b/test/run.test.js
@@ -61,6 +61,7 @@ test('run', (t) => {
 
     t.equal(result.errors, 0, 'no errors')
     t.equal(result.mismatches, 0, 'no mismatches')
+    t.equal(result.resets, 0, 'no resets')
 
     t.equal(result['1xx'], 0, '1xx codes')
     t.equal(result['2xx'], result.requests.total, '2xx codes')
@@ -593,6 +594,7 @@ test('run promise', (t) => {
     t.ok(result.finish, 'finish time exists')
 
     t.equal(result.errors, 0, 'no errors')
+    t.equal(result.resets, 0, 'no resets')
 
     t.equal(result['1xx'], 0, '1xx codes')
     t.equal(result['2xx'], result.requests.total, '2xx codes')
@@ -673,3 +675,25 @@ test('should handle duration in string format', t => {
     t.pass()
   })
 })
+
+test('should count resets', t => {
+  t.plan(1)
+  const server = helper.startServer()
+  run({
+    url: 'http://localhost:' + server.address().port,
+    connections: 1,
+    amount: 10,
+    requests: [
+      { method: 'GET' },
+      { method: 'PUT' },
+      {
+        method: 'POST',
+        // falsey result will reset
+        setupRequest: () => {}
+      }
+    ]
+  }).then((result) => {
+    t.is(result.resets, 4)
+    t.end()
+  })
+})