feature/pretty print (#81)

* backbone pretty print

* add: toJSON and fix tree generation

* add: tests

* fix: tree order loading

* add: tcs declaration

*  fix: manage of function with same names

* remove: after show in pretty print

* add: test more strict

* add: map to track nodeIds

* add: map to track parents

* fix: prettyPrint return string and typo

* fix: time is too relative

README.md

@@ -82,6 +82,8 @@ async function third (instance, opts) {
   * <a href="#onClose"><code>instance.<b>onClose()</b></code></a>
   * <a href="#close"><code>instance.<b>close()</b></code></a>
   * <a href="#express"><code>avvio.<b>express()</b></code></a>
+  * <a href="#toJSON"><code>avvio.<b>toJSON()</b></code></a>
+  * <a href="#prettyPrint"><code>avvio.<b>prettyPrint()</b></code></a>
 
 -------------------------------------------------------
 <a name="constructor"></a>
@@ -508,6 +510,83 @@ app.close()
 
 -------------------------------------------------------
 
+<a name="toJSON"></a>
+
+### avvio.toJSON()
+
+Return a JSON tree rappresenting the state of the plugins and the loading time.
+Call it on `preReady` to get the complete tree.
+
+```js
+const avvio = require('avvio')()
+avvio.on('preReady', () => {
+  avvio.toJSON()
+})
+```
+
+The ouput is like this:
+```json
+{
+  "label": "bound root",
+  "start": 1550245184665,
+  "nodes": [
+    {
+      "parent": "bound root",
+      "start": 1550245184665,
+      "label": "first",
+      "nodes": [
+        {
+          "parent": "first",
+          "start": 1550245184708,
+          "label": "second",
+          "nodes": [],
+          "stop": 1550245184709,
+          "diff": 1
+        }
+      ],
+      "stop": 1550245184709,
+      "diff": 44
+    },
+    {
+      "parent": "bound root",
+      "start": 1550245184709,
+      "label": "third",
+      "nodes": [],
+      "stop": 1550245184709,
+      "diff": 0
+    }
+  ],
+  "stop": 1550245184709,
+  "diff": 44
+}
+```
+
+-------------------------------------------------------
+
+<a name="prettyPrint"></a>
+
+### avvio.prettyPrint()
+
+This method will return a printable string with the tree returned by the `toJSON()` method.
+
+```js
+const avvio = require('avvio')()
+avvio.on('preReady', () => {
+  console.log(avvio.prettyPrint())
+})
+```
+
+The output will be like:
+
+```
+avvio 56 ms
+├── first 52 ms
+├── second 1 ms
+└── third 2 ms
+```
+
+-------------------------------------------------------
+
 ## Acknowledgements
 
 This project was kindly sponsored by [nearForm](http://nearform.com).

boot.js

@@ -3,6 +3,7 @@
 const fastq = require('fastq')
 const EE = require('events').EventEmitter
 const inherits = require('util').inherits
+const TimeTree = require('./time-tree')
 const Plugin = require('./plugin')
 const debug = require('debug')('avvio')
 
@@ -113,6 +114,7 @@ function Boot (server, opts, done) {
 
   this.started = false
   this.booted = false
+  this.pluginTree = new TimeTree()
 
   this._readyQ = fastq(this, callWithCbOrNextTick, 1)
   this._readyQ.pause()
@@ -133,6 +135,13 @@ function Boot (server, opts, done) {
   this._doStart = null
   const main = new Plugin(this, root.bind(this), opts, noop, 0)
 
+  main.once('start', (serverName, funcName, time) => {
+    const nodeId = this.pluginTree.start(null, funcName, time)
+    main.once('loaded', (serverName, funcName, time) => {
+      this.pluginTree.stop(nodeId, time)
+    })
+  })
+
   Plugin.loadPlugin.call(this, main, (err) => {
     debug('root plugin ready')
     this.emit('preReady')
@@ -195,6 +204,14 @@ Boot.prototype._addPlugin = function (plugin, opts, isAfter) {
   const current = this._current[0]
 
   const obj = new Plugin(this, plugin, opts, isAfter)
+  if (!isAfter) {
+    obj.once('start', (serverName, funcName, time) => {
+      const nodeId = this.pluginTree.start(current.name, funcName, time)
+      obj.once('loaded', (serverName, funcName, time) => {
+        this.pluginTree.stop(nodeId, time)
+      })
+    })
+  }
 
   if (current.loaded) {
     throw new Error(`Impossible to load "${obj.name}" plugin because the parent "${current.name}" was already loaded`)
@@ -288,6 +305,14 @@ Boot.prototype.ready = function (func) {
   })
 }
 
+Boot.prototype.prettyPrint = function () {
+  return this.pluginTree.prittyPrint()
+}
+
+Boot.prototype.toJSON = function () {
+  return this.pluginTree.toJSON()
+}
+
 function noop () { }
 
 function callWithCbOrNextTick (func, cb, context) {

example.js

@@ -4,6 +4,7 @@ const avvio = require('.')()
 
 avvio
   .use(first, { hello: 'world' })
+  .use(duplicate, { count: 0 })
   .after((err, cb) => {
     if (err) {
       console.log('something bad happened')
@@ -12,6 +13,7 @@ avvio
     console.log('after first and second')
     cb()
   })
+  .use(duplicate, { count: 4 })
   .use(third, (err) => {
     if (err) {
       console.log('something bad happened')
@@ -27,10 +29,14 @@ avvio
     console.log('application booted!')
   })
 
+avvio.on('preReady', () => {
+  console.log(avvio.prettyPrint())
+})
+
 function first (instance, opts, cb) {
   console.log('first loaded', opts)
   instance.use(second)
-  cb()
+  setTimeout(cb, 42)
 }
 
 function second (instance, opts, cb) {
@@ -42,3 +48,11 @@ function third (instance, opts, cb) {
   console.log('third loaded')
   cb()
 }
+
+function duplicate (instance, opts, cb) {
+  console.log('duplicate loaded', opts.count)
+  if (opts.count > 0) {
+    instance.use(duplicate, { count: opts.count - 1 })
+  }
+  setTimeout(cb, 20)
+}

index.d.ts

@@ -43,6 +43,10 @@ declare namespace avvio {
 
     start(): this;
 
+    toJSON(): Object;
+
+    prettyPrint(): string;
+
     override: (
       server: context<I>,
       fn: Plugin<any, I>,

package.json

@@ -40,6 +40,7 @@
     "typescript": "^3.1.1"
   },
   "dependencies": {
+    "archy": "^1.0.0",
     "debug": "^4.0.0",
     "fastq": "^1.6.0"
   }

plugin.js

@@ -1,6 +1,8 @@
 'use strict'
 
 const fastq = require('fastq')
+const EE = require('events').EventEmitter
+const inherits = require('util').inherits
 const debug = require('debug')('avvio')
 const CODE_PLUGIN_TIMEOUT = 'ERR_AVVIO_PLUGIN_TIMEOUT'
 
@@ -45,6 +47,8 @@ function Plugin (parent, func, optsOrFunc, isAfter, timeout) {
   // or they will end up at the top of _current
 }
 
+inherits(Plugin, EE)
+
 Plugin.prototype.exec = function (server, cb) {
   const func = this.func
   var completed = false
@@ -81,6 +85,7 @@ Plugin.prototype.exec = function (server, cb) {
     }, this.timeout)
   }
 
+  this.emit('start', this.server ? this.server.name : null, this.name, Date.now())
   var promise = func(this.server, this.opts, done)
   if (promise && typeof promise.then === 'function') {
     debug('resolving promise', name)
@@ -113,6 +118,7 @@ Plugin.prototype.exec = function (server, cb) {
 
 Plugin.prototype.enqueue = function (obj, cb) {
   debug('enqueue', this.name, obj.name)
+  this.emit('enqueue', this.server ? this.server.name : null, this.name, Date.now())
   this.q.push(obj, cb)
 }
 
@@ -124,6 +130,7 @@ Plugin.prototype.finish = function (err, cb) {
     }
 
     debug('loaded', this.name)
+    this.emit('loaded', this.server ? this.server.name : null, this.name, Date.now())
     this.loaded = true
 
     cb(err)

test/pretty-print.test.js

@@ -0,0 +1,57 @@
+'use strict'
+
+const test = require('tap').test
+const boot = require('..')
+
+test('pretty print', t => {
+  t.plan(14)
+
+  const app = boot()
+  app
+    .use(first)
+    .use(duplicate, { count: 3 })
+    .use(second)
+    .use(duplicate, { count: 2 })
+    .use(third)
+    .use(duplicate, { count: 1 })
+
+  const linesExpected = [ /bound root \d+ ms/,
+    /├── first \d+ ms/,
+    /├─┬ duplicate \d+ ms/,
+    /│ └─┬ duplicate \d+ ms/,
+    /│ {3}└─┬ duplicate \d+ ms/,
+    /│ {5}└── duplicate \d+ ms/,
+    /├── second \d+ ms/,
+    /├─┬ duplicate \d+ ms/,
+    /│ └─┬ duplicate \d+ ms/,
+    /│ {3}└── duplicate \d+ ms/,
+    /├── third \d+ ms/,
+    /└─┬ duplicate \d+ ms/,
+    / {2}└── duplicate \d+ ms/,
+    ''
+  ]
+
+  app.on('preReady', function show () {
+    const print = app.prettyPrint()
+    print.split('\n').forEach((l, i) => {
+      t.match(l, linesExpected[i])
+    })
+  })
+
+  function first (s, opts, done) {
+    done()
+  }
+  function second (s, opts, done) {
+    done()
+  }
+  function third (s, opts, done) {
+    done()
+  }
+
+  function duplicate (instance, opts, cb) {
+    if (opts.count > 0) {
+      instance.use(duplicate, { count: opts.count - 1 })
+    }
+    setTimeout(cb, 20)
+  }
+})