forked from haproxy/haproxy
-
Notifications
You must be signed in to change notification settings - Fork 0
/
regression-testing.txt
706 lines (611 loc) · 30.4 KB
/
regression-testing.txt
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
+---------------------------------------+
| HAProxy regression testing with vtest |
+---------------------------------------+
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 vtest tool. Note that vtest was formally developed for
varnish cache reg testing and was named varnishtest. vtest is an haproxy specific
version of varnishtest program which reuses the non varnish cache specific code.
A lot of general information about how to write VTC files may be found in 'man/vtc.7'
manual of varnish cache sources directory or directly on the web here:
https://varnish-cache.org/docs/trunk/reference/vtc.html
It is *highly* recommended to read this manual before asking to haproxy ML. This
documentation only deals with the vtest support for haproxy.
vtest installation
------------------------
To use vtest you will have to download and compile the recent vtest
sources found at https://github.com/vtest/VTest.
To compile vtest:
$ cd VTest
$ make vtest
Note that varnishtest may be also compiled but not without the varnish cache
sources already compiled:
$ VARNISH_SRC=<...> make varnishtest
After having compiled these sources, the vtest executable location is at the
root of the vtest sources directory.
vtest execution
---------------------
vtest is able to search for the haproxy executable file it is supposed to
launch thanks to the PATH environment variable. To force the executable to be used by
vtest, the HAPROXY_PROGRAM environment variable for vtest may be
typically set as follows:
$ HAPROXY_PROGRAM=~/srcs/haproxy/haproxy vtest ...
vtest program comes with interesting options. The most interesting are:
-t Timeout in seconds to abort the test if some launched program
-v By default, vtest does not dump the outputs of process 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 vtest, -d option is enabled by default.
How to write VTC files
----------------------
A VTC file must start with a "varnishtest" or "vtest" 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
vtest parser code for haproxy commands generates macros the vtest
parser code for varnish cache has no knowledge of. This line prevents vtest from
failing in such cases. As a "cli" macro automatically generated, this
"feature ignore_unknown_macro" is mandatory for each VTC file for haproxy.
To make vtest capable of testing haproxy, two new VTC commands have been
implemented: "haproxy" and "syslog". "haproxy" is used to start haproxy process.
"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 vtest process.
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 <[email protected]>
#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
# segmentation fault when first errors are caught, 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] (25558) : parsing [/tmp/vtc.25540.59b6ec5d/h1/cfg:10] : 'filter' : ''spoe' : missing config file'
*** h1 0.0 debug|[ALERT] (25558) : Error(s) found in configuration file : /tmp/vtc.25540.59b6ec5d/h1/cfg
*** h1 0.0 debug|[ALERT] (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 output 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 <[email protected]>
#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 immediately
# retrieve the source and destination addresses from the connection, but it
# seems cleaner to simply pin the front connection, marking it "tracked" by
# adding the LW_XPRT flag to mention that we'll need some of these elements
# at the last moment. Only LW_FRTIP and LW_CLIP are affected. Note that after
# this change, LW_FRTIP could simply be removed as it's not used anywhere.
# Note that the problem doesn't happen when using %[src] or %[dst] since
# all sample expressions set LW_XPRT.
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"}