npmlog with timestamp doc, return code bugfix and test

README.md

@@ -158,6 +158,31 @@ mode con lines=32766
 ```
 > http://stackoverflow.com/a/8775884/1123955
 
+### NpmLog with Timestamp ###
+Here's a quick and dirty patch, to npmlog/log.js
+
+```javascript
+  m.message.split(/\r?\n/).forEach(function (line) {
+
+    var date = new Date();
+    var min = date.getMinutes()
+    var sec = date.getSeconds()
+    var hour = date.getHours()
+
+    if (sec < 10) { sec = '0' + sec }
+    if (min < 10) { min = '0' + min }
+    if (hour < 10) { hour = '0' + hour }
+
+    this.write(hour + ':' + min + ':' + sec + ' ')
+
+    if (this.heading) {
+      this.write(this.heading, this.headingStyle)
+      this.write(' ')
+    }
+```
+
+And we can looking forward the official support from npmlog: https://github.com/npm/npmlog/pull/24
+
 # Requirement
 
 ECMAScript2015(ES6). I develop and test wechaty with Node.js v6.0.

src/puppet-web-bridge.js

@@ -64,7 +64,7 @@ class Bridge {
 
       const injectio = this.getInjectio()
       let retObj = yield this.execute(injectio, this.port)
-      if (retObj && /^2|3/.test(retObj.code)) {   // HTTP Code 2XX & 3XX
+      if (retObj && /^(2|3)/.test(retObj.code)) {   // HTTP Code 2XX & 3XX
         log.verbose('PuppetWebBridge', 'inject() eval(Wechaty) return code[%d] message[%s] port[%d]'
           , retObj.code, retObj.message, retObj.port)
       } else {                                    // HTTP Code 4XX & 5XX
@@ -72,15 +72,18 @@ class Bridge {
       }
 
       retObj = yield this.proxyWechaty('init')
-      if (retObj && /^2|3/.test(retObj.code)) {   // HTTP Code 2XX & 3XX
+      if (retObj && /^(2|3)/.test(retObj.code)) {   // HTTP Code 2XX & 3XX
         log.verbose('PuppetWebBridge', 'inject() Wechaty.init() return code[%d] message[%s] port[%d]'
           , retObj.code, retObj.message, retObj.port)
       } else {                                    // HTTP Code 4XX & 5XX
         throw new Error('execute proxyWechaty(init) error: ' + retObj.code + ', ' + retObj.message)
       }
 
-      // const r = yield this.proxyWechaty('initClog')
-      // log.warn('PuppetWebBridge', 'initClog(): %s', r)
+      const r = yield this.ding('inject()')
+      if (r!=='inject()') {
+        throw new Error('fail to get right return from call ding()')
+      }
+      log.verbose('PuppetWebBridge', 'inject() ding success')
 
       return true
 

src/puppet-web-browser.js

@@ -146,6 +146,7 @@ class Browser extends EventEmitter {
         , 'NoSuchWindowError: no such window: target window already closed'
       ]
       const crashRegex = new RegExp(crashMsgs.join('|'), 'i')
+
       if (crashRegex.test(e.message)) { log.warn('PuppetWebBrowser', 'driver.quit() browser crashed') }
       else                            { log.warn('PuppetWebBrowser', 'driver.quit() exception: %s', e.message) }
     })
@@ -316,6 +317,7 @@ class Browser extends EventEmitter {
       this.live = false
       // must use nextTick here, or promise will hang... 2016/6/10
       process.nextTick(() => {
+        log.verbose('PuppetWebBrowser', 'dead() emit a `dead` event')
         this.emit('dead', errMsg)
       })
     }

src/puppet-web-event.js

@@ -51,6 +51,7 @@ const PuppetWebEvent = {
 }
 
 function onBrowserDead(e) {
+  log.verbose('PuppetWebEvent', 'onBrowserDead()')
   // because this function is async, so maybe entry more than one times.
   // guard by variable: onBrowserBirthing to prevent the 2nd time entrance.
   if (this.onBrowserBirthing) {

src/puppet-web.js

@@ -186,7 +186,7 @@ class PuppetWeb extends Puppet {
   watchDog(data, options) {
     log.silly('PuppetWeb', 'watchDog(%s)', data)
     options = options || {}
-    const timeout = options.timeout || 60000 // 60s default. can be override in options
+    const timeout = options.timeout || 60000 // 60s default. can be override in options but be careful about the number zero(0)
     const type   =  options.type    || 'food'  // just a name
 
     if (this.watchDogTimer) { clearTimeout(this.watchDogTimer) }
@@ -229,6 +229,7 @@ class PuppetWeb extends Puppet {
   }
 
   watchDogReset(timeout) {
+    log.warn('PuppetWeb', 'watchDogReset() timeout %d', timeout)
     const e = new Error('watchdog reset after ' + Math.floor(timeout/1000) + ' seconds')
     this.emit('error', e)
     return Event.onBrowserDead.call(this, e)

test/puppet-web-event-spec.js

+const co    = require('co')
+const util  = require('util')
+const test  = require('tap').test
+const retryPromise = require('retry-promise').default
+
+const log = require('../src/npmlog-env')
+
+const PORT = process.env.WECHATY_PORT || 58788
+const HEAD = process.env.WECHATY_HEAD || false
+const SESSION = 'unit-test-session.wechaty.json'
+
+const PuppetWeb = require('../src/puppet-web')
+const PuppetWebEvent = require('../src/puppet-web-event')
+
+test('Puppet Web Event smoking test', function(t) {
+  let pw = new PuppetWeb({port: PORT, head: HEAD, session: SESSION})
+  t.ok(pw, 'should instantiated a PuppetWeb')
+
+  co(function* () {
+    yield pw.init()
+    t.pass('should be inited')
+
+    yield PuppetWebEvent.onBrowserDead.call(pw, 'test')
+  })
+  .catch(e => t.fail(e))  // Reject
+  .then(r => {            // Finally 1
+    pw.quit().then(t.end)
+  })
+  .catch(e => t.fail(e))  // Exception
+})

test/puppet-web-spec.js

@@ -125,13 +125,16 @@ test('Puppet Web watchdog timer', function(t) {
     t.pass('should kill both browser & bridge')
 
     pw.once('error', e => {
-      t.ok(/watchdog timeout/i.test(e), 'should emit error after watchdog timeout')
+      t.ok(/watchdog reset/i.test(e.message), 'should get event[error] after watchdog timeout')
     })
+    pw.watchDog('feed_and_active_it', {timeout: 1})
+    yield new Promise((resolve) => setTimeout(() => resolve(), 2)) // wait untill reset
+    t.pass('should feed the watchdog and had already fireed a reset above')
 
-    pw.watchDog('feed_and_active_it', {timeout: 10})
-    t.pass('should feed the watchdog and set timeout')
+    pw.once('error', e => t.fail('waitDing() triggered watchDogReset()'))
 
     const EXPECTED_DING_DATA = 'dingdong'
+    pw.watchDog('feed to extend the dog life')
     const dong = yield waitDing(EXPECTED_DING_DATA)
     t.equal(dong, EXPECTED_DING_DATA, 'should get EXPECTED_DING_DATA from ding after watchdog reset')
   })
@@ -146,12 +149,13 @@ test('Puppet Web watchdog timer', function(t) {
   return
   /////////////////////////////////////////////////////////////////////////////
   function waitDing(data) {
-    const max = 30
-    const backoff = 100
+    const max = 7
+    const backoff = 2000
 
     // max = (2*totalTime/backoff) ^ (1/2)
-    // timeout = 11250 for {max: 15, backoff: 100}
-    // timeout = 45000 for {max: 30, backoff: 100}
+    // timeout = 11,250 for {max: 15, backoff: 100}
+    // timeout = 45,000 for {max: 30, backoff: 100}
+    // timeout = 49,000 for {max: 7, backoff: 2000}
     const timeout = max * (backoff * max) / 2
 
     return retryPromise({ max: max, backoff: backoff }, function (attempt) {