AW: 400 SC on h2 xhr post
N¬Æ§Kó0K"wë,j»÷Pý:]xÐAãPÓNûm¸ S¡h¥$Ú®·»
pµë
©®r~æ[±¢¸!jèÇ'è®h¥»++ç-n4Ñ ¨ ±ºh²ÐÚµákoLj½´×ÝtãÝ·ûM4Ð*'µéí-©à¹¨ uàÄ
íz{SÊ{¦V¢ÈZ®Ç
AW: 400 SC on h2 xhr post
N¬Æ§Kó0K"wë,j¼Ô@ÂÔN5à ApÀ<`<à1ï°¢©®r~æ[±¢¸!jèÇ'è®h¥»++ç-n4Ñ
¨ ±ºh²ÐÚµäî{nj½´×Ýy×;ûM4Ð*'µéí-©à¹¨ uàÄ
íz{SÊ{¦V¢ÈZ®Ç
AW: 400 SC on h2 xhr post
N¬Æ§Kó0K"wë,j¸ßÎuä>Aß~ã@µ .û ½EØÅï@Ó «îºÉ(éãj¹èë¬Þç~
ªk£ ¢¹¢ìh®Z¦º1Éú+)nÆàJæãyË@[4H*'la®,´6y;Û£¯m5÷^9ë}>ÓM4
íz{Kjx.jx1¢{^Ôò¥ë^Æß騧r«±ë
AW: 400 SC on h2 xhr post
Hello Jarno,
thanks for your suggestions. It was not successful.
However, I managed to make it reproductible. I would be really happy, if
someone more experienced would take a look on this.
Setup
Client (Chrome) -> Haproxy (Docker) -> Jetty (Docker)
The client executes following script, it can be saved on the local disk, we can
ignore the CORS logging. Do not change the '3', otherwise it will not occur.
function loopMe () {
setTimeout(function () {
var xhr = new XMLHttpRequest();
xhr.open('POST', 'https://[DOMAIN]/app/docker-jetty.json');
xhr.send();
loopMe();
}, 3)
}
loopMe();
Haproxy.cfg
global
daemon
tune.ssl.default-dh-param 2048
stats socket /var/run/haproxy.stat
defaults
mode http
option httplog
log stdout format raw daemon
timeout connect 5m
timeout client 5m
timeout server 5m
frontend frontend_h2
bind *:443 ssl crt /usr/local/etc/haproxy/ssl/ alpn h2,http/1.1
use_backend backend_jetty
backend backend_jetty
server web850 127.0.0.1:81
Commands for starting the container
1) docker run -p 443:443 -v [LOCAL_DIR_HAPROXY]:/usr/local/etc/haproxy/ -it
haproxy:1.9.4
2) docker run -d --name jetty -v [LOCAL_DIR_JETTY]:/var/lib/jetty/webapps -p
81:8080 jetty
Substitute the following variables:
1) [DOMAIN]: Domain you have a certificate for or generate one
2) [LOCAL_DIR_HAPROXY]: Local directory where you need to put the "haproxy.cfg"
and your certificate (subdirectory "ssl")
3) [LOCAL_DIR_JETTY]: Local directory, create a subdirectory called "app" and
create an empty file named "docker-jetty.json").
Substitute the variables, start the container and open the script in the
browser. After 10-15 requests you should get a SC 400
At first sight, it looks like jetty is doing something terribly wrong. But, and
that's the problem, it does not occur if I have just http/1.1 enabled between
the client and haproxy. Any ideas?
Thanks,
Max
-Ursprüngliche Nachricht-
Von: Jarno Huuskonen
Gesendet: Mittwoch, 20. März 2019 12:59
An: Maximilian Böhm
Cc: haproxy@formilux.org
Betreff: Re: 400 SC on h2 xhr post
Hi Max,
On Wed, Mar 20, Maximilian Böhm wrote:
> >> If the 400 errors happen within 3mins, have you tried changing
> >> client/keep-alive timeouts to see if anything changes ?
> They do most often happen in the first 3 mins. But that's not always the
> case. And if it's really a timeout, shouldn't it be more clearly recurring?
> Like every tenth request fails. But that's also not the case. Sometimes it's
> the 3rd request, sometimes the 20th or even later.
> However, I did increase the previously set timeouts (40min). But this did not
> change anything at all. Is there another timeout which explicitly only
> affects h2 on the client side?
I'm not aware of any more timeouts to test. I think possible timeouts are in
https://cbonte.github.io/haproxy-dconv/1.9/configuration.html#4.1
Have you tested different values for http-reuse (never to always) ?
(https://cbonte.github.io/haproxy-dconv/1.9/configuration.html#4.2-http-reuse)
(Probably doesn't make any difference).
This could be related to
https://www.mail-archive.com/haproxy@formilux.org/msg32959.html
that test case also returns 400 error with state CH-- with http2.
-Jarno
> -Ursprüngliche Nachricht-
> Von: Jarno Huuskonen
> Gesendet: Dienstag, 19. März 2019 17:34
> An: Maximilian Böhm
> Cc: haproxy@formilux.org
> Betreff: Re: 400 SC on h2 xhr post
>
> Hi,
>
> On Tue, Mar 19, Maximilian Böhm wrote:
> > The problem I experience is within a legacy javascript application which
> > periodically checks if the user is still logged in. It does so by sending
> > an xhr request every 30 seconds (I said, it's a legacy app, right? It does
> > so by POST not GET...). As you may guess, this behavior works using http1.1
> > quasi infinitely. But as soon as I activate HTTP/2, I'll get the following
> > output (sooner or later):
> > 172.17.0.1:46372 [19/Mar/2019:12:10:13.465] [fntnd] [bknd] 0/0/0/14/14 200
> > 368 - - 1/1/0/1/0 0/0 "POST [URL] HTTP/1.1"
> > 172.17.0.1:46372 [19/Mar/2019:12:10:43.465] [fntnd] [bknd] 0/0/0/-1/8 400
> > 187 - - CH-- 1/1/0/0/0 0/0 "POST [URL] HTTP/1.1"
> >
> > Which means, the developer toolbar announces a response code "400" and
> > "400 Bad requestYour browser sent an invalid
> > request.". I was not yet successful reproduce this behavior
> > with OkHttp (java http2-capable library). Jetty - on the backend site -
> > does not report any requests in its ncsa request log.
>
> I've seen some(very few (maybe one-two a day)) 400 bad requests with haproxy
> 1.9.4 (http2) to apache+php (http/1.1) backend. These requests alos have CH..
> state in logs.
> (400 errors have also happened for GET requests).
>
> > It is not directly reproducible (like every second time) but it
AW: 400 SC on h2 xhr post
Hello Jarno, >> If the 400 errors happen within 3mins, have you tried changing >> client/keep-alive timeouts to see if anything changes ? They do most often happen in the first 3 mins. But that's not always the case. And if it's really a timeout, shouldn't it be more clearly recurring? Like every tenth request fails. But that's also not the case. Sometimes it's the 3rd request, sometimes the 20th or even later. However, I did increase the previously set timeouts (40min). But this did not change anything at all. Is there another timeout which explicitly only affects h2 on the client side? Thanks, Max -Ursprüngliche Nachricht- Von: Jarno Huuskonen Gesendet: Dienstag, 19. März 2019 17:34 An: Maximilian Böhm Cc: haproxy@formilux.org Betreff: Re: 400 SC on h2 xhr post Hi, On Tue, Mar 19, Maximilian Böhm wrote: > The problem I experience is within a legacy javascript application which > periodically checks if the user is still logged in. It does so by sending an > xhr request every 30 seconds (I said, it's a legacy app, right? It does so by > POST not GET...). As you may guess, this behavior works using http1.1 quasi > infinitely. But as soon as I activate HTTP/2, I'll get the following output > (sooner or later): > 172.17.0.1:46372 [19/Mar/2019:12:10:13.465] [fntnd] [bknd] 0/0/0/14/14 200 > 368 - - 1/1/0/1/0 0/0 "POST [URL] HTTP/1.1" > 172.17.0.1:46372 [19/Mar/2019:12:10:43.465] [fntnd] [bknd] 0/0/0/-1/8 400 187 > - - CH-- 1/1/0/0/0 0/0 "POST [URL] HTTP/1.1" > > Which means, the developer toolbar announces a response code "400" and > "400 Bad requestYour browser sent an invalid > request.". I was not yet successful reproduce this behavior > with OkHttp (java http2-capable library). Jetty - on the backend site - does > not report any requests in its ncsa request log. I've seen some(very few (maybe one-two a day)) 400 bad requests with haproxy 1.9.4 (http2) to apache+php (http/1.1) backend. These requests alos have CH.. state in logs. (400 errors have also happened for GET requests). > It is not directly reproducible (like every second time) but it usually > happens with the first 3 minutes. I experienced this behavior in Chrome > (73.0.3683.75), Firefox (65.0.2 (32-Bit)) and Edge (44.17763.1.0). I also > tried with different networks and different internet connections. > > Any ideas? Maybe a similar bug is known? What shall/can I do next? Setting up > Wireshark with MITM and comparing the requests? Right now, I can't imagine > the error is on side of the client nor on the backend (the backend is not > changed). If the 400 errors happen within 3mins, have you tried changing client/keep-alive timeouts to see if anything changes ? > timeout queue 2m > timeout client 2m > timeout http-keep-alive 2m -Jarno -- Jarno Huuskonen smime.p7s Description: S/MIME cryptographic signature
AW: 400 SC on h2 xhr post
Hello Willy, thanks for your suggestions. >> There are two things you can try : >> 1) please issue "show errors" on your CLI when this happens >> 2) you can enable the HTX mode I did both. Though It was not really a success... What could I do next? Everything - browser, docker/haproxy and the jetty application are running on the same machine, there is no wire in between... (ok, except the database, but I do not have a request reaching the servlet). 172.17.0.1:47340 [19/Mar/2019:15:03:49.755] [FRONTEND] [BACKEND]/web850 0/0/0/-1/13 400 191 - - CH-- 1/1/0/0/0 0/0 "POST [URL] HTTP/2.0" root@ad23bb7939a9:/# echo "show errors" | socat unix-connect:/var/run/haproxy.stat stdio Total events captured on [19/Mar/2019:15:04:05.665] : 0 root@ad23bb7939a9:/# echo "show sess" | socat unix-connect:/var/run/haproxy.stat stdio 0x5604be62deb0: proto=unix_stream src=unix:1 fe=GLOBAL be= srv= ts age=0s calls=1 cpu=0 lat=0 rq[fÀc220h,i=0,an h,rx=,wx=,ax=] rp[f008000h,i=0,an h,rx=,wx=,ax=] s0=[7,80008h,fd,ex=] s1=[7,204018h,fd=-1,ex=] exp root@ad23bb7939a9:/# echo "show stat" | socat unix-connect:/var/run/haproxy.stat stdio # pxname,svname,qcur,qmax,scur,smax,slim,stot,bin,bout,dreq,dresp,ereq,econ,eresp,wretr,wredis,status,weight,act,bck,chkfail,chkdown,lastchg,downtime,qlimit,pid,iid,sid,throttle,lbtot,tracked,type,rate,rate_lim,rate_max,check_status,check_code,check_duration,hrsp_1xx,hrsp_2xx,hrsp_3xx,hrsp_4xx,hrsp_5xx,hrsp_other,hanafail,req_rate,req_rate_max,req_tot,cli_abrt,srv_abrt,comp_in,comp_out,comp_byp,comp_rsp,lastsess,last_chk,last_agt,qtime,ctime,rtime,ttime,agent_status,agent_code,agent_duration,check_desc,agent_desc,check_rise,check_fall,check_health,agent_rise,agent_fall,agent_health,addr,cookie,mode,algo,conn_rate,conn_rate_max,conn_tot,intercepted,dcon,dses,wrew,connect,reuse,cache_lookups,cache_hits, frontend_https-sni,FRONTEND,,,1,1,2000,1,119357,1935662,0,0,0,OPEN,1,2,00,0,0,10,147,0,1,0,0,,0,28,148,,,0,0,0,0,http,,0,1,1,0,0,0,0,,,0,0, [BACKEND],[XXX],0,0,0,11,,148,119357,1935662,,0,,0,0,0,0,no check,1,1,0,,,492,,,1,3,1,,148,,2,0,,280,147,0,0,0,0,1,0,8,,,0,1,16,784172.18.11.102:80,,http0,27,121,,, [BACKEND],BACKEND,0,0,0,11,200,148,119357,1935662,0,0,,0,0,0,0,UP,1,1,0,,0,492,0,,1,3,0,,148,,1,0,,280,147,0,1,0,0148,1,0,0,0,0,0,8,,,0,1,16,784,,http,roundrobin,,,0,27,121,0,0, Which basically says there is one "hrsp_4xx". root@ad23bb7939a9:/# echo "show info" | socat unix-connect:/var/run/haproxy.stat stdio Name: HAProxy Version: 1.9.4 Release_date: 2019/02/06 Nbthread: 1 Nbproc: 1 Process_num: 1 Pid: 250 Uptime: 0d 0h12m56s Uptime_sec: 776 Memmax_MB: 0 PoolAlloc_MB: 0 PoolUsed_MB: 0 PoolFailed: 0 Ulimit-n: 4031 Maxsock: 4041 Maxconn: 2000 Hard_maxconn: 2000 CurrConns: 0 CumConns: 8 CumReq: 157 MaxSslConns: 0 CurrSslConns: 0 CumSslConns: 1 Maxpipes: 0 PipesUsed: 0 PipesFree: 0 ConnRate: 0 ConnRateLimit: 0 MaxConnRate: 1 SessRate: 0 SessRateLimit: 0 MaxSessRate: 1 SslRate: 0 SslRateLimit: 0 MaxSslRate: 1 SslFrontendKeyRate: 0 SslFrontendMaxKeyRate: 1 SslFrontendSessionReuse_pct: 0 SslBackendKeyRate: 0 SslBackendMaxKeyRate: 0 SslCacheLookups: 0 SslCacheMisses: 0 CompressBpsIn: 0 CompressBpsOut: 0 CompressBpsRateLim: 0 ZlibMemUsage: 0 MaxZlibMemUsage: 0 Tasks: 7 Run_queue: 1 Idle_pct: 100 node: ad23bb7939a9 Stopping: 0 Jobs: 4 Unstoppable Jobs: 0 Listeners: 3 ActivePeers: 0 ConnectedPeers: 0 DroppedLogs: 0 BusyPolling: 0 -Ursprüngliche Nachricht- Von: Willy Tarreau Gesendet: Dienstag, 19. März 2019 15:48 An: Maximilian Böhm Cc: haproxy@formilux.org Betreff: Re: 400 SC on h2 xhr post Hi Maximilian, On Tue, Mar 19, 2019 at 01:17:52PM +, Maximilian Böhm wrote: > 172.17.0.1:46372 [19/Mar/2019:12:10:43.465] [fntnd] [bknd] 0/0/0/-1/8 400 187 > - - CH-- 1/1/0/0/0 0/0 "POST [URL] HTTP/1.1" This one could indicate a client close while uploading the contents, but it could also actually be a side effect of the ambiguity we have at certain stages between an end of request and a close, and the short timings make me think about this. > Any ideas? Maybe a similar bug is known? Not directly known but could be related to something we're currently working on as indicated above. > What shall/can I do next? Setting up > Wireshark with MITM and comparing the requests? Right now, I can't > imagine the error is on side of the client nor on the backend (the > backend is not changed). There are two things you can try : 1) please issue "show errors" on your CLI when this happens, to see if you find a real client error captured there. It could be possible that something is invalid in the request and that it was blocked during the parsing (though quite unlikely). 2) you can enable the HTX mode which avoids the translation from H2 to H1 before processing the request. For this, please add "option http-use-htx" to your configuration and see if the problem goes away or becomes more
