Hi Willy,
After the commit "6ec902a MINOR: threads: serialize threads
initialization" however i have failing / slow health checks in the
tls_health_checks.vtc test. Before that the Layer7-OK takes 5ms after
this commit the healthcheck takes up to 75ms or even more.. It causes
the 20ms connect/server timeouts to also to fail the test fairly often
but not always..
Seems like something isn't quite right there. Can you check?
Regards,
PiBa-NL (Pieter)
Log can be seen below (p.s. i added milliseconds output also to the
vtest log.. ):
*** h2 0.299 debug|[WARNING] 157/231456 (78988) : Health check for
server be2/srv1 succeeded, reason: Layer7 check passed, code: 200, info:
"OK", check duration: 149ms, status: 1/1 UP.
## With HTX
* top 0.000 TEST
./work/haproxy-6ec902a/reg-tests/checks/tls_health_checks.vtc starting
**** top 0.000 extmacro def pwd=/usr/ports/net/haproxy-devel
**** top 0.000 extmacro def no-htx=
**** top 0.000 extmacro def localhost=127.0.0.1
**** top 0.000 extmacro def bad_backend=127.0.0.1 19775
**** top 0.000 extmacro def bad_ip=192.0.2.255
**** top 0.000 macro def
testdir=/usr/ports/net/haproxy-devel/./work/haproxy-6ec902a/reg-tests/checks
**** top 0.000 macro def tmpdir=/tmp/vtc.78981.41db79fd
** top 0.000 === varnishtest "Health-check test over TLS/SSL"
* top 0.000 VTEST Health-check test over TLS/SSL
** top 0.000 === feature ignore_unknown_macro
** top 0.000 === server s1 {
** s1 0.000 Starting server
**** s1 0.000 macro def s1_addr=127.0.0.1
**** s1 0.000 macro def s1_port=19776
**** s1 0.000 macro def s1_sock=127.0.0.1 19776
* s1 0.000 Listen on 127.0.0.1 19776
** top 0.001 === server s2 {
** s2 0.001 Starting server
**** s2 0.001 macro def s2_addr=127.0.0.1
**** s2 0.001 macro def s2_port=19777
**** s2 0.001 macro def s2_sock=127.0.0.1 19777
* s2 0.001 Listen on 127.0.0.1 19777
** top 0.002 === syslog S1 -level notice {
** S1 0.002 Starting syslog server
**** S1 0.002 macro def S1_addr=127.0.0.1
**** S1 0.002 macro def S1_port=14641
**** S1 0.002 macro def S1_sock=127.0.0.1 14641
* S1 0.002 Bound on 127.0.0.1 14641
** s2 0.002 Started on 127.0.0.1 19777 (1 iterations)
** s1 0.002 Started on 127.0.0.1 19776 (1 iterations)
** top 0.002 === haproxy h1 -conf {
** S1 0.002 Started on 127.0.0.1 14641 (level: 5)
** S1 0.002 === recv
**** h1 0.007 macro def h1_cli_sock=::1 19778
**** h1 0.007 macro def h1_cli_addr=::1
**** h1 0.007 macro def h1_cli_port=19778
**** h1 0.007 setenv(cli, 8)
**** h1 0.007 macro def h1_fe1_sock=::1 19779
**** h1 0.007 macro def h1_fe1_addr=::1
**** h1 0.007 macro def h1_fe1_port=19779
**** h1 0.007 setenv(fe1, 9)
**** h1 0.007 macro def h1_fe2_sock=::1 19780
**** h1 0.007 macro def h1_fe2_addr=::1
**** h1 0.007 macro def h1_fe2_port=19780
**** h1 0.007 setenv(fe2, 10)
** h1 0.007 haproxy_start
**** h1 0.007 opt_worker 0 opt_daemon 0 opt_check_mode 0
**** h1 0.007 argv|exec "haproxy" -d -f "/tmp/vtc.78981.41db79fd/h1/cfg"
**** h1 0.007 conf| global
**** h1 0.007 conf|\tstats socket
"/tmp/vtc.78981.41db79fd/h1/stats.sock" level admin mode 600
**** h1 0.007 conf| stats socket "fd@${cli}" level admin
**** h1 0.007 conf|
**** h1 0.007 conf| global
**** h1 0.007 conf| tune.ssl.default-dh-param 2048
**** h1 0.007 conf|
**** h1 0.007 conf| defaults
**** h1 0.007 conf| mode http
**** h1 0.007 conf| timeout client 20
**** h1 0.007 conf| timeout server 20
**** h1 0.007 conf| timeout connect 20
**** h1 0.007 conf|
**** h1 0.007 conf| backend be1
**** h1 0.007 conf| server srv1 127.0.0.1:19776
**** h1 0.007 conf|
**** h1 0.007 conf| backend be2
**** h1 0.007 conf| server srv2 127.0.0.1:19777
**** h1 0.007 conf|
**** h1 0.007 conf| frontend fe1
**** h1 0.007 conf| option httplog
**** h1 0.007 conf| log 127.0.0.1:14641 len 2048 local0 debug err
**** h1 0.007 conf| bind "fd@${fe1}" ssl crt
/usr/ports/net/haproxy-devel/./work/haproxy-6ec902a/reg-tests/checks/common.pem
**** h1 0.007 conf| use_backend be1
**** h1 0.007 conf|
**** h1 0.007 conf| frontend fe2
**** h1 0.007 conf| option tcplog
**** h1 0.007 conf| bind "fd@${fe2}" ssl crt
/usr/ports/net/haproxy-devel/./work/haproxy-6ec902a/reg-tests/checks/common.pem
**** h1 0.007 conf| use_backend be2
**** h1 0.007 XXX 12 @637
*** h1 0.008 PID: 78985
**** h1 0.008 macro def h1_pid=78985
**** h1 0.008 macro def h1_name=/tmp/vtc.78981.41db79fd/h1
** top 0.008 === syslog S2 -level notice {
** S2 0.008 Starting syslog server
**** S2 0.008 macro def S2_addr=127.0.0.1
**** S2 0.008 macro def S2_port=35409
**** S2 0.008 macro def S2_sock=127.0.0.1 35409
* S2 0.008 Bound on 127.0.0.1 35409
** top 0.009 === syslog S4 -level notice {
** S4 0.009 Starting syslog server
**** S4 0.009 macro def S4_addr=127.0.0.1
**** S4 0.009 macro def S4_port=38038
**** S4 0.009 macro def S4_sock=127.0.0.1 38038
* S4 0.009 Bound on 127.0.0.1 38038
** S2 0.009 Started on 127.0.0.1 35409 (level: 5)
** S2 0.009 === recv
** top 0.010 === haproxy h2 -conf {
** S4 0.010 Started on 127.0.0.1 38038 (level: 5)
** S4 0.010 === recv
**** h2 0.016 macro def h2_cli_sock=::1 19781
**** h2 0.016 macro def h2_cli_addr=::1
**** h2 0.016 macro def h2_cli_port=19781
**** h2 0.016 setenv(cli, 15)
** h2 0.016 haproxy_start
**** h2 0.016 opt_worker 0 opt_daemon 0 opt_check_mode 0
**** h2 0.016 argv|exec "haproxy" -d -f "/tmp/vtc.78981.41db79fd/h2/cfg"
**** h2 0.016 conf| global
**** h2 0.016 conf|\tstats socket
"/tmp/vtc.78981.41db79fd/h2/stats.sock" level admin mode 600
**** h2 0.016 conf| stats socket "fd@${cli}" level admin
**** h2 0.016 conf|
**** h2 0.016 conf| global
**** h2 0.016 conf| tune.ssl.default-dh-param 2048
**** h2 0.016 conf|
**** h2 0.016 conf| defaults
**** h2 0.016 conf| timeout client 20
**** h2 0.016 conf| timeout server 20
**** h2 0.016 conf| timeout connect 20
**** h2 0.016 conf| default-server downinter 1s inter 500 rise
1 fall 1
**** h2 0.016 conf|
**** h2 0.016 conf| backend be2
**** h2 0.016 conf| option log-health-checks
**** h2 0.016 conf| option httpchk OPTIONS *
HTTP/1.1\r\nHost:\ www
**** h2 0.016 conf| log 127.0.0.1:35409 daemon
**** h2 0.016 conf| server srv1 ::1:19779 ssl crt
/usr/ports/net/haproxy-devel/./work/haproxy-6ec902a/reg-tests/checks/common.pem
verify none check
**** h2 0.016 conf|
**** h2 0.016 conf| backend be4
**** h2 0.016 conf| option log-health-checks
**** h2 0.016 conf| log 127.0.0.1:38038 daemon
**** h2 0.016 conf| server srv2 ::1:19780 ssl crt
/usr/ports/net/haproxy-devel/./work/haproxy-6ec902a/reg-tests/checks/common.pem
verify none check-ssl check
**** h2 0.016 XXX 17 @637
*** h2 0.016 PID: 78988
**** h2 0.016 macro def h2_pid=78988
**** h2 0.016 macro def h2_name=/tmp/vtc.78981.41db79fd/h2
** top 0.017 === syslog S1 -wait
** S1 0.017 Waiting for syslog server (5)
*** h1 0.018 debug|[WARNING] 157/231456 (78985) : config : log
format ignored for frontend 'fe2' since it has no log address.
*** h1 0.020 debug|Note: setting global.maxconn to 117418.
*** h1 0.020 debug|Available polling systems :
*** h1 0.020 debug| kqueue : pref=300, test result OK
*** h1 0.020 debug| poll : pref=200, test result OK
*** h1 0.020 debug| select : pref=150, test result FAILED
*** h1 0.020 debug|Total: 3 (2 usable), will use kqueue.
*** h1 0.020 debug|
*** h1 0.020 debug|Available filters :
*** h1 0.020 debug|\t[SPOE] spoe
*** h1 0.020 debug|\t[COMP] compression
*** h1 0.020 debug|\t[CACHE] cache
*** h1 0.020 debug|\t[TRACE] trace
*** h2 0.025 debug|Note: setting global.maxconn to 117418.
*** h2 0.025 debug|Available polling systems :
*** h2 0.025 debug| kqueue : pref=300, test result OK
*** h2 0.025 debug| poll : pref=200, test result OK
*** h2 0.025 debug| select : pref=150, test result FAILED
*** h2 0.025 debug|Total: 3 (2 usable), will use kqueue.
*** h2 0.025 debug|
*** h2 0.025 debug|Available filters :
*** h2 0.025 debug|\t[SPOE] spoe
*** h2 0.025 debug|\t[COMP] compression
*** h2 0.025 debug|\t[CACHE] cache
*** h2 0.025 debug|\t[TRACE] trace
*** h1 0.026 debug|Using kqueue() as the polling mechanism.
**** S1 0.027 syslog|<133>Jun 7 23:14:56 haproxy[78985]: Proxy fe1
started.
** S1 0.027 === expect ~ "[^:\\[ ]\\[${h1_pid}\\]: Proxy fe1 started."
**** S1 0.027 EXPECT MATCH ~ "[^:\[ ]\[78985\]: Proxy fe1 started."
** S1 0.027 === recv info
*** h2 0.032 debug|Using kqueue() as the polling mechanism.
**** S2 0.033 syslog|<29>Jun 7 23:14:56 haproxy[78988]: Proxy be2
started.
** S2 0.033 === expect ~ "[^:\\[ ]\\[${h2_pid}\\]: Proxy be2 started."
**** S4 0.033 syslog|<29>Jun 7 23:14:56 haproxy[78988]: Proxy be4
started.
** S4 0.033 === expect ~ "[^:\\[ ]\\[${h2_pid}\\]: Proxy be4 started."
**** S4 0.033 EXPECT MATCH ~ "[^:\[ ]\[78988\]: Proxy be4 started."
** S4 0.033 === recv
**** S2 0.033 EXPECT MATCH ~ "[^:\[ ]\[78988\]: Proxy be2 started."
** S2 0.033 === recv
*** h1 0.296 debug|00000000:fe1.accept(0009)=0024 from [::1:19782]
ALPN=<none>
*** h1 0.299 debug|00000000:fe1.clireq[0024:ffffffff]: OPTIONS *
HTTP/1.1
*** h1 0.299 debug|00000000:fe1.clihdr[0024:ffffffff]: host: www
*** s1 0.299 accepted fd 7 127.0.0.1 19784
** s1 0.299 === rxreq
**** s1 0.299 rxhdr|OPTIONS * HTTP/1.1\r
**** s1 0.299 rxhdr|host: www\r
**** s1 0.299 rxhdr|\r
**** s1 0.299 rxhdrlen = 33
**** s1 0.299 http[ 0] |OPTIONS
**** s1 0.299 http[ 1] |*
**** s1 0.299 http[ 2] |HTTP/1.1
**** s1 0.299 http[ 3] |host: www
**** s1 0.299 bodylen = 0
** s1 0.299 === expect req.method == OPTIONS
**** s1 0.299 EXPECT req.method (OPTIONS) == "OPTIONS" match
** s1 0.299 === expect req.url == *
**** s1 0.299 EXPECT req.url (*) == "*" match
** s1 0.299 === expect req.proto == HTTP/1.1
**** s1 0.299 EXPECT req.proto (HTTP/1.1) == "HTTP/1.1" match
** s1 0.299 === txresp
**** s1 0.299 txresp|HTTP/1.1 200 OK\r
**** s1 0.299 txresp|Content-Length: 0\r
**** s1 0.299 txresp|\r
*** s1 0.299 shutting fd 7
** s1 0.299 Ending
*** h1 0.299 debug|00000000:be1.srvrep[0024:003d]: HTTP/1.1 200 OK
*** h1 0.299 debug|00000000:be1.srvhdr[0024:003d]: content-length: 0
*** h1 0.299 debug|00000000:be1.srvcls[0024:003d]
*** h1 0.299 debug|00000000:be1.clicls[0024:003d]
*** h1 0.299 debug|00000000:be1.closed[0024:003d]
*** h1 0.299 debug|00000001:fe1.accept(0009)=0024 from [::1:19782]
ALPN=<none>
**** S1 0.299 syslog|<134>Jun 7 23:14:56 haproxy[78985]: ::1:19782
[07/Jun/2019:23:14:56.395] fe1~ be1/srv1 0/0/0/0/0 200 54 - - ----
2/1/0/0/0 0/0 "OPTIONS * HTTP/1.1"
** S1 0.299 === expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* fe1~ be1/srv1
.* 200 [...
**** S1 0.299 EXPECT MATCH ~ "[^:\[ ]\[78985\]: .* fe1~ be1/srv1 .*
200 [[:digit:]]+ - - ---- .* "OPTIONS \* HTTP/1.1""
** S1 0.299 === recv info
*** h2 0.299 debug|[WARNING] 157/231456 (78988) : Health check for
server be2/srv1 succeeded, reason: Layer7 check passed, code: 200, info:
"OK", check duration: 149ms, status: 1/1 UP.
**** S2 0.299 syslog|<29>Jun 7 23:14:56 haproxy[78988]: Health check
for server be2/srv1 succeeded, reason: Layer7 check passed, code: 200,
info: "OK", check duration: 149ms, status: 1/1 UP.
** S2 0.300 === expect ~ "[^:\\[ ]\\[${h2_pid}\\]: Health check for
server b...
**** S2 0.300 EXPECT MATCH ~ "[^:\[ ]\[78988\]: Health check for
server be2/srv1 succeeded, reason: Layer7 check passed, code: 200, info:
"OK", check duration: [[:digit:]]+ms, status: 1/1 UP."
** S2 0.300 === recv
*** h1 0.300 debug|00000002:fe2.accept(000a)=003c from [::1:19783]
ALPN=<none>
*** h1 0.300 debug|00000001:fe1.clicls[0024:ffffffff]
*** h1 0.300 debug|00000001:fe1.closed[0024:ffffffff]
*** h2 0.300 debug|[WARNING] 157/231456 (78988) : Health check for
server be4/srv2 succeeded, reason: Layer6 check passed, check duration:
17ms, status: 1/1 UP.
*** h1 0.300 debug|00000002:fe2.clicls[003c:ffffffff]
