hhvm/hsl-experimental

[Network] $socket->readAsync() blocks when there's no more data to read.

azjezz opened this issue · 13 comments

azjezz commented

code :

<<__EntryPoint>>
async function main(): Awaitable<void> {
  $server = await TCP\Server::createAsync(
    Network\IPProtocolVersion::IPV4,
    '127.0.0.1',
    '0',
  );
  
  $address = $server->getLocalAddress();
  echo 'Listening on http://'.$address[0].$address[1]."\n";

  while(true) {
    $connection = await $server->nextConnectionNDAsync();
    $statusLine = $connection->readLineAsync();
    $headers = '';
    do {
      $line = await $connection->readLineAsync();
      $headers .= $line;
    } while($line !== "\r\n");   
    
	\var_dump($statusLine, $headers);
    // attempt to read body ?

    // the following blocks : 
    // read always returns empty string ''
    // isEndOfFile always returns false, nothing is going to stop the loop
    $body = await $connection->readAsync(); //

    // the following blocks : 
    // read always returns empty string ''
    // isEndOfFile always return false
    // timeout exception is not thrown ?
    $body = await $connection->readAsync(null, 0.1);
     
    await $connection->writeAsnyc("HTTP/1.1 200 OK
Connection: close
X-Powered-By: HHVM

Hello");

    await $connection->closeAsync();
  }
}

start the server :

$ hhvm server.hack

attempt to send a get request to the server ( simply by visiting the shown url in the browser )

azjezz commented

currently, i'm using a "hack" around this :

namespace Nuxed\Http\Server\_Private;

use namespace HH\Lib\Experimental\OS;
use namespace HH\Lib\Async;
use namespace HH\Asio;

async function timeout<T>(Awaitable<T> $task, float $seconds): Awaitable<T> {
  $usecs = (int)(1000000 * $seconds);
  $poll = Async\KeyedPoll::create();
  $poll->add('sleep', SleepWaitHandle::create($usecs));
  $poll->add('task', $task);

  foreach ($poll await as $key => $value) {
    if ($key === 'sleep') {
      throw new OS\TimeoutError('Task timeout.');
    } else {
      /* HH_IGNORE_ERROR[4110] */
      return $value;
    }
  }

  return await $task;
}

later :

$body = Server\_Private\timeout($connection->readAsync($chunkSize), $timeout);
fredemmott commented 
    // the following blocks : 
    // read always returns empty string ''
    // isEndOfFile always returns false, nothing is going to stop the loop
    $body = await $connection->readAsync(); //

If the connection is still open, this is acting as documented.

    // the following blocks : 
    // read always returns empty string ''
    // isEndOfFile always return false
    // timeout exception is not thrown ?
    $body = await $connection->readAsync(null, 0.1);

If nothing strange is going on, this is likely a bug

fredemmott commented

What do you get for this case?

use namespace HH\Lib\Experimental\{TCP, Network};

async function server(TCP\Server $server): Awaitable<void> {
  await using $conn = await $server->nextConnectionAsync();
  $line = await $conn->readLineAsync();
  \var_dump('server read line: '.$line);
  $t = microtime(true);
  try {
    $rest = await $conn->readAsync(null, 0.1);
  } finally {
    $elapsed = microtime(true) - $t;
    \var_dump('server left readAsync after '.$elapsed.' seconds');
  }
  \var_dump('server read rest: '.$rest);
}

async function client(int $port): Awaitable<void> {
  await using $conn = await TCP\connect_async('127.0.0.1', $port);
  await $conn->writeAsync("Hello, world\n");
  \var_dump('client sleeping for 1s');
  await \HH\Asio\usleep(1000 * 1000);
  \var_dump('client slept for 1s');
}

<<__EntryPoint>>
async function main(): Awaitable<void> {
  require_once('vendor/autoload.hack');
  \Facebook\AutoloadMap\initialize();

  $server = await TCP\Server::createAsync(
    Network\IPProtocolVersion::IPV4,
    '127.0.0.1',
    0
  );

  list($_, $port) = $server->getLocalAddress();

  concurrent {
    await server($server);
    await client($port);
  };

  \var_dump('End of program');
}

On MacOS Catalina and Ubuntu 18.04, I'm getting:

string(22) "client sleeping for 1s"
string(31) "server read line: Hello, world
"
string(52) "server left readAsync after 0.15044164657593 seconds"
string(19) "client slept for 1s"

Fatal error: Uncaught exception 'HH\Lib\Experimental\OS\TimeoutError' with message 'HH\Lib\Experimental\IO\_Private\LegacyPHPResourceReadHandleTrait::readAsync' in /test/vendor/hhvm/hsl-experimental/src/os/_Private/Errno.php:234

This shows the timeout happening at the correct point - the finally block executes after ~ 0.1s, while the client is still sleeping.

If you have the same behavior, are you able to change it into an isolated example showing the problem?

fredemmott commented

$body = await $connection->readAsync(null, 0.1);

It would also be useful to add the microtime/try/finally stuff from my example around this part of your example

azjezz commented

On MacOS Catalina and Ubuntu 18.04, I'm getting:

same ( ubuntu )

but in this case :

use namespace HH\Lib\Experimental\{TCP, Network};

async function server(TCP\Server $server): Awaitable<void> {
  $conn = await $server->nextConnectionNDAsync();
  while (true) {
    $t = microtime(true);

    try {
      $rest = await $conn->readAsync(null, 0.1);
    } catch (OS\TimeoutException $e) {
      \var_dump('timeout');
    } finally {
      $elapsed = microtime(true) - $t;
      \var_dump('server left readAsync after '.$elapsed.' seconds');
    }

    \var_dump('server read: '.$rest);
  }
}

async function client(int $port): Awaitable<void> {
  $conn = await TCP\connect_nd_async('127.0.0.1', $port);
  while (true) {
    await $conn->writeAsync("Hello, world\n");
    \var_dump('client sleeping for 1s');
    await \HH\Asio\usleep(1000 * 1000);
    \var_dump('client slept for 1s');
  }
}

<<__EntryPoint>>
async function main(): Awaitable<void> {
  require_once('vendor/autoload.hack');
  \Facebook\AutoloadMap\initialize();

  $server = await TCP\Server::createAsync(
    Network\IPProtocolVersion::IPV4,
    '127.0.0.1',
    0,
  );

  list($_, $port) = $server->getLocalAddress();

  concurrent {
    await server($server);
    await client($port);
  }
  ;

  \var_dump('End of program');
}

you see :

string(22) "client sleeping for 1s"
string(52) "server left readAsync after 0.17155075073242 seconds"
string(19) "client slept for 1s"
string(22) "client sleeping for 1s"
string(19) "client slept for 1s"

and it hangs in there, what is weird is that \var_dump('server left readAsync after '.$elapsed.' seconds'); is reached, but not timeout or \var_dump('server read: '.$rest);

fredemmott commented 
`} catch (OS\TimeoutException $e) {`

It's TimeoutError, not Exception; can you check that's what you are using?

If correcting that doesn't work, can you catch \Throwable and dump \get_class() of the exception?

and it hangs in there

Expected: the looped writeAsync hangs until write succeeds, or timeout is hit - and there's no timeout. Once the server's buffers are full enough, it's not going to be willing to queue up more reads, and given the server's thrown an uncaught exception, it's not reading it.

fredemmott commented

Also check that you have use namespace HH\Lib\Experimental\OS at the top/run the typechecker :)

  • 👍1
azjezz commented

that works, but :

string(22) "client sleeping for 1s"
string(7) "timeout"
string(35) "HH\Lib\Experimental\OS\TimeoutError"
string(52) "server left readAsync after 0.17977809906006 seconds"
string(13) "server read: "
string(19) "client slept for 1s"
string(22) "client sleeping for 1s"
string(7) "timeout"
string(35) "HH\Lib\Experimental\OS\TimeoutError"
string(52) "server left readAsync after 0.90896153450012 seconds"
string(13) "server read: "
string(19) "client slept for 1s"
string(22) "client sleeping for 1s"
string(7) "timeout"
string(35) "HH\Lib\Experimental\OS\TimeoutError"
string(52) "server left readAsync after 0.99659657478333 seconds"
string(13) "server read: "
string(19) "client slept for 1s"
string(22) "client sleeping for 1s"
string(7) "timeout"
string(35) "HH\Lib\Experimental\OS\TimeoutError"
string(51) "server left readAsync after 1.0006637573242 seconds"
string(13) "server read: "
string(19) "client slept for 1s"
string(22) "client sleeping for 1s"
string(7) "timeout"
string(35) "HH\Lib\Experimental\OS\TimeoutError"
string(52) "server left readAsync after 0.99992060661316 seconds"
string(13) "server read: "
string(19) "client slept for 1s"
string(22) "client sleeping for 1s"
string(7) "timeout"
string(35) "HH\Lib\Experimental\OS\TimeoutError"
string(50) "server left readAsync after 1.000298500061 seconds"
string(13) "server read: "

the timeout is 0.1, the server leaves readAsync after 1.x ( except for the first read ? )

azjezz commented

also why is the server throwing a time exception here if there's data ?

use namespace HH\Lib\Experimental\{TCP, Network};

async function server(TCP\Server $server): Awaitable<void> {
  $conn = await $server->nextConnectionNDAsync();
  while (true) {
    $t = microtime(true);
    $rest = '';

    try {
      $rest = await $conn->readAsync(null, 0.1);
    } catch (\Throwable $e) {
      \var_dump('timeout');
    } finally {
      $elapsed = microtime(true) - $t;
      \var_dump('server left readAsync after '.$elapsed.' seconds');
    }

    if ('' !== $rest) {
      \var_dump('server read: '.$rest);
    }
  }
}

async function client(int $port): Awaitable<void> {
  $conn = await TCP\connect_nd_async('127.0.0.1', $port);
  while (true) {
    await $conn->writeAsync("Hello, world\n");
    \var_dump('client sleeping for 1s');
    await \HH\Asio\usleep(1000 * 1000);
    \var_dump('client slept for 1s');
  }
}

<<__EntryPoint>>
async function main(): Awaitable<void> {
  require_once('vendor/autoload.hack');
  \Facebook\AutoloadMap\initialize();

  $server = await TCP\Server::createAsync(
    Network\IPProtocolVersion::IPV4,
    '127.0.0.1',
    0,
  );

  list($_, $port) = $server->getLocalAddress();

  concurrent {
    await server($server);
    await client($port);
  }
  ;

  \var_dump('End of program');
}

-> client writing
-> server attempts read -> no data -> throws timeout
-> client already written data to the server, and going in a loop writing more
-> server keeps on throwing timeout exception every time

fredemmott commented

also why is the server throwing a time exception here if there's data ?

/** Read until we reach $max_bytes, or the end of the file. */

Probably needs clarifying that $max_bytes = null means 'no limit', not 'whatever is available'

fredemmott commented

perhaps we need a readNextAsync or similar.

  • 👍1
azjezz commented

i was able to replicate the issue : ( readAsync hangs , exception not thrown )

there's no way to tell if there's more data to read :( an exception should be thrown in this case :

use namespace HH\Lib\Experimental\{TCP, Network};

async function server(TCP\Server $server): Awaitable<void> {
  $conn = await $server->nextConnectionNDAsync();
  while (true) {
    \var_dump('+');
    $t = microtime(true);
    $rest = '';

    try {
      \var_dump('reading :)');
      $rest = await $conn->readAsync(1, 0.1);
    } catch (\Throwable $e) {
      \var_dump('timeout');
    } finally {
      $elapsed = microtime(true) - $t;
      \var_dump('server left readAsync after '.$elapsed.' seconds');
    }
    
    \var_dump('~');

    if ('' !== $rest) {
      \var_dump('server read: '.$rest);
    }
  }
}

async function client(int $port): Awaitable<void> {
  $conn = await TCP\connect_nd_async('127.0.0.1', $port);
  await $conn->writeAsync("hello, world!");
  \var_dump('gave the server some data, now going in a loop :)');
  while (true) {
    await \HH\Asio\later();
  }
}

<<__EntryPoint>>
async function main(): Awaitable<void> {
  require_once('vendor/autoload.hack');
  \Facebook\AutoloadMap\initialize();

  $server = await TCP\Server::createAsync(
    Network\IPProtocolVersion::IPV4,
    '127.0.0.1',
    0,
  );

  list($_, $port) = $server->getLocalAddress();

  concurrent {
    await server($server);
    await client($port);
  }
  ;

  \var_dump('End of program');
}

output :

string(1) "+"
string(10) "reading :)"
string(49) "gave the server some data, now going in a loop :)"
string(53) "server left readAsync after 0.093807458877563 seconds"
string(1) "~"
string(14) "server read: h"
string(1) "+"
string(10) "reading :)"
string(53) "server left readAsync after 0.002147912979126 seconds"
string(1) "~"
string(14) "server read: e"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 1.2397766113281E-5 seconds"
string(1) "~"
string(14) "server read: l"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 9.0599060058594E-6 seconds"
string(1) "~"
string(14) "server read: l"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 5.2452087402344E-6 seconds"
string(1) "~"
string(14) "server read: o"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 6.1988830566406E-6 seconds"
string(1) "~"
string(14) "server read: ,"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 6.4373016357422E-6 seconds"
string(1) "~"
string(14) "server read:  "
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 6.1988830566406E-6 seconds"
string(1) "~"
string(14) "server read: w"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 6.1988830566406E-6 seconds"
string(1) "~"
string(14) "server read: o"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 6.1988830566406E-6 seconds"
string(1) "~"
string(14) "server read: r"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 5.4836273193359E-6 seconds"
string(1) "~"
string(14) "server read: l"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 6.1988830566406E-6 seconds"
string(1) "~"
string(14) "server read: d"
string(1) "+"
string(10) "reading :)"
string(54) "server left readAsync after 5.9604644775391E-6 seconds"
string(1) "~"
string(14) "server read: !"
string(1) "+"
string(10) "reading :)"
fredemmott commented

hphpd shows that a tiny timeout is being passed to stream_await(), and HHVM is not respecting it.

In my case, this ends up being a timeout of ~ 0.00090441703796387, which is ~ 0.9ms

A timeout of < 1ms is equivalent to 0, which is no timeout: https://github.com/facebook/hhvm/blob/91be13e14afb076330bfc10ca179aae773921b9e/hphp/runtime/base/file-await.cpp#L30