On 06/07/2018 03:14 PM, Frederic Lecaille wrote:
Hi all,
We have recently worked in colloboration with Poul-Henning Kamp to use
varnishtest regression testing (script driven) tool for Varnish HTTP
Cache so that to modify it and make it capable of also test haproxy.
Note that here we are speaking about *regression* testing which has
nothing to see with others classes of tests (unit, integration,
performance etc). The aim of such tests is: to prevent old bugs from
coming back!
A nice reference manual for varnishtest may be bound here:
https://varnish-cache.org/docs/6.0/reference/varnishtest.html
In a few words, varnishtest program is able to start HTTP clients and
servers and put a varnish-cache processus (or several) in the middle to
test it, making these clients and servers interact with each others. So,
here we wanted to do the same thing for haproxy.
Of course, it will not always be possible to write a regression test
script for each bug to come.
Please find attached to this mail a first patch to document how to use
varnishtest regression testing tool with haproxy and help you to write
regression test files.
We will have to discuss about how to organize the test files for these
regressions tests.
A big thank you to Poul-Henning Kamp for having helped us during this
interesting project.
Regards,
Fred.
Well... this is patch matching with the previous text file.
Fred
>From deb0549ad58e7a4a91a631c6b673f832ace1f428 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20L=C3=A9caille?= <flecai...@haproxy.com>
Date: Thu, 7 Jun 2018 14:57:30 +0200
Subject: [PATCH] DOC: regression testing: Add a short starting guide.
This documentation describes how to write varnish test case (VTC)
files to reg test haproxy.
---
doc/regression-testing.txt | 697 +++++++++++++++++++++++++++++++++++++++++++++
1 file changed, 697 insertions(+)
create mode 100644 doc/regression-testing.txt
diff --git a/doc/regression-testing.txt b/doc/regression-testing.txt
new file mode 100644
index 0000000..2df67cb
--- /dev/null
+++ b/doc/regression-testing.txt
@@ -0,0 +1,697 @@
+ +---------------------------------------------+
+ | HAProxy regression testing with varnishtest |
+ +---------------------------------------------+
+
+
+The information found in this file are a short starting guide to help you to
+write VTC (Varnish Test Case) scripts (or VTC files) for haproxy regression testing.
+Such VTC files are currently used to test Varnish cache application developed by
+Poul-Henning Kamp. A very big thanks you to him for having helped you to add
+our haproxy C modules to varnishtest tool.
+
+A lot of general information about how to write VTC files may be found in 'man/vtc.7'
+manual. It is *highly* recommended to read this manual before asking. This
+documentation only deals with the varnishtest support for haproxy.
+
+
+varnishtest installation
+------------------------
+
+To use varnishtest you will have to download and compile the recent Varnish cache
+sources found at https://github.com/varnishcache/varnish-cache.
+
+To compile Varnish cache :
+
+ $ ./autogen.sh
+ $ ./configure
+ $ make
+
+The varnishtest sources may be found in 'bin/varnishtest' directory.
+'bin/varnishtest/tests' is plenty of VTC files for Varnish cache. After having
+compiled these sources, the varnishtest executable location is
+'bin/varnishtest/varnishtest'.
+
+varnishtest is able to search for the haproxy executable file it is supposed to
+launch in the PATH environment variable. To force the executable to be used by
+varnishtest, the HAPROXY_PROGRAM environment variable for varnishtest may be
+typically set as follows:
+
+ $ HAPROXY_PROGRAM=~/srcs/haproxy/haproxy varnishtest ...
+
+
+varnistest exectution
+---------------------
+
+varnishtest program comes with interesting options. The most interesting are:
+
+ -t Timeout in seconds to abort the test if some launched program
+ -v By default, varnishtest does not dump the outputs of processus it launched
+ when the test passes. With this option the outputs are dumped even
+ when the test passes.
+ -L to always keep the temporary VTC directories.
+ -l to keep the temporary VTC directories only when the test fails.
+
+About haproxy when launched by varnishtest, -d option is enabled by default.
+
+
+How to write VTC files
+----------------------
+
+A VTC file must start with a "varnishtest" command line followed by a descriptive
+line enclosed by double quotes. This is not specific to the VTC files for haproxy.
+
+The VTC files for haproxy must also contain a "feature ignore_unknown_macro" line
+if any macro is used for haproxy in this file. This is due to the fact that
+varnishtest parser code for haproxy commands generates macros the varnishtest
+parser code for varnish has no knowledge of. This line prevents varnishtest from
+failing in such cases.
+
+To make varnishtest capable of testing haproxy, two new VTC commands have been
+implemented: "haproxy" and "syslog". "haproxy" is used to start haproxy processus.
+"syslog" is used to start syslog servers (at this time, only used by haproxy).
+
+As haproxy cannot work without configuration file, a VTC file for haproxy must
+embed the configuration files contents for the haproxy instances it declares.
+This may be done using the following intuitive syntax construction: -conf {...}.
+Here -conf is an argument of "haproxy" VTC command to declare the configuration
+file of the haproxy instances it also declares (see "Basic HAProxy test" VTC file
+below).
+
+As for varnish VTC files, the parser of VTC files for haproxy automatically
+generates macros for the declared frontends to be reused by the clients later
+in the script, so after having written the "haproxy" command sections.
+The syntax "fd@${my_frontend_fd_name}" must be used to bind the frontend
+listeners to localhost address and random ports (see "Environment variables"
+section of haproxy documentation). This is mandatory.
+
+Each time the haproxy command parser finds a "fd@${xyz}" string in a 'ABC'
+"haproxy" command section, it generates three macros: 'ABC_xyz_addr', 'ABC_xyz_port'
+and 'ABC_xyz_sock', with 'ABC_xyz_sock' being resolved as 'ABC_xyz_addr
+ABC_xyz_port' typically used by clients -connect parameter.
+
+Each haproxy instance works in their own temporary working directories located
+at '/tmp/vtc.<varnitest PID>.XXXXXXXX/<haproxy_instance_name>' (with XXXXXXXX
+a random 8 digits hexadecimal integer. This is in this temporary directory that
+the configuration file is temporarily written.
+
+A 'stats.sock' UNIX socket is also created in this directory. There is no need
+to declare such stats sockets in the -conf {...} section. The name of the parent
+directory of the haproxy instances working directories is stored in 'tmpdir'. In
+fact this is the working directory of the current varnishtest processus.
+
+There also exists 'testdir' macro which is the parent directory of the VTC file.
+It may be useful to use other files located in the same directory than the current
+VTC file.
+
+
+
+VTC file examples
+-----------------
+
+The following first VTC file is a real regression test case file for a bug which has
+been fixed by 84c844e commit. We declare a basic configuration for a 'h1' haproxy
+instance.
+
+ varnishtest "SPOE bug: missing configuration file"
+
+ #commit 84c844eb12b250aa86f2aadaff77c42dfc3cb619
+ #Author: Christopher Faulet <cfau...@haproxy.com>
+ #Date: Fri Mar 23 14:37:14 2018 +0100
+
+ # BUG/MINOR: spoe: Initialize variables used during conf parsing before any check
+
+ # Some initializations must be done at the beginning of parse_spoe_flt to avoid
+ # segmentaion fault when first errors are catched, when the "filter spoe" line is
+ # parsed.
+
+ haproxy h1 -conf-BAD {} {
+ defaults
+ timeout connect 5000ms
+ timeout client 50000ms
+ timeout server 50000ms
+
+ frontend my-front
+ filter spoe
+ }
+
+
+-conf-BAD haproxy command argument is used. Its role it to launch haproxy with
+-c option (configuration file checking) and check that 'h1' exit(3) with 1 as
+status. Here is the output when running this VTC file:
+
+
+ **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
+ **** top 0.0 extmacro def localhost=127.0.0.1
+ **** top 0.0 extmacro def bad_backend=127.0.0.1 39564
+ **** top 0.0 extmacro def bad_ip=192.0.2.255
+ **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
+ **** top 0.0 macro def tmpdir=/tmp/vtc.6377.64329194
+ * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc starting
+ ** top 0.0 === varnishtest "SPOE bug: missing configuration file"
+ * top 0.0 TEST SPOE bug: missing configuration file
+ ** top 0.0 === haproxy h1 -conf-BAD {} {
+ **** h1 0.0 conf| global
+ **** h1 0.0 conf|\tstats socket /tmp/vtc.6377.64329194/h1/stats.sock level admin mode 600
+ **** h1 0.0 conf|
+ **** h1 0.0 conf|\tdefaults
+ **** h1 0.0 conf| timeout connect 5000ms
+ **** h1 0.0 conf| timeout client 50000ms
+ **** h1 0.0 conf| timeout server 50000ms
+ **** h1 0.0 conf|
+ **** h1 0.0 conf|\tfrontend my-front
+ **** h1 0.0 conf|\t\tfilter spoe
+ **** h1 0.0 conf|
+ ** h1 0.0 haproxy_start
+ **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 1
+ **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -c -f /tmp/vtc.6377.64329194/h1/cfg
+ **** h1 0.0 XXX 5 @277
+ *** h1 0.0 PID: 6395
+ **** h1 0.0 macro def h1_pid=6395
+ **** h1 0.0 macro def h1_name=/tmp/vtc.6377.64329194/h1
+ ** h1 0.0 Wait
+ ** h1 0.0 Stop HAproxy pid=6395
+ **** h1 0.0 STDOUT poll 0x10
+ ** h1 0.0 WAIT4 pid=6395 status=0x008b (user 0.000000 sys 0.000000)
+ * h1 0.0 Expected exit: 0x1 signal: 0 core: 0
+ ---- h1 0.0 Bad exit status: 0x008b exit 0x0 signal 11 core 128
+ * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc
+ ** h1 0.0 Reset and free h1 haproxy 6395
+ ** h1 0.0 Wait
+ ---- h1 0.0 Assert error in haproxy_wait(), vtc_haproxy.c line 326: Condition(*(&h->fds[1]) >= 0) not true.
+
+ * top 0.0 failure during reset
+ # top TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc FAILED (0.008) exit=2
+
+
+'h1' exited with (128 + 11) status and a core file was produced in
+/tmp/vtc.6377.64329194/h1 directory.
+With the patch provided by 84c844e commit, varnishtest makes this VTC file pass
+as expected (verbose mode execution):
+
+ **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
+ **** top 0.0 extmacro def localhost=127.0.0.1
+ **** top 0.0 extmacro def bad_backend=127.0.0.1 42264
+ **** top 0.0 extmacro def bad_ip=192.0.2.255
+ **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
+ **** top 0.0 macro def tmpdir=/tmp/vtc.25540.59b6ec5d
+ * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc starting
+ ** top 0.0 === varnishtest "SPOE bug: missing configuration file"
+ * top 0.0 TEST SPOE bug: missing configuration file
+ ** top 0.0 === haproxy h1 -conf-BAD {} {
+ **** h1 0.0 conf| global
+ **** h1 0.0 conf|\tstats socket /tmp/vtc.25540.59b6ec5d/h1/stats.sock level admin mode 600
+ **** h1 0.0 conf|
+ **** h1 0.0 conf|\tdefaults
+ **** h1 0.0 conf| timeout connect 5000ms
+ **** h1 0.0 conf| timeout client 50000ms
+ **** h1 0.0 conf| timeout server 50000ms
+ **** h1 0.0 conf|
+ **** h1 0.0 conf|\tfrontend my-front
+ **** h1 0.0 conf|\t\tfilter spoe
+ **** h1 0.0 conf|
+ ** h1 0.0 haproxy_start
+ **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 1
+ **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -c -f /tmp/vtc.25540.59b6ec5d/h1/cfg
+ **** h1 0.0 XXX 5 @277
+ *** h1 0.0 PID: 25558
+ **** h1 0.0 macro def h1_pid=25558
+ **** h1 0.0 macro def h1_name=/tmp/vtc.25540.59b6ec5d/h1
+ ** h1 0.0 Wait
+ ** h1 0.0 Stop HAproxy pid=25558
+ *** h1 0.0 debug|[ALERT] 157/135318 (25558) : parsing [/tmp/vtc.25540.59b6ec5d/h1/cfg:10] : 'filter' : ''spoe' : missing config file'
+ *** h1 0.0 debug|[ALERT] 157/135318 (25558) : Error(s) found in configuration file : /tmp/vtc.25540.59b6ec5d/h1/cfg
+ *** h1 0.0 debug|[ALERT] 157/135318 (25558) : Fatal errors found in configuration.
+ **** h1 0.0 STDOUT poll 0x10
+ ** h1 0.0 WAIT4 pid=25558 status=0x0100 (user 0.000000 sys 0.000000)
+ ** h1 0.0 Found expected ''
+ * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc
+ ** h1 0.0 Reset and free h1 haproxy -1
+ * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc completed
+ # top TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc passed (0.004)
+
+
+The following VTC file does almost nothing except running a shell to list
+the contents of 'tmpdir' directory after having launched a haproxy instance
+and 's1' HTTP server. This shell also prints the content of 'cfg' 'h1' configuration
+file.
+
+ varnishtest "List the contents of 'tmpdir'"
+ feature ignore_unknown_macro
+
+ server s1 {
+ } -start
+
+ haproxy h1 -conf {
+ defaults
+ mode http
+ timeout connect 5s
+ timeout server 30s
+ timeout client 30s
+
+ backend be1
+ server srv1 ${s1_addr}:${s1_port}
+
+ frontend http1
+ use_backend be1
+ bind "fd@${my_frontend_fd}"
+ } -start
+
+ shell {
+ echo "${tmpdir} working directory content:"
+ ls -lR ${tmpdir}
+ cat ${tmpdir}/h1/cfg
+ }
+
+We give only the ouput of the shell to illustrate this example:
+
+ .
+ .
+ .
+ ** top 0.0 === shell {
+ **** top 0.0 shell_cmd|exec 2>&1 ;
+ **** top 0.0 shell_cmd| echo "tmpdir: /tmp/vtc.32092.479d521e"
+ **** top 0.0 shell_cmd| ls -lR /tmp/vtc.32092.479d521e
+ **** top 0.0 shell_cmd| cat /tmp/vtc.32092.479d521e/h1/cfg
+ .
+ .
+ .
+ **** top 0.0 shell_out|/tmp/vtc.3808.448cbfe0 working directory content:
+ **** top 0.0 shell_out|/tmp/vtc.32092.479d521e:
+ **** top 0.0 shell_out|total 8
+ **** top 0.0 shell_out|drwxr-xr-x 2 users 4096 Jun 7 11:09 h1
+ **** top 0.0 shell_out|-rw-r--r-- 1 me users 84 Jun 7 11:09 INFO
+ **** top 0.0 shell_out|
+ **** top 0.0 shell_out|/tmp/vtc.32092.479d521e/h1:
+ **** top 0.0 shell_out|total 4
+ **** top 0.0 shell_out|-rw-r----- 1 fred users 339 Jun 7 11:09 cfg
+ **** top 0.0 shell_out|srw------- 1 fred users 0 Jun 7 11:09 stats.sock
+ **** top 0.0 shell_out| global
+ **** top 0.0 shell_out|\tstats socket /tmp/vtc.32092.479d521e/h1/stats.sock level admin mode 600
+ **** top 0.0 shell_out|
+ **** top 0.0 shell_out| defaults
+ **** top 0.0 shell_out| mode http
+ **** top 0.0 shell_out| timeout connect 5s
+ **** top 0.0 shell_out| timeout server 30s
+ **** top 0.0 shell_out| timeout client 30s
+ **** top 0.0 shell_out|
+ **** top 0.0 shell_out| backend be1
+ **** top 0.0 shell_out| server srv1 127.0.0.1:36984
+ **** top 0.0 shell_out|
+ **** top 0.0 shell_out| frontend http1
+ **** top 0.0 shell_out| use_backend be1
+ **** top 0.0 shell_out| bind "fd@${my_frontend_fd}"
+ **** top 0.0 shell_status = 0x0000
+
+
+The following example illustrate how to run a basic HTTP transaction between 'c1'
+client and 's1' server with 'http1' as haproxy frontend. This frontend listen
+on TCP socket with 'my_frontend_fd' as file descriptor.
+
+ # Mandatory line
+ varnishtest "Basic HAproxy test"
+
+ # As some macros for haproxy are used in this file, this line is mandatory.
+ feature ignore_unknown_macro
+
+ server s1 {
+ rxreq
+ txresp -body "s1 >>> Hello world!"
+ } -start
+
+ haproxy h1 -conf {
+ # Configuration file of 'h1' haproxy instance.
+ defaults
+ mode http
+ timeout connect 5s
+ timeout server 30s
+ timeout client 30s
+
+ backend be1
+ # declare 'srv1' server to point to 's1' server instance declare above.
+ server srv1 ${s1_addr}:${s1_port}
+
+ frontend http1
+ use_backend be1
+ bind "fd@${my_frontend_fd}"
+ } -start
+
+ client c1 -connect ${h1_my_frontend_fd_sock} {
+ txreq -url "/"
+ rxresp
+ expect resp.status == 200
+ expect resp.body == "s1 >>> Hello world!"
+ } -run
+
+
+It is possible to shorten the previous VTC file haproxy command section as follows:
+
+ haproxy h1 -conf {
+ # Configuration file of 'h1' haproxy instance.
+ defaults
+ mode http
+ timeout connect 5s
+ timeout server 30s
+ timeout client 30s
+ }
+
+In this latter example, "backend" and "frontend" sections are automatically
+generated depending on the declarations of server instances.
+
+
+Another interesting real regression test case is the following: we declare one
+server 's1', a syslog server 'Slg_1' and a basic haproxy configuration for 'h1'
+haproxy instance. Here we want to check that the syslog message are correctly
+formatted thanks to "expect" "syslog" command (see syslog Slg_1 {...} command)
+below.
+
+ varnishtest "Wrong ip/port logging"
+ feature ignore_unknown_macro
+
+ #commit d02286d6c866e5c0a7eb6fbb127fa57f3becaf16
+ #Author: Willy Tarreau <w...@1wt.eu>
+ #Date: Fri Jun 23 11:23:43 2017 +0200
+ #
+ # 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 immediatly
+ # 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.
+
+
+ server s1 {
+ rxreq
+ txresp
+ } -start
+
+ syslog Slg_1 -level notice {
+ recv
+ recv
+ recv info
+ expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_port}.*\"ts\":\"cD\",\"
+ } -start
+
+ haproxy h1 -conf {
+ global
+ log ${Slg_1_addr}:${Slg_1_port} local0
+
+ defaults
+ log global
+ timeout connect 3000
+ timeout client 5
+ timeout server 10000
+
+ 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} check
+ } -start
+
+ client c1 -connect ${h1_fe_1_sock} {
+ txreq -url "/"
+ delay 0.02
+ } -run
+
+ syslog Slg_1 -wait
+
+
+Here is the output produced by varnishtest with the latter VTC file:
+
+ **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
+ **** top 0.0 extmacro def localhost=127.0.0.1
+ **** top 0.0 extmacro def bad_backend=127.0.0.1 40386
+ **** top 0.0 extmacro def bad_ip=192.0.2.255
+ **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
+ **** top 0.0 macro def tmpdir=/tmp/vtc.15752.560ca66b
+ * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc starting
+ ** top 0.0 === varnishtest "HAPEE bug 2788"
+ * top 0.0 TEST HAPEE bug 2788
+ ** top 0.0 === feature ignore_unknown_macro
+ ** top 0.0 === server s1 {
+ ** s1 0.0 Starting server
+ **** s1 0.0 macro def s1_addr=127.0.0.1
+ **** s1 0.0 macro def s1_port=35564
+ **** s1 0.0 macro def s1_sock=127.0.0.1 35564
+ * s1 0.0 Listen on 127.0.0.1 35564
+ ** top 0.0 === syslog Slg_1 -level notice {
+ ** Slg_1 0.0 Starting syslog server
+ ** s1 0.0 Started on 127.0.0.1 35564
+ **** Slg_1 0.0 macro def Slg_1_addr=127.0.0.1
+ **** Slg_1 0.0 macro def Slg_1_port=33012
+ **** Slg_1 0.0 macro def Slg_1_sock=127.0.0.1 33012
+ * Slg_1 0.0 Bound on 127.0.0.1 33012
+ ** top 0.0 === haproxy h1 -conf {
+ ** Slg_1 0.0 Started on 127.0.0.1 33012 (level: 5)
+ ** Slg_1 0.0 === recv
+ **** h1 0.0 macro def h1_fe_1_sock=::1 51782
+ **** h1 0.0 macro def h1_fe_1_addr=::1
+ **** h1 0.0 macro def h1_fe_1_port=51782
+ **** h1 0.0 setenv(fe_1, 7)
+ **** h1 0.0 conf| global
+ **** h1 0.0 conf|\tstats socket /tmp/vtc.15752.560ca66b/h1/stats.sock level admin mode 600
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| global
+ **** h1 0.0 conf| log 127.0.0.1:33012 local0
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| defaults
+ **** h1 0.0 conf| log global
+ **** h1 0.0 conf| timeout connect 3000
+ **** h1 0.0 conf| timeout client 5
+ **** h1 0.0 conf| timeout server 10000
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| frontend fe1
+ **** h1 0.0 conf| bind "fd@${fe_1}"
+ **** h1 0.0 conf| mode tcp
+ **** h1 0.0 conf| 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\"}
+ **** h1 0.0 conf| default_backend be_app
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| backend be_app
+ **** h1 0.0 conf| server app1 127.0.0.1:35564 check
+ ** h1 0.0 haproxy_start
+ **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 0
+ **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -d -f /tmp/vtc.15752.560ca66b/h1/cfg
+ **** h1 0.0 XXX 9 @277
+ *** h1 0.0 PID: 15787
+ **** h1 0.0 macro def h1_pid=15787
+ **** h1 0.0 macro def h1_name=/tmp/vtc.15752.560ca66b/h1
+ ** top 0.0 === client c1 -connect ${h1_fe_1_sock} {
+ ** c1 0.0 Starting client
+ ** c1 0.0 Waiting for client
+ *** c1 0.0 Connect to ::1 51782
+ *** c1 0.0 connected fd 8 from ::1 46962 to ::1 51782
+ ** c1 0.0 === txreq -url "/"
+ **** c1 0.0 txreq|GET / HTTP/1.1\r
+ **** c1 0.0 txreq|Host: 127.0.0.1\r
+ **** c1 0.0 txreq|\r
+ ** c1 0.0 === delay 0.02
+ *** c1 0.0 delaying 0.02 second(s)
+ *** h1 0.0 debug|Note: setting global.maxconn to 2000.
+ *** h1 0.0 debug|Available polling systems :
+ *** h1 0.0 debug| epoll :
+ *** h1 0.0 debug|pref=300,
+ *** h1 0.0 debug| test result OK
+ *** h1 0.0 debug| poll : pref=200, test result OK
+ *** h1 0.0 debug| select :
+ *** h1 0.0 debug|pref=150, test result FAILED
+ *** h1 0.0 debug|Total: 3 (2 usable), will use epoll.
+ *** h1 0.0 debug|
+ *** h1 0.0 debug|Available filters :
+ *** h1 0.0 debug|\t[SPOE] spoe
+ *** h1 0.0 debug|\t[COMP] compression
+ *** h1 0.0 debug|\t[TRACE] trace
+ **** Slg_1 0.0 syslog|<133>Jun 7 14:12:51 haproxy[15787]: Proxy fe1 started.
+ ** Slg_1 0.0 === recv
+ **** Slg_1 0.0 syslog|<133>Jun 7 14:12:51 haproxy[15787]: Proxy be_app started.
+ ** Slg_1 0.0 === recv info
+ *** h1 0.0 debug|00000000:fe1.accept(0007)=000a from [::1:46962]
+ *** s1 0.0 accepted fd 6 127.0.0.1 56770
+ ** s1 0.0 === rxreq
+ **** s1 0.0 rxhdr|GET / HTTP/1.1\r
+ **** s1 0.0 rxhdr|Host: 127.0.0.1\r
+ **** s1 0.0 rxhdr|\r
+ **** s1 0.0 rxhdrlen = 35
+ **** s1 0.0 http[ 0] |GET
+ **** s1 0.0 http[ 1] |/
+ **** s1 0.0 http[ 2] |HTTP/1.1
+ **** s1 0.0 http[ 3] |Host: 127.0.0.1
+ **** s1 0.0 bodylen = 0
+ ** s1 0.0 === txresp
+ **** s1 0.0 txresp|HTTP/1.1 200 OK\r
+ **** s1 0.0 txresp|Content-Length: 0\r
+ **** s1 0.0 txresp|\r
+ *** s1 0.0 shutting fd 6
+ ** s1 0.0 Ending
+ *** h1 0.0 debug|00000000:be_app.srvcls[000a:000c]
+ *** h1 0.0 debug|00000000:be_app.clicls[000a:000c]
+ *** h1 0.0 debug|00000000:be_app.closed[000a:000c]
+ **** Slg_1 0.0 syslog|<134>Jun 7 14:12:51 haproxy[15787]: {"dip":"","dport":"0","c_ip":"::1","c_port":"46962","fe_name":"fe1","be_name":"be_app","s_name":"app1","ts":"cD","bytes_read":"38"}
+ ** Slg_1 0.0 === expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_p...
+ ---- Slg_1 0.0 EXPECT FAILED ~ "\"dip\":\"::1\",\"dport\":\"51782.*\"ts\":\"cD\",\""
+ *** c1 0.0 closing fd 8
+ ** c1 0.0 Ending
+ * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/d02286d.vtc
+ ** h1 0.0 Reset and free h1 haproxy 15787
+ ** h1 0.0 Wait
+ ** h1 0.0 Stop HAproxy pid=15787
+ **** h1 0.0 Kill(2)=0: Success
+ **** h1 0.0 STDOUT poll 0x10
+ ** h1 0.1 WAIT4 pid=15787 status=0x0002 (user 0.000000 sys 0.004000)
+ ** s1 0.1 Waiting for server (4/-1)
+ ** Slg_1 0.1 Waiting for syslog server (5)
+ * top 0.1 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc FAILED
+ # top TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc FAILED (0.131) exit=2
+
+This test does not pass without the bug fix of d02286d commit. Indeed the third syslog
+message received by 'Slg_1' syslog server does not match the regular expression
+of the "syslog" "expect" command:
+
+ expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_port}.*\"ts\":\"cD\",\"
+
+(the IP address and port are missing), contrary to what happens with the correct bug fix:
+
+ **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
+ **** top 0.0 extmacro def localhost=127.0.0.1
+ **** top 0.0 extmacro def bad_backend=127.0.0.1 37284
+ **** top 0.0 extmacro def bad_ip=192.0.2.255
+ **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
+ **** top 0.0 macro def tmpdir=/tmp/vtc.12696.186b28b0
+ * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc starting
+ ** top 0.0 === varnishtest "HAPEE bug 2788"
+ * top 0.0 TEST HAPEE bug 2788
+ ** top 0.0 === feature ignore_unknown_macro
+ ** top 0.0 === server s1 {
+ ** s1 0.0 Starting server
+ **** s1 0.0 macro def s1_addr=127.0.0.1
+ **** s1 0.0 macro def s1_port=53384
+ **** s1 0.0 macro def s1_sock=127.0.0.1 53384
+ * s1 0.0 Listen on 127.0.0.1 53384
+ ** top 0.0 === syslog Slg_1 -level notice {
+ ** Slg_1 0.0 Starting syslog server
+ **** Slg_1 0.0 macro def Slg_1_addr=127.0.0.1
+ ** s1 0.0 Started on 127.0.0.1 53384
+ **** Slg_1 0.0 macro def Slg_1_port=36195
+ **** Slg_1 0.0 macro def Slg_1_sock=127.0.0.1 36195
+ * Slg_1 0.0 Bound on 127.0.0.1 36195
+ ** top 0.0 === haproxy h1 -conf {
+ ** Slg_1 0.0 Started on 127.0.0.1 36195 (level: 5)
+ ** Slg_1 0.0 === recv
+ **** h1 0.0 macro def h1_fe_1_sock=::1 39264
+ **** h1 0.0 macro def h1_fe_1_addr=::1
+ **** h1 0.0 macro def h1_fe_1_port=39264
+ **** h1 0.0 setenv(fe_1, 7)
+ **** h1 0.0 conf| global
+ **** h1 0.0 conf|\tstats socket /tmp/vtc.12696.186b28b0/h1/stats.sock level admin mode 600
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| global
+ **** h1 0.0 conf| log 127.0.0.1:36195 local0
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| defaults
+ **** h1 0.0 conf| log global
+ **** h1 0.0 conf| timeout connect 3000
+ **** h1 0.0 conf| timeout client 5
+ **** h1 0.0 conf| timeout server 10000
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| frontend fe1
+ **** h1 0.0 conf| bind "fd@${fe_1}"
+ **** h1 0.0 conf| mode tcp
+ **** h1 0.0 conf| 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\"}
+ **** h1 0.0 conf| default_backend be_app
+ **** h1 0.0 conf|
+ **** h1 0.0 conf| backend be_app
+ **** h1 0.0 conf| server app1 127.0.0.1:53384 check
+ ** h1 0.0 haproxy_start
+ **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 0
+ **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -d -f /tmp/vtc.12696.186b28b0/h1/cfg
+ **** h1 0.0 XXX 9 @277
+ *** h1 0.0 PID: 12728
+ **** h1 0.0 macro def h1_pid=12728
+ **** h1 0.0 macro def h1_name=/tmp/vtc.12696.186b28b0/h1
+ ** top 0.0 === client c1 -connect ${h1_fe_1_sock} {
+ ** c1 0.0 Starting client
+ ** c1 0.0 Waiting for client
+ *** c1 0.0 Connect to ::1 39264
+ *** c1 0.0 connected fd 8 from ::1 41245 to ::1 39264
+ ** c1 0.0 === txreq -url "/"
+ **** c1 0.0 txreq|GET / HTTP/1.1\r
+ **** c1 0.0 txreq|Host: 127.0.0.1\r
+ **** c1 0.0 txreq|\r
+ ** c1 0.0 === delay 0.02
+ *** c1 0.0 delaying 0.02 second(s)
+ *** h1 0.0 debug|Note: setting global.maxconn to 2000.
+ *** h1 0.0 debug|Available polling systems :
+ *** h1 0.0 debug| epoll : pref=300,
+ *** h1 0.0 debug| test result OK
+ *** h1 0.0 debug| poll : pref=200, test result OK
+ *** h1 0.0 debug| select : pref=150, test result FAILED
+ *** h1 0.0 debug|Total: 3 (2 usable), will use epoll.
+ *** h1 0.0 debug|
+ *** h1 0.0 debug|Available filters :
+ *** h1 0.0 debug|\t[SPOE] spoe
+ *** h1 0.0 debug|\t[COMP] compression
+ *** h1 0.0 debug|\t[TRACE] trace
+ *** h1 0.0 debug|Using epoll() as the polling mechanism.
+ **** Slg_1 0.0 syslog|<133>Jun 7 14:10:18 haproxy[12728]: Proxy fe1 started.
+ ** Slg_1 0.0 === recv
+ **** Slg_1 0.0 syslog|<133>Jun 7 14:10:18 haproxy[12728]: Proxy be_app started.
+ ** Slg_1 0.0 === recv info
+ *** h1 0.0 debug|00000000:fe1.accept(0007)=000c from [::1:41245] ALPN=<none>
+ *** s1 0.0 accepted fd 6 127.0.0.1 49946
+ ** s1 0.0 === rxreq
+ **** s1 0.0 rxhdr|GET / HTTP/1.1\r
+ **** s1 0.0 rxhdr|Host: 127.0.0.1\r
+ **** s1 0.0 rxhdr|\r
+ **** s1 0.0 rxhdrlen = 35
+ **** s1 0.0 http[ 0] |GET
+ **** s1 0.0 http[ 1] |/
+ **** s1 0.0 http[ 2] |HTTP/1.1
+ **** s1 0.0 http[ 3] |Host: 127.0.0.1
+ **** s1 0.0 bodylen = 0
+ ** s1 0.0 === txresp
+ **** s1 0.0 txresp|HTTP/1.1 200 OK\r
+ **** s1 0.0 txresp|Content-Length: 0\r
+ **** s1 0.0 txresp|\r
+ *** s1 0.0 shutting fd 6
+ ** s1 0.0 Ending
+ *** h1 0.0 debug|00000000:be_app.srvcls[000c:adfd]
+ *** h1 0.0 debug|00000000:be_app.clicls[000c:adfd]
+ *** h1 0.0 debug|00000000:be_app.closed[000c:adfd]
+ **** Slg_1 0.0 syslog|<134>Jun 7 14:10:18 haproxy[12728]: {"dip":"::1","dport":"39264","c_ip":"::1","c_port":"41245","fe_name":"fe1","be_name":"be_app","s_name":"app1","ts":"cD","bytes_read":"38"}
+ ** Slg_1 0.0 === expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_p...
+ **** Slg_1 0.0 EXPECT MATCH ~ "\"dip\":\"::1\",\"dport\":\"39264.*\"ts\":\"cD\",\""
+ *** Slg_1 0.0 shutting fd 5
+ ** Slg_1 0.0 Ending
+ *** c1 0.0 closing fd 8
+ ** c1 0.0 Ending
+ ** top 0.0 === syslog Slg_1 -wait
+ ** Slg_1 0.0 Waiting for syslog server (-1)
+ * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/d02286d.vtc
+ ** h1 0.0 Reset and free h1 haproxy 12728
+ ** h1 0.0 Wait
+ ** h1 0.0 Stop HAproxy pid=12728
+ **** h1 0.0 Kill(2)=0: Success
+ **** h1 0.0 STDOUT poll 0x10
+ ** h1 0.1 WAIT4 pid=12728 status=0x0002 (user 0.000000 sys 0.004000)
+ ** s1 0.1 Waiting for server (4/-1)
+ * top 0.1 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc completed
+ # top TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc passed (0.128)
+
+In this latter execution the third syslog message is correct:
+
+ **** Slg_1 0.0 syslog|<134>Jun 7 14:10:18 haproxy[12728]: {"dip":"::1","dport":"39264","c_ip":"::1","c_port":"41245","fe_name":"fe1","be_name":"be_app","s_name":"app1","ts":"cD","bytes_read":"38"}
+
--
2.1.4
