Repository: ViacomInc/data-point (js)

Issue:
debug/trace integration into data-point
<!--
Thanks for your interest in the project. We appreciate bugs filed and PRs submitted!
Please make sure that you are familiar with and follow the Code of Conduct for
this project (found in the CODE_OF_CONDUCT.md file).

Please fill/un-comment out this template with all the relevant information so we can
understand what's going on and fix the issue.
-->

**Problem description**:

There is no direct way to know if an entity was executed, when it was bypassed and when it got resolved. 

**Suggested solution**:

Using the debug module, we can add calls to scoped debug statements to be able to trace each entity. Each scope should have the type of entity so we can filter the logs by types.

<!--If you have a link or example that reproduces your issue please include it. A reproduction with as little code as possible is better.-->

**Environment**:

- `data-point` version: All
- `node` version: N/A
- `npm` version: N/A


Pull request description:
feat(data-point): implement debug module
<!--
Thanks for your interest in the project. We appreciate bugs filed and PRs submitted!

Please make sure that you are familiar with and follow the Code of Conduct for
this project (found in the CODE_OF_CONDUCT.md file).

Also, please make sure you're familiar with and follow the instructions in the
contributing guidelines (found in the CONTRIBUTING.md file).

Please fill out the information below to expedite the review and (hopefully)
merge of your pull request!

BREAKING CHANGES:

If your PR includes a breaking change, please submit it with a codemod under
data-point-codemods that will help users upgrade their codebase.

Breaking changes without a codemod will not be accepted unless a codemod is not
viable or does not apply to the specific situation.
-->

<!-- What changes are being made? (What feature/bug is being fixed here?) -->
**What**:

traces base entity and exposes scoped debug at accumulator object

<!-- Why are these changes necessary? -->
**Why**:

closes #285

<!-- Have you done all of these things?  -->
**Checklist**:
<!-- add "N/A" to the end of each line that's irrelevant to your changes -->
<!-- to check an item, place an "x" in the box like so: "- [x] Documentation" -->
- [ ] Has Breaking changes
- [ ] Documentation
- [ ] Tests
- [X] Ready to be merged <!-- In your opinion, is this ready to be merged as soon as it's reviewed? -->
- [ ] Added username to **all-contributors** list

<!-- feel free to add additional comments -->


Patch:
diff --git a/packages/data-point/README.md b/packages/data-point/README.md
index 4e11f3c..a583c2d 100644
--- a/packages/data-point/README.md
+++ b/packages/data-point/README.md
@@ -433,6 +433,7 @@ The `accumulator.value` property is the current input data. This property should
 | *params*  | `Object` | Value of the current Entity's params property. (for all entities except [Reducer](#reducer-entity)) |
 | *locals*  | `Object` | Value passed from the `options` _argument_ when executing [dataPoint.transform](#api-data-point-transform). |
 | *reducer*  | `Object` | Information relative to the current [Reducer](#reducers) being executed. |
+| *debug*  | `Function` | [debug](https://github.com/visionmedia/debug) method with scope `data-point` |
 
 ## <a name="reducers">Reducers</a>
 
diff --git a/packages/data-point/lib/accumulator/factory.js b/packages/data-point/lib/accumulator/factory.js
index b753efd..497b043 100644
--- a/packages/data-point/lib/accumulator/factory.js
+++ b/packages/data-point/lib/accumulator/factory.js
@@ -1,4 +1,5 @@
 const merge = require('lodash/merge')
+const debug = require('debug')('data-point')
 
 /**
  * @class
@@ -31,8 +32,9 @@ function create (spec) {
   accumulator.locals = merge({}, spec.locals)
   accumulator.values = spec.values
   accumulator.trace = spec.trace
+  accumulator.debug = debug
 
-  return Object.freeze(accumulator)
+  return accumulator
 }
 
 module.exports.create = create
diff --git a/packages/data-point/lib/entity-types/base-entity/resolve.js b/packages/data-point/lib/entity-types/base-entity/resolve.js
index e92a078..73cd5fb 100644
--- a/packages/data-point/lib/entity-types/base-entity/resolve.js
+++ b/packages/data-point/lib/entity-types/base-entity/resolve.js
@@ -1,8 +1,20 @@
+const debug = require('debug')
 const Promise = require('bluebird')
-
 const middleware = require('../../middleware')
-
 const utils = require('../../utils')
+const memoize = require('lodash/memoize')
+
+/**
+ * create a new debug scope
+ * @param {String} entityType debug scope
+ */
+function createDebugEntity (entityType) {
+  return debug(`data-point:entity:${entityType}`)
+}
+
+// debug scope gets memoized so it is not as expensive, it will only create one
+// per entity type
+const debugEntity = memoize(createDebugEntity)
 
 /**
  * @param {Object} manager
@@ -114,6 +126,7 @@ function resolveMiddleware (manager, promise, name) {
     })
     .then(middlewareResult => {
       if (middlewareResult.___resolve === true) {
+        middlewareResult.debug(middlewareResult.uid, '- will bypass')
         // doing this until proven wrong :)
         const err = new Error('bypassing middleware')
         err.name = 'bypass'
@@ -172,19 +185,23 @@ function resolveEntity (
   } = currentAccumulator.reducer.spec
 
   const entityId = id
+  const uid = `${entityId}:${utils.getUID()}`
+  const accUid = utils.set(currentAccumulator, 'uid', uid)
+
+  accUid.debug = debugEntity(reducer.entityType)
 
   const trace =
     currentAccumulator.trace === true ||
     currentAccumulator.reducer.spec.params.trace === true
 
   let timeId
-  let accUid = currentAccumulator
   if (trace === true) {
-    accUid = utils.set(currentAccumulator, 'euid', utils.getUID())
-    timeId = `⧖ ${entityId}(${accUid.euid})`
+    timeId = `⧖ ${uid}`
     console.time(timeId)
   }
 
+  accUid.debug(uid, '- resolve:start')
+
   let result = Promise.resolve(accUid)
 
   result = addToPromiseChain(result, inputType, acc =>
@@ -200,6 +217,7 @@ function resolveEntity (
   )
 
   result = result.then(acc => {
+    acc.debug(acc.uid, '- resolve')
     return mainResolver(acc, resolveReducer.bind(null, manager))
   })
 
@@ -240,6 +258,8 @@ function resolveEntity (
         console.timeEnd(timeId)
       }
 
+      resultContext.debug(resultContext.uid, `- resolve:end`)
+
       // clean up any modifications we have done to the result context and pass
       // a copy of the original accumulator with only `value` modified
       return utils.set(accumulator, 'value', resultContext.value)
diff --git a/packages/data-point/package.json b/packages/data-point/package.json
index d4cfd86..9021cd4 100644
--- a/packages/data-point/package.json
+++ b/packages/data-point/package.json
@@ -58,6 +58,7 @@
   "dependencies": {
     "ajv": "5.2.3",
     "bluebird": "3.5.0",
+    "debug": "3.x",
     "deep-freeze": "0.0.1",
     "lodash": "4.17.4",
     "request": "2.82.0",


Test patch:
diff --git a/packages/data-point/lib/entity-types/base-entity/__snapshots__/resolve.test.js.snap b/packages/data-point/lib/entity-types/base-entity/__snapshots__/resolve.test.js.snap
index c2812c8..5922cbf 100644
--- a/packages/data-point/lib/entity-types/base-entity/__snapshots__/resolve.test.js.snap
+++ b/packages/data-point/lib/entity-types/base-entity/__snapshots__/resolve.test.js.snap
@@ -3,7 +3,7 @@
 exports[`ResolveEntity.resolveEntity It should log trace calls when set to true 1`] = `
 Array [
   Array [
-    "⧖ model:asIs(1)",
+    "⧖ model:asIs:3",
   ],
 ]
 `;
@@ -11,7 +11,7 @@ Array [
 exports[`ResolveEntity.resolveEntity It should log trace calls when set to true 2`] = `
 Array [
   Array [
-    "⧖ model:asIs(1)",
+    "⧖ model:asIs:3",
   ],
 ]
 `;
diff --git a/packages/data-point/lib/entity-types/integrations.test.js b/packages/data-point/lib/entity-types/integrations.test.js
index 0c76e34..7c38059 100644
--- a/packages/data-point/lib/entity-types/integrations.test.js
+++ b/packages/data-point/lib/entity-types/integrations.test.js
@@ -237,7 +237,7 @@ describe('trace feature', () => {
         console.time = consoleTime
         console.timeEnd = consoleTimeEnd
         const ids = _.map(timeIds, 'id')
-        expect(ids[0]).toContain('⧖ model:tracedViaOptions(')
+        expect(ids[0]).toContain('⧖ model:tracedViaOptions:')
       })
   })
   test('trace via entity params', () => {
@@ -263,7 +263,7 @@ describe('trace feature', () => {
         console.time = consoleTime
         console.timeEnd = consoleTimeEnd
         const ids = _.map(timeIds, 'id')
-        expect(ids[0]).toContain('⧖ model:tracedViaParams(')
+        expect(ids[0]).toContain('⧖ model:tracedViaParams:')
       })
   })
 })