websockify.py code 400, message Bad request syntax ('\x88

[OldWolf2]

This error occurs only with websockify.py (cloned 26-May-2015), not with the Node.js version. Using Python 2.7.8 (precompiled Windows binary); and get the same problem in both browsers I've tried, IE11.0.9600.17691, and Chrome 43.0.2357.65 m.

After the Javascript code calls sock.close() on its WebSocket, then websockify.py logs a message such as :

127.0.0.1 - - [28/May/2015 14:49:28] code 400, message Bad request syntax ('\x88 \x8f\x96\x09\x4c\x15\x95\xe1\x18\x74\xe4\x6E\x29\x61\xb6\x6a\x20\x7a\xe5\x6c\x28')

This is actually a valid message in the WebSocket protocol (RFC 6455). 0x88 means FIN+Close, 0x8F means Masked and length 15 bytes; 96094c15 is an XOR mask, and applying it to the rest of the text uncovers 1000 "Target Closed" which is a correct message.

I'm not sure why websockify doesn't like this particular message, maybe it doesn't have mask support? My send-receive works perfectly well from HTML5 to my plaintext server via websockify; this error is just a bogus log message after each close() .

Here is Wireshark screenshot: http://i.imgur.com/mHuHxJ6.png

52770 is my server's listen port; 52771 is websockify.py's listen port. 57461 is the source port of the browser's connection to websockify. As you can see, this packet which is being reported on came after the FIN for the connection to 52770; i.e. while the connection between browser and websockify is being shut down and therefore it can't be due to a problem with my server.

Websockify was started by "run 52771 localhost:52770".

[stephenjamieson]

Any luck debugging this one?

[OldWolf2]

Hi

On 8/07/2015 12:51 a.m., stephenjamieson wrote:

Any luck debugging this one?

No. I'm not really familiar with Python so I didn't try. I ended up making a websocket server directly, instead of using websockify.

Regards, Matt.

[beckjim]

Hi,

I'm having the same issue with websockify.py. I can reproduce it quite easily when authenticating with a wrong password in noVNC. (Not always but most of the time). Makes no difference whether direct access or behind apache. Unfortunately I'm not a python programmer ...

Regards, Stefan

[stephenjamieson]

Upgraded websockets and using python 3, same issue.

[kanaka]

Just to be clear, this is not preventing connections, it's just a misleading error message, is that correct?

Possibly what is happening is that there is some weird interaction between the regular web handler and the websocket handler and it seems that after the websocket handler is closed, the regular web handler continues to get bytes from the client and gets the close websocket packet at which point it gives the bad request syntax. I won't have an opportunity to look at this further in the near future but maybe that will help with tracking down the underlying root cause.

[stephenjamieson]

It happens for me while I'm in the middle of a connection, and it disconnects. Doesn't seem to have this issue with node.

[kanaka]

@stephenjamieson you're getting spontaneous disconnects? I suspect that is a different problem that results in this symptom (rather than it being the cause of the problem). The websockify message looks to me like a problem where something triggers a close (either client or VNC server) and the connection between the browser and websockify is not cleanly closed down. @OldWolf2 are you also seeing spontaneous disconnects, or is this just a message you see during a normal connection terminate event (bad password, pressing disconnect button, etc).

[stephenjamieson]

I would agree except the node version of websockify seems to not have the same issue, I do not get the spontaneous disconnects.

[kanaka]

@stephenjamieson perhaps timing differences between the node and python versions is triggering a noVNC bug. In particular, it might be this issue: https://github.com/kanaka/noVNC/pull/524 Can you try with the most recent noVNC using both node and python websockify and see if you still see the same behavior in both?

[DirectXMan12]

@kanaka : the bug you linked wasn't actually disconnects -- it was just hanging, but it's possible the over-read could manifest in other ways. @stephenjamieson : do you see any errors on your browser's javascript console (F12 in both Firefox and Chrome, or alternatively accessible under menu->Developer in Firefox or menu->More tools->Developer tools in Chrome)

[Ziris85]

I'm finding I have the same issue with the spontaneous disconnects. At first I thought I was just hitting a timeout somewhere, but I wasn't able to track one down that made sense, especially considering at least for me the disconnects are erratic - sometimes it happens shortly after the connection is open, other times it will last for several minutes. Since this topic seems to have fizzled out, @stephenjamieson did you find out what the cause of your disconnects were?

[stephenjamieson]

@Ziris85 I started using the ruby version and have no problems, more memory and cpu usage, but it works.

[Ziris85]

Thanks for getting back to me @stephenjamieson. I think I'm going to open up a new issue on the noVNC project page for this. I'm certain this is a noVNC issue and not a websockify issue - I was having problems with the python version of websockify, but when I switched over to connecting to a VNC server directly (sans websockify) the problem persists. I'll link the new issue in here once I've made it.

[henickr]

i'm also having this issue while using the eyeOS html5 spice client ... not noVNC... maybe it could be a websocket issue... worst case, i think that websockify could translate this message in to one of the error codes on the chart below for you so people have some general idea what to do if it fails.

even if the x88 does mean FIN+Close then the connection is closing intentionally and is the reason my project is not working. my specific message is "\x88\x8f\xec:\xd2\xeb\xef\xd2\x86\x8a\x9e]\xb7\x9f\xccY\xbe\x84\x9f_\xb6"

this works perfectly with https turned off and only occurs with it on. it used to happen pre-https but only infrequently (as opposed to every single time now-- over https) after seeing that chart below... makes much more sense when considering some transient random usage issue.

i am currently using a self signed certificate but it is the same one being used by the referrer and already accepted in browser while visiting the eyeOS address that connects to the qemu backend.

0x8f 15 byte xor mask is ecd2ebef to decode the rest \xd2\x86\x8a\x9e]\xb7\x9f\xccY\xbe\x84\x9f_\xb6

This is the table saying what codes mean what from RFC 6455:

 |Status Code | Meaning         | Contact       | Reference |
-+------------+-----------------+---------------+-----------|
 | 1000       | Normal Closure  | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1001       | Going Away      | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1002       | Protocol error  | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1003       | Unsupported Data| hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1004       | ---Reserved---- | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1005       | No Status Rcvd  | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1006       | Abnormal Closure| hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1007       | Invalid frame   | hybi@ietf.org | RFC 6455  |
 |            | payload data    |               |           |
-+------------+-----------------+---------------+-----------|
 | 1008       | Policy Violation| hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1009       | Message Too Big | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1010       | Mandatory Ext.  | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|
 | 1011       | Internal Server | hybi@ietf.org | RFC 6455  |
 |            | Error           |               |           |
-+------------+-----------------+---------------+-----------|
 | 1015       | TLS handshake   | hybi@ietf.org | RFC 6455  |
-+------------+-----------------+---------------+-----------|

So I will decode this error and see if I can get further here but maybe websockify could have a module to decode this for people might be useful in error handling and sanity.

Any direction someone could give me would be awesome if someone is still reading this old post.

Thanks!

[henickr]

and after a translation session with the chart in section 5.2. Base Framing Protocol from RFC 6455. (the chart wont paste here even with code tags it screws up)

\x88 / \x8f / \xec \x3a \xd2 \xeb / \xef\xd2\x86\x8a\x9e]\xb7\x9f\xccY\xbe\x84\x9f_\xb6 Fin+Close / Mask,15 bit payload / 4byte mask key ( ec 3a d2 eb) / Payload Data Status Code ( ef d2 ) UTF-8 Encoded Text ( 86 8a 9e 5d b7 9f cc 59 be 84 9f 5f b6 )

Mask: 1110110000111010 1101001011101011 Data: 1110111111010010 UMSK: 0000001111101000

Unmasked Payload (hex): 03 e8 Payload Data : 2 bytes (16-bit bigendian unsigned) of Status Code (03e8) = 1000

"Normal Closure". That was very anti-climactic after all that.

I'm going to translate all of them and print them out in hex so they can be parsed for. I'm using eyeOS html5 spice client and it works perfectly over http using the ws protocol.

After switching to https and wss the eyeOS client displays a black screen, never connects and throws a code in the form of an encoded string to websockify.log

[henickr]

ok here is a script that may help others...

#!/usr/bin/perl -w

use Encode qw(decode);

#$payload = "\x88\x8f\xec:\xd2\xeb\xef\xd2\x86\x8a\x9e]\xb7\x9f\xccY\xbe\x84\x9f_\xb6";
$payload = "\x88\x8f\xec\xeb[\xb1\xef\x03\x0f\xd0\x9e\x8c>\xc5\xcc\x887\xde\x9f\x8e?";
#$key = "\xec\x3a\xd2\xeb";

$payload_size = length ($payload);

if (0) {
  my ( $hex ) = unpack ('H*', $payload);
  print "$hex\n";
  exit (0);
}

$pos = 0;

$frametype = substr ($payload, $pos, 1);
#$frametype = $payload[$pos];

if (0) {
  my ( $hex ) = unpack ('H*', $frametype);
  print "$hex\n";
  exit (0);
}

#($fin, $res, $frametype2) = unpack ("b1 b3 h" , $frametype);
$ft = ord ($frametype);
#$fin  = $ft & ( 1 << 7 );
$fin  = $ft >> 7;
$frametype2 = $ft & ord('\x0f');
$pos++;

printf ("FIN=%x, Frametype = %x\n", $fin , $frametype2);

$datasize = ord (substr ($payload, $pos, 1));
#$mask = ( $payloadsize & ( 1 << 7 ) );
$mask =  $datasize >> 7;
$datasize &= ord ('\x7f');
#unpack ('n', $payloadsize);
$pos++;

printf ("Mask = %d, Datasize = %u\n", $mask, $datasize);

if ( $mask ) {
  $maskkey = substr ($payload, $pos, 4);
  $pos += 4;

  $data = '';
  $keypos = 0;
  while ( $pos < $payload_size) {
    $d = ord ( substr ($payload, $pos, 1));
    $k = ord ( substr ($maskkey, $keypos, 1));
    $v = $d ^ $k;

    #printf  (STDERR " keypos= %d, d= %x, k= %x, v=%x\n", $keypos, $d, $k, $v);

    $keypos = ( $keypos + 1) % 4;
    $pos++;
    $data .= chr ($v);
  }

}
else {
  $data = substr ($payload, $pos);
}

$code = unpack ('n', $data);
$data = substr ($data, 2);

printf ("Data (%u/%u):  \n", length ($data), $datasize);

$chars = decode ('UTF-8', $data);
printf ("Code=%u, chars=($chars)\n", $code, $data);

change the $payload variable above to your message attached to 'bad request' and this script will tell you why it is happening. it isn't very informative to me because it keeps just telling me, 1000 - Target closed. So it didn't help me. But at least you'll know why websockets is closing if you use this.

[CendioOssman]

This was fixed in 30942f12d3909fd9bb4302a9d0b0567c7bcd216a.