2017-08-11 13:04:58 +03:00
// +build !windows
package integration
import (
"bufio"
"net/http"
"os"
2019-11-14 18:40:05 +03:00
"strings"
2017-08-11 13:04:58 +03:00
"syscall"
"time"
"github.com/go-check/check"
2020-09-16 16:46:04 +03:00
"github.com/traefik/traefik/v2/integration/try"
2017-08-11 13:04:58 +03:00
checker "github.com/vdemeester/shakers"
)
2020-05-11 13:06:07 +03:00
// Log rotation integration test suite.
2017-08-11 13:04:58 +03:00
type LogRotationSuite struct { BaseSuite }
2018-01-11 12:04:03 +03:00
func ( s * LogRotationSuite ) SetUpSuite ( c * check . C ) {
s . createComposeProject ( c , "access_log" )
s . composeProject . Start ( c )
s . composeProject . Container ( c , "server1" )
}
2017-08-11 13:04:58 +03:00
func ( s * LogRotationSuite ) TestAccessLogRotation ( c * check . C ) {
// Start Traefik
2017-09-13 11:34:04 +03:00
cmd , display := s . traefikCmd ( withConfigFile ( "fixtures/access_log_config.toml" ) )
defer display ( c )
2018-02-05 11:48:03 +03:00
defer displayTraefikLogFile ( c , traefikTestLogFile )
2017-08-11 13:04:58 +03:00
err := cmd . Start ( )
c . Assert ( err , checker . IsNil )
2020-10-09 10:32:03 +03:00
defer s . killCmd ( cmd )
2018-02-05 11:48:03 +03:00
2017-08-11 13:04:58 +03:00
defer os . Remove ( traefikTestAccessLogFile )
// Verify Traefik started ok
verifyEmptyErrorLog ( c , "traefik.log" )
2018-01-11 12:04:03 +03:00
waitForTraefik ( c , "server1" )
2017-08-11 13:04:58 +03:00
// Make some requests
2018-01-11 12:04:03 +03:00
req , err := http . NewRequest ( http . MethodGet , "http://127.0.0.1:8000/" , nil )
c . Assert ( err , checker . IsNil )
req . Host = "frontend1.docker.local"
err = try . Request ( req , 500 * time . Millisecond , try . StatusCodeIs ( http . StatusOK ) , try . HasBody ( ) )
2017-08-11 13:04:58 +03:00
c . Assert ( err , checker . IsNil )
// Rename access log
err = os . Rename ( traefikTestAccessLogFile , traefikTestAccessLogFile + ".rotated" )
c . Assert ( err , checker . IsNil )
// in the midst of the requests, issue SIGUSR1 signal to server process
err = cmd . Process . Signal ( syscall . SIGUSR1 )
c . Assert ( err , checker . IsNil )
// continue issuing requests
2018-01-11 12:04:03 +03:00
err = try . Request ( req , 500 * time . Millisecond , try . StatusCodeIs ( http . StatusOK ) , try . HasBody ( ) )
2017-08-11 13:04:58 +03:00
c . Assert ( err , checker . IsNil )
2018-01-11 12:04:03 +03:00
err = try . Request ( req , 500 * time . Millisecond , try . StatusCodeIs ( http . StatusOK ) , try . HasBody ( ) )
2017-08-11 13:04:58 +03:00
c . Assert ( err , checker . IsNil )
// Verify access.log.rotated output as expected
2017-10-06 10:20:13 +03:00
logAccessLogFile ( c , traefikTestAccessLogFile + ".rotated" )
2017-08-11 13:04:58 +03:00
lineCount := verifyLogLines ( c , traefikTestAccessLogFile + ".rotated" , 0 , true )
c . Assert ( lineCount , checker . GreaterOrEqualThan , 1 )
2017-10-06 10:20:13 +03:00
// make sure that the access log file is at least created before we do assertions on it
err = try . Do ( 1 * time . Second , func ( ) error {
_ , err := os . Stat ( traefikTestAccessLogFile )
return err
} )
c . Assert ( err , checker . IsNil , check . Commentf ( "access log file was not created in time" ) )
2017-08-11 13:04:58 +03:00
// Verify access.log output as expected
2017-10-06 10:20:13 +03:00
logAccessLogFile ( c , traefikTestAccessLogFile )
2017-08-11 13:04:58 +03:00
lineCount = verifyLogLines ( c , traefikTestAccessLogFile , lineCount , true )
c . Assert ( lineCount , checker . Equals , 3 )
verifyEmptyErrorLog ( c , traefikTestLogFile )
}
func ( s * LogRotationSuite ) TestTraefikLogRotation ( c * check . C ) {
// Start Traefik
2017-09-13 11:34:04 +03:00
cmd , display := s . traefikCmd ( withConfigFile ( "fixtures/traefik_log_config.toml" ) )
defer display ( c )
2018-02-05 11:48:03 +03:00
defer displayTraefikLogFile ( c , traefikTestLogFile )
2017-08-11 13:04:58 +03:00
err := cmd . Start ( )
c . Assert ( err , checker . IsNil )
2020-10-09 10:32:03 +03:00
defer s . killCmd ( cmd )
2018-02-05 11:48:03 +03:00
2017-08-11 13:04:58 +03:00
defer os . Remove ( traefikTestAccessLogFile )
2018-01-11 12:04:03 +03:00
waitForTraefik ( c , "server1" )
2017-08-11 13:04:58 +03:00
// Rename traefik log
err = os . Rename ( traefikTestLogFile , traefikTestLogFile + ".rotated" )
c . Assert ( err , checker . IsNil )
// issue SIGUSR1 signal to server process
err = cmd . Process . Signal ( syscall . SIGUSR1 )
c . Assert ( err , checker . IsNil )
err = cmd . Process . Signal ( syscall . SIGTERM )
c . Assert ( err , checker . IsNil )
// Allow time for switch to be processed
err = try . Do ( 3 * time . Second , func ( ) error {
_ , err = os . Stat ( traefikTestLogFile )
return err
} )
c . Assert ( err , checker . IsNil )
// we have at least 6 lines in traefik.log.rotated
lineCount := verifyLogLines ( c , traefikTestLogFile + ".rotated" , 0 , false )
// GreaterOrEqualThan used to ensure test doesn't break
// If more log entries are output on startup
2017-08-25 17:10:03 +03:00
c . Assert ( lineCount , checker . GreaterOrEqualThan , 5 )
2017-08-11 13:04:58 +03:00
2018-07-03 11:02:03 +03:00
// Verify traefik.log output as expected
2017-08-11 13:04:58 +03:00
lineCount = verifyLogLines ( c , traefikTestLogFile , lineCount , false )
c . Assert ( lineCount , checker . GreaterOrEqualThan , 7 )
}
2017-10-06 10:20:13 +03:00
func logAccessLogFile ( c * check . C , fileName string ) {
2021-03-04 22:08:03 +03:00
output , err := os . ReadFile ( fileName )
2017-10-06 10:20:13 +03:00
c . Assert ( err , checker . IsNil )
c . Logf ( "Contents of file %s\n%s" , fileName , string ( output ) )
}
2017-08-11 13:04:58 +03:00
func verifyEmptyErrorLog ( c * check . C , name string ) {
err := try . Do ( 5 * time . Second , func ( ) error {
2021-03-04 22:08:03 +03:00
traefikLog , e2 := os . ReadFile ( name )
2017-08-11 13:04:58 +03:00
if e2 != nil {
return e2
}
2019-01-18 17:18:04 +03:00
c . Assert ( string ( traefikLog ) , checker . HasLen , 0 )
2017-08-11 13:04:58 +03:00
return nil
} )
c . Assert ( err , checker . IsNil )
}
func verifyLogLines ( c * check . C , fileName string , countInit int , accessLog bool ) int {
rotated , err := os . Open ( fileName )
c . Assert ( err , checker . IsNil )
rotatedLog := bufio . NewScanner ( rotated )
count := countInit
for rotatedLog . Scan ( ) {
line := rotatedLog . Text ( )
if accessLog {
if len ( line ) > 0 {
2019-11-14 18:40:05 +03:00
if ! strings . Contains ( line , "/api/rawdata" ) {
CheckAccessLogFormat ( c , line , count )
count ++
}
2017-08-11 13:04:58 +03:00
}
2019-11-14 18:40:05 +03:00
} else {
count ++
2017-08-11 13:04:58 +03:00
}
}
return count
}