mirror of
https://github.com/coder/coder.git
synced 2026-09-24 15:04:27 +08:00
feat: add telemetry for task lifecycle events (#21922)
Relates to https://github.com/coder/internal/issues/1259 Adds new database queries and telemetry collection functions to gather task lifecycle events (pause/resume cycles, idle time) for analytics. Task events track pause/resume activity, idle duration before pausing, paused duration, and time from resume to first app status, filtered to recent activity based on the telemetry snapshot interval. 🤖 Created with Mux (Opus 4.6).
This commit is contained in:
Cian Johnston
+163
-25
@@ -416,9 +416,10 @@ func checkIDPOrgSync(ctx context.Context, db database.Store, values *codersdk.De
|
||||
func (r *remoteReporter) createSnapshot() (*Snapshot, error) {
|
||||
var (
|
||||
ctx = r.ctx
|
||||
now = r.options.Clock.Now()
|
||||
// For resources that grow in size very quickly (like workspace builds),
|
||||
// we only report events that occurred within the past hour.
|
||||
createdAfter = dbtime.Time(r.options.Clock.Now().Add(-1 * time.Hour)).UTC()
|
||||
createdAfter = dbtime.Time(now.Add(-1 * time.Hour)).UTC()
|
||||
eg errgroup.Group
|
||||
snapshot = &Snapshot{
|
||||
DeploymentID: r.options.DeploymentID,
|
||||
@@ -740,17 +741,19 @@ func (r *remoteReporter) createSnapshot() (*Snapshot, error) {
|
||||
return nil
|
||||
})
|
||||
eg.Go(func() error {
|
||||
dbTasks, err := r.options.Database.ListTasks(ctx, database.ListTasksParams{
|
||||
OwnerID: uuid.Nil,
|
||||
OrganizationID: uuid.Nil,
|
||||
Status: "",
|
||||
})
|
||||
tasks, err := CollectTasks(ctx, r.options.Database)
|
||||
if err != nil {
|
||||
return err
|
||||
return xerrors.Errorf("collect tasks telemetry: %w", err)
|
||||
}
|
||||
for _, dbTask := range dbTasks {
|
||||
snapshot.Tasks = append(snapshot.Tasks, ConvertTask(dbTask))
|
||||
snapshot.Tasks = tasks
|
||||
return nil
|
||||
})
|
||||
eg.Go(func() error {
|
||||
events, err := CollectTaskEvents(ctx, r.options.Database, createdAfter, now)
|
||||
if err != nil {
|
||||
return xerrors.Errorf("collect task events telemetry: %w", err)
|
||||
}
|
||||
snapshot.TaskEvents = events
|
||||
return nil
|
||||
})
|
||||
eg.Go(func() error {
|
||||
@@ -902,6 +905,129 @@ func (r *remoteReporter) collectBoundaryUsageSummary(ctx context.Context) (*Boun
|
||||
}, nil
|
||||
}
|
||||
|
||||
func CollectTasks(ctx context.Context, db database.Store) ([]Task, error) {
|
||||
dbTasks, err := db.ListTasks(ctx, database.ListTasksParams{
|
||||
OwnerID: uuid.Nil,
|
||||
OrganizationID: uuid.Nil,
|
||||
Status: "",
|
||||
})
|
||||
if err != nil {
|
||||
return nil, xerrors.Errorf("list tasks: %w", err)
|
||||
}
|
||||
if len(dbTasks) == 0 {
|
||||
return []Task{}, nil
|
||||
}
|
||||
|
||||
tasks := make([]Task, 0, len(dbTasks))
|
||||
for _, dbTask := range dbTasks {
|
||||
tasks = append(tasks, ConvertTask(dbTask))
|
||||
}
|
||||
return tasks, nil
|
||||
}
|
||||
|
||||
// buildTaskEvent constructs a TaskEvent from the combined query row.
|
||||
func buildTaskEvent(
|
||||
row database.GetTelemetryTaskEventsRow,
|
||||
createdAfter time.Time,
|
||||
now time.Time,
|
||||
) TaskEvent {
|
||||
event := TaskEvent{
|
||||
TaskID: row.TaskID.String(),
|
||||
}
|
||||
|
||||
var (
|
||||
hasStartBuild = row.StartBuildCreatedAt.Valid
|
||||
isResumed = hasStartBuild && row.StartBuildNumber.Valid && row.StartBuildNumber.Int32 > 1
|
||||
hasStopBuild = row.StopBuildCreatedAt.Valid
|
||||
startedAfterStop = hasStartBuild && hasStopBuild && row.StartBuildCreatedAt.Time.After(row.StopBuildCreatedAt.Time)
|
||||
currentlyPaused = hasStopBuild && !startedAfterStop
|
||||
)
|
||||
|
||||
// Pause-related fields (requires a stop build).
|
||||
if hasStopBuild {
|
||||
event.LastPausedAt = &row.StopBuildCreatedAt.Time
|
||||
switch {
|
||||
case row.StopBuildReason.Valid && row.StopBuildReason.BuildReason == database.BuildReasonTaskAutoPause:
|
||||
event.PauseReason = ptr.Ref("auto")
|
||||
case row.StopBuildReason.Valid && row.StopBuildReason.BuildReason == database.BuildReasonTaskManualPause:
|
||||
event.PauseReason = ptr.Ref("manual")
|
||||
default:
|
||||
event.PauseReason = ptr.Ref("other")
|
||||
}
|
||||
|
||||
// Idle duration: time between last working status and the pause.
|
||||
if row.LastWorkingStatusAt.Valid &&
|
||||
row.StopBuildCreatedAt.Time.After(row.LastWorkingStatusAt.Time) {
|
||||
idle := row.StopBuildCreatedAt.Time.Sub(row.LastWorkingStatusAt.Time)
|
||||
event.IdleDurationMS = ptr.Ref(idle.Milliseconds())
|
||||
}
|
||||
}
|
||||
|
||||
// Resume-related fields (requires task_resume start after stop).
|
||||
if startedAfterStop {
|
||||
// Paused duration: time between pause and resume.
|
||||
if row.StartBuildCreatedAt.Time.After(createdAfter) {
|
||||
paused := row.StartBuildCreatedAt.Time.Sub(row.StopBuildCreatedAt.Time)
|
||||
event.PausedDurationMS = ptr.Ref(paused.Milliseconds())
|
||||
}
|
||||
|
||||
// Below only relevant for "resumed" tasks, not when initially created.
|
||||
if isResumed {
|
||||
event.LastResumedAt = &row.StartBuildCreatedAt.Time
|
||||
switch {
|
||||
// TODO(Cian): will this exist? Future readers may know better than I.
|
||||
// case row.StartBuildReason == database.BuildReasonTaskAutoResume:
|
||||
// event.ResumeReason = ptr.Ref("auto")
|
||||
case row.StartBuildReason.BuildReason == database.BuildReasonTaskResume:
|
||||
event.ResumeReason = ptr.Ref("manual")
|
||||
default: // Task resumed by starting workspace?
|
||||
event.ResumeReason = ptr.Ref("other")
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// Unresolved pause: report current paused duration.
|
||||
if currentlyPaused {
|
||||
paused := now.Sub(row.StopBuildCreatedAt.Time)
|
||||
event.PausedDurationMS = ptr.Ref(paused.Milliseconds())
|
||||
}
|
||||
|
||||
// Resume-to-status duration.
|
||||
if row.FirstStatusAfterResumeAt.Valid && isResumed {
|
||||
delta := row.FirstStatusAfterResumeAt.Time.Sub(row.StartBuildCreatedAt.Time)
|
||||
event.ResumeToStatusMS = ptr.Ref(delta.Milliseconds())
|
||||
}
|
||||
|
||||
// Active duration: from SQL calculation.
|
||||
if row.ActiveDurationMs > 0 {
|
||||
event.ActiveDurationMS = ptr.Ref(row.ActiveDurationMs)
|
||||
}
|
||||
|
||||
return event
|
||||
}
|
||||
|
||||
// CollectTaskEvents collects lifecycle events for tasks with recent activity.
|
||||
func CollectTaskEvents(ctx context.Context, db database.Store, createdAfter, now time.Time) ([]TaskEvent, error) {
|
||||
rows, err := db.GetTelemetryTaskEvents(ctx, database.GetTelemetryTaskEventsParams{
|
||||
CreatedAfter: createdAfter,
|
||||
Now: now,
|
||||
})
|
||||
if err != nil {
|
||||
return nil, xerrors.Errorf("get telemetry task events: %w", err)
|
||||
}
|
||||
events := make([]TaskEvent, 0, len(rows))
|
||||
for _, row := range rows {
|
||||
events = append(events, buildTaskEvent(row, createdAfter, now))
|
||||
}
|
||||
return events, nil
|
||||
}
|
||||
|
||||
// HashContent returns a SHA256 hash of the content as a hex string.
|
||||
// This is useful for hashing sensitive content like prompts for telemetry.
|
||||
func HashContent(content string) string {
|
||||
return fmt.Sprintf("%x", sha256.Sum256([]byte(content)))
|
||||
}
|
||||
|
||||
// ConvertAPIKey anonymizes an API key.
|
||||
func ConvertAPIKey(apiKey database.APIKey) APIKey {
|
||||
a := APIKey{
|
||||
@@ -1370,6 +1496,7 @@ type Snapshot struct {
|
||||
NetworkEvents []NetworkEvent `json:"network_events"`
|
||||
Organizations []Organization `json:"organizations"`
|
||||
Tasks []Task `json:"tasks"`
|
||||
TaskEvents []TaskEvent `json:"task_events"`
|
||||
TelemetryItems []TelemetryItem `json:"telemetry_items"`
|
||||
UserTailnetConnections []UserTailnetConnection `json:"user_tailnet_connections"`
|
||||
PrebuiltWorkspaces []PrebuiltWorkspace `json:"prebuilt_workspaces"`
|
||||
@@ -1931,25 +2058,36 @@ type Task struct {
|
||||
WorkspaceAppID *string `json:"workspace_app_id"`
|
||||
TemplateVersionID string `json:"template_version_id"`
|
||||
PromptHash string `json:"prompt_hash"` // Prompt is hashed for privacy.
|
||||
CreatedAt time.Time `json:"created_at"`
|
||||
Status string `json:"status"`
|
||||
CreatedAt time.Time `json:"created_at"`
|
||||
}
|
||||
|
||||
// ConvertTask anonymizes a Task.
|
||||
// TaskEvent represents lifecycle events for a task (pause/resume
|
||||
// cycles). The createdAfter parameter gates PausedDurationMS so
|
||||
// that only recent pause/resume pairs are reported.
|
||||
type TaskEvent struct {
|
||||
TaskID string `json:"task_id"`
|
||||
LastPausedAt *time.Time `json:"last_paused_at"`
|
||||
LastResumedAt *time.Time `json:"last_resumed_at"`
|
||||
PauseReason *string `json:"pause_reason"`
|
||||
ResumeReason *string `json:"resume_reason"`
|
||||
IdleDurationMS *int64 `json:"idle_duration_ms"`
|
||||
PausedDurationMS *int64 `json:"paused_duration_ms"`
|
||||
ResumeToStatusMS *int64 `json:"resume_to_status_ms"`
|
||||
ActiveDurationMS *int64 `json:"active_duration_ms"`
|
||||
}
|
||||
|
||||
// ConvertTask converts a database Task to a telemetry Task.
|
||||
func ConvertTask(task database.Task) Task {
|
||||
t := &Task{
|
||||
ID: task.ID.String(),
|
||||
OrganizationID: task.OrganizationID.String(),
|
||||
OwnerID: task.OwnerID.String(),
|
||||
Name: task.Name,
|
||||
WorkspaceID: nil,
|
||||
WorkspaceBuildNumber: nil,
|
||||
WorkspaceAgentID: nil,
|
||||
WorkspaceAppID: nil,
|
||||
TemplateVersionID: task.TemplateVersionID.String(),
|
||||
PromptHash: fmt.Sprintf("%x", sha256.Sum256([]byte(task.Prompt))),
|
||||
CreatedAt: task.CreatedAt,
|
||||
Status: string(task.Status),
|
||||
t := Task{
|
||||
ID: task.ID.String(),
|
||||
OrganizationID: task.OrganizationID.String(),
|
||||
OwnerID: task.OwnerID.String(),
|
||||
Name: task.Name,
|
||||
TemplateVersionID: task.TemplateVersionID.String(),
|
||||
PromptHash: HashContent(task.Prompt),
|
||||
Status: string(task.Status),
|
||||
CreatedAt: task.CreatedAt,
|
||||
}
|
||||
if task.WorkspaceID.Valid {
|
||||
t.WorkspaceID = ptr.Ref(task.WorkspaceID.UUID.String())
|
||||
@@ -1963,7 +2101,7 @@ func ConvertTask(task database.Task) Task {
|
||||
if task.WorkspaceAppID.Valid {
|
||||
t.WorkspaceAppID = ptr.Ref(task.WorkspaceAppID.UUID.String())
|
||||
}
|
||||
return *t
|
||||
return t
|
||||
}
|
||||
|
||||
type telemetryItemKey string
|
||||
|
||||
@@ -4,6 +4,7 @@ import (
|
||||
"context"
|
||||
"database/sql"
|
||||
"encoding/json"
|
||||
"fmt"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"net/url"
|
||||
@@ -13,6 +14,7 @@ import (
|
||||
"time"
|
||||
|
||||
"github.com/go-chi/chi/v5"
|
||||
"github.com/google/go-cmp/cmp"
|
||||
"github.com/google/uuid"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
@@ -21,12 +23,14 @@ import (
|
||||
"github.com/coder/coder/v2/buildinfo"
|
||||
"github.com/coder/coder/v2/coderd/boundaryusage"
|
||||
"github.com/coder/coder/v2/coderd/database"
|
||||
"github.com/coder/coder/v2/coderd/database/dbfake"
|
||||
"github.com/coder/coder/v2/coderd/database/dbgen"
|
||||
"github.com/coder/coder/v2/coderd/database/dbtestutil"
|
||||
"github.com/coder/coder/v2/coderd/database/dbtime"
|
||||
"github.com/coder/coder/v2/coderd/idpsync"
|
||||
"github.com/coder/coder/v2/coderd/runtimeconfig"
|
||||
"github.com/coder/coder/v2/coderd/telemetry"
|
||||
"github.com/coder/coder/v2/coderd/util/ptr"
|
||||
"github.com/coder/coder/v2/codersdk"
|
||||
"github.com/coder/coder/v2/testutil"
|
||||
"github.com/coder/quartz"
|
||||
@@ -313,6 +317,17 @@ func TestTelemetry(t *testing.T) {
|
||||
require.Equal(t, string(database.WorkspaceAgentSubsystemEnvbox), wsa.Subsystems[0])
|
||||
require.Equal(t, string(database.WorkspaceAgentSubsystemExectrace), wsa.Subsystems[1])
|
||||
require.Len(t, snapshot.Tasks, 1)
|
||||
require.Len(t, snapshot.TaskEvents, 1)
|
||||
taskEvent := snapshot.TaskEvents[0]
|
||||
assert.Equal(t, task.ID.String(), taskEvent.TaskID)
|
||||
assert.Nil(t, taskEvent.LastResumedAt)
|
||||
assert.Nil(t, taskEvent.LastPausedAt)
|
||||
assert.Nil(t, taskEvent.PauseReason)
|
||||
assert.Nil(t, taskEvent.ResumeReason)
|
||||
assert.Nil(t, taskEvent.IdleDurationMS)
|
||||
assert.Nil(t, taskEvent.PausedDurationMS)
|
||||
assert.Nil(t, taskEvent.ResumeToStatusMS)
|
||||
assert.Nil(t, taskEvent.ActiveDurationMS)
|
||||
for _, snapTask := range snapshot.Tasks {
|
||||
assert.Equal(t, task.ID.String(), snapTask.ID)
|
||||
assert.Equal(t, task.OrganizationID.String(), snapTask.OrganizationID)
|
||||
@@ -326,6 +341,7 @@ func TestTelemetry(t *testing.T) {
|
||||
assert.Equal(t, taskWA.WorkspaceAppID.UUID.String(), *snapTask.WorkspaceAppID)
|
||||
assert.Equal(t, task.TemplateVersionID.String(), snapTask.TemplateVersionID)
|
||||
assert.Equal(t, "e196fe22e61cfa32d8c38749e0ce348108bb4cae29e2c36cdcce7e77faa9eb5f", snapTask.PromptHash)
|
||||
assert.Equal(t, string(task.Status), snapTask.Status)
|
||||
assert.Equal(t, task.CreatedAt.UTC(), snapTask.CreatedAt.UTC())
|
||||
}
|
||||
|
||||
@@ -675,6 +691,573 @@ func TestPrebuiltWorkspacesTelemetry(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// taskTelemetryHelper is a grab bag of stuff useful in task telemetry test cases
|
||||
type taskTelemetryHelper struct {
|
||||
t *testing.T
|
||||
ctx context.Context
|
||||
db database.Store
|
||||
org database.Organization
|
||||
user database.User
|
||||
}
|
||||
|
||||
// createBuild creates a workspace build with the given parameters,
|
||||
// handling provisioner job creation automatically.
|
||||
func (h *taskTelemetryHelper) createBuild(
|
||||
resp dbfake.WorkspaceResponse,
|
||||
buildNumber int32,
|
||||
createdAt time.Time,
|
||||
transition database.WorkspaceTransition,
|
||||
reason database.BuildReason,
|
||||
) (database.WorkspaceBuild, *database.WorkspaceApp) {
|
||||
job := dbgen.ProvisionerJob(h.t, h.db, nil, database.ProvisionerJob{
|
||||
Provisioner: database.ProvisionerTypeTerraform,
|
||||
StorageMethod: database.ProvisionerStorageMethodFile,
|
||||
Type: database.ProvisionerJobTypeWorkspaceBuild,
|
||||
OrganizationID: h.org.ID,
|
||||
})
|
||||
bld := dbgen.WorkspaceBuild(h.t, h.db, database.WorkspaceBuild{
|
||||
WorkspaceID: resp.Workspace.ID,
|
||||
TemplateVersionID: resp.TemplateVersion.ID,
|
||||
JobID: job.ID,
|
||||
Transition: transition,
|
||||
Reason: reason,
|
||||
BuildNumber: buildNumber,
|
||||
CreatedAt: createdAt,
|
||||
HasAITask: sql.NullBool{
|
||||
Bool: true,
|
||||
Valid: true,
|
||||
},
|
||||
})
|
||||
if transition == database.WorkspaceTransitionStart {
|
||||
require.NotEmpty(h.t, resp.Agents, "need at least one agent")
|
||||
agt := resp.Agents[0]
|
||||
// App IDs are regenerated by provisionerd each build.
|
||||
app := dbgen.WorkspaceApp(h.t, h.db, database.WorkspaceApp{
|
||||
AgentID: agt.ID,
|
||||
})
|
||||
_, err := h.db.UpsertTaskWorkspaceApp(h.ctx, database.UpsertTaskWorkspaceAppParams{
|
||||
TaskID: resp.Task.ID,
|
||||
WorkspaceBuildNumber: buildNumber,
|
||||
WorkspaceAgentID: uuid.NullUUID{UUID: agt.ID, Valid: true},
|
||||
WorkspaceAppID: uuid.NullUUID{UUID: app.ID, Valid: true},
|
||||
})
|
||||
require.NoError(h.t, err, "failed to upsert task app")
|
||||
return bld, &app
|
||||
}
|
||||
return bld, nil
|
||||
}
|
||||
|
||||
// nolint: dupl // Test code is better WET than DRY.
|
||||
func TestTasksTelemetry(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
// Define a fixed reference time for deterministic testing.
|
||||
now := time.Date(2025, 1, 15, 12, 0, 0, 0, time.UTC)
|
||||
|
||||
createAppStatus := func(ctx context.Context, db database.Store, wsID uuid.UUID, agentID, appID uuid.UUID, state database.WorkspaceAppStatusState, message string, createdAt time.Time) {
|
||||
_, err := db.InsertWorkspaceAppStatus(ctx, database.InsertWorkspaceAppStatusParams{
|
||||
ID: uuid.New(),
|
||||
CreatedAt: createdAt,
|
||||
WorkspaceID: wsID,
|
||||
AgentID: agentID,
|
||||
AppID: appID,
|
||||
State: state,
|
||||
Message: message,
|
||||
})
|
||||
require.NoError(t, err)
|
||||
}
|
||||
|
||||
getApp := func(ctx context.Context, db database.Store, agentID uuid.UUID) database.WorkspaceApp {
|
||||
apps, err := db.GetWorkspaceAppsByAgentID(ctx, agentID)
|
||||
require.NoError(t, err)
|
||||
require.NotEmpty(t, apps, "expected at least one app")
|
||||
return apps[0]
|
||||
}
|
||||
|
||||
type statusSpec struct {
|
||||
state database.WorkspaceAppStatusState
|
||||
message string
|
||||
offset time.Duration
|
||||
}
|
||||
|
||||
type buildSpec struct {
|
||||
buildNumber int32
|
||||
offset time.Duration
|
||||
transition database.WorkspaceTransition
|
||||
reason database.BuildReason
|
||||
statuses []statusSpec // created after this build, using this build's app
|
||||
}
|
||||
|
||||
tests := []struct {
|
||||
name string
|
||||
|
||||
// Input: DB setup.
|
||||
skipWorkspace bool
|
||||
createdOffset time.Duration
|
||||
buildOffset *time.Duration
|
||||
extraBuilds []buildSpec
|
||||
appStatuses []statusSpec
|
||||
|
||||
// Expected output.
|
||||
expectEvent bool
|
||||
lastPausedOffset *time.Duration
|
||||
lastResumedOffset *time.Duration
|
||||
pauseReason *string
|
||||
resumeReason *string
|
||||
idleDurationMS *int64
|
||||
pausedDurationMS *int64
|
||||
resumeToStatusMS *int64
|
||||
activeDurationMS *int64
|
||||
}{
|
||||
{
|
||||
name: "no workspace - all lifecycle fields nil",
|
||||
skipWorkspace: true,
|
||||
createdOffset: -1 * time.Hour,
|
||||
},
|
||||
{
|
||||
name: "running workspace - no pause/resume events",
|
||||
createdOffset: -45 * time.Minute,
|
||||
buildOffset: ptr.Ref(-30 * time.Minute),
|
||||
expectEvent: true,
|
||||
},
|
||||
{
|
||||
name: "with app status - no lifecycle events",
|
||||
createdOffset: -90 * time.Minute,
|
||||
buildOffset: ptr.Ref(-45 * time.Minute),
|
||||
appStatuses: []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "Task started", -40 * time.Minute},
|
||||
},
|
||||
expectEvent: true,
|
||||
// ResumeToStatusMS is nil because initial start (BuildReasonInitiator)
|
||||
// doesn't count - only task_resume starts are considered.
|
||||
activeDurationMS: ptr.Ref(int64(40 * time.Minute / time.Millisecond)),
|
||||
},
|
||||
{
|
||||
name: "auto paused - LastPausedAt and PauseReason=auto",
|
||||
createdOffset: -3 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -20 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-20 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
pausedDurationMS: ptr.Ref(20 * time.Minute.Milliseconds()), // Ongoing pause.
|
||||
},
|
||||
{
|
||||
name: "manual paused - LastPausedAt and PauseReason=manual",
|
||||
createdOffset: -4 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -15 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskManualPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-15 * time.Minute),
|
||||
pauseReason: ptr.Ref("manual"),
|
||||
pausedDurationMS: ptr.Ref(15 * time.Minute.Milliseconds()), // Ongoing pause.
|
||||
},
|
||||
{
|
||||
name: "paused with idle time - IdleDurationMS calculated",
|
||||
createdOffset: -5 * time.Hour,
|
||||
appStatuses: []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "Working on something", -40 * time.Minute},
|
||||
{database.WorkspaceAppStatusStateIdle, "Idle now", -35 * time.Minute},
|
||||
},
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -25 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-25 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
idleDurationMS: ptr.Ref(15 * time.Minute.Milliseconds()), // Last working (-40) to stop (-25).
|
||||
activeDurationMS: ptr.Ref(5 * time.Minute.Milliseconds()), // -40 min (working) to -35 min (idle).
|
||||
pausedDurationMS: ptr.Ref(25 * time.Minute.Milliseconds()), // Ongoing pause: now - (-25min).
|
||||
},
|
||||
{
|
||||
name: "paused with working status after pause - IdleDurationMS nil",
|
||||
createdOffset: -5 * time.Hour,
|
||||
appStatuses: []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "Working after pause", -20 * time.Minute},
|
||||
},
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -25 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-25 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
pausedDurationMS: ptr.Ref(25 * time.Minute.Milliseconds()), // Ongoing pause.
|
||||
// IdleDurationMS is nil because "last working" is after pause.
|
||||
// ActiveDurationMS is nil because working→stop interval is negative.
|
||||
},
|
||||
{
|
||||
name: "recently resumed - PausedDurationMS calculated",
|
||||
createdOffset: -6 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -50 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
{3, -10 * time.Minute, database.WorkspaceTransitionStart, database.BuildReasonTaskResume, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-50 * time.Minute),
|
||||
lastResumedOffset: ptr.Ref(-10 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
resumeReason: ptr.Ref("manual"),
|
||||
pausedDurationMS: ptr.Ref(40 * time.Minute.Milliseconds()),
|
||||
},
|
||||
{
|
||||
// This test verifies that we do not double-report task events outside of the window.
|
||||
name: "resumed long ago - PausedDurationMS nil",
|
||||
createdOffset: -10 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -5 * time.Hour, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
{3, -2 * time.Hour, database.WorkspaceTransitionStart, database.BuildReasonTaskResume, nil},
|
||||
},
|
||||
expectEvent: false,
|
||||
},
|
||||
{
|
||||
name: "multiple cycles - captures latest pause/resume",
|
||||
createdOffset: -8 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -3 * time.Hour, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
{3, -150 * time.Minute, database.WorkspaceTransitionStart, database.BuildReasonTaskResume, nil},
|
||||
{4, -30 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskManualPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-30 * time.Minute),
|
||||
pauseReason: ptr.Ref("manual"),
|
||||
pausedDurationMS: ptr.Ref(30 * time.Minute.Milliseconds()), // Ongoing pause: now - (-30min).
|
||||
},
|
||||
{
|
||||
name: "currently paused after recent resume - reports ongoing pause",
|
||||
createdOffset: -6 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -50 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
{3, -30 * time.Minute, database.WorkspaceTransitionStart, database.BuildReasonTaskResume, nil},
|
||||
{4, -10 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskManualPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-10 * time.Minute),
|
||||
pauseReason: ptr.Ref("manual"),
|
||||
pausedDurationMS: ptr.Ref(10 * time.Minute.Milliseconds()), // Ongoing pause: now - pause time.
|
||||
},
|
||||
{
|
||||
name: "multiple cycles with recent resume - pairs with preceding pause",
|
||||
createdOffset: -6 * time.Hour,
|
||||
appStatuses: []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "started work", -6 * time.Hour},
|
||||
},
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -50 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
{3, -30 * time.Minute, database.WorkspaceTransitionStart, database.BuildReasonTaskResume, []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "resumed work", -25 * time.Minute},
|
||||
}},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-50 * time.Minute),
|
||||
lastResumedOffset: ptr.Ref(-30 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
resumeReason: ptr.Ref("manual"),
|
||||
pausedDurationMS: ptr.Ref(20 * time.Minute.Milliseconds()),
|
||||
resumeToStatusMS: ptr.Ref((5 * time.Minute).Milliseconds()),
|
||||
// Build 1 ("started work") -> Build 2 (stop) (5h10m) + Build 3 ("resumed work") -> now (25m)
|
||||
// TODO(cian): We define IdleDurationMS as "the time from the last working status to pause".
|
||||
// We know that the task has reported working since T-6h and got auto-paused at T-50m.
|
||||
// We can reasonably assume that it has been 'idle' from when it was stopped (T-30m) to
|
||||
// its next report at T-25m. This is covered by ResumeToStatusMS.
|
||||
// But do we consider the time since its last report (T-6h) to its being auto-paused
|
||||
// as truly "idle"?
|
||||
idleDurationMS: ptr.Ref(310 * time.Minute.Milliseconds()),
|
||||
activeDurationMS: ptr.Ref((5*time.Hour + 10*time.Minute + 25*time.Minute).Milliseconds()),
|
||||
},
|
||||
{
|
||||
name: "all fields populated - full lifecycle",
|
||||
createdOffset: -7 * time.Hour,
|
||||
appStatuses: []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "Started working", -390 * time.Minute},
|
||||
{database.WorkspaceAppStatusStateWorking, "Still working", -45 * time.Minute},
|
||||
},
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -35 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
{3, -5 * time.Minute, database.WorkspaceTransitionStart, database.BuildReasonTaskResume, []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "Resumed work", -3 * time.Minute},
|
||||
{database.WorkspaceAppStatusStateIdle, "Finished work", -2 * time.Minute},
|
||||
}},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-35 * time.Minute),
|
||||
lastResumedOffset: ptr.Ref(-5 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
resumeReason: ptr.Ref("manual"),
|
||||
idleDurationMS: ptr.Ref(10 * time.Minute.Milliseconds()),
|
||||
pausedDurationMS: ptr.Ref(30 * time.Minute.Milliseconds()),
|
||||
resumeToStatusMS: ptr.Ref((2 * time.Minute).Milliseconds()),
|
||||
// Active duration: (-390 to -35) + (-3 to -2) = 355 + 1 = 356 min.
|
||||
activeDurationMS: ptr.Ref(356 * time.Minute.Milliseconds()),
|
||||
},
|
||||
{
|
||||
name: "non-task_resume builds are tracked as other",
|
||||
createdOffset: -4 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -60 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
{3, -30 * time.Minute, database.WorkspaceTransitionStart, database.BuildReasonInitiator, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-60 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
resumeReason: ptr.Ref("other"),
|
||||
// LastResumedAt is set because isResumed is true (build_number > 1)
|
||||
// even though the start reason isn't task_resume.
|
||||
lastResumedOffset: ptr.Ref(-30 * time.Minute),
|
||||
// PausedDurationMS reports ongoing pause: now - (-60min) = 60min.
|
||||
pausedDurationMS: ptr.Ref(30 * time.Minute.Milliseconds()),
|
||||
},
|
||||
{
|
||||
name: "simple ongoing pause reports duration",
|
||||
createdOffset: -3 * time.Hour,
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -45 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-45 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
// No resume, so ongoing pause: now - (-45min) = 45min.
|
||||
pausedDurationMS: ptr.Ref(45 * time.Minute.Milliseconds()),
|
||||
},
|
||||
{
|
||||
name: "active duration with paused task",
|
||||
createdOffset: -2 * time.Hour,
|
||||
buildOffset: ptr.Ref(-2 * time.Hour),
|
||||
appStatuses: []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "Started", -90 * time.Minute},
|
||||
{database.WorkspaceAppStatusStateIdle, "Thinking", -60 * time.Minute}, // 30min working
|
||||
{database.WorkspaceAppStatusStateWorking, "Resumed", -45 * time.Minute},
|
||||
{database.WorkspaceAppStatusStateComplete, "Done", -30 * time.Minute}, // 15min working
|
||||
},
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -25 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-25 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
idleDurationMS: ptr.Ref(20 * time.Minute.Milliseconds()), // Last working (-45) to stop (-25).
|
||||
activeDurationMS: ptr.Ref(45 * time.Minute.Milliseconds()), // 30 + 15 = 45min of "working".
|
||||
pausedDurationMS: ptr.Ref(25 * time.Minute.Milliseconds()), // Ongoing pause.
|
||||
},
|
||||
{
|
||||
// When a workspace_app_status and a workspace_build share
|
||||
// the exact same created_at timestamp, the ordering inside
|
||||
// task_status_timeline is ambiguous. The boundary row must
|
||||
// sort after real statuses so that LEAD() and the lws
|
||||
// lateral join produce deterministic results.
|
||||
name: "status and build at same timestamp - deterministic ordering",
|
||||
createdOffset: -3 * time.Hour,
|
||||
buildOffset: ptr.Ref(-2 * time.Hour),
|
||||
appStatuses: []statusSpec{
|
||||
{database.WorkspaceAppStatusStateWorking, "Started work", -90 * time.Minute},
|
||||
// This status has the exact same timestamp as the
|
||||
// stop build below, exercising the tiebreaker.
|
||||
{database.WorkspaceAppStatusStateWorking, "Last update before pause", -30 * time.Minute},
|
||||
},
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -30 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-30 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
// IdleDurationMS is nil: the Go code requires
|
||||
// stop.After(lastWorking), which is false when equal.
|
||||
// Active: -90m (working) → -30m (boundary/stop) = 60 min.
|
||||
activeDurationMS: ptr.Ref(60 * time.Minute.Milliseconds()),
|
||||
pausedDurationMS: ptr.Ref(30 * time.Minute.Milliseconds()),
|
||||
},
|
||||
{
|
||||
// SQL filter: EXISTS (workspace_builds.created_at > createdAfter).
|
||||
// This task has only old builds (7 days ago), so it won't match
|
||||
// the 1-hour createdAfter filter and should not return an event.
|
||||
name: "old task with no recent builds - not returned",
|
||||
createdOffset: -7 * 24 * time.Hour,
|
||||
buildOffset: ptr.Ref(-7 * 24 * time.Hour),
|
||||
expectEvent: false,
|
||||
},
|
||||
{
|
||||
// SQL filter: EXISTS (workspace_builds.created_at > createdAfter).
|
||||
// This task was created 7 days ago, but has a recent stop build,
|
||||
// so it should match the filter and return an event.
|
||||
name: "old task with recent build - returned",
|
||||
createdOffset: -7 * 24 * time.Hour,
|
||||
buildOffset: ptr.Ref(-7 * 24 * time.Hour),
|
||||
extraBuilds: []buildSpec{
|
||||
{2, -30 * time.Minute, database.WorkspaceTransitionStop, database.BuildReasonTaskAutoPause, nil},
|
||||
},
|
||||
expectEvent: true,
|
||||
lastPausedOffset: ptr.Ref(-30 * time.Minute),
|
||||
pauseReason: ptr.Ref("auto"),
|
||||
pausedDurationMS: ptr.Ref(30 * time.Minute.Milliseconds()), // Ongoing pause.
|
||||
},
|
||||
}
|
||||
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
ctx := testutil.Context(t, testutil.WaitMedium)
|
||||
db, _ := dbtestutil.NewDB(t)
|
||||
org, err := db.GetDefaultOrganization(ctx)
|
||||
require.NoError(t, err)
|
||||
user := dbgen.User(t, db, database.User{})
|
||||
_ = dbgen.OrganizationMember(t, db, database.OrganizationMember{
|
||||
UserID: user.ID,
|
||||
OrganizationID: org.ID,
|
||||
})
|
||||
h := &taskTelemetryHelper{
|
||||
t: t,
|
||||
ctx: ctx,
|
||||
db: db,
|
||||
org: org,
|
||||
user: user,
|
||||
}
|
||||
|
||||
// Create a deleted task. This is a test antagonist that should never show up in results.
|
||||
deletedTaskResp := dbfake.WorkspaceBuild(h.t, h.db, database.WorkspaceTable{
|
||||
OrganizationID: h.org.ID,
|
||||
OwnerID: h.user.ID,
|
||||
}).WithTask(database.TaskTable{
|
||||
Prompt: fmt.Sprintf("deleted-task-%s", t.Name()),
|
||||
CreatedAt: now.Add(-100 * time.Hour),
|
||||
}, nil).Seed(database.WorkspaceBuild{
|
||||
Transition: database.WorkspaceTransitionStart,
|
||||
Reason: database.BuildReasonInitiator,
|
||||
BuildNumber: 1,
|
||||
CreatedAt: now.Add(-100 * time.Hour),
|
||||
}).Succeeded().Do()
|
||||
_, err = db.DeleteTask(h.ctx, database.DeleteTaskParams{
|
||||
DeletedAt: now.Add(-99 * time.Hour),
|
||||
ID: deletedTaskResp.Task.ID,
|
||||
})
|
||||
require.NoError(h.t, err, "creating deleted task antagonist")
|
||||
|
||||
var expectedTask telemetry.Task
|
||||
|
||||
if tt.skipWorkspace {
|
||||
tv := dbgen.TemplateVersion(t, h.db, database.TemplateVersion{
|
||||
OrganizationID: h.org.ID,
|
||||
CreatedBy: h.user.ID,
|
||||
HasAITask: sql.NullBool{Bool: true, Valid: true},
|
||||
})
|
||||
task := dbgen.Task(h.t, h.db, database.TaskTable{
|
||||
OwnerID: h.user.ID,
|
||||
OrganizationID: h.org.ID,
|
||||
WorkspaceID: uuid.NullUUID{},
|
||||
TemplateVersionID: tv.ID,
|
||||
Prompt: fmt.Sprintf("pending-task-%s", t.Name()),
|
||||
CreatedAt: now.Add(tt.createdOffset),
|
||||
})
|
||||
expectedTask = telemetry.Task{
|
||||
ID: task.ID.String(),
|
||||
OrganizationID: h.org.ID.String(),
|
||||
OwnerID: h.user.ID.String(),
|
||||
Name: task.Name,
|
||||
TemplateVersionID: tv.ID.String(),
|
||||
PromptHash: telemetry.HashContent(task.Prompt),
|
||||
Status: "pending",
|
||||
CreatedAt: task.CreatedAt,
|
||||
}
|
||||
} else {
|
||||
buildCreatedAt := now.Add(tt.createdOffset)
|
||||
if tt.buildOffset != nil {
|
||||
buildCreatedAt = now.Add(*tt.buildOffset)
|
||||
}
|
||||
|
||||
resp := dbfake.WorkspaceBuild(h.t, h.db, database.WorkspaceTable{
|
||||
OrganizationID: h.org.ID,
|
||||
OwnerID: h.user.ID,
|
||||
}).WithTask(database.TaskTable{
|
||||
Prompt: fmt.Sprintf("task-%s", t.Name()),
|
||||
CreatedAt: now.Add(tt.createdOffset),
|
||||
}, nil).Seed(database.WorkspaceBuild{
|
||||
Transition: database.WorkspaceTransitionStart,
|
||||
Reason: database.BuildReasonInitiator,
|
||||
BuildNumber: 1,
|
||||
CreatedAt: buildCreatedAt,
|
||||
}).Succeeded().Do()
|
||||
|
||||
app := getApp(h.ctx, h.db, resp.Agents[0].ID)
|
||||
|
||||
for _, s := range tt.appStatuses {
|
||||
createAppStatus(h.ctx, h.db, resp.Workspace.ID, resp.Agents[0].ID, app.ID, s.state, s.message, now.Add(s.offset))
|
||||
}
|
||||
|
||||
for _, b := range tt.extraBuilds {
|
||||
bld, bldApp := h.createBuild(resp, b.buildNumber, now.Add(b.offset), b.transition, b.reason)
|
||||
_ = bld
|
||||
if bldApp != nil {
|
||||
for _, s := range b.statuses {
|
||||
createAppStatus(h.ctx, h.db, resp.Workspace.ID, resp.Agents[0].ID, bldApp.ID, s.state, s.message, now.Add(s.offset))
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// Refresh the task
|
||||
updated, err := h.db.GetTaskByID(ctx, resp.Task.ID)
|
||||
require.NoError(t, err, "fetching updated task")
|
||||
expectedTask = telemetry.Task{
|
||||
ID: updated.ID.String(),
|
||||
OrganizationID: updated.OrganizationID.String(),
|
||||
OwnerID: updated.OwnerID.String(),
|
||||
Name: updated.Name,
|
||||
WorkspaceID: ptr.Ref(updated.WorkspaceID.UUID.String()),
|
||||
WorkspaceBuildNumber: ptr.Ref(int64(updated.WorkspaceBuildNumber.Int32)),
|
||||
WorkspaceAgentID: ptr.Ref(updated.WorkspaceAgentID.UUID.String()),
|
||||
WorkspaceAppID: ptr.Ref(updated.WorkspaceAppID.UUID.String()),
|
||||
TemplateVersionID: updated.TemplateVersionID.String(),
|
||||
PromptHash: telemetry.HashContent(updated.Prompt),
|
||||
Status: string(updated.Status),
|
||||
CreatedAt: updated.CreatedAt,
|
||||
}
|
||||
}
|
||||
|
||||
actualTasks, err := telemetry.CollectTasks(h.ctx, h.db)
|
||||
require.NoError(t, err, "unexpected error collecting tasks telemetry")
|
||||
// Invariant: deleted tasks should NEVER appear in results.
|
||||
require.Len(t, actualTasks, 1, "expected exactly one task")
|
||||
|
||||
if diff := cmp.Diff(expectedTask, actualTasks[0]); diff != "" {
|
||||
t.Fatalf("test case %q: task diff (-want +got):\n%s", tt.name, diff)
|
||||
}
|
||||
|
||||
actualEvents, err := telemetry.CollectTaskEvents(h.ctx, h.db, now.Add(-1*time.Hour), now)
|
||||
require.NoError(t, err)
|
||||
if !tt.expectEvent {
|
||||
require.Empty(t, actualEvents)
|
||||
} else {
|
||||
expectedEvent := telemetry.TaskEvent{
|
||||
TaskID: expectedTask.ID,
|
||||
}
|
||||
if tt.lastPausedOffset != nil {
|
||||
t := now.Add(*tt.lastPausedOffset)
|
||||
expectedEvent.LastPausedAt = &t
|
||||
}
|
||||
if tt.lastResumedOffset != nil {
|
||||
t := now.Add(*tt.lastResumedOffset)
|
||||
expectedEvent.LastResumedAt = &t
|
||||
}
|
||||
expectedEvent.PauseReason = tt.pauseReason
|
||||
expectedEvent.ResumeReason = tt.resumeReason
|
||||
expectedEvent.IdleDurationMS = tt.idleDurationMS
|
||||
expectedEvent.PausedDurationMS = tt.pausedDurationMS
|
||||
expectedEvent.ResumeToStatusMS = tt.resumeToStatusMS
|
||||
expectedEvent.ActiveDurationMS = tt.activeDurationMS
|
||||
|
||||
// Each test case creates exactly one workspace with lifecycle
|
||||
// activity, so we expect exactly one event.
|
||||
require.Len(t, actualEvents, 1)
|
||||
actual := actualEvents[0]
|
||||
|
||||
if diff := cmp.Diff(expectedEvent, actual); diff != "" {
|
||||
t.Fatalf("test case %q: event diff (-want +got):\n%s", tt.name, diff)
|
||||
}
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
type mockDB struct {
|
||||
database.Store
|
||||
}
|
||||
@@ -767,7 +1350,7 @@ func TestRecordTelemetryStatus(t *testing.T) {
|
||||
require.Nil(t, snapshot1)
|
||||
}
|
||||
|
||||
for i := 0; i < 3; i++ {
|
||||
for range 3 {
|
||||
// Whatever happens, subsequent calls should not report if telemetryEnabled didn't change
|
||||
snapshot2, err := telemetry.RecordTelemetryStatus(ctx, logger, db, testCase.telemetryEnabled)
|
||||
require.NoError(t, err)
|
||||
|
||||
Reference in New Issue
Block a user