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