diff --git a/provisioner/terraform/executor.go b/provisioner/terraform/executor.go index 67922d0ffb..5ef7f626f9 100644 --- a/provisioner/terraform/executor.go +++ b/provisioner/terraform/executor.go @@ -28,7 +28,10 @@ import ( "github.com/coder/coder/v2/provisionersdk/proto" ) -var version170 = version.Must(version.NewVersion("1.7.0")) +var ( + version170 = version.Must(version.NewVersion("1.7.0")) + version190 = version.Must(version.NewVersion("1.9.0")) +) type executor struct { logger slog.Logger @@ -225,7 +228,7 @@ func (e *executor) init(ctx, killCtx context.Context, logr logSink) error { lockFilePath := filepath.Join(e.workdir, ".terraform.lock.hcl") preInitChecksum := checksumFileCRC32(ctx, e.logger, lockFilePath) - outWriter, doneOut := logWriter(logr, proto.LogLevel_DEBUG) + outWriter, doneOut := e.provisionLogWriter(logr) errWriter, doneErr := logWriter(logr, proto.LogLevel_ERROR) defer func() { _ = outWriter.Close() @@ -244,7 +247,16 @@ func (e *executor) init(ctx, killCtx context.Context, logr logSink) error { "-input=false", } - err := e.execWriteOutput(ctx, killCtx, args, e.basicEnv(), outWriter, errBuf) + ver, err := e.version(ctx) + if err != nil { + return xerrors.Errorf("extract version: %w", err) + } + if ver.GreaterThanOrEqual(version190) { + // Added in v1.9.0: + args = append(args, "-json") + } + + err = e.execWriteOutput(ctx, killCtx, args, e.basicEnv(), outWriter, errBuf) var exitErr *exec.ExitError if xerrors.As(err, &exitErr) { if bytes.Contains(errBuf.b.Bytes(), []byte("text file busy")) { @@ -809,6 +821,9 @@ func extractTimingSpan(log *terraformProvisionLog) (time.Time, *timingSpan, erro return time.Time{}, nil, xerrors.Errorf("unexpected timing kind: %q", log.Type) } + // Init logs omit millisecond precision, so using `time.Now` as a fallback + // for these logs is more precise than parsing the second precision alone. + // https://github.com/hashicorp/terraform/pull/37818 ts, err := time.Parse("2006-01-02T15:04:05.000000Z07:00", log.Timestamp) if err != nil { // TODO: log @@ -816,10 +831,11 @@ func extractTimingSpan(log *terraformProvisionLog) (time.Time, *timingSpan, erro } return ts, &timingSpan{ - kind: typ, - action: log.Hook.Action, - provider: log.Hook.Resource.Provider, - resource: log.Hook.Resource.Addr, + kind: typ, + messageCode: log.MessageCode, + action: log.Hook.Action, + provider: log.Hook.Resource.Provider, + resource: log.Hook.Resource.Addr, }, nil } @@ -842,11 +858,14 @@ func convertTerraformLogLevel(logLevel string, sink logSink) proto.LogLevel { } type terraformProvisionLog struct { - Level string `json:"@level"` - Message string `json:"@message"` - Timestamp string `json:"@timestamp"` - Type string `json:"type"` - Hook terraformProvisionLogHook `json:"hook"` + Level string `json:"@level"` + Message string `json:"@message"` + Timestamp string `json:"@timestamp"` + Type string `json:"type"` + // MessageCode is only set for init phase messages after Terraform 1.9.0 + // This field is not used by plan/apply. + MessageCode initMessageCode `json:"message_code,omitempty"` + Hook terraformProvisionLogHook `json:"hook"` Diagnostic *tfjson.Diagnostic `json:"diagnostic,omitempty"` } diff --git a/provisioner/terraform/inittimings.go b/provisioner/terraform/inittimings.go new file mode 100644 index 0000000000..e72d237b52 --- /dev/null +++ b/provisioner/terraform/inittimings.go @@ -0,0 +1,166 @@ +package terraform + +import ( + "slices" + "time" + + "github.com/coder/coder/v2/coderd/database" + "github.com/coder/coder/v2/provisionersdk/proto" +) + +const ( + // defaultInitAction is a human-readable action for init timing spans. The coder + // frontend displays the action, which would be an empty string if not set to + // this constant. Setting it to "load" gives more context to users about what is + // happening during init. The init steps either "load" from disk or http. + defaultInitAction = "load" +) + +var ( + // resourceName maps init message codes to human-readable resource names. + // This is purely for better readability in the timing spans. + resourceName = map[initMessageCode]string{ + initInitializingBackendMessage: "backend", + initInitializingStateStoreMessage: "backend", + + initInitializingModulesMessage: "modules", + initUpgradingModulesMessage: "modules", + + initInitializingProviderPluginMessage: "provider plugins", + } + + // executionOrder is the expected sequential steps during `terraform init`. + // Some steps of the init have more than 1 possible "initMessageCode". + // + // In practice, since Coder has a defined way of running Terraform, only + // one code per step is expected. However, this allows for future-proofing + // in case Coder adds more Terraform init configurations. + executionOrder = [][]initMessageCode{ + { + initInitializingBackendMessage, + initInitializingStateStoreMessage, // If using a state store backend + }, + { + initInitializingModulesMessage, + initUpgradingModulesMessage, // if "-upgrade" flag provided + }, + {initInitializingProviderPluginMessage}, + { + initOutputInitSuccessMessage, + initOutputInitSuccessCloudMessage, // If using terraform cloud + }, + } +) + +// ingestInitTiming handles ingesting timing spans from `terraform init` logs. +// These logs are formatted differently from plan/apply logs, so they need their +// own ingestion logic. +// +// The logs are also less granular, only indicating the start of major init +// steps, rather than per-resource actions. Since initialization is done +// serially, we can infer the end time of each stage from the start time of the +// next stage. +func (t *timingAggregator) ingestInitTiming(ts time.Time, s *timingSpan) { + switch s.messageCode { + case initInitializingBackendMessage, initInitializingStateStoreMessage: + // Backend loads the tfstate from the backend data source. For coder, this is + // always a state file on disk, making it nearly an instantaneous operation. + s.start = ts + s.state = proto.TimingState_STARTED + case initInitializingModulesMessage, initUpgradingModulesMessage: + s.start = ts + s.state = proto.TimingState_STARTED + case initInitializingProviderPluginMessage: + s.start = ts + s.state = proto.TimingState_STARTED + case initOutputInitSuccessMessage, initOutputInitSuccessCloudMessage: + // The final message indicates successful completion of init. There is no start + // message for this, but we want to continue the pattern such that this completes + // the previous stage. + s.end = ts + s.state = proto.TimingState_COMPLETED + default: + return + } + + // Init logs should be assigned to the init stage. + // Ideally the executor could use an `init` stage aggregator directly, but + // that would require a larger refactor. + s.stage = database.ProvisionerJobTimingStageInit + // The default action is an empty string. Set it to "load" for some human readability. + s.action = defaultInitAction + // Resource name is an empty string. Name it something more useful. + s.resource = resourceName[s.messageCode] + + // finishPrevious completes the previous step in the init sequence, if applicable. + t.finishPrevious(ts, s) + + t.lookupMu.Lock() + // Memoize this span by its unique attributes and the determined state. + // This will be used in aggregate() to determine the duration of the resource action. + t.stateLookup[s.hashByState(s.state)] = s + t.lookupMu.Unlock() +} + +func (t *timingAggregator) finishPrevious(ts time.Time, s *timingSpan) { + index := slices.IndexFunc(executionOrder, func(codes []initMessageCode) bool { + return slices.Contains(codes, s.messageCode) + }) + if index <= 0 { + // If the index is not found or is the first item, nothing to complete. + return + } + + // Complete the previous message. + previousSteps := executionOrder[index-1] + + t.lookupMu.Lock() + // Complete the previous step. We are not tracking the state of these steps, so + // we cannot tell for sure what the previous step `MessageCode` was. The + // aggregator only reports timings that have a start & end. So if we end all + // possible previous step `MessageCodes`, the aggregator will only report the one + // that was actually started. + // + // This is a bit of a hack, but it works given the constraints of the init logs. + // Ideally we would store more state about the init steps. Or loop over the + // stored timings to find the one that was started. This is just simpler and + // accomplishes the same goal. + for _, step := range previousSteps { + cpy := *s + cpy.start = time.Time{} + cpy.end = ts + cpy.messageCode = step + cpy.resource = resourceName[step] + cpy.state = proto.TimingState_COMPLETED + t.stateLookup[cpy.hashByState(cpy.state)] = &cpy + } + + t.lookupMu.Unlock() +} + +// mergeInitTimings merges manual init timings with existing timings that are +// sourced by the logs. This is done because prior to Terraform v1.9, init logs +// did not have a `-json` formatting option. +// So before v1.9, the init stage is manually timed outside the `terraform init`. +// After v1.9, the init stage is timed via logs. +func mergeInitTimings(manualInit []*proto.Timing, existing []*proto.Timing) []*proto.Timing { + initFailed := slices.ContainsFunc(existing, func(timing *proto.Timing) bool { + return timing.State == proto.TimingState_FAILED + }) + + if initFailed { + // The init logs do not provide enough information for failed init timings. + // So use the manual timings in this case. + return append(manualInit, existing...) + } + + hasInitStage := slices.ContainsFunc(existing, func(timing *proto.Timing) bool { + return timing.Stage == string(database.ProvisionerJobTimingStageInit) + }) + + if hasInitStage { + return existing + } + + return append(manualInit, existing...) +} diff --git a/provisioner/terraform/provision.go b/provisioner/terraform/provision.go index c97a583af7..ec9f96c3ed 100644 --- a/provisioner/terraform/provision.go +++ b/provisioner/terraform/provision.go @@ -170,7 +170,7 @@ func (s *server) Plan( // Prepend init timings since they occur prior to plan timings. // Order is irrelevant; this is merely indicative. - resp.Timings = append(initTimings.aggregate(), resp.Timings...) + resp.Timings = mergeInitTimings(initTimings.aggregate(), resp.Timings) resp.Modules = modules return resp } diff --git a/provisioner/terraform/testdata/timings-aggregation/complete.txtar b/provisioner/terraform/testdata/timings-aggregation/complete.txtar index 40acb9ae06..564bbd45bf 100644 --- a/provisioner/terraform/testdata/timings-aggregation/complete.txtar +++ b/provisioner/terraform/testdata/timings-aggregation/complete.txtar @@ -1,5 +1,27 @@ A successful build which results in successful plan and apply timings. - +-- init -- +{"@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"} +{"@level":"info","@message":"Initializing the backend...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_backend_message","type":"init_output"} +{"@level":"info","@message":"Initializing modules...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_modules_message","type":"init_output"} +{"@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"} +{"@level":"info","@message":"- cursor in .terraform/modules/cursor","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:29.982904-05:00","type":"log"} +{"@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"} +{"@level":"info","@message":"- jetbrains in .terraform/modules/jetbrains","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:30.202355-05:00","type":"log"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} -- plan -- {"@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"} {"@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. {"@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"} {"@level":"info","@message":"Outputs: 0","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.205051+02:00","outputs":{},"type":"outputs"} -- timings -- +{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:31Z","action":"load","resource":"modules","stage":"init","state":"COMPLETED"} +{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:29Z","action":"load","resource":"backend","stage":"init","state":"COMPLETED"} +{"start":"2025-10-22T17:48:31Z","end":"2025-10-22T17:48:34Z","action":"load","resource":"provider plugins","stage":"init","state":"COMPLETED"} {"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"} {"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"} {"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"} {"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"} {"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"} {"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"} -{"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"} \ No newline at end of file +{"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"} diff --git a/provisioner/terraform/testdata/timings-aggregation/fake-terraform.sh b/provisioner/terraform/testdata/timings-aggregation/fake-terraform.sh index 4eb0d11ad0..582df28c62 100755 --- a/provisioner/terraform/testdata/timings-aggregation/fake-terraform.sh +++ b/provisioner/terraform/testdata/timings-aggregation/fake-terraform.sh @@ -1,4 +1,4 @@ -#!/bin/bash +#!/usr/bin/env bash function terraform_version() { cat <<'EOL' @@ -58,24 +58,28 @@ EOL function terraform_init() { cat <<'EOL' - -Initializing the backend... - -Initializing provider plugins... -- Reusing previous version of coder/coder from the dependency lock file -- Reusing previous version of kreuzwerker/docker from the dependency lock file -- Using previously-installed coder/coder v1.0.1 -- Using previously-installed kreuzwerker/docker v3.0.2 - -Terraform has been successfully initialized! - -You may now begin working with Terraform. Try running "terraform plan" to see -any changes that are required for your infrastructure. All Terraform commands -should now work. - -If you ever set or change modules or backend configuration for Terraform, -rerun this command to reinitialize your working directory. If you forget, other -commands will detect it and remind you to do so if necessary. +{"@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"} +{"@level":"info","@message":"Initializing the backend...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_backend_message","type":"init_output"} +{"@level":"info","@message":"Initializing modules...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_modules_message","type":"init_output"} +{"@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"} +{"@level":"info","@message":"- cursor in .terraform/modules/cursor","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:29.982904-05:00","type":"log"} +{"@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"} +{"@level":"info","@message":"- jetbrains in .terraform/modules/jetbrains","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:30.202355-05:00","type":"log"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} EOL } diff --git a/provisioner/terraform/testdata/timings-aggregation/init.txtar b/provisioner/terraform/testdata/timings-aggregation/init.txtar index df9db78255..a4b0f640c6 100644 --- a/provisioner/terraform/testdata/timings-aggregation/init.txtar +++ b/provisioner/terraform/testdata/timings-aggregation/init.txtar @@ -2,8 +2,6 @@ Init produces JSON logs, but not with discrete fields which we can parse. It only gained the ability to output JSON logs in v1.9.0 (https://github.com/hashicorp/terraform/blob/v1.9/CHANGELOG.md#190-june-26-2024), so I've included the non-JSON logs as well. -Neither one produces any timings. - -- init -- # Before v1.9.0 Initializing the backend... @@ -24,15 +22,30 @@ If you ever set or change modules or backend configuration for Terraform, rerun this command to reinitialize your working directory. If you forget, other commands will detect it and remind you to do so if necessary. -# After v1.9.0 -{"@level":"info","@message":"Terraform 1.9.2","@module":"terraform.ui","@timestamp":"2024-08-15T09:19:30.835464+02:00","terraform":"1.9.2","type":"version","ui":"1.2"} -{"@level":"info","@message":"Initializing the backend...","@module":"terraform.ui","@timestamp":"2024-08-15T07:19:30Z","message_code":"initializing_backend_message","type":"init_output"} -{"@level":"info","@message":"Initializing modules...","@module":"terraform.ui","@timestamp":"2024-08-15T07:19:30Z","message_code":"initializing_modules_message","type":"init_output"} -{"@level":"info","@message":"Initializing provider plugins...","@module":"terraform.ui","@timestamp":"2024-08-15T07:19:30Z","message_code":"initializing_provider_plugin_message","type":"init_output"} -{"@level":"info","@message":"coder/coder: Reusing previous version from the dependency lock file","@module":"terraform.ui","@timestamp":"2024-08-15T09:19:30.870861+02:00","type":"log"} -{"@level":"info","@message":"hashicorp/http: Reusing previous version from the dependency lock file","@module":"terraform.ui","@timestamp":"2024-08-15T09:19:31.282247+02:00","type":"log"} -{"@level":"info","@message":"coder/coder v1.0.1: Using previously-installed provider version","@module":"terraform.ui","@timestamp":"2024-08-15T09:19:31.466355+02:00","type":"log"} -{"@level":"info","@message":"hashicorp/http v3.4.4: Using previously-installed provider version","@module":"terraform.ui","@timestamp":"2024-08-15T09:19:31.479221+02:00","type":"log"} -{"@level":"info","@message":"Terraform has been successfully initialized!","@module":"terraform.ui","@timestamp":"2024-08-15T07:19:31Z","message_code":"output_init_success_message","type":"init_output"} -{"@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":"2024-08-15T07:19:31Z","message_code":"output_init_success_cli_message","type":"init_output"} --- timings -- \ No newline at end of file +# After v1.9.0, uncached +{"@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"} +{"@level":"info","@message":"Initializing the backend...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_backend_message","type":"init_output"} +{"@level":"info","@message":"Initializing modules...","@module":"terraform.ui","@timestamp":"2025-10-22T17:48:29.000000Z","message_code":"initializing_modules_message","type":"init_output"} +{"@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"} +{"@level":"info","@message":"- cursor in .terraform/modules/cursor","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:29.982904-05:00","type":"log"} +{"@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"} +{"@level":"info","@message":"- jetbrains in .terraform/modules/jetbrains","@module":"terraform.ui","@timestamp":"2025-10-22T12:48:30.202355-05:00","type":"log"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +{"@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"} +-- timings -- +{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:31Z","action":"load","resource":"modules","stage":"init","state":"COMPLETED"} +{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:29Z","action":"load","resource":"backend","stage":"init","state":"COMPLETED"} +{"start":"2025-10-22T17:48:31Z","end":"2025-10-22T17:48:34Z","action":"load","resource":"provider plugins","stage":"init","state":"COMPLETED"} diff --git a/provisioner/terraform/testdata/timings-aggregation/initupgrade.txtar b/provisioner/terraform/testdata/timings-aggregation/initupgrade.txtar new file mode 100644 index 0000000000..25472b1a37 --- /dev/null +++ b/provisioner/terraform/testdata/timings-aggregation/initupgrade.txtar @@ -0,0 +1,29 @@ +# terraform init -upgrade -json +-- init -- +{"@level":"info","@message":"Terraform 1.13.3","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:51.988373-05:00","terraform":"1.13.3","type":"version","ui":"1.2"} +{"@level":"info","@message":"Initializing the backend...","@module":"terraform.ui","@timestamp":"2025-10-27T19:00:51.000000Z","message_code":"initializing_backend_message","type":"init_output"} +{"@level":"info","@message":"Upgrading modules...","@module":"terraform.ui","@timestamp":"2025-10-27T19:00:51.000000Z","message_code":"upgrading_modules_message","type":"init_output"} +{"@level":"info","@message":"Downloading registry.coder.com/coder/cursor/coder 1.3.2 for cursor...","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:52.152388-05:00","type":"log"} +{"@level":"info","@message":"- cursor in .terraform/modules/cursor","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:52.394592-05:00","type":"log"} +{"@level":"info","@message":"Downloading registry.coder.com/coder/jetbrains/coder 1.1.0 for jetbrains...","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:52.450002-05:00","type":"log"} +{"@level":"info","@message":"- jetbrains in .terraform/modules/jetbrains","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:52.686200-05:00","type":"log"} +{"@level":"info","@message":"Downloading git::https://github.com/coder/large-module.git for large-5mb-module...","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:52.686229-05:00","type":"log"} +{"@level":"info","@message":"- large-5mb-module in .terraform/modules/large-5mb-module","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:54.298240-05:00","type":"log"} +{"@level":"info","@message":"Initializing provider plugins...","@module":"terraform.ui","@timestamp":"2025-10-27T19:00:54.000000Z","message_code":"initializing_provider_plugin_message","type":"init_output"} +{"@level":"info","@message":"Finding matching versions for provider: hashicorp/http, version_constraint: \"\u003e= 3.0.0\"","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:54.299465-05:00","type":"log"} +{"@level":"info","@message":"Finding matching versions for provider: coder/coder, version_constraint: \"\u003e= 2.5.0, ~\u003e 2.9\"","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:54.364986-05:00","type":"log"} +{"@level":"info","@message":"Finding matching versions for provider: kreuzwerker/docker, version_constraint: \"~\u003e 3.0\"","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:54.391509-05:00","type":"log"} +{"@level":"info","@message":"Installing provider version: hashicorp/http v3.5.0...","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:54.605182-05:00","type":"log"} +{"@level":"info","@message":"Installed provider version: hashicorp/http v3.5.0 (signed by HashiCorp)","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:54.892077-05:00","type":"log"} +{"@level":"info","@message":"Installing provider version: coder/coder v2.12.0...","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:55.246866-05:00","type":"log"} +{"@level":"info","@message":"Installed provider version: coder/coder v2.12.0 (signed by a HashiCorp partnerkey_id: 93C75807601AA0EC)","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:55.641603-05:00","type":"log"} +{"@level":"info","@message":"Installing provider version: kreuzwerker/docker v3.6.2...","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:55.862015-05:00","type":"log"} +{"@level":"info","@message":"Installed provider version: kreuzwerker/docker v3.6.2 (self-signedkey_id: BD080C4571C6104C)","@module":"terraform.ui","@timestamp":"2025-10-27T14:00:56.699002-05:00","type":"log"} +{"@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-27T14:00:56.699025-05:00","type":"log"} +{"@level":"info","@message":"Terraform has made some changes to the provider dependency selections recorded\nin the .terraform.lock.hcl file. Review those changes and commit them to your\nversion control system if they represent changes you intended to make.","@module":"terraform.ui","@timestamp":"2025-10-27T19:00:56Z","message_code":"dependencies_lock_changes_info","type":"init_output"} +{"@level":"info","@message":"Terraform has been successfully initialized!","@module":"terraform.ui","@timestamp":"2025-10-27T19:00:56.000000Z","message_code":"output_init_success_message","type":"init_output"} +{"@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-27T19:00:56Z","message_code":"output_init_success_cli_message","type":"init_output"} +-- timings -- +{"start":"2025-10-27T19:00:51Z","end":"2025-10-27T19:00:54Z","action":"load","resource":"modules","stage":"init","state":"COMPLETED"} +{"start":"2025-10-27T19:00:51Z","end":"2025-10-27T19:00:51Z","action":"load","resource":"backend","stage":"init","state":"COMPLETED"} +{"start":"2025-10-27T19:00:54Z","end":"2025-10-27T19:00:56Z","action":"load","resource":"provider plugins","stage":"init","state":"COMPLETED"} diff --git a/provisioner/terraform/timings.go b/provisioner/terraform/timings.go index 370836229d..d2fe742398 100644 --- a/provisioner/terraform/timings.go +++ b/provisioner/terraform/timings.go @@ -48,6 +48,28 @@ const ( timingInitOutput timingKind = "init_output" ) +// Source: https://github.com/hashicorp/terraform/blob/6b73f710f8152ef4808e4de5bdfb35314442f4a5/internal/command/views/init.go#L267-L321 +type initMessageCode string + +const ( + initCopyingConfigurationMessage initMessageCode = "copying_configuration_message" + initEmptyMessage initMessageCode = "empty_message" + initOutputInitEmptyMessage initMessageCode = "output_init_empty_message" + initOutputInitSuccessMessage initMessageCode = "output_init_success_message" + initOutputInitSuccessCloudMessage initMessageCode = "output_init_success_cloud_message" + initOutputInitSuccessCLIMessage initMessageCode = "output_init_success_cli_message" + initOutputInitSuccessCLICloudMessage initMessageCode = "output_init_success_cli_cloud_message" + initUpgradingModulesMessage initMessageCode = "upgrading_modules_message" + initInitializingTerraformCloudMessage initMessageCode = "initializing_terraform_cloud_message" + initInitializingModulesMessage initMessageCode = "initializing_modules_message" + initInitializingBackendMessage initMessageCode = "initializing_backend_message" + initInitializingStateStoreMessage initMessageCode = "initializing_state_store_message" + initDefaultWorkspaceCreatedMessage initMessageCode = "default_workspace_created_message" + initInitializingProviderPluginMessage initMessageCode = "initializing_provider_plugin_message" + initLockInfo initMessageCode = "lock_info" + initDependenciesLockChangesInfo initMessageCode = "dependencies_lock_changes_info" +) + type timingAggregator struct { stage database.ProvisionerJobTimingStage @@ -57,7 +79,9 @@ type timingAggregator struct { } type timingSpan struct { - kind timingKind + kind timingKind + // messageCode is only present in `terraform init` timings. + messageCode initMessageCode start, end time.Time stage database.ProvisionerJobTimingStage action, provider, resource string @@ -94,6 +118,10 @@ func (t *timingAggregator) ingest(ts time.Time, s *timingSpan) { case timingApplyErrored, timingProvisionErrored, timingInitErrored, timingGraphErrored: s.end = ts s.state = proto.TimingState_FAILED + case timingInitOutput: + // init timings are based on the init message code. + t.ingestInitTiming(ts, s) + return default: // We just want start/end timings, ignore all other events. return @@ -182,7 +210,7 @@ func (l timingKind) Valid() bool { // if all other attributes are identical. func (l timingKind) Category() string { switch l { - case timingInitStart, timingInitComplete, timingInitErrored: + case timingInitStart, timingInitComplete, timingInitErrored, timingInitOutput: return "init" case timingGraphStart, timingGraphComplete, timingGraphErrored: return "graph" @@ -201,6 +229,9 @@ func (l timingKind) Category() string { // The combination of resource and provider names MUST be unique across entries. func (e *timingSpan) hashByState(state proto.TimingState) uint64 { id := fmt.Sprintf("%s:%s:%s:%s:%s", e.kind.Category(), state.String(), e.action, e.resource, e.provider) + if e.messageCode != "" { + id += ":" + string(e.messageCode) + } return xxhash.Sum64String(id) } @@ -226,7 +257,7 @@ func createInitTimingsEvent(event timingKind) (time.Time, *timingSpan) { kind: event, action: "initializing terraform", provider: "terraform", - resource: "state file", + resource: "init", } } diff --git a/provisioner/terraform/timings_internal_test.go b/provisioner/terraform/timings_internal_test.go index 95dc47318e..552bec5a19 100644 --- a/provisioner/terraform/timings_internal_test.go +++ b/provisioner/terraform/timings_internal_test.go @@ -22,6 +22,8 @@ var ( inputSimple []byte //go:embed testdata/timings-aggregation/init.txtar inputInit []byte + //go:embed testdata/timings-aggregation/initupgrade.txtar + inputInitUpgrade []byte //go:embed testdata/timings-aggregation/error.txtar inputError []byte //go:embed testdata/timings-aggregation/complete.txtar @@ -45,6 +47,10 @@ func TestAggregation(t *testing.T) { name: "init", input: inputInit, }, + { + name: "initupgrade", + input: inputInitUpgrade, + }, { name: "simple", input: inputSimple, diff --git a/provisioner/terraform/timings_test.go b/provisioner/terraform/timings_test.go index ec91caf301..fe167b830f 100644 --- a/provisioner/terraform/timings_test.go +++ b/provisioner/terraform/timings_test.go @@ -98,6 +98,9 @@ func TestTimingsFromProvision(t *testing.T) { // Then: the received timings should match the expected values below. // NOTE: These timings have been encoded to JSON format to make the tests more readable. + 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"} +{"start":"2025-10-22T17:48:29Z","end":"2025-10-22T17:48:29Z","action":"load","resource":"backend","stage":"init","state":"COMPLETED"} +{"start":"2025-10-22T17:48:31Z","end":"2025-10-22T17:48:34Z","action":"load","resource":"provider plugins","stage":"init","state":"COMPLETED"}`)) 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"} {"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"} {"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"}`)) @@ -105,10 +108,10 @@ func TestTimingsFromProvision(t *testing.T) { {"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"} {"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"} {"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"}`)) - initTiming := terraform_internal.ParseTimingLines(t, []byte(`{"start":"2000-01-01T01:01:01.123456Z", "end":"2000-01-01T01:01:01.123456Z", "action":"initializing terraform", "source":"terraform", "resource":"state file", "stage":"init", "state":"COMPLETED"}`))[0] - graphTiming := 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"}`))[0] + 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"}`)) + graphTiming := graphTimings[0] - require.Len(t, timings, len(planTimings)+len(applyTimings)+2) + require.Len(t, timings, len(initTimings)+len(planTimings)+len(applyTimings)+len(graphTimings)) // init/graph timings are computed dynamically during provisioning whereas plan/apply come from the logs (fixtures) in // provisioner/terraform/testdata/timings-aggregation/fake-terraform.sh. @@ -117,11 +120,12 @@ func TestTimingsFromProvision(t *testing.T) { // We manually override the init/graph timings' timestamps so that the equality check works (all other fields should be as expected). pCursor := 0 aCursor := 0 + iCursor := 0 for _, tim := range timings { switch tim.Stage { case string(database.ProvisionerJobTimingStageInit): - tim.Start, tim.End = initTiming.Start, initTiming.End - require.True(t, terraform_internal.TimingsAreEqual(t, []*proto.Timing{initTiming}, []*proto.Timing{tim})) + require.True(t, terraform_internal.TimingsAreEqual(t, []*proto.Timing{initTimings[iCursor]}, []*proto.Timing{tim})) + iCursor++ case string(database.ProvisionerJobTimingStageGraph): tim.Start, tim.End = graphTiming.Start, graphTiming.End require.True(t, terraform_internal.TimingsAreEqual(t, []*proto.Timing{graphTiming}, []*proto.Timing{tim}))