Skip to content

Commit 4a29b96

Browse files
dannykoppingdannykopping
committed
Tests
Signed-off-by: Danny Kopping <danny@coder.com>
1 parent a070e07 commit 4a29b96

File tree

7 files changed

+478
-32
lines changed

7 files changed

+478
-32
lines changed

‎provisioner/terraform/executor.go

Lines changed: 44 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -565,41 +565,27 @@ func (e *executor) provisionLogWriter(sink logSink) (io.WriteCloser, <-chan any)
565565

566566
func (e *executor) provisionReadAndLog(sink logSink, r io.Reader, done chan<- any) {
567567
defer close(done)
568+
569+
errCount := 0
570+
568571
scanner := bufio.NewScanner(r)
569572
for scanner.Scan() {
570-
var log terraformProvisionLog
571-
err := json.Unmarshal(scanner.Bytes(), &log)
572-
if err != nil {
573-
// Sometimes terraform doesn't log JSON, even though we asked it to.
574-
// The terraform maintainers have said on the issue tracker that
575-
// they don't guarantee that non-JSON lines won't get printed.
576-
// https://github.com/hashicorp/terraform/issues/29252#issuecomment-887710001
577-
//
578-
// > I think as a practical matter it isn't possible for us to
579-
// > promise that the output will always be entirely JSON, because
580-
// > there's plenty of code that runs before command line arguments
581-
// > are parsed and thus before we even know we're in JSON mode.
582-
// > Given that, I'd suggest writing code that consumes streaming
583-
// > JSON output from Terraform in such a way that it can tolerate
584-
// > the output not having JSON in it at all.
585-
//
586-
// Log lines such as:
587-
// - Acquiring state lock. This may take a few moments...
588-
// - Releasing state lock. This may take a few moments...
589-
if strings.TrimSpace(scanner.Text()) == "" {
590-
continue
591-
}
592-
log.Level = "info"
593-
log.Message = scanner.Text()
573+
log := parseTerraformLogLine(scanner.Bytes())
574+
if log == nil {
575+
continue
594576
}
595577

596578
logLevel := convertTerraformLogLevel(log.Level, sink)
597579
sink.ProvisionLog(logLevel, log.Message)
598580

599581
ts, span, err := extractTimingSpan(log)
600582
if err != nil {
601-
e.logger.Debug(context.Background(), "failed to extract timings entry from log line",
602-
slog.F("line", log.Message), slog.Error(err))
583+
// It's too noisy to log all of these as timings are not an essential feature, but we do need to log *some*.
584+
if errCount%10 == 0 {
585+
e.logger.Warn(context.Background(), "(sampled) failed to extract timings entry from log line",
586+
slog.F("line", log.Message), slog.Error(err))
587+
}
588+
errCount++
603589
} else {
604590
// Only ingest valid timings.
605591
e.timings.ingest(ts, span)
@@ -616,15 +602,44 @@ func (e *executor) provisionReadAndLog(sink logSink, r io.Reader, done chan<- an
616602
}
617603
}
618604

619-
func extractTimingSpan(log terraformProvisionLog) (time.Time, *timingSpan, error) {
605+
func parseTerraformLogLine(line []byte) *terraformProvisionLog {
606+
var log terraformProvisionLog
607+
err := json.Unmarshal(line, &log)
608+
if err != nil {
609+
// Sometimes terraform doesn't log JSON, even though we asked it to.
610+
// The terraform maintainers have said on the issue tracker that
611+
// they don't guarantee that non-JSON lines won't get printed.
612+
// https://github.com/hashicorp/terraform/issues/29252#issuecomment-887710001
613+
//
614+
// > I think as a practical matter it isn't possible for us to
615+
// > promise that the output will always be entirely JSON, because
616+
// > there's plenty of code that runs before command line arguments
617+
// > are parsed and thus before we even know we're in JSON mode.
618+
// > Given that, I'd suggest writing code that consumes streaming
619+
// > JSON output from Terraform in such a way that it can tolerate
620+
// > the output not having JSON in it at all.
621+
//
622+
// Log lines such as:
623+
// - Acquiring state lock. This may take a few moments...
624+
// - Releasing state lock. This may take a few moments...
625+
if len(bytes.TrimSpace(line)) == 0 {
626+
return nil
627+
}
628+
log.Level = "info"
629+
log.Message = string(line)
630+
}
631+
return &log
632+
}
633+
634+
func extractTimingSpan(log *terraformProvisionLog) (time.Time, *timingSpan, error) {
620635
// Input is not well-formed, bail out.
621636
if log.Type == "" {
622-
return time.Time{}, nil, xerrors.Errorf("invalid type: %q", log.Type)
637+
return time.Time{}, nil, xerrors.Errorf("invalid timing kind: %q", log.Type)
623638
}
624639

625640
typ := timingKind(log.Type)
626641
if !typ.Valid() {
627-
return time.Time{}, nil, xerrors.Errorf("invalid type: %q", log.Type)
642+
return time.Time{}, nil, xerrors.Errorf("unexpected timing kind: %q", log.Type)
628643
}
629644

630645
ts, err := time.Parse("2006-01-02T15:04:05.000000Z07:00", log.Timestamp)

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

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,39 @@
1+
A successful build which results in successful plan and apply timings.
2+
3+
-- plan --
4+
{"@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"}
5+
{"@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"}
6+
{"@level":"info","@message":"data.coder_parameter.memory_size: Refreshing...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.194726+02:00","hook":{"resource":{"addr":"data.coder_parameter.memory_size","module":"","resource":"data.coder_parameter.memory_size","implied_provider":"coder","resource_type":"coder_parameter","resource_name":"memory_size","resource_key":null},"action":"read"},"type":"apply_start"}
7+
{"@level":"info","@message":"data.coder_provisioner.me: Refreshing...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.194726+02:00","hook":{"resource":{"addr":"data.coder_provisioner.me","module":"","resource":"data.coder_provisioner.me","implied_provider":"coder","resource_type":"coder_provisioner","resource_name":"me","resource_key":null},"action":"read"},"type":"apply_start"}
8+
{"@level":"info","@message":"data.coder_provisioner.me: Refresh complete after 0s [id=2470b3d2-32f4-4f95-ac70-0971efdb8338]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.195712+02:00","hook":{"resource":{"addr":"data.coder_provisioner.me","module":"","resource":"data.coder_provisioner.me","implied_provider":"coder","resource_type":"coder_provisioner","resource_name":"me","resource_key":null},"action":"read","id_key":"id","id_value":"2470b3d2-32f4-4f95-ac70-0971efdb8338","elapsed_seconds":0},"type":"apply_complete"}
9+
{"@level":"info","@message":"data.coder_workspace.me: Refresh complete after 0s [id=feb06d32-3252-4cd8-b7db-ea0c5145747f]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.195820+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","id_key":"id","id_value":"feb06d32-3252-4cd8-b7db-ea0c5145747f","elapsed_seconds":0},"type":"apply_complete"}
10+
{"@level":"info","@message":"data.coder_parameter.memory_size: Refresh complete after 0s [id=b136c86c-1be0-43b4-9d78-e492918c5de0]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.195836+02:00","hook":{"resource":{"addr":"data.coder_parameter.memory_size","module":"","resource":"data.coder_parameter.memory_size","implied_provider":"coder","resource_type":"coder_parameter","resource_name":"memory_size","resource_key":null},"action":"read","id_key":"id","id_value":"b136c86c-1be0-43b4-9d78-e492918c5de0","elapsed_seconds":0},"type":"apply_complete"}
11+
{"@level":"info","@message":"coder_agent.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221555+02:00","change":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
12+
{"@level":"info","@message":"docker_image.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221574+02:00","change":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
13+
{"@level":"info","@message":"docker_volume.home_volume: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221580+02:00","change":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create"},"type":"planned_change"}
14+
{"@level":"info","@message":"docker_container.workspace[0]: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221584+02:00","change":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create"},"type":"planned_change"}
15+
{"@level":"info","@message":"Plan: 4 to add, 0 to change, 0 to destroy.","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221589+02:00","changes":{"add":4,"change":0,"import":0,"remove":0,"operation":"plan"},"type":"change_summary"}
16+
-- apply --
17+
{"@level":"info","@message":"Terraform 1.9.2","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.507006+02:00","terraform":"1.9.2","type":"version","ui":"1.2"}
18+
{"@level":"info","@message":"coder_agent.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572335+02:00","change":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
19+
{"@level":"info","@message":"docker_image.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572411+02:00","change":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
20+
{"@level":"info","@message":"docker_volume.home_volume: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572416+02:00","change":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create"},"type":"planned_change"}
21+
{"@level":"info","@message":"docker_container.workspace[0]: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572424+02:00","change":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create"},"type":"planned_change"}
22+
{"@level":"info","@message":"coder_agent.main: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.616546+02:00","hook":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create"},"type":"apply_start"}
23+
{"@level":"info","@message":"coder_agent.main: Creation complete after 0s [id=a23083da-4679-4396-a306-f7b466237883]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.618045+02:00","hook":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create","id_key":"id","id_value":"a23083da-4679-4396-a306-f7b466237883","elapsed_seconds":0},"type":"apply_complete"}
24+
{"@level":"info","@message":"docker_image.main: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.626722+02:00","hook":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create"},"type":"apply_start"}
25+
{"@level":"info","@message":"docker_volume.home_volume: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.627335+02:00","hook":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create"},"type":"apply_start"}
26+
{"@level":"info","@message":"docker_volume.home_volume: Creation complete after 0s [id=coder-feb06d32-3252-4cd8-b7db-ea0c5145747f-home]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.660616+02:00","hook":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create","id_key":"id","id_value":"coder-feb06d32-3252-4cd8-b7db-ea0c5145747f-home","elapsed_seconds":0},"type":"apply_complete"}
27+
{"@level":"info","@message":"docker_image.main: Creation complete after 0s [id=sha256:443d199e8bfcce69c2aa494b36b5f8b04c3b183277cd19190e9589fd8552d618nginx:latest]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.669954+02:00","hook":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create","id_key":"id","id_value":"sha256:443d199e8bfcce69c2aa494b36b5f8b04c3b183277cd19190e9589fd8552d618nginx:latest","elapsed_seconds":0},"type":"apply_complete"}
28+
{"@level":"info","@message":"docker_container.workspace[0]: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.682223+02:00","hook":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create"},"type":"apply_start"}
29+
{"@level":"info","@message":"docker_container.workspace[0]: Creation complete after 0s [id=e39f34233fe1f6d18a33eaed8ad47ef1ae19ccf8cf6841858d5f2dafe4e3c8c9]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.186482+02:00","hook":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create","id_key":"id","id_value":"e39f34233fe1f6d18a33eaed8ad47ef1ae19ccf8cf6841858d5f2dafe4e3c8c9","elapsed_seconds":0},"type":"apply_complete"}
30+
{"@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"}
31+
{"@level":"info","@message":"Outputs: 0","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.205051+02:00","outputs":{},"type":"outputs"}
32+
-- timings --
33+
{"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"}
34+
{"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"}
35+
{"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"}
36+
{"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"}
37+
{"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"}
38+
{"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"}

0 commit comments

Comments
 (0)