From 0d5c8b7c3df8451167b7aab95270ad94b53e5f29 Mon Sep 17 00:00:00 2001 From: katexochen Date: Thu, 10 Feb 2022 22:24:04 +0100 Subject: [PATCH 1/5] Make flushDaemon stoppable and testable Refactor flushDaemon function into a seperate struct. Instead of starting the daemon in the init function, it is now started during createFile, where it is only used. Add function to stop daemon. This way, users can gracefully shut down klog and prevent goroutine leakage. Test daemon flushing. --- examples/flushing/flushing_test.go | 39 ++++++++++++++ examples/go.mod | 1 + examples/go.sum | 45 +++++++++++++++- klog.go | 82 ++++++++++++++++++++++++++++-- klog_test.go | 57 +++++++++++++++++---- 5 files changed, 208 insertions(+), 16 deletions(-) create mode 100644 examples/flushing/flushing_test.go diff --git a/examples/flushing/flushing_test.go b/examples/flushing/flushing_test.go new file mode 100644 index 00000000..3d46fbca --- /dev/null +++ b/examples/flushing/flushing_test.go @@ -0,0 +1,39 @@ +package main + +import ( + "flag" + "testing" + + "go.uber.org/goleak" + "k8s.io/klog/v2" +) + +func main() { + klog.InitFlags(nil) + + // By default klog writes to stderr. Setting logtostderr to false makes klog + // write to a log file. + flag.Set("logtostderr", "false") + flag.Set("log_file", "myfile.log") + flag.Parse() + + // Info writes the first log message. When the first log file is created, + // a flushDaemon is started to frequently flush bytes to the file. + klog.Info("nice to meet you") + + // klog won't ever stop this flushDaemon. To exit without leaking a goroutine, + // the daemon can be stopped manually. + klog.StopFlushDaemon() + + // After you stopped the flushDaemon, you can still manually flush. + klog.Info("bye") + klog.Flush() +} + +func TestLeakingFlushDaemon(t *testing.T) { + // goleak detects leaking goroutines. + defer goleak.VerifyNone(t) + + // Without calling StopFlushDaemon in main, this test will fail. + main() +} diff --git a/examples/go.mod b/examples/go.mod index d7956666..c0edcc16 100644 --- a/examples/go.mod +++ b/examples/go.mod @@ -6,6 +6,7 @@ require ( github.com/go-logr/logr v1.2.2 github.com/go-logr/zapr v1.2.2 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b + go.uber.org/goleak v1.1.12 go.uber.org/zap v1.19.0 k8s.io/klog/v2 v2.30.0 ) diff --git a/examples/go.sum b/examples/go.sum index 5b43f393..2414d126 100644 --- a/examples/go.sum +++ b/examples/go.sum @@ -1,6 +1,7 @@ github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8= github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= @@ -19,38 +20,78 @@ github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINE github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4= github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= +github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw= go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= -go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= +go.uber.org/goleak v1.1.12 h1:gZAh5/EyT/HQwlpkCy6wTpqfH9H8Lz8zbm3dZh+OyzA= +go.uber.org/goleak v1.1.12/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ= go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= go.uber.org/zap v1.19.0 h1:mZQZefskPPCMIBCSEH0v2/iUqqLrYtaeqwD6FUGUnFE= go.uber.org/zap v1.19.0/go.mod h1:xg/QME4nWcxGxrpdeYfq7UvYrLh66cuVKdrbD1XF/NI= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= +golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= +golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= +golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= +golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= +golang.org/x/mod v0.4.2 h1:Gz96sIWK3OalVv/I/qNygP42zyoKp3xptRVCWRFEBvo= +golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= +golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= +golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= +golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= +golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM= +golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210510120138-977fb7262007 h1:gG67DSER+11cZvqIMb8S8bt0vZtiN6xWYARwirrOSfE= +golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= +golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= +golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= +golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= +golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= -golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/tools v0.1.5 h1:ouewzE6p+/VEB31YYnTbEJdi8pFqKp4P4n85vwo3DHA= +golang.org/x/tools v0.1.5/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= +golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= +golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= +golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 h1:go1bK/D/BFZV2I8cIQd1NKEZ+0owSTG1fDTci4IqFcE= +golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY= +gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY= +gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10= gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo= gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/klog.go b/klog.go index 3435461d..31ef6bd0 100644 --- a/klog.go +++ b/klog.go @@ -380,7 +380,7 @@ type flushSyncWriter interface { io.Writer } -// init sets up the defaults and runs flushDaemon. +// init sets up the defaults. func init() { logging.stderrThreshold = severityValue{ Severity: severity.ErrorLog, // Default stderrThreshold is ERROR. @@ -395,7 +395,7 @@ func init() { logging.addDirHeader = false logging.skipLogHeaders = false logging.oneOutput = false - go logging.flushDaemon() + logging.flushD = newFlushDaemon(flushInterval, logging.lockAndFlushAll) } // InitFlags is for explicitly initializing the flags. @@ -447,6 +447,8 @@ type loggingT struct { mu sync.Mutex // file holds writer for each of the log types. file [severity.NumSeverity]flushSyncWriter + // flushD holds a flushDaemon that frequently flushes log file buffers. + flushD *flushDaemon // pcs is used in V to avoid an allocation when computing the caller's PC. pcs [1]uintptr // vmap is a cache of the V Level for each V() call site, identified by PC. @@ -1022,6 +1024,7 @@ const bufferSize = 256 * 1024 // createFiles creates all the log files for severity from sev down to infoLog. // l.mu is held. func (l *loggingT) createFiles(sev severity.Severity) error { + l.flushD.run() now := time.Now() // Files are created in decreasing severity order, so as soon as we find one // has already been created, we can stop. @@ -1042,10 +1045,79 @@ func (l *loggingT) createFiles(sev severity.Severity) error { const flushInterval = 5 * time.Second // flushDaemon periodically flushes the log file buffers. -func (l *loggingT) flushDaemon() { - for range time.NewTicker(flushInterval).C { - l.lockAndFlushAll() +type flushDaemon struct { + mu sync.Mutex + interval time.Duration + flush func() + stopC chan struct{} + stopDone chan struct{} +} + +// newFlushDaemon retrun a new flushDaemon. +func newFlushDaemon(interval time.Duration, flush func()) *flushDaemon { + return &flushDaemon{ + interval: interval, + flush: flush, + } +} + +// run starts a goroutine that periodically calls the daemons flush function. +// Calling run on an already running daemon will have no effect. +func (f *flushDaemon) run() { + f.mu.Lock() + defer f.mu.Unlock() + + if f.stopC != nil { // daemon already running + return + } + + f.stopC = make(chan struct{}, 1) + f.stopDone = make(chan struct{}, 1) + + go func() { + ticker := time.NewTicker(f.interval) + defer ticker.Stop() + defer func() { f.stopDone <- struct{}{} }() + for { + select { + case <-ticker.C: + f.flush() + case <-f.stopC: + return + } + } + }() +} + +// stop stops the running flushDaemon and waits until the daemon has shut down. +// Calling stop on a daemon that isn't running will have no effect. +func (f *flushDaemon) stop() { + f.mu.Lock() + defer f.mu.Unlock() + + if f.stopC == nil { // daemon not running + return } + + f.stopC <- struct{}{} + <-f.stopDone + + f.stopC = nil + f.stopDone = nil +} + +// isRunning returns true if the flush daemon is running. +func (f *flushDaemon) isRunning() bool { + f.mu.Lock() + defer f.mu.Unlock() + return f.stopC != nil +} + +// StopFlushDaemon stops the flush daemon, if running. +// This prevents klog from leaking goroutines on shutdown. After stopping +// the daemon, you can still manually flush buffers by calling Flush(). +func StopFlushDaemon() { + logging.flushD.stop() } // lockAndFlushAll is like flushAll but locks l.mu first. diff --git a/klog_test.go b/klog_test.go index 6e166763..3f3e7465 100644 --- a/klog_test.go +++ b/klog_test.go @@ -378,10 +378,11 @@ func TestSetOutputDataRace(t *testing.T) { setFlags() defer logging.swap(logging.newBuffers()) var wg sync.WaitGroup + var daemons []*flushDaemon for i := 1; i <= 50; i++ { - go func() { - logging.flushDaemon() - }() + daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll) + daemon.run() + daemons = append(daemons, daemon) } for i := 1; i <= 50; i++ { wg.Add(1) @@ -391,9 +392,9 @@ func TestSetOutputDataRace(t *testing.T) { }() } for i := 1; i <= 50; i++ { - go func() { - logging.flushDaemon() - }() + daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll) + daemon.run() + daemons = append(daemons, daemon) } for i := 1; i <= 50; i++ { wg.Add(1) @@ -403,11 +404,14 @@ func TestSetOutputDataRace(t *testing.T) { }() } for i := 1; i <= 50; i++ { - go func() { - logging.flushDaemon() - }() + daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll) + daemon.run() + daemons = append(daemons, daemon) } wg.Wait() + for _, d := range daemons { + d.stop() + } } func TestLogToOutput(t *testing.T) { @@ -1852,3 +1856,38 @@ func (s *structWithLock) addWithDefer() { defer s.m.Unlock() s.n++ } + +func TestFlushDaemon(t *testing.T) { + for sev := severity.InfoLog; sev < severity.FatalLog; sev++ { + var flushed int + spyFunc := func() { flushed++ } + testLog := loggingT{flushD: newFlushDaemon(10*time.Millisecond, spyFunc)} + + // Calling testLog will call createFile, which should start the daemon. + testLog.print(sev, nil, nil, "x") + + if !testLog.flushD.isRunning() { + t.Error("expected flushD to be running") + } + + time.Sleep(400 * time.Millisecond) + testLog.flushD.stop() + + if flushed < 3 { + t.Errorf("expected syncBuffer to be flushed at least 3 times, but was %d times", flushed) + } + } +} + +func TestStopFlushDaemon(t *testing.T) { + logging.flushD.stop() + logging.flushD = newFlushDaemon(time.Second, func() {}) + logging.flushD.run() + if !logging.flushD.isRunning() { + t.Error("expected flushD to be running") + } + StopFlushDaemon() + if logging.flushD.isRunning() { + t.Error("expected flushD to be stopped") + } +} From 7ad18de3dc96c9672392ede07446c7c3624b4f2d Mon Sep 17 00:00:00 2001 From: katexochen Date: Thu, 24 Feb 2022 08:36:32 +0100 Subject: [PATCH 2/5] fixup! Make flushDaemon stoppable and testable --- go.mod | 5 ++++- go.sum | 11 +++++++++++ klog.go | 8 ++++++-- klog_test.go | 27 +++++++++++++++++++-------- 4 files changed, 40 insertions(+), 11 deletions(-) diff --git a/go.mod b/go.mod index 31aefba7..6385c6cd 100644 --- a/go.mod +++ b/go.mod @@ -2,4 +2,7 @@ module k8s.io/klog/v2 go 1.13 -require github.com/go-logr/logr v1.2.0 +require ( + github.com/go-logr/logr v1.2.0 + k8s.io/utils v0.0.0-20220210201930-3a6ce19ff2f9 +) diff --git a/go.sum b/go.sum index 919fbadb..ef731394 100644 --- a/go.sum +++ b/go.sum @@ -1,2 +1,13 @@ +github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/go-logr/logr v0.1.0/go.mod h1:ixOQHD9gLJUVQQ2ZOR7zLEifBX6tGkNJF4QyIY7sIas= github.com/go-logr/logr v1.2.0 h1:QK40JKJyMdUDz+h+xvCsru/bJhvG0UxvePV0ufL/AcE= github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/spf13/afero v1.2.2/go.mod h1:9ZxEEn6pIJ8Rxe320qSDBk6AsU0r9pR7Q4OcevTdifk= +github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= +golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= +k8s.io/klog/v2 v2.0.0/go.mod h1:PBfzABfn139FHAV07az/IF9Wp1bkk3vpT2XSJ76fSDE= +k8s.io/utils v0.0.0-20220210201930-3a6ce19ff2f9 h1:HNSDgDCrr/6Ly3WEGKZftiE7IY19Vz2GdbOCyI4qqhc= +k8s.io/utils v0.0.0-20220210201930-3a6ce19ff2f9/go.mod h1:jPW/WVKK9YHAvNhRxK0md/EJ228hCsBRufyofKtW8HA= diff --git a/klog.go b/klog.go index 31ef6bd0..40509647 100644 --- a/klog.go +++ b/klog.go @@ -94,6 +94,7 @@ import ( "k8s.io/klog/v2/internal/buffer" "k8s.io/klog/v2/internal/serialize" "k8s.io/klog/v2/internal/severity" + "k8s.io/utils/clock" ) // severityValue identifies the sort of log: info, warning etc. It also implements @@ -1047,6 +1048,7 @@ const flushInterval = 5 * time.Second // flushDaemon periodically flushes the log file buffers. type flushDaemon struct { mu sync.Mutex + clock clock.WithTicker interval time.Duration flush func() stopC chan struct{} @@ -1058,6 +1060,7 @@ func newFlushDaemon(interval time.Duration, flush func()) *flushDaemon { return &flushDaemon{ interval: interval, flush: flush, + clock: clock.RealClock{}, } } @@ -1074,15 +1077,16 @@ func (f *flushDaemon) run() { f.stopC = make(chan struct{}, 1) f.stopDone = make(chan struct{}, 1) + ticker := f.clock.NewTicker(f.interval) go func() { - ticker := time.NewTicker(f.interval) defer ticker.Stop() defer func() { f.stopDone <- struct{}{} }() for { select { - case <-ticker.C: + case <-ticker.C(): f.flush() case <-f.stopC: + f.flush() return } } diff --git a/klog_test.go b/klog_test.go index 3f3e7465..4046137c 100644 --- a/klog_test.go +++ b/klog_test.go @@ -39,6 +39,7 @@ import ( "k8s.io/klog/v2/internal/buffer" "k8s.io/klog/v2/internal/severity" "k8s.io/klog/v2/internal/test" + testingclock "k8s.io/utils/clock/testing" ) // TODO: This test package should be refactored so that tests cannot @@ -1859,9 +1860,18 @@ func (s *structWithLock) addWithDefer() { func TestFlushDaemon(t *testing.T) { for sev := severity.InfoLog; sev < severity.FatalLog; sev++ { - var flushed int - spyFunc := func() { flushed++ } - testLog := loggingT{flushD: newFlushDaemon(10*time.Millisecond, spyFunc)} + flushed := make(chan struct{}, 1) + spyFunc := func() { + flushed <- struct{}{} + } + testClock := testingclock.NewFakeClock(time.Now()) + testLog := loggingT{ + flushD: &flushDaemon{ + interval: time.Millisecond, + flush: spyFunc, + clock: testClock, + }, + } // Calling testLog will call createFile, which should start the daemon. testLog.print(sev, nil, nil, "x") @@ -1870,12 +1880,13 @@ func TestFlushDaemon(t *testing.T) { t.Error("expected flushD to be running") } - time.Sleep(400 * time.Millisecond) + testClock.Step(time.Second) + <-flushed + testClock.Step(time.Second) + <-flushed testLog.flushD.stop() - - if flushed < 3 { - t.Errorf("expected syncBuffer to be flushed at least 3 times, but was %d times", flushed) - } + // wait for stop to trigger one last flush + <-flushed } } From b6757a587622d8f9959b99f8d044f9070f62453d Mon Sep 17 00:00:00 2001 From: katexochen Date: Thu, 24 Feb 2022 23:08:27 +0100 Subject: [PATCH 3/5] fixup! Make flushDaemon stoppable and testable --- klog.go | 12 ++++++++---- klog_test.go | 14 +++++--------- 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/klog.go b/klog.go index 40509647..0b235f42 100644 --- a/klog.go +++ b/klog.go @@ -396,7 +396,7 @@ func init() { logging.addDirHeader = false logging.skipLogHeaders = false logging.oneOutput = false - logging.flushD = newFlushDaemon(flushInterval, logging.lockAndFlushAll) + logging.flushD = newFlushDaemon(flushInterval, logging.lockAndFlushAll, nil) } // InitFlags is for explicitly initializing the flags. @@ -1055,12 +1055,16 @@ type flushDaemon struct { stopDone chan struct{} } -// newFlushDaemon retrun a new flushDaemon. -func newFlushDaemon(interval time.Duration, flush func()) *flushDaemon { +// newFlushDaemon returns a new flushDaemon. If the passed clock is nil, a +// clock.RealClock is used. +func newFlushDaemon(interval time.Duration, flush func(), tickClock clock.WithTicker) *flushDaemon { + if tickClock == nil { + tickClock = clock.RealClock{} + } return &flushDaemon{ interval: interval, flush: flush, - clock: clock.RealClock{}, + clock: tickClock, } } diff --git a/klog_test.go b/klog_test.go index 4046137c..3875766f 100644 --- a/klog_test.go +++ b/klog_test.go @@ -381,7 +381,7 @@ func TestSetOutputDataRace(t *testing.T) { var wg sync.WaitGroup var daemons []*flushDaemon for i := 1; i <= 50; i++ { - daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll) + daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll, nil) daemon.run() daemons = append(daemons, daemon) } @@ -393,7 +393,7 @@ func TestSetOutputDataRace(t *testing.T) { }() } for i := 1; i <= 50; i++ { - daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll) + daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll, nil) daemon.run() daemons = append(daemons, daemon) } @@ -405,7 +405,7 @@ func TestSetOutputDataRace(t *testing.T) { }() } for i := 1; i <= 50; i++ { - daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll) + daemon := newFlushDaemon(time.Second, logging.lockAndFlushAll, nil) daemon.run() daemons = append(daemons, daemon) } @@ -1866,11 +1866,7 @@ func TestFlushDaemon(t *testing.T) { } testClock := testingclock.NewFakeClock(time.Now()) testLog := loggingT{ - flushD: &flushDaemon{ - interval: time.Millisecond, - flush: spyFunc, - clock: testClock, - }, + flushD: newFlushDaemon(time.Second, spyFunc, testClock), } // Calling testLog will call createFile, which should start the daemon. @@ -1892,7 +1888,7 @@ func TestFlushDaemon(t *testing.T) { func TestStopFlushDaemon(t *testing.T) { logging.flushD.stop() - logging.flushD = newFlushDaemon(time.Second, func() {}) + logging.flushD = newFlushDaemon(time.Second, func() {}, nil) logging.flushD.run() if !logging.flushD.isRunning() { t.Error("expected flushD to be running") From 31a05ea15320b33d83f6113ab5a7aab61c48a934 Mon Sep 17 00:00:00 2001 From: katexochen Date: Sat, 26 Feb 2022 10:36:13 +0100 Subject: [PATCH 4/5] fixup! Make flushDaemon stoppable and testable --- examples/go.sum | 3 +++ klog_test.go | 27 +++++++++++++++++++++++---- 2 files changed, 26 insertions(+), 4 deletions(-) diff --git a/examples/go.sum b/examples/go.sum index 2414d126..eae042c1 100644 --- a/examples/go.sum +++ b/examples/go.sum @@ -23,6 +23,7 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/spf13/afero v1.2.2/go.mod h1:9ZxEEn6pIJ8Rxe320qSDBk6AsU0r9pR7Q4OcevTdifk= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= @@ -95,3 +96,5 @@ gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo= gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +k8s.io/utils v0.0.0-20220210201930-3a6ce19ff2f9 h1:HNSDgDCrr/6Ly3WEGKZftiE7IY19Vz2GdbOCyI4qqhc= +k8s.io/utils v0.0.0-20220210201930-3a6ce19ff2f9/go.mod h1:jPW/WVKK9YHAvNhRxK0md/EJ228hCsBRufyofKtW8HA= diff --git a/klog_test.go b/klog_test.go index 3875766f..cd89f883 100644 --- a/klog_test.go +++ b/klog_test.go @@ -1876,13 +1876,32 @@ func TestFlushDaemon(t *testing.T) { t.Error("expected flushD to be running") } + timer := time.NewTimer(10 * time.Second) + defer timer.Stop() testClock.Step(time.Second) - <-flushed + select { + case <-flushed: + case <-timer.C: + t.Fatal("flushDaemon didn't call flush function on tick") + } + + timer = time.NewTimer(10 * time.Second) + defer timer.Stop() testClock.Step(time.Second) - <-flushed + select { + case <-flushed: + case <-timer.C: + t.Fatal("flushDaemon didn't call flush function on second tick") + } + + timer = time.NewTimer(10 * time.Second) + defer timer.Stop() testLog.flushD.stop() - // wait for stop to trigger one last flush - <-flushed + select { + case <-flushed: + case <-timer.C: + t.Fatal("flushDaemon didn't call flush function on last time on stop") + } } } From ec084842e8589c8f4ee4f1be7f534eeaf953378c Mon Sep 17 00:00:00 2001 From: katexochen Date: Sat, 26 Feb 2022 10:40:50 +0100 Subject: [PATCH 5/5] fixup! Make flushDaemon stoppable and testable --- klog_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/klog_test.go b/klog_test.go index cd89f883..95553d5f 100644 --- a/klog_test.go +++ b/klog_test.go @@ -1900,7 +1900,7 @@ func TestFlushDaemon(t *testing.T) { select { case <-flushed: case <-timer.C: - t.Fatal("flushDaemon didn't call flush function on last time on stop") + t.Fatal("flushDaemon didn't call flush function one last time on stop") } } }