07f1630a77
This test has an expect rule for syslog that looks for [cC]D, to
indicate a client abort or timeout during the data phase. The purpose
was to say that when it fails it must be this, but the very low timeout
(1ms) still makes it prone to succeeding if the machine is highly loaded.
This has become more visible since commit e8b1ad4c2b ("BUG/MEDIUM: clock:
also update the date offset on time jumps") because the clock drift
adjustments are more systematic. Since this commit, running 50 such tests
at twice more than the number of CPUs in parallel is sufficient to yield
errors due to some lines appearing as succeeding:
make reg-tests -- --j $((($(nproc)+1)*2)) --vtestparams -n50 reg-tests/log/wrong_ip_port_logging.vtc
It was observed that pauses up to 300ms were observed in epoll_wait() in
such circumstances, which were properly fixed by the time drift detection..
Another approach would consist in increasing the permitted margin during
which we don't fix the clock drift but that would not be logical since the
base time had really been awaited for.
This should be backported to all stable releases since the commit above
will trigger the issue more often.
(cherry picked from commit 036ab62231003e7e7072986626597682725edff8)
Signed-off-by: Willy Tarreau <w@1wt.eu>
63 lines
2.0 KiB
Plaintext
63 lines
2.0 KiB
Plaintext
# commit d02286d
|
|
# BUG/MINOR: log: pin the front connection when front ip/ports are logged
|
|
#
|
|
# Mathias Weiersmueller reported an interesting issue with logs which Lukas
|
|
# diagnosed as dating back from commit 9b061e332 (1.5-dev9). When front
|
|
# connection information (ip, port) are logged in TCP mode and the log is
|
|
# emitted at the end of the connection (eg: because %B or any log tag
|
|
# requiring LW_BYTES is set), the log is emitted after the connection is
|
|
# closed, so the address and ports cannot be retrieved anymore.
|
|
#
|
|
# It could be argued that we'd make a special case of these to immediately
|
|
# retrieve the source and destination addresses from the connection, but it
|
|
# seems cleaner to simply pin the front connection, marking it "tracked" by
|
|
# adding the LW_XPRT flag to mention that we'll need some of these elements
|
|
# at the last moment. Only LW_FRTIP and LW_CLIP are affected. Note that after
|
|
# this change, LW_FRTIP could simply be removed as it's not used anywhere.
|
|
#
|
|
# Note that the problem doesn't happen when using %[src] or %[dst] since
|
|
# all sample expressions set LW_XPRT.
|
|
|
|
#REGTEST_TYPE=bug
|
|
|
|
varnishtest "Wrong ip/port logging"
|
|
feature ignore_unknown_macro
|
|
|
|
server s1 {
|
|
rxreq
|
|
delay 0.02
|
|
} -start
|
|
|
|
syslog Slg_1 -level notice {
|
|
recv info
|
|
expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_port}.*\"ts\":\"[cC-][D-]\",\"
|
|
} -start
|
|
|
|
haproxy h1 -conf {
|
|
global
|
|
log ${Slg_1_addr}:${Slg_1_port} local0
|
|
|
|
defaults
|
|
log global
|
|
timeout connect "${HAPROXY_TEST_TIMEOUT-5s}"
|
|
timeout client 1
|
|
timeout server "${HAPROXY_TEST_TIMEOUT-5s}"
|
|
|
|
frontend fe1
|
|
bind "fd@${fe_1}"
|
|
mode tcp
|
|
log-format {\"dip\":\"%fi\",\"dport\":\"%fp\",\"c_ip\":\"%ci\",\"c_port\":\"%cp\",\"fe_name\":\"%ft\",\"be_name\":\"%b\",\"s_name\":\"%s\",\"ts\":\"%ts\",\"bytes_read\":\"%B\"}
|
|
default_backend be_app
|
|
|
|
backend be_app
|
|
server app1 ${s1_addr}:${s1_port}
|
|
} -start
|
|
|
|
client c1 -connect ${h1_fe_1_sock} {
|
|
txreq -url "/"
|
|
expect_close
|
|
} -run
|
|
|
|
syslog Slg_1 -wait
|
|
|