search

tg123 / websockify-nginx-module

Embed websockify into Nginx (convert any tcp connection into websocket)
MIT License
140 stars 59 forks source link

ngx_http_websockify_send_with_encode: encode error! #1

Closed fmbiete closed 10 years ago

fmbiete commented 10 years ago

Hi,

I'm seeing this in my nginx error log: 2014/06/27 13:22:37 [error] 1651#0: *425 ngx_http_websockify_send_with_encode: encode error! while proxying upgraded connection, client: 10.10.10.10, server: name.server.com, request: "GET /vnc/5002 HTTP/1.1", upstream: "websockify://127.0.0.1:5002", host: "name.server.com"

And this in the firefox console: New state 'failed', was 'normal'. Msg: Disconnected: illegal hextile subencoding 201

nginx 1.6.0 CentOS 6.5 x86_64 Fedora 20 x86_64

It doesn't happen always, but more frequently in CentOS than Fedora.

Can you help me??

haoel commented 10 years ago

Hi,

it seems there has some illegal data.

To understand and narrow down this issue, could you please help confirm the following things: 1) Only Firefox has this problem? no problem for Chrome or IE? 2) Can you reproduce this problem with the official noVNC web? http://kanaka.github.io/noVNC/noVNC/vnc.html

--Hao

fmbiete commented 10 years ago

Hi,

I'm seeing the same problem with Chrome (35), Firefox (30) and IE (11). -No, I'm not seeing the problem with the official noVNC websockify-

fmbiete commented 10 years ago

Wrong, I'm seeing the same problem with noVNC official web. It just doesn't happens always.

haoel commented 10 years ago

I just tried half an hour for Firefox + CentOS 6.5 X86_64, cannot reproduce it. And I will keep trying to reproduce it.

Besides, how often the encode error happened on your site?

fmbiete commented 10 years ago

8/10 times with nginx 1.6.0. Not so far with nginx 1.4.7.

Could be related to some change in nginx?

fmbiete commented 10 years ago

Using "websockify_send_flush on;" seems to solve the problem. So far no errors (i will keep checking). Does it make any sense?

tg123 commented 10 years ago

websockify_send_flush on is not a good idea that causes ngx to busy wait in order to send all buff to client

i checked the code found something may lead an encode problem please refer to branch https://github.com/tg123/websockify-nginx-module/tree/issue1

tested if can fix your problem

fmbiete commented 10 years ago

I tested with issue1 branch, but I'm seeing the same error.

Using websockify_send_flush the problem dissapears. Could be that nginx returns partial data that cannot be decoded by noVNC and this closes the connection?

The vnc screen is painted but dissapears without being completed.

New state 'loaded', was 'disconnected'. Msg: noVNC ready: native WebSockets, canvas rendering 
New state 'connect', was 'loaded'. 
Skipping unsupported WebSocket binary sub-protocol 
New state 'ProtocolVersion', was 'connect'. Msg: Starting VNC handshake 
New state 'Security', was 'ProtocolVersion'. Msg: Sent ProtocolVersion: 003.003 
New state 'Authentication', was 'Security'. Msg: Authenticating using scheme: 1 
New state 'ClientInitialisation', was 'Authentication'. Msg: No auth required 
New state 'ServerInitialisation', was 'ClientInitialisation'. Msg: Authentication OK 
Server native red-shift is not 16 
New state 'normal', was 'ServerInitialisation'. Msg: Connected (encrypted) to: XenServer Virtual Terminal 
New state 'failed', was 'normal'. Msg: Disconnected: illegal hextile subencoding 90 
Error while connected. 
New state 'disconnected', was 'failed'. 
WebSocket on-error event 
WebSocket on-close event 
Received onclose while disconnected (code: 1006)
haoel commented 10 years ago

Did you see the "encode error" in nginx log? if it is, then the connection should be dropped by back-end.

Because turn on the "websockify_send_flush" option helps, I think this problem might be the part of code about the buffer we cached.

We might need a bit more time to investigate this issue.

And, may I ask you help to enable the nginx debug logging? so that we can see how your nginx caches and sends the data. Thanks!

fmbiete commented 10 years ago

Many thanks to both of you for the interest!!! The alternatives to this nginx plugins are very poor...

Yes, I'm seeing the "encode error", and also a "decode error"

2014/06/28 19:55:45 [debug] 28506#0: *228 websockify : found SEC_WEBSOCKET_KEY : XunoftgV133epYWfJpqwPQ==
2014/06/28 19:55:45 [debug] 28506#0: *228 websockify : ngx_http_websockify_process_header
2014/06/28 19:55:45 [debug] 28506#0: *228 ngx_http_websockify_send_with_encode: sending data...[12]
2014/06/28 19:55:45 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 18 / 18
2014/06/28 19:55:45 [debug] 28506#0: *228 ngx_http_websockify_send_with_decode: [22]
2014/06/28 19:55:45 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 12 / 12
2014/06/28 19:55:45 [debug] 28506#0: *228 ngx_http_websockify_send_with_encode: sending data...[4]
2014/06/28 19:55:45 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 10 / 10
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_decode: [10]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 1 / 1
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_encode: sending data...[50]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 70 / 70
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_decode: [118]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 82 / 82
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_encode: sending data...[4096]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 5468 / 5468
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_encode: sending data...[12288]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : -2 / 16388
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_encode: old buff not clean...[16388]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 16388 / 16388
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 21852 / 21852
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_decode: [22]
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_buffer: sent buffer : 10 / 10
2014/06/28 19:55:46 [debug] 28506#0: *228 ngx_http_websockify_send_with_decode: [6]
2014/06/28 19:55:46 [error] 28506#0: *228 ngx_http_websockify_send_with_decode: decode error!  while proxying upgraded connection, client: 10.2.96.253, server: name.domain, request: "GET /vnc/5003 HTTP/1.1", upstream: "websockify://127.0.0.1:5003", host: "name.domain"
2014/06/28 20:00:18 [debug] 28504#0: *621 websockify : found SEC_WEBSOCKET_KEY : Yg5NPU9gqTcMutABrje0GA==                                                                                                                                    
2014/06/28 20:00:18 [debug] 28504#0: *621 websockify : ngx_http_websockify_process_header                                                                                                                                                    
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[12]                                                                                                                                          
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 18 / 18                                                                                                                                             
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_decode: [22]                                                                                                                                                         
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 12 / 12                                                                                                                                             
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[4]                                                                                                                                           
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 10 / 10                                                                                                                                             
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_decode: [10]                                                                                                                                                         
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 1 / 1                                                                                                                                               
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[50]                                                                                                                                          
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 70 / 70                                                                                                                                             
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_decode: [118]                                                                                                                                                        
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 82 / 82                                                                                                                                             
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[4096]                                                                                                                                        
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 5468 / 5468                                                                                                                                         
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[12288]                                                                                                                                       
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : -2 / 16388                                                                                                                                          
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[16384]                                                                                                                                       
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: old buff not clean...[16388]                                                                                                                                 
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 16388 / 16388                                                                                                                                       
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852                                                                                                                                          
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[16384]                                                                                                                                       
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: old buff not clean...[21852]                                                                                                                                 
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 21852 / 21852                                                                                                                                       
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852                                                                                                                                          
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_decode: [22]                                                                                                                                                         
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : 10 / 10
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: old buff not clean...[21852]
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : -2 / 43704
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_with_encode: old buff not clean...[43704]
2014/06/28 20:00:18 [debug] 28504#0: *621 ngx_http_websockify_send_buffer: sent buffer : -2 / 43704
2014/06/28 20:00:18 [error] 28504#0: *621 ngx_http_websockify_send_with_encode: encode error!  while proxying upgraded connection, client: 10.2.96.253, server: name.domain, request: "GET /vnc/5003 HTTP/1.1", upstream: "websockify://127.0.0.1:5003", host: "name.domain"
tg123 commented 10 years ago

sorry, it is a bug.

buff overflow cause the encode error (not enough buff space) I am now working on it

tg123 commented 10 years ago

image

thank you reproduced

tg123 commented 10 years ago

hi @fmbiete check out branch issue1

i think i have fixed it

fmbiete commented 10 years ago

Sorry, I'm seeing the same errors

2014/06/29 17:05:43 [debug] 15127#0: *79 websockify : found SEC_WEBSOCKET_KEY : TM4f01q6V8lqFN8EU8o1MQ==
2014/06/29 17:05:43 [debug] 15127#0: *79 websockify : ngx_http_websockify_process_header
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[12]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 18 / 18
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_decode: [22]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 12 / 12
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[4]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 10 / 10
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_decode: [10]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 1 / 1
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[50]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 70 / 70
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_decode: [118]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 82 / 82
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[4096]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 5468 / 5468
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[12288]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : -2 / 16388
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: old buff not clean...[16388]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 16388 / 16388
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_decode: [22]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 10 / 10
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: old buff not clean...[21852]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 21852 / 21852
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: old buff not clean...[21852]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 21852 / 21852
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_encode: old buff not clean...[21852]
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : 21852 / 21852
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:05:43 [debug] 15127#0: *79 ngx_http_websockify_send_with_decode: [6]
2014/06/29 17:05:43 [error] 15127#0: *79 ngx_http_websockify_send_with_decode: decode error!  while proxying upgraded connection, client: 10.2.96.253, server: name.domain, request: "GET /vnc/5003 HTTP/1.1", upstream: "websockify://127.0.0.1:5003", host: "name.domain"

2014/06/29 17:06:17 [debug] 15127#0: *132 websockify : found SEC_WEBSOCKET_KEY : HlUG5An/HrC5a8GKtmRjuA==
2014/06/29 17:06:17 [debug] 15127#0: *132 websockify : ngx_http_websockify_process_header
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[12]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 18 / 18
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_decode: [22]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 12 / 12
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[4]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 10 / 10
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_decode: [10]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 1 / 1
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[50]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 70 / 70
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_decode: [118]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 82 / 82
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[4096]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 5468 / 5468
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[12288]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : -2 / 16388
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: old buff not clean...[16388]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 16388 / 16388
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_decode: [22]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 10 / 10
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: old buff not clean...[21852]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 21852 / 21852
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: old buff not clean...[21852]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : 21852 / 21852
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: old buff not clean...[21852]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : -2 / 21852
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : -2 / 43704
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: sending data...[16384]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_with_encode: old buff not clean...[43704]
2014/06/29 17:06:17 [debug] 15127#0: *132 ngx_http_websockify_send_buffer: sent buffer : -2 / 43704
2014/06/29 17:06:17 [error] 15127#0: *132 ngx_http_websockify_send_with_encode: encode error!  while proxying upgraded connection, client: 10.2.96.253, server: name.domain, request: "GET /vnc/5003 HTTP/1.1", upstream: "websockify://127.0.0.1:5003", host: "name.domain"
tg123 commented 10 years ago

hi @fmbiete are you sure your code is clean?

log should show ngx_http_websockify_send_buffer: add timer after '-2 / xx'

fmbiete commented 10 years ago

True, I only updated the nginx-debug package and not the nginx package. Sorry. With the latest "issue1" I'm not seeing the error. 20/20 tests ok so far

Thank you very much!!!