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