gvisor.dev/gvisor@v0.0.0-20240520182842-f9d4d51c7e0f/test/metricsviz/metricsviz.go (about) 1 // Copyright 2024 The gVisor Authors. 2 // 3 // Licensed under the Apache License, Version 2.0 (the "License"); 4 // you may not use this file except in compliance with the License. 5 // You may obtain a copy of the License at 6 // 7 // http://www.apache.org/licenses/LICENSE-2.0 8 // 9 // Unless required by applicable law or agreed to in writing, software 10 // distributed under the License is distributed on an "AS IS" BASIS, 11 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 12 // See the License for the specific language governing permissions and 13 // limitations under the License. 14 15 // Package metricsviz charts profiling metrics data and renders them to HTML. 16 package metricsviz 17 18 import ( 19 "bytes" 20 "context" 21 "errors" 22 "fmt" 23 "hash/adler32" 24 "os" 25 "path" 26 "regexp" 27 "slices" 28 "sort" 29 "strconv" 30 "strings" 31 "testing" 32 "time" 33 34 "github.com/docker/docker/api/types" 35 "github.com/go-echarts/go-echarts/v2/charts" 36 "github.com/go-echarts/go-echarts/v2/components" 37 "github.com/go-echarts/go-echarts/v2/opts" 38 echartstypes "github.com/go-echarts/go-echarts/v2/types" 39 "google.golang.org/protobuf/encoding/protojson" 40 "gvisor.dev/gvisor/pkg/metric" 41 mpb "gvisor.dev/gvisor/pkg/metric/metric_go_proto" 42 ) 43 44 const ( 45 htmlRawLogsPrefix = "GVISOR RAW LOGS:" 46 htmlRawLogsSuffix = "/END OF RAW GVISOR LOGS" 47 ) 48 49 // MetricName is the name of a metric. 50 type MetricName string 51 52 // Metric is the full metadata about a metric. 53 type Metric struct { 54 // Name is the name of the metric. 55 Name MetricName 56 // Metadata is the metadata of the metric. 57 Metadata *mpb.MetricMetadata 58 } 59 60 // MetricAndFields is a metric name and a set of field values. 61 type MetricAndFields struct { 62 // MetricName is the name of the metric. 63 MetricName MetricName 64 // FieldValues is the comma-concatenated version of the field values. 65 FieldValues string 66 } 67 68 // Point is a single data point at a given time within a time series. 69 type Point struct { 70 // When is the time at which the value was measured. 71 When time.Time 72 // Value is the value that was measured at that time. 73 Value uint64 74 } 75 76 // TimeSeries describes the evolution of a metric (for a given set of field 77 // values) over time. 78 type TimeSeries struct { 79 // Metric is the metric being measured. 80 Metric *Metric 81 // Fields is the set of field values of the metric. 82 FieldValues map[string]string 83 // Data is the timestamped set of data points for this metric and field 84 // values. 85 Data []Point 86 } 87 88 // String returns the name of the timeseries. 89 func (ts *TimeSeries) String() string { 90 if len(ts.FieldValues) == 0 { 91 if desc := strings.TrimSuffix(ts.Metric.Metadata.GetDescription(), "."); desc != "" { 92 return desc 93 } 94 return string(ts.Metric.Name) 95 } 96 orderedFields := make([]string, 0, len(ts.FieldValues)) 97 for f := range ts.FieldValues { 98 orderedFields = append(orderedFields, f) 99 } 100 sort.Strings(orderedFields) 101 var b strings.Builder 102 b.WriteString(string(ts.Metric.Name)) 103 b.WriteString("{") 104 for i, f := range orderedFields { 105 if i > 0 { 106 b.WriteString(",") 107 } 108 b.WriteString(f) 109 b.WriteString("=") 110 b.WriteString(ts.FieldValues[f]) 111 } 112 b.WriteString("}") 113 return b.String() 114 } 115 116 // Data maps metrics and field values to timeseries. 117 type Data struct { 118 startTime time.Time 119 rawLogs string 120 data map[MetricAndFields]*TimeSeries 121 } 122 123 // HTMLOptions are options for generating an HTML page with charts of the 124 // metrics data. 125 type HTMLOptions struct { 126 // Title is the title of this set of charts. 127 Title string 128 129 // ContainerName is the name of the container for which the metrics were 130 // collected. May be empty; usually only specified when there are more 131 // than one container involved in a single test or benchmark. 132 ContainerName string 133 134 // When is the time at which the measurements were taken. 135 When time.Time 136 } 137 138 type chart struct { 139 Title string 140 Series []*TimeSeries 141 } 142 143 // isCumulative returns whether the given series are all cumulative or all 144 // not cumulative. It returns an error if the series are a mix of cumulative 145 // and non-cumulative timeseries. 146 func (c *chart) isCumulative() (bool, error) { 147 var isCumulative bool 148 for i, ts := range c.Series { 149 tsCumulative := ts.Metric.Metadata.GetCumulative() 150 if i == 0 { 151 isCumulative = tsCumulative 152 } else if isCumulative != tsCumulative { 153 return false, fmt.Errorf("series %d (%v) is cumulative=%v, but series 0 (%v) is cumulative=%v", i, ts, tsCumulative, c.Series[0], isCumulative) 154 } 155 } 156 return isCumulative, nil 157 } 158 159 // getXAxis returns the X axis labels for the chart. 160 func (c *chart) getXAxis() ([]string, error) { 161 // Determine the resolution for the timestamps on the X axis. 162 // We do this depending on how long the time series we are charting is. 163 var xAxisResolution time.Duration 164 if len(c.Series) == 0 || len(c.Series[0].Data) < 2 { 165 return nil, errors.New("no series or not enough data points in series") 166 } 167 xMinTime := c.Series[0].Data[0].When 168 xMaxTime := c.Series[0].Data[len(c.Series[0].Data)-1].When 169 xDuration := xMaxTime.Sub(xMinTime) 170 switch { 171 case xDuration <= 11*time.Second: 172 xAxisResolution = time.Nanosecond 173 case xDuration <= 91*time.Second: 174 xAxisResolution = time.Microsecond 175 case xDuration <= 16*time.Minute: 176 xAxisResolution = time.Millisecond 177 default: 178 xAxisResolution = time.Second 179 } 180 formatXAxis := func(t time.Time) string { 181 secondTimestamp := t.Format("15:04:05") 182 nanos := t.Nanosecond() 183 onlyNanos := nanos % 1_000 184 onlyMicros := (nanos / 1_000) % 1_000 185 onlyMillis := (nanos / 1_000_000) % 1_000 186 switch xAxisResolution { 187 case time.Nanosecond: 188 return fmt.Sprintf("%s.%03d_%03d_%03d", secondTimestamp, onlyMillis, onlyMicros, onlyNanos) 189 case time.Microsecond: 190 return fmt.Sprintf("%s.%03d_%03d", secondTimestamp, onlyMillis, onlyMicros) 191 case time.Millisecond: 192 return fmt.Sprintf("%s.%03d", secondTimestamp, onlyMillis) 193 case time.Second: 194 return secondTimestamp 195 default: 196 panic("invalid x axis resolution") 197 } 198 } 199 var xAxis []string 200 for i, ts := range c.Series { 201 if i == 0 { 202 // Define the X axis. 203 xAxis = make([]string, len(ts.Data)) 204 for i, p := range ts.Data { 205 xAxis[i] = formatXAxis(p.When) 206 } 207 } else { 208 // Check that the X axis is the same for all series. 209 if len(xAxis) != len(ts.Data) { 210 return nil, fmt.Errorf("series %d has %d data points, but series 0 has %d", i, len(ts.Data), len(xAxis)) 211 } 212 for j, p := range ts.Data { 213 if xAxis[j] != formatXAxis(p.When) { 214 return nil, fmt.Errorf("series %d and series 0 differ at data point %d: %q vs %q", i, j, xAxis[j], formatXAxis(p.When)) 215 } 216 } 217 } 218 } 219 return xAxis, nil 220 } 221 222 // series returns a single line series of the chart. 223 func (c *chart) series(ts *TimeSeries, isCumulative bool) ([]opts.LineData, error) { 224 const windowDuration = time.Second 225 seriesData := make([]opts.LineData, len(ts.Data)) 226 if isCumulative { 227 lastValidXIndex := 0 228 for i, p := range ts.Data { 229 baselineWhen := p.When.Add(-windowDuration) 230 foundExactIndex := -1 231 foundBeforeIndex := -1 232 foundAfterIndex := -1 233 baselineSearch: 234 for j := lastValidXIndex; j <= i; j++ { 235 jWhen := ts.Data[j].When 236 switch { 237 case jWhen.Equal(baselineWhen): 238 foundExactIndex = j 239 break baselineSearch 240 case jWhen.Before(baselineWhen): 241 foundBeforeIndex = j 242 case jWhen.After(baselineWhen) && foundAfterIndex == -1: 243 foundAfterIndex = j 244 break baselineSearch 245 default: 246 return nil, fmt.Errorf("non-ordered timestamps in timeseries: %v", ts.Data) 247 } 248 } 249 switch { 250 case foundExactIndex != -1: 251 lastValidXIndex = foundExactIndex 252 baseline := ts.Data[foundExactIndex].Value 253 seriesData[i] = opts.LineData{Value: p.Value - baseline, YAxisIndex: 0} 254 case foundBeforeIndex != -1 && foundAfterIndex != -1: 255 lastValidXIndex = foundBeforeIndex 256 // Interpolate between the two points. 257 baselineBefore := ts.Data[foundBeforeIndex].Value 258 baselineAfter := ts.Data[foundAfterIndex].Value 259 baselineDelta := baselineAfter - baselineBefore 260 whenBefore := ts.Data[foundBeforeIndex].When 261 whenAfter := ts.Data[foundAfterIndex].When 262 whenDelta := whenAfter.Sub(whenBefore) 263 baselineWhenFraction := float64(baselineWhen.Sub(whenBefore)) / float64(whenDelta) 264 baseline := baselineBefore + uint64(float64(baselineDelta)*baselineWhenFraction) 265 seriesData[i] = opts.LineData{Value: p.Value - baseline, YAxisIndex: 0, Symbol: "none"} 266 default: 267 // Happens naturally for points too early in the timeseries, 268 // set the point to nil. 269 seriesData[i] = opts.LineData{Value: nil, YAxisIndex: 0, Symbol: "none"} 270 } 271 } 272 } else { 273 // Non-cumulative time series are more straightforward. 274 for i, p := range ts.Data { 275 seriesData[i] = opts.LineData{Value: p.Value, YAxisIndex: 0, Symbol: "none"} 276 } 277 } 278 return seriesData, nil 279 } 280 281 // Charter creates a Charter for this chart. 282 func (c *chart) Charter() (components.Charter, error) { 283 lineChart := charts.NewLine() 284 yAxis := opts.YAxis{ 285 Scale: true, 286 Show: true, 287 } 288 isCumulative, err := c.isCumulative() 289 if err != nil { 290 return nil, fmt.Errorf("cannot determine cumulative-ness of the chart: %w", err) 291 } 292 xAxis, err := c.getXAxis() 293 if err != nil { 294 return nil, fmt.Errorf("cannot determine X axis of the chart: %w", err) 295 } 296 for _, ts := range c.Series { 297 seriesData, err := c.series(ts, isCumulative) 298 if err != nil { 299 return nil, fmt.Errorf("cannot determine series data for %v: %w", ts, err) 300 } 301 lineChart.AddSeries( 302 ts.String(), 303 seriesData, 304 charts.WithLabelOpts(opts.Label{Show: false}), 305 ) 306 } 307 chartTitle := c.Title 308 if isCumulative { 309 chartTitle += " per second" 310 yAxis.Name = "per second" 311 } 312 lineChart.SetXAxis(xAxis) 313 lineChart.SetGlobalOptions( 314 charts.WithTitleOpts(opts.Title{Title: chartTitle}), 315 charts.WithInitializationOpts(opts.Initialization{Theme: echartstypes.ThemeVintage}), 316 charts.WithXAxisOpts(opts.XAxis{ 317 Show: true, 318 Data: []string{"foo", "bar"}, 319 SplitNumber: 24, 320 AxisLabel: &opts.AxisLabel{Show: true}, 321 }), 322 charts.WithYAxisOpts(yAxis, 0), 323 charts.WithLegendOpts(opts.Legend{ 324 Show: true, 325 SelectedMode: "multiple", 326 Orient: "vertical", 327 Right: "5%", 328 Padding: []int{24, 8}, 329 }), 330 charts.WithDataZoomOpts(opts.DataZoom{Type: "inside", XAxisIndex: 0}), 331 charts.WithDataZoomOpts(opts.DataZoom{Type: "slider", XAxisIndex: 0}), 332 charts.WithDataZoomOpts(opts.DataZoom{Type: "inside", YAxisIndex: 0}), 333 charts.WithTooltipOpts(opts.Tooltip{Show: true, Trigger: "axis"}), 334 charts.WithToolboxOpts(opts.Toolbox{ 335 Show: true, 336 Feature: &opts.ToolBoxFeature{ 337 SaveAsImage: &opts.ToolBoxFeatureSaveAsImage{Name: "📸 PNG", Show: true, Type: "png"}, 338 }, 339 }), 340 ) 341 lineChart.Validate() 342 return lineChart, nil 343 } 344 345 // ToHTML generates an HTML page with charts of the metrics data. 346 func (d *Data) ToHTML(opts HTMLOptions) (string, error) { 347 page := components.NewPage() 348 var chartTitleRoot string 349 if opts.ContainerName == "" { 350 chartTitleRoot = opts.Title 351 page.PageTitle = fmt.Sprintf("Metrics for %s at %v", opts.Title, opts.When.Format(time.DateTime)) 352 } else { 353 chartTitleRoot = fmt.Sprintf("%s [%s]", opts.Title, opts.ContainerName) 354 page.PageTitle = fmt.Sprintf("Metrics for %s (container %s) at %v", opts.Title, opts.ContainerName, opts.When.Format(time.DateTime)) 355 } 356 page.Theme = echartstypes.ThemeVintage 357 page.SetLayout(components.PageFlexLayout) 358 359 // Find which groups contain which metrics that we're seeing in the data. 360 groupsToMetricNames := make(map[GroupName][]MetricName, len(d.data)) 361 for maf := range d.data { 362 for groupName, metricsInGroup := range Groups { 363 if slices.Contains(metricsInGroup, maf.MetricName) && !slices.Contains(groupsToMetricNames[groupName], maf.MetricName) { 364 groupsToMetricNames[groupName] = append(groupsToMetricNames[groupName], maf.MetricName) 365 } 366 } 367 } 368 369 // Find which groups for which we have data for at least 2 metrics. 370 // These metrics will be displayed in the group charts only. 371 // The rest of the metrics will be displayed in their own chart. 372 metricToGroups := make(map[MetricName][]GroupName, len(d.data)) 373 for groupName, activeGroupMetrics := range groupsToMetricNames { 374 if len(activeGroupMetrics) >= 2 { 375 for _, m := range activeGroupMetrics { 376 metricToGroups[m] = append(metricToGroups[m], groupName) 377 } 378 } 379 } 380 381 // Now go through the data and group it by the chart it'll end up in. 382 chartNameToChart := make(map[string]*chart, len(d.data)) 383 var chartNames []string 384 for maf, ts := range d.data { 385 groupsForMetric := metricToGroups[maf.MetricName] 386 if len(groupsForMetric) > 0 { 387 // Group metric chart. 388 for _, groupName := range groupsForMetric { 389 chartName := string(groupName) 390 c, ok := chartNameToChart[chartName] 391 if !ok { 392 c = &chart{Title: fmt.Sprintf("%s: %s", chartTitleRoot, groupName)} 393 chartNameToChart[chartName] = c 394 chartNames = append(chartNames, chartName) 395 } 396 c.Series = append(c.Series, ts) 397 } 398 } else { 399 // Individual metric chart. 400 chartName := string(maf.MetricName) 401 c, ok := chartNameToChart[chartName] 402 if !ok { 403 c = &chart{Title: fmt.Sprintf("%s: %s", chartTitleRoot, ts.String())} 404 chartNameToChart[chartName] = c 405 chartNames = append(chartNames, chartName) 406 } 407 c.Series = append(c.Series, ts) 408 } 409 } 410 sort.Strings(chartNames) 411 for _, chartName := range chartNames { 412 c := chartNameToChart[chartName] 413 charter, err := c.Charter() 414 if err != nil { 415 return "", fmt.Errorf("failed to create charter for %q: %w", chartName, err) 416 } 417 page.AddCharts(charter) 418 } 419 page.InitAssets() 420 page.Validate() 421 var b bytes.Buffer 422 if err := page.Render(&b); err != nil { 423 return "", fmt.Errorf("failed to render page: %w", err) 424 } 425 html := b.String() 426 427 // Insert raw logs in the HTML file itself as a comment. 428 const headTag = "<head>" 429 headTagIndex := strings.Index(html, headTag) 430 if headTagIndex == -1 { 431 return "", fmt.Errorf("no <head> tag found in HTML") 432 } 433 headTagFinishIndex := headTagIndex + len(headTag) 434 html = html[:headTagFinishIndex] + "\n<!--\n" + htmlRawLogsPrefix + "\n" + d.rawLogs + "\n" + htmlRawLogsSuffix + "\n-->\n" + html[headTagFinishIndex:] 435 return html, nil 436 } 437 438 // ErrNoMetricData is returned when no metrics data is found in logs. 439 var ErrNoMetricData = errors.New("no metrics data found") 440 441 // Parse parses metrics data out of the given logs containing 442 // profiling metrics data. 443 // If `hasPrefix`, only lines prefixed with `metric.MetricsPrefix` 444 // will be parsed. If false, all lines will be parsed, and the 445 // prefix will be stripped if it is found. 446 // If the log does not contain any metrics data, ErrNoMetricData is returned. 447 // If the log does contain data but not all lines can be validated, an error 448 // is returned but the returned `*Data` is still populated as much as 449 // possible. 450 func Parse(logs string, hasPrefix bool) (*Data, error) { 451 data := &Data{rawLogs: logs, data: make(map[MetricAndFields]*TimeSeries)} 452 var header []MetricAndFields 453 metricsMeta := make(map[MetricName]*Metric) 454 lineChecksum := adler32.New() 455 overallChecksum := adler32.New() 456 checkedHash := false 457 lineHashMismatch := false 458 metricsLineFound := false 459 var gotErrs []error 460 for _, line := range strings.Split(logs, "\n") { 461 if hasPrefix && !strings.HasPrefix(line, metric.MetricsPrefix) { 462 continue 463 } 464 if line == "" { 465 continue 466 } 467 metricsLineFound = true 468 lineData := strings.TrimPrefix(line, metric.MetricsPrefix) 469 470 // Check for hash match. 471 if strings.HasPrefix(lineData, metric.MetricsHashIndicator) { 472 hash := strings.TrimPrefix(lineData, metric.MetricsHashIndicator) 473 wantHashInt64, err := strconv.ParseUint(strings.TrimPrefix(hash, "0x"), 16, 32) 474 if err != nil { 475 gotErrs = append(gotErrs, fmt.Errorf("invalid hash line: %q: %w", line, err)) 476 continue 477 } 478 checkedHash = true 479 wantHash := uint32(wantHashInt64) 480 if gotHash := overallChecksum.Sum32(); gotHash != wantHash { 481 // If there has already been a line checksum mismatch, we already know 482 // that the overall checksum won't match either, so no need to add 483 // another error about it here. 484 if !lineHashMismatch { 485 gotErrs = append(gotErrs, fmt.Errorf("checksum mismatch: computed 0x%x, logs said it should be 0x%x. This is likely due to a log buffer overrun or similar issue causing some lines to be omitted; please configure the container or the runtime to allow higher logging volume", gotHash, wantHash)) 486 } 487 } 488 continue 489 } 490 491 // If it's not a hash line, add it to the hash regardless of which other 492 // type of line it is. 493 overallChecksum.Write([]byte(lineData)) 494 overallChecksum.Write([]byte("\n")) 495 496 if hasPrefix { 497 // There should be a per-line checksum at the end of each line. 498 tabSplit := strings.Split(lineData, "\t") 499 if len(tabSplit) < 2 { 500 gotErrs = append(gotErrs, fmt.Errorf("invalid line: %q (no tab separator found)", line)) 501 continue 502 } 503 lineChecksum.Reset() 504 lineChecksum.Write([]byte(strings.Join(tabSplit[:len(tabSplit)-1], "\t"))) 505 wantLineChecksum := fmt.Sprintf("0x%x", lineChecksum.Sum32()) 506 if gotLineChecksum := tabSplit[len(tabSplit)-1]; gotLineChecksum != wantLineChecksum { 507 gotErrs = append(gotErrs, fmt.Errorf("per-line checksum mismatch: computed 0x%x, line said it should be 0x%x (%q). This is likely due to a log buffer overrun or similar issue causing some lines to be omitted; please configure the container or the runtime to allow higher logging volume", wantLineChecksum, gotLineChecksum, line)) 508 lineHashMismatch = true 509 continue 510 } 511 lineData = strings.Join(tabSplit[:len(tabSplit)-1], "\t") 512 } 513 514 if strings.HasPrefix(lineData, metric.MetricsMetaIndicator) { 515 lineMetadata := strings.TrimPrefix(lineData, metric.MetricsMetaIndicator) 516 components := strings.Split(lineMetadata, "\t") 517 if len(components) != 2 { 518 return nil, fmt.Errorf("invalid meta line: %q", line) 519 } 520 name := MetricName(components[0]) 521 var metadata mpb.MetricMetadata 522 if err := protojson.Unmarshal([]byte(components[1]), &metadata); err != nil { 523 return nil, fmt.Errorf("invalid metric metadata line: %q", line) 524 } 525 metricsMeta[name] = &Metric{ 526 Name: name, 527 Metadata: &metadata, 528 } 529 continue 530 } 531 532 if strings.HasPrefix(lineData, metric.MetricsStartTimeIndicator) { 533 timestamp, err := strconv.ParseUint(strings.TrimPrefix(lineData, metric.MetricsStartTimeIndicator), 10, 64) 534 if err != nil { 535 return nil, fmt.Errorf("invalid start time line: %q: %w", line, err) 536 } 537 const nanosPerSecond = 1_000_000_000 538 data.startTime = time.Unix(int64(timestamp/nanosPerSecond), int64(timestamp%nanosPerSecond)) 539 continue 540 } 541 542 // Check for the header line. 543 if header == nil { 544 // Assume the first non-metadata line is the header. 545 headerCells := strings.Split(lineData, "\t") 546 if headerCells[0] != metric.TimeColumn { 547 return nil, fmt.Errorf("invalid header line: %q", line) 548 } 549 for i, cell := range headerCells[1:] { 550 if hasPrefix && i == len(headerCells)-2 && cell == "Checksum" { 551 // Ignore this column name; it is the column indicator for the per-line checksum. 552 continue 553 } 554 // If metric fields were to be implemented, they would be part of 555 // the header cell here. For now we just assume that the header 556 // cells are just metric names. 557 name := MetricName(cell) 558 if _, ok := metricsMeta[name]; !ok { 559 return nil, fmt.Errorf("invalid header line: %q (unknown metric %q)", line, name) 560 } 561 maf := MetricAndFields{MetricName: name} 562 header = append(header, maf) 563 data.data[maf] = &TimeSeries{Metric: metricsMeta[name]} 564 } 565 if len(header) != len(metricsMeta) { 566 return nil, fmt.Errorf("invalid header line: %q (header has %d metrics (%+v), but %d metrics were found in metadata: %v)", line, len(header), header, len(metricsMeta), metricsMeta) 567 } 568 continue 569 } 570 571 // Regular lines. 572 tabularData := strings.Split(lineData, "\t") 573 if len(tabularData) != len(header)+1 { 574 return nil, fmt.Errorf("invalid data line: %q with %d components which does not match header which has %d components. This is likely due to a log buffer overrun or similar issue causing the line to be cut off; please configure the container or the runtime to allow higher logging volume", line, len(tabularData), len(header)) 575 } 576 offsetNanos, err := strconv.ParseUint(tabularData[0], 10, 64) 577 if err != nil { 578 return nil, fmt.Errorf("invalid data line: %q (bad timestamp: %w)", line, err) 579 } 580 timestamp := data.startTime.Add(time.Duration(offsetNanos) * time.Nanosecond) 581 for i, cell := range tabularData[1:] { 582 timeseries := data.data[header[i]] 583 value, err := strconv.ParseUint(cell, 10, 64) 584 if err != nil { 585 return nil, fmt.Errorf("invalid data line: %q (bad value in column %d: %q: %w)", line, i, cell, err) 586 } 587 timeseries.Data = append(timeseries.Data, Point{When: timestamp, Value: value}) 588 } 589 } 590 if !metricsLineFound { 591 return nil, ErrNoMetricData 592 } 593 if data.startTime.IsZero() { 594 return nil, fmt.Errorf("no start time found in logs") 595 } 596 if len(header) == 0 { 597 return nil, fmt.Errorf("no header found in logs") 598 } 599 if hasPrefix && !checkedHash { 600 gotErrs = append(gotErrs, fmt.Errorf("no hash data found in logs")) 601 } 602 switch len(gotErrs) { 603 case 0: 604 return data, nil 605 case 1: 606 return data, gotErrs[0] 607 default: 608 return data, fmt.Errorf("multiple errors found in logs: %v", gotErrs) 609 } 610 } 611 612 var unsafeFileCharacters = regexp.MustCompile("[^-_a-zA-Z0-9., @:+=]+") 613 614 // slugify returns a slugified version of the given string, safe for use 615 // in a file path. 616 func slugify(s string) string { 617 s = strings.ReplaceAll(s, "/", "_") 618 s = unsafeFileCharacters.ReplaceAllString(s, "_") 619 if s == "" { 620 return "blank" 621 } 622 return s 623 } 624 625 // Container represents a container that can be stopped and from which we can 626 // get logs. 627 type Container interface { 628 Stop(context.Context) error 629 Status(context.Context) (types.ContainerState, error) 630 Logs(context.Context) (string, error) 631 } 632 633 // FromContainerLogs parses a container's logs and reports metrics data 634 // found within. 635 // The container must be stopped or stoppable by the time this is called. 636 func FromContainerLogs(ctx context.Context, testLike testing.TB, container Container) { 637 FromNamedContainerLogs(ctx, testLike, container, "") 638 } 639 640 // FromNamedContainerLogs parses a container's logs and reports metrics data 641 // found within, making note of the container's name on the results page. 642 // The container must be stopped or stoppable by the time this is called. 643 func FromNamedContainerLogs(ctx context.Context, testLike testing.TB, container Container, containerName string) { 644 // If the container is not stopped, stop it. 645 // This is necessary to flush the profiling metrics logs. 646 st, err := container.Status(ctx) 647 if err != nil { 648 testLike.Fatalf("Failed to get container status: %v", err) 649 } 650 if st.Running { 651 if err := container.Stop(ctx); err != nil { 652 testLike.Fatalf("Failed to stop container: %v", err) 653 } 654 } 655 // Get the logs. 656 logs, err := container.Logs(ctx) 657 if err != nil { 658 testLike.Fatalf("Failed to get container logs: %v", err) 659 } 660 data, err := Parse(logs, true) 661 if err != nil { 662 if errors.Is(err, ErrNoMetricData) { 663 return // No metric data in the logs, so stay quiet. 664 } 665 if data == nil { 666 testLike.Fatalf("Failed to parse metrics data: %v", err) 667 } 668 testLike.Logf("Error while parsing metrics data (data may be incomplete): %v", err) 669 } 670 htmlOptions := HTMLOptions{ 671 Title: testLike.Name(), 672 ContainerName: containerName, 673 When: data.startTime, 674 } 675 html, err := data.ToHTML(htmlOptions) 676 if err != nil { 677 testLike.Fatalf("Failed to generate HTML: %v", err) 678 } 679 if err := publishHTMLFn(ctx, testLike.Logf, htmlOptions, html); err != nil { 680 testLike.Fatalf("Failed to publish HTML: %v", err) 681 } 682 } 683 684 // FromProfilingMetricsLogFile parses a profiling metrics log file 685 // (as created by --profiling-metrics-log) and reports metrics data within. 686 func FromProfilingMetricsLogFile(ctx context.Context, testLike testing.TB, logFile string) { 687 contents, err := os.ReadFile(logFile) 688 if err != nil { 689 testLike.Fatalf("failed to read log file: %v", err) 690 } 691 if err := fromFile(ctx, testLike.Name(), logFile, contents, false, testLike.Logf); err != nil { 692 testLike.Fatalf("Failed to process metrics logs file: %v", err) 693 } 694 } 695 696 // FromFile reads a file and detects whether it is a profiling metrics log 697 // file or a file with GVISOR_METRICS-prefixed lines. 698 // Either way, it parses the metrics data and reports it. 699 func FromFile(ctx context.Context, logFile string, logFn func(string, ...any)) error { 700 contents, err := os.ReadFile(logFile) 701 if err != nil { 702 return fmt.Errorf("failed to read log file: %w", err) 703 } 704 lines := strings.Split(string(contents), "\n") 705 logName := strings.TrimSuffix(path.Base(logFile), ".log") 706 foundRawHTMLPrefix := -1 707 foundRawHTMLSuffix := -1 708 for i, line := range lines { 709 line = strings.TrimSpace(line) 710 if line == htmlRawLogsPrefix { 711 foundRawHTMLPrefix = i 712 } else if line == htmlRawLogsSuffix { 713 foundRawHTMLSuffix = i 714 } 715 } 716 if foundRawHTMLPrefix != -1 && foundRawHTMLSuffix != -1 { 717 // Isolate the contents of the raw logs from inside the HTML file. 718 lines = lines[foundRawHTMLPrefix+1 : foundRawHTMLSuffix] 719 contents = []byte(strings.Join(lines, "\n")) 720 } 721 for _, line := range lines { 722 if line == "" { 723 continue 724 } 725 if strings.HasPrefix(line, metric.MetricsPrefix) { 726 return fromFile(ctx, logName, logFile, contents, true, logFn) 727 } 728 if strings.HasPrefix(line, metric.TimeColumn) { 729 return fromFile(ctx, logName, logFile, contents, false, logFn) 730 } 731 } 732 return fmt.Errorf("could not recognize %q as a metrics log file", logFile) 733 } 734 735 func fromFile(ctx context.Context, name, logFile string, logContents []byte, hasPrefix bool, logFn func(string, ...any)) error { 736 data, err := Parse(string(logContents), hasPrefix) 737 if err != nil { 738 if errors.Is(err, ErrNoMetricData) { 739 return nil // No metric data in the logs, so stay quiet. 740 } 741 if data == nil { 742 return fmt.Errorf("failed to parse metrics data: %w", err) 743 } 744 logFn("Error while parsing metrics data (data may be incomplete): %v", err) 745 } 746 htmlOptions := HTMLOptions{ 747 Title: name, 748 When: data.startTime, 749 } 750 html, err := data.ToHTML(htmlOptions) 751 if err != nil { 752 return fmt.Errorf("failed to generate HTML: %w", err) 753 } 754 if strings.HasSuffix(logFile, ".log") { 755 // Best-effort conversion to HTML next to the .log file in the directory, 756 // if permissions allow that. Ignore errors, what matters more is the 757 // publishing step later on. 758 _ = os.WriteFile(strings.TrimSuffix(logFile, ".log")+".html", []byte(html), 0644) 759 } 760 if err := publishHTMLFn(ctx, logFn, htmlOptions, html); err != nil { 761 return fmt.Errorf("failed to publish HTML: %w", err) 762 } 763 return nil 764 }