Improvements to server logging (#2155)

- Add logging for new campaigns
- Add logging for new query creations/modification/deletion
- Add usernames for logs found in labels, options, packs, osquery options, queries and scheduled queries where something is created, modified or deleted

server/datastore/inmem/targets.go

@@ -0,0 +1,12 @@
+package inmem
+
+import (
+	"time"
+
+	"github.com/kolide/fleet/server/kolide"
+)
+
+func (d *Datastore) CountHostsInTargets(hostIDs, labelIDs []uint, now time.Time) (kolide.TargetMetrics, error) {
+	// noop
+	return kolide.TargetMetrics{}, nil
+}

server/kolide/campaigns.go

@@ -74,6 +74,7 @@ const (
 type DistributedQueryCampaign struct {
 	UpdateCreateTimestamps
 	DeleteFields
+	Metrics TargetMetrics
 	ID      uint                   `json:"id"`
 	QueryID uint                   `json:"query_id" db:"query_id"`
 	Status  DistributedQueryStatus `json:"status"`

server/mock/datastore.go

@@ -21,7 +21,7 @@ var _ kolide.Datastore = (*Store)(nil)
 type Store struct {
 	kolide.PasswordResetStore
 	kolide.YARAStore
-	kolide.TargetStore
+	TargetStore
 	SessionStore
 	CampaignStore
 	ScheduledQueryStore

server/mock/datastore_targets.go

@@ -0,0 +1,23 @@
+// Automatically generated by mockimpl. DO NOT EDIT!
+
+package mock
+
+import (
+	"time"
+
+	"github.com/kolide/fleet/server/kolide"
+)
+
+var _ kolide.TargetStore = (*TargetStore)(nil)
+
+type CountHostsInTargetsFunc func(hostIDs, labelIDs []uint, now time.Time) (kolide.TargetMetrics, error)
+
+type TargetStore struct {
+	CountHostsInTargetsFunc        CountHostsInTargetsFunc
+	CountHostsInTargetsFuncInvoked bool
+}
+
+func (s *TargetStore) CountHostsInTargets(hostIDs, labelIDs []uint, now time.Time) (kolide.TargetMetrics, error) {
+	s.CountHostsInTargetsFuncInvoked = true
+	return s.CountHostsInTargetsFunc(hostIDs, labelIDs, now)
+}

server/service/logging_campaigns.go

@@ -0,0 +1,78 @@
+package service
+
+import (
+	"context"
+	"time"
+
+	"github.com/kolide/fleet/server/contexts/viewer"
+	"github.com/kolide/fleet/server/kolide"
+	"github.com/kolide/fleet/server/websocket"
+)
+
+func (mw loggingMiddleware) NewDistributedQueryCampaign(ctx context.Context, queryString string, hosts []uint, labels []uint) (*kolide.DistributedQueryCampaign, error) {
+	var (
+		loggedInUser = "unauthenticated"
+		campaign     *kolide.DistributedQueryCampaign
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		_ = mw.logger.Log(
+			"method", "NewDistributedQueryCampaign",
+			"err", err,
+			"user", loggedInUser,
+			"sql", queryString,
+			"numHosts", campaign.Metrics.TotalHosts,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	campaign, err = mw.Service.NewDistributedQueryCampaign(ctx, queryString, hosts, labels)
+	return campaign, err
+}
+
+func (mw loggingMiddleware) NewDistributedQueryCampaignByNames(ctx context.Context, queryString string, hosts []string, labels []string) (*kolide.DistributedQueryCampaign, error) {
+	var (
+		loggedInUser = "unauthenticated"
+		campaign     *kolide.DistributedQueryCampaign
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		_ = mw.logger.Log(
+			"method", "NewDistributedQueryCampaignByNames",
+			"err", err,
+			"user", loggedInUser,
+			"numHosts", campaign.Metrics.TotalHosts,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	campaign, err = mw.Service.NewDistributedQueryCampaignByNames(ctx, queryString, hosts, labels)
+	return campaign, err
+}
+
+func (mw loggingMiddleware) StreamCampaignResults(ctx context.Context, conn *websocket.Conn, campaignID uint) {
+	var (
+		loggedInUser = "unauthenticated"
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		_ = mw.logger.Log(
+			"method", "StreamCampaignResults",
+			"campaignID", campaignID,
+			"err", err,
+			"user", loggedInUser,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	mw.Service.StreamCampaignResults(ctx, conn, campaignID)
+}

server/service/logging_labels.go

@@ -4,19 +4,27 @@ import (
 	"context"
 	"time"
 
+	"github.com/kolide/fleet/server/contexts/viewer"
 	"github.com/kolide/fleet/server/kolide"
 )
 
 func (mw loggingMiddleware) NewLabel(ctx context.Context, p kolide.LabelPayload) (*kolide.Label, error) {
 	var (
-		label *kolide.Label
-		err   error
+		label        *kolide.Label
+		err          error
+		loggedInUser = "unauthenticated"
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "NewLabel",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
@@ -27,14 +35,21 @@ func (mw loggingMiddleware) NewLabel(ctx context.Context, p kolide.LabelPayload)
 
 func (mw loggingMiddleware) ModifyLabel(ctx context.Context, id uint, p kolide.ModifyLabelPayload) (*kolide.Label, error) {
 	var (
-		label *kolide.Label
-		err   error
+		label        *kolide.Label
+		err          error
+		loggedInUser = "unauthenticated"
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		mw.logger.Log(
 			"method", "ModifyLabel",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
@@ -81,13 +96,20 @@ func (mw loggingMiddleware) GetLabel(ctx context.Context, id uint) (*kolide.Labe
 
 func (mw loggingMiddleware) DeleteLabel(ctx context.Context, name string) error {
 	var (
-		err error
+		err          error
+		loggedInUser = "unauthenticated"
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "DeleteLabel",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
@@ -121,10 +143,20 @@ func (mw loggingMiddleware) GetLabelSpecs(ctx context.Context) (specs []*kolide.
 }
 
 func (mw loggingMiddleware) ApplyLabelSpecs(ctx context.Context, specs []*kolide.LabelSpec) (err error) {
+	var (
+		loggedInUser = "unauthenticated"
+	)
+
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		mw.logger.Log(
 			"method", "ApplyLabelSpecs",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())

server/service/logging_options.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"time"
 
+	"github.com/kolide/fleet/server/contexts/viewer"
 	"github.com/kolide/fleet/server/kolide"
 )
 
@@ -26,14 +27,21 @@ func (mw loggingMiddleware) GetOptions(ctx context.Context) ([]kolide.Option, er
 
 func (mw loggingMiddleware) ModifyOptions(ctx context.Context, req kolide.OptionRequest) ([]kolide.Option, error) {
 	var (
-		options []kolide.Option
-		err     error
+		options      []kolide.Option
+		err          error
+		loggedInUser = "unauthenticated"
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		mw.logger.Log(
 			"method", "ModifyOptions",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())

server/service/logging_osquery_options.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"time"
 
+	"github.com/kolide/fleet/server/contexts/viewer"
 	"github.com/kolide/fleet/server/kolide"
 )
 
@@ -20,10 +21,19 @@ func (mw loggingMiddleware) GetOptionsSpec(ctx context.Context) (spec *kolide.Op
 }
 
 func (mw loggingMiddleware) ApplyOptionsSpec(ctx context.Context, spec *kolide.OptionsSpec) (err error) {
+	var (
+		loggedInUser = "unauthenticated"
+	)
+
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
 	defer func(begin time.Time) {
 		mw.logger.Log(
 			"method", "ApplyOptionsSpec",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())

server/service/logging_packs.go

@@ -4,19 +4,27 @@ import (
 	"context"
 	"time"
 
+	"github.com/kolide/fleet/server/contexts/viewer"
 	"github.com/kolide/fleet/server/kolide"
 )
 
 func (mw loggingMiddleware) NewPack(ctx context.Context, p kolide.PackPayload) (*kolide.Pack, error) {
 	var (
-		pack *kolide.Pack
-		err  error
+		pack         *kolide.Pack
+		loggedInUser = "unauthenticated"
+		err          error
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "NewPack",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
@@ -27,14 +35,21 @@ func (mw loggingMiddleware) NewPack(ctx context.Context, p kolide.PackPayload) (
 
 func (mw loggingMiddleware) ModifyPack(ctx context.Context, id uint, p kolide.PackPayload) (*kolide.Pack, error) {
 	var (
-		pack *kolide.Pack
-		err  error
+		pack         *kolide.Pack
+		loggedInUser = "unauthenticated"
+		err          error
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "ModifyPack",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
@@ -81,17 +96,23 @@ func (mw loggingMiddleware) GetPack(ctx context.Context, id uint) (*kolide.Pack,
 
 func (mw loggingMiddleware) DeletePack(ctx context.Context, name string) error {
 	var (
-		err error
+		loggedInUser = "unauthenticated"
+		err          error
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "DeletePack",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
-
 	err = mw.Service.DeletePack(ctx, name)
 	return err
 }
@@ -243,10 +264,20 @@ func (mw loggingMiddleware) GetPackSpecs(ctx context.Context) (specs []*kolide.P
 }
 
 func (mw loggingMiddleware) ApplyPackSpecs(ctx context.Context, specs []*kolide.PackSpec) (err error) {
+	var (
+		loggedInUser = "unauthenticated"
+	)
+
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
-		mw.logger.Log(
+		_ = mw.logger.Log(
 			"method", "ApplyPackSpecs",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())

server/service/logging_queries.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"time"
 
+	"github.com/kolide/fleet/server/contexts/viewer"
 	"github.com/kolide/fleet/server/kolide"
 )
 
@@ -42,3 +43,111 @@ func (mw loggingMiddleware) ApplyQuerySpecs(ctx context.Context, specs []*kolide
 	err = mw.Service.ApplyQuerySpecs(ctx, specs)
 	return err
 }
+
+func (mw loggingMiddleware) ListQueries(ctx context.Context, opt kolide.ListOptions) ([]*kolide.Query, error) {
+	var (
+		loggedInUser = "unauthenticated"
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "ListQueries",
+			"err", err,
+			"user", loggedInUser,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	query, err := mw.Service.ListQueries(ctx, opt)
+	return query, err
+}
+func (mw loggingMiddleware) GetQuery(ctx context.Context, id uint) (*kolide.Query, error) {
+	var (
+		loggedInUser = "unauthenticated"
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "GetQuery",
+			"err", err,
+			"user", loggedInUser,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	query, err := mw.Service.GetQuery(ctx, id)
+	return query, err
+}
+func (mw loggingMiddleware) NewQuery(ctx context.Context, p kolide.QueryPayload) (*kolide.Query, error) {
+	var (
+		query        *kolide.Query
+		loggedInUser = "unauthenticated"
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "NewQuery",
+			"err", err,
+			"user", loggedInUser,
+			"name", query.Name,
+			"sql", query.Query,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	query, err = mw.Service.NewQuery(ctx, p)
+	return query, err
+}
+func (mw loggingMiddleware) ModifyQuery(ctx context.Context, id uint, p kolide.QueryPayload) (*kolide.Query, error) {
+	var (
+		query        *kolide.Query
+		loggedInUser = "unauthenticated"
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "ModifyQuery",
+			"err", err,
+			"user", loggedInUser,
+			"name", query.Name,
+			"sql", query.Query,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	query, err = mw.Service.ModifyQuery(ctx, id, p)
+	return query, err
+}
+func (mw loggingMiddleware) DeleteQuery(ctx context.Context, name string) error {
+	var (
+		loggedInUser = "unauthenticated"
+		err          error
+	)
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "DeleteQuery",
+			"err", err,
+			"name", name,
+			"user", loggedInUser,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	err = mw.Service.DeleteQuery(ctx, name)
+	return err
+}

server/service/logging_scheduled_queries.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"time"
 
+	"github.com/kolide/fleet/server/contexts/viewer"
 	"github.com/kolide/fleet/server/kolide"
 )
 
@@ -43,16 +44,24 @@ func (mw loggingMiddleware) GetScheduledQuery(ctx context.Context, id uint) (*ko
 	return query, err
 }
 
+//these ones too
 func (mw loggingMiddleware) ScheduleQuery(ctx context.Context, sq *kolide.ScheduledQuery) (*kolide.ScheduledQuery, error) {
 	var (
-		query *kolide.ScheduledQuery
-		err   error
+		query        *kolide.ScheduledQuery
+		err          error
+		loggedInUser = "unauthenticated"
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "ScheduleQuery",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
@@ -63,13 +72,20 @@ func (mw loggingMiddleware) ScheduleQuery(ctx context.Context, sq *kolide.Schedu
 
 func (mw loggingMiddleware) DeleteScheduledQuery(ctx context.Context, id uint) error {
 	var (
-		err error
+		err          error
+		loggedInUser = "unauthenticated"
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "DeleteScheduledQuery",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())
@@ -80,14 +96,21 @@ func (mw loggingMiddleware) DeleteScheduledQuery(ctx context.Context, id uint) e
 
 func (mw loggingMiddleware) ModifyScheduledQuery(ctx context.Context, id uint, p kolide.ScheduledQueryPayload) (*kolide.ScheduledQuery, error) {
 	var (
-		query *kolide.ScheduledQuery
-		err   error
+		query        *kolide.ScheduledQuery
+		err          error
+		loggedInUser = "unauthenticated"
 	)
 
+	if vc, ok := viewer.FromContext(ctx); ok {
+
+		loggedInUser = vc.Username()
+	}
+
 	defer func(begin time.Time) {
 		_ = mw.logger.Log(
 			"method", "ModifyScheduledQuery",
 			"err", err,
+			"user", loggedInUser,
 			"took", time.Since(begin),
 		)
 	}(time.Now())

server/service/service_campaigns.go

@@ -77,7 +77,10 @@ func (svc service) NewDistributedQueryCampaign(ctx context.Context, queryString
 			return nil, errors.Wrap(err, "adding label target")
 		}
 	}
-
+	campaign.Metrics, err = svc.ds.CountHostsInTargets(hosts, labels, time.Now())
+	if err != nil {
+		return nil, errors.Wrap(err, "counting hosts")
+	}
 	return campaign, nil
 }
 

server/service/service_osquery_test.go

@@ -848,6 +848,9 @@ func TestNewDistributedQueryCampaign(t *testing.T) {
 		return target, nil
 	}
 
+	ds.CountHostsInTargetsFunc = func(hostIDs, labelIDs []uint, now time.Time) (kolide.TargetMetrics, error) {
+		return kolide.TargetMetrics{}, nil
+	}
 	viewerCtx := viewer.NewContext(context.Background(), viewer.Viewer{
 		User: &kolide.User{
 			ID: 0,
@@ -859,12 +862,12 @@ func TestNewDistributedQueryCampaign(t *testing.T) {
 	assert.Equal(t, gotQuery.ID, gotCampaign.QueryID)
 	assert.Equal(t, []*kolide.DistributedQueryCampaignTarget{
 		&kolide.DistributedQueryCampaignTarget{
-			Type:                       kolide.TargetHost,
+			Type: kolide.TargetHost,
 			DistributedQueryCampaignID: campaign.ID,
 			TargetID:                   2,
 		},
 		&kolide.DistributedQueryCampaignTarget{
-			Type:                       kolide.TargetLabel,
+			Type: kolide.TargetLabel,
 			DistributedQueryCampaignID: campaign.ID,
 			TargetID:                   1,
 		},