18348: Add ClusterID field to service log entries.
authorTom Clegg <tom@curii.com>
Wed, 8 Dec 2021 19:51:13 +0000 (14:51 -0500)
committerTom Clegg <tom@curii.com>
Wed, 8 Dec 2021 19:51:13 +0000 (14:51 -0500)
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom@curii.com>

apps/workbench/config/initializers/lograge.rb
lib/service/cmd.go
services/api/config/initializers/lograge.rb
services/crunch-dispatch-local/crunch-dispatch-local.go
services/crunch-dispatch-slurm/crunch-dispatch-slurm.go
services/keep-web/main.go
services/keep-web/server.go
services/keep-web/server_test.go
services/keepproxy/keepproxy.go

index 6e7f165c135b2132bcaef1e89ccac6890f585ed4..795be7bfc39907ee6590378484b8c04aa9329c3c 100644 (file)
@@ -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
index 880799b348b57b2e9d485711c2b49ccd2f1757e4..dbafc89fe4792d90b30e5fa70ec18b43a0c5107d 100644 (file)
@@ -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)
 
index 9b422462b193a400a58375bc31cf76486132d023..9c0f76691535eade936fa1712c06ea1657031c47 100644 (file)
@@ -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],
index c9cbdd01fec15ca340d0e9342f8a1e24c42f1942..968b556a27e720d100abb705e3b704cb2b237299 100644 (file)
@@ -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)
index ff1077fae63ace1703e8c66ad95e54bb32d5a49a..84105e1fc77e5315df0ab1a7d3ba8d6b219f9b99 100644 (file)
@@ -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
index aa97a18ad899af1a49897e72e6c63ec439dbe35b..208b23b93b5206c0e55cea5a8eab74849a54855f 100644 (file)
@@ -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)
        }
 }
index 586f6b805736e23437357dbc8eb1a8cf4b5a5cc7..24f1b77be238bd188b482a9beb678e1b7dfc812f 100644 (file)
@@ -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
index 54e9ddf3704d606a14c2b8965c1bf611cacb76bd..2d28dbc5d7175fe78149487f532d4b6b5f4a08ac 100644 (file)
@@ -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)
 }
 
index 7c1360ad71a2e945b2aaee72d4f6aadabaf664ba..c2760a2a4fb462e193f833ac97f59167871c7065 100644 (file)
@@ -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)
                }