internal/tracer: migrate to new logging library (#37973)

This commit is contained in:
Robert Lin 2022-06-29 16:50:48 -07:00 committed by GitHub
parent f99b3aef52
commit 25dec337d9
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 61 additions and 46 deletions

View File

@ -189,7 +189,7 @@ func Main(enterpriseSetupHook func(db database.DB, c conftypes.UnifiedWatchable)
// Filter trace logs
d, _ := time.ParseDuration(traceThreshold)
logging.Init(logging.Filter(loghandlers.Trace(strings.Fields(traceFields), d)))
tracer.Init(conf.DefaultClient())
tracer.Init(sglog.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
profiler.Init()

View File

@ -71,7 +71,7 @@ func main() {
defer liblog.Sync()
conf.Init()
go conf.Watch(liblog.Update(conf.GetLogSinks))
tracer.Init(conf.DefaultClient())
tracer.Init(log.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
// Ready immediately

View File

@ -95,7 +95,7 @@ func main() {
defer liblog.Sync()
go conf.Watch(liblog.Update(conf.GetLogSinks))
tracer.Init(conf.DefaultClient())
tracer.Init(log.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
profiler.Init()

View File

@ -85,7 +85,7 @@ func Main(enterpriseInit EnterpriseInit) {
defer liblog.Sync()
go conf.Watch(liblog.Update(conf.GetLogSinks))
tracer.Init(conf.DefaultClient())
tracer.Init(log.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
profiler.Init()

View File

@ -241,7 +241,7 @@ func main() {
defer liblog.Sync()
go conf.Watch(liblog.Update(conf.GetLogSinks))
tracer.Init(conf.DefaultClient())
tracer.Init(log.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
profiler.Init()

View File

@ -49,7 +49,7 @@ func Main(setup SetupFunc) {
defer liblog.Sync()
go conf.Watch(liblog.Update(conf.GetLogSinks))
tracer.Init(conf.DefaultClient())
tracer.Init(log.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
profiler.Init()

View File

@ -62,7 +62,7 @@ func Start(logger log.Logger, additionalJobs map[string]job.Job, registerEnterpr
env.HandleHelpFlag()
conf.Init()
logging.Init()
tracer.Init(conf.DefaultClient())
tracer.Init(log.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
profiler.Init()

View File

@ -60,7 +60,7 @@ func main() {
})
defer liblog.Sync()
go conf.Watch(liblog.Update(conf.GetLogSinks))
tracer.Init(conf.DefaultClient())
tracer.Init(log.Scoped("tracer", "internal tracer package"), conf.DefaultClient())
trace.Init()
profiler.Init()

View File

@ -8,6 +8,7 @@ import (
"github.com/inconshreveable/log15"
"github.com/opentracing/opentracing-go"
"github.com/sourcegraph/log"
"github.com/uber/jaeger-client-go"
jaegercfg "github.com/uber/jaeger-client-go/config"
jaegermetrics "github.com/uber/jaeger-lib/metrics"
@ -20,18 +21,6 @@ import (
"github.com/sourcegraph/sourcegraph/lib/errors"
)
func init() {
// Tune GOMAXPROCS for kubernetes. All our binaries import this package,
// so we tune for all of them.
//
// TODO it is surprising that we do this here. We should create a standard
// import for sourcegraph binaries which would have less surprising
// behaviour.
if _, err := maxprocs.Set(); err != nil {
log15.Error("automaxprocs failed", "error", err)
}
}
// options control the behavior of a TracerType
type options struct {
TracerType
@ -46,22 +35,32 @@ type options struct {
type TracerType string
const (
None TracerType = "none"
Ot TracerType = "opentracing"
None TracerType = "none"
OpenTracing TracerType = "opentracing"
)
// isSetByUser returns true if the TracerType is one supported by the schema
// should be kept in sync with ObservabilityTracing.Type in schema/site.schema.json
func (t TracerType) isSetByUser() bool {
switch t {
case Ot:
case OpenTracing:
return true
}
return false
}
// Init should be called from the main function of service
func Init(c conftypes.WatchableSiteConfig) {
func Init(logger log.Logger, c conftypes.WatchableSiteConfig) {
// Tune GOMAXPROCS for kubernetes. All our binaries import this package,
// so we tune for all of them.
//
// TODO it is surprising that we do this here. We should create a standard
// import for sourcegraph binaries which would have less surprising
// behaviour.
if _, err := maxprocs.Set(); err != nil {
logger.Error("automaxprocs failed", log.Error(err))
}
opts := &options{}
opts.serviceName = env.MyName
if version.IsDev(version.Version()) {
@ -69,12 +68,12 @@ func Init(c conftypes.WatchableSiteConfig) {
}
opts.version = version.Version()
initTracer(opts, c)
initTracer(logger, opts, c)
}
// initTracer is a helper that should be called exactly once (from Init).
func initTracer(opts *options, c conftypes.WatchableSiteConfig) {
globalTracer := newSwitchableTracer()
func initTracer(logger log.Logger, opts *options, c conftypes.WatchableSiteConfig) {
globalTracer := newSwitchableTracer(logger.Scoped("global", "the global tracer"))
opentracing.SetGlobalTracer(globalTracer)
// initial tracks if it's our first run of conf.Watch. This is used to
@ -103,10 +102,10 @@ func initTracer(opts *options, c conftypes.WatchableSiteConfig) {
switch tracingConfig.Sampling {
case "all":
samplingStrategy = policy.TraceAll
setTracer = Ot
setTracer = OpenTracing
case "selective":
samplingStrategy = policy.TraceSelective
setTracer = Ot
setTracer = OpenTracing
}
if t := TracerType(tracingConfig.Type); t.isSetByUser() {
setTracer = t
@ -135,9 +134,11 @@ func initTracer(opts *options, c conftypes.WatchableSiteConfig) {
prevTracer := oldOpts.TracerType
oldOpts = opts
t, closer, err := newTracer(&opts, prevTracer)
t, closer, err := newTracer(logger, &opts, prevTracer)
if err != nil {
log15.Warn("Could not initialize tracer", "tracer", opts.TracerType, "error", err.Error())
logger.Warn("Could not initialize tracer",
log.String("tracer", string(opts.TracerType)),
log.Error(err))
return
}
globalTracer.set(t, closer, opts.debug)
@ -145,13 +146,13 @@ func initTracer(opts *options, c conftypes.WatchableSiteConfig) {
}
// TODO Use openTelemetry https://github.com/sourcegraph/sourcegraph/issues/27386
func newTracer(opts *options, prevTracer TracerType) (opentracing.Tracer, io.Closer, error) {
func newTracer(logger log.Logger, opts *options, prevTracer TracerType) (opentracing.Tracer, io.Closer, error) {
if opts.TracerType == None {
log15.Info("tracing disabled")
logger.Info("tracing disabled")
return opentracing.NoopTracer{}, nil, nil
}
log15.Info("opentracing: enabled")
logger.Info("opentracing: enabled")
cfg, err := jaegercfg.FromEnv()
cfg.ServiceName = opts.serviceName
if err != nil {
@ -166,7 +167,7 @@ func newTracer(opts *options, prevTracer TracerType) (opentracing.Tracer, io.Clo
cfg.Sampler.Param = 1
}
tracer, closer, err := cfg.NewTracer(
jaegercfg.Logger(log15Logger{}),
jaegercfg.Logger(jaegerLoggerShim{logger: logger.Scoped("jaeger", "Jaeger tracer")}),
jaegercfg.Metrics(jaegermetrics.NullFactory),
)
if err != nil {
@ -176,12 +177,14 @@ func newTracer(opts *options, prevTracer TracerType) (opentracing.Tracer, io.Clo
return tracer, closer, nil
}
type log15Logger struct{}
type jaegerLoggerShim struct {
logger log.Logger
}
func (l log15Logger) Error(msg string) { log15.Error(msg) }
func (l jaegerLoggerShim) Error(msg string) { l.logger.Error(msg) }
func (l log15Logger) Infof(msg string, args ...any) {
log15.Info(fmt.Sprintf(msg, args...))
func (l jaegerLoggerShim) Infof(msg string, args ...any) {
l.logger.Info(fmt.Sprintf(msg, args...))
}
// move to OpenTelemetry https://github.com/sourcegraph/sourcegraph/issues/27386
@ -191,19 +194,30 @@ type switchableTracer struct {
mu sync.RWMutex
opentracer opentracing.Tracer
tracerCloser io.Closer
log bool
logger log.Logger
parentLogger log.Logger // used to create logger
}
var _ opentracing.Tracer = &switchableTracer{}
// move to OpenTelemetry https://github.com/sourcegraph/sourcegraph/issues/27386
func newSwitchableTracer() *switchableTracer {
return &switchableTracer{opentracer: opentracing.NoopTracer{}}
func newSwitchableTracer(logger log.Logger) *switchableTracer {
var t opentracing.NoopTracer
return &switchableTracer{
opentracer: t,
logger: logger.With(log.String("opentracer", fmt.Sprintf("%T", t))),
parentLogger: logger,
}
}
func (t *switchableTracer) StartSpan(operationName string, opts ...opentracing.StartSpanOption) opentracing.Span {
t.mu.RLock()
defer t.mu.RUnlock()
if t.log {
log15.Info("opentracing: StartSpan", "operationName", operationName, "opentracer", fmt.Sprintf("%T", t.opentracer))
t.logger.Info("opentracing: StartSpan",
log.String("operationName", operationName))
}
return t.opentracer.StartSpan(operationName, opts...)
}
@ -212,7 +226,7 @@ func (t *switchableTracer) Inject(sm opentracing.SpanContext, format any, carrie
t.mu.RLock()
defer t.mu.RUnlock()
if t.log {
log15.Info("opentracing: Inject", "opentracer", fmt.Sprintf("%T", t.opentracer))
t.logger.Info("opentracing: Inject")
}
return t.opentracer.Inject(sm, format, carrier)
}
@ -221,12 +235,12 @@ func (t *switchableTracer) Extract(format any, carrier any) (opentracing.SpanCon
t.mu.RLock()
defer t.mu.RUnlock()
if t.log {
log15.Info("opentracing: Extract", "tracer", fmt.Sprintf("%T", t.opentracer))
t.logger.Info("opentracing: Extract")
}
return t.opentracer.Extract(format, carrier)
}
func (t *switchableTracer) set(tracer opentracing.Tracer, tracerCloser io.Closer, log bool) {
func (t *switchableTracer) set(tracer opentracing.Tracer, tracerCloser io.Closer, shouldLog bool) {
t.mu.Lock()
defer t.mu.Unlock()
if tc := t.tracerCloser; tc != nil {
@ -236,5 +250,6 @@ func (t *switchableTracer) set(tracer opentracing.Tracer, tracerCloser io.Closer
t.tracerCloser = tracerCloser
t.opentracer = tracer
t.log = log
t.log = shouldLog
t.logger = t.parentLogger.With(log.String("opentracer", fmt.Sprintf("%T", t)))
}