From 89cab1faedd4c4209ac642ffd442b0085d9da593 Mon Sep 17 00:00:00 2001 From: Tom Clegg Date: Wed, 8 Dec 2021 14:51:13 -0500 Subject: [PATCH] 18348: Add ClusterID field to service log entries. Arvados-DCO-1.1-Signed-off-by: Tom Clegg --- apps/workbench/config/initializers/lograge.rb | 1 + lib/service/cmd.go | 3 +- services/api/config/initializers/lograge.rb | 1 + .../crunch-dispatch-local.go | 9 ++- .../crunch-dispatch-slurm.go | 2 + services/keep-web/main.go | 23 +++--- services/keep-web/server.go | 5 +- services/keep-web/server_test.go | 5 +- services/keepproxy/keepproxy.go | 81 +++++++++++-------- 9 files changed, 78 insertions(+), 52 deletions(-) diff --git a/apps/workbench/config/initializers/lograge.rb b/apps/workbench/config/initializers/lograge.rb index 6e7f165c13..795be7bfc3 100644 --- a/apps/workbench/config/initializers/lograge.rb +++ b/apps/workbench/config/initializers/lograge.rb @@ -7,6 +7,7 @@ ArvadosWorkbench::Application.configure do config.lograge.formatter = Lograge::Formatters::Logstash.new config.lograge.custom_options = lambda do |event| payload = { + ClusterID: Rails.configuration.ClusterID, request_id: event.payload[:request_id], } # Also log params (minus the pseudo-params added by Rails). But if diff --git a/lib/service/cmd.go b/lib/service/cmd.go index 880799b348..dbafc89fe4 100644 --- a/lib/service/cmd.go +++ b/lib/service/cmd.go @@ -105,7 +105,8 @@ func (c *command) RunCommand(prog string, args []string, stdin io.Reader, stdout // logger with a new one according to the logging config. log = ctxlog.New(stderr, cluster.SystemLogs.Format, cluster.SystemLogs.LogLevel) logger := log.WithFields(logrus.Fields{ - "PID": os.Getpid(), + "PID": os.Getpid(), + "ClusterID": cluster.ClusterID, }) ctx := ctxlog.Context(c.ctx, logger) diff --git a/services/api/config/initializers/lograge.rb b/services/api/config/initializers/lograge.rb index 9b422462b1..9c0f766915 100644 --- a/services/api/config/initializers/lograge.rb +++ b/services/api/config/initializers/lograge.rb @@ -9,6 +9,7 @@ Server::Application.configure do config.lograge.formatter = Lograge::Formatters::Logstash.new config.lograge.custom_options = lambda do |event| payload = { + ClusterID: Rails.configuration.ClusterID, request_id: event.payload[:request_id], client_ipaddr: event.payload[:client_ipaddr], client_auth: event.payload[:client_auth], diff --git a/services/crunch-dispatch-local/crunch-dispatch-local.go b/services/crunch-dispatch-local/crunch-dispatch-local.go index c9cbdd01fe..968b556a27 100644 --- a/services/crunch-dispatch-local/crunch-dispatch-local.go +++ b/services/crunch-dispatch-local/crunch-dispatch-local.go @@ -35,11 +35,11 @@ var ( ) func main() { - logger := logrus.StandardLogger() + baseLogger := logrus.StandardLogger() if os.Getenv("DEBUG") != "" { - logger.SetLevel(logrus.DebugLevel) + baseLogger.SetLevel(logrus.DebugLevel) } - logger.Formatter = &logrus.JSONFormatter{ + baseLogger.Formatter = &logrus.JSONFormatter{ TimestampFormat: "2006-01-02T15:04:05.000000000Z07:00", } @@ -70,7 +70,7 @@ func main() { return } - loader := config.NewLoader(nil, logger) + loader := config.NewLoader(nil, baseLogger) cfg, err := loader.Load() if err != nil { fmt.Fprintf(os.Stderr, "error loading config: %s\n", err) @@ -82,6 +82,7 @@ func main() { os.Exit(1) } + logger := baseLogger.WithField("ClusterID", cluster.ClusterID) logger.Printf("crunch-dispatch-local %s started", version) runningCmds = make(map[string]*exec.Cmd) diff --git a/services/crunch-dispatch-slurm/crunch-dispatch-slurm.go b/services/crunch-dispatch-slurm/crunch-dispatch-slurm.go index ff1077fae6..84105e1fc7 100644 --- a/services/crunch-dispatch-slurm/crunch-dispatch-slurm.go +++ b/services/crunch-dispatch-slurm/crunch-dispatch-slurm.go @@ -114,6 +114,8 @@ func (disp *Dispatcher) configure(prog string, args []string) error { return fmt.Errorf("config error: %s", err) } + disp.logger = disp.logger.WithField("ClusterID", disp.cluster.ClusterID) + disp.Client.APIHost = disp.cluster.Services.Controller.ExternalURL.Host disp.Client.AuthToken = disp.cluster.SystemRootToken disp.Client.Insecure = disp.cluster.TLS.Insecure diff --git a/services/keep-web/main.go b/services/keep-web/main.go index aa97a18ad8..208b23b93b 100644 --- a/services/keep-web/main.go +++ b/services/keep-web/main.go @@ -5,6 +5,7 @@ package main import ( + "context" "flag" "fmt" "mime" @@ -13,6 +14,7 @@ import ( "git.arvados.org/arvados.git/lib/cmd" "git.arvados.org/arvados.git/lib/config" "git.arvados.org/arvados.git/sdk/go/arvados" + "git.arvados.org/arvados.git/sdk/go/ctxlog" "github.com/coreos/go-systemd/daemon" "github.com/ghodss/yaml" "github.com/sirupsen/logrus" @@ -97,16 +99,17 @@ func configure(logger log.FieldLogger, args []string) (*Config, error) { } func main() { - logger := log.New() - + initLogger := log.StandardLogger() + logger := initLogger.WithField("PID", os.Getpid()) cfg, err := configure(logger, os.Args) if err != nil { - logger.Fatal(err) + log.Fatal(err) } else if cfg == nil { return } - - log.Printf("keep-web %s started", version) + logger = logger.WithField("ClusterID", cfg.cluster.ClusterID) + logger.Printf("keep-web %s started", version) + ctx := ctxlog.Context(context.Background(), logger) if ext := ".txt"; mime.TypeByExtension(ext) == "" { log.Warnf("cannot look up MIME type for %q -- this probably means /etc/mime.types is missing -- clients will see incorrect content types", ext) @@ -114,14 +117,14 @@ func main() { os.Setenv("ARVADOS_API_HOST", cfg.cluster.Services.Controller.ExternalURL.Host) srv := &server{Config: cfg} - if err := srv.Start(logrus.StandardLogger()); err != nil { - log.Fatal(err) + if err := srv.Start(ctx, initLogger); err != nil { + logger.Fatal(err) } if _, err := daemon.SdNotify(false, "READY=1"); err != nil { - log.Printf("Error notifying init daemon: %v", err) + logger.Printf("Error notifying init daemon: %v", err) } - log.Println("Listening at", srv.Addr) + logger.Println("Listening at", srv.Addr) if err := srv.Wait(); err != nil { - log.Fatal(err) + logger.Fatal(err) } } diff --git a/services/keep-web/server.go b/services/keep-web/server.go index 586f6b8057..24f1b77be2 100644 --- a/services/keep-web/server.go +++ b/services/keep-web/server.go @@ -10,7 +10,6 @@ import ( "net/http" "git.arvados.org/arvados.git/sdk/go/arvados" - "git.arvados.org/arvados.git/sdk/go/ctxlog" "git.arvados.org/arvados.git/sdk/go/httpserver" "github.com/prometheus/client_golang/prometheus" "github.com/sirupsen/logrus" @@ -21,7 +20,7 @@ type server struct { Config *Config } -func (srv *server) Start(logger *logrus.Logger) error { +func (srv *server) Start(ctx context.Context, logger *logrus.Logger) error { h := &handler{Config: srv.Config} reg := prometheus.NewRegistry() h.Config.Cache.registry = reg @@ -33,7 +32,7 @@ func (srv *server) Start(logger *logrus.Logger) error { mh := httpserver.Instrument(reg, logger, httpserver.AddRequestIDs(httpserver.LogRequests(h))) h.MetricsAPI = mh.ServeAPI(h.Config.cluster.ManagementToken, http.NotFoundHandler()) srv.Handler = mh - srv.BaseContext = func(net.Listener) context.Context { return ctxlog.Context(context.Background(), logger) } + srv.BaseContext = func(net.Listener) context.Context { return ctx } var listen arvados.URL for listen = range srv.Config.cluster.Services.WebDAV.InternalURLs { break diff --git a/services/keep-web/server_test.go b/services/keep-web/server_test.go index 54e9ddf370..2d28dbc5d7 100644 --- a/services/keep-web/server_test.go +++ b/services/keep-web/server_test.go @@ -6,6 +6,7 @@ package main import ( "bytes" + "context" "crypto/md5" "encoding/json" "fmt" @@ -447,7 +448,9 @@ func (s *IntegrationSuite) SetUpTest(c *check.C) { cfg.cluster.Users.AnonymousUserToken = arvadostest.AnonymousToken s.ArvConfig = arvCfg s.testServer = &server{Config: cfg} - err = s.testServer.Start(ctxlog.TestLogger(c)) + logger := ctxlog.TestLogger(c) + ctx := ctxlog.Context(context.Background(), logger) + err = s.testServer.Start(ctx, logger) c.Assert(err, check.Equals, nil) } diff --git a/services/keepproxy/keepproxy.go b/services/keepproxy/keepproxy.go index 7c1360ad71..c2760a2a4f 100644 --- a/services/keepproxy/keepproxy.go +++ b/services/keepproxy/keepproxy.go @@ -5,6 +5,7 @@ package main import ( + "context" "errors" "flag" "fmt" @@ -23,6 +24,7 @@ import ( "git.arvados.org/arvados.git/lib/config" "git.arvados.org/arvados.git/sdk/go/arvados" "git.arvados.org/arvados.git/sdk/go/arvadosclient" + "git.arvados.org/arvados.git/sdk/go/ctxlog" "git.arvados.org/arvados.git/sdk/go/health" "git.arvados.org/arvados.git/sdk/go/httpserver" "git.arvados.org/arvados.git/sdk/go/keepclient" @@ -30,7 +32,7 @@ import ( "github.com/ghodss/yaml" "github.com/gorilla/mux" lru "github.com/hashicorp/golang-lru" - log "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus" ) var version = "dev" @@ -42,13 +44,19 @@ var ( const rfc3339NanoFixed = "2006-01-02T15:04:05.000000000Z07:00" -func configure(logger log.FieldLogger, args []string) (*arvados.Cluster, error) { +func configure(args []string) (*arvados.Cluster, logrus.FieldLogger, error) { prog := args[0] flags := flag.NewFlagSet(prog, flag.ContinueOnError) dumpConfig := flags.Bool("dump-config", false, "write current configuration to stdout and exit") getVersion := flags.Bool("version", false, "Print version information and exit.") + initLogger := logrus.New() + initLogger.Formatter = &logrus.JSONFormatter{ + TimestampFormat: rfc3339NanoFixed, + } + var logger logrus.FieldLogger = initLogger + loader := config.NewLoader(os.Stdin, logger) loader.SetupFlags(flags) args = loader.MungeLegacyConfigArgs(logger, args[1:], "-legacy-keepproxy-config") @@ -57,55 +65,56 @@ func configure(logger log.FieldLogger, args []string) (*arvados.Cluster, error) os.Exit(code) } else if *getVersion { fmt.Printf("keepproxy %s\n", version) - return nil, nil + return nil, logger, nil } cfg, err := loader.Load() if err != nil { - return nil, err + return nil, logger, err } cluster, err := cfg.GetCluster("") if err != nil { - return nil, err + return nil, logger, err } + logger = ctxlog.New(os.Stderr, cluster.SystemLogs.Format, cluster.SystemLogs.LogLevel).WithFields(logrus.Fields{ + "ClusterID": cluster.ClusterID, + "PID": os.Getpid(), + }) + if *dumpConfig { out, err := yaml.Marshal(cfg) if err != nil { - return nil, err + return nil, logger, err } if _, err := os.Stdout.Write(out); err != nil { - return nil, err + return nil, logger, err } - return nil, nil + return nil, logger, nil } - return cluster, nil + + return cluster, logger, nil } func main() { - logger := log.New() - logger.Formatter = &log.JSONFormatter{ - TimestampFormat: rfc3339NanoFixed, - } - - cluster, err := configure(logger, os.Args) + cluster, logger, err := configure(os.Args) if err != nil { - log.Fatal(err) + logger.Fatal(err) } if cluster == nil { return } - log.Printf("keepproxy %s started", version) + logger.Printf("keepproxy %s started", version) if err := run(logger, cluster); err != nil { - log.Fatal(err) + logger.Fatal(err) } - log.Println("shutting down") + logger.Println("shutting down") } -func run(logger log.FieldLogger, cluster *arvados.Cluster) error { +func run(logger logrus.FieldLogger, cluster *arvados.Cluster) error { client, err := arvados.NewClientFromConfig(cluster) if err != nil { return err @@ -124,7 +133,7 @@ func run(logger log.FieldLogger, cluster *arvados.Cluster) error { } if cluster.SystemLogs.LogLevel == "debug" { - keepclient.DebugPrintf = log.Printf + keepclient.DebugPrintf = logger.Printf } kc, err := keepclient.MakeKeepClient(arv) if err != nil { @@ -148,16 +157,16 @@ func run(logger log.FieldLogger, cluster *arvados.Cluster) error { } if _, err := daemon.SdNotify(false, "READY=1"); err != nil { - log.Printf("Error notifying init daemon: %v", err) + logger.Printf("Error notifying init daemon: %v", err) } - log.Println("listening at", listener.Addr()) + logger.Println("listening at", listener.Addr()) // Shut down the server gracefully (by closing the listener) // if SIGTERM is received. term := make(chan os.Signal, 1) go func(sig <-chan os.Signal) { s := <-sig - log.Println("caught signal:", s) + logger.Println("caught signal:", s) listener.Close() }(term) signal.Notify(term, syscall.SIGTERM) @@ -168,7 +177,13 @@ func run(logger log.FieldLogger, cluster *arvados.Cluster) error { if err != nil { return err } - return http.Serve(listener, httpserver.AddRequestIDs(httpserver.LogRequests(router))) + server := http.Server{ + Handler: httpserver.AddRequestIDs(httpserver.LogRequests(router)), + BaseContext: func(net.Listener) context.Context { + return ctxlog.Context(context.Background(), logger) + }, + } + return server.Serve(listener) } type TokenCacheEntry struct { @@ -267,7 +282,7 @@ func (h *proxyHandler) CheckAuthorizationHeader(req *http.Request) (pass bool, t } } if err != nil { - log.Printf("%s: CheckAuthorizationHeader error: %v", GetRemoteAddress(req), err) + ctxlog.FromContext(req.Context()).Printf("%s: CheckAuthorizationHeader error: %v", GetRemoteAddress(req), err) return false, "", nil } @@ -309,13 +324,13 @@ type proxyHandler struct { *APITokenCache timeout time.Duration transport *http.Transport - logger log.FieldLogger + logger logrus.FieldLogger cluster *arvados.Cluster } // MakeRESTRouter returns an http.Handler that passes GET and PUT // requests to the appropriate handlers. -func MakeRESTRouter(kc *keepclient.KeepClient, timeout time.Duration, cluster *arvados.Cluster, logger log.FieldLogger) (http.Handler, error) { +func MakeRESTRouter(kc *keepclient.KeepClient, timeout time.Duration, cluster *arvados.Cluster, logger logrus.FieldLogger) (http.Handler, error) { rest := mux.NewRouter() transport := defaultTransport @@ -390,12 +405,12 @@ func SetCorsHeaders(resp http.ResponseWriter) { type InvalidPathHandler struct{} func (InvalidPathHandler) ServeHTTP(resp http.ResponseWriter, req *http.Request) { - log.Printf("%s: %s %s unroutable", GetRemoteAddress(req), req.Method, req.URL.Path) + ctxlog.FromContext(req.Context()).Printf("%s: %s %s unroutable", GetRemoteAddress(req), req.Method, req.URL.Path) http.Error(resp, "Bad request", http.StatusBadRequest) } func (h *proxyHandler) Options(resp http.ResponseWriter, req *http.Request) { - log.Printf("%s: %s %s", GetRemoteAddress(req), req.Method, req.URL.Path) + ctxlog.FromContext(req.Context()).Printf("%s: %s %s", GetRemoteAddress(req), req.Method, req.URL.Path) SetCorsHeaders(resp) } @@ -419,7 +434,7 @@ func (h *proxyHandler) Get(resp http.ResponseWriter, req *http.Request) { var proxiedURI = "-" defer func() { - log.Println(GetRemoteAddress(req), req.Method, req.URL.Path, status, expectLength, responseLength, proxiedURI, err) + h.logger.Println(GetRemoteAddress(req), req.Method, req.URL.Path, status, expectLength, responseLength, proxiedURI, err) if status != http.StatusOK { http.Error(resp, err.Error(), status) } @@ -470,7 +485,7 @@ func (h *proxyHandler) Get(resp http.ResponseWriter, req *http.Request) { } if expectLength == -1 { - log.Println("Warning:", GetRemoteAddress(req), req.Method, proxiedURI, "Content-Length not provided") + h.logger.Println("Warning:", GetRemoteAddress(req), req.Method, proxiedURI, "Content-Length not provided") } switch respErr := err.(type) { @@ -518,7 +533,7 @@ func (h *proxyHandler) Put(resp http.ResponseWriter, req *http.Request) { var locatorOut string = "-" defer func() { - log.Println(GetRemoteAddress(req), req.Method, req.URL.Path, status, expectLength, kc.Want_replicas, wroteReplicas, locatorOut, err) + h.logger.Println(GetRemoteAddress(req), req.Method, req.URL.Path, status, expectLength, kc.Want_replicas, wroteReplicas, locatorOut, err) if status != http.StatusOK { http.Error(resp, err.Error(), status) } -- 2.30.2