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

how to NOT scan the QRCode on each opening #151

Closed
dcsan opened this issue Dec 21, 2016 · 21 comments
Closed

how to NOT scan the QRCode on each opening #151

dcsan opened this issue Dec 21, 2016 · 21 comments

Comments

@dcsan
Copy link

dcsan commented Dec 21, 2016

Run npm run doctor or wechaty run doctor(for docker user), paste output here

  1. Wechaty version: #git[4ed33d2 https://github.com/XXX has or is using name 'Foo' from external module "../bar" but cannot be named microsoft/TypeScript#9944 compact selenium-webdriver types v2, hope @types v3 will publish soon]
  2. Darwin x64 version 16.1.0 memory 27/8192 MB
  3. Docker: false
  4. Node version: v7.2.1

Expected behavior

I understand that giving a profile string will name the bot, and the cookie data will be saved, so I don't need to re-scan the QR code to login each time. ref:
https://github.com/wechaty/wechaty/wiki/API#wechatyinstanceprofilestring-wechaty

Actual behavior

Data IS saved to a file
Each time the bot starts up, it's needed to scan the QRCode again.

Steps to reproduce the behavior (and fixes, if any)

Launch a bot using any method. pass in:

const WcBot = Wechaty.instance(
  {profile: "SOMENAME"}
)

the file SOMENAME.wechat.json IS created.

I am using ctrl-C to kill the node process - is this correct?
I have tried leaving the browser open and closing it.

Paste the full output logs here with WECHATY_LOG=silly set

next comment

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

initial launch

➜  kbot git:(master) ✗ echo $WECHATY_LOG       
silly
➜  kbot git:(master) ✗ npm start

> kbot@0.6.47 start /Users/dc/dev/rikai/ta-bot/kbot
> DEBUG=*,-engine*,- ts-node bot.ts

SILL Brolog WECHATY_LOG set level to silly
SILL StateMonitor constructor(Wechaty, standby)
VERB Wechaty contructor()
VERB Wechaty addListener(login, function)
VERB Wechaty addListener(logout, function)
VERB Wechaty addListener(error, function)
VERB Wechaty addListener(scan, function)
VERB Wechaty addListener(message, function)
  bot:startup startup +0ms
  bot:startup initDb +2ms
  bot:startup done +28ms
INFO Wechaty v#git[4ed33d2 https://github.com/Microsoft/TypeScript/issues/9944 compact selenium-webdriver types v2, hope @types v3 will publish soon] initializing...
VERB Wechaty puppet: web
VERB Wechaty head: chrome
VERB Wechaty profile: KBOT.wechaty.json
VERB Wechaty uuid: dafda773-e6a9-4c69-883c-bbcf13b7b9f9
SILL StateMonitor Wechaty:current() - standby
VERB StateMonitor Wechaty:target(ready) <- (standby)
VERB StateMonitor Wechaty:current(ready,false) <- (standby,true)
SILL StateMonitor constructor(Puppet, dead)
VERB Config puppetInstance(PuppetWeb)
VERB PuppetWeb init() with head:chrome, profile:KBOT.wechaty.json
VERB StateMonitor Puppet:target(live) <- (dead)
VERB StateMonitor Puppet:current(live,false) <- (dead,true)
SILL UtilLib getPort(18788)
SILL UtilLib getPort(18788) return: 20057
VERB PuppetWeb init() getPort 20057
VERB PuppetWeb initServer()
SILL StateMonitor Puppet:target() - live
VERB PuppetWebServer init() on port 20057
  express:application set "x-powered-by" to true +0ms
  express:application set "etag" to 'weak' +2ms
  express:application set "etag fn" to [Function: wetag] +0ms
  express:application set "env" to 'development' +1ms
  express:application set "query parser" to 'extended' +0ms
  express:application set "query parser fn" to [Function: parseExtendedQueryString] +0ms
  express:application set "subdomain offset" to 2 +0ms
  express:application set "trust proxy" to false +0ms
  express:application set "trust proxy fn" to [Function: trustNone] +1ms
  express:application booting in development mode +0ms
  express:application set "view" to [Function: View] +0ms
  express:application set "views" to '/Users/dc/dev/rikai/ta-bot/kbot/views' +0ms
  express:application set "jsonp callback name" to 'callback' +0ms
  express:router use / query +14ms
  express:router:layer new / +1ms
  express:router use / expressInit +1ms
  express:router:layer new / +0ms
  express:router use / jsonParser +0ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +0ms
  express:router:layer new / +0ms
  express:router:route new /ding +0ms
  express:router:layer new /ding +1ms
  express:router:route get /ding +0ms
  express:router:layer new / +0ms
VERB PuppetWebServer createHttpsServer() listen on port 20057
  socket.io:server initializing namespace / +0ms
  socket.io:server creating engine.io instance with opts {"path":"/socket.io"} +2ms
  socket.io:server attaching client serving req handler +3ms
VERB PuppetWeb initServer() done
VERB PuppetWeb initBrowser()
SILL StateMonitor constructor(Browser, close)
VERB PuppetWebBrowser constructor() with head(chrome) sessionFile(KBOT.wechaty.json)
VERB PuppetWebBrowserDriver constructor(chrome)
VERB PuppetWebBrowserCookie constructor(BrowserDriver, KBOT.wechaty.json)
SILL StateMonitor Puppet:target() - live
VERB PuppetWebBrowser init()
SILL StateMonitor Browser:current() - close
VERB StateMonitor Browser:target(open) <- (close)
VERB StateMonitor Browser:current(open,false) <- (close,true)
VERB PuppetWebBrowserDriver init() for head: chrome
VERB PuppetWebBrowserDriver initChromeDriver()
VERB PuppetWebBrowserDriver initChromeDriver() new Builder()
VERB PuppetWebBrowserDriver initChromeDriver() new Builder() done
VERB PuppetWebBrowserDriver valid()
VERB PuppetWebBrowserDriver valid() getSession()
  bot:Grammar gram count 49 +112ms
VERB PuppetWebBrowserDriver valid() getSession() then() done
VERB PuppetWebBrowserDriver valid() getSession() then() watchdog timer exist, will be cleared
VERB PuppetWebBrowserDriver watchdogTimer = null after set null
VERB PuppetWebBrowserDriver valid() driver.getSession() done()
VERB PuppetWebBrowserDriver valid() driver.executeScript() done
SILL PuppetWebBrowserDriver valid() driver ok
VERB PuppetWebBrowserDriver initChromeDriver() valid() done: true
SILL PuppetWebBrowserDriver initChromeDriver() success
VERB PuppetWebBrowser init() driver.init() done
VERB PuppetWebBrowser open(https://wx.qq.com/zh_CN/htmledition/v2/images/webwxgeticon.jpg)
VERB PuppetWebBrowserCookie load() from KBOT.wechaty.json
SILL PuppetWebBrowserCookie addCookies({"domain":".wechat.com","expiry":1482375002,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en_US"})
WARN PuppetWebBrowserCookie addCookies() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
ERR PuppetWebBrowserCookie load() add() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
VERB PuppetWebBrowser browser.loadSession(KBOT.wechaty.json) exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
VERB PuppetWebBrowser open(https://wx.qq.com)
SILL StateMonitor Browser:target() - open
VERB StateMonitor Browser:current(open,true) <- (open,false)
VERB PuppetWeb initBrowser() done
VERB PuppetWeb initBridge()
VERB PuppetWebBridge new Bridge({puppet: PuppetWeb, port: 20057})
SILL StateMonitor Puppet:target() - live
VERB PuppetWebBridge init()
VERB PuppetWebBridge inject()
VERB PuppetWebBridge getInjectio()
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("injectioReturnValue = /** * * Wechaty - Wechat for Bot, and human who talk to  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() eval(Wechaty) return code[200] message[WechatyBro Inject Done] port[20057]
VERB PuppetWebBridge proxyWechaty(init, )
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() Wechaty.init() return code[200] message[WechatyBro Init Succ on port: 20057] port[20057]
VERB PuppetWebBridge ding(inject())
VERB PuppetWebBridge proxyWechaty(ding, inject())
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() ding success
VERB PuppetWeb initBridge() done
VERB StateMonitor Puppet:current(live,true) <- (live,false)
SILL PuppetWebWatchdog onFeed: 120000, HEARTBEAT[inited]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
VERB PuppetWebWatchdog clearWatchDogTimer() nothing to clear
SILL PuppetWebWatchdog setWatchDogTimer(120000, HEARTBEAT:[inited])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 32 MB, require: 4 MB
VERB PuppetWeb init() done
VERB StateMonitor Wechaty:current(ready,true) <- (ready,false)
  socket.io:server incoming connection with id zusf-b1bSgxUI6MIAAAA +3s
  socket.io:client connecting to namespace / +0ms
  socket.io:namespace adding socket to nsp / +1ms
  socket.io:socket socket connected - writing packet +2ms
  socket.io:socket joining room zusf-b1bSgxUI6MIAAAA +0ms
  socket.io:client writing packet {"type":0,"nsp":"/"} +1ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +3s
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +0ms
VERB PuppetWebServer createSocketIo() got connection from browser
VERB PuppetWebServer initEventFromClient()
VERB PuppetWebEvent onServerConnection: [object Object]
  socket.io:socket joined room zusf-b1bSgxUI6MIAAAA +2ms
  socket.io-parser decoded 2["log","connectSocket()"] as {"type":2,"nsp":"/","data":["log","connectSocket()"]} +768ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket()"]} +767ms
  socket.io:socket emitting event ["log","connectSocket()"] +0ms
  socket.io:socket dispatching an event ["log","connectSocket()"] +1ms
VERB PuppetWebEvent onServerLog(connectSocket())
  socket.io-parser decoded 2["log","connectSocket: io not found. loading lib..."] as {"type":2,"nsp":"/","data":["log","connectSocket: io not found. loading lib..."]} +4ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket: io not found. loading lib..."]} +3ms
  socket.io:socket emitting event ["log","connectSocket: io not found. loading lib..."] +0ms
  socket.io:socket dispatching an event ["log","connectSocket: io not found. loading lib..."] +0ms
VERB PuppetWebEvent onServerLog(connectSocket: io not found. loading lib...)
  socket.io-parser decoded 2["log","checkScan() - code change detected: from null to 0"] as {"type":2,"nsp":"/","data":["log","checkScan() - code change detected: from null to 0"]} +2ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","checkScan() - code change detected: from null to 0"]} +1ms
  socket.io:socket emitting event ["log","checkScan() - code change detected: from null to 0"] +0ms
  socket.io:socket dispatching an event ["log","checkScan() - code change detected: from null to 0"] +0ms
VERB PuppetWebEvent onServerLog(checkScan() - code change detected: from null to 0)
  socket.io-parser decoded 2["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}] as {"type":2,"nsp":"/","data":["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}]} +0ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}]} +0ms
  socket.io:socket emitting event ["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}] +0ms
  socket.io:socket dispatching an event ["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}] +0ms
VERB PuppetWebEvent onServerScan(0)
SILL PuppetWebBrowserCookie save() to file KBOT.wechaty.json
  socket.io-parser decoded 2["ding","heartbeat@browser"] as {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +3ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +3ms
  socket.io:socket emitting event ["ding","heartbeat@browser"] +0ms
  socket.io:socket dispatching an event ["ding","heartbeat@browser"] +0ms
SILL PuppetWebEvent onServerDing(heartbeat@browser)
SILL PuppetWebWatchdog onFeed: 60000, HEARTBEAT[heartbeat@browser]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [120] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, HEARTBEAT:[heartbeat@browser])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 53 MB, require: 4 MB
  socket.io-parser decoded 2["log","recv ding"] as {"type":2,"nsp":"/","data":["log","recv ding"]} +2ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","recv ding"]} +2ms
  socket.io:socket emitting event ["log","recv ding"] +0ms
  socket.io:socket dispatching an event ["log","recv ding"] +0ms
VERB PuppetWebEvent onServerLog(recv ding)
  socket.io-parser decoded 2["log","socket io lib loaded."] as {"type":2,"nsp":"/","data":["log","socket io lib loaded."]} +1ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","socket io lib loaded."]} +1ms
  socket.io:socket emitting event ["log","socket io lib loaded."] +0ms
  socket.io:socket dispatching an event ["log","socket io lib loaded."] +0ms
VERB PuppetWebEvent onServerLog(socket io lib loaded.)
SILL PuppetWebBrowserCookie save() saving 3 cookies: pgv_pvi,pgv_si,mm_lang
  socket.io-parser decoded 2["log","connectSocket()"] as {"type":2,"nsp":"/","data":["log","connectSocket()"]} +2ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket()"]} +2ms
  socket.io:socket emitting event ["log","connectSocket()"] +0ms
  socket.io:socket dispatching an event ["log","connectSocket()"] +0ms
VERB PuppetWebEvent onServerLog(connectSocket())
SILL PuppetWebBrowserCookie save() 3 cookies to KBOT.wechaty.json
SILL PuppetWebWatchdog onFeed: 60000, SCAN[[object Object]]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [60] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, SCAN:[[object Object]])
SILL PuppetWebWatchdog monitorScan(SCAN)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 53 MB, require: 4 MB
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
https://login.weixin.qq.com/qrcode/ofW7AHClxQ==
[0] Scan QR Code in above url to login: 
  socket.io-parser decoded 2["ding","heartbeat@browser"] as {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +14s
  socket.io:socket got packet {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +14s
  socket.io:socket emitting event ["ding","heartbeat@browser"] +1ms
  socket.io:socket dispatching an event ["ding","heartbeat@browser"] +0ms
SILL PuppetWebEvent onServerDing(heartbeat@browser)
SILL PuppetWebWatchdog onFeed: 60000, HEARTBEAT[heartbeat@browser]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [47] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, HEARTBEAT:[heartbeat@browser])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 40 MB, require: 4 MB
  socket.io-parser decoded 2["log","checkScan() - code change detected: from 0 to 201"] as {"type":2,"nsp":"/","data":["log","checkScan() - code change detected: from 0 to 201"]} +4s
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","checkScan() - code change detected: from 0 to 201"]} +4s
  socket.io:socket emitting event ["log","checkScan() - code change detected: from 0 to 201"] +0ms
  socket.io:socket dispatching an event ["log","checkScan() - code change detected: from 0 to 201"] +0ms
VERB PuppetWebEvent onServerLog(checkScan() - code change detected: from 0 to 201)
  socket.io-parser decoded 2["scan",{"code":201,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}] as {"type":2,"nsp":"/","data":["scan",{"code":201,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}]} +5ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["scan",{"code":201,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}]} +5ms
  socket.io:socket emitting event ["scan",{"code":201,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}] +0ms
  socket.io:socket dispatching an event ["scan",{"code":201,"url":"https://login.weixin.qq.com/qrcode/ofW7AHClxQ=="}] +0ms
VERB PuppetWebEvent onServerScan(201)
SILL PuppetWebBrowserCookie save() to file KBOT.wechaty.json
SILL PuppetWebBrowserCookie save() saving 3 cookies: pgv_pvi,pgv_si,mm_lang
SILL PuppetWebBrowserCookie save() 3 cookies to KBOT.wechaty.json
SILL PuppetWebWatchdog onFeed: 60000, SCAN[[object Object]]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [56] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, SCAN:[[object Object]])
SILL PuppetWebWatchdog monitorScan(SCAN)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 41 MB, require: 4 MB
https://login.weixin.qq.com/qrcode/ofW7AHClxQ==
[201] Scan QR Code in above url to login: 
  socket.io-parser decoded 2["unload","[object Event]"] as {"type":2,"nsp":"/","data":["unload","[object Event]"]} +6s
  socket.io:socket got packet {"type":2,"nsp":"/","data":["unload","[object Event]"]} +6s
  socket.io:socket emitting event ["unload","[object Event]"] +0ms
  socket.io:socket dispatching an event ["unload","[object Event]"] +0ms
  socket.io:client client close with reason transport close +7ms
  socket.io:socket closing socket - reason transport close +1ms
SILL PuppetWebServer initEventsFromClient() on(disconnect) socket.io disconnect: transport close
VERB PuppetWebEvent onServerDisconnect(transport close)
SILL StateMonitor Puppet:current() - live
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
VERB PuppetWebBrowser readyLive()
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBrowser Browser.execute("return 1+1")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
VERB PuppetWebEvent onServerDisconnect() re-initing bridge
VERB PuppetWebBridge init()
VERB PuppetWebBridge inject()
VERB PuppetWebBridge getInjectio()
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("injectioReturnValue = /** * * Wechaty - Wechat for Bot, and human who talk to  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() eval(Wechaty) return code[200] message[WechatyBro Inject Done] port[20057]
VERB PuppetWebBridge proxyWechaty(init, )
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() Wechaty.init() return code[200] message[WechatyBro Init Succ on port: 20057] port[20057]
VERB PuppetWebBridge ding(inject())
VERB PuppetWebBridge proxyWechaty(ding, inject())
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
  socket.io:server incoming connection with id WbtOXLTRzTBVXF2KAAAB +2s
  socket.io:client connecting to namespace / +1ms
  socket.io:namespace adding socket to nsp / +2ms
  socket.io:socket socket connected - writing packet +1ms
  socket.io:socket joining room WbtOXLTRzTBVXF2KAAAB +0ms
  socket.io:client writing packet {"type":0,"nsp":"/"} +1ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +2s
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +1ms
VERB PuppetWebServer createSocketIo() got connection from browser
VERB PuppetWebServer initEventFromClient()
VERB PuppetWebEvent onServerConnection: [object Object]
  socket.io:socket joined room WbtOXLTRzTBVXF2KAAAB +3ms
SILL PuppetWebBridge inject() ding success
VERB PuppetWebEvent onServerDisconnect() setTimeout() bridge.init() done.
  socket.io-parser decoded 2["log","login(page refresh)"] as {"type":2,"nsp":"/","data":["log","login(page refresh)"]} +24ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","login(page refresh)"]} +25ms
  socket.io:socket emitting event ["log","login(page refresh)"] +0ms
  socket.io:socket dispatching an event ["log","login(page refresh)"] +0ms
VERB PuppetWebEvent onServerLog(login(page refresh))
  socket.io-parser decoded 2["login","page refresh"] as {"type":2,"nsp":"/","data":["login","page refresh"]} +246ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["login","page refresh"]} +251ms
  socket.io:socket emitting event ["login","page refresh"] +0ms
  socket.io:socket dispatching an event ["login","page refresh"] +0ms
VERB PuppetWebEvent onServerLogin(page refresh, 0)
VERB PuppetWebBridge getUserName()
VERB PuppetWebBridge proxyWechaty(getUserName, )
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
  socket.io-parser decoded 2["log","connectSocket()"] as {"type":2,"nsp":"/","data":["log","connectSocket()"]} +9ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket()"]} +3ms
  socket.io:socket emitting event ["log","connectSocket()"] +2ms
  socket.io:socket dispatching an event ["log","connectSocket()"] +0ms
VERB PuppetWebEvent onServerLog(connectSocket())
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
  socket.io-parser decoded 2["log","connectSocket: io not found. loading lib..."] as {"type":2,"nsp":"/","data":["log","connectSocket: io not found. loading lib..."]} +6ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket: io not found. loading lib..."]} +5ms
  socket.io:socket emitting event ["log","connectSocket: io not found. loading lib..."] +0ms
  socket.io:socket dispatching an event ["log","connectSocket: io not found. loading lib..."] +0ms
VERB PuppetWebEvent onServerLog(connectSocket: io not found. loading lib...)
  socket.io-parser decoded 2["log","checkScan() - already login, no more check, and return(only)"] as {"type":2,"nsp":"/","data":["log","checkScan() - already login, no more check, and return(only)"]} +5ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","checkScan() - already login, no more check, and return(only)"]} +10ms
  socket.io:socket emitting event ["log","checkScan() - already login, no more check, and return(only)"] +1ms
  socket.io:socket dispatching an event ["log","checkScan() - already login, no more check, and return(only)"] +0ms
VERB PuppetWebEvent onServerLog(checkScan() - already login, no more check, and return(only))
SILL PuppetWebEvent bridge.getUserName: @4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365
SILL Contact constructor(@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365)
SILL Contact ready()
SILL Contact get contact via PuppetWeb
SILL PuppetWebBridge getContact() retryPromise: attampt 1/35 time for timeout 306250
VERB PuppetWebBridge proxyWechaty(getContact, @4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365)
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
  socket.io-parser decoded 2["ding","heartbeat@browser"] as {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +15ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +8ms
  socket.io:socket emitting event ["ding","heartbeat@browser"] +0ms
  socket.io:socket dispatching an event ["ding","heartbeat@browser"] +2ms
SILL PuppetWebEvent onServerDing(heartbeat@browser)
SILL PuppetWebWatchdog onFeed: 60000, HEARTBEAT[heartbeat@browser]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [53] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, HEARTBEAT:[heartbeat@browser])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
SILL PuppetWebWatchdog memoryCheck() free: 119 MB, require: 4 MB
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
  socket.io-parser decoded 2["log","socket io lib loaded."] as {"type":2,"nsp":"/","data":["log","socket io lib loaded."]} +10ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","socket io lib loaded."]} +14ms
  socket.io:socket emitting event ["log","socket io lib loaded."] +1ms
  socket.io:socket dispatching an event ["log","socket io lib loaded."] +0ms
VERB PuppetWebEvent onServerLog(socket io lib loaded.)
SILL Contact contactGetter(@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365) resolved
SILL PuppetWebEvent onServerLogin() user DC-bot logined
SILL PuppetWebBrowserCookie save() to file KBOT.wechaty.json
  socket.io-parser decoded 2["log","connectSocket()"] as {"type":2,"nsp":"/","data":["log","connectSocket()"]} +20ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket()"]} +14ms
  socket.io:socket emitting event ["log","connectSocket()"] +0ms
  socket.io:socket dispatching an event ["log","connectSocket()"] +0ms
VERB PuppetWebEvent onServerLog(connectSocket())
  socket.io-parser decoded 2["log","recv ding"] as {"type":2,"nsp":"/","data":["log","recv ding"]} +2ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","recv ding"]} +1ms
  socket.io:socket emitting event ["log","recv ding"] +0ms
  socket.io:socket dispatching an event ["log","recv ding"] +8ms
VERB PuppetWebEvent onServerLog(recv ding)
SILL PuppetWebBrowserCookie save() saving 9 cookies: mm_lang,webwx_auth_ticket,webwxuvid,webwx_data_ticket,pgv_si,wxloadtime,wxsid,pgv_pvi,wxuin
SILL PuppetWebBrowserCookie save() 9 cookies to KBOT.wechaty.json
INFO Bot DC-bot logined
VERB Wechaty say(Wechaty login)
SILL Message constructor() SN:0
SILL Contact constructor(filehelper)
SILL PuppetWeb send() destination: filehelper, content: Wechaty login)
VERB PuppetWebBridge proxyWechaty(send, filehelper, Wechaty login)
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
  socket.io-parser decoded 2["message",{"ToUserName":"filehelper","Content":"Wechaty login","MsgType":1,"FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MsgId":"14823322145360487","LocalID":"14823322145360487","ClientMsgId":"14823322145360487","CreateTime":1482332215,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"Wechaty login","MMPeerUserName":"filehelper","MMDigest":"Wechaty login","MMIsSend":true,"MMIsChatRoom":false,"MMActualContent":"Wechaty login","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:56","MMDisplayTime":1482332215,"MMTime":"22:56"}] as {"type":2,"nsp":"/","data":["message",{"ToUserName":"filehelper","Content":"Wechaty login","MsgType":1,"FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MsgId":"14823322145360487","LocalID":"14823322145360487","ClientMsgId":"14823322145360487","CreateTime":1482332215,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"Wechaty login","MMPeerUserName":"filehelper","MMDigest":"Wechaty login","MMIsSend":true,"MMIsChatRoom":false,"MMActualContent":"Wechaty login","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:56","MMDisplayTime":1482332215,"MMTime":"22:56"}]} +31ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["message",{"ToUserName":"filehelper","Content":"Wechaty login","MsgType":1,"FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MsgId":"14823322145360487","LocalID":"14823322145360487","ClientMsgId":"14823322145360487","CreateTime":1482332215,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"Wechaty login","MMPeerUserName":"filehelper","MMDigest":"Wechaty login","MMIsSend":true,"MMIsChatRoom":false,"MMActualContent":"Wechaty login","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:56","MMDisplayTime":1482332215,"MMTime":"22:56"}]} +26ms
  socket.io:socket emitting event ["message",{"ToUserName":"filehelper","Content":"Wechaty login","MsgType":1,"FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MsgId":"14823322145360487","LocalID":"14823322145360487","ClientMsgId":"14823322145360487","CreateTime":1482332215,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"Wechaty login","MMPeerUserName":"filehelper","MMDigest":"Wechaty login","MMIsSend":true,"MMIsChatRoom":false,"MMActualContent":"Wechaty login","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:56","MMDisplayTime":1482332215,"MMTime":"22:56"}] +1ms
  socket.io:socket dispatching an event ["message",{"ToUserName":"filehelper","Content":"Wechaty login","MsgType":1,"FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MsgId":"14823322145360487","LocalID":"14823322145360487","ClientMsgId":"14823322145360487","CreateTime":1482332215,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"Wechaty login","MMPeerUserName":"filehelper","MMDigest":"Wechaty login","MMIsSend":true,"MMIsChatRoom":false,"MMActualContent":"Wechaty login","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:56","MMDisplayTime":1482332215,"MMTime":"22:56"}] +1ms
SILL Message constructor() SN:1
SILL Message ready()
SILL Contact ready()
SILL Contact ready()
SILL Contact get contact via PuppetWeb
SILL PuppetWebBridge getContact() retryPromise: attampt 1/35 time for timeout 306250
VERB PuppetWebBridge proxyWechaty(getContact, filehelper)
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL Contact contactGetter(filehelper) resolved
SILL Message ready()
SILL Contact ready()
SILL Contact ready()
  bot:WcBot RECV: Wechaty login +29s
  bot:WcBot room null +0ms
<DC-bot>:{TEXT}Wechaty login
  bot:WcBot dont reply to self message +0ms
  socket.io-parser decoded 2["ding","heartbeat@browser"] as {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +15s
  socket.io:socket got packet {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +15s
  socket.io:socket emitting event ["ding","heartbeat@browser"] +0ms
  socket.io:socket dispatching an event ["ding","heartbeat@browser"] +0ms
SILL PuppetWebEvent onServerDing(heartbeat@browser)
SILL PuppetWebWatchdog onFeed: 60000, HEARTBEAT[heartbeat@browser]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [46] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, HEARTBEAT:[heartbeat@browser])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
SILL PuppetWebWatchdog memoryCheck() free: 57 MB, require: 4 MB
  socket.io-parser decoded 2["message",{"MsgType":1,"Content":"test","FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","ToUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MsgId":"14823322366800213","LocalID":"14823322366800213","ClientMsgId":"14823322366800213","CreateTime":1482332237,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"test","MMPeerUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MMDigest":"test","MMIsSend":true,"MMIsChatRoom":true,"MMActualContent":"test","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:57","MMDisplayTime":1482332237,"MMTime":"22:57"}] as {"type":2,"nsp":"/","data":["message",{"MsgType":1,"Content":"test","FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","ToUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MsgId":"14823322366800213","LocalID":"14823322366800213","ClientMsgId":"14823322366800213","CreateTime":1482332237,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"test","MMPeerUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MMDigest":"test","MMIsSend":true,"MMIsChatRoom":true,"MMActualContent":"test","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:57","MMDisplayTime":1482332237,"MMTime":"22:57"}]} +8s
  socket.io:socket got packet {"type":2,"nsp":"/","data":["message",{"MsgType":1,"Content":"test","FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","ToUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MsgId":"14823322366800213","LocalID":"14823322366800213","ClientMsgId":"14823322366800213","CreateTime":1482332237,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"test","MMPeerUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MMDigest":"test","MMIsSend":true,"MMIsChatRoom":true,"MMActualContent":"test","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:57","MMDisplayTime":1482332237,"MMTime":"22:57"}]} +8s
  socket.io:socket emitting event ["message",{"MsgType":1,"Content":"test","FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","ToUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MsgId":"14823322366800213","LocalID":"14823322366800213","ClientMsgId":"14823322366800213","CreateTime":1482332237,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"test","MMPeerUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MMDigest":"test","MMIsSend":true,"MMIsChatRoom":true,"MMActualContent":"test","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:57","MMDisplayTime":1482332237,"MMTime":"22:57"}] +0ms
  socket.io:socket dispatching an event ["message",{"MsgType":1,"Content":"test","FromUserName":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","ToUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MsgId":"14823322366800213","LocalID":"14823322366800213","ClientMsgId":"14823322366800213","CreateTime":1482332237,"MMStatus":1,"sendByLocal":true,"MMAtContacts":"","MMSendContent":"test","MMPeerUserName":"@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5","MMDigest":"test","MMIsSend":true,"MMIsChatRoom":true,"MMActualContent":"test","MMActualSender":"@4379b77717d8ab07977ba40bbba85f5e90698839407518cb12ff04d3e3b4a365","MMDigestTime":"22:57","MMDisplayTime":1482332237,"MMTime":"22:57"}] +0ms
SILL Message constructor() SN:2
SILL Message ready()
SILL Contact ready()
SILL Room constructor(@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5)
SILL Room ready()
SILL PuppetWebBridge getContact() retryPromise: attampt 1/35 time for timeout 306250
VERB PuppetWebBridge proxyWechaty(getContact, @@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5)
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL Room contactGetter(@@e3896bf57a9937367b1a9944297ed1c6e4cc7b59e6f25fc7d9d9a0c0d3978ab5) resolved
SILL Contact constructor(@d977dc2b39a2a08d6ec44a548ac40db8b7b99dda7cdf5adeaf071629b496fbb8)
SILL Contact constructor(@c81b173ca7fbd29c07fd0d2f4ba61d09c3d462ce5013b42c93ebd2c880a2bedd)
SILL Contact constructor(@1fd06859f4d7a8ab9b7e60219ffadb47)
SILL Contact ready(function)
SILL PuppetWebBridge getContact() retryPromise: attampt 1/35 time for timeout 306250
VERB PuppetWebBridge proxyWechaty(getContact, @d977dc2b39a2a08d6ec44a548ac40db8b7b99dda7cdf5adeaf071629b496fbb8)
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL Contact ready(function)
SILL Contact ready(function)
SILL PuppetWebBridge getContact() retryPromise: attampt 1/35 time for timeout 306250
VERB PuppetWebBridge proxyWechaty(getContact, @c81b173ca7fbd29c07fd0d2f4ba61d09c3d462ce5013b42c93ebd2c880a2bedd)
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL Contact ready(function)
SILL PuppetWebBridge getContact() retryPromise: attampt 1/35 time for timeout 306250
VERB PuppetWebBridge proxyWechaty(getContact, @1fd06859f4d7a8ab9b7e60219ffadb47)
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL Contact contactGetter(@d977dc2b39a2a08d6ec44a548ac40db8b7b99dda7cdf5adeaf071629b496fbb8) resolved
SILL Contact contactGetter(@1fd06859f4d7a8ab9b7e60219ffadb47) resolved
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL Contact contactGetter(@c81b173ca7fbd29c07fd0d2f4ba61d09c3d462ce5013b42c93ebd2c880a2bedd) resolved
SILL Message ready()
SILL Contact ready()
SILL Room ready()
  bot:WcBot RECV: test +22s
  bot:WcBot room Room {

... data

[TestBotGroup]<DC-bot>:{TEXT}test
  bot:WcBot dont reply to self message +9ms
  socket.io-parser decoded 2["ding","heartbeat@browser"] as {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +7s
  socket.io:socket got packet {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +7s
  socket.io:socket emitting event ["ding","heartbeat@browser"] +0ms
  socket.io:socket dispatching an event ["ding","heartbeat@browser"] +0ms
SILL PuppetWebEvent onServerDing(heartbeat@browser)
SILL PuppetWebWatchdog onFeed: 60000, HEARTBEAT[heartbeat@browser]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [45] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, HEARTBEAT:[heartbeat@browser])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
SILL PuppetWebWatchdog memoryCheck() free: 36 MB, require: 4 MB
^CWechaty exit 130 because of SIGINT 
VERB Wechaty say(Wechaty exit 130 because of SIGINT )
SILL Message constructor() SN:3
SILL PuppetWeb send() destination: filehelper, content: Wechaty exit 130 because of SIGINT )
VERB PuppetWebBridge proxyWechaty(send, filehelper, Wechaty exit 130 because of SIGINT )
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open

bot stopped with ctrl-C

restart bot and a QR is then again required.


➜  kbot git:(master) ✗ npm start

> kbot@0.6.47 start /Users/dc/dev/rikai/ta-bot/kbot
> DEBUG=*,-engine*,- ts-node bot.ts

SILL Brolog WECHATY_LOG set level to silly
SILL StateMonitor constructor(Wechaty, standby)
VERB Wechaty contructor()
VERB Wechaty addListener(login, function)
VERB Wechaty addListener(logout, function)
VERB Wechaty addListener(error, function)
VERB Wechaty addListener(scan, function)
VERB Wechaty addListener(message, function)
  bot:startup startup +0ms
  bot:startup initDb +1ms
  bot:startup done +23ms
INFO Wechaty v#git[4ed33d2 https://github.com/Microsoft/TypeScript/issues/9944 compact selenium-webdriver types v2, hope @types v3 will publish soon] initializing...
VERB Wechaty puppet: web
VERB Wechaty head: chrome
VERB Wechaty profile: KBOT.wechaty.json
VERB Wechaty uuid: 2f015bdc-88f4-4384-998c-e3010fbc4988
SILL StateMonitor Wechaty:current() - standby
VERB StateMonitor Wechaty:target(ready) <- (standby)
VERB StateMonitor Wechaty:current(ready,false) <- (standby,true)
SILL StateMonitor constructor(Puppet, dead)
VERB Config puppetInstance(PuppetWeb)
VERB PuppetWeb init() with head:chrome, profile:KBOT.wechaty.json
VERB StateMonitor Puppet:target(live) <- (dead)
VERB StateMonitor Puppet:current(live,false) <- (dead,true)
SILL UtilLib getPort(18788)
SILL UtilLib getPort(18788) return: 19061
VERB PuppetWeb init() getPort 19061
VERB PuppetWeb initServer()
SILL StateMonitor Puppet:target() - live
VERB PuppetWebServer init() on port 19061
  express:application set "x-powered-by" to true +0ms
  express:application set "etag" to 'weak' +2ms
  express:application set "etag fn" to [Function: wetag] +1ms
  express:application set "env" to 'development' +0ms
  express:application set "query parser" to 'extended' +0ms
  express:application set "query parser fn" to [Function: parseExtendedQueryString] +0ms
  express:application set "subdomain offset" to 2 +1ms
  express:application set "trust proxy" to false +0ms
  express:application set "trust proxy fn" to [Function: trustNone] +0ms
  express:application booting in development mode +0ms
  express:application set "view" to [Function: View] +0ms
  express:application set "views" to '/Users/dc/dev/rikai/ta-bot/kbot/views' +1ms
  express:application set "jsonp callback name" to 'callback' +0ms
  express:router use / query +13ms
  express:router:layer new / +1ms
  express:router use / expressInit +0ms
  express:router:layer new / +0ms
  express:router use / jsonParser +1ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +0ms
  express:router:layer new / +0ms
  express:router:route new /ding +0ms
  express:router:layer new /ding +0ms
  express:router:route get /ding +0ms
  express:router:layer new / +0ms
VERB PuppetWebServer createHttpsServer() listen on port 19061
  socket.io:server initializing namespace / +0ms
  socket.io:server creating engine.io instance with opts {"path":"/socket.io"} +1ms
  socket.io:server attaching client serving req handler +2ms
VERB PuppetWeb initServer() done
VERB PuppetWeb initBrowser()
SILL StateMonitor constructor(Browser, close)
VERB PuppetWebBrowser constructor() with head(chrome) sessionFile(KBOT.wechaty.json)
VERB PuppetWebBrowserDriver constructor(chrome)
VERB PuppetWebBrowserCookie constructor(BrowserDriver, KBOT.wechaty.json)
SILL StateMonitor Puppet:target() - live
VERB PuppetWebBrowser init()
SILL StateMonitor Browser:current() - close
VERB StateMonitor Browser:target(open) <- (close)
VERB StateMonitor Browser:current(open,false) <- (close,true)
VERB PuppetWebBrowserDriver init() for head: chrome
VERB PuppetWebBrowserDriver initChromeDriver()
VERB PuppetWebBrowserDriver initChromeDriver() new Builder()
VERB PuppetWebBrowserDriver initChromeDriver() new Builder() done
VERB PuppetWebBrowserDriver valid()
VERB PuppetWebBrowserDriver valid() getSession()
  bot:Grammar gram count 49 +112ms
VERB PuppetWebBrowserDriver valid() getSession() then() done
VERB PuppetWebBrowserDriver valid() getSession() then() watchdog timer exist, will be cleared
VERB PuppetWebBrowserDriver watchdogTimer = null after set null
VERB PuppetWebBrowserDriver valid() driver.getSession() done()
VERB PuppetWebBrowserDriver valid() driver.executeScript() done
SILL PuppetWebBrowserDriver valid() driver ok
VERB PuppetWebBrowserDriver initChromeDriver() valid() done: true
SILL PuppetWebBrowserDriver initChromeDriver() success
VERB PuppetWebBrowser init() driver.init() done
VERB PuppetWebBrowser open(https://wx.qq.com/zh_CN/htmledition/v2/images/webwxgeticon.jpg)
VERB PuppetWebBrowserCookie load() from KBOT.wechaty.json
SILL PuppetWebBrowserCookie addCookies({"domain":".wechat.com","expiry":1482375412,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en_US"})
WARN PuppetWebBrowserCookie addCookies() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
ERR PuppetWebBrowserCookie load() add() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
VERB PuppetWebBrowser browser.loadSession(KBOT.wechaty.json) exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
VERB PuppetWebBrowser open(https://wx.qq.com)
SILL StateMonitor Browser:target() - open
VERB StateMonitor Browser:current(open,true) <- (open,false)
VERB PuppetWeb initBrowser() done
VERB PuppetWeb initBridge()
VERB PuppetWebBridge new Bridge({puppet: PuppetWeb, port: 19061})
SILL StateMonitor Puppet:target() - live
VERB PuppetWebBridge init()
VERB PuppetWebBridge inject()
VERB PuppetWebBridge getInjectio()
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("injectioReturnValue = /** * * Wechaty - Wechat for Bot, and human who talk to  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() eval(Wechaty) return code[200] message[WechatyBro Inject Done] port[19061]
VERB PuppetWebBridge proxyWechaty(init, )
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() Wechaty.init() return code[200] message[WechatyBro Init Succ on port: 19061] port[19061]
VERB PuppetWebBridge ding(inject())
VERB PuppetWebBridge proxyWechaty(ding, inject())
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute("return typeof WechatyBro === "undefined"")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge execute()
SILL PuppetWebBrowser Browser.execute(" const callback = arguments[arguments.length - 1] const isAsync = (typeof  ... ")
SILL StateMonitor Browser:target() - open
SILL StateMonitor Browser:current() - open
SILL PuppetWebBridge inject() ding success
VERB PuppetWeb initBridge() done
VERB StateMonitor Puppet:current(live,true) <- (live,false)
SILL PuppetWebWatchdog onFeed: 120000, HEARTBEAT[inited]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
VERB PuppetWebWatchdog clearWatchDogTimer() nothing to clear
SILL PuppetWebWatchdog setWatchDogTimer(120000, HEARTBEAT:[inited])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 28 MB, require: 4 MB
VERB PuppetWeb init() done
VERB StateMonitor Wechaty:current(ready,true) <- (ready,false)
  socket.io:server incoming connection with id Vj9nsEhIbqR-zu1oAAAA +2s
  socket.io:client connecting to namespace / +1ms
  socket.io:namespace adding socket to nsp / +0ms
  socket.io:socket socket connected - writing packet +2ms
  socket.io:socket joining room Vj9nsEhIbqR-zu1oAAAA +0ms
  socket.io:client writing packet {"type":0,"nsp":"/"} +1ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +2s
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +0ms
VERB PuppetWebServer createSocketIo() got connection from browser
VERB PuppetWebServer initEventFromClient()
VERB PuppetWebEvent onServerConnection: [object Object]
  socket.io:socket joined room Vj9nsEhIbqR-zu1oAAAA +1ms
  socket.io-parser decoded 2["log","connectSocket()"] as {"type":2,"nsp":"/","data":["log","connectSocket()"]} +768ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket()"]} +768ms
  socket.io:socket emitting event ["log","connectSocket()"] +0ms
  socket.io:socket dispatching an event ["log","connectSocket()"] +0ms
VERB PuppetWebEvent onServerLog(connectSocket())
  socket.io-parser decoded 2["log","connectSocket: io not found. loading lib..."] as {"type":2,"nsp":"/","data":["log","connectSocket: io not found. loading lib..."]} +2ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket: io not found. loading lib..."]} +1ms
  socket.io:socket emitting event ["log","connectSocket: io not found. loading lib..."] +1ms
  socket.io:socket dispatching an event ["log","connectSocket: io not found. loading lib..."] +0ms
VERB PuppetWebEvent onServerLog(connectSocket: io not found. loading lib...)
  socket.io-parser decoded 2["log","checkScan() - code change detected: from null to 0"] as {"type":2,"nsp":"/","data":["log","checkScan() - code change detected: from null to 0"]} +2ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","checkScan() - code change detected: from null to 0"]} +1ms
  socket.io:socket emitting event ["log","checkScan() - code change detected: from null to 0"] +0ms
  socket.io:socket dispatching an event ["log","checkScan() - code change detected: from null to 0"] +0ms
VERB PuppetWebEvent onServerLog(checkScan() - code change detected: from null to 0)
  socket.io-parser decoded 2["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/YfiMkp3v4w=="}] as {"type":2,"nsp":"/","data":["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/YfiMkp3v4w=="}]} +1ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/YfiMkp3v4w=="}]} +1ms
  socket.io:socket emitting event ["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/YfiMkp3v4w=="}] +0ms
  socket.io:socket dispatching an event ["scan",{"code":0,"url":"https://login.weixin.qq.com/qrcode/YfiMkp3v4w=="}] +0ms
VERB PuppetWebEvent onServerScan(0)
SILL PuppetWebBrowserCookie save() to file KBOT.wechaty.json
  socket.io-parser decoded 2["ding","heartbeat@browser"] as {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +3ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["ding","heartbeat@browser"]} +4ms
  socket.io:socket emitting event ["ding","heartbeat@browser"] +0ms
  socket.io:socket dispatching an event ["ding","heartbeat@browser"] +0ms
SILL PuppetWebEvent onServerDing(heartbeat@browser)
SILL PuppetWebWatchdog onFeed: 60000, HEARTBEAT[heartbeat@browser]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [120] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, HEARTBEAT:[heartbeat@browser])
SILL PuppetWebWatchdog monitorScan(HEARTBEAT)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 49 MB, require: 4 MB
  socket.io-parser decoded 2["log","recv ding"] as {"type":2,"nsp":"/","data":["log","recv ding"]} +3ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","recv ding"]} +2ms
  socket.io:socket emitting event ["log","recv ding"] +0ms
  socket.io:socket dispatching an event ["log","recv ding"] +0ms
VERB PuppetWebEvent onServerLog(recv ding)
SILL PuppetWebBrowserCookie save() saving 3 cookies: pgv_pvi,pgv_si,mm_lang
  socket.io-parser decoded 2["log","socket io lib loaded."] as {"type":2,"nsp":"/","data":["log","socket io lib loaded."]} +3ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","socket io lib loaded."]} +3ms
  socket.io:socket emitting event ["log","socket io lib loaded."] +0ms
  socket.io:socket dispatching an event ["log","socket io lib loaded."] +0ms
VERB PuppetWebEvent onServerLog(socket io lib loaded.)
  socket.io-parser decoded 2["log","connectSocket()"] as {"type":2,"nsp":"/","data":["log","connectSocket()"]} +1ms
  socket.io:socket got packet {"type":2,"nsp":"/","data":["log","connectSocket()"]} +1ms
  socket.io:socket emitting event ["log","connectSocket()"] +0ms
  socket.io:socket dispatching an event ["log","connectSocket()"] +0ms
VERB PuppetWebEvent onServerLog(connectSocket())
SILL PuppetWebBrowserCookie save() 3 cookies to KBOT.wechaty.json
SILL PuppetWebWatchdog onFeed: 60000, SCAN[[object Object]]
SILL StateMonitor Puppet:target() - live
SILL StateMonitor Puppet:inprocess() false
SILL PuppetWebWatchdog clearWatchDogTimer() [60] seconds left
SILL PuppetWebWatchdog setWatchDogTimer(60000, SCAN:[[object Object]])
SILL PuppetWebWatchdog monitorScan(SCAN)
SILL PuppetWebWatchdog autoSaveSession()
VERB PuppetWebWatchdog autoSaveSession() skiped as no this.userId
SILL PuppetWebWatchdog memoryCheck() free: 49 MB, require: 4 MB
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
                                                              
https://login.weixin.qq.com/qrcode/YfiMkp3v4w==
[0] Scan QR Code in above url to login: 
^CWechaty exit 130 because of SIGINT 
VERB Wechaty say(Wechaty exit 130 because of SIGINT )

➜  kbot git:(master) ✗ 

@huan
Copy link
Member

huan commented Dec 21, 2016

Hi @dcsan ,

It seems that you are run into issue #31

According to your log:

VERB PuppetWebBrowser open(https://wx.qq.com/zh_CN/htmledition/v2/images/webwxgeticon.jpg)
SILL PuppetWebBrowserCookie addCookies({"domain":".wechat.com","expiry":1482375002,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en_US"})
WARN PuppetWebBrowserCookie addCookies() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
ERR PuppetWebBrowserCookie load() add() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
VERB PuppetWebBrowser browser.loadSession(KBOT.wechaty.json) exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
VERB PuppetWebBrowser open(https://wx.qq.com)

It's obviously that you are using wechat.com, however, Wechaty did not recognize that and still using the wx.qq.com, which caused the cookie could not set back in the browser. As the result, you have to re-scan the Qr Code because you lost your cookies.

I thought this problem was solved by this commit: c78329e#diff-67759812817c700bf8e67907e5adffa6R183 , but there must be something wrong with that: It should use the hostname from cookies to open url in browser, which should be wechat.com in your case, but it return wx.qq.com by mistake.

I'll check it later, and you are welcome to review my code if you want to fix this faster. :)

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

adding from chat

please notice this two lines in the log:

  1. VERB PuppetWebBrowser open(https://wx.qq.com/zh_CN/htmledition/v2/images/webwxgeticon.jpg)
  2. SILL PuppetWebBrowserCookie addCookies({"domain":".wechat.com",

We need to keep the domain in 1st line(wx.qq.com) and the 2st line(.wechat.com) the same. If it is not, you will have to re-scan

BrowserCookie.hostname() should do that, but it's not. Code review is welcome at here: c78329e9dd1157e74614ae1d#diff-67759812817c700bf8e67907e5adffa6R183

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

when wechat sends me to web2.wechat.com

image

the PROFILE.wechaty.json seems to have cookies at the right domain?

[
  {
    "domain": ".wechat.com",
    "expiry": 1482378174,
    "httpOnly": false,
    "name": "mm_lang",
    "path": "/",
    "secure": false,
    "value": "en_US"
  },
  {
    "domain": ".wechat.com",
    "expiry": 1797694974,
    "httpOnly": false,
    "name": "webwx_auth_ticket",
    "path": "/",
    "secure": false,
    "value": "CIsBEKi.......RiYc="
  },

@huan
Copy link
Member

huan commented Dec 21, 2016

Yes, the cookie file should always right.

What we need to do when starting Wechaty, is to get hostname out of cookie file, and use that hostname in the browser to visit the webwxapp. If so, the cookie can be set back correctly, and session can be restored.

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

at wx.qq.com
image

the cookie file still has .wechat domain?

[
  {
    "domain": ".wechat.com",
    "expiry": 1482378174,
    "httpOnly": false,
    "name": "mm_lang",
    "path": "/",
    "secure": false,
    "value": "en_US"
  },
  {
    "domain": ".wechat.com",
    "expiry": 1797694974,
    "httpOnly": false,
    "name": "webwx_auth_ticket",
    "path": "/",
    "secure": false,
    "value": "CIsB....QyRiYc="
  },

@huan
Copy link
Member

huan commented Dec 21, 2016

Strange. The cookies should be saved to file right after user login, and will auto save to file every 5 minutes.

If the hostname in cookie is not the same as the url, there must something wrong.

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

hmm, deleted cookie file and now it seems to be updated to the right domain. maybe it's not getting overwritten properly somehow when the domain changes?

btw the domains are there before I login.

[
  {
    "domain": ".qq.com",
    "expiry": 2147385600,
    "httpOnly": false,
    "name": "pgv_pvi",
    "path": "/",
    "secure": false,
    "value": "1443930112"
  },
  {
    "domain": ".qq.com",
    "httpOnly": false,
    "name": "pgv_si",
    "path": "/",
    "secure": false,
    "value": "s4759231488"
  },
  {
    "domain": ".wx.qq.com",
    "expiry": 1482378961,
    "httpOnly": false,
    "name": "mm_lang",
    "path": "/",
    "secure": false,
    "value": "en"
  }
]

after I login I assume the rest will appear.
hmm i think the domain may change

@huan huan added the bug label Dec 21, 2016
@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

yes the domains change halfway

the QR code is presented at this domain:
https://wx.qq.com/

but after I scan it I am redirected here:
https://web2.wechat.com/

Could this maybe (possibly) be as I have an english OS?

In any case the cookies file has the right (final) domain:

[{"domain":".wechat.com","expiry":1482379153

@huan
Copy link
Member

huan commented Dec 21, 2016

Could you please post the full file here, with two different version of wx.qq.com and wechat.com?

I need them to write a unit test, thanks!

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

initial state

login is presented at wx.qq.com
before scanning QR code
(note I haven't prettified the JSON this is how it is written)

[{"domain":".qq.com","expiry":2147385600,"httpOnly":false,"name":"pgv_pvi","path":"/","secure":false,"value":"8512099328"},{"domain":".qq.com","httpOnly":false,"name":"pgv_si","path":"/","secure":false,"value":"s5248662528"},{"domain":".wx.qq.com","expiry":1482380243,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en"}]

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

after scanning the QRCode
I'm redirected to web2.wechat.com

cookies file

[{"domain":".wechat.com","expiry":1482380361,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en_US"},{"domain":".wechat.com","expiry":1797697161,"httpOnly":false,"name":"webwx_auth_ticket","path":"/","secure":false,"value":"CIsBEIW4yZYPGoABjgOYg33uUb4ct38aQsfT/zJ8FDNF8yKX4o4sJT7aVXjvBUjBLC/SXBj38TSCEmWsK8DME2FzDUl4kS2vXalfNnAFdScEuveH/h7T2CbHbvv5O4fDfxW2Olb5OQoWLrS61Wkx0XjghelAhyusVCGHiRVTtHaCx4gfyHk4+QyRiYc="},{"domain":".wechat.com","expiry":1797697161,"httpOnly":false,"name":"webwxuvid","path":"/","secure":false,"value":"e2108c64dbecd6ea0e3bc7a0266f467dcc63350fbc55559cdf6c25afd6f8bd88c7216d3aaec6427e41c2b918872bb549"},{"domain":".wechat.com","expiry":1482380361,"httpOnly":false,"name":"webwx_data_ticket","path":"/","secure":false,"value":"gScvXIoeHANgdX4Dq5kOjAGY"},{"domain":".wechat.com","httpOnly":false,"name":"pgv_si","path":"/","secure":false,"value":"s4528565248"},{"domain":".wechat.com","expiry":1482380361,"httpOnly":false,"name":"wxloadtime","path":"/","secure":false,"value":"1482337161"},{"domain":".wechat.com","expiry":1482380361,"httpOnly":false,"name":"wxsid","path":"/","secure":false,"value":"GURmztH40ijJuL3f"},{"domain":".wechat.com","expiry":2147385600,"httpOnly":false,"name":"pgv_pvi","path":"/","secure":false,"value":"6397004800"},{"domain":".wechat.com","expiry":1482380361,"httpOnly":false,"name":"wxuin","path":"/","secure":false,"value":"278208447"}]

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

If I quit and try to npm start again the domains are now reset correctly, temporarily

[{"domain":".qq.com","expiry":2147385600,"httpOnly":false,"name":"pgv_pvi","path":"/","secure":false,"value":"9658915840"},{"domain":".qq.com","httpOnly":false,"name":"pgv_si","path":"/","secure":false,"value":"s3164663808"},{"domain":".wx.qq.com","expiry":1482380491,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en"}]

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

FWIW I turned loglevel back to DEBUG and now I'm noticing a few of these:

INFO Wechaty v#git[4ed33d2 https://github.com/Microsoft/TypeScript/issues/9944 compact selenium-webdriver types v2, hope @types v3 will publish soon] initializing...
  bot:Grammar gram count 49 +106ms
WARN PuppetWebBrowserCookie addCookies() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)
ERR PuppetWebBrowserCookie load() add() exception: invalid cookie domain: invalid domain:".wechat.com"
  (Session info: chrome=55.0.2883.95)
  (Driver info: chromedriver=2.25.426935 (820a95b0b81d33e42712f9198c215f703412e1a1),platform=Mac OS X 10.12.1 x86_64)

@huan
Copy link
Member

huan commented Dec 21, 2016

@dcsan I just added some unit tests and a bug fix, could you have a try with the latest code?

Please pay attention to this part of the log output:

VERB PuppetWebBrowserCookie hostname()
VERB PuppetWebBrowserCookie getCookiesFromFile() from demo.wechaty.json
SILL PuppetWebBrowserCookie hostname() got web.wechat.com

VERB PuppetWebBrowser open(https://web.wechat.com/zh_CN/htmledition/v2/images/webwxgeticon.jpg)

SILL PuppetWebBrowserCookie addCookies({"domain":".wechat.com","expiry":1482380361,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en_US"})

This line: SILL PuppetWebBrowserCookie hostname() got web.wechat.com should match your cookie domain in cookie file.

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

Still requires login each time but the cookies seem to match.

QRCode is shown at web.wechat.com
PuppetWebBrowserCookie hostname() got web.wechat.com
and the cookies in the file (from last login) are also .wechat.com

So up to here things match. However, it's still needed to scan the QRCode every time.

After login we are redirected (now to web2.wechat.com - same domain but different subdomain) but this should be after login so not relevant.

details:

VERB PuppetWebBrowserCookie hostname()
VERB PuppetWebBrowserCookie getCookiesFromFile() from SOMENAME.wechaty.json
SILL PuppetWebBrowserCookie hostname() got web.wechat.com

VERB PuppetWebBrowser open(https://web.wechat.com/zh_CN/htmledition/v2/images/webwxgeticon.jpg)

SILL PuppetWebBrowserCookie addCookies({"domain":".wechat.com","expiry":1482386001,"httpOnly":false,"name":"mm_lang","path":"/","secure":false,"value":"en"})

Is it correct that I should stop the process with ctrl-C and then also "leave" the browser?

@dcsan
Copy link
Author

dcsan commented Dec 21, 2016

  1. Wechaty version: #git[890137b fix ci with browser.open() & hostname]
  2. Darwin x64 version 16.1.0 memory 197/8192 MB
  3. Docker: false
  4. Node version: v7.2.1

@huan
Copy link
Member

huan commented Dec 21, 2016

Wechaty will create a new browser on each time it starts. So the old browser will be never reused.

It seems hostname() works fine according to your log. If the cookies can be set back correctly, then you will no need to scan QR Code. If you are asked for the scan, then there must be other problems for your browser with wechat.com.

When I use Wechaty on wx.qq.com, most of the times the session can be restored, but there's still sometimes it not work as expected. Please let me know if you could find any clues of it, thanks.

@dcsan
Copy link
Author

dcsan commented Dec 22, 2016

For what it's worth, I noticed that on one account I use the problems are much worse than another.

  • problem account:
    only use from iPad
    100% requires to scan QRCode each time

  • OK account
    scan from iPhone
    30% requires scan QRCode

I can't think of any other differences.
They are both active accounts I use in many locations and devices.
Both iphone and ipad are set to english OS now.

trying to track what might be the issue.

@huan
Copy link
Member

huan commented Dec 28, 2016

Let's continue monitoring this problem.

Also, there's #57 might related to this one.

@huan
Copy link
Member

huan commented Aug 18, 2017

Did not hear from others about this issue.

Close for now.

@huan huan closed this as completed Aug 18, 2017
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