G33kDude / Chrome.ahk

Automate Google Chrome using native AutoHotkey
https://autohotkey.com/boards/viewtopic.php?t=42890
MIT License
340 stars 83 forks source link

TIMEOUT on PageInstance.Call("Runtime.evaluate" #32

Open dbareis opened 2 years ago

dbareis commented 2 years ago

First of all this function and probably others should have a timeout to allow for exception handling, as it is this will fail in a loop after a variable number of loops, sometimes the first sometimes after 100 and sometimes not before 300 but it will fail (I'm searching for a selector that never exists for this test):

document.querySelector('#XbirthLabel') != null ? 'Exists' : 'Not Found';

The following code is basically from chrome.ahk with some debugging and the "timeout parameter":

;============================================================================
TEST_MyDbgEvaluate(PageInstance, JS)
;     https://chromedevtools.github.io/devtools-protocol/tot/Runtime/#method-evaluate
; RC: https://chromedevtools.github.io/devtools-protocol/tot/Runtime/#type-RemoteObject
;============================================================================
{
    MyDebug("TEST_DEBUG: PageInstance - Runtime.evaluate : BEFORE - timeout 5000ms (5 seconds)")
    response := PageInstance.Call("Runtime.evaluate",
                                        ( LTrim Join
                                            {
                                                "expression": JS,
                                                "objectGroup": "console",
                                                "includeCommandLineAPI": Chrome.Jxon_True(),
                                                "silent": Chrome.Jxon_False(),
                                                "returnByValue": Chrome.Jxon_False(),
                                                "userGesture": Chrome.Jxon_True(),
                                                "timeout":     2000,
                                                "awaitPromise": Chrome.Jxon_False()
                                            }
                                        ))
    MyDebug("TEST_DEBUG: PageInstance - Runtime.evaluate : AFTER")
    if  (response.exceptionDetails)
    {
        MyDebug("TEST_DEBUG: ######################### TIMEOUT ???????????? ##########################")
        throw Exception(response.result.description,, Chrome.Jxon_Dump(response.exceptionDetails))
    }

    MyDebug("TEST_DEBUG: PageInstance - Runtime.evaluate : RETURNING TO CALLER")
    return response.result

}

;===========================================================================================
TEST_MyBrowserElementExists(PageInstance, JsSelector, Dbg:=true)
;
; AtMemorialPage := MyBrowserElementExists(CreatePage, SaveToVirtCem, true)
;
; https://www.autohotkey.com/boards/viewtopic.php?t=88258
; SearchPage.WaitForLoad()
; ### NOTE ###
; "JsRc := PageInstance.Evaluate(Js).value" sometimes hangs
;===========================================================================================
{
    FoundIt    := "Exists"
    JavaScript := "document.querySelector('" . JsSelector . "') != null ? '" . FoundIt . "' : 'Not Found';"
    MyDebug("TEST_MyBrowserElementExists(): JS: " . JavaScript)
    MyDebugIndent()
        SetTimer, TimedOut_TEST_MyBrowserElementExists, 5000                 ;1 second should be way more than enough, use 5
            ;RemoteObject := PageInstance.Evaluate(JavaScript)
             RemoteObject := TEST_MyDbgEvaluate(PageInstance, JavaScript)
        SetTimer, TimedOut_TEST_MyBrowserElementExists, off
        JsRc         := RemoteObject.value
        if  (JsRc != FoundIt)
            JsRcTF := false       ;;Doesn't exist
        else
            JsRcTF := true
        MyDebug( "TEST_MyBrowserElementExists(), RC=" . JsRcTF . "(" . JsRc . "), JsSelector=" . JsSelector )
    MyDebugIndent(-1)
    return JsRcTF

The timeout parameter doesn't work. I can of course set a AHK timer and die (as the above code does) but I want the query to return false (or simply retry the call) on hang and the caller can then retry. Do I need some magic like "Chrome.Jxon_False()" to pass numbers?

I can't see how true or false is being passed in the following "chrome.ahk" code (but then I'm no AHK expert):

    Jxon_True()
    {
        static obj := {}
        return obj
    }

    Jxon_False()
    {
        static obj := {}
        return obj
    }
dbareis commented 2 years ago

To me this part of "chrome.ahk" code looks like a bug:

this.ws.Send(Chrome.Jxon_Dump({"id": ID ,  "params": Params ? Params : {},  "method": DomainAndMethod}))

            if !WaitForResponse
                return

            ; Wait for the response
            this.responses[ID] := False    ;Race condition? Could already have been set to "True"?
            while !this.responses[ID]
            {
                ;DB$ MyDebug("waiting 50ms...")
                Sleep, 50
            }

From what I can see (again no AHK expert):

  1. "this.ws.Send" sends the request
  2. A response returns ansyc somewhere and sets this.responses[ID] := True
  3. If waiting for a response you set "this.responses[ID] := False", What is to stop this already having been set async to True?

If I put a sleep() above "this.responses[ID] := False" it hangs every time supporting my theory....

dbareis commented 2 years ago

The following log shows the above race condition plus missing ID:

08:33:58.315    24140   AutoHotkey.exe  [AHK]:  TEST_MyBrowserElementExists(): JS: document.querySelector('#XbirthLabel') != null ? 'Exists' : 'Not Found';
08:33:58.346    24140   AutoHotkey.exe  [AHK]:       DB$:DEBUG: Response WITHOUT ID!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
08:33:58.362    24140   AutoHotkey.exe  [AHK]:       DB$:DEBUG: Response set to FALSE, wait loop starting
08:34:03.313    24140   AutoHotkey.exe  [AHK]:       TimedOut_TEST_MyBrowserElementExists() - TIMEOUT

This is the "chrome.ahk" code:

if this.responses.HasKey(data.ID)
{
    this.responses[data.ID] := data
    MyDebug("DB$:DEBUG: Response set for : " . data.ID)
}
else
{
    MyDebug("DB$:DEBUG: Response WITHOUT ID!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!")
}

Note that I also removed the "response set to false" logging as that would affect the timing, the ID is still missing as this log shows:

08:41:35.628    2632    AutoHotkey.exe  [AHK]:  TEST_MyBrowserElementExists(): JS: document.querySelector('#XbirthLabel') != null ? 'Exists' : 'Not Found';
08:41:35.658    2632    AutoHotkey.exe  [AHK]:       DB$:DEBUG: Response WITHOUT ID!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
08:41:37.279    2632    AutoHotkey.exe  [AHK]:       DB$:DEBUG: Response WITHOUT ID!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
08:41:40.626    2632    AutoHotkey.exe  [AHK]:       TimedOut_TEST_MyBrowserElementExists() - TIMEOUT

Also note that two responses were received! Although that may not matter, it appears that while the browser is up a ID-less response is received every 15 seconds. I don't know whether that is just while idle or if it could potentially interfere.

dbareis commented 2 years ago

A bit more work and debugging suggest a response does get received but it hasn't got an ID (according to "if this.responses.HasKey(data.ID)", yet it appears to contain it, here is some logging:

16:36:34.331    11292   AutoHotkey.exe  [AHK]:   ### DomainAndMethod: Runtime.evaluate
16:36:34.331    11292   AutoHotkey.exe  [AHK]:   ### Params         : 
16:36:34.331    11292   AutoHotkey.exe  [AHK]:   ### WaitForResponse: 1
16:36:34.331    11292   AutoHotkey.exe  [AHK]:   Waiting for a response...  Specified .call() timeout in ms: 2000
16:36:34.331    11292   AutoHotkey.exe  [AHK]:   Will wait for 40.000000 loops, each 50 ms
16:36:34.361    11292   AutoHotkey.exe  [AHK]:   DB$:DEBUG: Response WITHOUT ID!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
16:36:34.361    11292   AutoHotkey.exe  [AHK]:        EventName: Message
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        data DUMP: {
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | id
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | :252,     <+++++++ The ID?
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | result
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | :{
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | result
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | :{
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | type
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | :
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | string
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | ,
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | value
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | :
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | Not Found  <+++++++ My expected value
16:36:34.362    11292   AutoHotkey.exe  [AHK]:        | }}}
dbareis commented 2 years ago

OK, I now realise that it's looking for something to match the received ID, when it fails this.responses.Length() = 0 (empty). I

Following calls may log "this.responses.Length() = 56" There are at least 2 responses arrays. Possibly more as I have also seen it try to match against a shorter but non-zero array(maybe responses get deleted somewhere?)

I haven't worked out how to dump the contents yet (arbitrary objects) or even how the contents gets updated but while I'm still investigating I'm also writing my own timeout workaround.

LOG: 'this.responses[]' is of length = 0 (at send, then receive fails), also always 0 for poll-keep alive[getVersion].zip