From 03e9c812353a1af9f697fef6bd6cc2eab5abc98d Mon Sep 17 00:00:00 2001 From: Ed Tan Date: Tue, 7 Aug 2018 11:27:35 -0400 Subject: [PATCH 1/2] Remove hardcoded debug log levels as described in concourse/bin#34. --- heartbeater.go | 11 +++++++---- heartbeater_test.go | 5 ++++- tsacmd/command.go | 5 +++++ tsacmd/server.go | 8 +++++--- 4 files changed, 21 insertions(+), 8 deletions(-) diff --git a/heartbeater.go b/heartbeater.go index 0fece890c05..8fabbb582ad 100644 --- a/heartbeater.go +++ b/heartbeater.go @@ -25,7 +25,8 @@ type EndpointPicker interface { } type heartbeater struct { - logger lager.Logger + logger lager.Logger + logLevel lager.LogLevel clock clock.Clock interval time.Duration @@ -43,6 +44,7 @@ type heartbeater struct { func NewHeartbeater( logger lager.Logger, + logLevel lager.LogLevel, clock clock.Clock, interval time.Duration, cprInterval time.Duration, @@ -54,7 +56,8 @@ func NewHeartbeater( clientWriter io.Writer, ) ifrit.Runner { return &heartbeater{ - logger: logger, + logger: logger, + logLevel: logLevel, clock: clock, interval: interval, @@ -107,7 +110,7 @@ func (heartbeater *heartbeater) Run(signals <-chan os.Signal, ready chan<- struc } func (heartbeater *heartbeater) register(logger lager.Logger) bool { - logger.RegisterSink(lager.NewWriterSink(heartbeater.clientWriter, lager.DEBUG)) + logger.RegisterSink(lager.NewWriterSink(heartbeater.clientWriter, heartbeater.logLevel)) heartbeatData := lager.Data{ "worker-platform": heartbeater.registration.Platform, @@ -176,7 +179,7 @@ const ( ) func (heartbeater *heartbeater) heartbeat(logger lager.Logger) HeartbeatStatus { - logger.RegisterSink(lager.NewWriterSink(heartbeater.clientWriter, lager.DEBUG)) + logger.RegisterSink(lager.NewWriterSink(heartbeater.clientWriter, heartbeater.logLevel)) heartbeatData := lager.Data{ "worker-platform": heartbeater.registration.Platform, diff --git a/heartbeater_test.go b/heartbeater_test.go index 6b9fcb9447e..e15d4a75b71 100644 --- a/heartbeater_test.go +++ b/heartbeater_test.go @@ -31,7 +31,8 @@ var _ = Describe("Heartbeater", func() { } var ( - logger lager.Logger + logger lager.Logger + logLevel lager.LogLevel addrToRegister string fakeClock *fakeclock.FakeClock @@ -60,6 +61,7 @@ var _ = Describe("Heartbeater", func() { BeforeEach(func() { logger = lagertest.NewTestLogger("test") + logLevel = lager.DEBUG addrToRegister = "1.2.3.4:7777" fakeClock = fakeclock.NewFakeClock(time.Unix(123, 456)) @@ -153,6 +155,7 @@ var _ = Describe("Heartbeater", func() { heartbeater = ifrit.Invoke( NewHeartbeater( logger, + logLevel, fakeClock, interval, cprInterval, diff --git a/tsacmd/command.go b/tsacmd/command.go index 6d522da174f..e0547d5b39c 100644 --- a/tsacmd/command.go +++ b/tsacmd/command.go @@ -102,8 +102,13 @@ func (cmd *TSACommand) Runner(args []string) (ifrit.Runner, error) { if cmd.SessionSigningKey != nil { tokenGenerator := tsa.NewTokenGenerator(cmd.SessionSigningKey.PrivateKey) + logLevel, err := lager.LogLevelFromString(cmd.Logger.LogLevel) + if err != nil { + panic(err) + } server := ®istrarSSHServer{ logger: logger, + logLevel: logLevel, heartbeatInterval: cmd.HeartbeatInterval, cprInterval: 1 * time.Second, atcEndpointPicker: atcEndpointPicker, diff --git a/tsacmd/server.go b/tsacmd/server.go index 3727ac34182..61e237ee2e5 100644 --- a/tsacmd/server.go +++ b/tsacmd/server.go @@ -27,6 +27,7 @@ const maxForwards = 2 type registrarSSHServer struct { logger lager.Logger + logLevel lager.LogLevel atcEndpointPicker tsa.EndpointPicker tokenGenerator tsa.TokenGenerator heartbeatInterval time.Duration @@ -194,7 +195,7 @@ func (server *registrarSSHServer) handleChannel( req.Reply(true, nil) - logger.RegisterSink(lager.NewWriterSink(channel, lager.DEBUG)) + logger.RegisterSink(lager.NewWriterSink(channel, server.logLevel)) err := server.landWorker(logger, channel, sessionID) if err != nil { logger.Error("failed-to-land-worker", err) @@ -210,7 +211,7 @@ func (server *registrarSSHServer) handleChannel( req.Reply(true, nil) - logger.RegisterSink(lager.NewWriterSink(channel, lager.DEBUG)) + logger.RegisterSink(lager.NewWriterSink(channel, server.logLevel)) err := server.retireWorker(logger, channel, sessionID) if err != nil { logger.Error("failed-to-retire-worker", err) @@ -226,7 +227,7 @@ func (server *registrarSSHServer) handleChannel( req.Reply(true, nil) - logger.RegisterSink(lager.NewWriterSink(channel, lager.DEBUG)) + logger.RegisterSink(lager.NewWriterSink(channel, server.logLevel)) err := server.deleteWorker(logger, channel, sessionID) if err != nil { logger.Error("failed-to-delete-worker", err) @@ -639,6 +640,7 @@ func (server *registrarSSHServer) continuouslyRegisterForwardedWorker( func (server *registrarSSHServer) heartbeatWorker(logger lager.Logger, worker atc.Worker, channel ssh.Channel) ifrit.Process { return ifrit.Background(tsa.NewHeartbeater( logger, + server.logLevel, clock.NewClock(), server.heartbeatInterval, server.cprInterval, From c1a02c6a07fb8587607ff2760b6325ed8bf2d79a Mon Sep 17 00:00:00 2001 From: Ed Tan Date: Tue, 7 Aug 2018 13:34:14 -0400 Subject: [PATCH 2/2] Add tests for log level setting --- heartbeater_test.go | 63 ++++++++++++++++++++++++++++++++++----------- 1 file changed, 48 insertions(+), 15 deletions(-) diff --git a/heartbeater_test.go b/heartbeater_test.go index e15d4a75b71..4f385a5bdb3 100644 --- a/heartbeater_test.go +++ b/heartbeater_test.go @@ -236,25 +236,58 @@ var _ = Describe("Heartbeater", func() { }) Context("when the ATC responds to registration requests", func() { - BeforeEach(func() { - fakeATC1.AppendHandlers(verifyRegister) - fakeATC2.AppendHandlers(verifyHeartbeat) + Context("When the DEBUG log level is set", func() { + BeforeEach(func() { + fakeATC1.AppendHandlers(verifyRegister) + fakeATC2.AppendHandlers(verifyHeartbeat) + }) + + It("immediately registers", func() { + expectedWorker.ActiveContainers = 2 + expectedWorker.ActiveVolumes = 3 + Expect(registrations).To(Receive(Equal(registration{expectedWorker, 2 * interval}))) + }) + + It("heartbeats", func() { + Expect(registrations).To(Receive()) + + fakeClock.WaitForWatcherAndIncrement(interval) + expectedWorker.ActiveContainers = 5 + expectedWorker.ActiveVolumes = 2 + Eventually(heartbeats).Should(Receive(Equal(registration{expectedWorker, 2 * interval}))) + }) + + It("logs debug messages", func() { + Expect(clientWriter).Should(gbytes.Say("test.register.start")) + Expect(clientWriter).Should(gbytes.Say("test.register.reached-worker")) + Expect(clientWriter).Should(gbytes.Say("test.register.done")) + + fakeClock.WaitForWatcherAndIncrement(interval) + Eventually(clientWriter).Should(gbytes.Say("test.heartbeat.start")) + Eventually(clientWriter).Should(gbytes.Say("test.heartbeat.reached-worker")) + Eventually(clientWriter).Should(gbytes.Say("test.heartbeat.done")) + }) }) - It("immediately registers", func() { - expectedWorker.ActiveContainers = 2 - expectedWorker.ActiveVolumes = 3 - Expect(registrations).To(Receive(Equal(registration{expectedWorker, 2 * interval}))) + Context("When the ERROR log level is set", func() { + BeforeEach(func() { + fakeATC1.AppendHandlers(verifyRegister) + fakeATC2.AppendHandlers(verifyHeartbeat) + logLevel = lager.ERROR + }) + + It("does not log messages", func() { + Expect(clientWriter).ShouldNot(gbytes.Say("test.register.start")) + Expect(clientWriter).ShouldNot(gbytes.Say("test.register.reached-worker")) + Expect(clientWriter).ShouldNot(gbytes.Say("test.register.done")) + + fakeClock.WaitForWatcherAndIncrement(interval) + Eventually(clientWriter).ShouldNot(gbytes.Say("test.heartbeat.start")) + Eventually(clientWriter).ShouldNot(gbytes.Say("test.heartbeat.reached-worker")) + Eventually(clientWriter).ShouldNot(gbytes.Say("test.heartbeat.done")) + }) }) - It("heartbeats", func() { - Expect(registrations).To(Receive()) - - fakeClock.WaitForWatcherAndIncrement(interval) - expectedWorker.ActiveContainers = 5 - expectedWorker.ActiveVolumes = 2 - Eventually(heartbeats).Should(Receive(Equal(registration{expectedWorker, 2 * interval}))) - }) }) Context("when heartbeat returns worker is landed", func() {