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

Throw client read timeout earlier and don’t close connection #140

Merged
merged 2 commits into from
Jul 3, 2021

Conversation

marcroberts
Copy link
Contributor

PR to solve issue #139

When a timeout occurs on the client-side in the $client->receive() call this throws a TimeoutException earlier and keeps the connection open. This allows a PING to be sent to keep the connection alive if needed by the server.

@marcroberts
Copy link
Contributor Author

I'm happy to update this to put this behaviour behind an option if necessary

@sirn-se
Copy link
Contributor

sirn-se commented Jun 20, 2021

Hi @marcroberts , and thanks for contributing!

I have run some manual tests on this PR, and it appears to have an issue. What I did was to set a low timeout on client, and then a sleep() of higher value on the echoserver to provoke timeout fails in client. I then end up with the "Empty read; connection dead?" error instead.

As far as I can tell, the fread() call on line 444 will return empty string on timeout, not false as assumed in PR.

There's a comment in docs page that support this finding; https://www.php.net/manual/en/function.fread.php#115340

Besides this issue, I find your PR agreeable.

@marcroberts
Copy link
Contributor Author

marcroberts commented Jun 22, 2021

That is curious. I'm using my branch in a staging environment at the moment and it is behaving as expected returning FALSE when the fread() times out.

Here's my debug output when I set the client timeout to 5 seconds. I'm catching the TimeoutException and sending a PING

[2021-06-22 09:34:30] local.DEBUG: Wrote 519 of 519 bytes.
[2021-06-22 09:34:30] local.INFO: Client connected to wss://[REDACTED]
[2021-06-22 09:34:30] local.DEBUG: Wrote 25 of 25 bytes.
[2021-06-22 09:34:30] local.DEBUG: Sent 'text' frame {"opcode":"text","final":true,"content-length":19}
[2021-06-22 09:34:30] local.INFO: Sent 'text' message {"opcode":"text","content-length":19,"frames":1}
[2021-06-22 09:34:30] local.DEBUG: Read 2 of 2 bytes.
[2021-06-22 09:34:30] local.DEBUG: Read 63 of 63 bytes.
[2021-06-22 09:34:30] local.DEBUG: Read '{opcode}' frame {"opcode":"text","final":true,"content-length":63}
[2021-06-22 09:34:30] local.INFO: Received '{opcode}' message {"opcode":"text","content-length":63,"frames":1}
[2021-06-22 09:34:30] local.DEBUG: subscribe OK
[2021-06-22 09:34:36] local.ERROR: Client read timeout {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":true,"blocked":true,"eof":false,"stream_type":"tcp_socket/ssl","mode":"r+","unread_bytes":0,"seekable":false}
[2021-06-22 09:34:36] local.DEBUG: Wrote 6 of 6 bytes.
[2021-06-22 09:34:36] local.DEBUG: Sent 'ping' frame {"opcode":"ping","final":true,"content-length":0}
[2021-06-22 09:34:36] local.INFO: Sent 'ping' message {"opcode":"ping","content-length":0,"frames":1}
[2021-06-22 09:34:36] local.DEBUG: Read 2 of 2 bytes.
[2021-06-22 09:34:36] local.DEBUG: Read '{opcode}' frame {"opcode":"pong","final":true,"content-length":0}
[2021-06-22 09:34:36] local.DEBUG: Received 'pong'.
[2021-06-22 09:34:41] local.ERROR: Client read timeout {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":true,"blocked":true,"eof":false,"stream_type":"tcp_socket/ssl","mode":"r+","unread_bytes":0,"seekable":false}
[2021-06-22 09:34:41] local.DEBUG: Wrote 6 of 6 bytes.
[2021-06-22 09:34:41] local.DEBUG: Sent 'ping' frame {"opcode":"ping","final":true,"content-length":0}
[2021-06-22 09:34:41] local.INFO: Sent 'ping' message {"opcode":"ping","content-length":0,"frames":1}
[2021-06-22 09:34:41] local.DEBUG: Read 2 of 2 bytes.
[2021-06-22 09:34:41] local.DEBUG: Read '{opcode}' frame {"opcode":"pong","final":true,"content-length":0}
[2021-06-22 09:34:41] local.DEBUG: Received 'pong'.

Perhaps we should check for the timeout specifically before the FALSE / '' checks ?

@jeeinn jeeinn mentioned this pull request Jun 28, 2021
@sirn-se
Copy link
Contributor

sirn-se commented Jun 29, 2021

Have run some additional tests, but I get the same results as before.

These are the test files I'm running;

// File: test-server.php

<?php
namespace WebSocket;
require __DIR__ . '/vendor/autoload.php';
error_reporting(-1);

$server = new Server();
$server->setLogger(new EchoLog());

try {
    $server->accept();
    while (true) {
        $message = $server->receive();
        if (is_null($message)) exit; // Done
        echo "Server received $message \n";
        sleep(2);
        $server->text("Server responding on: $message");
    }
} catch (ConnectionException $e) {
    echo "> ERROR: {$e->getMessage()}\n";
}
// File: test-client.php

<?php
namespace WebSocket;
require __DIR__ . '/vendor/autoload.php';
error_reporting(-1);

try {
    $client = new Client('ws://localhost:8000', ['timeout' => 1]);
    $client->setLogger(new EchoLog());

    $client->text('Client message');
    $response = $client->receive();
    echo "Client received: $response \n";

    $client->close();

} catch (\Throwable $e) {
    echo "ERROR: {$e->getMessage()}\n";
}

Note the timeout of client is 1 and there is a sleep(2) before server responds.

The output of client is now;

info     | Client connected to ws://localhost/ 
debug    | Wrote 20 of 20 bytes. 
debug    | Sent 'text' frame {"opcode":"text","final":true,"content-length":14}
info     | Sent 'text' message {"opcode":"text","content-length":14,"frames":1}
error    | Empty read; connection dead? {"timed_out":true,"blocked":true,"eof":false,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false}
ERROR: Empty read; connection dead?

If I change so it checks empty string, I instead get;

debug    | Wrote 187 of 187 bytes. 
info     | Client connected to ws://localhost/ 
debug    | Wrote 20 of 20 bytes. 
debug    | Sent 'text' frame {"opcode":"text","final":true,"content-length":14}
info     | Sent 'text' message {"opcode":"text","content-length":14,"frames":1}
error    | Client read timeout {"timed_out":true,"blocked":true,"eof":false,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false}
ERROR: Client read timeout

Comparing to your log, above runs without SSL on local server. Maybe that's what causes the different results?

But yes, I suppose the stable solution is to check for timeout on falsish results, before the more explicit null/empty string checks.

@marcroberts
Copy link
Contributor Author

That is odd. I'll update the PR to check for a timeout on falsey response.

@sirn-se sirn-se merged commit 45be5ab into Textalk:master Jul 3, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants