blob: 52857a2e3183d007124d89d1acfcf2c2d1344879 [file] [log] [blame]
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +02001# commit d02286d
2# BUG/MINOR: log: pin the front connection when front ip/ports are logged
3#
4# Mathias Weiersmueller reported an interesting issue with logs which Lukas
5# diagnosed as dating back from commit 9b061e332 (1.5-dev9). When front
6# connection information (ip, port) are logged in TCP mode and the log is
7# emitted at the end of the connection (eg: because %B or any log tag
8# requiring LW_BYTES is set), the log is emitted after the connection is
9# closed, so the address and ports cannot be retrieved anymore.
10#
Joseph Herlantec4abde2018-11-13 20:15:49 -080011# It could be argued that we'd make a special case of these to immediately
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +020012# retrieve the source and destination addresses from the connection, but it
13# seems cleaner to simply pin the front connection, marking it "tracked" by
14# adding the LW_XPRT flag to mention that we'll need some of these elements
15# at the last moment. Only LW_FRTIP and LW_CLIP are affected. Note that after
16# this change, LW_FRTIP could simply be removed as it's not used anywhere.
17#
18# Note that the problem doesn't happen when using %[src] or %[dst] since
19# all sample expressions set LW_XPRT.
20
Frédéric Lécailledc1a3bd2019-03-29 15:07:24 +010021#REGTEST_TYPE=bug
22
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +020023varnishtest "Wrong ip/port logging"
24feature ignore_unknown_macro
25
26server s1 {
27 rxreq
Christopher Faulet0dc100b2019-04-01 15:33:19 +020028 delay 0.02
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +020029} -start
30
31syslog Slg_1 -level notice {
32 recv
33 recv
34 recv info
Willy Tarreauf95838c2018-10-28 19:19:48 +010035 expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_port}.*\"ts\":\"[cC]D\",\"
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +020036} -start
37
38haproxy h1 -conf {
39 global
40 log ${Slg_1_addr}:${Slg_1_port} local0
41
42defaults
43 log global
44 timeout connect 3000
Willy Tarreauf95838c2018-10-28 19:19:48 +010045 timeout client 1
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +020046 timeout server 10000
47
48frontend fe1
49 bind "fd@${fe_1}"
50 mode tcp
51 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\"}
52 default_backend be_app
53
54backend be_app
PiBa-NLfefb9e32018-12-08 21:36:55 +010055 server app1 ${s1_addr}:${s1_port}
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +020056} -start
57
58client c1 -connect ${h1_fe_1_sock} {
59 txreq -url "/"
Frédéric Lécaille5dfdd4a2019-05-07 12:00:36 +020060 expect_close
Frédéric Lécaille9b53b4c2018-06-20 07:26:44 +020061} -run
62
63syslog Slg_1 -wait
64