[ARVADOS] created: 2.1.0-1700-gfd7e2559f

Git user git at public.arvados.org
Mon Dec 6 16:57:52 UTC 2021


        at  fd7e2559fc06ad7c6ed5a5977a22a60df8f2fc19 (commit)


commit fd7e2559fc06ad7c6ed5a5977a22a60df8f2fc19
Author: Tom Clegg <tom at curii.com>
Date:   Fri Dec 3 15:59:46 2021 -0500

    18348: Add ClusterID field to service log entries.
    
    Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom at curii.com>

diff --git a/apps/workbench/config/initializers/lograge.rb b/apps/workbench/config/initializers/lograge.rb
index 6e7f165c1..795be7bfc 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 880799b34..dbafc89fe 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 9b422462b..9c0f76691 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 c9cbdd01f..0f2a58a9d 100644
--- a/services/crunch-dispatch-local/crunch-dispatch-local.go
+++ b/services/crunch-dispatch-local/crunch-dispatch-local.go
@@ -82,6 +82,7 @@ func main() {
 		os.Exit(1)
 	}
 
+	disp.logger = disp.logger.WithField("ClusterID", disp.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 ff1077fae..84105e1fc 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 aa97a18ad..d28656bd9 100644
--- a/services/keep-web/main.go
+++ b/services/keep-web/main.go
@@ -97,16 +97,15 @@ func configure(logger log.FieldLogger, args []string) (*Config, error) {
 }
 
 func main() {
-	logger := log.New()
-
+	logger := log.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)
 
 	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 +113,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(logger); 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 586f6b805..c0ebe91ae 100644
--- a/services/keep-web/server.go
+++ b/services/keep-web/server.go
@@ -21,7 +21,7 @@ type server struct {
 	Config *Config
 }
 
-func (srv *server) Start(logger *logrus.Logger) error {
+func (srv *server) Start(logger logrus.FieldLogger) error {
 	h := &handler{Config: srv.Config}
 	reg := prometheus.NewRegistry()
 	h.Config.Cache.registry = reg
@@ -30,7 +30,7 @@ func (srv *server) Start(logger *logrus.Logger) error {
 	// httpserver.HandlerWithDeadline() so large file uploads are
 	// allowed to take longer than the usual API.RequestTimeout.
 	// See #13697.
-	mh := httpserver.Instrument(reg, logger, httpserver.AddRequestIDs(httpserver.LogRequests(h)))
+	mh := httpserver.Instrument(reg, nil, 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) }
diff --git a/services/keepproxy/keepproxy.go b/services/keepproxy/keepproxy.go
index 7c1360ad7..c2760a2a4 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)
 		}

-----------------------------------------------------------------------


hooks/post-receive
-- 




More information about the arvados-commits mailing list