Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit924afb7

Browse files
authored
feat: add more detailed init timings in build timeline (#20503)
This uses the `terraform init -json` logs to add more visibility intothe `init` phase of `plan`. The `init` logs omit `ms` precision, so wehave to use `time.Now()` 😢Open TF PR:hashicorp/terraform#37818
1 parent45c43d4 commit924afb7

File tree

10 files changed

+353
-56
lines changed

10 files changed

+353
-56
lines changed

‎provisioner/terraform/executor.go‎

Lines changed: 31 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,10 @@ import (
2828
"github.com/coder/coder/v2/provisionersdk/proto"
2929
)
3030

31-
varversion170=version.Must(version.NewVersion("1.7.0"))
31+
var (
32+
version170=version.Must(version.NewVersion("1.7.0"))
33+
version190=version.Must(version.NewVersion("1.9.0"))
34+
)
3235

3336
typeexecutorstruct {
3437
logger slog.Logger
@@ -225,7 +228,7 @@ func (e *executor) init(ctx, killCtx context.Context, logr logSink) error {
225228
lockFilePath:=filepath.Join(e.workdir,".terraform.lock.hcl")
226229
preInitChecksum:=checksumFileCRC32(ctx,e.logger,lockFilePath)
227230

228-
outWriter,doneOut:=logWriter(logr,proto.LogLevel_DEBUG)
231+
outWriter,doneOut:=e.provisionLogWriter(logr)
229232
errWriter,doneErr:=logWriter(logr,proto.LogLevel_ERROR)
230233
deferfunc() {
231234
_=outWriter.Close()
@@ -244,7 +247,16 @@ func (e *executor) init(ctx, killCtx context.Context, logr logSink) error {
244247
"-input=false",
245248
}
246249

247-
err:=e.execWriteOutput(ctx,killCtx,args,e.basicEnv(),outWriter,errBuf)
250+
ver,err:=e.version(ctx)
251+
iferr!=nil {
252+
returnxerrors.Errorf("extract version: %w",err)
253+
}
254+
ifver.GreaterThanOrEqual(version190) {
255+
// Added in v1.9.0:
256+
args=append(args,"-json")
257+
}
258+
259+
err=e.execWriteOutput(ctx,killCtx,args,e.basicEnv(),outWriter,errBuf)
248260
varexitErr*exec.ExitError
249261
ifxerrors.As(err,&exitErr) {
250262
ifbytes.Contains(errBuf.b.Bytes(), []byte("text file busy")) {
@@ -809,17 +821,21 @@ func extractTimingSpan(log *terraformProvisionLog) (time.Time, *timingSpan, erro
809821
return time.Time{},nil,xerrors.Errorf("unexpected timing kind: %q",log.Type)
810822
}
811823

824+
// Init logs omit millisecond precision, so using `time.Now` as a fallback
825+
// for these logs is more precise than parsing the second precision alone.
826+
// https://github.com/hashicorp/terraform/pull/37818
812827
ts,err:=time.Parse("2006-01-02T15:04:05.000000Z07:00",log.Timestamp)
813828
iferr!=nil {
814829
// TODO: log
815830
ts=time.Now()
816831
}
817832

818833
returnts,&timingSpan{
819-
kind:typ,
820-
action:log.Hook.Action,
821-
provider:log.Hook.Resource.Provider,
822-
resource:log.Hook.Resource.Addr,
834+
kind:typ,
835+
messageCode:log.MessageCode,
836+
action:log.Hook.Action,
837+
provider:log.Hook.Resource.Provider,
838+
resource:log.Hook.Resource.Addr,
823839
},nil
824840
}
825841

@@ -842,11 +858,14 @@ func convertTerraformLogLevel(logLevel string, sink logSink) proto.LogLevel {
842858
}
843859

844860
typeterraformProvisionLogstruct {
845-
Levelstring`json:"@level"`
846-
Messagestring`json:"@message"`
847-
Timestampstring`json:"@timestamp"`
848-
Typestring`json:"type"`
849-
HookterraformProvisionLogHook`json:"hook"`
861+
Levelstring`json:"@level"`
862+
Messagestring`json:"@message"`
863+
Timestampstring`json:"@timestamp"`
864+
Typestring`json:"type"`
865+
// MessageCode is only set for init phase messages after Terraform 1.9.0
866+
// This field is not used by plan/apply.
867+
MessageCodeinitMessageCode`json:"message_code,omitempty"`
868+
HookterraformProvisionLogHook`json:"hook"`
850869

851870
Diagnostic*tfjson.Diagnostic`json:"diagnostic,omitempty"`
852871
}
Lines changed: 166 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,166 @@
1+
package terraform
2+
3+
import (
4+
"slices"
5+
"time"
6+
7+
"github.com/coder/coder/v2/coderd/database"
8+
"github.com/coder/coder/v2/provisionersdk/proto"
9+
)
10+
11+
const (
12+
// defaultInitAction is a human-readable action for init timing spans. The coder
13+
// frontend displays the action, which would be an empty string if not set to
14+
// this constant. Setting it to "load" gives more context to users about what is
15+
// happening during init. The init steps either "load" from disk or http.
16+
defaultInitAction="load"
17+
)
18+
19+
var (
20+
// resourceName maps init message codes to human-readable resource names.
21+
// This is purely for better readability in the timing spans.
22+
resourceName=map[initMessageCode]string{
23+
initInitializingBackendMessage:"backend",
24+
initInitializingStateStoreMessage:"backend",
25+
26+
initInitializingModulesMessage:"modules",
27+
initUpgradingModulesMessage:"modules",
28+
29+
initInitializingProviderPluginMessage:"provider plugins",
30+
}
31+
32+
// executionOrder is the expected sequential steps during `terraform init`.
33+
// Some steps of the init have more than 1 possible "initMessageCode".
34+
//
35+
// In practice, since Coder has a defined way of running Terraform, only
36+
// one code per step is expected. However, this allows for future-proofing
37+
// in case Coder adds more Terraform init configurations.
38+
executionOrder= [][]initMessageCode{
39+
{
40+
initInitializingBackendMessage,
41+
initInitializingStateStoreMessage,// If using a state store backend
42+
},
43+
{
44+
initInitializingModulesMessage,
45+
initUpgradingModulesMessage,// if "-upgrade" flag provided
46+
},
47+
{initInitializingProviderPluginMessage},
48+
{
49+
initOutputInitSuccessMessage,
50+
initOutputInitSuccessCloudMessage,// If using terraform cloud
51+
},
52+
}
53+
)
54+
55+
// ingestInitTiming handles ingesting timing spans from `terraform init` logs.
56+
// These logs are formatted differently from plan/apply logs, so they need their
57+
// own ingestion logic.
58+
//
59+
// The logs are also less granular, only indicating the start of major init
60+
// steps, rather than per-resource actions. Since initialization is done
61+
// serially, we can infer the end time of each stage from the start time of the
62+
// next stage.
63+
func (t*timingAggregator)ingestInitTiming(ts time.Time,s*timingSpan) {
64+
switchs.messageCode {
65+
caseinitInitializingBackendMessage,initInitializingStateStoreMessage:
66+
// Backend loads the tfstate from the backend data source. For coder, this is
67+
// always a state file on disk, making it nearly an instantaneous operation.
68+
s.start=ts
69+
s.state=proto.TimingState_STARTED
70+
caseinitInitializingModulesMessage,initUpgradingModulesMessage:
71+
s.start=ts
72+
s.state=proto.TimingState_STARTED
73+
caseinitInitializingProviderPluginMessage:
74+
s.start=ts
75+
s.state=proto.TimingState_STARTED
76+
caseinitOutputInitSuccessMessage,initOutputInitSuccessCloudMessage:
77+
// The final message indicates successful completion of init. There is no start
78+
// message for this, but we want to continue the pattern such that this completes
79+
// the previous stage.
80+
s.end=ts
81+
s.state=proto.TimingState_COMPLETED
82+
default:
83+
return
84+
}
85+
86+
// Init logs should be assigned to the init stage.
87+
// Ideally the executor could use an `init` stage aggregator directly, but
88+
// that would require a larger refactor.
89+
s.stage=database.ProvisionerJobTimingStageInit
90+
// The default action is an empty string. Set it to "load" for some human readability.
91+
s.action=defaultInitAction
92+
// Resource name is an empty string. Name it something more useful.
93+
s.resource=resourceName[s.messageCode]
94+
95+
// finishPrevious completes the previous step in the init sequence, if applicable.
96+
t.finishPrevious(ts,s)
97+
98+
t.lookupMu.Lock()
99+
// Memoize this span by its unique attributes and the determined state.
100+
// This will be used in aggregate() to determine the duration of the resource action.
101+
t.stateLookup[s.hashByState(s.state)]=s
102+
t.lookupMu.Unlock()
103+
}
104+
105+
func (t*timingAggregator)finishPrevious(ts time.Time,s*timingSpan) {
106+
index:=slices.IndexFunc(executionOrder,func(codes []initMessageCode)bool {
107+
returnslices.Contains(codes,s.messageCode)
108+
})
109+
ifindex<=0 {
110+
// If the index is not found or is the first item, nothing to complete.
111+
return
112+
}
113+
114+
// Complete the previous message.
115+
previousSteps:=executionOrder[index-1]
116+
117+
t.lookupMu.Lock()
118+
// Complete the previous step. We are not tracking the state of these steps, so
119+
// we cannot tell for sure what the previous step `MessageCode` was. The
120+
// aggregator only reports timings that have a start & end. So if we end all
121+
// possible previous step `MessageCodes`, the aggregator will only report the one
122+
// that was actually started.
123+
//
124+
// This is a bit of a hack, but it works given the constraints of the init logs.
125+
// Ideally we would store more state about the init steps. Or loop over the
126+
// stored timings to find the one that was started. This is just simpler and
127+
// accomplishes the same goal.
128+
for_,step:=rangepreviousSteps {
129+
cpy:=*s
130+
cpy.start= time.Time{}
131+
cpy.end=ts
132+
cpy.messageCode=step
133+
cpy.resource=resourceName[step]
134+
cpy.state=proto.TimingState_COMPLETED
135+
t.stateLookup[cpy.hashByState(cpy.state)]=&cpy
136+
}
137+
138+
t.lookupMu.Unlock()
139+
}
140+
141+
// mergeInitTimings merges manual init timings with existing timings that are
142+
// sourced by the logs. This is done because prior to Terraform v1.9, init logs
143+
// did not have a `-json` formatting option.
144+
// So before v1.9, the init stage is manually timed outside the `terraform init`.
145+
// After v1.9, the init stage is timed via logs.
146+
funcmergeInitTimings(manualInit []*proto.Timing,existing []*proto.Timing) []*proto.Timing {
147+
initFailed:=slices.ContainsFunc(existing,func(timing*proto.Timing)bool {
148+
returntiming.State==proto.TimingState_FAILED
149+
})
150+
151+
ifinitFailed {
152+
// The init logs do not provide enough information for failed init timings.
153+
// So use the manual timings in this case.
154+
returnappend(manualInit,existing...)
155+
}
156+
157+
hasInitStage:=slices.ContainsFunc(existing,func(timing*proto.Timing)bool {
158+
returntiming.Stage==string(database.ProvisionerJobTimingStageInit)
159+
})
160+
161+
ifhasInitStage {
162+
returnexisting
163+
}
164+
165+
returnappend(manualInit,existing...)
166+
}

‎provisioner/terraform/provision.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -170,7 +170,7 @@ func (s *server) Plan(
170170

171171
// Prepend init timings since they occur prior to plan timings.
172172
// Order is irrelevant; this is merely indicative.
173-
resp.Timings=append(initTimings.aggregate(),resp.Timings...)
173+
resp.Timings=mergeInitTimings(initTimings.aggregate(),resp.Timings)
174174
resp.Modules=modules
175175
returnresp
176176
}

‎provisioner/terraform/testdata/timings-aggregation/complete.txtar‎

Lines changed: 27 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,27 @@
11
A successful build which results in successful plan and apply timings.
2-
2+
-- init --
3+
{"@level":"info","@message":"Terraform 1.13.3","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:29.576675-05:00","terraform":"1.13.3","type":"version","ui":"1.2"}
4+
{"@level":"info","@message":"Initializing the backend...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_backend_message","type":"init_output"}
5+
{"@level":"info","@message":"Initializing modules...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_modules_message","type":"init_output"}
6+
{"@level":"info","@message":"Downloading registry.coder.com/coder/cursor/coder 1.3.2 for cursor...","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:29.780639-05:00","type":"log"}
7+
{"@level":"info","@message":"- cursor in .terraform/modules/cursor","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:29.982904-05:00","type":"log"}
8+
{"@level":"info","@message":"Downloading registry.coder.com/coder/jetbrains/coder 1.1.0 for jetbrains...","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:30.039894-05:00","type":"log"}
9+
{"@level":"info","@message":"- jetbrains in .terraform/modules/jetbrains","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:30.202355-05:00","type":"log"}
10+
{"@level":"info","@message":"Downloading git::https://github.com/coder/large-module.git for large-5mb-module...","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:30.202394-05:00","type":"log"}
11+
{"@level":"info","@message":"- large-5mb-module in .terraform/modules/large-5mb-module","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:31.799988-05:00","type":"log"}
12+
{"@level":"info","@message":"Initializing provider plugins...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:31.000000Z","message_code":"initializing_provider_plugin_message","type":"init_output"}
13+
{"@level":"info","@message":"kreuzwerker/docker: Reusing previous version from the dependency lock file","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:31.801342-05:00","type":"log"}
14+
{"@level":"info","@message":"hashicorp/http: Reusing previous version from the dependency lock file","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:31.868885-05:00","type":"log"}
15+
{"@level":"info","@message":"coder/coder: Reusing previous version from the dependency lock file","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:31.894724-05:00","type":"log"}
16+
{"@level":"info","@message":"Installing provider version: hashicorp/http v3.5.0...","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:32.081468-05:00","type":"log"}
17+
{"@level":"info","@message":"Installed provider version: hashicorp/http v3.5.0 (signed by HashiCorp)","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:32.375580-05:00","type":"log"}
18+
{"@level":"info","@message":"Installing provider version: coder/coder v2.11.0...","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:32.869110-05:00","type":"log"}
19+
{"@level":"info","@message":"Installed provider version: coder/coder v2.11.0 (signed by a HashiCorp partnerkey_id: 93C75807601AA0EC)","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:33.350069-05:00","type":"log"}
20+
{"@level":"info","@message":"Installing provider version: kreuzwerker/docker v3.6.2...","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:33.572112-05:00","type":"log"}
21+
{"@level":"info","@message":"Installed provider version: kreuzwerker/docker v3.6.2 (self-signedkey_id: BD080C4571C6104C)","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:34.458153-05:00","type":"log"}
22+
{"@level":"info","@message":"Partner and community providers are signed by their developers.\nIf you'd like to know more about provider signing, you can read about it here:\nhttps://developer.hashicorp.com/terraform/cli/plugins/signing","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:34.458177-05:00","type":"log"}
23+
{"@level":"info","@message":"Terraform has been successfully initialized!","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:34.000000Z","message_code":"output_init_success_message","type":"init_output"}
24+
{"@level":"info","@message":"You may now begin working with Terraform. Try running \"terraform plan\" to see\nany changes that are required for your infrastructure. All Terraform commands\nshould now work.\n\nIf you ever set or change modules or backend configuration for Terraform,\nrerun this command to reinitialize your working directory. If you forget, other\ncommands will detect it and remind you to do so if necessary.","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:34Z","message_code":"output_init_success_cli_message","type":"init_output"}
325
-- plan --
426
{"@level":"info","@message":"Terraform 1.9.2","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:38.097648+02:00","terraform":"1.9.2","type":"version","ui":"1.2"}
527
{"@level":"info","@message":"data.coder_workspace.me: Refreshing...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.194726+02:00","hook":{"resource":{"addr":"data.coder_workspace.me","module":"","resource":"data.coder_workspace.me","implied_provider":"coder","resource_type":"coder_workspace","resource_name":"me","resource_key":null},"action":"read"},"type":"apply_start"}
@@ -30,10 +52,13 @@ A successful build which results in successful plan and apply timings.
3052
{"@level":"info","@message":"Apply complete! Resources: 4 added, 0 changed, 0 destroyed.","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.204593+02:00","changes":{"add":4,"change":0,"import":0,"remove":0,"operation":"apply"},"type":"change_summary"}
3153
{"@level":"info","@message":"Outputs: 0","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.205051+02:00","outputs":{},"type":"outputs"}
3254
-- timings --
55+
{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:31Z","action":"load","resource":"modules","stage":"init","state":"COMPLETED"}
56+
{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:29Z","action":"load","resource":"backend","stage":"init","state":"COMPLETED"}
57+
{"start":"2025-10-22T17:48:31Z","end":"2025-10-22T17:48:34Z","action":"load","resource":"provider plugins","stage":"init","state":"COMPLETED"}
3358
{"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"}
3459
{"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"}
3560
{"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"}
3661
{"start":"2024-08-15T08:26:39.616546Z","end":"2024-08-15T08:26:39.618045Z","action":"create","source":"coder","resource":"coder_agent.main","stage":"apply","state":"COMPLETED"}
3762
{"start":"2024-08-15T08:26:39.626722Z","end":"2024-08-15T08:26:39.669954Z","action":"create","source":"docker","resource":"docker_image.main","stage":"apply","state":"COMPLETED"}
3863
{"start":"2024-08-15T08:26:39.627335Z","end":"2024-08-15T08:26:39.660616Z","action":"create","source":"docker","resource":"docker_volume.home_volume","stage":"apply","state":"COMPLETED"}
39-
{"start":"2024-08-15T08:26:39.682223Z","end":"2024-08-15T08:26:40.186482Z","action":"create","source":"docker","resource":"docker_container.workspace[0]","stage":"apply","state":"COMPLETED"}
64+
{"start":"2024-08-15T08:26:39.682223Z","end":"2024-08-15T08:26:40.186482Z","action":"create","source":"docker","resource":"docker_container.workspace[0]","stage":"apply","state":"COMPLETED"}

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp