fix race condition when browser init too fast (#899)

src/puppet-web/bridge.ts

@@ -72,11 +72,9 @@ export class Bridge extends EventEmitter {
       this.browser = await this.initBrowser()
       log.verbose('PuppetWebBridge', 'init() initBrowser() done')
 
-      this.page    = await this.initPage(this.browser)
+      this.page = await this.initPage(this.browser)
       log.verbose('PuppetWebBridge', 'init() initPage() done')
 
-      await this.readyAngular(this.page)
-      await this.inject(this.page)
     } catch (e) {
       log.error('PuppetWebBridge', 'init() exception: %s', e)
       throw e
@@ -106,21 +104,9 @@ export class Bridge extends EventEmitter {
     log.verbose('PuppetWebBridge', 'initPage()')
 
     const page = await browser.newPage()
-
-    const cookieList = this.options.profile.get('cookies') as Cookie[]
-    const url        = this.entryUrl(cookieList)
-
-    log.verbose('PuppetWebBridge', 'initPage() before page.goto(url)')
-    await page.goto(url) // Does this related to(?) the CI Error: exception: Navigation Timeout Exceeded: 30000ms exceeded
-    log.verbose('PuppetWebBridge', 'initPage() after page.goto(url)')
-
-    if (cookieList && cookieList.length) {
-      await page.setCookie(...cookieList)
-      log.silly('PuppetWebBridge', 'initPage() page.setCookie() %s cookies set back', cookieList.length)
-      await page.reload() // reload page to make effect of the new cookie.
-    }
-
-    await page.exposeFunction('emit', this.emit.bind(this))
+    // set this in time because the following callbacks
+    // might be called before initPage() return.
+    this.page = page
 
     const onDialog = async (dialog: Dialog) => {
       log.warn('PuppetWebBridge', 'init() page.on(dialog) type:%s message:%s',
@@ -135,7 +121,51 @@ export class Bridge extends EventEmitter {
 
       this.emit('error', new Error(`${dialog.type}(${dialog.message()})`))
     }
+
+    const onLoad = async () => {
+      log.verbose('PuppetWebBridge', 'initPage() on(load) %s', page.url())
+      try {
+        await page.exposeFunction('emit', this.emit.bind(this))
+      } catch (e) {
+        // exposed function will stay in the browser after reload the page
+        log.verbose('PuppetWebBridge', 'initPage() onLoad() page.exposeFunction(emit) exception: %s', e)
+      }
+
+      try {
+        await this.readyAngular(page)
+        await this.inject(page)
+
+        const clicked = await this.clickSwitchAccount()
+        if (clicked) {
+          log.verbose('PuppetWebBridge', 'initPage() onLoad() clickSwitchAccount() clicked')
+        } else {
+          log.silly('PuppetWebBridge', 'initPage() onLoad() clickSwitchAccount() NOP')
+        }
+
+      } catch (e) {
+        log.error('PuppetWebBridge', 'init() initPage() onLoad() exception: %s', e)
+        this.emit('error', e)
+      }
+    }
+
     page.on('dialog', onDialog)
+    page.on('load', onLoad)
+    page.on('error', e => this.emit('error', e))
+
+    ///////////////////
+
+    const cookieList = this.options.profile.get('cookies') as Cookie[]
+    const url        = this.entryUrl(cookieList)
+
+    log.verbose('PuppetWebBridge', 'initPage() before page.goto(url)')
+    await page.goto(url) // Does this related to(?) the CI Error: exception: Navigation Timeout Exceeded: 30000ms exceeded
+    log.verbose('PuppetWebBridge', 'initPage() after page.goto(url)')
+
+    if (cookieList && cookieList.length) {
+      await page.setCookie(...cookieList)
+      log.silly('PuppetWebBridge', 'initPage() page.setCookie() %s cookies set back', cookieList.length)
+      await page.reload() // reload page to make effect of the new cookie.
+    }
 
     return page
   }
@@ -148,7 +178,7 @@ export class Bridge extends EventEmitter {
       await page.waitForFunction(`typeof window.angular !== 'undefined'`)
 
       clearTimeout(timer)
-      log.verbose('PuppetWebBridge', 'readyAngular() Promise.resolve()')
+      log.silly('PuppetWebBridge', 'readyAngular() resolve-ed')
       resolve()
     })
   }
@@ -184,7 +214,7 @@ export class Bridge extends EventEmitter {
         throw new Error('execute proxyWechaty(init) error: ' + retObj.code + ', ' + retObj.message)
       }
 
-      const SUCCESS_CIPHER = 'inject() OK!'
+      const SUCCESS_CIPHER = 'ding() OK!'
       const r = await this.ding(SUCCESS_CIPHER)
       if (r !== SUCCESS_CIPHER) {
         throw new Error('fail to get right return from call ding()')
@@ -215,7 +245,7 @@ export class Bridge extends EventEmitter {
       await this.browser.close()
       log.silly('PuppetWebBridge', 'quit() browser.close()-ed')
     } catch (e) {
-      log.warn('PuppetWebBridge', 'quit() exception: %s', e && e.message || e)
+      log.warn('PuppetWebBridge', 'quit() exception: %s', e)
       this.emit('error', e)
     }
   }

src/puppet-web/event.ts

@@ -59,7 +59,7 @@ function onDing(this: PuppetWeb, data): void {
 }
 
 async function onScan(this: PuppetWeb, data: ScanInfo): Promise<void> {
-  log.verbose('PuppetWebEvent', 'onScan(%d)', data && data.code)
+  log.verbose('PuppetWebEvent', 'onScan({code: %d, url: %s})', data.code, data.url)
 
   if (this.state.off()) {
     log.verbose('PuppetWebEvent', 'onScan(%s) state.off()=%s, NOOP',

src/puppet-web/puppet-web.ts

@@ -95,11 +95,6 @@ export class PuppetWeb extends Puppet {
       this.bridge = await this.initBridge(this.options.profile)
       log.verbose('PuppetWeb', 'initBridge() done')
 
-      const clicked = await this.bridge.clickSwitchAccount()
-      if (clicked) {
-        log.verbose('PuppetWeb', 'init() bridge.clickSwitchAccount() clicked')
-      }
-
       /**
        *  state must set to `live`
        *  before feed Watchdog

src/puppet-web/wechaty-bro.js

@@ -47,7 +47,7 @@
       return retObj
     }
 
-    if (WechatyBro.vars.initStatus === true) {
+    if (WechatyBro.vars.initState === true) {
       log('WechatyBro.init() called twice: already inited')
       retObj.code = 304 // 304 Not Modified https://www.w3.org/Protocols/rfc2616/rfc2616-sec10.html#sec10.3.5
       retObj.message = 'init() already inited before. returned with do nothing'
@@ -68,21 +68,25 @@
     heartBeat(true)
 
     log('inited!. ;-D')
-    WechatyBro.vars.initStatus = true
+    WechatyBro.vars.initState = true
 
     retObj.code = 200
     retObj.message = 'WechatyBro Init Succ'
     return retObj
   }
 
-  function log(text) { WechatyBro.emit('log', text) }
+  function log(text) {
+    WechatyBro.emit('log', text)
+  }
 
   /**
   *
   * Functions that Glued with AngularJS
   *
   */
-  function MMCgiLogined() { return !!(window.MMCgi && window.MMCgi.isLogin) }
+  function MMCgiLogined() {
+    return !!(window.MMCgi && window.MMCgi.isLogin)
+  }
 
   function angularIsReady() {
     // don't log inside, because we has not yet init clog here.
@@ -187,7 +191,7 @@
 
   function checkScan() {
     // log('checkScan()')
-    if (isLogin()) {
+    if (loginState()) {
       log('checkScan() - already login, no more check, and return(only)') //but I will emit a login event')
       // login('checkScan found already login')
       return
@@ -205,7 +209,7 @@
     // 200: 登录成功
     var code  = +WechatyBro.glue.loginScope.code
     var url   =  WechatyBro.glue.loginScope.qrcodeUrl
-    // log('checkScan() code:' + code + ' url:' + url + ' scanCode:' + WechatyBro.vars.scanCode)
+    log('checkScan() code:' + code + ' url:' + url + ' scanCode:' + WechatyBro.vars.scanCode)
 
     if (url && code !== WechatyBro.vars.scanCode) {
       log('checkScan() - code change detected: from '
@@ -220,38 +224,42 @@
       WechatyBro.vars.scanCode = code
     }
 
-    if (code === 200) {
-      login('scan code 200')
-    } else {
-      setTimeout(checkScan, 1000)
+    if (code !== 200) {
+      return setTimeout(checkScan, 1000)
     }
-    return
+
+    WechatyBro.vars.scanCode = null
+    WechatyBro.glue.loginScope.code = null
+
+    return login('scan code 200')
   }
 
-  function isLogin() {
-    return !!WechatyBro.vars.loginStatus
+  function loginState(state) {
+    if (typeof state === 'undefined') {
+      return !!WechatyBro.vars.loginState
+    }
+    WechatyBro.vars.loginState = state
+    return
   }
 
   function login(data) {
     log('login(' + data + ')')
-    if (!WechatyBro.vars.loginStatus) {
-      WechatyBro.vars.loginStatus = true
-    }
-    WechatyBro.vars.scanCode = null
+    loginState(true)
     WechatyBro.emit('login', data)
   }
 
   function logout(data) {
     log('logout(' + data + ')')
-    WechatyBro.vars.loginStatus = false
+
+    loginState(false)
+
     // WechatyBro.emit('logout', data)
     if (WechatyBro.glue.loginFactory) {
       WechatyBro.glue.loginFactory.loginout()
+    } else {
+      log('logout() WechatyBro.glue.loginFactory NOT found')
     }
 
-    WechatyBro.vars.scanCode        = null
-    WechatyBro.glue.loginScope.code = null
-
     checkScan()
   }
 
@@ -268,7 +276,7 @@
       return false
     }
     rootScope.$on('message:add:success', function(event, data) {
-      if (!isLogin()) { // in case of we missed the pageInit event
+      if (!loginState()) { // in case of we missed the pageInit event
         login('by event[message:add:success]')
       }
       WechatyBro.emit('message', data)
@@ -789,8 +797,8 @@
 
     // variable
     , vars: {
-      loginStatus : false,
-      initStatus  : false,
+      loginState : false,
+      initState  : false,
 
       scanCode        : null,
       heartBeatTimmer : null,
@@ -834,7 +842,11 @@
     , verifyUserOk:      verifyUserOk
 
     // test purpose
-    , isLogin: isLogin
+    , isLogin: () => {
+      log('DEPRECATED. use loginState() instead');
+      return loginState()
+    }
+    , loginState: loginState
   }
 
   this.WechatyBro = WechatyBro