Client sent invalid method logged when using websockets

[Kronuz]

I'm getting a lot of messages like this one in my nginx logs

2013/08/08 07:58:05 [info] 54046#0: *7306 client sent invalid method while reading client request line, client: 66.27.123.10  
server: mydomain.com, request: "<8A><80>]<9E>3O<8A><80><A2><F1><BD>|<8A><80><<BF><80><AA><8A><80><80>e<8D><CC><8A><80><D6><CB>G
<94><8A><80><C2><9D>fZ<8A><80><9D>x<9B><92><8A><80><D2><8D>4P<8A><80><F2>b<E6>^@<8A><80><CF><A2>gd<8A><80>C<CA><E7><E8><8A>
<80><DC><8B><9D><CC><8A><80>^Vcv<E2><8A><80><B9>\<E4><98><8A><80>Fh<8C>0<8A><80>^T<E9><86><E8><8A><80><9D><DF>M<C3><8A><80>6m 
<C8><8A><80>+<9A>?<A8><8A><80><8E><<B0>K<8A><80><88>^FOG<8A><80>\^T<C6><F5><8A><80> <A5><83>O<8A><80>Fs<E7><A3><8A><80>'^Q
<88>?<8A><80><F6>Ii<AD><8A><80>Bd<9B><A1><8A><80><A9>d<AA>D<8A><80>]<A9>3<86><8A><80>^Y<97>d<F1><8A>...

The <8A><80> part is what hints me this could be related to the nginx-push-stream module I'm I correct?... I'm using websockets. Could it be something wrong somewhere? (Perhaps in the js lib?)

[wandenberg]

Hi,

to help you I need more information. What js library are you using? Which browser made this request? Websocket has many implementations, the module support only 2 of them. May be an old browser, or a browser which does not implement correctly the specification. If you can, send me a step by step how to reproduce the problem.

[Kronuz]

I am using the pushstream.js library in your repp's master branch. nginx-push-stream also from master and compiled as a Nginx 1.4.2 plugin. And the browser is latest stable Google Chrome for OS X (as this has also happened in my local configuration, in the machine I use). Unfortunately, this only happens in occasions, and I'm unable to consistently reproduce the problem. The client adds channels, and uses pushstream through secure sockets... then suddenly the nginx server starts reporting those messages from time to time.

[jerzyk]

I'm getting same error, this happens when server was restarted and clients are trying to reestablish connection to websockets.

[wandenberg]

Hi,

sorry for the late response, and thanks for report when the problem happens. This helped a lot. Please, try the code on 0.4.x branch. I fixed this message error and the lazy reload problem. And send me some feedback if you keep receiving the messages errors

Regards, Wandenberg

On Sat, Sep 28, 2013 at 1:12 PM, jerzyk notifications@github.com wrote:

I'm getting same error, this happens when server was restarted and clients are trying to reestablish connection to websockets.

— Reply to this email directly or view it on GitHubhttps://github.com/wandenberg/nginx-push-stream-module/issues/95#issuecomment-25300913 .

[Kronuz]

I'm still getting things like this, although far less frequently it seems (changed the actual string in the message to utf-8 for posting here):

2013/10/22 12:22:16 [info] 61022#0: *196 client sent invalid method while reading client request line, client: 127.0.0.1, server: *.publish, request: '\xef\xbf\xbd\xef\xbf\xbd4{\xef\xbf\xbdH\xef\xbf\xbd\xef\xbf\xbdDN\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdKp8\xef\xbf\xbd\xef\xbf\xbdh\xef\xbf\xbd\xee\x8a\x80\xef\xbf\xbd}%                                                                                                                                                                                 \xef\xbf\xbd\xef\xbf\xbdX\xef\xbf\xbd\xef\xbf\xbd\\\xef\xbf\xbd\xef\xbf\xbd1s\xef\xbf\xbd|\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd_t\xc8\x8a\xef\xbf\xbd\xef\xbf\xbd>\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdlF\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdajP\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdZ\xef\xbf\xbd\x7f\xef\xbf\xbd\xef\xbf\xbd\xd1\xa5s\xd1\x8a\xef\xbf\xbd\xef\xbf\xbds4\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd2\xe5\x8a\x80\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdp\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd                                                                   \xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd*\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdj6                                                                             \xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd*\xef\xbf\xbd=\xef\xbf\xbdd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdG3\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdF\xef\xbf\xbd\xef\xbf\xbdd\xef\xbf\xbd\xd4\x8a\xef\xbf\xbd\xef\xbf\xbdkoE\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdN\xef\xbf\xbd\xef\xbf\xbdZ\xef\xbf\xbdR\xef\xbf\xbd/O\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbda=a\xef\xbf\xbd\xef\xbf\xbd9\xef\xbf\xbdF\x7f\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdo\xef\xbf\xbdm\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd/*^\xef\xbf\xbd\xef\xbf\xbdsFQ\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdsI\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd \xef\xbf\xbdY\xd0\x8a\xef\xbf\xbd"\xef\xbf\xbd0\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd#\xf3\xb9\x8f\x8a\xef\xbf\xbd1\xef\xbf\xbd\xcf\x8a\xef\xbf\xbd\xc2\xb0\xef\xbf\xbd\xe9\x8a\x80\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdG)d\xef\xbf\xbd\xef\xbf\xbd\xeb\x92\xaa\xef\xbf\xbd\xef\xbf\xbdA\xef\xbf\xbd\xef\xbf\xbd5\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd \xca\x8a\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xc8\x8a\xef\xbf\xbd\xef\xbf\xbdz+B\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd6\xef\xbf\xbd7\xef\xbf\xbd\xef\xbf\xbd                                                      \xef\xbf\xbd\xef\xbf\xbd4\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdz(,\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd4\xef\xbf\xbd\xef\xbf\xbd>                                                                       \xef\xbf\xbd\xc5\x8a\xef\xbf\xbd\xef\xbf\xbdq\xef\xbf\xbd\xef\xbf\xbdo\xef\xbf\xbd\xef\xbf\xbde\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdj}J\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd*\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdM CT\xef\xbf\xbd\xef\xbf\xbd.\xef\xbf\xbdp$\xef\xbf\xbd\xef\xbf\xbd>\xef\xbf\xbd+y\xef\xbf\xbd\xef\xbf\xbdY\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd^!\xe1\xbf\x8a\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\x8a\x80\xef\xbf\xbd\xef\xbf\xbdDA\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdv97\xef\xbf\xbd\xef\xbf\xbd,t2Z\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbda\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdV\xef\xbf\xbd}\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd9+\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd]\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd3a\xe1\xaa\x8a\xef\xbf\xbdba\xef\xbf\xbdn\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd/\xef\xbf\xbdm\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd:\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xdb\x92pX\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd*\xef\xbf\xbd\xef\xbf\xbdr\xef\xbf\xbd\xef\xbf\xbd'

and messages like the next one are, I suppose, maybe what changed... because I started getting more of this:

2013/10/22 12:13:30 [info] 61022#0: *234 client closed connection while waiting for request, client: 127.0.0.1, server: 0.0.0.0:80

[wandenberg]

Hi,

please try the version on 0.4.x branch. This branch will be released soon as 0.4.0 version. I have made some changes to fix this problem when reloading the server.

On Wed, Oct 23, 2013 at 1:38 PM, Germán M. Bravo notifications@github.comwrote:

I'm still getting things like this, although far less frequently it seems:

2013/10/22 12:22:16 [info] 61022#0: _196 client sent invalid method while reading client request line, client (changed the actual string in the message to utf-8 for posting here): 127.0.0.1, server: *.publish, request: '\xef\xbf\xbd\xef\xbf\xbd4{\xef\xbf\xbdH\xef\xbf\xbd\xef\xbf\xbdDN\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdKp8\xef\xbf\xbd\xef\xbf\xbdh\xef\xbf\xbd\xee\x8a\x80\xef\xbf\xbd}% \xef\xbf\xbd\xef\xbf\xbdX\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd1s\xef\xbf\xbd|\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdt\xc8\x8a\xef\xbf\xbd\xef\xbf\xbd>\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdlF\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdajP\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdZ\xef\xbf\xbd\x7f\xef\xbf\xbd\xef\xbf\ xbd\xd1\xa5s\xd1\x8a\xef\xbf\xbd\xef\xbf\xbds4\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd2\xe5\x8a\x80\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdp\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd \xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdj6 \xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd=\xef\xbf\xbdd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdG3\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdF\xef\xbf\xbd\xef\xbf\xbdd\xef\xbf\xbd\xd4\x8a\xef\xbf\xbd\xef\xbf\xbdkoE\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdN\xef\xbf\xbd\xef\xbf\xbdZ\xef\xbf\xbdR\xef\xbf\xbd/O\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbda=a\xef\xbf\xbd\xef\xbf\xbd9\xef\xbf\xbdF\x7f\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdo\ xef\xbf\xbdm\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd/^\xef\xbf\xbd\xef\xbf\xbdsFQ\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdsI\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd \xef\xbf\xbdY\xd0\x8a\xef\xbf\xbd"\xef\xbf\xbd0\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd#\xf3\xb9\x8f\x8a\xef\xbf\xbd1\xef\xbf\xbd\xcf\x8a\xef\xbf\xbd\xc2\xb0\xef\xbf\xbd\xe9\x8a\x80\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdG)d\xef\xbf\xbd\xef\xbf\xbd\xeb\x92\xaa\xef\xbf\xbd\xef\xbf\xbdA\xef\xbf\xbd\xef\xbf\xbd5\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd \xca\x8a\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xc8\x8a\xef\xbf\xbd\xef\xbf\xbdz+B\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd6\xef\xbf\xbd7\xef\xbf\xbd\xef\xbf\xbd \xef\xbf\xbd\xef\xbf\xbd4\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdz(,\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd4\xef\xbf\xbd\xef\xbf\xbd> \xef\xbf\xbd\xc5\x8a\xef\xbf\xbd\xef\xbf\xbdq\xef\xbf\xbd\xef\xbf\xbdo\xef\xbf\xbd\xef\xbf\xbde\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdj}J\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdM CT\xef\xbf\xbd\xef\xbf\xbd.\xef\xbf\xbdp$\xef\xbf\xbd\xef\xbf\xbd>\xef\xbf\xbd+y\xef\xbf\xbd\xef\xbf\xbdY\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd^!\xe1\xbf\x8a\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\x8a\x80\xef\xbf\xbd\xef\xbf\xbdDA\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdv97\xef\xbf\xbd\xef\xbf\xbd,t2Z\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbda\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdV\xef\xbf\xbd}\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd9+\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd]\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd3a\xe1\xaa\x8a\xef\xbf\xbdba\xef\xbf\xbdn\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd/\xef\xbf\xbdm\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd:\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xdb\x92pX\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xb d\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbd\xef\xbf\xbdr\xef\xbf\xbd\xef\xbf\xbd'

and messages like the next one are, I suppose, maybe what changed... because I started getting more of this:

2013/10/22 12:13:30 [info] 61022#0: *234 client closed connection while waiting for request, client: 127.0.0.1, server: 0.0.0.0:80

— Reply to this email directly or view it on GitHubhttps://github.com/wandenberg/nginx-push-stream-module/issues/95#issuecomment-26915853 .

[Kronuz]

Yes, I am trying the tip of 0.4.x branch ;) ...but the problem is still there (not as frequent as it was though, it seems).

[wandenberg]

So, can you check the try_websocket_keepalive_fix branch? It is equals to 0.4.x branch except I disabled the keepalive support for websocket. So, if the connection fails it will start the protocol handshake again.

On Wed, Oct 23, 2013 at 4:12 PM, Germán M. Bravo notifications@github.comwrote:

Yes, I am trying the tip of 0.4.x branch ;) ...but the problem is still there (not as frequent as it was though, it seems).

— Reply to this email directly or view it on GitHubhttps://github.com/wandenberg/nginx-push-stream-module/issues/95#issuecomment-26929274 .

[wandenberg]

This was solved on tag 0.4.0 3d3a204177d3a7ab8a2858e04e792a6d11bf133f