Pawl closing connection with code 1006 instead of 1000

[ghost]

When I try to close the websocket connection with a close code 1000 (close normal), then Pawl instead disconnects with a close code 1006 (close abnormal). I've found this issue while fiddling with the Discord API and the bot account still stayed online as opposed of showing as offline. So I've fiddled a simple Node.js websocket server which dumps the close code.

PHP code:

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

$connector = new \Ratchet\Client\Connector($loop);
$connector('ws://localhost:8080')->done(function (\Ratchet\Client\WebSocket $conn) use ($loop) {
    $conn->on('message', function ($message) {
        var_dump($message);
    });
    $conn->on('close', function (...$args) {
        var_dump($args);
    });
    
    $loop->addTimer(10, function () use ($conn) {
        echo 'Closing WS'.PHP_EOL;
        $conn->close();
    });
});

$loop->run();

JS code:

const { Server } = require('ws');
const wss = new Server({ port: 8080 });

wss.on('connection', function connection(ws) {
    ws.on('close', (event) => {
        console.log('close', event);
    });
});

Logged gets the following:

PHP:

Closing WS
array(3) {
  [0] =>
  int(1000)
  [1] =>
  string(0) ""
  [2] =>
  class Ratchet\Client\WebSocket#49 (6) {
    public $request =>
    class GuzzleHttp\Psr7\Request#34 (7) {
      private $method =>
      string(3) "GET"
      private $requestTarget =>
      NULL
      private $uri =>
      class GuzzleHttp\Psr7\Uri#35 (7) {
        ...
      }
      private $headers =>
      array(7) {
        ...
      }
      private $headerNames =>
      array(7) {
        ...
      }
      private $protocol =>
      string(3) "1.1"
      private $stream =>
      class GuzzleHttp\Psr7\Stream#89 (7) {
        ...
      }
    }
    public $response =>
    class GuzzleHttp\Psr7\Response#55 (6) {
      private $reasonPhrase =>
      string(19) "Switching Protocols"
      private $statusCode =>
      int(101)
      private $headers =>
      array(3) {
        ...
      }
      private $headerNames =>
      array(3) {
        ...
      }
      private $protocol =>
      string(3) "1.1"
      private $stream =>
      class GuzzleHttp\Psr7\Stream#59 (7) {
        ...
      }
    }
    protected $_stream =>
    class React\Socket\Connection#63 (6) {
      public $unix =>
      bool(false)
      public $encryptionEnabled =>
      bool(false)
      public $stream =>
      resource(61) of type (stream)
      private $input =>
      class React\Stream\DuplexResourceStream#64 (9) {
        ...
      }
      protected $listeners =>
      array(3) {
        ...
      }
      protected $onceListeners =>
      array(0) {
        ...
      }
    }
    protected $_close =>
    class Closure#42 (3) {
      public $static =>
      array(2) {
        ...
      }
      public $this =>
              ...

      public $parameter =>
      array(2) {
        ...
      }
    }
    protected $listeners =>
    array(2) {
      'message' =>
      array(1) {
        ...
      }
      'close' =>
      array(1) {
        ...
      }
    }
    protected $onceListeners =>
    array(0) {
    }
  }
}

JS:

close 1006

I believe this is an issue with ratchetphp/rfc6455, but I thought I will post this issue in ratchetphp/pawl, as this is the library I use. Feel free to open an issue in rfc6455 and reference this issue. I will try digging some deeper into this issue.

[cboden]

hmm, this is a little puzzling the fact that is happens with 2 different servers...

The logic is in fact in Pawl, not the RFC lib. 1006 is supposed to be issued if the underlying socket is closed without the upper WebSocket doing a closing handshake first...

1. If you call close it will
2. Call the inner close closure setting the static variable
3. If the underlying socket closes we should call close abnormally
4. The closure should ignore the call

--

As I was writing that I can see a scenario where this breaks: If the write happens in 1. and the server closes the connection (which is allowed at this point) 3. happens next causing 4. to happen before 2. ever happens.

However, with the above theory I wrote I would expect your var_dump($args) inside the on close would happen twice. Can you confirm this?

[ghost]

No, the var_dump only happens once. However if I comment out the return statement inside the close closure, I do get two. The first one being code 1000 and the second one 1006, which is what I would expect, since the stream was closed, but since it was supposed to be a normal close, we ignore the abnormal close, hence the static variable and return statement.

[cboden]

I tried your node script and received the same result. I made a Ratchet server to contrast and received a 1002 when Pawl attempted to close.

Pawl close payload:

Ratchet response payload:

Pawl isn't masking its close frame. Oops!

[cboden]

The PR didn't fully fix the problem. Pawl is being impatient beginning the shutdown process after sending its close frame before it has received the ack from the server. The node example doesn't like this. I'll need to do another PR with a timeout that will end the connection after sending in case the server doesn't sever the connection.

[cboden]

From https://tools.ietf.org/html/rfc6455#section-7.1.1:

The underlying TCP connection, in most normal cases, SHOULD be closed
first by the server, so that it holds the TIME_WAIT state and not the
client (as this would prevent it from re-opening the connection for 2
maximum segment lifetimes (2MSL), while there is no corresponding
server impact as a TIME_WAIT connection is immediately reopened upon
a new SYN with a higher seq number). In abnormal cases (such as not
having received a TCP Close from the server after a reasonable amount
of time) a client MAY initiate the TCP Close. As such, when a server
is instructed to Close the WebSocket Connection it SHOULD initiate
a TCP Close immediately, and when a client is instructed to do the
same, it SHOULD wait for a TCP Close from the server.

I'll work on another PR to inject an EventLoop into WebSocket and only close the underlying TCP connection if the server hasn't done so after a protocol Close initiation after a period of time.

[ghost]

The mentioned PR does work for Discord. ;)

[cboden]

v0.3.1 has been released with this fix

[ryancwalsh]

@cboden Thanks for ratchetphp/Pawl. Super impressive. And it's mostly working for me.

I'm using "ratchet/pawl": "^0.3.4", and I wonder if this issue is actually fixed or not. Above you said:

The PR didn't fully fix the problem. Pawl is being impatient beginning the shutdown process after sending its close frame before it has received the ack from the server. The node example doesn't like this. I'll need to do another PR with a timeout that will end the connection after sending in case the server doesn't sever the connection.

Do you think that's what I'm experiencing with this problem here?

Do you have any recommendations for me?

E.g. should I try #67 (comment)?

Thanks. I really appreciate your work.

[ryancwalsh]

@mbonneau You helped me solve this problem 21 days ago, and I really appreciate it.

I haven't been able to make progress since then. I'm still stuck getting a 1006 error code every time I send an mp3 larger than ~23 MB / 66 mins. (For shorter mp3s, it always works.)

I'm even following your advice to someone else and using addPeriodicTimer with PING.

    public function getTextFromAudio($audioFileContents, $contentType, $accessToken, $callback) {
        $this->listening = false;
        $this->responseJson = null;
        $url = \me\Tools\SystemTools::getUrlWithUpdatedParams(self::WS_HOST . self::WS_PATH, [
                    'model' => 'en-US_NarrowbandModel',
                    'watson-token' => $accessToken
                        ], \League\Uri\Ws::class);
        $headers = ['X-Watson-Learning-Opt-Out' => true];
        Log::debug('\Ratchet\Client\connect ' . sha1($audioFileContents));
        $loop = \React\EventLoop\Factory::create();
        $connector = new \Ratchet\Client\Connector($loop);
        $connector($url, [], $headers)->then(function(\Ratchet\Client\WebSocket $conn) use($contentType, $audioFileContents, $callback, $loop) {
            $conn->on('message', function($msg) use ($conn, $callback) {
                $this->handleIncomingWebSocketMessage($msg, $conn, $callback);
            });
            $conn->on('close', function($code = null, $reason = null) {
                Log::debug("Connection closed ({$code} - {$reason})");
            });
            $conn->on('error', function($error) {
                Log::error("Ratchet Pawl error ({$error})");
            });
            $loop->addPeriodicTimer(120, function () use ($conn) {
                $conn->send(new \Ratchet\RFC6455\Messaging\Frame('', true, \Ratchet\RFC6455\Messaging\Frame::OP_PING));
                Log::debug('sent ping');
            });
            $this->startWatsonStream($conn, $contentType);
            $this->sendBinaryMessage($conn, $audioFileContents);
            Log::debug('send action stop');
            $conn->send(json_encode(['action' => 'stop']));
        }, function (\Exception $e) use ($loop) {
            Log::error("Could not connect: {$e->getMessage()} " . $e->getTraceAsString());
            $loop->stop();
        });
        $loop->run();
    }

If my understanding is correct that 1006 is always a client-side issue, it means that I'm not properly using ratchetphp/Pawl.

I'm wondering if you see anything that I'm doing wrong.

What would you look into?

I really appreciate all of your help!

[hobsRKM]

v0.3.1 has been released with this fix

it's not fixed. I am still getting this error in the latest version 0.3.5. I am not calling close explicitly, but after keeping it alive for about 3-4 hours socket gets closed with 1006.