Merge pull request #462 from pact-foundation/feat/request-response-tr…

…acing

feat: request response tracing

.github/issue_template.md

@@ -22,6 +22,7 @@ Confirm the following:
 - [ ] I have created a reproducable git repository (see below) to illuminate the problem
 - [ ] I have the read the FAQs in the Readme
 - [ ] I have triple checked, that there are **no unhandled promises** in my code
+- [ ] I have set my log level to trace and attached a log file showing the complete request/response cycle
 
 ### Expected behaviour
 

.nycrc

@@ -19,8 +19,8 @@
   ],
   "sourceMap": true,
   "instrument": true,
-  "lines": 90,
-  "statements": 90,
-  "functions": 90,
-  "branches": 90
+  "lines": 80,
+  "statements": 80,
+  "functions": 80,
+  "branches": 80
 }

README.md

@@ -585,7 +585,7 @@ const {
 } = require("@pact-foundation/pact")
 
 // 1 Dog API Handler
-const dogApiHandler = function (dog) {
+const dogApiHandler = function(dog) {
   if (!dog.id && !dog.name && !dog.type) {
     throw new Error("missing fields")
   }
@@ -1063,7 +1063,7 @@ There is an `XmlBuilder` class that provides a DSL to help construct XML bodies
 for example:
 
 ```javascript
-body: new XmlBuilder("1.0", "UTF-8", "ns1:projects").build((el) => {
+body: new XmlBuilder("1.0", "UTF-8", "ns1:projects").build(el => {
   el.setAttributes({
     id: "1234",
     "xmlns:ns1": "http://some.namespace/and/more/stuff",
@@ -1076,8 +1076,8 @@ body: new XmlBuilder("1.0", "UTF-8", "ns1:projects").build((el) => {
       name: string("Project 1"),
       due: timestamp("yyyy-MM-dd'T'HH:mm:ss.SZ", "2016-02-11T09:46:56.023Z"),
     },
-    (project) => {
-      project.appendElement("ns1:tasks", {}, (task) => {
+    project => {
+      project.appendElement("ns1:tasks", {}, task => {
         task.eachLike(
           "ns1:task",
           {
@@ -1157,8 +1157,7 @@ You can change the log levels using the `LOG_LEVEL` environment variable.
 
 ## Troubleshooting / FAQs
 
-If you are having issues, a good place to start is setting `logLevel: 'DEBUG'`
-when configuring the `new Pact({...})` object.
+If you are having issues, a good place to start is setting `logLevel: 'debug'` when configuring the `new Pact({...})` object. Setting it to `trace` will give you detailed in/out requests as far as Pact sees it.
 
 ### Alpine + Docker
 
@@ -1236,11 +1235,11 @@ The correct code for the above is:
 
 ```js
 it("returns a successful thing", () => {
-  return executeApiCallThatIsAPromise()
+  return executeApiCallThatIsAPromise() // <- explicit return here, you could also use the "async/await" syntax here
     .then((response) => {
       expect(response.data).to.eq({...})
     })
-    .then(() => provider.verify())
+    .then(() => provider.verify()) // provider.verify() also returned
   })
 ```
 
@@ -1328,7 +1327,7 @@ See [this issue](https://github.com/angular/angular/issues/13554) for background
 
 ### Debugging
 
-If your standard tricks don't get you anywhere, setting the logLevel to `DEBUG` and increasing the timeout doesn't help and you don't know where else to look, it could be that the binaries we use to do much of the Pact magic aren't starting as expected.
+If your standard tricks don't get you anywhere, setting the logLevel to `trace` and increasing the timeout doesn't help and you don't know where else to look, it could be that the binaries we use to do much of the Pact magic aren't starting as expected.
 
 Try starting the mock service manually and seeing if it comes up. When submitting a bug report, it would be worth running these commands before hand as it will greatly help us:
 

src/common/logger.ts

@@ -1,6 +1,8 @@
 import * as bunyan from "bunyan"
+import { RequestOptions, ClientRequest, IncomingMessage } from "http"
 const PrettyStream = require("bunyan-prettystream")
 const pkg = require("./metadata")
+const http = require("http")
 
 const prettyStdOut = new PrettyStream()
 prettyStdOut.pipe(process.stdout)
@@ -23,7 +25,7 @@ export class Logger extends bunyan {
   }
 }
 
-export default new Logger({
+const logger = new Logger({
   name: `pact@${pkg.version}`,
   streams: [
     {
@@ -33,3 +35,51 @@ export default new Logger({
     },
   ],
 })
+
+export const traceHttpInteractions = () => {
+  const originalRequest = http.request
+
+  http.request = (options: RequestOptions, cb: any): ClientRequest => {
+    const requestBodyChunks: Buffer[] = []
+    const responseBodyChunks: Buffer[] = []
+
+    const hijackedCalback = (res: any) => {
+      logger.trace("outgoing request", {
+        ...options,
+        body: Buffer.concat(requestBodyChunks).toString("utf8"),
+      })
+
+      if (cb) {
+        return cb(res)
+      }
+    }
+
+    const clientRequest: ClientRequest = originalRequest(
+      options,
+      hijackedCalback
+    )
+    const oldWrite = clientRequest.write.bind(clientRequest)
+
+    clientRequest.write = (chunk: any) => {
+      requestBodyChunks.push(Buffer.from(chunk))
+      return oldWrite(chunk)
+    }
+
+    clientRequest.on("response", (incoming: IncomingMessage) => {
+      incoming.on("readable", () => {
+        responseBodyChunks.push(Buffer.from(incoming.read()))
+      })
+      incoming.on("end", () => {
+        logger.trace({
+          body: Buffer.concat(responseBodyChunks).toString("utf8"),
+          headers: incoming.headers,
+          statusCode: incoming.statusCode,
+        })
+      })
+    })
+
+    return clientRequest
+  }
+}
+
+export default logger

src/dsl/verifier.ts

@@ -6,7 +6,7 @@ import pact from "@pact-foundation/pact-node"
 import { qToPromise } from "../common/utils"
 import { VerifierOptions as PactNodeVerifierOptions } from "@pact-foundation/pact-node"
 import serviceFactory from "@pact-foundation/pact-node"
-import { omit, isEmpty } from "lodash"
+import { omit, isEmpty, pickBy, identity, reduce } from "lodash"
 import * as express from "express"
 import * as http from "http"
 import logger from "../common/logger"
@@ -127,6 +127,13 @@ export class Verifier {
     app.use(this.stateSetupPath, bodyParser.json())
     app.use(this.stateSetupPath, bodyParser.urlencoded({ extended: true }))
 
+    // Trace req/res logging
+    if (this.config.logLevel === "trace") {
+      logger.info("trace logging enabled")
+      app.use(this.createRequestTracer())
+      app.use(this.createResponseTracer())
+    }
+
     // Allow for request filtering
     if (this.config.requestFilter !== undefined) {
       app.use(this.config.requestFilter)
@@ -158,6 +165,40 @@ export class Verifier {
     }
   }
 
+  private createRequestTracer(): express.RequestHandler {
+    return (req, _, next) => {
+      logger.trace("incoming request", removeEmptyRequestProperties(req))
+      next()
+    }
+  }
+
+  private createResponseTracer(): express.RequestHandler {
+    return (_, res, next) => {
+      const [oldWrite, oldEnd] = [res.write, res.end]
+      const chunks: Buffer[] = []
+
+      res.write = (chunk: any) => {
+        chunks.push(Buffer.from(chunk))
+        return oldWrite.apply(res, [chunk])
+      }
+
+      res.end = (chunk: any) => {
+        if (chunk) {
+          chunks.push(Buffer.from(chunk))
+        }
+        const body = Buffer.concat(chunks).toString("utf8")
+        logger.trace(
+          "outgoing response",
+          removeEmptyResponseProperties(body, res)
+        )
+        oldEnd.apply(res, [chunk])
+      }
+      if (typeof next === "function") {
+        next()
+      }
+    }
+  }
+
   // Lookup the handler based on the description, or get the default handler
   private setupStates(descriptor: ProviderState): Promise<any> {
     const promises: Array<Promise<any>> = new Array()
@@ -218,3 +259,31 @@ export class Verifier {
     )
   }
 }
+
+const removeEmptyRequestProperties = (req: express.Request) =>
+  pickBy(
+    {
+      body: req.body,
+      headers: req.headers,
+      method: req.method,
+      path: req.path,
+    },
+    identity
+  )
+
+const removeEmptyResponseProperties = (body: any, res: express.Response) =>
+  pickBy(
+    {
+      body,
+      headers: reduce(
+        res.getHeaders(),
+        (acc: any, val, index) => {
+          acc[index] = val
+          return acc
+        },
+        {}
+      ),
+      status: res.statusCode,
+    },
+    identity
+  )

src/httpPact.ts

@@ -5,7 +5,7 @@ import * as process from "process"
 import { Interaction, InteractionObject } from "./dsl/interaction"
 import { isEmpty } from "lodash"
 import { isPortAvailable } from "./common/net"
-import logger from "./common/logger"
+import logger, { traceHttpInteractions } from "./common/logger"
 import { LogLevels } from "@pact-foundation/pact-node/src/logger"
 import { MockService } from "./dsl/mockService"
 import { PactOptions, PactOptionsComplete } from "./dsl/options"
@@ -59,6 +59,10 @@ export class Pact {
     logger.level(this.opts.logLevel as LogLevels)
     serviceFactory.logLevel(this.opts.logLevel)
 
+    if (this.opts.logLevel === "trace") {
+      traceHttpInteractions()
+    }
+
     this.createServer(config)
   }