Conflict between await and execute command

[slava-vishnyakov]

First of all - thanks for the wonderful package!

Second, i think there is a flaw in how the messages are handled if you use callbacks and call another method from within a callback.. The bug is tricky, because it depends on the ordering of the messages between client and server, so it takes a few runs to catch it.

Relevant parts:

$ctx = Context::withTimeout(Context::background(), 30 /* seconds */);

Launcher::$defaultArgs = []; // run not headless -- bug happens often this way

...

$devtools->network()->enable(...);

$devtools->network()->addLoadingFinishedListener(function ($e) ... {
    $request = GetResponseBodyRequest::builder()->setRequestId($e->requestId)->build();
    $devtools->network()->getResponseBody($ctx, $request);
});

$pageDomain = $devtools->page();
$pageDomain->enable($ctx);
$url = 'https://www.google.com';
$pageDomain->navigate($ctx, NavigateRequest::builder()->setUrl($url)->build());
$pageDomain->awaitLoadEventFired($ctx);

What I expect this program to do:
to finish without timeout

What happens:
in some percentage of cases (50%?) it ends with a timeout on awaitLoadEventFired

The full source is here https://gist.github.com/slava-vishnyakov/057d2dfb0b9b1bad878130c9607e3179

Ok, so now we have something like this:

1. awaitLoadEventFired loops handleMessage waiting for Page.loadEventFired
2. at the same time we have a stream of incoming Network.loadingFinished messages, which trigger a callback, which then calls for getResponseBody method
3. (which starts another loop) and
4. occasionally Page.loadEventFired happens to be in this getReponseBody loop, not in awaitLoadEventFired and therefore awaitLoadEventFired never sees this Page.loadEventFired event.

I've added a few debug prints to see this:

So as I understand it, it goes like this:

awaitLoadEventFired (waiting for event YYY)
  -> awaitLoadEventFired calls handleMessage
      <- event which has a callback
    -> handleMessage sees there is a callback, calls callback
      -> callback calls executeCommand
        -> executeCommand calls handleMessage (waiting for command result)
        -> executeCommand calls handleMessage (waiting for command result)
           <- event YYY  (handleMessage is not interested, since it waits for command result)
           <- command result
        -> returns result
      -> callback ends
  we are back at awaitLoadEventFired loop, maybe there are more events, maybe not
  -> calls handleMessage

So, the fix should be something like "if we are awaiting for something and deep handleMessage gets it - we need to "bubble" it somehow"..

The problem gets deeper, since a callback might call executeCommand, which will trigger a callback, which will trigger another callback, which might call another executeCommand..

-> await XX
  -> callback
    -> executeCommand
      -> (in callback, calls await..)
         -> await XX
           -> callback
             -> executeCommand
                <-- XX happens
                <-- other XX happens

So, basically we can't have something like a $this->await[$method] = {null | XX_Response}, we need something more clever, which will say that we have 2 awaits upstream waiting for XX

So, my first stab at the fix (quite a bit ugly, but I don't know how to express it better):

(noticed that in this version I have $this->awaits -- it should be $this->awaitMethods, this is corrected in code below)

Basically we have two new instance variables - the number of awaits upstream waiting for particular method ($awaitMethods (naming is hard... $methodAwaitersCount ? :) )) and responses for those ($awaitMessages).

Now, when we enter handleMessage - we look whether there is an await upstream for this method. If there is - we don't process it and store to $awaitMessages variable..

After we return from callback - we look if there is a message for this method stored for us. If there is - we decrement the number of "awaiters" and return the message..

The new handleMessage:

private $awaitMethods = [];
private $awaitMessages = [];

private function handleMessage($message, ?string $returnIfEventMethod = null)
{
	if (isset($message->error)) {
		throw new ErrorException($message->error->message, $message->error->code);

	} else if (isset($message->method)) {
		if (isset($this->awaitMethods[$message->method]) && $this->awaitMethods[$message->method] > 0) {
			$this->awaitMessages[$message->method] [] = $message;

			return null;
		}

		if (isset($this->listeners[$message->method])) {
			if ($returnIfEventMethod !== null) {
				// add this method to await notifications (increment)
				if (!isset($this->awaitMethods[$returnIfEventMethod])) {
					$this->awaitMethods[$returnIfEventMethod] = 1;
				} else {
					$this->awaitMethods[$returnIfEventMethod]++;
				}
			}

			foreach ($this->listeners[$message->method] as $callback) {
				$callback($message->params);
			}

			if ($returnIfEventMethod !== null && count($this->awaitMessages[$returnIfEventMethod]) > 0) {
				// handleMessage inside callback got the message, take the first message from responses
				$message = array_shift($this->awaitMessages[$returnIfEventMethod]);
				// we are not waiting for this message anymore
				$this->awaitMethods[$returnIfEventMethod]--;

				return $message;
			}
		}

		if ($returnIfEventMethod !== null && $message->method === $returnIfEventMethod) {
			return $message;
		} else {
			if (!isset($this->eventBuffers[$message->method])) {
				$this->eventBuffers[$message->method] = [];
			}
			array_push($this->eventBuffers[$message->method], $message);
		}

	} else if (isset($message->id)) {
		$this->commandResults[$message->id] = $message->result ?? new \stdClass();

	} else {
		throw new RuntimeException(sprintf(
			"Unhandled message: %s",
			json_encode($message, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE)
		));
	}

	return null;
}

[slava-vishnyakov]

Ok, this got sent accidentally too early, I'll fix the formatting now.. (Fixed).

[slava-vishnyakov]

I don't attach a Pull Request - your code is beautiful and surely you can write a better solution based on the idea.

Thank you for a package!

[slava-vishnyakov]

Just noticed, this probably should be moved:

[jakubkulhan]

Hi, thank you for the thorough examination of the problem.

Both DevtoolsClient & Session use similar pattern with eventBuffers & commandResults - and if you do not await any other event in listener callback, the event received while executing command in callback should be buffered and returned afterwards.

I think what the fix should do is to create "scopes" of eventBuffers & commandResults before executing listener's code. I'll try to look into that soon.

[holgerk]

Hello, thx for the great project.
I think i have found a simple solution for this issue:
#20
What do you think?