Stream reads blocking with Stream::handleData's fread

[slowbro]

Hello,

I ran into an interesting issue with this library when attempting to use Devristo/phpws and its builtin websocket client. When data is read from a stream using the Stream class' handleData function, reads seem to be blocking even though stream_set_blocking is called in __construct. I found that replacing line 121's fread with a stream_get_contents resolved my blocking reads issue. I feel like this class should be using the stream_ functions anyways - but it seems like a mix of f* and stream_ functions are used.

Is there a possibility a fix for this can be issued?

The only way I know to reproduce this involves a lot of steps and a specific product (Slack) and protocol (Hybi Websockets). I have tested that this issue exists on multiple boxes using PHP 5.5. I'll outline the steps to reproduce..

1. Sign up for a free Slack team here: https://slack.com/
2. Use the slack API doc site to 'test' the rtm.start call. This will give you a Websocket URL to connect to (must be used within 30 seconds, FYI). It's at the very bottom of the output. https://api.slack.com/methods/rtm.start/test
3. Connect using Devristo/phpws using the URL you got in step 2.

require_once("vendor/autoload.php");                // Composer autoloader

$loop = \React\EventLoop\Factory::create();

$logger = new \Zend\Log\Logger();
$writer = new Zend\Log\Writer\Stream("php://output");
$logger->addWriter($writer);

$client = new \Devristo\Phpws\Client\WebSocket("wss_url_here", $loop, $logger);

$client->on("request", function($headers) use ($logger){
    $logger->notice("Request object created!");
});

$client->on("handshake", function() use ($logger) {
    $logger->notice("Handshake received!");
});

$client->on("connect", function($headers) use ($logger, $client){
    $logger->notice("Connected!");
});

$client->on("message", function($message) use ($client, $logger){
    $logger->notice("Got message: ".$message->getData());
});

$client->open();
$loop->run();

4. Type messages on the Slack web client from one or more users. Note that your PHP app will always be one event behind because it it blocking until the next read comes in.

Again, I know this is kind of a weird example, but it's the only thing I've been using this lib for and I don't have another websocket service I can test. It may be related to how the websocket clients end their frames/lines and how fread expects them to end... I'm not completely sure.

Let me know if you need more information on this. I will be happy to provide what I can.

[slowbro]

FYI it looks like a similar issue was noted in reactphp/socket:

https://github.com/reactphp/socket/blob/master/src/Connection.php#L11-L13

In my fork, I have changed the fread to a stream_socket_revcfrom but unfortunately this caused the websocket connection to never complete. This specifically may be an issue with phpws, and not with stream.

Edit: Looks like stream_socket_revcfrom bypasses TLS/SSL filters and is returning encrypted data (which explains that..), so stream_get_* may be the only option in this sense.

[cboden]

What operating system are you running this on?

[slowbro]

This is on CentOS. I have tested it on 6.5 and 6.6.

[cboden]

First try taking your logger out. By default the STDOUT stream blocks. If your'e still having the issue next I'd suggest trying Pawl as your WebSocket client.

[slowbro]

I tried setting the logger to /dev/null instead of php://stdout, but I got the same result. Unfortunately phpws requires the logger. I'm pretty positive that it's not related to the logger.. the fread in Stream was what was hanging and confirmed by some crude debugging echos before and after it. Could STDOUT still cause that fread to block..?

In any case, Pawl looks nice.. I may end up going that route.

[slowbro]

Okay, I tested this with Pawl as well, completely removing my code and the logger except for a required API call to get the websocket URL. It still lags behind by one message..

$ ../bot.php test
Got message: {"type":"hello"}
Got message: {"type":"presence_change","user":"U03DL95FD","presence":"active"}
Got message: {"type":"user_typing","channel":"C02MJ52L8","user":"U029R8PCV"}
Got message: {"type":"message","channel":"C02MJ52L8","user":"U029R8PCV","text":"test","ts":"1422911582.000442","team":"x"}
Got message: {"type":"user_typing","channel":"C02MJ52L8","user":"U029R8PCV"}

class TestCommand extends CConsoleCommand {

    public function run($args){
        $slack = Slack\Slack::factory();
        $ws = $slack->startRtm();

        $loop = \React\EventLoop\Factory::create();
        $connector = new \Ratchet\Client\Factory($loop);

        $connector($ws)->then(function(\Ratchet\Client\WebSocket $conn) use ($slack){
            $slack->setClient($conn);
            $conn->on("message", function($message){
                echo "Got message: $message".PHP_EOL;
            });

        }, function ($e) use ($loop){
            echo "Could not connect: {$e->getMessage()}";
            $loop->stop();
        });

        $loop->run();
    }

}

As of the above, I had sent two messages: "test" and "test2". When using stream_get_contents these app appear instantly. When using fread, they do not show up until the next event JSON comes in from Slack. For example, 'test1' only came in because I started typing 'test2' and a user_typing event came in. After I had submitted 'test', the output was stopped at the first user_typing and would not move forward until I began typing again.

I hope that all makes sense.

[slowbro]

I took it even further and took Yii out of the loop as well. Just a bare test program using only Pawl and a url provided from argv..

<?php
require("protected/vendor/autoload.php");
$loop = \React\EventLoop\Factory::create();
$connector = new \Ratchet\Client\Factory($loop);

$connector($argv[1])->then(function(\Ratchet\Client\WebSocket $conn){
        $conn->on("message", function($message){
            echo "Got message: $message".PHP_EOL;
        });

        }, function ($e) use ($loop){
        echo "Could not connect: {$e->getMessage()}";
        $loop->stop();
});

$loop->run();

This, still, showed the same symptoms as phpws. If the fread is changed to a stream_get_contents, it works as expected - otherwise it blocks.

[cboden]

What's the output of composer show -i?

[slowbro]

$ composer show -i
cboden/ratchet           v0.3.2             PHP WebSocket library
evenement/evenement      v2.0.0             Événement is a very simple event dispatching library for PHP
guzzle/common            v3.9.2             Common libraries used by Guzzle
guzzle/http              v3.9.2             HTTP libraries used by Guzzle
guzzle/parser            v3.9.2             Interchangeable parsers used by Guzzle
guzzle/stream            v3.9.2             Guzzle stream wrapper component
ratchet/pawl             dev-master 3ba8d56 Asynchronous WebSocket client
react/cache              v0.4.0             Async caching.
react/dns                v0.4.1             Async DNS resolver.
react/event-loop         v0.4.1             Event loop abstraction layer that libraries can use for evented I/O.
react/promise            v2.2.0             A lightweight implementation of CommonJS Promises/A for PHP
react/socket             v0.4.2             Library for building an evented socket server.
react/socket-client      v0.4.2             Async connector to open TCP/IP and SSL/TLS based connections.
react/stream             v0.4.2             Basic readable and writable stream interfaces that support piping.
symfony/event-dispatcher v2.6.3             Symfony EventDispatcher Component
symfony/http-foundation  v2.6.3             Symfony HttpFoundation Component
symfony/routing          v2.6.3             Symfony Routing Component

This is in a brand new folder - only Pawl in composer.json.

[cboden]

Hmm, I was thinking it could have been an SSL bug we recently (thought) we fixed in socket-client...Can you try the same thing but without SSL by any chance?

[slowbro]

Unfortunately I can't get a ws:// for Slack.. they only give me wss :(

I tested with ws(s)://echo.websocket.org and it seems to work OK.. I $conn->send("hello!!"); before $conn->on('message' ...).

I don't know of anything else to test with; perhaps something more involved than an echo server. Do you have any ideas?

[slowbro]

For fun, I tested the Slack WSS URL with an external tester. I used the "Simple WebSocket Client" Chrome Extension, connected to the URL that Slack gave me, and did not observe this problem. There was no blocking, and messages came through A-OK.

[cboden]

In your vendor folder find this file/line - change the code to force wrapSecure be true. Does that solve the issue?

[slowbro]

Yep, that fixed the problem.

$ php -a
Interactive shell

php > echo PHP_VERSION_ID;
50520

$ rpm -qa | grep php
php-common-5.5.20-2.el6.remi.x86_64
php-mbstring-5.5.20-2.el6.remi.x86_64
php-phpunit-File-Iterator-1.3.4-5.el6.remi.noarch
php-symfony-class-loader-2.5.8-1.el6.remi.noarch
php-phpunit-PHPUnit-MockObject-2.3.0-1.el6.remi.noarch
php-process-5.5.20-2.el6.remi.x86_64
php-pecl-zip-1.12.4-1.el6.remi.5.5.x86_64
php-devel-5.5.20-2.el6.remi.x86_64
php-cli-5.5.20-2.el6.remi.x86_64
php-phpunit-Text-Template-1.2.0-4.el6.remi.noarch
php-phpunit-Version-1.0.4-1.el6.remi.noarch
php-phpunit-PHP-Timer-1.0.5-5.el6.remi.noarch
php-phpunit-diff-1.2.0-1.el6.remi.noarch
php-phpunit-exporter-1.0.2-1.el6.remi.noarch
php-symfony-yaml-2.5.8-1.el6.remi.noarch
php-phpunit-comparator-1.1.0-1.el6.remi.noarch
php-soap-5.5.20-2.el6.remi.x86_64
php-sebastian-global-state-1.0.0-1.el6.remi.noarch
php-phpunit-PHP-CodeCoverage-2.0.14-1.el6.remi.noarch
php-tidy-5.5.20-2.el6.remi.x86_64
php-pecl-jsonc-1.3.6-1.el6.remi.5.5.1.x86_64
php-pecl-jsonc-devel-1.3.6-1.el6.remi.5.5.1.x86_64
php-pdo-5.5.20-2.el6.remi.x86_64
php-phpunit-environment-1.2.1-1.el6.remi.noarch
php-doctrine-instantiator-1.0.3-1.el6.remi.noarch
php-symfony-common-2.5.8-1.el6.remi.noarch
php-phpunit-PHP-Invoker-1.1.3-6.el6.remi.noarch
php-phpunit-PHP-TokenStream-1.3.0-1.el6.remi.noarch
php-phpunit-PHPUnit-4.4.1-1.el6.remi.noarch
php-xml-5.5.20-2.el6.remi.x86_64
php-pear-1.9.5-3.el6.remi.noarch
php-mysqlnd-5.5.20-2.el6.remi.x86_64

Perhaps it's an issue with Remi's 5.5.20 build - or it affects this version too?

[cboden]

According to the latest comment the fix @DaveRandom applied has been reverted due to a bug that blocks connecting.

Until that's resolved (again) we'll have to remove that version check condition in SocketClient. I'll start work on that tonight after work.