Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix Gorouter's debugserver endpoint to allow log level changes at runtime #452

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
+105 −11
Open

Fix Gorouter's debugserver endpoint to allow log level changes at runtime #452

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
0fc4cb0
WIP Fix debugserver logging level endpoints
MarcPaquette Oct 25, 2024
973c7e2
Add integration tests and fix issue
MarcPaquette Oct 31, 2024
3ec0125
Add mutex for config changes
MarcPaquette Nov 6, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
73 changes: 73 additions & 0 deletions integration/main_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package integration

import (
"bufio"
"bytes"
"crypto/tls"
"encoding/json"
"errors"
Expand Down Expand Up @@ -618,6 +619,78 @@ var _ = Describe("Router Integration", func() {
Consistently(contentsFunc).ShouldNot(ContainSubstring("Component Router registered successfully"))
})

Context("It starts up a debugserver", func() {
var (
testState *testState
contentsFunc func() string = func() string {
return string(gorouterSession.Out.Contents())
}
)

BeforeEach(func() {

testState = NewTestState()
testState.cfg.DebugAddr = "127.0.0.1:17017"
gorouterSession = testState.StartGorouter()
})

It("can change the debugserver's logging level", func() {

Consistently(contentsFunc).ShouldNot(ContainSubstring(`{log_level":0,"timestamp"`))

request, err := http.NewRequest("PUT", fmt.Sprintf("http://%s/log-level", testState.cfg.DebugAddr), bytes.NewBufferString("debug"))
Expect(err).NotTo(HaveOccurred())

response, err := http.DefaultClient.Do(request)
Expect(err).NotTo(HaveOccurred())

Expect(response.StatusCode).To(Equal(http.StatusOK))
response.Body.Close()

Consistently(contentsFunc).Should(ContainSubstring(`{"log_level":0,"timestamp"`))

// And back to info level
gorouterSession.Out.Clear()
request, err = http.NewRequest("PUT", fmt.Sprintf("http://%s/log-level", testState.cfg.DebugAddr), bytes.NewBufferString("info"))
Expect(err).NotTo(HaveOccurred())

response, err = http.DefaultClient.Do(request)
Expect(err).NotTo(HaveOccurred())

Expect(response.StatusCode).To(Equal(http.StatusOK))
response.Body.Close()

//Terminate everything just to generate some info logs
testState.StopAndCleanup()

Consistently(contentsFunc).ShouldNot(ContainSubstring(`{"log_level":0,"timestamp"`))
Eventually(contentsFunc).Should(ContainSubstring(`{"log_level":1,"timestamp"`))

})

It("Does not accept invalid debug levels", func() {

Consistently(contentsFunc).ShouldNot(ContainSubstring(`{log_level":0,"timestamp"`))

gorouterSession.Out.Clear()

request, err := http.NewRequest("PUT", fmt.Sprintf("http://%s/log-level", testState.cfg.DebugAddr), bytes.NewBufferString("meow"))
Expect(err).NotTo(HaveOccurred())

response, err := http.DefaultClient.Do(request)
Expect(err).NotTo(HaveOccurred())

Expect(response.StatusCode).To(Equal(http.StatusOK))
response.Body.Close()

Expect(gorouterSession.ExitCode()).To(Equal(-1))

Consistently(contentsFunc).ShouldNot(ContainSubstring(`{"log_level":0,"timestamp"`))
Eventually(contentsFunc).Should(ContainSubstring(`{"log_level":1,"timestamp"`))
})

})

Describe("loggregator metrics emitted", func() {
var (
fakeMetron test_util.FakeMetron
Expand Down
39 changes: 31 additions & 8 deletions logger/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,13 +8,14 @@ import (
"sync"
"time"

"code.cloudfoundry.org/lager/v3"
"go.uber.org/zap"
"go.uber.org/zap/exp/zapslog"
"go.uber.org/zap/zapcore"
)

var (
conf dynamicLoggingConfig
Conf DynamicLoggingConfig
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why is this exported now? I assume for the change in main.go?

exposing the variable means anyone anywhere can change it. what about adding a getter function instead?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We need the satisfy the debugserver's reconfigurable sink: https://github.com/cloudfoundry/debugserver/blob/main/server.go#L24-L26

The base gorouter logger is inited at the package level and privately puts us in a bit of an odd spot with further changes to the logger. I exported the config as we need the debugserver to actually change the config via SetMinLevel()

Basically since the grlogger.baseLogger is initialized on importation via init() and private to the package, I pushed the config out as public as we need something to satisfy the ReconfigurableSinkInterface. A getter doesn't quite fit the pattern. There is an argument for pushing it further down, but this was a bit simpler.

I went with the config as it's the area where adding the method to satisfy the ReconfigurableSinkInterface was the least intrusive.

baseLogger *slog.Logger
writeSyncer = &dynamicWriter{w: os.Stdout}
mutex sync.Mutex
Expand All @@ -23,7 +24,7 @@ var (
/*
dynamicLoggingConfig holds dynamic configuration for the time encoding and logging level.
*/
type dynamicLoggingConfig struct {
type DynamicLoggingConfig struct {
encoding string
level zap.AtomicLevel
}
Expand Down Expand Up @@ -74,10 +75,10 @@ SetTimeEncoder dynamically sets the time encoder at runtime:
All other values: The encoder is set to an Epoch encoder
*/
func SetTimeEncoder(enc string) {
conf.encoding = enc
Conf.encoding = enc
}

func (e *dynamicLoggingConfig) encodeTime(t time.Time, pae zapcore.PrimitiveArrayEncoder) {
func (e *DynamicLoggingConfig) encodeTime(t time.Time, pae zapcore.PrimitiveArrayEncoder) {
switch e.encoding {
case "rfc3339":
RFC3339Formatter()(t, pae)
Expand All @@ -91,11 +92,33 @@ SetLoggingLevel dynamically sets the logging level at runtime. See https://githu
for possible logging levels.
*/
func SetLoggingLevel(level string) {
mutex.Lock()
defer mutex.Unlock()
Comment on lines +95 to +96
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ameowlia
I added the Mutex here since there are a few different ways the logging level can get changed.

zapLevel, err := zapcore.ParseLevel(level)
if err != nil {
panic(err)
}
conf.level.SetLevel(zapLevel)
Conf.level.SetLevel(zapLevel)
}

// This exists to be able to export the logging level configs to the debugserver
func (loggingConf DynamicLoggingConfig) SetMinLevel(level lager.LogLevel) {
Conf.level.SetLevel(toZapLevel(level))
}

func toZapLevel(level lager.LogLevel) zapcore.Level {
switch level {
case lager.DEBUG:
return zapcore.DebugLevel
case lager.INFO:
return zapcore.InfoLevel
MarcPaquette marked this conversation as resolved.
Show resolved Hide resolved
case lager.ERROR:
return zapcore.ErrorLevel
case lager.FATAL:
return zapcore.FatalLevel
default:
return zapcore.InfoLevel
}
}

type Logger interface {
Expand All @@ -108,22 +131,22 @@ timestamp format and writeSyncer.
func initializeLogger() *slog.Logger {
zapLevel := zap.InfoLevel

conf = dynamicLoggingConfig{encoding: "epoch", level: zap.NewAtomicLevelAt(zapLevel)}
Conf = DynamicLoggingConfig{encoding: "epoch", level: zap.NewAtomicLevelAt(zapLevel)}

zapConfig := zapcore.EncoderConfig{
MessageKey: "message",
LevelKey: "log_level",
EncodeLevel: numberLevelFormatter,
TimeKey: "timestamp",
EncodeTime: conf.encodeTime,
EncodeTime: Conf.encodeTime,
EncodeCaller: zapcore.ShortCallerEncoder,
StacktraceKey: "stack_trace",
}

zapCore := zapcore.NewCore(
zapcore.NewJSONEncoder(zapConfig),
writeSyncer,
conf.level,
Conf.level,
)

zapHandler := zapslog.NewHandler(zapCore, zapslog.WithCaller(true))
Expand Down
4 changes: 1 addition & 3 deletions main.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,6 @@ import (
"code.cloudfoundry.org/clock"
"code.cloudfoundry.org/debugserver"
mr "code.cloudfoundry.org/go-metric-registry"
"code.cloudfoundry.org/lager/v3"
"code.cloudfoundry.org/tlsconfig"
"github.com/cloudfoundry/dropsonde"
"github.com/cloudfoundry/dropsonde/metric_sender"
Expand Down Expand Up @@ -107,8 +106,7 @@ func main() {
}

if c.DebugAddr != "" {
reconfigurableSink := lager.ReconfigurableSink{}
_, err = debugserver.Run(c.DebugAddr, &reconfigurableSink)
_, err = debugserver.Run(c.DebugAddr, &grlog.Conf)
if err != nil {
logger.Error("failed-to-start-debug-server", grlog.ErrAttr(err))
}
Expand Down