lib/service/cmd.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: Apache-2.0
   4
   5 // Package service provides a cmd.Handler that brings up a system service.
   6 package service
   7
   8 import (
   9         "context"
  10         "flag"
  11         "fmt"
  12         "io"
  13         "net"
  14         "net/http"
  15         "net/http/httptest"
  16         _ "net/http/pprof"
  17         "net/url"
  18         "os"
  19         "strings"
  20         "time"
  21
  22         "git.arvados.org/arvados.git/lib/cmd"
  23         "git.arvados.org/arvados.git/lib/config"
  24         "git.arvados.org/arvados.git/sdk/go/arvados"
  25         "git.arvados.org/arvados.git/sdk/go/ctxlog"
  26         "git.arvados.org/arvados.git/sdk/go/health"
  27         "git.arvados.org/arvados.git/sdk/go/httpserver"
  28         "github.com/coreos/go-systemd/daemon"
  29         "github.com/julienschmidt/httprouter"
  30         "github.com/prometheus/client_golang/prometheus"
  31         "github.com/sirupsen/logrus"
  32 )
  33
  34 type Handler interface {
  35         http.Handler
  36         CheckHealth() error
  37         // Done returns a channel that closes when the handler shuts
  38         // itself down, or nil if this never happens.
  39         Done() <-chan struct{}
  40 }
  41
  42 type NewHandlerFunc func(_ context.Context, _ *arvados.Cluster, token string, registry *prometheus.Registry) Handler
  43
  44 type command struct {
  45         newHandler NewHandlerFunc
  46         svcName    arvados.ServiceName
  47         ctx        context.Context // enables tests to shutdown service; no public API yet
  48 }
  49
  50 var requestQueueDumpCheckInterval = time.Minute
  51
  52 // Command returns a cmd.Handler that loads site config, calls
  53 // newHandler with the current cluster and node configs, and brings up
  54 // an http server with the returned handler.
  55 //
  56 // The handler is wrapped with server middleware (adding X-Request-ID
  57 // headers, logging requests/responses, etc).
  58 func Command(svcName arvados.ServiceName, newHandler NewHandlerFunc) cmd.Handler {
  59         return &command{
  60                 newHandler: newHandler,
  61                 svcName:    svcName,
  62                 ctx:        context.Background(),
  63         }
  64 }
  65
  66 func (c *command) RunCommand(prog string, args []string, stdin io.Reader, stdout, stderr io.Writer) int {
  67         log := ctxlog.New(stderr, "json", "info")
  68
  69         var err error
  70         defer func() {
  71                 if err != nil {
  72                         log.WithError(err).Error("exiting")
  73                 }
  74         }()
  75
  76         flags := flag.NewFlagSet("", flag.ContinueOnError)
  77         flags.SetOutput(stderr)
  78
  79         loader := config.NewLoader(stdin, log)
  80         loader.SetupFlags(flags)
  81
  82         // prog is [keepstore, keep-web, git-httpd, ...]  but the
  83         // legacy config flags are [-legacy-keepstore-config,
  84         // -legacy-keepweb-config, -legacy-git-httpd-config, ...]
  85         legacyFlag := "-legacy-" + strings.Replace(prog, "keep-", "keep", 1) + "-config"
  86         args = loader.MungeLegacyConfigArgs(log, args, legacyFlag)
  87
  88         versionFlag := flags.Bool("version", false, "Write version information to stdout and exit 0")
  89         pprofAddr := flags.String("pprof", "", "Serve Go profile data at `[addr]:port`")
  90         if ok, code := cmd.ParseFlags(flags, prog, args, "", stderr); !ok {
  91                 return code
  92         } else if *versionFlag {
  93                 return cmd.Version.RunCommand(prog, args, stdin, stdout, stderr)
  94         }
  95
  96         if *pprofAddr != "" {
  97                 go func() {
  98                         log.Println(http.ListenAndServe(*pprofAddr, nil))
  99                 }()
 100         }
 101
 102         if strings.HasSuffix(prog, "controller") {
 103                 // Some config-loader checks try to make API calls via
 104                 // controller. Those can't be expected to work if this
 105                 // process _is_ the controller: we haven't started an
 106                 // http server yet.
 107                 loader.SkipAPICalls = true
 108         }
 109
 110         cfg, err := loader.Load()
 111         if err != nil {
 112                 return 1
 113         }
 114         cluster, err := cfg.GetCluster("")
 115         if err != nil {
 116                 return 1
 117         }
 118
 119         // Now that we've read the config, replace the bootstrap
 120         // logger with a new one according to the logging config.
 121         log = ctxlog.New(stderr, cluster.SystemLogs.Format, cluster.SystemLogs.LogLevel)
 122         logger := log.WithFields(logrus.Fields{
 123                 "PID":       os.Getpid(),
 124                 "ClusterID": cluster.ClusterID,
 125         })
 126         ctx := ctxlog.Context(c.ctx, logger)
 127
 128         listenURL, internalURL, err := getListenAddr(cluster.Services, c.svcName, log)
 129         if err != nil {
 130                 return 1
 131         }
 132         ctx = context.WithValue(ctx, contextKeyURL{}, internalURL)
 133
 134         reg := prometheus.NewRegistry()
 135         loader.RegisterMetrics(reg)
 136
 137         // arvados_version_running{version="1.2.3~4"} 1.0
 138         mVersion := prometheus.NewGaugeVec(prometheus.GaugeOpts{
 139                 Namespace: "arvados",
 140                 Name:      "version_running",
 141                 Help:      "Indicated version is running.",
 142         }, []string{"version"})
 143         mVersion.WithLabelValues(cmd.Version.String()).Set(1)
 144         reg.MustRegister(mVersion)
 145
 146         handler := c.newHandler(ctx, cluster, cluster.SystemRootToken, reg)
 147         if err = handler.CheckHealth(); err != nil {
 148                 return 1
 149         }
 150
 151         instrumented := httpserver.Instrument(reg, log,
 152                 httpserver.HandlerWithDeadline(cluster.API.RequestTimeout.Duration(),
 153                         httpserver.AddRequestIDs(
 154                                 httpserver.Inspect(reg, cluster.ManagementToken,
 155                                         httpserver.LogRequests(
 156                                                 interceptHealthReqs(cluster.ManagementToken, handler.CheckHealth,
 157                                                         &httpserver.RequestLimiter{
 158                                                                 Handler:                    handler,
 159                                                                 MaxConcurrent:              cluster.API.MaxConcurrentRequests,
 160                                                                 MaxQueue:                   cluster.API.MaxQueuedRequests,
 161                                                                 MaxQueueTimeForMinPriority: cluster.API.MaxQueueTimeForLockRequests.Duration(),
 162                                                                 Priority:                   c.requestPriority,
 163                                                                 Registry:                   reg}))))))
 164         srv := &httpserver.Server{
 165                 Server: http.Server{
 166                         Handler:     ifCollectionInHost(instrumented, instrumented.ServeAPI(cluster.ManagementToken, instrumented)),
 167                         BaseContext: func(net.Listener) context.Context { return ctx },
 168                 },
 169                 Addr: listenURL.Host,
 170         }
 171         if listenURL.Scheme == "https" || listenURL.Scheme == "wss" {
 172                 tlsconfig, err := makeTLSConfig(cluster, logger)
 173                 if err != nil {
 174                         logger.WithError(err).Errorf("cannot start %s service on %s", c.svcName, listenURL.String())
 175                         return 1
 176                 }
 177                 srv.TLSConfig = tlsconfig
 178         }
 179         err = srv.Start()
 180         if err != nil {
 181                 return 1
 182         }
 183         logger.WithFields(logrus.Fields{
 184                 "URL":     listenURL,
 185                 "Listen":  srv.Addr,
 186                 "Service": c.svcName,
 187                 "Version": cmd.Version.String(),
 188         }).Info("listening")
 189         if _, err := daemon.SdNotify(false, "READY=1"); err != nil {
 190                 logger.WithError(err).Errorf("error notifying init daemon")
 191         }
 192         go func() {
 193                 // Shut down server if caller cancels context
 194                 <-ctx.Done()
 195                 srv.Close()
 196         }()
 197         go func() {
 198                 // Shut down server if handler dies
 199                 <-handler.Done()
 200                 srv.Close()
 201         }()
 202         go c.requestQueueDumpCheck(cluster, prog, reg, &srv.Server, logger)
 203         err = srv.Wait()
 204         if err != nil {
 205                 return 1
 206         }
 207         return 0
 208 }
 209
 210 // If SystemLogs.RequestQueueDumpDirectory is set, monitor the
 211 // server's incoming HTTP request queue size. When it exceeds 90% of
 212 // API.MaxConcurrentRequests, write the /_inspect/requests data to a
 213 // JSON file in the specified directory.
 214 func (c *command) requestQueueDumpCheck(cluster *arvados.Cluster, prog string, reg *prometheus.Registry, srv *http.Server, logger logrus.FieldLogger) {
 215         outdir := cluster.SystemLogs.RequestQueueDumpDirectory
 216         if outdir == "" || cluster.ManagementToken == "" || cluster.API.MaxConcurrentRequests < 1 {
 217                 return
 218         }
 219         logger = logger.WithField("worker", "RequestQueueDump")
 220         outfile := outdir + "/" + prog + "-requests.json"
 221         for range time.NewTicker(requestQueueDumpCheckInterval).C {
 222                 mfs, err := reg.Gather()
 223                 if err != nil {
 224                         logger.WithError(err).Warn("error getting metrics")
 225                         continue
 226                 }
 227                 dump := false
 228                 for _, mf := range mfs {
 229                         if mf.Name != nil && *mf.Name == "arvados_concurrent_requests" && len(mf.Metric) == 1 {
 230                                 n := int(mf.Metric[0].GetGauge().GetValue())
 231                                 if n > 0 && n >= cluster.API.MaxConcurrentRequests*9/10 {
 232                                         dump = true
 233                                         break
 234                                 }
 235                         }
 236                 }
 237                 if dump {
 238                         req, err := http.NewRequest("GET", "/_inspect/requests", nil)
 239                         if err != nil {
 240                                 logger.WithError(err).Warn("error in http.NewRequest")
 241                                 continue
 242                         }
 243                         req.Header.Set("Authorization", "Bearer "+cluster.ManagementToken)
 244                         resp := httptest.NewRecorder()
 245                         srv.Handler.ServeHTTP(resp, req)
 246                         if code := resp.Result().StatusCode; code != http.StatusOK {
 247                                 logger.WithField("StatusCode", code).Warn("error getting /_inspect/requests")
 248                                 continue
 249                         }
 250                         err = os.WriteFile(outfile, resp.Body.Bytes(), 0777)
 251                         if err != nil {
 252                                 logger.WithError(err).Warn("error writing file")
 253                                 continue
 254                         }
 255                 }
 256         }
 257 }
 258
 259 func (c *command) requestPriority(req *http.Request, queued time.Time) int64 {
 260         switch {
 261         case req.Method == http.MethodPost && strings.HasPrefix(req.URL.Path, "/arvados/v1/containers/") && strings.HasSuffix(req.URL.Path, "/lock"):
 262                 // Return 503 immediately instead of queueing. We want
 263                 // to send feedback to dispatchcloud ASAP to stop
 264                 // bringing up new containers.
 265                 return httpserver.MinPriority
 266         case req.Method == http.MethodPost && strings.HasPrefix(req.URL.Path, "/arvados/v1/logs"):
 267                 // "Create log entry" is the most harmless kind of
 268                 // request to drop. Negative priority is called "low"
 269                 // in aggregate metrics.
 270                 return -1
 271         case req.Header.Get("Origin") != "":
 272                 // Handle interactive requests first. Positive
 273                 // priority is called "high" in aggregate metrics.
 274                 return 1
 275         default:
 276                 // Zero priority is called "normal" in aggregate
 277                 // metrics.
 278                 return 0
 279         }
 280 }
 281
 282 // If an incoming request's target vhost has an embedded collection
 283 // UUID or PDH, handle it with hTrue, otherwise handle it with
 284 // hFalse.
 285 //
 286 // Facilitates routing "http://collections.example/metrics" to metrics
 287 // and "http://{uuid}.collections.example/metrics" to a file in a
 288 // collection.
 289 func ifCollectionInHost(hTrue, hFalse http.Handler) http.Handler {
 290         return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 291                 if arvados.CollectionIDFromDNSName(r.Host) != "" {
 292                         hTrue.ServeHTTP(w, r)
 293                 } else {
 294                         hFalse.ServeHTTP(w, r)
 295                 }
 296         })
 297 }
 298
 299 func interceptHealthReqs(mgtToken string, checkHealth func() error, next http.Handler) http.Handler {
 300         mux := httprouter.New()
 301         mux.Handler("GET", "/_health/ping", &health.Handler{
 302                 Token:  mgtToken,
 303                 Prefix: "/_health/",
 304                 Routes: health.Routes{"ping": checkHealth},
 305         })
 306         mux.NotFound = next
 307         return ifCollectionInHost(next, mux)
 308 }
 309
 310 // Determine listenURL (addr:port where server should bind) and
 311 // internalURL (target url that client should connect to) for a
 312 // service.
 313 //
 314 // If the config does not specify ListenURL, we check all of the
 315 // configured InternalURLs. If there is exactly one that matches our
 316 // hostname, or exactly one that matches a local interface address,
 317 // then we use that as listenURL.
 318 //
 319 // Note that listenURL and internalURL may use different protocols
 320 // (e.g., listenURL is http, but the service sits behind a proxy, so
 321 // clients connect using https).
 322 func getListenAddr(svcs arvados.Services, prog arvados.ServiceName, log logrus.FieldLogger) (arvados.URL, arvados.URL, error) {
 323         svc, ok := svcs.Map()[prog]
 324         if !ok {
 325                 return arvados.URL{}, arvados.URL{}, fmt.Errorf("unknown service name %q", prog)
 326         }
 327
 328         if want := os.Getenv("ARVADOS_SERVICE_INTERNAL_URL"); want != "" {
 329                 url, err := url.Parse(want)
 330                 if err != nil {
 331                         return arvados.URL{}, arvados.URL{}, fmt.Errorf("$ARVADOS_SERVICE_INTERNAL_URL (%q): %s", want, err)
 332                 }
 333                 if url.Path == "" {
 334                         url.Path = "/"
 335                 }
 336                 for internalURL, conf := range svc.InternalURLs {
 337                         if internalURL.String() == url.String() {
 338                                 listenURL := conf.ListenURL
 339                                 if listenURL.Host == "" {
 340                                         listenURL = internalURL
 341                                 }
 342                                 return listenURL, internalURL, nil
 343                         }
 344                 }
 345                 log.Warnf("possible configuration error: listening on %s (from $ARVADOS_SERVICE_INTERNAL_URL) even though configuration does not have a matching InternalURLs entry", url)
 346                 internalURL := arvados.URL(*url)
 347                 return internalURL, internalURL, nil
 348         }
 349
 350         errors := []string{}
 351         for internalURL, conf := range svc.InternalURLs {
 352                 listenURL := conf.ListenURL
 353                 if listenURL.Host == "" {
 354                         // If ListenURL is not specified, assume
 355                         // InternalURL is also usable as the listening
 356                         // proto/addr/port (i.e., simple case with no
 357                         // intermediate proxy/routing)
 358                         listenURL = internalURL
 359                 }
 360                 listenAddr := listenURL.Host
 361                 if _, _, err := net.SplitHostPort(listenAddr); err != nil {
 362                         // url "https://foo.example/" (with no
 363                         // explicit port name/number) means listen on
 364                         // the well-known port for the specified
 365                         // protocol, "foo.example:https".
 366                         port := listenURL.Scheme
 367                         if port == "ws" || port == "wss" {
 368                                 port = "http" + port[2:]
 369                         }
 370                         listenAddr = net.JoinHostPort(listenAddr, port)
 371                 }
 372                 listener, err := net.Listen("tcp", listenAddr)
 373                 if err == nil {
 374                         listener.Close()
 375                         return listenURL, internalURL, nil
 376                 } else if strings.Contains(err.Error(), "cannot assign requested address") {
 377                         // If 'Host' specifies a different server than
 378                         // the current one, it'll resolve the hostname
 379                         // to IP address, and then fail because it
 380                         // can't bind an IP address it doesn't own.
 381                         continue
 382                 } else {
 383                         errors = append(errors, fmt.Sprintf("%s: %s", listenURL, err))
 384                 }
 385         }
 386         if len(errors) > 0 {
 387                 return arvados.URL{}, arvados.URL{}, fmt.Errorf("could not enable the %q service on this host: %s", prog, strings.Join(errors, "; "))
 388         }
 389         return arvados.URL{}, arvados.URL{}, fmt.Errorf("configuration does not enable the %q service on this host", prog)
 390 }
 391
 392 type contextKeyURL struct{}
 393
 394 func URLFromContext(ctx context.Context) (arvados.URL, bool) {
 395         u, ok := ctx.Value(contextKeyURL{}).(arvados.URL)
 396         return u, ok
 397 }