From 2aa6f522183a4270e06e3aa6f2caba9f615d2019 Mon Sep 17 00:00:00 2001 From: iacore Date: Wed, 28 Aug 2024 13:52:28 +0000 Subject: [PATCH] Log spans --- audit/log_reporter.go | 19 +++++++++++ audit/tracing.go | 56 +++++++++++++++++++++++++++------ config/environment_variables.go | 5 +++ config/proxy_checker.go | 6 ++-- main.go | 24 ++------------ main_test.go | 4 +-- template/render_test.go | 2 +- 7 files changed, 78 insertions(+), 38 deletions(-) create mode 100644 audit/log_reporter.go diff --git a/audit/log_reporter.go b/audit/log_reporter.go new file mode 100644 index 0000000..82480ec --- /dev/null +++ b/audit/log_reporter.go @@ -0,0 +1,19 @@ +package audit + +import ( + "log" + + "github.com/openzipkin/zipkin-go/model" +) + +type LogReporter struct { + l *log.Logger +} + +func (rr LogReporter) Send(m model.SpanModel) { + rr.l.Print(m.Name) +} + +func (rr LogReporter) Close() error { + return nil +} diff --git a/audit/tracing.go b/audit/tracing.go index cf752d7..4a47010 100644 --- a/audit/tracing.go +++ b/audit/tracing.go @@ -9,23 +9,59 @@ import ( "path" "time" + "github.com/openzipkin/zipkin-go" + "github.com/openzipkin/zipkin-go/reporter" + http_reporter "github.com/openzipkin/zipkin-go/reporter/http" + + "codeberg.org/vnpower/pixivfe/v2/config" "codeberg.org/vnpower/pixivfe/v2/handlers/user_context" "codeberg.org/vnpower/pixivfe/v2/utils" - "github.com/openzipkin/zipkin-go" ) const DevDir_Response = "/tmp/pixivfe-dev/resp" var optionSaveResponse bool -func Init(saveResponse bool, tracer *zipkin.Tracer) error { +func Init(saveResponse bool) error { optionSaveResponse = saveResponse - utils.Tracer = tracer if optionSaveResponse { - return os.MkdirAll(DevDir_Response, 0o700) - } else { - return nil + err := os.MkdirAll(DevDir_Response, 0o700) + if err != nil { + return err + } } + + var reporter reporter.Reporter = nil + + _, enableReporting := config.LookupEnv("PIXIVFE_ENABLE_ZIPKIN") + if enableReporting { + reporter = http_reporter.NewReporter("http://localhost:9411/api/v2/spans") + defer func() { + _ = reporter.Close() + }() + } else { + // comment out this block in logging is too verbose + reporter = LogReporter{l: log.New(os.Stderr, "", log.Flags())} + defer func() { + _ = reporter.Close() + }() + } + + // this is purely theoretical. the port is used for distributed tracing. + endpoint, err := zipkin.NewEndpoint("pixivfe", "localhost:8282") + if err != nil { + log.Fatalf("unable to create local endpoint: %+v\n", err) + } + + // initialize our tracer + tracer, err := zipkin.NewTracer(reporter, zipkin.WithLocalEndpoint(endpoint)) + if err != nil { + log.Fatalf("unable to create tracer: %+v\n", err) + } + + utils.Tracer = tracer + + return nil } type ServerPerformance struct { @@ -56,7 +92,7 @@ func LogServerRoundTrip(context context.Context, perf ServerPerformance) { log.Printf("Internal Server Error: %s", perf.Error) } - span, _ := utils.Tracer.StartSpanFromContext(context, fmt.Sprintf("Served %v %v %v %v", perf.Method, perf.Path, perf.Status, perf.Error), zipkin.StartTime(perf.StartTime), zipkin.Parent(user_context.GetUserContext(context).Parent)) + span, _ := utils.Tracer.StartSpanFromContext(context, fmt.Sprintf("%v %v %v %v", perf.Method, perf.Path, perf.Status, perf.Error), zipkin.StartTime(perf.StartTime), zipkin.Parent(user_context.GetUserContext(context).Parent)) span.Tag("RemoteAddr", perf.RemoteAddr) span.FinishedWithDuration(perf.EndTime.Sub(perf.StartTime)) } @@ -67,13 +103,13 @@ func LogAPIRoundTrip(context context.Context, perf APIPerformance) { var err error perf.ResponseFilename, err = writeResponseBodyToFile(perf.Body) if err != nil { - log.Println("When saving response to file: ", err) + log.Print("When saving response to file: ", err) } else { - log.Println(fmt.Sprintf("[API] %v %v saved to %v", perf.Method, perf.Url, perf.ResponseFilename)) + log.Printf("[API] %v %v saved to %v", perf.Method, perf.Url, perf.ResponseFilename) } } if !(300 > perf.Response.StatusCode && perf.Response.StatusCode >= 200) { - log.Println("(WARN) non-2xx response from pixiv:") + log.Print("(WARN) non-2xx response from pixiv:") } } span, _ := utils.Tracer.StartSpanFromContext(context, fmt.Sprintf("API %v %v %v", perf.Method, perf.Url, perf.Error), zipkin.StartTime(perf.StartTime), zipkin.Parent(user_context.GetUserContext(context).Parent)) diff --git a/config/environment_variables.go b/config/environment_variables.go index b3cac1a..9337680 100644 --- a/config/environment_variables.go +++ b/config/environment_variables.go @@ -110,6 +110,11 @@ var EnvList []*EnvVar = []*EnvVar{ // The interval in minutes between proxy checks. Defaults to 480 minutes (8 hours) if not set. // You can disable this by setting the value to 0. Then, proxies will only be checked once at server initialization. }, + { + Name: "PIXIVFE_ENABLE_ZIPKIN", + CommonName: "report spans to http://localhost:9411/api/v2/spans", + // **Required**: No + }, } // ====================================================================== diff --git a/config/proxy_checker.go b/config/proxy_checker.go index 18774f9..453163a 100644 --- a/config/proxy_checker.go +++ b/config/proxy_checker.go @@ -31,14 +31,14 @@ func StartProxyChecker(r context.Context) { for { select { case <-stopChan: - log.Println("Stopping proxy checker...") + log.Print("Stopping proxy checker...") return default: checkProxies(r) if t := GlobalServerConfig.ProxyCheckInterval; t > 0 { time.Sleep(t) } else { - log.Println("Proxy check interval set to 0, disabling auto-check from now on.") + log.Print("Proxy check interval set to 0, disabling auto-check from now on.") select {} // Sweet dreams! } } @@ -126,5 +126,5 @@ func logf(format string, v ...any) { } func logln(v ...any) { - log.Println(v...) + log.Print(v...) } diff --git a/main.go b/main.go index 7511308..98c74db 100644 --- a/main.go +++ b/main.go @@ -11,9 +11,6 @@ import ( "runtime" "syscall" - "github.com/openzipkin/zipkin-go" - zipkin_httpreporter "github.com/openzipkin/zipkin-go/reporter/http" - "codeberg.org/vnpower/pixivfe/v2/audit" "codeberg.org/vnpower/pixivfe/v2/config" "codeberg.org/vnpower/pixivfe/v2/handlers" @@ -21,25 +18,8 @@ import ( ) func main() { - reporter := zipkin_httpreporter.NewReporter("http://localhost:9411/api/v2/spans") - defer func() { - _ = reporter.Close() - }() - - // this is purely theoretical. the port is used for distributed tracing. - endpoint, err := zipkin.NewEndpoint("pixivfe", "localhost:8282") - if err != nil { - log.Fatalf("unable to create local endpoint: %+v\n", err) - } - - // initialize our tracer - tracer, err := zipkin.NewTracer(reporter, zipkin.WithLocalEndpoint(endpoint)) - if err != nil { - log.Fatalf("unable to create tracer: %+v\n", err) - } - config.GlobalServerConfig.LoadConfig() - audit.Init(config.GlobalServerConfig.InDevelopment, tracer) + audit.Init(config.GlobalServerConfig.InDevelopment) template.Init(config.GlobalServerConfig.InDevelopment) // Initialize and start the proxy checker @@ -67,7 +47,7 @@ func main() { runtime.LockOSThread() // Go quirk https://github.com/golang/go/issues/27505 err := cmd.Run() if err != nil { - log.Println(fmt.Errorf("when running sass: %w", err)) + log.Print(fmt.Errorf("when running sass: %w", err)) } }() } diff --git a/main_test.go b/main_test.go index c5af432..77d2030 100644 --- a/main_test.go +++ b/main_test.go @@ -27,7 +27,7 @@ func setup() { log.Fatalf("could not launch browser: %v", err) } - log.Println("Setup is complete") + log.Print("Setup is complete") } func teardown() { @@ -38,7 +38,7 @@ func teardown() { if err := pw.Stop(); err != nil { log.Fatalf("could not stop Playwright: %v", err) } - log.Println("Teardown is complete") + log.Print("Teardown is complete") } // TestMain can be used for global setup and teardown diff --git a/template/render_test.go b/template/render_test.go index 295328c..75c16ce 100644 --- a/template/render_test.go +++ b/template/render_test.go @@ -67,7 +67,7 @@ func manualTest[T any](t *testing.T, data T) { log.Panicf("struct name does not start with 'Data_': %s", route_name) } - // log.Println("Testing " + route_name) + // log.Print("Testing " + route_name) variables := jet.VarMap{}