search

Textalk / websocket-php

WebSocket client and server in PHP
Other
918 stars 253 forks source link

ConnectionException: Empty read; connection dead? #104

Closed mikebover closed 3 years ago

mikebover commented 3 years ago

Hello team,

Sometimes my php script receives the below ConnectionException message, once start to receive doesn't stops to receive it until I restart the script.

Nov 3 08:20:35 crypto php[36560]: Exception Error 0 =>>>>> WebSocket\ConnectionException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":false,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:349 Nov 3 08:20:35 crypto php[36560]: Stack trace: Nov 3 08:20:35 crypto php[36560]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 3 08:20:35 crypto php[36560]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 3 08:20:35 crypto php[36560]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 3 08:20:35 crypto php[36560]: #3 /var/www/html/prod/bitmex_get_data.php(329): WebSocket\Base->receive() Nov 3 08:20:35 crypto php[36560]: #4 {main} Nov 3 08:20:35 crypto php[36560]: 1025 Nov 3 08:20:35 crypto php[36560]: Exception Error 1 =>>>>> WebSocket\ConnectionException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":false,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:349 Nov 3 08:20:35 crypto php[36560]: Stack trace: Nov 3 08:20:35 crypto php[36560]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 3 08:20:35 crypto php[36560]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 3 08:20:35 crypto php[36560]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 3 08:20:35 crypto php[36560]: #3 /var/www/html/prod/bitmex_get_data.php(329): WebSocket\Base->receive() Nov 3 08:20:35 crypto php[36560]: #4 {main} Nov 3 08:20:35 crypto php[36560]: 1025 Nov 3 08:20:35 crypto php[36560]: Exception Error 2 =>>>>> WebSocket\ConnectionException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":false,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:349 Nov 3 08:20:35 crypto php[36560]: Stack trace: Nov 3 08:20:35 crypto php[36560]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 3 08:20:35 crypto php[36560]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 3 08:20:35 crypto php[36560]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 3 08:20:35 crypto php[36560]: #3 /var/www/html/prod/bitmex_get_data.php(329): WebSocket\Base->receive() Nov 3 08:20:35 crypto php[36560]: #4 {main} Nov 3 08:20:35 crypto php[36560]: 1025 Nov 3 08:20:35 crypto php[36560]: Exception Error 3 =>>>>> WebSocket\ConnectionException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":false,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:349 Nov 3 08:20:35 crypto php[36560]: Stack trace: Nov 3 08:20:35 crypto php[36560]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 3 08:20:35 crypto php[36560]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 3 08:20:35 crypto php[36560]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 3 08:20:35 crypto php[36560]: #3 /var/www/html/prod/bitmex_get_data.php(329): WebSocket\Base->receive() Nov 3 08:20:35 crypto php[36560]: #4 {main} Nov 3 08:20:35 crypto php[36560]: 1025

My code php is this:

$index_exception =0;

$client = new WebSocket\Client($ws_open_session);

while (true) {
    try {
        $message = $client->receive();
        // php code for inserting data to MySQL Database
        }
    catch (\WebSocket\ConnectionException $e) 
        {
        echo "Exception Error ".$index_exception++." =>>>>> ".$e."\n";
        $code = $e->getCode();
        print_r($code);
        echo "\n";
        }
}

I would like to be able to know why it is received the message with "timed_out":false,"blocked":true,"eof":true. I understand that message is caused because the server (in this case Bitmex exchange websocket service), sends a "eof":true to finish the conexion.

Is there any way to debug if it is received a PING message and not replyed?

Can anyone assist me to understand what is happening and how to solve it?

Best regards! Mike

sirn-se commented 3 years ago

It appears that the client expects there is data to read from the stream, but the stream is empty (and possibly closed).

You can attach a PSR-3 compatible logger to get some additional info on how things are handled. Beyond that it's very hard to debug these kind of errors, unfortunately.

mikebover commented 3 years ago

@sirn-se Thank you for your answer.

I'm so sorry but I have no idea about how to attach a PSR-3 compatible logger, please can you instruct me on how to do it?

Best regards! Mike

sirn-se commented 3 years ago

Attaching it is really easy;

$client = new WebSocket\Client($ws_open_session);
$client->setLogger($psr_logger);

Or do you mean your not familiar with the PSR standard interface for logging?

Monolog is a popular and competent PSR logger, but it might be a bit overkill just to get some dump output. What you could do is to attach a minimal echo logger;

class EchoLog implements \Psr\Log\LoggerInterface {
  use \Psr\Log\LoggerTrait;
  public function log($level, $message, array $context = []) {
    echo "[$level] $message \n";
  }
}

$client = new WebSocket\Client($ws_open_session);
$client->setLogger(new EchoLog());
mikebover commented 3 years ago

@sirn-se Thank you so much.

Now I can see a log like this:

Nov 4 12:29:05 crypto php[40479]: [info] Received 'text' message Nov 4 12:29:06 crypto php[40479]: [info] Received 'text' message Nov 4 12:29:06 crypto php[40479]: [info] Received 'text' message Nov 4 12:29:06 crypto php[40479]: [info] Received 'text' message Nov 4 12:29:07 crypto php[40479]: [info] Received 'text' message Nov 4 12:29:08 crypto php[40479]: [info] Received 'text' message Nov 4 12:29:08 crypto php[40479]: [info] Received 'text' message

I'm going to monitor it.

I will update the issue with the logs when I get the Exception message.

Best regards!

mikebover commented 3 years ago

Hello Team,

I have receives few messages of TimeoutException, in some cases with "eof":false, in which cases the connection was recovered and the Websocket did continue receiving data.

In other case the TimeoutException message had "eof":true and "Empty read; connection dead?", then the Websocket conexion was not recovered anymore and the TimeoutException message was repeated indefinitely.

See below the log messages summary:

Nov 4 12:59:58 crypto php[40479]: [info] Received 'text' message Nov 4 12:59:59 crypto php[40479]: [info] Received 'text' message Nov 4 12:59:59 crypto php[40479]: [info] Received 'text' message Nov 4 12:59:59 crypto php[40479]: [info] Received 'text' message Nov 4 13:00:04 crypto php[40479]: [warning] Broken frame, read 0 of stated 2 bytes. Nov 4 13:00:04 crypto php[40479]: Exception Error 0 =>>>>> WebSocket\TimeoutException: Broken frame, read 0 of stated 2 bytes. Stream state: {"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} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:343 Nov 4 13:00:04 crypto php[40479]: Stack trace: Nov 4 13:00:04 crypto php[40479]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(326): WebSocket\Base->throwException() Nov 4 13:00:04 crypto php[40479]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 4 13:00:04 crypto php[40479]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 4 13:00:04 crypto php[40479]: #3 /var/www/html/prod/bitmex_get_data.php(345): WebSocket\Base->receive() Nov 4 13:00:04 crypto php[40479]: #4 {main} Nov 4 13:00:04 crypto php[40479]: 1024 Nov 4 13:00:06 crypto php[40479]: [info] Received 'text' message Nov 4 13:00:06 crypto php[40479]: [info] Received 'text' message Nov 4 13:00:07 crypto php[40479]: [info] Received 'text' message Nov 4 13:00:07 crypto php[40479]: [info] Received 'text' message Nov 4 13:00:07 crypto php[40479]: [info] Received 'text' message

Nov 4 14:14:40 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:40 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:41 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:42 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:47 crypto php[40479]: [warning] Broken frame, read 0 of stated 2 bytes. Nov 4 14:14:47 crypto php[40479]: Exception Error 1 =>>>>> WebSocket\TimeoutException: Broken frame, read 0 of stated 2 bytes. Stream state: {"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} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:343 Nov 4 14:14:47 crypto php[40479]: Stack trace: Nov 4 14:14:47 crypto php[40479]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(326): WebSocket\Base->throwException() Nov 4 14:14:47 crypto php[40479]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 4 14:14:47 crypto php[40479]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 4 14:14:47 crypto php[40479]: #3 /var/www/html/prod/bitmex_get_data.php(345): WebSocket\Base->receive() Nov 4 14:14:47 crypto php[40479]: #4 {main} Nov 4 14:14:47 crypto php[40479]: 1024 Nov 4 14:14:48 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:48 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:48 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:48 crypto php[40479]: [info] Received 'text' message Nov 4 14:14:49 crypto php[40479]: [info] Received 'text' message

Nov 5 00:23:49 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:50 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:50 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:50 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:50 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:50 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:50 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:51 crypto php[40479]: [info] Received 'text' message Nov 5 00:23:51 crypto php[40479]: [warning] Empty read; connection dead? Nov 5 00:23:51 crypto php[40479]: Exception Error 2 =>>>>> WebSocket\TimeoutException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":true,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:343 Nov 5 00:23:51 crypto php[40479]: Stack trace: Nov 5 00:23:51 crypto php[40479]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 5 00:23:51 crypto php[40479]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 5 00:23:51 crypto php[40479]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 5 00:23:51 crypto php[40479]: #3 /var/www/html/prod/bitmex_get_data.php(345): WebSocket\Base->receive() Nov 5 00:23:51 crypto php[40479]: #4 {main} Nov 5 00:23:51 crypto php[40479]: 1024 Nov 5 00:23:51 crypto php[40479]: [warning] Empty read; connection dead? Nov 5 00:23:51 crypto php[40479]: Exception Error 3 =>>>>> WebSocket\TimeoutException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":true,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:343 Nov 5 00:23:51 crypto php[40479]: Stack trace: Nov 5 00:23:51 crypto php[40479]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 5 00:23:51 crypto php[40479]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 5 00:23:51 crypto php[40479]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 5 00:23:51 crypto php[40479]: #3 /var/www/html/prod/bitmex_get_data.php(345): WebSocket\Base->receive() Nov 5 00:23:51 crypto php[40479]: #4 {main} Nov 5 00:23:51 crypto php[40479]: 1024 Nov 5 00:23:51 crypto php[40479]: [warning] Empty read; connection dead? Nov 5 00:23:51 crypto php[40479]: Exception Error 4 =>>>>> WebSocket\TimeoutException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":true,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:343 Nov 5 00:23:51 crypto php[40479]: Stack trace: Nov 5 00:23:51 crypto php[40479]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 5 00:23:51 crypto php[40479]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 5 00:23:51 crypto php[40479]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 5 00:23:51 crypto php[40479]: #3 /var/www/html/prod/bitmex_get_data.php(345): WebSocket\Base->receive() Nov 5 00:23:51 crypto php[40479]: #4 {main} Nov 5 00:23:51 crypto php[40479]: 1024 Nov 5 00:23:51 crypto php[40479]: [warning] Empty read; connection dead? Nov 5 00:23:51 crypto php[40479]: Exception Error 5 =>>>>> WebSocket\TimeoutException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":true,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:343 Nov 5 00:23:51 crypto php[40479]: Stack trace: Nov 5 00:23:51 crypto php[40479]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 5 00:23:51 crypto php[40479]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 5 00:23:51 crypto php[40479]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 5 00:23:51 crypto php[40479]: #3 /var/www/html/prod/bitmex_get_data.php(345): WebSocket\Base->receive() Nov 5 00:23:51 crypto php[40479]: #4 {main} Nov 5 00:23:51 crypto php[40479]: 1024 Nov 5 00:23:51 crypto php[40479]: [warning] Empty read; connection dead? Nov 5 00:23:51 crypto php[40479]: Exception Error 6 =>>>>> WebSocket\TimeoutException: Empty read; connection dead? Stream state: {"crypto":{"protocol":"TLSv1.2","cipher_name":"ECDHE-RSA-AES128-GCM-SHA256","cipher_bits":128,"cipher_version":"TLSv1.2"},"timed_out":true,"blocked":true,"eof":true,"stream_type":"tcp_socket\/ssl","mode":"r+","unread_bytes":0,"seekable":false} in /var/www/html/prod/vendor/textalk/websocket/lib/Base.php:343 Nov 5 00:23:51 crypto php[40479]: Stack trace: Nov 5 00:23:51 crypto php[40479]: #0 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(329): WebSocket\Base->throwException() Nov 5 00:23:51 crypto php[40479]: #1 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(177): WebSocket\Base->read() Nov 5 00:23:51 crypto php[40479]: #2 /var/www/html/prod/vendor/textalk/websocket/lib/Base.php(166): WebSocket\Base->receiveFragment() Nov 5 00:23:51 crypto php[40479]: #3 /var/www/html/prod/bitmex_get_data.php(345): WebSocket\Base->receive() Nov 5 00:23:51 crypto php[40479]: #4 {main} Nov 5 00:23:51 crypto php[40479]: 1024

Can anyone explainme what happens and how to handle it?

Have I to close the current connexion with $client->close() and then create a new one with $client = new WebSocket\Client($ws_open_session) as it is at the begining of the php code?

Would the below php code be correct?

What it does in case EOF is true, is a $client->close() and then a "goto" to the beginning to open a new Websocket connection.


open_WebSocket_connection:  

$index_exception =0;

$client = new WebSocket\Client($ws_open_session);

while (true) {
    try {
        $message = $client->receive();
        // php code for inserting data to MySQL Database
        }
    catch (\WebSocket\ConnectionException $e) 
        {
        echo "Exception Error ".$index_exception++." =>>>>> ".$e."\n";
        $code = $e->getCode();
        print_r($code);
        echo "\n";

        $exception_message = $e->getMessage();
        echo "Exception Message:"."\n";
        print_r($exception_message);
        echo "\n";

        $json_begin=strpos($exception_message, '{');
        $exception_message_json=substr($exception_message,$json_begin);

        $exception_message_array = json_decode($exception_message_json, true);

        if ($exception_message_array['eof'])
            {
                $client->close();
                goto open_WebSocket_connection;
            }   

        }
}

Best regards! Mike

sirn-se commented 3 years ago

The first batches work as intended, getting a timeout and restarting. You can specify a higher timeout value to reduce this, default timeout is only 5 seconds. You can add your own value as an option to the constructor.

The last batch is more of a problem. It appears as the stream is "half open", considered by the client to be usable but in reality is not. With your dump I can simulate and investigate this, see if we can fix that in some way.