blob: 1b6c21d10bb71aa056023f36c7299756dd39f862 [file] [log] [blame]
Frédéric Lécaille617d4f52019-01-11 10:10:22 +01001 +---------------------------------------+
2 | HAProxy regression testing with vtest |
3 +---------------------------------------+
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +02004
5
6The information found in this file are a short starting guide to help you to
7write VTC (Varnish Test Case) scripts (or VTC files) for haproxy regression testing.
8Such VTC files are currently used to test Varnish cache application developed by
9Poul-Henning Kamp. A very big thanks you to him for having helped you to add
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010010our haproxy C modules to vtest tool. Note that vtest was formally developed for
11varnish cache reg testing and was named varnishtest. vtest is an haproxy specific
12version of varnishtest program which reuses the non varnish cache specific code.
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020013
14A lot of general information about how to write VTC files may be found in 'man/vtc.7'
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010015manual of varnish cache sources directory or directly on the web here:
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020016
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010017 https://varnish-cache.org/docs/trunk/reference/vtc.html
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020018
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010019It is *highly* recommended to read this manual before asking to haproxy ML. This
20documentation only deals with the vtest support for haproxy.
21
22
23vtest installation
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020024------------------------
25
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010026To use vtest you will have to download and compile the recent vtest
27sources found at https://github.com/vtest/VTest.
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020028
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010029To compile vtest:
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020030
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010031 $ cd VTest
32 $ make vtest
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020033
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010034Note that varnishtest may be also compiled but not without the varnish cache
35sources already compiled:
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020036
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010037 $ VARNISH_SRC=<...> make varnishtest
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020038
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010039After having compiled these sources, the vtest executable location is at the
40root of the vtest sources directory.
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020041
42
Michael Prokop4438c602019-05-24 10:25:45 +020043vtest execution
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020044---------------------
45
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010046vtest is able to search for the haproxy executable file it is supposed to
47launch thanks to the PATH environment variable. To force the executable to be used by
48vtest, the HAPROXY_PROGRAM environment variable for vtest may be
49typically set as follows:
50
51 $ HAPROXY_PROGRAM=~/srcs/haproxy/haproxy vtest ...
52
53vtest program comes with interesting options. The most interesting are:
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020054
55 -t Timeout in seconds to abort the test if some launched program
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010056 -v By default, vtest does not dump the outputs of processus it launched
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020057 when the test passes. With this option the outputs are dumped even
58 when the test passes.
59 -L to always keep the temporary VTC directories.
60 -l to keep the temporary VTC directories only when the test fails.
61
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010062About haproxy, when launched by vtest, -d option is enabled by default.
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020063
64
65How to write VTC files
66----------------------
67
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010068A VTC file must start with a "varnishtest" or "vtest" command line followed by a
69descriptive line enclosed by double quotes. This is not specific to the VTC files
70for haproxy.
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020071
72The VTC files for haproxy must also contain a "feature ignore_unknown_macro" line
73if any macro is used for haproxy in this file. This is due to the fact that
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010074vtest parser code for haproxy commands generates macros the vtest
75parser code for varnish cache has no knowledge of. This line prevents vtest from
76failing in such cases. As a "cli" macro automatically generated, this
77"feature ignore_unknown_macro" is mandatory for each VTC file for haproxy.
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020078
Frédéric Lécaille617d4f52019-01-11 10:10:22 +010079To make vtest capable of testing haproxy, two new VTC commands have been
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +020080implemented: "haproxy" and "syslog". "haproxy" is used to start haproxy processus.
81"syslog" is used to start syslog servers (at this time, only used by haproxy).
82
83As haproxy cannot work without configuration file, a VTC file for haproxy must
84embed the configuration files contents for the haproxy instances it declares.
85This may be done using the following intuitive syntax construction: -conf {...}.
86Here -conf is an argument of "haproxy" VTC command to declare the configuration
87file of the haproxy instances it also declares (see "Basic HAProxy test" VTC file
88below).
89
90As for varnish VTC files, the parser of VTC files for haproxy automatically
91generates macros for the declared frontends to be reused by the clients later
92in the script, so after having written the "haproxy" command sections.
93The syntax "fd@${my_frontend_fd_name}" must be used to bind the frontend
94listeners to localhost address and random ports (see "Environment variables"
95section of haproxy documentation). This is mandatory.
96
97Each time the haproxy command parser finds a "fd@${xyz}" string in a 'ABC'
98"haproxy" command section, it generates three macros: 'ABC_xyz_addr', 'ABC_xyz_port'
99and 'ABC_xyz_sock', with 'ABC_xyz_sock' being resolved as 'ABC_xyz_addr
100ABC_xyz_port' typically used by clients -connect parameter.
101
102Each haproxy instance works in their own temporary working directories located
103at '/tmp/vtc.<varnitest PID>.XXXXXXXX/<haproxy_instance_name>' (with XXXXXXXX
104a random 8 digits hexadecimal integer. This is in this temporary directory that
105the configuration file is temporarily written.
106
107A 'stats.sock' UNIX socket is also created in this directory. There is no need
108to declare such stats sockets in the -conf {...} section. The name of the parent
109directory of the haproxy instances working directories is stored in 'tmpdir'. In
Frédéric Lécaille617d4f52019-01-11 10:10:22 +0100110fact this is the working directory of the current vtest processus.
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +0200111
112There also exists 'testdir' macro which is the parent directory of the VTC file.
113It may be useful to use other files located in the same directory than the current
114VTC file.
115
116
117
118VTC file examples
119-----------------
120
121The following first VTC file is a real regression test case file for a bug which has
122been fixed by 84c844e commit. We declare a basic configuration for a 'h1' haproxy
123instance.
124
125 varnishtest "SPOE bug: missing configuration file"
126
127 #commit 84c844eb12b250aa86f2aadaff77c42dfc3cb619
128 #Author: Christopher Faulet <cfaulet@haproxy.com>
129 #Date: Fri Mar 23 14:37:14 2018 +0100
130
131 # BUG/MINOR: spoe: Initialize variables used during conf parsing before any check
132
133 # Some initializations must be done at the beginning of parse_spoe_flt to avoid
Ilya Shipitsin2a950d02020-03-06 13:07:38 +0500134 # segmentation fault when first errors are caught, when the "filter spoe" line is
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +0200135 # parsed.
136
137 haproxy h1 -conf-BAD {} {
138 defaults
139 timeout connect 5000ms
140 timeout client 50000ms
141 timeout server 50000ms
142
143 frontend my-front
144 filter spoe
145 }
146
147
148-conf-BAD haproxy command argument is used. Its role it to launch haproxy with
149-c option (configuration file checking) and check that 'h1' exit(3) with 1 as
150status. Here is the output when running this VTC file:
151
152
153 **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
154 **** top 0.0 extmacro def localhost=127.0.0.1
155 **** top 0.0 extmacro def bad_backend=127.0.0.1 39564
156 **** top 0.0 extmacro def bad_ip=192.0.2.255
157 **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
158 **** top 0.0 macro def tmpdir=/tmp/vtc.6377.64329194
159 * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc starting
160 ** top 0.0 === varnishtest "SPOE bug: missing configuration file"
161 * top 0.0 TEST SPOE bug: missing configuration file
162 ** top 0.0 === haproxy h1 -conf-BAD {} {
163 **** h1 0.0 conf| global
164 **** h1 0.0 conf|\tstats socket /tmp/vtc.6377.64329194/h1/stats.sock level admin mode 600
165 **** h1 0.0 conf|
166 **** h1 0.0 conf|\tdefaults
167 **** h1 0.0 conf| timeout connect 5000ms
168 **** h1 0.0 conf| timeout client 50000ms
169 **** h1 0.0 conf| timeout server 50000ms
170 **** h1 0.0 conf|
171 **** h1 0.0 conf|\tfrontend my-front
172 **** h1 0.0 conf|\t\tfilter spoe
173 **** h1 0.0 conf|
174 ** h1 0.0 haproxy_start
175 **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 1
176 **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -c -f /tmp/vtc.6377.64329194/h1/cfg
177 **** h1 0.0 XXX 5 @277
178 *** h1 0.0 PID: 6395
179 **** h1 0.0 macro def h1_pid=6395
180 **** h1 0.0 macro def h1_name=/tmp/vtc.6377.64329194/h1
181 ** h1 0.0 Wait
182 ** h1 0.0 Stop HAproxy pid=6395
183 **** h1 0.0 STDOUT poll 0x10
184 ** h1 0.0 WAIT4 pid=6395 status=0x008b (user 0.000000 sys 0.000000)
185 * h1 0.0 Expected exit: 0x1 signal: 0 core: 0
186 ---- h1 0.0 Bad exit status: 0x008b exit 0x0 signal 11 core 128
187 * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc
188 ** h1 0.0 Reset and free h1 haproxy 6395
189 ** h1 0.0 Wait
190 ---- h1 0.0 Assert error in haproxy_wait(), vtc_haproxy.c line 326: Condition(*(&h->fds[1]) >= 0) not true.
191
192 * top 0.0 failure during reset
193 # top TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc FAILED (0.008) exit=2
194
195
196'h1' exited with (128 + 11) status and a core file was produced in
197/tmp/vtc.6377.64329194/h1 directory.
198With the patch provided by 84c844e commit, varnishtest makes this VTC file pass
199as expected (verbose mode execution):
200
201 **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
202 **** top 0.0 extmacro def localhost=127.0.0.1
203 **** top 0.0 extmacro def bad_backend=127.0.0.1 42264
204 **** top 0.0 extmacro def bad_ip=192.0.2.255
205 **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
206 **** top 0.0 macro def tmpdir=/tmp/vtc.25540.59b6ec5d
207 * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc starting
208 ** top 0.0 === varnishtest "SPOE bug: missing configuration file"
209 * top 0.0 TEST SPOE bug: missing configuration file
210 ** top 0.0 === haproxy h1 -conf-BAD {} {
211 **** h1 0.0 conf| global
212 **** h1 0.0 conf|\tstats socket /tmp/vtc.25540.59b6ec5d/h1/stats.sock level admin mode 600
213 **** h1 0.0 conf|
214 **** h1 0.0 conf|\tdefaults
215 **** h1 0.0 conf| timeout connect 5000ms
216 **** h1 0.0 conf| timeout client 50000ms
217 **** h1 0.0 conf| timeout server 50000ms
218 **** h1 0.0 conf|
219 **** h1 0.0 conf|\tfrontend my-front
220 **** h1 0.0 conf|\t\tfilter spoe
221 **** h1 0.0 conf|
222 ** h1 0.0 haproxy_start
223 **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 1
224 **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -c -f /tmp/vtc.25540.59b6ec5d/h1/cfg
225 **** h1 0.0 XXX 5 @277
226 *** h1 0.0 PID: 25558
227 **** h1 0.0 macro def h1_pid=25558
228 **** h1 0.0 macro def h1_name=/tmp/vtc.25540.59b6ec5d/h1
229 ** h1 0.0 Wait
230 ** h1 0.0 Stop HAproxy pid=25558
231 *** h1 0.0 debug|[ALERT] 157/135318 (25558) : parsing [/tmp/vtc.25540.59b6ec5d/h1/cfg:10] : 'filter' : ''spoe' : missing config file'
232 *** h1 0.0 debug|[ALERT] 157/135318 (25558) : Error(s) found in configuration file : /tmp/vtc.25540.59b6ec5d/h1/cfg
233 *** h1 0.0 debug|[ALERT] 157/135318 (25558) : Fatal errors found in configuration.
234 **** h1 0.0 STDOUT poll 0x10
235 ** h1 0.0 WAIT4 pid=25558 status=0x0100 (user 0.000000 sys 0.000000)
236 ** h1 0.0 Found expected ''
237 * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc
238 ** h1 0.0 Reset and free h1 haproxy -1
239 * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc completed
240 # top TEST /home/fred/src/varnish-cache-haproxy/spoe_bug.vtc passed (0.004)
241
242
243The following VTC file does almost nothing except running a shell to list
244the contents of 'tmpdir' directory after having launched a haproxy instance
245and 's1' HTTP server. This shell also prints the content of 'cfg' 'h1' configuration
246file.
247
248 varnishtest "List the contents of 'tmpdir'"
249 feature ignore_unknown_macro
250
251 server s1 {
252 } -start
253
254 haproxy h1 -conf {
255 defaults
256 mode http
257 timeout connect 5s
258 timeout server 30s
259 timeout client 30s
260
261 backend be1
262 server srv1 ${s1_addr}:${s1_port}
263
264 frontend http1
265 use_backend be1
266 bind "fd@${my_frontend_fd}"
267 } -start
268
269 shell {
270 echo "${tmpdir} working directory content:"
271 ls -lR ${tmpdir}
272 cat ${tmpdir}/h1/cfg
273 }
274
Joseph Herlant71b4b152018-11-13 16:55:16 -0800275We give only the output of the shell to illustrate this example:
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +0200276
277 .
278 .
279 .
280 ** top 0.0 === shell {
281 **** top 0.0 shell_cmd|exec 2>&1 ;
282 **** top 0.0 shell_cmd| echo "tmpdir: /tmp/vtc.32092.479d521e"
283 **** top 0.0 shell_cmd| ls -lR /tmp/vtc.32092.479d521e
284 **** top 0.0 shell_cmd| cat /tmp/vtc.32092.479d521e/h1/cfg
285 .
286 .
287 .
288 **** top 0.0 shell_out|/tmp/vtc.3808.448cbfe0 working directory content:
289 **** top 0.0 shell_out|/tmp/vtc.32092.479d521e:
290 **** top 0.0 shell_out|total 8
291 **** top 0.0 shell_out|drwxr-xr-x 2 users 4096 Jun 7 11:09 h1
292 **** top 0.0 shell_out|-rw-r--r-- 1 me users 84 Jun 7 11:09 INFO
293 **** top 0.0 shell_out|
294 **** top 0.0 shell_out|/tmp/vtc.32092.479d521e/h1:
295 **** top 0.0 shell_out|total 4
296 **** top 0.0 shell_out|-rw-r----- 1 fred users 339 Jun 7 11:09 cfg
297 **** top 0.0 shell_out|srw------- 1 fred users 0 Jun 7 11:09 stats.sock
298 **** top 0.0 shell_out| global
299 **** top 0.0 shell_out|\tstats socket /tmp/vtc.32092.479d521e/h1/stats.sock level admin mode 600
300 **** top 0.0 shell_out|
301 **** top 0.0 shell_out| defaults
302 **** top 0.0 shell_out| mode http
303 **** top 0.0 shell_out| timeout connect 5s
304 **** top 0.0 shell_out| timeout server 30s
305 **** top 0.0 shell_out| timeout client 30s
306 **** top 0.0 shell_out|
307 **** top 0.0 shell_out| backend be1
308 **** top 0.0 shell_out| server srv1 127.0.0.1:36984
309 **** top 0.0 shell_out|
310 **** top 0.0 shell_out| frontend http1
311 **** top 0.0 shell_out| use_backend be1
312 **** top 0.0 shell_out| bind "fd@${my_frontend_fd}"
313 **** top 0.0 shell_status = 0x0000
314
315
316The following example illustrate how to run a basic HTTP transaction between 'c1'
317client and 's1' server with 'http1' as haproxy frontend. This frontend listen
318on TCP socket with 'my_frontend_fd' as file descriptor.
319
320 # Mandatory line
321 varnishtest "Basic HAproxy test"
322
323 # As some macros for haproxy are used in this file, this line is mandatory.
324 feature ignore_unknown_macro
325
326 server s1 {
327 rxreq
328 txresp -body "s1 >>> Hello world!"
329 } -start
330
331 haproxy h1 -conf {
332 # Configuration file of 'h1' haproxy instance.
333 defaults
334 mode http
335 timeout connect 5s
336 timeout server 30s
337 timeout client 30s
338
339 backend be1
340 # declare 'srv1' server to point to 's1' server instance declare above.
341 server srv1 ${s1_addr}:${s1_port}
342
343 frontend http1
344 use_backend be1
345 bind "fd@${my_frontend_fd}"
346 } -start
347
348 client c1 -connect ${h1_my_frontend_fd_sock} {
349 txreq -url "/"
350 rxresp
351 expect resp.status == 200
352 expect resp.body == "s1 >>> Hello world!"
353 } -run
354
355
356It is possible to shorten the previous VTC file haproxy command section as follows:
357
358 haproxy h1 -conf {
359 # Configuration file of 'h1' haproxy instance.
360 defaults
361 mode http
362 timeout connect 5s
363 timeout server 30s
364 timeout client 30s
365 }
366
367In this latter example, "backend" and "frontend" sections are automatically
368generated depending on the declarations of server instances.
369
370
371Another interesting real regression test case is the following: we declare one
372server 's1', a syslog server 'Slg_1' and a basic haproxy configuration for 'h1'
373haproxy instance. Here we want to check that the syslog message are correctly
374formatted thanks to "expect" "syslog" command (see syslog Slg_1 {...} command)
375below.
376
377 varnishtest "Wrong ip/port logging"
378 feature ignore_unknown_macro
379
380 #commit d02286d6c866e5c0a7eb6fbb127fa57f3becaf16
381 #Author: Willy Tarreau <w@1wt.eu>
382 #Date: Fri Jun 23 11:23:43 2017 +0200
383 #
384 # BUG/MINOR: log: pin the front connection when front ip/ports are logged
385 #
386 # Mathias Weiersmueller reported an interesting issue with logs which Lukas
387 # diagnosed as dating back from commit 9b061e332 (1.5-dev9). When front
388 # connection information (ip, port) are logged in TCP mode and the log is
389 # emitted at the end of the connection (eg: because %B or any log tag
390 # requiring LW_BYTES is set), the log is emitted after the connection is
391 # closed, so the address and ports cannot be retrieved anymore.
392 #
Joseph Herlant71b4b152018-11-13 16:55:16 -0800393 # It could be argued that we'd make a special case of these to immediately
Frédéric Lécaillefd9655c2018-06-07 14:57:30 +0200394 # retrieve the source and destination addresses from the connection, but it
395 # seems cleaner to simply pin the front connection, marking it "tracked" by
396 # adding the LW_XPRT flag to mention that we'll need some of these elements
397 # at the last moment. Only LW_FRTIP and LW_CLIP are affected. Note that after
398 # this change, LW_FRTIP could simply be removed as it's not used anywhere.
399
400 # Note that the problem doesn't happen when using %[src] or %[dst] since
401 # all sample expressions set LW_XPRT.
402
403
404 server s1 {
405 rxreq
406 txresp
407 } -start
408
409 syslog Slg_1 -level notice {
410 recv
411 recv
412 recv info
413 expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_port}.*\"ts\":\"cD\",\"
414 } -start
415
416 haproxy h1 -conf {
417 global
418 log ${Slg_1_addr}:${Slg_1_port} local0
419
420 defaults
421 log global
422 timeout connect 3000
423 timeout client 5
424 timeout server 10000
425
426 frontend fe1
427 bind "fd@${fe_1}"
428 mode tcp
429 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\"}
430 default_backend be_app
431
432 backend be_app
433 server app1 ${s1_addr}:${s1_port} check
434 } -start
435
436 client c1 -connect ${h1_fe_1_sock} {
437 txreq -url "/"
438 delay 0.02
439 } -run
440
441 syslog Slg_1 -wait
442
443
444Here is the output produced by varnishtest with the latter VTC file:
445
446 **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
447 **** top 0.0 extmacro def localhost=127.0.0.1
448 **** top 0.0 extmacro def bad_backend=127.0.0.1 40386
449 **** top 0.0 extmacro def bad_ip=192.0.2.255
450 **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
451 **** top 0.0 macro def tmpdir=/tmp/vtc.15752.560ca66b
452 * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc starting
453 ** top 0.0 === varnishtest "HAPEE bug 2788"
454 * top 0.0 TEST HAPEE bug 2788
455 ** top 0.0 === feature ignore_unknown_macro
456 ** top 0.0 === server s1 {
457 ** s1 0.0 Starting server
458 **** s1 0.0 macro def s1_addr=127.0.0.1
459 **** s1 0.0 macro def s1_port=35564
460 **** s1 0.0 macro def s1_sock=127.0.0.1 35564
461 * s1 0.0 Listen on 127.0.0.1 35564
462 ** top 0.0 === syslog Slg_1 -level notice {
463 ** Slg_1 0.0 Starting syslog server
464 ** s1 0.0 Started on 127.0.0.1 35564
465 **** Slg_1 0.0 macro def Slg_1_addr=127.0.0.1
466 **** Slg_1 0.0 macro def Slg_1_port=33012
467 **** Slg_1 0.0 macro def Slg_1_sock=127.0.0.1 33012
468 * Slg_1 0.0 Bound on 127.0.0.1 33012
469 ** top 0.0 === haproxy h1 -conf {
470 ** Slg_1 0.0 Started on 127.0.0.1 33012 (level: 5)
471 ** Slg_1 0.0 === recv
472 **** h1 0.0 macro def h1_fe_1_sock=::1 51782
473 **** h1 0.0 macro def h1_fe_1_addr=::1
474 **** h1 0.0 macro def h1_fe_1_port=51782
475 **** h1 0.0 setenv(fe_1, 7)
476 **** h1 0.0 conf| global
477 **** h1 0.0 conf|\tstats socket /tmp/vtc.15752.560ca66b/h1/stats.sock level admin mode 600
478 **** h1 0.0 conf|
479 **** h1 0.0 conf| global
480 **** h1 0.0 conf| log 127.0.0.1:33012 local0
481 **** h1 0.0 conf|
482 **** h1 0.0 conf| defaults
483 **** h1 0.0 conf| log global
484 **** h1 0.0 conf| timeout connect 3000
485 **** h1 0.0 conf| timeout client 5
486 **** h1 0.0 conf| timeout server 10000
487 **** h1 0.0 conf|
488 **** h1 0.0 conf| frontend fe1
489 **** h1 0.0 conf| bind "fd@${fe_1}"
490 **** h1 0.0 conf| mode tcp
491 **** 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\"}
492 **** h1 0.0 conf| default_backend be_app
493 **** h1 0.0 conf|
494 **** h1 0.0 conf| backend be_app
495 **** h1 0.0 conf| server app1 127.0.0.1:35564 check
496 ** h1 0.0 haproxy_start
497 **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 0
498 **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -d -f /tmp/vtc.15752.560ca66b/h1/cfg
499 **** h1 0.0 XXX 9 @277
500 *** h1 0.0 PID: 15787
501 **** h1 0.0 macro def h1_pid=15787
502 **** h1 0.0 macro def h1_name=/tmp/vtc.15752.560ca66b/h1
503 ** top 0.0 === client c1 -connect ${h1_fe_1_sock} {
504 ** c1 0.0 Starting client
505 ** c1 0.0 Waiting for client
506 *** c1 0.0 Connect to ::1 51782
507 *** c1 0.0 connected fd 8 from ::1 46962 to ::1 51782
508 ** c1 0.0 === txreq -url "/"
509 **** c1 0.0 txreq|GET / HTTP/1.1\r
510 **** c1 0.0 txreq|Host: 127.0.0.1\r
511 **** c1 0.0 txreq|\r
512 ** c1 0.0 === delay 0.02
513 *** c1 0.0 delaying 0.02 second(s)
514 *** h1 0.0 debug|Note: setting global.maxconn to 2000.
515 *** h1 0.0 debug|Available polling systems :
516 *** h1 0.0 debug| epoll :
517 *** h1 0.0 debug|pref=300,
518 *** h1 0.0 debug| test result OK
519 *** h1 0.0 debug| poll : pref=200, test result OK
520 *** h1 0.0 debug| select :
521 *** h1 0.0 debug|pref=150, test result FAILED
522 *** h1 0.0 debug|Total: 3 (2 usable), will use epoll.
523 *** h1 0.0 debug|
524 *** h1 0.0 debug|Available filters :
525 *** h1 0.0 debug|\t[SPOE] spoe
526 *** h1 0.0 debug|\t[COMP] compression
527 *** h1 0.0 debug|\t[TRACE] trace
528 **** Slg_1 0.0 syslog|<133>Jun 7 14:12:51 haproxy[15787]: Proxy fe1 started.
529 ** Slg_1 0.0 === recv
530 **** Slg_1 0.0 syslog|<133>Jun 7 14:12:51 haproxy[15787]: Proxy be_app started.
531 ** Slg_1 0.0 === recv info
532 *** h1 0.0 debug|00000000:fe1.accept(0007)=000a from [::1:46962]
533 *** s1 0.0 accepted fd 6 127.0.0.1 56770
534 ** s1 0.0 === rxreq
535 **** s1 0.0 rxhdr|GET / HTTP/1.1\r
536 **** s1 0.0 rxhdr|Host: 127.0.0.1\r
537 **** s1 0.0 rxhdr|\r
538 **** s1 0.0 rxhdrlen = 35
539 **** s1 0.0 http[ 0] |GET
540 **** s1 0.0 http[ 1] |/
541 **** s1 0.0 http[ 2] |HTTP/1.1
542 **** s1 0.0 http[ 3] |Host: 127.0.0.1
543 **** s1 0.0 bodylen = 0
544 ** s1 0.0 === txresp
545 **** s1 0.0 txresp|HTTP/1.1 200 OK\r
546 **** s1 0.0 txresp|Content-Length: 0\r
547 **** s1 0.0 txresp|\r
548 *** s1 0.0 shutting fd 6
549 ** s1 0.0 Ending
550 *** h1 0.0 debug|00000000:be_app.srvcls[000a:000c]
551 *** h1 0.0 debug|00000000:be_app.clicls[000a:000c]
552 *** h1 0.0 debug|00000000:be_app.closed[000a:000c]
553 **** 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"}
554 ** Slg_1 0.0 === expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_p...
555 ---- Slg_1 0.0 EXPECT FAILED ~ "\"dip\":\"::1\",\"dport\":\"51782.*\"ts\":\"cD\",\""
556 *** c1 0.0 closing fd 8
557 ** c1 0.0 Ending
558 * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/d02286d.vtc
559 ** h1 0.0 Reset and free h1 haproxy 15787
560 ** h1 0.0 Wait
561 ** h1 0.0 Stop HAproxy pid=15787
562 **** h1 0.0 Kill(2)=0: Success
563 **** h1 0.0 STDOUT poll 0x10
564 ** h1 0.1 WAIT4 pid=15787 status=0x0002 (user 0.000000 sys 0.004000)
565 ** s1 0.1 Waiting for server (4/-1)
566 ** Slg_1 0.1 Waiting for syslog server (5)
567 * top 0.1 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc FAILED
568 # top TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc FAILED (0.131) exit=2
569
570This test does not pass without the bug fix of d02286d commit. Indeed the third syslog
571message received by 'Slg_1' syslog server does not match the regular expression
572of the "syslog" "expect" command:
573
574 expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_port}.*\"ts\":\"cD\",\"
575
576(the IP address and port are missing), contrary to what happens with the correct bug fix:
577
578 **** top 0.0 extmacro def pwd=/home/fred/src/haproxy
579 **** top 0.0 extmacro def localhost=127.0.0.1
580 **** top 0.0 extmacro def bad_backend=127.0.0.1 37284
581 **** top 0.0 extmacro def bad_ip=192.0.2.255
582 **** top 0.0 macro def testdir=//home/fred/src/varnish-cache-haproxy
583 **** top 0.0 macro def tmpdir=/tmp/vtc.12696.186b28b0
584 * top 0.0 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc starting
585 ** top 0.0 === varnishtest "HAPEE bug 2788"
586 * top 0.0 TEST HAPEE bug 2788
587 ** top 0.0 === feature ignore_unknown_macro
588 ** top 0.0 === server s1 {
589 ** s1 0.0 Starting server
590 **** s1 0.0 macro def s1_addr=127.0.0.1
591 **** s1 0.0 macro def s1_port=53384
592 **** s1 0.0 macro def s1_sock=127.0.0.1 53384
593 * s1 0.0 Listen on 127.0.0.1 53384
594 ** top 0.0 === syslog Slg_1 -level notice {
595 ** Slg_1 0.0 Starting syslog server
596 **** Slg_1 0.0 macro def Slg_1_addr=127.0.0.1
597 ** s1 0.0 Started on 127.0.0.1 53384
598 **** Slg_1 0.0 macro def Slg_1_port=36195
599 **** Slg_1 0.0 macro def Slg_1_sock=127.0.0.1 36195
600 * Slg_1 0.0 Bound on 127.0.0.1 36195
601 ** top 0.0 === haproxy h1 -conf {
602 ** Slg_1 0.0 Started on 127.0.0.1 36195 (level: 5)
603 ** Slg_1 0.0 === recv
604 **** h1 0.0 macro def h1_fe_1_sock=::1 39264
605 **** h1 0.0 macro def h1_fe_1_addr=::1
606 **** h1 0.0 macro def h1_fe_1_port=39264
607 **** h1 0.0 setenv(fe_1, 7)
608 **** h1 0.0 conf| global
609 **** h1 0.0 conf|\tstats socket /tmp/vtc.12696.186b28b0/h1/stats.sock level admin mode 600
610 **** h1 0.0 conf|
611 **** h1 0.0 conf| global
612 **** h1 0.0 conf| log 127.0.0.1:36195 local0
613 **** h1 0.0 conf|
614 **** h1 0.0 conf| defaults
615 **** h1 0.0 conf| log global
616 **** h1 0.0 conf| timeout connect 3000
617 **** h1 0.0 conf| timeout client 5
618 **** h1 0.0 conf| timeout server 10000
619 **** h1 0.0 conf|
620 **** h1 0.0 conf| frontend fe1
621 **** h1 0.0 conf| bind "fd@${fe_1}"
622 **** h1 0.0 conf| mode tcp
623 **** 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\"}
624 **** h1 0.0 conf| default_backend be_app
625 **** h1 0.0 conf|
626 **** h1 0.0 conf| backend be_app
627 **** h1 0.0 conf| server app1 127.0.0.1:53384 check
628 ** h1 0.0 haproxy_start
629 **** h1 0.0 opt_worker 0 opt_daemon 0 opt_check_mode 0
630 **** h1 0.0 argv|exec /home/fred/src/haproxy/haproxy -d -f /tmp/vtc.12696.186b28b0/h1/cfg
631 **** h1 0.0 XXX 9 @277
632 *** h1 0.0 PID: 12728
633 **** h1 0.0 macro def h1_pid=12728
634 **** h1 0.0 macro def h1_name=/tmp/vtc.12696.186b28b0/h1
635 ** top 0.0 === client c1 -connect ${h1_fe_1_sock} {
636 ** c1 0.0 Starting client
637 ** c1 0.0 Waiting for client
638 *** c1 0.0 Connect to ::1 39264
639 *** c1 0.0 connected fd 8 from ::1 41245 to ::1 39264
640 ** c1 0.0 === txreq -url "/"
641 **** c1 0.0 txreq|GET / HTTP/1.1\r
642 **** c1 0.0 txreq|Host: 127.0.0.1\r
643 **** c1 0.0 txreq|\r
644 ** c1 0.0 === delay 0.02
645 *** c1 0.0 delaying 0.02 second(s)
646 *** h1 0.0 debug|Note: setting global.maxconn to 2000.
647 *** h1 0.0 debug|Available polling systems :
648 *** h1 0.0 debug| epoll : pref=300,
649 *** h1 0.0 debug| test result OK
650 *** h1 0.0 debug| poll : pref=200, test result OK
651 *** h1 0.0 debug| select : pref=150, test result FAILED
652 *** h1 0.0 debug|Total: 3 (2 usable), will use epoll.
653 *** h1 0.0 debug|
654 *** h1 0.0 debug|Available filters :
655 *** h1 0.0 debug|\t[SPOE] spoe
656 *** h1 0.0 debug|\t[COMP] compression
657 *** h1 0.0 debug|\t[TRACE] trace
658 *** h1 0.0 debug|Using epoll() as the polling mechanism.
659 **** Slg_1 0.0 syslog|<133>Jun 7 14:10:18 haproxy[12728]: Proxy fe1 started.
660 ** Slg_1 0.0 === recv
661 **** Slg_1 0.0 syslog|<133>Jun 7 14:10:18 haproxy[12728]: Proxy be_app started.
662 ** Slg_1 0.0 === recv info
663 *** h1 0.0 debug|00000000:fe1.accept(0007)=000c from [::1:41245] ALPN=<none>
664 *** s1 0.0 accepted fd 6 127.0.0.1 49946
665 ** s1 0.0 === rxreq
666 **** s1 0.0 rxhdr|GET / HTTP/1.1\r
667 **** s1 0.0 rxhdr|Host: 127.0.0.1\r
668 **** s1 0.0 rxhdr|\r
669 **** s1 0.0 rxhdrlen = 35
670 **** s1 0.0 http[ 0] |GET
671 **** s1 0.0 http[ 1] |/
672 **** s1 0.0 http[ 2] |HTTP/1.1
673 **** s1 0.0 http[ 3] |Host: 127.0.0.1
674 **** s1 0.0 bodylen = 0
675 ** s1 0.0 === txresp
676 **** s1 0.0 txresp|HTTP/1.1 200 OK\r
677 **** s1 0.0 txresp|Content-Length: 0\r
678 **** s1 0.0 txresp|\r
679 *** s1 0.0 shutting fd 6
680 ** s1 0.0 Ending
681 *** h1 0.0 debug|00000000:be_app.srvcls[000c:adfd]
682 *** h1 0.0 debug|00000000:be_app.clicls[000c:adfd]
683 *** h1 0.0 debug|00000000:be_app.closed[000c:adfd]
684 **** 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"}
685 ** Slg_1 0.0 === expect ~ \"dip\":\"${h1_fe_1_addr}\",\"dport\":\"${h1_fe_1_p...
686 **** Slg_1 0.0 EXPECT MATCH ~ "\"dip\":\"::1\",\"dport\":\"39264.*\"ts\":\"cD\",\""
687 *** Slg_1 0.0 shutting fd 5
688 ** Slg_1 0.0 Ending
689 *** c1 0.0 closing fd 8
690 ** c1 0.0 Ending
691 ** top 0.0 === syslog Slg_1 -wait
692 ** Slg_1 0.0 Waiting for syslog server (-1)
693 * top 0.0 RESETTING after /home/fred/src/varnish-cache-haproxy/d02286d.vtc
694 ** h1 0.0 Reset and free h1 haproxy 12728
695 ** h1 0.0 Wait
696 ** h1 0.0 Stop HAproxy pid=12728
697 **** h1 0.0 Kill(2)=0: Success
698 **** h1 0.0 STDOUT poll 0x10
699 ** h1 0.1 WAIT4 pid=12728 status=0x0002 (user 0.000000 sys 0.004000)
700 ** s1 0.1 Waiting for server (4/-1)
701 * top 0.1 TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc completed
702 # top TEST /home/fred/src/varnish-cache-haproxy/d02286d.vtc passed (0.128)
703
704In this latter execution the third syslog message is correct:
705
706 **** 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"}