1package integration
2
3import (
4	"crypto/md5"
5	"crypto/rand"
6	"fmt"
7	"io"
8	"net/http"
9	"os"
10	"strconv"
11	"strings"
12	"time"
13
14	"github.com/go-check/check"
15	"github.com/traefik/traefik/v2/integration/try"
16	"github.com/traefik/traefik/v2/pkg/log"
17	"github.com/traefik/traefik/v2/pkg/middlewares/accesslog"
18	checker "github.com/vdemeester/shakers"
19)
20
21const (
22	traefikTestLogFile       = "traefik.log"
23	traefikTestAccessLogFile = "access.log"
24)
25
26// AccessLogSuite tests suite.
27type AccessLogSuite struct{ BaseSuite }
28
29type accessLogValue struct {
30	formatOnly bool
31	code       string
32	user       string
33	routerName string
34	serviceURL string
35}
36
37func (s *AccessLogSuite) SetUpSuite(c *check.C) {
38	s.createComposeProject(c, "access_log")
39	s.composeUp(c)
40}
41
42func (s *AccessLogSuite) TearDownTest(c *check.C) {
43	displayTraefikLogFile(c, traefikTestLogFile)
44	_ = os.Remove(traefikTestAccessLogFile)
45}
46
47func (s *AccessLogSuite) TestAccessLog(c *check.C) {
48	ensureWorkingDirectoryIsClean()
49
50	// Start Traefik
51	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
52	defer display(c)
53
54	defer func() {
55		traefikLog, err := os.ReadFile(traefikTestLogFile)
56		c.Assert(err, checker.IsNil)
57		log.WithoutContext().Info(string(traefikLog))
58	}()
59
60	err := cmd.Start()
61	c.Assert(err, checker.IsNil)
62	defer s.killCmd(cmd)
63
64	waitForTraefik(c, "server1")
65
66	checkStatsForLogFile(c)
67
68	// Verify Traefik started OK
69	checkTraefikStarted(c)
70
71	// Make some requests
72	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
73	c.Assert(err, checker.IsNil)
74	req.Host = "frontend1.docker.local"
75
76	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
77	c.Assert(err, checker.IsNil)
78
79	req, err = http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
80	c.Assert(err, checker.IsNil)
81	req.Host = "frontend2.docker.local"
82
83	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
84	c.Assert(err, checker.IsNil)
85	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
86	c.Assert(err, checker.IsNil)
87
88	// Verify access.log output as expected
89	count := checkAccessLogOutput(c)
90
91	c.Assert(count, checker.GreaterOrEqualThan, 3)
92
93	// Verify no other Traefik problems
94	checkNoOtherTraefikProblems(c)
95}
96
97func (s *AccessLogSuite) TestAccessLogAuthFrontend(c *check.C) {
98	ensureWorkingDirectoryIsClean()
99
100	expected := []accessLogValue{
101		{
102			formatOnly: false,
103			code:       "401",
104			user:       "-",
105			routerName: "rt-authFrontend",
106			serviceURL: "-",
107		},
108		{
109			formatOnly: false,
110			code:       "401",
111			user:       "test",
112			routerName: "rt-authFrontend",
113			serviceURL: "-",
114		},
115		{
116			formatOnly: false,
117			code:       "200",
118			user:       "test",
119			routerName: "rt-authFrontend",
120			serviceURL: "http://172.31.42",
121		},
122	}
123
124	// Start Traefik
125	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
126	defer display(c)
127
128	err := cmd.Start()
129	c.Assert(err, checker.IsNil)
130	defer s.killCmd(cmd)
131
132	checkStatsForLogFile(c)
133
134	waitForTraefik(c, "authFrontend")
135
136	// Verify Traefik started OK
137	checkTraefikStarted(c)
138
139	// Test auth entrypoint
140	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8006/", nil)
141	c.Assert(err, checker.IsNil)
142	req.Host = "frontend.auth.docker.local"
143
144	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusUnauthorized), try.HasBody())
145	c.Assert(err, checker.IsNil)
146
147	req.SetBasicAuth("test", "")
148
149	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusUnauthorized), try.HasBody())
150	c.Assert(err, checker.IsNil)
151
152	req.SetBasicAuth("test", "test")
153
154	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
155	c.Assert(err, checker.IsNil)
156
157	// Verify access.log output as expected
158	count := checkAccessLogExactValuesOutput(c, expected)
159
160	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
161
162	// Verify no other Traefik problems
163	checkNoOtherTraefikProblems(c)
164}
165
166func (s *AccessLogSuite) TestAccessLogDigestAuthMiddleware(c *check.C) {
167	ensureWorkingDirectoryIsClean()
168
169	expected := []accessLogValue{
170		{
171			formatOnly: false,
172			code:       "401",
173			user:       "-",
174			routerName: "rt-digestAuthMiddleware",
175			serviceURL: "-",
176		},
177		{
178			formatOnly: false,
179			code:       "401",
180			user:       "test",
181			routerName: "rt-digestAuthMiddleware",
182			serviceURL: "-",
183		},
184		{
185			formatOnly: false,
186			code:       "200",
187			user:       "test",
188			routerName: "rt-digestAuthMiddleware",
189			serviceURL: "http://172.31.42",
190		},
191	}
192
193	// Start Traefik
194	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
195	defer display(c)
196
197	err := cmd.Start()
198	c.Assert(err, checker.IsNil)
199	defer s.killCmd(cmd)
200
201	checkStatsForLogFile(c)
202
203	waitForTraefik(c, "digestAuthMiddleware")
204
205	// Verify Traefik started OK
206	checkTraefikStarted(c)
207
208	// Test auth entrypoint
209	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8008/", nil)
210	c.Assert(err, checker.IsNil)
211	req.Host = "entrypoint.digest.auth.docker.local"
212
213	resp, err := try.ResponseUntilStatusCode(req, 500*time.Millisecond, http.StatusUnauthorized)
214	c.Assert(err, checker.IsNil)
215
216	digest := digestParts(resp)
217	digest["uri"] = "/"
218	digest["method"] = http.MethodGet
219	digest["username"] = "test"
220	digest["password"] = "wrong"
221
222	req.Header.Set("Authorization", getDigestAuthorization(digest))
223	req.Header.Set("Content-Type", "application/json")
224
225	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusUnauthorized), try.HasBody())
226	c.Assert(err, checker.IsNil)
227
228	digest["password"] = "test"
229
230	req.Header.Set("Authorization", getDigestAuthorization(digest))
231
232	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
233	c.Assert(err, checker.IsNil)
234
235	// Verify access.log output as expected
236	count := checkAccessLogExactValuesOutput(c, expected)
237
238	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
239
240	// Verify no other Traefik problems
241	checkNoOtherTraefikProblems(c)
242}
243
244// Thanks to mvndaai for digest authentication
245// https://stackoverflow.com/questions/39474284/how-do-you-do-a-http-post-with-digest-authentication-in-golang/39481441#39481441
246func digestParts(resp *http.Response) map[string]string {
247	result := map[string]string{}
248	if len(resp.Header["Www-Authenticate"]) > 0 {
249		wantedHeaders := []string{"nonce", "realm", "qop", "opaque"}
250		responseHeaders := strings.Split(resp.Header["Www-Authenticate"][0], ",")
251		for _, r := range responseHeaders {
252			for _, w := range wantedHeaders {
253				if strings.Contains(r, w) {
254					result[w] = strings.Split(r, `"`)[1]
255				}
256			}
257		}
258	}
259	return result
260}
261
262func getMD5(data string) string {
263	digest := md5.New()
264	if _, err := digest.Write([]byte(data)); err != nil {
265		log.WithoutContext().Error(err)
266	}
267	return fmt.Sprintf("%x", digest.Sum(nil))
268}
269
270func getCnonce() string {
271	b := make([]byte, 8)
272	if _, err := io.ReadFull(rand.Reader, b); err != nil {
273		log.WithoutContext().Error(err)
274	}
275	return fmt.Sprintf("%x", b)[:16]
276}
277
278func getDigestAuthorization(digestParts map[string]string) string {
279	d := digestParts
280	ha1 := getMD5(d["username"] + ":" + d["realm"] + ":" + d["password"])
281	ha2 := getMD5(d["method"] + ":" + d["uri"])
282	nonceCount := "00000001"
283	cnonce := getCnonce()
284	response := getMD5(fmt.Sprintf("%s:%s:%s:%s:%s:%s", ha1, d["nonce"], nonceCount, cnonce, d["qop"], ha2))
285	authorization := fmt.Sprintf(`Digest username="%s", realm="%s", nonce="%s", uri="%s", cnonce="%s", nc=%s, qop=%s, response="%s", opaque="%s", algorithm="MD5"`,
286		d["username"], d["realm"], d["nonce"], d["uri"], cnonce, nonceCount, d["qop"], response, d["opaque"])
287	return authorization
288}
289
290func (s *AccessLogSuite) TestAccessLogFrontendRedirect(c *check.C) {
291	ensureWorkingDirectoryIsClean()
292
293	expected := []accessLogValue{
294		{
295			formatOnly: false,
296			code:       "302",
297			user:       "-",
298			routerName: "rt-frontendRedirect",
299			serviceURL: "-",
300		},
301		{
302			formatOnly: true,
303		},
304	}
305
306	// Start Traefik
307	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
308	defer display(c)
309
310	err := cmd.Start()
311	c.Assert(err, checker.IsNil)
312	defer s.killCmd(cmd)
313
314	checkStatsForLogFile(c)
315
316	waitForTraefik(c, "frontendRedirect")
317
318	// Verify Traefik started OK
319	checkTraefikStarted(c)
320
321	// Test frontend redirect
322	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8005/test", nil)
323	c.Assert(err, checker.IsNil)
324	req.Host = ""
325
326	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
327	c.Assert(err, checker.IsNil)
328
329	// Verify access.log output as expected
330	count := checkAccessLogExactValuesOutput(c, expected)
331
332	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
333
334	// Verify no other Traefik problems
335	checkNoOtherTraefikProblems(c)
336}
337
338func (s *AccessLogSuite) TestAccessLogRateLimit(c *check.C) {
339	ensureWorkingDirectoryIsClean()
340
341	expected := []accessLogValue{
342		{
343			formatOnly: true,
344		},
345		{
346			formatOnly: true,
347		},
348		{
349			formatOnly: false,
350			code:       "429",
351			user:       "-",
352			routerName: "rt-rateLimit",
353			serviceURL: "-",
354		},
355	}
356
357	// Start Traefik
358	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
359	defer display(c)
360
361	err := cmd.Start()
362	c.Assert(err, checker.IsNil)
363	defer s.killCmd(cmd)
364
365	checkStatsForLogFile(c)
366
367	waitForTraefik(c, "rateLimit")
368
369	// Verify Traefik started OK
370	checkTraefikStarted(c)
371
372	// Test rate limit
373	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8007/", nil)
374	c.Assert(err, checker.IsNil)
375	req.Host = "ratelimit.docker.local"
376
377	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
378	c.Assert(err, checker.IsNil)
379	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
380	c.Assert(err, checker.IsNil)
381	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusTooManyRequests), try.HasBody())
382	c.Assert(err, checker.IsNil)
383
384	// Verify access.log output as expected
385	count := checkAccessLogExactValuesOutput(c, expected)
386
387	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
388
389	// Verify no other Traefik problems
390	checkNoOtherTraefikProblems(c)
391}
392
393func (s *AccessLogSuite) TestAccessLogBackendNotFound(c *check.C) {
394	ensureWorkingDirectoryIsClean()
395
396	expected := []accessLogValue{
397		{
398			formatOnly: false,
399			code:       "404",
400			user:       "-",
401			routerName: "-",
402			serviceURL: "-",
403		},
404	}
405
406	// Start Traefik
407	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
408	defer display(c)
409
410	err := cmd.Start()
411	c.Assert(err, checker.IsNil)
412	defer s.killCmd(cmd)
413
414	waitForTraefik(c, "server1")
415
416	checkStatsForLogFile(c)
417
418	// Verify Traefik started OK
419	checkTraefikStarted(c)
420
421	// Test rate limit
422	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
423	c.Assert(err, checker.IsNil)
424	req.Host = "backendnotfound.docker.local"
425
426	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusNotFound), try.HasBody())
427	c.Assert(err, checker.IsNil)
428
429	// Verify access.log output as expected
430	count := checkAccessLogExactValuesOutput(c, expected)
431
432	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
433
434	// Verify no other Traefik problems
435	checkNoOtherTraefikProblems(c)
436}
437
438func (s *AccessLogSuite) TestAccessLogFrontendWhitelist(c *check.C) {
439	ensureWorkingDirectoryIsClean()
440
441	expected := []accessLogValue{
442		{
443			formatOnly: false,
444			code:       "403",
445			user:       "-",
446			routerName: "rt-frontendWhitelist",
447			serviceURL: "-",
448		},
449	}
450
451	// Start Traefik
452	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
453	defer display(c)
454
455	err := cmd.Start()
456	c.Assert(err, checker.IsNil)
457	defer s.killCmd(cmd)
458
459	checkStatsForLogFile(c)
460
461	waitForTraefik(c, "frontendWhitelist")
462
463	// Verify Traefik started OK
464	checkTraefikStarted(c)
465
466	// Test rate limit
467	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8000/", nil)
468	c.Assert(err, checker.IsNil)
469	req.Host = "frontend.whitelist.docker.local"
470
471	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusForbidden), try.HasBody())
472	c.Assert(err, checker.IsNil)
473
474	// Verify access.log output as expected
475	count := checkAccessLogExactValuesOutput(c, expected)
476
477	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
478
479	// Verify no other Traefik problems
480	checkNoOtherTraefikProblems(c)
481}
482
483func (s *AccessLogSuite) TestAccessLogAuthFrontendSuccess(c *check.C) {
484	ensureWorkingDirectoryIsClean()
485
486	expected := []accessLogValue{
487		{
488			formatOnly: false,
489			code:       "200",
490			user:       "test",
491			routerName: "rt-authFrontend",
492			serviceURL: "http://172.31.42",
493		},
494	}
495
496	// Start Traefik
497	cmd, display := s.traefikCmd(withConfigFile("fixtures/access_log_config.toml"))
498	defer display(c)
499
500	err := cmd.Start()
501	c.Assert(err, checker.IsNil)
502	defer s.killCmd(cmd)
503
504	checkStatsForLogFile(c)
505
506	waitForTraefik(c, "authFrontend")
507
508	// Verify Traefik started OK
509	checkTraefikStarted(c)
510
511	// Test auth entrypoint
512	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8006/", nil)
513	c.Assert(err, checker.IsNil)
514	req.Host = "frontend.auth.docker.local"
515	req.SetBasicAuth("test", "test")
516
517	err = try.Request(req, 500*time.Millisecond, try.StatusCodeIs(http.StatusOK), try.HasBody())
518	c.Assert(err, checker.IsNil)
519
520	// Verify access.log output as expected
521	count := checkAccessLogExactValuesOutput(c, expected)
522
523	c.Assert(count, checker.GreaterOrEqualThan, len(expected))
524
525	// Verify no other Traefik problems
526	checkNoOtherTraefikProblems(c)
527}
528
529func checkNoOtherTraefikProblems(c *check.C) {
530	traefikLog, err := os.ReadFile(traefikTestLogFile)
531	c.Assert(err, checker.IsNil)
532	if len(traefikLog) > 0 {
533		fmt.Printf("%s\n", string(traefikLog))
534	}
535}
536
537func checkAccessLogOutput(c *check.C) int {
538	lines := extractLines(c)
539	count := 0
540	for i, line := range lines {
541		if len(line) > 0 {
542			count++
543			CheckAccessLogFormat(c, line, i)
544		}
545	}
546	return count
547}
548
549func checkAccessLogExactValuesOutput(c *check.C, values []accessLogValue) int {
550	lines := extractLines(c)
551	count := 0
552	for i, line := range lines {
553		fmt.Println(line)
554		if len(line) > 0 {
555			count++
556			if values[i].formatOnly {
557				CheckAccessLogFormat(c, line, i)
558			} else {
559				checkAccessLogExactValues(c, line, i, values[i])
560			}
561		}
562	}
563	return count
564}
565
566func extractLines(c *check.C) []string {
567	accessLog, err := os.ReadFile(traefikTestAccessLogFile)
568	c.Assert(err, checker.IsNil)
569
570	lines := strings.Split(string(accessLog), "\n")
571
572	var clean []string
573	for _, line := range lines {
574		if !strings.Contains(line, "/api/rawdata") {
575			clean = append(clean, line)
576		}
577	}
578	return clean
579}
580
581func checkStatsForLogFile(c *check.C) {
582	err := try.Do(1*time.Second, func() error {
583		if _, errStat := os.Stat(traefikTestLogFile); errStat != nil {
584			return fmt.Errorf("could not get stats for log file: %w", errStat)
585		}
586		return nil
587	})
588	c.Assert(err, checker.IsNil)
589}
590
591func ensureWorkingDirectoryIsClean() {
592	os.Remove(traefikTestAccessLogFile)
593	os.Remove(traefikTestLogFile)
594}
595
596func checkTraefikStarted(c *check.C) []byte {
597	traefikLog, err := os.ReadFile(traefikTestLogFile)
598	c.Assert(err, checker.IsNil)
599	if len(traefikLog) > 0 {
600		fmt.Printf("%s\n", string(traefikLog))
601	}
602	return traefikLog
603}
604
605func CheckAccessLogFormat(c *check.C, line string, i int) {
606	results, err := accesslog.ParseAccessLog(line)
607	c.Assert(err, checker.IsNil)
608	c.Assert(results, checker.HasLen, 14)
609	c.Assert(results[accesslog.OriginStatus], checker.Matches, `^(-|\d{3})$`)
610	count, _ := strconv.Atoi(results[accesslog.RequestCount])
611	c.Assert(count, checker.GreaterOrEqualThan, i+1)
612	c.Assert(results[accesslog.RouterName], checker.Matches, `"(rt-.+@docker|api@internal)"`)
613	c.Assert(results[accesslog.ServiceURL], checker.HasPrefix, `"http://`)
614	c.Assert(results[accesslog.Duration], checker.Matches, `^\d+ms$`)
615}
616
617func checkAccessLogExactValues(c *check.C, line string, i int, v accessLogValue) {
618	results, err := accesslog.ParseAccessLog(line)
619	c.Assert(err, checker.IsNil)
620	c.Assert(results, checker.HasLen, 14)
621	if len(v.user) > 0 {
622		c.Assert(results[accesslog.ClientUsername], checker.Equals, v.user)
623	}
624	c.Assert(results[accesslog.OriginStatus], checker.Equals, v.code)
625	count, _ := strconv.Atoi(results[accesslog.RequestCount])
626	c.Assert(count, checker.GreaterOrEqualThan, i+1)
627	c.Assert(results[accesslog.RouterName], checker.Matches, `^"?`+v.routerName+`.*(@docker)?$`)
628	c.Assert(results[accesslog.ServiceURL], checker.Matches, `^"?`+v.serviceURL+`.*$`)
629	c.Assert(results[accesslog.Duration], checker.Matches, `^\d+ms$`)
630}
631
632func waitForTraefik(c *check.C, containerName string) {
633	time.Sleep(1 * time.Second)
634
635	// Wait for Traefik to turn ready.
636	req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8080/api/rawdata", nil)
637	c.Assert(err, checker.IsNil)
638
639	err = try.Request(req, 2*time.Second, try.StatusCodeIs(http.StatusOK), try.BodyContains(containerName))
640	c.Assert(err, checker.IsNil)
641}
642
643func displayTraefikLogFile(c *check.C, path string) {
644	if c.Failed() {
645		if _, err := os.Stat(path); !os.IsNotExist(err) {
646			content, errRead := os.ReadFile(path)
647			fmt.Printf("%s: Traefik logs: \n", c.TestName())
648			if errRead == nil {
649				fmt.Println(content)
650			} else {
651				fmt.Println(errRead)
652			}
653		} else {
654			fmt.Printf("%s: No Traefik logs.\n", c.TestName())
655		}
656		errRemove := os.Remove(path)
657		if errRemove != nil {
658			fmt.Println(errRemove)
659		}
660	}
661}
662