Welcome! Log In Create A New Profile

Advanced

WebSocket + compression + timeout tunnel broken in v1.7?

Posted by Kristjan Koppel 
Kristjan Koppel
WebSocket + compression + timeout tunnel broken in v1.7?
March 17, 2017 12:00PM
Hi!



I upgraded a HAProxy instance from v1.6.10 to v1.7.3 with no changes to configuration and I noticed that now clients connecting to a WebSocket backend are getting disconnected after being idle for "timeout client" time rather than the much longer "timeout tunnel" time. As I understand it, "timeout tunnel" is supposed to override the "timeout client" setting for WebSocket sessions and this worked fine with v1.6 and earlier.



Also, this HAProxy instance has compression enabled in the defaults section. If I remove the compression settings from there (or if I move them to other backends only), then "timeout tunnel" starts to work again. So, I guess this is a bug in HAProxy v1.7?



I managed to reproduce this with the official HAProxy Docker images, a minimal haproxy.cfg and wscat (from the Debian package node-ws) as follows:



haproxy.cfg:


global

stats socket /run/haproxy.sock mode 660 level admin

stats timeout 30s

daemon



defaults

mode http

timeout connect 5s

timeout client 50s

timeout server 60s

timeout tunnel 15m



compression algo gzip

compression type text/html



listen ws_test

bind :8000

server wscat 172.17.0.1:8001





I started one wscat instance in listening mode for the backend:

$ wscat -l 8001



With HAProxy v1.6.11 running the above config I see the following:

$ date; wscat -c ws://172.17.0.2:8000; date

Fri Mar 17 12:10:59 EET 2017

connected (press CTRL+C to quit)

> foo

< bar

disconnected

Fri Mar 17 12:26:03 EET 2017


State of the session about 30 seconds after starting the above command:
$ echo "show sess" | socat /run/haproxy.sock stdio

0x12253b0: proto=tcpv4 src=172.17.0.1:52046 fe=ws_test be=ws_test srv=wscat ts=08 age=31s calls=4 rq[f=8848202h,i=0,an=00h,rx=14m32s,wx=,ax=] rp[f=88048202h,i=0,an=00h,rx=14m32s,wx=,ax=] s0=[7,8h,fd=1,ex=] s1=[7,118h,fd=2,ex=] exp=14m29s




With HAProxy v1.7.3 running the same config I see the following:

$ date; wscat -c ws://172.17.0.3:8000; date

Fri Mar 17 12:29:39 EET 2017

connected (press CTRL+C to quit)

> foo

< bar

disconnected

Fri Mar 17 12:30:33 EET 2017



Obviously it takes me a bit of time to send the 2 strings manually, so total time is a bit more than the "timeout client" value here.



State of the session about 30 seconds after starting the above command:

$ echo "show sess" | socat /run/haproxy.sock stdio

0x22a4f10: proto=tcpv4 src=172.17.0.1:55996 fe=ws_test be=ws_test srv=wscat ts=04 age=33s calls=6 rq[f=8848000h,i=0,an=00h,rx=20s,wx=,ax=] rp[f=88048000h,i=0,an=00h,rx=30s,wx=,ax=] s0=[7,8h,fd=1,ex=] s1=[7,118h,fd=2,ex=] exp=20s





If I remove the compression lines from the config and try again with HAProxy v1.7.3, then it's fine again:

$ date; wscat -c ws://172.17.0.3:8000; date

Fri Mar 17 12:35:22 EET 2017

connected (press CTRL+C to quit)

> foo

< bar

disconnected

Fri Mar 17 12:50:26 EET 2017



State of the session about 30 seconds after starting the above command:

$ echo "show sess" | socat /run/haproxy.sock stdio

0x1e64500: proto=tcpv4 src=172.17.0.1:56038 fe=ws_test be=ws_test srv=wscat ts=04 age=31s calls=5 rq[f=8848000h,i=0,an=00h,rx=14m33s,wx=,ax=] rp[f=88048000h,i=0,an=00h,rx=14m33s,wx=,ax=] s0=[7,8h,fd=1,ex=] s1=[7,118h,fd=2,ex=] exp=14m33s



I'll be happy to provide any additional information if needed.





--

Kristjan
Hello Krisjan,



Thank you for posting this issue that helped us isolate our issue as well.





Hello HAProxy Developers,



We are seeking your assistance to overcome this issue. This would enable our WebSocket product benefit from HTTP compression.



· Our WebSocket product that was working through 1.6.x, started reloading through 1.7.3 every 35 seconds—the value assigned to timeout client / server (defaults). When compression algo (defaults) is removed, timeout tunnel (backend) is effective.

· Other non-WebSocket products are working fine even with compression algo (defaults) and timeout tunnel (backend). Our HAProxy is compiled with USE_ZLIB=1 (not SLZ).



Thank you.



Sincerely,



Hemant K. Sabat



Coscend Communications Solutions

Web site: www.Coscend.com http://www.coscend.com/

------------------------------------------------------------------

Real-time, Interactive Video Collaboration, Tele-healthcare, Tele-education, Telepresence Services, on the fly…

------------------------------------------------------------------

CONFIDENTIALITY NOTICE: See 'Confidentiality Notice Regarding E-mail Messages from Coscend Communications Solutions' posted at: http://www.Coscend.com/Terms_and_Conditions.html





From: Kristjan Koppel [mailto:[email protected]]
Sent: Friday, March 17, 2017 5:57 AM
To: haproxy <[email protected]>
Subject: WebSocket + compression + timeout tunnel broken in v1.7?



Hi!



I upgraded a HAProxy instance from v1.6.10 to v1.7.3 with no changes to configuration and I noticed that now clients connecting to a WebSocket backend are getting disconnected after being idle for "timeout client" time rather than the much longer "timeout tunnel" time. As I understand it, "timeout tunnel" is supposed to override the "timeout client" setting for WebSocket sessions and this worked fine with v1.6 and earlier.



Also, this HAProxy instance has compression enabled in the defaults section. If I remove the compression settings from there (or if I move them to other backends only), then "timeout tunnel" starts to work again. So, I guess this is a bug in HAProxy v1.7?



I managed to reproduce this with the official HAProxy Docker images, a minimal haproxy.cfg and wscat (from the Debian package node-ws) as follows:



haproxy.cfg:

global

stats socket /run/haproxy.sock mode 660 level admin

stats timeout 30s

daemon



defaults

mode http

timeout connect 5s

timeout client 50s

timeout server 60s

timeout tunnel 15m



compression algo gzip

compression type text/html



listen ws_test

bind :8000

server wscat 172.17.0.1:8001





I started one wscat instance in listening mode for the backend:

$ wscat -l 8001



With HAProxy v1.6.11 running the above config I see the following:

$ date; wscat -c ws://172.17.0.2:8000; date

Fri Mar 17 12:10:59 EET 2017

connected (press CTRL+C to quit)

> foo

< bar

disconnected

Fri Mar 17 12:26:03 EET 2017

State of the session about 30 seconds after starting the above command:

$ echo "show sess" | socat /run/haproxy.sock stdio

0x12253b0: proto=tcpv4 src=172.17.0.1:52046 fe=ws_test be=ws_test srv=wscat ts=08 age=31s calls=4 rq[f=8848202h,i=0,an=00h,rx=14m32s,wx=,ax=] rp[f=88048202h,i=0,an=00h,rx=14m32s,wx=,ax=] s0=[7,8h,fd=1,ex=] s1=[7,118h,fd=2,ex=] exp=14m29s



With HAProxy v1.7.3 running the same config I see the following:

$ date; wscat -c ws://172.17.0.3:8000; date

Fri Mar 17 12:29:39 EET 2017

connected (press CTRL+C to quit)

> foo

< bar

disconnected

Fri Mar 17 12:30:33 EET 2017



Obviously it takes me a bit of time to send the 2 strings manually, so total time is a bit more than the "timeout client" value here.



State of the session about 30 seconds after starting the above command:

$ echo "show sess" | socat /run/haproxy.sock stdio

0x22a4f10: proto=tcpv4 src=172.17.0.1:55996 fe=ws_test be=ws_test srv=wscat ts=04 age=33s calls=6 rq[f=8848000h,i=0,an=00h,rx=20s,wx=,ax=] rp[f=88048000h,i=0,an=00h,rx=30s,wx=,ax=] s0=[7,8h,fd=1,ex=] s1=[7,118h,fd=2,ex=] exp=20s





If I remove the compression lines from the config and try again with HAProxy v1.7.3, then it's fine again:

$ date; wscat -c ws://172.17.0.3:8000; date

Fri Mar 17 12:35:22 EET 2017

connected (press CTRL+C to quit)

> foo

< bar

disconnected

Fri Mar 17 12:50:26 EET 2017



State of the session about 30 seconds after starting the above command:

$ echo "show sess" | socat /run/haproxy.sock stdio

0x1e64500: proto=tcpv4 src=172.17.0.1:56038 fe=ws_test be=ws_test srv=wscat ts=04 age=31s calls=5 rq[f=8848000h,i=0,an=00h,rx=14m33s,wx=,ax=] rp[f=88048000h,i=0,an=00h,rx=14m33s,wx=,ax=] s0=[7,8h,fd=1,ex=] s1=[7,118h,fd=2,ex=] exp=14m33s



I'll be happy to provide any additional information if needed.





--

Kristjan



No virus found in this message.
Checked by AVG - www.avg.com http://www.avg.com/email-signature
Version: 2016.0.8007 / Virus Database: 4756/14130 - Release Date: 03/17/17
Christopher Faulet
Re: WebSocket + compression + timeout tunnel broken in v1.7?
March 20, 2017 10:40AM
Le 17/03/2017 à 11:57, Kristjan Koppel a écrit :
> Hi!
>
> I upgraded a HAProxy instance from v1.6.10 to v1.7.3 with no changes to
> configuration and I noticed that now clients connecting to a WebSocket
> backend are getting disconnected after being idle for "timeout client"
> time rather than the much longer "timeout tunnel" time. As I understand
> it, "timeout tunnel" is supposed to override the "timeout client"
> setting for WebSocket sessions and this worked fine with v1.6 and earlier.
>
> Also, this HAProxy instance has compression enabled in the defaults
> section. If I remove the compression settings from there (or if I move
> them to other backends only), then "timeout tunnel" starts to work
> again. So, I guess this is a bug in HAProxy v1.7?
>
> I managed to reproduce this with the official HAProxy Docker images, a
> minimal haproxy.cfg and wscat (from the Debian package node-ws) as follows:
>
> haproxy.cfg:
> global
> stats socket /run/haproxy.sock mode 660 level admin
> stats timeout 30s
> daemon
>
> defaults
> mode http
> timeout connect 5s
> timeout client 50s
> timeout server 60s
> timeout tunnel 15m
>
> compression algo gzip
> compression type text/html
>
> listen ws_test
> bind :8000
> server wscat 172.17.0.1:8001
>
>
> I started one wscat instance in listening mode for the backend:
> $ wscat -l 8001
>
> With HAProxy v1.6.11 running the above config I see the following:
> $ date; wscat -c ws://172.17.0.2:8000; date
> Fri Mar 17 12:10:59 EET 2017
> connected (press CTRL+C to quit)
>> foo
> < bar
> disconnected
> Fri Mar 17 12:26:03 EET 2017
>
> State of the session about 30 seconds after starting the above command:
> $ echo "show sess" | socat /run/haproxy.sock stdio
> 0x12253b0: proto=tcpv4 src=172.17.0.1:52046 fe=ws_test be=ws_test
> srv=wscat ts=08 age=31s calls=4
> rq[f=8848202h,i=0,an=00h,rx=14m32s,wx=,ax=]
> rp[f=88048202h,i=0,an=00h,rx=14m32s,wx=,ax=] s0=[7,8h,fd=1,ex=]
> s1=[7,118h,fd=2,ex=] exp=14m29s
>
>
> With HAProxy v1.7.3 running the same config I see the following:
> $ date; wscat -c ws://172.17.0.3:8000; date
> Fri Mar 17 12:29:39 EET 2017
> connected (press CTRL+C to quit)
>> foo
> < bar
> disconnected
> Fri Mar 17 12:30:33 EET 2017
>
> Obviously it takes me a bit of time to send the 2 strings manually, so
> total time is a bit more than the "timeout client" value here.
>
> State of the session about 30 seconds after starting the above command:
> $ echo "show sess" | socat /run/haproxy.sock stdio
> 0x22a4f10: proto=tcpv4 src=172.17.0.1:55996 fe=ws_test be=ws_test
> srv=wscat ts=04 age=33s calls=6 rq[f=8848000h,i=0,an=00h,rx=20s,wx=,ax=]
> rp[f=88048000h,i=0,an=00h,rx=30s,wx=,ax=] s0=[7,8h,fd=1,ex=]
> s1=[7,118h,fd=2,ex=] exp=20s
>
>
> If I remove the compression lines from the config and try again with
> HAProxy v1.7.3, then it's fine again:
> $ date; wscat -c ws://172.17.0.3:8000; date
> Fri Mar 17 12:35:22 EET 2017
> connected (press CTRL+C to quit)
>> foo
> < bar
> disconnected
> Fri Mar 17 12:50:26 EET 2017
>
> State of the session about 30 seconds after starting the above command:
> $ echo "show sess" | socat /run/haproxy.sock stdio
> 0x1e64500: proto=tcpv4 src=172.17.0.1:56038 fe=ws_test be=ws_test
> srv=wscat ts=04 age=31s calls=5
> rq[f=8848000h,i=0,an=00h,rx=14m33s,wx=,ax=]
> rp[f=88048000h,i=0,an=00h,rx=14m33s,wx=,ax=] s0=[7,8h,fd=1,ex=]
> s1=[7,118h,fd=2,ex=] exp=14m33s
>
> I'll be happy to provide any additional information if needed.
>

Hi Kristjan,

Thanks for this detailed report. You're right. This is a bug and it was
fixed in 1.8. It will soon be backported in 1.7. If you're curious, the
commit fixing the bug is e600624 ("BUG/MEDIUM: filters: Fix channels
synchronization in flt_end_analyze"). You can safely apply it on 1.7.3.

--
Christopher Faulet
On Mon, Mar 20, 2017 at 10:28:41AM +0100, Christopher Faulet wrote:
> Thanks for this detailed report. You're right. This is a bug and it was
> fixed in 1.8. It will soon be backported in 1.7. If you're curious, the
> commit fixing the bug is e600624 ("BUG/MEDIUM: filters: Fix channels
> synchronization in flt_end_analyze"). You can safely apply it on 1.7.3.

Thanks for confirming it's the same one. I need a bit of time to finish
merging all pending fixes and backport them to 1.7 (and sometimes 1.6
and even 1.5). One less bug to hunt :-)

Willy
Kristjan Koppel
Re: WebSocket + compression + timeout tunnel broken in v1.7?
March 21, 2017 02:10PM
Hi!


---- On Tue, 21 Mar 2017 08:46:57 +0200 Willy Tarreau &lt;[email protected]&gt; wrote ----



On Mon, Mar 20, 2017 at 10:28:41AM +0100, Christopher Faulet wrote:

&gt; Thanks for this detailed report. You're right. This is a bug and it was

&gt; fixed in 1.8. It will soon be backported in 1.7. If you're curious, the

&gt; commit fixing the bug is e600624 ("BUG/MEDIUM: filters: Fix channels

&gt; synchronization in flt_end_analyze"). You can safely apply it on 1.7.3.



Thanks for confirming it's the same one. I need a bit of time to finish

merging all pending fixes and backport them to 1.7 (and sometimes 1.6

and even 1.5). One less bug to hunt :-)




I can also confirm that this change fixes the problem for me in v1.7.3.
Thank you both for your awesome work!





--

Kristjan
On Tue, Mar 21, 2017 at 03:07:37PM +0200, Kristjan Koppel wrote:
(...)
> I can also confirm that this change fixes the problem for me in v1.7.3.

Thanks for confirming, it's always encouraging!

Willy
Sorry, only registered users may post in this forum.

Click here to login