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