19388: Log user activity.
authorTom Clegg <tom@curii.com>
Fri, 23 Sep 2022 19:09:07 +0000 (15:09 -0400)
committerTom Clegg <tom@curii.com>
Fri, 23 Sep 2022 19:09:07 +0000 (15:09 -0400)
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom@curii.com>

lib/config/config.default.yml
lib/config/export.go
lib/controller/localdb/collection.go
lib/controller/localdb/conn.go
lib/controller/localdb/container_request.go
lib/controller/localdb/log_activity.go [new file with mode: 0644]
lib/controller/localdb/log_activity_test.go [new file with mode: 0644]
lib/ctrlctx/auth.go
lib/ctrlctx/db.go
sdk/go/arvados/client.go
sdk/go/arvados/config.go

index 444398bc3303d8ef3a1b50563933781649717b19..816d0f99e2f685285f79de86c3952e6b88a4352f 100644 (file)
@@ -373,6 +373,18 @@ Clusters:
       # cluster.
       RoleGroupsVisibleToAll: true
 
+      # During each period, a log entry with event_type="activity"
+      # will be recorded for each user who is active during that
+      # period. The object_uuid attribute will indicate the user's
+      # UUID.
+      #
+      # Multiple log entries for the same user may be generated during
+      # a period if there are multiple controller processes or a
+      # controller process is restarted.
+      #
+      # Use 0 to disable activity logging.
+      ActivityLoggingPeriod: 24h
+
     AuditLogs:
       # Time to keep audit logs, in seconds. (An audit log is a row added
       # to the "logs" table in the PostgreSQL database each time an
index a55295d1268b7cc0829ec2fe5073eb276c5b4564..fb17a45c84a82fe4568777065fe23684c49a4603 100644 (file)
@@ -226,6 +226,7 @@ var whitelist = map[string]bool{
        "TLS.Key":                                             false,
        "Users":                                               true,
        "Users.ActivatedUsersAreVisibleToOthers":              false,
+       "Users.ActivityLoggingPeriod":                         false,
        "Users.AdminNotifierEmailFrom":                        false,
        "Users.AnonymousUserToken":                            true,
        "Users.AutoAdminFirstUser":                            false,
index 868e466e9e281bf7f4f5eaf8b4f7a530956653cf..581595e5e3818a56b4194adc47834e87035a3ce8 100644 (file)
@@ -22,6 +22,7 @@ import (
 // CollectionGet defers to railsProxy for everything except blob
 // signatures.
 func (conn *Conn) CollectionGet(ctx context.Context, opts arvados.GetOptions) (arvados.Collection, error) {
+       conn.logActivity(ctx)
        if len(opts.Select) > 0 {
                // We need to know IsTrashed and TrashAt to implement
                // signing properly, even if the caller doesn't want
@@ -39,6 +40,7 @@ func (conn *Conn) CollectionGet(ctx context.Context, opts arvados.GetOptions) (a
 // CollectionList defers to railsProxy for everything except blob
 // signatures.
 func (conn *Conn) CollectionList(ctx context.Context, opts arvados.ListOptions) (arvados.CollectionList, error) {
+       conn.logActivity(ctx)
        if len(opts.Select) > 0 {
                // We need to know IsTrashed and TrashAt to implement
                // signing properly, even if the caller doesn't want
@@ -58,6 +60,7 @@ func (conn *Conn) CollectionList(ctx context.Context, opts arvados.ListOptions)
 // CollectionCreate defers to railsProxy for everything except blob
 // signatures and vocabulary checking.
 func (conn *Conn) CollectionCreate(ctx context.Context, opts arvados.CreateOptions) (arvados.Collection, error) {
+       conn.logActivity(ctx)
        err := conn.checkProperties(ctx, opts.Attrs["properties"])
        if err != nil {
                return arvados.Collection{}, err
@@ -82,6 +85,7 @@ func (conn *Conn) CollectionCreate(ctx context.Context, opts arvados.CreateOptio
 // CollectionUpdate defers to railsProxy for everything except blob
 // signatures and vocabulary checking.
 func (conn *Conn) CollectionUpdate(ctx context.Context, opts arvados.UpdateOptions) (arvados.Collection, error) {
+       conn.logActivity(ctx)
        err := conn.checkProperties(ctx, opts.Attrs["properties"])
        if err != nil {
                return arvados.Collection{}, err
index a36822ad6b1f5df1f73ffbc3536d76a7215f1817..0420cf6f2f24edf4814c95fefb59382ff4de3350 100644 (file)
@@ -33,8 +33,11 @@ type Conn struct {
        lastVocabularyRefreshCheck time.Time
        lastVocabularyError        error
        loginController
-       gwTunnels     map[string]*yamux.Session
-       gwTunnelsLock sync.Mutex
+       gwTunnels        map[string]*yamux.Session
+       gwTunnelsLock    sync.Mutex
+       activeUsers      map[string]bool
+       activeUsersLock  sync.Mutex
+       activeUsersReset time.Time
 }
 
 func NewConn(cluster *arvados.Cluster) *Conn {
index 5b2ce95da99c2c8195ce2ceac6aaa925a75d2e0f..49e21840ea206f69684738e2f9aec98f0f6c2fd3 100644 (file)
@@ -13,6 +13,7 @@ import (
 // ContainerRequestCreate defers to railsProxy for everything except
 // vocabulary checking.
 func (conn *Conn) ContainerRequestCreate(ctx context.Context, opts arvados.CreateOptions) (arvados.ContainerRequest, error) {
+       conn.logActivity(ctx)
        err := conn.checkProperties(ctx, opts.Attrs["properties"])
        if err != nil {
                return arvados.ContainerRequest{}, err
@@ -27,6 +28,7 @@ func (conn *Conn) ContainerRequestCreate(ctx context.Context, opts arvados.Creat
 // ContainerRequestUpdate defers to railsProxy for everything except
 // vocabulary checking.
 func (conn *Conn) ContainerRequestUpdate(ctx context.Context, opts arvados.UpdateOptions) (arvados.ContainerRequest, error) {
+       conn.logActivity(ctx)
        err := conn.checkProperties(ctx, opts.Attrs["properties"])
        if err != nil {
                return arvados.ContainerRequest{}, err
@@ -37,3 +39,18 @@ func (conn *Conn) ContainerRequestUpdate(ctx context.Context, opts arvados.Updat
        }
        return resp, nil
 }
+
+func (conn *Conn) ContainerRequestGet(ctx context.Context, opts arvados.GetOptions) (arvados.ContainerRequest, error) {
+       conn.logActivity(ctx)
+       return conn.railsProxy.ContainerRequestGet(ctx, opts)
+}
+
+func (conn *Conn) ContainerRequestList(ctx context.Context, opts arvados.ListOptions) (arvados.ContainerRequestList, error) {
+       conn.logActivity(ctx)
+       return conn.railsProxy.ContainerRequestList(ctx, opts)
+}
+
+func (conn *Conn) ContainerRequestDelete(ctx context.Context, opts arvados.DeleteOptions) (arvados.ContainerRequest, error) {
+       conn.logActivity(ctx)
+       return conn.railsProxy.ContainerRequestDelete(ctx, opts)
+}
diff --git a/lib/controller/localdb/log_activity.go b/lib/controller/localdb/log_activity.go
new file mode 100644 (file)
index 0000000..9c9660a
--- /dev/null
@@ -0,0 +1,117 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
+package localdb
+
+import (
+       "context"
+       "time"
+
+       "git.arvados.org/arvados.git/lib/ctrlctx"
+       "git.arvados.org/arvados.git/sdk/go/arvados"
+       "git.arvados.org/arvados.git/sdk/go/ctxlog"
+)
+
+func (conn *Conn) logActivity(ctx context.Context) {
+       p := conn.cluster.Users.ActivityLoggingPeriod.Duration()
+       if p < 1 {
+               ctxlog.FromContext(ctx).Debug("logActivity disabled by config")
+               return
+       }
+       user, _, err := ctrlctx.CurrentAuth(ctx)
+       if err == ctrlctx.ErrUnauthenticated {
+               ctxlog.FromContext(ctx).Debug("logActivity skipped for unauthenticated request")
+               return
+       } else if err != nil {
+               ctxlog.FromContext(ctx).WithError(err).Error("logActivity CurrentAuth failed")
+               return
+       }
+       now := time.Now()
+       conn.activeUsersLock.Lock()
+       if conn.activeUsers == nil || conn.activeUsersReset.IsZero() || conn.activeUsersReset.Before(now) {
+               conn.activeUsersReset = alignedPeriod(now, p)
+               conn.activeUsers = map[string]bool{}
+       }
+       logged := conn.activeUsers[user.UUID]
+       if !logged {
+               // Prevent other concurrent calls from logging about
+               // this user until we finish.
+               conn.activeUsers[user.UUID] = true
+       }
+       conn.activeUsersLock.Unlock()
+       if logged {
+               return
+       }
+       defer func() {
+               // If we return without logging, reset the flag so we
+               // try again on the user's next API call.
+               if !logged {
+                       conn.activeUsersLock.Lock()
+                       conn.activeUsers[user.UUID] = false
+                       conn.activeUsersLock.Unlock()
+               }
+       }()
+
+       tx, err := ctrlctx.NewTx(ctx)
+       if err != nil {
+               ctxlog.FromContext(ctx).WithError(err).Error("logActivity NewTx failed")
+               return
+       }
+       defer tx.Rollback()
+       _, err = tx.ExecContext(ctx, `
+insert into logs
+ (uuid,
+  owner_uuid, modified_by_user_uuid, object_owner_uuid,
+  event_type,
+  summary,
+  object_uuid,
+  properties,
+  event_at, created_at, updated_at, modified_at)
+ values
+ ($1, $2, $2, $2, $3, $4, $5, $6,
+  current_timestamp at time zone 'UTC',
+  current_timestamp at time zone 'UTC',
+  current_timestamp at time zone 'UTC',
+  current_timestamp at time zone 'UTC')
+ returning id`,
+               arvados.RandomUUID(conn.cluster.ClusterID, "57u5n"),
+               conn.cluster.ClusterID+"-tpzed-000000000000000", // both modified_by and object_owner
+               "activity",
+               "activity of "+user.UUID,
+               user.UUID,
+               "{}")
+       if err != nil {
+               ctxlog.FromContext(ctx).WithError(err).Error("logActivity query failed")
+               return
+       }
+       err = tx.Commit()
+       if err != nil {
+               ctxlog.FromContext(ctx).WithError(err).Error("logActivity commit failed")
+               return
+       }
+       logged = true
+}
+
+// alignedPeriod computes a time interval that includes now and aligns
+// to local clock times that are multiples of p. For example, if local
+// time is UTC-5 and ActivityLoggingPeriod=4h, periodStart and
+// periodEnd will be 0000-0400, 0400-0800, etc., in local time. If p
+// is a multiple of 24h, periods will start and end at midnight.
+//
+// If DST starts or ends during this period, the boundaries will be
+// aligned based on either DST or non-DST time depending on whether
+// now is before or after the DST transition. The consequences are
+// presumed to be inconsequential, e.g., logActivity may unnecessarily
+// log activity more than once in a period that includes a DST
+// transition.
+//
+// In all cases, the period ends in the future.
+//
+// Only the end of the period is returned.
+func alignedPeriod(now time.Time, p time.Duration) time.Time {
+       _, tzsec := now.Zone()
+       tzoff := time.Duration(tzsec) * time.Second
+       periodStart := now.Add(tzoff).Truncate(p).Add(-tzoff)
+       return periodStart.Add(p)
+}
diff --git a/lib/controller/localdb/log_activity_test.go b/lib/controller/localdb/log_activity_test.go
new file mode 100644 (file)
index 0000000..6a9bc45
--- /dev/null
@@ -0,0 +1,46 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
+package localdb
+
+import (
+       "time"
+
+       check "gopkg.in/check.v1"
+)
+
+var _ = check.Suite(&activityPeriodSuite{})
+
+type activityPeriodSuite struct{}
+
+// The important thing is that, even when daylight savings time is
+// making things difficult, the current period ends in the future.
+func (*activityPeriodSuite) TestPeriod(c *check.C) {
+       toronto, err := time.LoadLocation("America/Toronto")
+       c.Assert(err, check.IsNil)
+
+       format := "2006-01-02 15:04:05 MST"
+       dststartday, err := time.ParseInLocation(format, "2022-03-13 00:00:00 EST", toronto)
+       c.Assert(err, check.IsNil)
+       dstendday, err := time.ParseInLocation(format, "2022-11-06 00:00:00 EDT", toronto)
+       c.Assert(err, check.IsNil)
+
+       for _, period := range []time.Duration{
+               time.Minute * 13,
+               time.Minute * 49,
+               time.Hour,
+               4 * time.Hour,
+               48 * time.Hour,
+       } {
+               for offset := time.Duration(0); offset < 48*time.Hour; offset += 3 * time.Minute {
+                       t := dststartday.Add(offset)
+                       end := alignedPeriod(t, period)
+                       c.Check(end.After(t), check.Equals, true, check.Commentf("period %v offset %v", period, offset))
+
+                       t = dstendday.Add(offset)
+                       end = alignedPeriod(t, period)
+                       c.Check(end.After(t), check.Equals, true, check.Commentf("period %v offset %v", period, offset))
+               }
+       }
+}
index 61c6253d419472924d63d0e90f26da2c8f9e0fa9..f4c472f73f534c4910cb961c63ff0c01af586b26 100644 (file)
@@ -9,7 +9,6 @@ import (
        "crypto/hmac"
        "crypto/sha256"
        "database/sql"
-       "encoding/json"
        "errors"
        "fmt"
        "io"
@@ -20,6 +19,7 @@ import (
        "git.arvados.org/arvados.git/lib/controller/api"
        "git.arvados.org/arvados.git/sdk/go/arvados"
        "git.arvados.org/arvados.git/sdk/go/auth"
+       "github.com/ghodss/yaml"
 )
 
 var (
@@ -135,7 +135,7 @@ func (ac *authcache) lookup(ctx context.Context, cluster *arvados.Cluster, token
        var args []interface{}
        if len(token) > 30 && strings.HasPrefix(token, "v2/") && token[30] == '/' {
                fields := strings.Split(token, "/")
-               cond = `aca.uuid=$1 and aca.api_token=$2`
+               cond = `aca.uuid = $1 and aca.api_token = $2`
                args = []interface{}{fields[1], fields[2]}
        } else {
                // Bare token or OIDC access token
@@ -145,24 +145,26 @@ func (ac *authcache) lookup(ctx context.Context, cluster *arvados.Cluster, token
                cond = `aca.api_token in ($1, $2)`
                args = []interface{}{token, hmac}
        }
-       var scopesJSON []byte
+       var expiresAt sql.NullTime
+       var scopesYAML []byte
        err = tx.QueryRowContext(ctx, `
 select aca.uuid, aca.expires_at, aca.api_token, aca.scopes, users.uuid, users.is_active, users.is_admin
  from api_client_authorizations aca
  left join users on aca.user_id = users.id
  where `+cond+`
  and (expires_at is null or expires_at > current_timestamp at time zone 'UTC')`, args...).Scan(
-               &aca.UUID, &aca.ExpiresAt, &aca.APIToken, &scopesJSON,
+               &aca.UUID, &expiresAt, &aca.APIToken, &scopesYAML,
                &user.UUID, &user.IsActive, &user.IsAdmin)
        if err == sql.ErrNoRows {
                return nil, nil, nil
        } else if err != nil {
                return nil, nil, err
        }
-       if len(scopesJSON) > 0 {
-               err = json.Unmarshal(scopesJSON, &aca.Scopes)
+       aca.ExpiresAt = expiresAt.Time
+       if len(scopesYAML) > 0 {
+               err = yaml.Unmarshal(scopesYAML, &aca.Scopes)
                if err != nil {
-                       return nil, nil, err
+                       return nil, nil, fmt.Errorf("loading scopes for %s: %w", aca.UUID, err)
                }
        }
        ent = &authcacheent{
index 36d79d3d2ef89ac9819d12e3f4e2f175c96426bd..a76420860604b9a6fb9823bdc6b3775c70f85ff4 100644 (file)
@@ -12,6 +12,7 @@ import (
        "git.arvados.org/arvados.git/lib/controller/api"
        "git.arvados.org/arvados.git/sdk/go/ctxlog"
        "github.com/jmoiron/sqlx"
+
        // sqlx needs lib/pq to talk to PostgreSQL
        _ "github.com/lib/pq"
 )
@@ -107,6 +108,26 @@ func New(ctx context.Context, getdb func(context.Context) (*sqlx.DB, error)) (co
        }
 }
 
+// NewTx starts a new transaction. The caller is responsible for
+// calling Commit or Rollback. This is suitable for database queries
+// that are separate from the API transaction (see CurrentTx), e.g.,
+// ones that will be committed even if the API call fails, or held
+// open after the API call finishes.
+func NewTx(ctx context.Context) (*sqlx.Tx, error) {
+       txn, ok := ctx.Value(contextKeyTransaction).(*transaction)
+       if !ok {
+               return nil, ErrNoTransaction
+       }
+       db, err := txn.getdb(ctx)
+       if err != nil {
+               return nil, err
+       }
+       return db.Beginx()
+}
+
+// CurrentTx returns a transaction that will be committed after the
+// current API call completes, or rolled back if the current API call
+// returns an error.
 func CurrentTx(ctx context.Context) (*sqlx.Tx, error) {
        txn, ok := ctx.Value(contextKeyTransaction).(*transaction)
        if !ok {
index cdc07bb0afd2c80b09985ad28f18c6c0fa1abcde..4dead0ada9143231a1b34c1700174279e64cfe83 100644 (file)
@@ -7,6 +7,7 @@ package arvados
 import (
        "bytes"
        "context"
+       "crypto/rand"
        "crypto/tls"
        "encoding/json"
        "errors"
@@ -15,6 +16,7 @@ import (
        "io/fs"
        "io/ioutil"
        "log"
+       "math/big"
        "net"
        "net/http"
        "net/url"
@@ -599,3 +601,13 @@ func (c *Client) PathForUUID(method, uuid string) (string, error) {
        }
        return path, nil
 }
+
+var maxUUIDInt = (&big.Int{}).Exp(big.NewInt(36), big.NewInt(15), nil)
+
+func RandomUUID(clusterID, infix string) string {
+       n, err := rand.Int(rand.Reader, maxUUIDInt)
+       if err != nil {
+               panic(err)
+       }
+       return clusterID + "-" + infix + "-" + n.Text(36)
+}
index eb564cb6102f2f16249bd37e8ac0ecbfe5bf579c..a1fc2e89f44331f005e2b28609a32dffe7c5480a 100644 (file)
@@ -248,6 +248,7 @@ type Cluster struct {
                PreferDomainForUsername               string
                UserSetupMailText                     string
                RoleGroupsVisibleToAll                bool
+               ActivityLoggingPeriod                 Duration
        }
        StorageClasses map[string]StorageClassConfig
        Volumes        map[string]Volume