Bug #1993: Web sockets - Wt - Redmine

Actions

Copy link

Bug #1993

closed

Web sockets

Added by Voice Vox over 11 years ago. Updated over 11 years ago.

Status:

Closed

Priority:

High

Assignee:

Koen Deforche

Target version:

3.3.1

Start date:

06/21/2013

Due date:

% Done:

Estimated time:

Description

When using web-sockets the following error occurs:

WebSocket connection to 'xxx' failed: Compressed bit must be 0 if no negotiated deflate-frame extension

As we have noticed it happens as a result of several "server pushes" made via WServer::post (or most likely when the triggerUpdates() is called afterwards). It doesn't happen instantly, but rather after a certain time or may be a certain number of Server Pushes. Not much of a regularity that we have noticed, but it happens always (!). Can be cured only with a full app reload (termination).

It happens with Chrome, FF, IE so it cannot be a result of a single browser's protocol misinterpretation.

Actions

Copy link

Updated by Koen Deforche over 11 years ago

Status changed from New to Feedback
Assignee set to Koen Deforche

Hey,

With what version of Wt do you get this? I believe this problem has been fixed in 3.3.0, or cerainly in latest git.

At least, we haven't seen it happening anymore lately.

Regards,

koen

Actions

Copy link

Updated by Voice Vox over 11 years ago

Hi, Koen,

we'be been using the latest release which is 3.3.0.

We will try it with the Git version as you recommend.

Thanks.

Actions

Copy link

Updated by Koen Deforche over 11 years ago

Hey,

Hold on!

I've found a possible cause for the problems you see; I will commit this work later today and drop a note here.

Regards,

koen

Actions

Copy link

Updated by Voice Vox over 11 years ago

Hi, Koen,

thanks for a prompt reply.

Meanwhile we have rebuilt our app with the latest version of Wt from your GIT repository and it has failed again with the same error.

Then we followed your request to enable the HTTP tracing and here's what we got (sorry there's a bit of a mess because it happened to be an application restart due to an F5, so only the second session matters):

INFO: Opened log file (nul).

Server started

[2013-Jun-24 12:27:57.366568] 5424 - [info] "config: reading Wt config file: c:\Wxx\config\General.xml (location = 'c:\Wxx')"

[2013-Jun-24 12:27:57.374607] 5424 - [info] "wthttp: reading wthttpd configuration from: c:\Wxx\config\Server.cfg"

[2013-Jun-24 12:27:57.544739] 5424 - [info] "WServer/wthttp: initializing built-in wthttpd"

INFO: Opened log file (nul).

[2013-Jun-24 12:27:57.762883] 5424 - [info] "wthttp: started server: http://0.0.0.0:8181"

[2013-Jun-24 12:27:57.765885] 5424 - [info] "wthttp: starting server: https://0.0.0.0:4430"

Server started

Press Enter to exit

[2013-Jun-24 12:27:57.786893] 5424 - [info] "Wt: session created (#sessions = 1)"

[2013-Jun-24 12:27:57.816007] 5424 [/ aUMhgmqnKWIE7TZ5] [info] "WEnvironment: UserAgent: Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/27.0.1453.116 Safari/537.36"

[2013-Jun-24 12:27:57.823009] 5424 - [info] "WebRequest: took 10.008ms"

[2013-Jun-24 12:27:58.155028] 5424 [/ aUMhgmqnKWIE7TZ5] [warning] "WApplication: Deploy-path ends with '/', using /?_= for internal paths"

[2013-Jun-24 12:27:58.281108] 5424 - [info] "WebRequest: took 449.093ms"

[2013-Jun-24 12:27:58.293115] 5424 - [info] "WebRequest: took 152.098ms"

[2013-Jun-24 12:27:58.794715] 5424 - [info] "WebRequest: took 396.528ms"

[2013-Jun-24 12:27:58.808725] 5424 - [info] "WebRequest: took 1ms"

[2013-Jun-24 12:27:59.372777] 5424 - [info] "wthttp: ws: connect with protocol version 13"

[2013-Jun-24 12:27:59.381780] 5424 - [info] "WebRequest: took 491.001ms"

[2013-Jun-24 12:27:59.382780] 5424 [/ aUMhgmqnKWIE7TZ5] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:07.257054] 5424 - [info] "Wt: session created (#sessions = 2)"

[2013-Jun-24 12:28:07.261057] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WEnvironment: UserAgent: Mozilla/5.0 (Windows NT 6.2; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/27.0.1453.116 Safari/537.36"

[2013-Jun-24 12:28:07.268061] 5424 - [info] "WebRequest: took 11.007ms"

[2013-Jun-24 12:28:07.271063] 5424 [/ aUMhgmqnKWIE7TZ5] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:07.276067] 5424 [/ aUMhgmqnKWIE7TZ5] [info] "WebRequest: took 6.004ms"

[2013-Jun-24 12:28:07.290076] 5424 [/ DoxQtVDcXF5NdMlf] [warning] "WApplication: Deploy-path ends with '/', using /?_= for internal paths"

[2013-Jun-24 12:28:07.296080] 5424 - [info] "WebRequest: took 18.012ms"

[2013-Jun-24 12:28:07.306087] 5424 - [info] "WebRequest: took 17.012ms"

[2013-Jun-24 12:28:07.373132] 5424 [/ aUMhgmqnKWIE7TZ5] [info] "Wt: session destroyed (#sessions = 1)"

[2013-Jun-24 12:28:07.379135] 5424 - [info] "WebRequest: took 7997.35ms"

[2013-Jun-24 12:28:07.468880] 5424 - [info] "WebRequest: took 49.718ms"

[2013-Jun-24 12:28:07.479889] 5424 - [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:08.395532] 5424 - [info] "wthttp: ws: connect with protocol version 13"

[2013-Jun-24 12:28:08.409538] 5424 - [info] "WebRequest: took 835.588ms"

[2013-Jun-24 12:28:08.411541] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:09.924206] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:09.927206] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 7.004ms"

[2013-Jun-24 12:28:10.193368] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:15.951956] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:15.955956] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 36.022ms"

[2013-Jun-24 12:28:16.512086] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:16.519091] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:16.661343] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 1ms"

[2013-Jun-24 12:28:17.120553] 5424 [/ DoxQtVDcXF5NdMlf] [secure] "XSS: discarding invalid attribute: id: moduleInfoTable"

[2013-Jun-24 12:28:17.505298] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 15.012ms"

[2013-Jun-24 12:28:17.510301] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 1.002ms"

[2013-Jun-24 12:28:18.925672] 5424 - [info] "WebRequest: took 1.001ms"

[2013-Jun-24 12:28:18.938692] 5424 - [info] "WebRequest: took 1.008ms"

[2013-Jun-24 12:28:18.954702] 5424 - [info] "WebRequest: took 1.999ms"

[2013-Jun-24 12:28:18.965708] 5424 [/ DoxQtVDcXF5NdMlf] [info] "Wt: discarding broken asyncResponse, (ws: 1"

[2013-Jun-24 12:28:18.971710] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 10563.2ms"

[2013-Jun-24 12:28:19.882859] 5424 - [info] "wthttp: ws: connect with protocol version 13"

[2013-Jun-24 12:28:19.898872] 5424 - [info] "WebRequest: took 933.164ms"

[2013-Jun-24 12:28:19.900869] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:22.418765] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 1.001ms"

[2013-Jun-24 12:28:22.488301] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 0ms"

[2013-Jun-24 12:28:22.493305] 5424 [/ DoxQtVDcXF5NdMlf] [info] "WebRequest: took 5.004ms"

[2013-Jun-24 12:28:22.597382] 5424 [/ DoxQtVDcXF5NdMlf] [info] "Wt: session destroyed (#sessions = 0)"

[2013-Jun-24 12:28:22.604386] 5424 - [info] "WebRequest: took 2706.52ms"

Possibly the error happened at the line shown with bold. Hope it helps you.

Thanks.

Actions

Copy link

Updated by Koen Deforche over 11 years ago

Hey,

I've pushed a new version just now. I would appreciate if you could give it a test.

If I'm right (and the patch is good) then I would expect that the error above is a consequence of the problem, not a cause.

koen

Actions

Copy link