Skip to content

Commit 7ac45f3

Browse files
EmyrkEmyrk
committed
timing fixes
1 parent 9630d94 commit 7ac45f3

File tree

2 files changed

+57
-42
lines changed

2 files changed

+57
-42
lines changed

‎provisioner/terraform/provision_test.go‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -138,6 +138,12 @@ func sendInit(sess proto.DRPCProvisioner_SessionClient, archive []byte) error {
138138
}}})
139139
}
140140

141+
func sendGraph(sess proto.DRPCProvisioner_SessionClient, source proto.GraphSource) error {
142+
return sess.Send(&proto.Request{Type: &proto.Request_Graph{Graph: &proto.GraphRequest{
143+
Source: source,
144+
}}})
145+
}
146+
141147
func sendPlan(sess proto.DRPCProvisioner_SessionClient, transition proto.WorkspaceTransition) error {
142148
return sess.Send(&proto.Request{Type: &proto.Request_Plan{Plan: &proto.PlanRequest{
143149
Metadata: &proto.Metadata{WorkspaceTransition: transition},

‎provisioner/terraform/timings_test.go‎

Lines changed: 51 additions & 42 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,8 @@ package terraform_test
44

55
import (
66
"context"
7+
"encoding/json"
8+
"fmt"
79
"os"
810
"path/filepath"
911
"strings"
@@ -36,63 +38,65 @@ func TestTimingsFromProvision(t *testing.T) {
3638
binaryPath: fakeBin,
3739
})
3840
sess := configure(ctx, t, api, &proto.Config{})
39-
_ = initDo(t, sess, testutil.CreateTar(t, nil))
4041

4142
ctx, cancel := context.WithTimeout(ctx, testutil.WaitLong)
4243
t.Cleanup(cancel)
4344

44-
// When: a plan is executed in the provisioner, our fake terraform will be executed and will produce a
45-
// state file and some log content.
46-
err = sendPlan(sess, proto.WorkspaceTransition_START)
47-
require.NoError(t, err)
48-
4945
var timings []*proto.Timing
5046

51-
for {
52-
select {
53-
case <-ctx.Done():
54-
t.Fatal(ctx.Err())
55-
default:
56-
}
57-
58-
msg, err := sess.Recv()
59-
require.NoError(t, err)
60-
61-
if log := msg.GetLog(); log != nil {
62-
t.Logf("%s: %s: %s", "plan", log.Level.String(), log.Output)
63-
}
64-
if c := msg.GetPlan(); c != nil {
65-
require.Empty(t, c.Error)
66-
// Capture the timing information returned by the plan process.
67-
timings = append(timings, c.GetTimings()...)
47+
handleResponse := func(t *testing.T, stage string) {
48+
t.Helper()
49+
for {
50+
select {
51+
case <-ctx.Done():
52+
t.Fatal(ctx.Err())
53+
default:
54+
}
55+
56+
msg, err := sess.Recv()
57+
require.NoError(t, err)
58+
59+
if log := msg.GetLog(); log != nil {
60+
t.Logf("%s: %s: %s", stage, log.Level.String(), log.Output)
61+
continue
62+
}
63+
switch {
64+
case msg.GetInit() != nil:
65+
timings = append(timings, msg.GetInit().GetTimings()...)
66+
case msg.GetPlan() != nil:
67+
timings = append(timings, msg.GetPlan().GetTimings()...)
68+
case msg.GetApply() != nil:
69+
timings = append(timings, msg.GetApply().GetTimings()...)
70+
case msg.GetGraph() != nil:
71+
timings = append(timings, msg.GetGraph().GetTimings()...)
72+
}
6873
break
6974
}
7075
}
7176

77+
// When: configured, our fake terraform will fake an init setup
78+
err = sendInit(sess, testutil.CreateTar(t, nil))
79+
require.NoError(t, err)
80+
handleResponse(t, "init")
81+
82+
// When: a plan is executed in the provisioner, our fake terraform will be executed and will produce a
83+
// state file and some log content.
84+
err = sendPlan(sess, proto.WorkspaceTransition_START)
85+
require.NoError(t, err)
86+
87+
handleResponse(t, "plan")
88+
7289
// When: the plan has completed, let's trigger an apply.
7390
err = sendApply(sess, proto.WorkspaceTransition_START)
7491
require.NoError(t, err)
7592

76-
for {
77-
select {
78-
case <-ctx.Done():
79-
t.Fatal(ctx.Err())
80-
default:
81-
}
93+
handleResponse(t, "apply")
8294

83-
msg, err := sess.Recv()
84-
require.NoError(t, err)
95+
// When: the apply has completed, graph the results
96+
err = sendGraph(sess, proto.GraphSource_SOURCE_STATE)
97+
require.NoError(t, err)
8598

86-
if log := msg.GetLog(); log != nil {
87-
t.Logf("%s: %s: %s", "apply", log.Level.String(), log.Output)
88-
}
89-
if c := msg.GetApply(); c != nil {
90-
require.Empty(t, c.Error)
91-
// Capture the timing information returned by the apply process.
92-
timings = append(timings, c.GetTimings()...)
93-
break
94-
}
95-
}
99+
handleResponse(t, "graph")
96100

97101
// Sort the timings stably to keep reduce flakiness.
98102
terraform_internal.StableSortTimings(t, timings)
@@ -107,7 +111,8 @@ func TestTimingsFromProvision(t *testing.T) {
107111
// NOTE: These timings have been encoded to JSON format to make the tests more readable.
108112
initTimings := terraform_internal.ParseTimingLines(t, []byte(`{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:31Z","action":"load","resource":"modules","stage":"init","state":"COMPLETED"}
109113
{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:29Z","action":"load","resource":"backend","stage":"init","state":"COMPLETED"}
110-
{"start":"2025-10-22T17:48:31Z","end":"2025-10-22T17:48:34Z","action":"load","resource":"provider plugins","stage":"init","state":"COMPLETED"}`))
114+
{"start":"2025-10-22T17:48:31Z","end":"2025-10-22T17:48:34Z","action":"load","resource":"provider plugins","stage":"init","state":"COMPLETED"}
115+
{}`))
111116
planTimings := terraform_internal.ParseTimingLines(t, []byte(`{"start":"2024-08-15T08:26:39.194726Z", "end":"2024-08-15T08:26:39.195836Z", "action":"read", "source":"coder", "resource":"data.coder_parameter.memory_size", "stage":"plan", "state":"COMPLETED"}
112117
{"start":"2024-08-15T08:26:39.194726Z", "end":"2024-08-15T08:26:39.195712Z", "action":"read", "source":"coder", "resource":"data.coder_provisioner.me", "stage":"plan", "state":"COMPLETED"}
113118
{"start":"2024-08-15T08:26:39.194726Z", "end":"2024-08-15T08:26:39.195820Z", "action":"read", "source":"coder", "resource":"data.coder_workspace.me", "stage":"plan", "state":"COMPLETED"}`))
@@ -118,6 +123,10 @@ func TestTimingsFromProvision(t *testing.T) {
118123
graphTimings := terraform_internal.ParseTimingLines(t, []byte(`{"start":"2000-01-01T01:01:01.123456Z", "end":"2000-01-01T01:01:01.123456Z", "action":"building terraform dependency graph", "source":"terraform", "resource":"state file", "stage":"graph", "state":"COMPLETED"}`))
119124
graphTiming := graphTimings[0]
120125

126+
for _, ti := range timings {
127+
msg, _ := json.Marshal(ti)
128+
fmt.Println(string(msg))
129+
}
121130
require.Len(t, timings, len(initTimings)+len(planTimings)+len(applyTimings)+len(graphTimings))
122131

123132
// init/graph timings are computed dynamically during provisioning whereas plan/apply come from the logs (fixtures) in

0 commit comments

Comments
 (0)