Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Selenium WebDriver driver.getSession() wait a long time #86

Closed
huan opened this issue Nov 12, 2016 · 11 comments
Closed

Selenium WebDriver driver.getSession() wait a long time #86

huan opened this issue Nov 12, 2016 · 11 comments
Labels

Comments

@huan
Copy link
Member

huan commented Nov 12, 2016

In our case, the timeout is 67 seconds:

Detail: https://travis-ci.org/wechaty/wechaty/jobs/175139957

I don't know why yet.

And it seems if we had an invalid WebDriver, then we will have a browser leak.

need to use process.kill to kill it, in clean().

A unit test fail log like this:

VERB PuppetWebBrowser constructor() with head(chrome) sessionFile()
VERB PuppetWebBrowserDriver constructor(chrome)
VERB PuppetWebBrowserCookie constructor(BrowserDriver, )
VERB PuppetWebBrowser init()
VERB StateMonitor Browser:target(open) <- (close)
VERB StateMonitor Browser:current(open,false) <- (close,true)
VERB PuppetWebBrowserDriver init() for head: chrome
VERB PuppetWebBrowserDriver getChromeDriver()
VERB PuppetWebBrowserDriver getChromeDriver() new Builder()
VERB PuppetWebBrowserDriver getChromeDriver() new Builder() done
VERB PuppetWebBrowserDriver valid()
WARN PuppetWebBrowserDriver valid() driver.getSession() timeout(halt?)
WARN PuppetWebBrowserDriver valid() driver.getSession() exception: valid() driver.getSession() timeout(halt?)
VERB PuppetWebBrowserDriver getChromeDriver() valid() done: false
VERB PuppetWebBrowserDriver getChromeDriver() new Builder()
WARN PuppetWebBrowserDriver getChromeDriver() got invalid driver
WARN PuppetWebBrowserDriver getChromeDriver() with retry: 1
VERB PuppetWebBrowserDriver getChromeDriver() new Builder() done
VERB PuppetWebBrowserDriver valid()
VERB PuppetWebBrowserDriver valid() driver.getSession() done
VERB PuppetWebBrowserDriver valid() driver.executeScript() done
VERB PuppetWebBrowserDriver getChromeDriver() valid() done: true
VERB PuppetWebBrowser init() driver.init() done
VERB PuppetWebBrowser open(https://wx.qq.com/zh_CN/htmledition/v2/images/webwxgeticon.jpg)
VERB PuppetWebBrowser open(https://wx.qq.com)
VERB StateMonitor Browser:current(open,true) <- (open,false)
VERB PuppetWebBrowser open(https://wx.qq.com)
VERB PuppetWebBrowser quit()
VERB StateMonitor Browser:current(close,false) <- (open,true)
ERR PuppetWebBrowser retryPromise failed: clean() found browser process, not clean, dirty
WARN PuppetWebBrowser quit() exception: clean() found browser process, not clean, dirty
WARN PuppetWebBrowser driver.quit() exception: clean() found browser process, not clean, dirty
VERB StateMonitor Browser:current(close,true) <- (close,false)
  ✖ test › webdriver › WebDriver process create & quit test no driver process after quit   
  t.is(pids.length, 0, 'no driver process after quit')
            |                                         
            5                                         
  
@JasLin
Copy link
Contributor

JasLin commented Nov 12, 2016

maybe cause by the latest version Selenium WebDriver ? it seems time out take place more frequently after upgrade from 3.0.0-beta-1 to 3.0.0

@huan
Copy link
Member Author

huan commented Nov 12, 2016

@JasLin if this is true, please have a look at #72 about the config variable: SELENIUM_PROMISE_MANAGER

Wechaty now set SELENIUM_PROMISE_MANAGER=0

You might want to set it to 1 to see if there'll be any difference.

@JasLin
Copy link
Contributor

JasLin commented Nov 13, 2016

it's strange , set SELENIUM_PROMISE_MANAGER=1 have no effect on process.env.SELENIUM_PROMISE_MANAGER

code : ding-dong-bot.ts

/**
 *
 * Wechaty - Wechat for Bot
 *
 * Connecting ChatBots
 * https://github.com/wechaty/wechaty
 *
 */

/* tslint:disable:variable-name */
const QrcodeTerminal = require('qrcode-terminal')

import {
  Wechaty
  , Config
  , log
} from '../'

const welcome = `
| __        __        _           _
| \\ \\      / /__  ___| |__   __ _| |_ _   _
|  \\ \\ /\\ / / _ \\/ __| '_ \\ / _\` | __| | | |
|   \\ V  V /  __/ (__| | | | (_| | |_| |_| |
|    \\_/\\_/ \\___|\\___|_| |_|\\__,_|\\__|\\__, |
|                                     |___/

=============== Powered by Wechaty ===============
-------- https://github.com/zixia/wechaty --------

I'm a bot, my super power is talk in Wechat.

If you send me a 'ding', I will reply you a 'dong'!
__________________________________________________

Hope you like it, and you are very welcome to
upgrade me for more super powers!

Please wait... I'm trying to login in...

`

console.log(welcome)

console.log('SELENIUM_PROMISE_MANAGER:' + process.env.SELENIUM_PROMISE_MANAGER)

const bot = Wechaty.instance({ profile: Config.DEFAULT_PROFILE })

bot
.on('login'   , user => {
  log.info('Bot', `${user.name()} logined`)
  console.log('SELENIUM_PROMISE_MANAGER:' + process.env.SELENIUM_PROMISE_MANAGER)
})
.on('logout'    , user => log.info('Bot', `${user.name()} logouted`))
.on('error'   , e => log.info('Bot', 'error: %s', e))
.on('scan', (url, code) => {
  if (!/201|200/.test(String(code))) {
    let loginUrl = url.replace(/\/qrcode\//, '/l/')
    QrcodeTerminal.generate(loginUrl)
  }
  console.log(`${url}\n[${code}] Scan QR Code in above url to login: `)
})
.on('message', m => {
  try {
    const room = m.room()
    console.log((room ? '[' + room.topic() + ']' : '')
                + '<' + m.from().name() + '>'
                + ':' + m.toStringDigest()
    )

    if (/^(ding|ping|bing)$/i.test(m.content()) && !m.self()) {
      m.say('dong')
      log.info('Bot', 'REPLY: dong')
    }
  } catch (e) {
    log.error('Bot', 'on(message) exception: %s' , e)
  }
})

bot.init()
.catch(e => {
  log.error('Bot', 'init() fail: %s', e)
  bot.quit()
  process.exit(-1)
})

function logToFile(data) {
  require('fs').appendFile('message.log', data + '\n\n#############################\n\n', err => {
    if (err) { log.error('LogToFile: %s', err) }
  })
}
if (typeof logToFile === 'fasdfsd') {
  console.log('disable linting warning')
}

run && output:

   master ●   echo $SELENIUM_PROMISE_MANAGER
0
    master ●  export SELENIUM_PROMISE_MANAGER=1 && ts-node example/ding-dong-bot.ts

| __        __        _           _
| \ \      / /__  ___| |__   __ _| |_ _   _
|  \ \ /\ / / _ \/ __| '_ \ / _` | __| | | |
|   \ V  V /  __/ (__| | | | (_| | |_| |_| |
|    \_/\_/ \___|\___|_| |_|\__,_|\__|\__, |
|                                     |___/

=============== Powered by Wechaty ===============
-------- https://github.com/zixia/wechaty --------

I'm a bot, my super power is talk in Wechat.

If you send me a 'ding', I will reply you a 'dong'!
__________________________________________________

Hope you like it, and you are very welcome to
upgrade me for more super powers!

Please wait... I'm trying to login in...


SELENIUM_PROMISE_MANAGER:0
INFO Wechaty v#git[f38fac0 code clean] initializing...
WARN PuppetWebBrowserCookie addCookies() exception: invalid cookie domain: invalid domain:".wx2.qq.com"
  (Session info: chrome=54.0.2840.90)
  (Driver info: chromedriver=2.24.417424 (c5c5ea873213ee72e3d0929b47482681555340c3),platform=Linux 4.4.0-45-generic x86_64)
ERR PuppetWebBrowserCookie load() add() exception: invalid cookie domain: invalid domain:".wx2.qq.com"
  (Session info: chrome=54.0.2840.90)
  (Driver info: chromedriver=2.24.417424 (c5c5ea873213ee72e3d0929b47482681555340c3),platform=Linux 4.4.0-45-generic x86_64)
^C
     master ●  echo $SELENIUM_PROMISE_MANAGER
1

@JasLin
Copy link
Contributor

JasLin commented Nov 13, 2016

found it hardcode in config.ts

/**
 * ISSUE #72
 * Introduce the SELENIUM_PROMISE_MANAGER environment variable.
 * When set to 1, selenium-webdriver will use the existing ControlFlow scheduler.
 * When set to 0, the SimpleScheduler will be used.
 */
process.env['SELENIUM_PROMISE_MANAGER'] = 0

will try to change it in code

@JasLin
Copy link
Contributor

JasLin commented Nov 13, 2016

changed it in code .
can not see the difference ,both are slow. i will trying to change the code to calculate the time spent on getSession() when i am back afternoon.

@JasLin
Copy link
Contributor

JasLin commented Nov 13, 2016

@zixia

code

 private async getChromeDriver(): Promise<WebDriver> {
    log.verbose('PuppetWebBrowserDriver', 'getChromeDriver()')
       ......
        console.time('valid')
        const valid = await this.valid(driver)
        console.timeEnd('valid')
        ......
    return driver
 }

private async valid(driver: WebDriver): Promise<boolean> {
    log.verbose('PuppetWebBrowserDriver', 'valid()')
    try {
      ......
        console.time('getSession')        
        // resolve
        driver.getSession()
              .then(session => {
                clearTimeout(timer)
                resolve(session)
              })
        console.timeEnd('getSession')
      })
     ......
  }

output

SELENIUM_PROMISE_MANAGER:0

getSession: 537.926ms
valid: 546.636ms

getSession: 491.898ms
valid: 500.848ms

getSession: 511.089ms
valid: 519.051ms

getSession: 487.795ms
valid: 500.454ms

getSession: 498.500ms
valid: 509.621ms

SELENIUM_PROMISE_MANAGER:1

getSession: 490.944ms
valid: 501.270ms

getSession: 484.682ms
valid: 496.679ms

getSession: 497.962ms
valid: 507.867ms

getSession: 504.996ms
valid: 514.519ms

getSession: 506.470ms
valid: 518.944ms

it looks everything all right.

@JasLin
Copy link
Contributor

JasLin commented Nov 13, 2016

@zixia another problem, on starting robot. opening the qrcode url at the chrome driver is slower then opening it at the native chrome browser.

in my case ,the native chrome popup and qrcode show fast(immediately), but the qrcode in the terminator was show after about 26s.

time trace: in broswer.ts

code

export class Browser extends EventEmitter {
  ......
  public async init(): Promise<void> {
    log.verbose('PuppetWebBrowser', 'init()')
    ......
    try {
      await this.driver.init()
      log.verbose('PuppetWebBrowser', 'init() driver.init() done')
      console.time('browser.openJumpUrl')
      await this.open(jumpUrl)
      console.timeEnd('browser.openJumpUrl') 
      await this.loadCookie()
                .catch(e => { // fail safe
                  log.verbose('PuppetWebBrowser', 'browser.loadSession(%s) exception: %s'
                                          , this.setting.sessionFile
                                          , e && e.message || e
                  )
                })
      console.time('browser.open')  
      await this.open()
      console.timeEnd('browser.open')      
      ......
    }
  }

  public async open(url: string = 'https://wx.qq.com'): Promise<void> {
    log.verbose('PuppetWebBrowser', `open(${url})`)
    try {
      console.time('driver.get')
      await this.driver.get(url)
      console.timeEnd('driver.get')
    } catch (e) {
      log.error('PuppetWebBrowser', 'open() exception: %s', e.message)
      throw e
    }
  }
  ......
}

output (ran it several times )

driver.get: 270.763ms
browser.openJumpUrl: 272.420ms
driver.get: 26375.641ms
browser.open: 26376.105ms
driver.get: 277.540ms
browser.openJumpUrl: 278.158ms
driver.get: 26444.618ms
browser.open: 26445.229ms

only this times is fast a little

driver.get: 623.712ms
browser.openJumpUrl: 624.237ms
driver.get: 2792.972ms
browser.open: 2793.391ms
driver.get: 291.821ms
browser.openJumpUrl: 292.312ms
driver.get: 26754.434ms
browser.open: 26754.965ms
driver.get: 264.332ms
browser.openJumpUrl: 264.723ms
driver.get: 29616.550ms
browser.open: 29617.324ms
driver.get: 274.785ms
browser.openJumpUrl: 275.427ms
driver.get: 26321.097ms
browser.open: 26321.565ms

Also: performance effect on browser.open is no difference between SELENIUM_PROMISE_MANAGER=0 and SELENIUM_PROMISE_MANAGER=1

@huan
Copy link
Member Author

huan commented Nov 13, 2016

Thanks for the benchmark.

About the 26s problem, it is a known issue #2 , I believe it belongs to the WebDriver support of browser. maybe need to hack chromedriver or ghostdriver(phantomjs) to know how to skip the waiting code.

@huan huan closed this as completed Nov 16, 2016
@huan
Copy link
Member Author

huan commented May 31, 2017

@huan huan reopened this May 31, 2017
@huan huan added the bug label May 31, 2017
@huan
Copy link
Member Author

huan commented Aug 26, 2017

This bug is still paining me time and again.

huan added a commit that referenced this issue Oct 8, 2017
@huan
Copy link
Member Author

huan commented Oct 8, 2017

This issue should be fixed at v0.10 or above.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants