Hi Christopher,
I just tried with a single limit on a single table (50m per 10s).
Unfortunately, it looks like the behavior persists.
Interestingly enough…the an_exp in this case is now 12m!
0x558271832070: [08/Sep/2023:11:47:38.760889] id=7741 proto=quic6
source=CLIENT:51574
flags=0x100c4a, conn_retries=0, conn_exp=<NEVER> conn_et=0x000
srv_conn=0x558270cccb10, pend_pos=(nil) waiting=0 epoch=0
frontend=stadiamaps (id=3 mode=http), listener=? (id=2) addr=SRV:443
backend=varnish (id=4 mode=http) addr=unix
server=varnish_local (id=1) addr=unix
task=0x558271694760 (state=0x00 nice=0 calls=2 rate=0 exp=12m51s tid=0(1/0)
age=7m54s)
txn=0x5582712b98c0 flags=0x843000 meth=1 status=200 req.st=MSG_DONE
rsp.st=MSG_DATA req.f=0x4c rsp.f=0x0d
scf=0x558270ffbe60 flags=0x00002402 state=EST
endp=CONN,0x558270e48250,0x05205001 sub=1 rex=? wex=<NEVER>
qcs=0x558270e48250 .flg=0x101 .id=0 .st=HCR .ctx=0x558270f48290, .err=0
qcc=0x55827119a3c0 .flg=0 .nbsc=2 .nbhreq=2, .task=0x558271836dc0
co0=0x5582717a0f70 ctrl=quic6 xprt=QUIC mux=QUIC data=STRM
target=LISTENER:0x558270438dc0
flags=0x80200300 fd=-1 fd.state=00 updt=0 fd.tmask=0x0
scb=0x55827167e4d0 flags=0x00001013 state=EST
endp=CONN,0x558271769980,0x05004001 sub=1 rex=? wex=<NEVER>
h1s=0x558271769980 h1s.flg=0x4090 .sd.flg=0x5004001 .req.state=MSG_DONE
.res.state=MSG_DONE
.meth=GET status=200 .sd.flg=0x05004001 .sc.flg=0x00001013
.sc.app=0x558271832070
.subs=0x55827167e4e8(ev=1 tl=0x558270f897b0 tl.calls=2
tl.ctx=0x55827167e4d0 tl.fct=sc_conn_io_cb)
h1c=0x5582715c3d90 h1c.flg=0x80000000 .sub=0 .ibuf=0@(nil)+0/0
.obuf=0@(nil)+0/0 .task=0x5582711a8e70 .exp=<NEVER>
co1=0x558270fe8930 ctrl=unix_stream xprt=RAW mux=H1 data=STRM
target=SERVER:0x558270cccb10
flags=0x00000300 fd=200 fd.state=1122 updt=0 fd.tmask=0x1
req=0x558271832090 (f=0x20848000 an=0x48000 pipe=0 tofwd=0 total=380)
an_exp=<NEVER> buf=0x558271832098 data=(nil) o=0 p=0 i=0 size=0
htx=0x55826f803860 flags=0x0 size=0 data=0 used=0 wrap=NO extra=0
res=0x5582718320e0 (f=0xa0040000 an=0x24000000 pipe=0 tofwd=0 total=7032)
an_exp=12m51s buf=0x5582718320e8 data=0x558270fb0000 o=0 p=0 i=16384
size=16384
htx=0x558270fb0000 flags=0x14 size=16336 data=6558 used=1 wrap=NO extra=0
Thanks for your help so far. I'll just leave this disabled and keep trying
things over the next few days if there isn't any obvious solution. :)
Best,
Luke
—
Luke Seelenbinder
Stadia Maps | Founder & CEO
stadiamaps.com
> On Sep 8, 2023, at 14:23, Christopher Faulet <[email protected]> wrote:
>
> Le 08/09/2023 à 13:42, Luke Seelenbinder a écrit :
>> Hi Christopher,
>> Thanks for the hint. I was able to replicate it and capture the following
>> from `show sess all`:
>> 0x562d78315da0: [08/Sep/2023:11:33:40.093147] id=32890 proto=tcpv4
>> source=<CLIENTIP>:34452
>> flags=0x100c4a, conn_retries=0, conn_exp=<NEVER> conn_et=0x000
>> srv_conn=0x562d77d74d60, pend_pos=(nil) waiting=0 epoch=0x3
>> frontend=stadiamaps (id=3 mode=http), listener=? (id=3) addr=<SRVIP>:443
>> backend=varnish (id=4 mode=http) addr=unix
>> server=varnish_local (id=1) addr=unix
>> task=0x562d781fba60 (state=0x00 nice=0 calls=2 rate=0 exp=38s tid=0(1/0)
>> age=21s)
>> txn=0x562d78373dc0 flags=0x843000 meth=1 status=404 req.st=MSG_DONE
>> rsp.st=MSG_DATA req.f=0x4c rsp.f=0x0d
>> scf=0x562d780c0fd0 flags=0x00002402 state=EST
>> endp=CONN,0x562d782bd030,0x05005001 sub=1 rex=2m38s wex=<NEVER>
>> h2s=0x562d782bd030 h2s.id=1 .st=HCR .flg=0x7001 .rxbuf=0@(nil)+0/0
>> .sc=0x562d780c0fd0(.flg=0x00002402 .app=0x562d78315da0)
>> .sd=0x562d78a50490(.flg=0x05005001)
>> .subs=0x562d780c0fe8(ev=1 tl=0x562d78655590 tl.calls=0
>> tl.ctx=0x562d780c0fd0 tl.fct=sc_conn_io_cb)
>> h2c=0x562d78843ea0 h2c.st0=FRH .err=0 .maxid=1 .lastid=-1 .flg=0x0200
>> .nbst=1 .nbsc=1
>> .fctl_cnt=0 .send_cnt=0 .tree_cnt=1 .orph_cnt=0 .sub=1 .dsi=0
>> .dbuf=0@(nil)+0/0
>> .mbuf=[1..1|32],h=[0@(nil)+0/0],t=[0@(nil)+0/0] .task=0x562d78f317f0
>> .exp=<NEVER>
>> co0=0x562d783e5d70 ctrl=tcpv4 xprt=SSL mux=H2 data=STRM
>> target=LISTENER:0x562d774e7ec0
>> flags=0x80000300 fd=209 fd.state=121 updt=0 fd.tmask=0x1
>> scb=0x562d78022fb0 flags=0x00001013 state=EST
>> endp=CONN,0x562d77fad040,0x05004001 sub=1 rex=38s wex=<NEVER>
>> h1s=0x562d77fad040 h1s.flg=0x4090 .sd.flg=0x5004001
>> .req.state=MSG_DONE .res.state=MSG_DONE
>> .meth=GET status=404 .sd.flg=0x05004001 .sc.flg=0x00001013
>> .sc.app=0x562d78315da0
>> .subs=0x562d78022fc8(ev=1 tl=0x562d785fbbb0 tl.calls=2
>> tl.ctx=0x562d78022fb0 tl.fct=sc_conn_io_cb)
>> h1c=0x562d78f71f70 h1c.flg=0x80000000 .sub=0 .ibuf=0@(nil)+0/0
>> .obuf=0@(nil)+0/0 .task=0x562d78c95990 .exp=<NEVER>
>> co1=0x562d78955070 ctrl=unix_stream xprt=RAW mux=H1 data=STRM
>> target=SERVER:0x562d77d74d60
>> flags=0x00000300 fd=172 fd.state=120 updt=0 fd.tmask=0x1
>> req=0x562d78315dc0 (f=0x20848000 an=0x48000 pipe=0 tofwd=0 total=158)
>> an_exp=<NEVER> buf=0x562d78315dc8 data=(nil) o=0 p=0 i=0 size=0
>> htx=0x562d7641d860 flags=0x0 size=0 data=0 used=0 wrap=NO extra=0
>> res=0x562d78315e10 (f=0xa0040000 an=0x24000000 pipe=0 tofwd=0 total=498)
>> an_exp=1m41s buf=0x562d78315e18 data=0x562d78a25f50 o=0 p=0 i=16384
>> size=16384
>> htx=0x562d78a25f50 flags=0x14 size=16336 data=301 used=1 wrap=NO
>> extra=0
>> Anything obvious to you? The data size is 301 bytes and it just hangs after
>> receiving headers for a few seconds (more than 6, but I'm not sure exactly
>> how many). It seems to flush the buffer as soon as some timeout triggers.
>> I'm still on 2.8.2, and based on what you said, it shouldn't matter for this
>> .
>
> Indeed, it is not related to any fixed bug.
>
> The response "an_exp" expiration date is quite huge (1m41s). But I didn't
> notice it at first. You have configured 2 bwlim-out filters to use the same
> table with different limits. So I guess it is possible to block some streams
> for a while if its rate exceeds the first limit (50m on 10s) because the same
> source address is already limited by the second limit (100m on 10s).
>
> This kind of configuration cannot work.
> --
> Christopher Faulet
