Merge pull request #9 from edtan/remove-hardcoded-debug-loglevel

Remove hardcoded debug log levels as described in vmware-archive/bin#34.

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,

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,
@@ -233,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() {

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 := &registrarSSHServer{
 			logger:            logger,
+			logLevel:          logLevel,
 			heartbeatInterval: cmd.HeartbeatInterval,
 			cprInterval:       1 * time.Second,
 			atcEndpointPicker: atcEndpointPicker,

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,