github.com/minio/mc@v0.0.0-20240503112107-b471de8d1882/cmd/admin-trace.go (about) 1 // Copyright (c) 2015-2022 MinIO, Inc. 2 // 3 // This file is part of MinIO Object Storage stack 4 // 5 // This program is free software: you can redistribute it and/or modify 6 // it under the terms of the GNU Affero General Public License as published by 7 // the Free Software Foundation, either version 3 of the License, or 8 // (at your option) any later version. 9 // 10 // This program is distributed in the hope that it will be useful 11 // but WITHOUT ANY WARRANTY; without even the implied warranty of 12 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 13 // GNU Affero General Public License for more details. 14 // 15 // You should have received a copy of the GNU Affero General Public License 16 // along with this program. If not, see <http://www.gnu.org/licenses/>. 17 18 package cmd 19 20 import ( 21 "bytes" 22 "context" 23 "fmt" 24 "hash/fnv" 25 "net/http" 26 "net/url" 27 "path" 28 "sort" 29 "strconv" 30 "strings" 31 "sync" 32 "time" 33 34 "github.com/charmbracelet/bubbles/spinner" 35 tea "github.com/charmbracelet/bubbletea" 36 "github.com/charmbracelet/lipgloss" 37 "github.com/dustin/go-humanize" 38 "github.com/fatih/color" 39 "github.com/minio/cli" 40 json "github.com/minio/colorjson" 41 "github.com/minio/madmin-go/v3" 42 "github.com/minio/mc/pkg/probe" 43 "github.com/minio/pkg/v2/console" 44 "github.com/olekukonko/tablewriter" 45 ) 46 47 var adminTraceFlags = []cli.Flag{ 48 cli.BoolFlag{ 49 Name: "verbose, v", 50 Usage: "print verbose trace", 51 }, 52 cli.BoolFlag{ 53 Name: "all, a", 54 Usage: "trace all call types", 55 }, 56 cli.StringSliceFlag{ 57 Name: "call", 58 Usage: "trace only matching call types. See CALL TYPES below for list. (default: s3)", 59 }, 60 cli.IntSliceFlag{ 61 Name: "status-code", 62 Usage: "trace only matching status code", 63 }, 64 cli.StringSliceFlag{ 65 Name: "method", 66 Usage: "trace only matching HTTP method", 67 }, 68 cli.StringSliceFlag{ 69 Name: "funcname", 70 Usage: "trace only matching func name", 71 }, 72 cli.StringSliceFlag{ 73 Name: "path", 74 Usage: "trace only matching path", 75 }, 76 cli.StringSliceFlag{ 77 Name: "node", 78 Usage: "trace only matching servers", 79 }, 80 cli.StringSliceFlag{ 81 Name: "request-header", 82 Usage: "trace only matching request headers", 83 }, 84 cli.StringSliceFlag{ 85 Name: "request-query", 86 Usage: "trace only matching request queries", 87 }, 88 cli.BoolFlag{ 89 Name: "errors, e", 90 Usage: "trace only failed requests", 91 }, 92 cli.BoolFlag{ 93 Name: "stats", 94 Usage: "accumulate stats", 95 }, 96 cli.IntFlag{ 97 Name: "stats-n", 98 Usage: "maximum number of stat entries", 99 Value: 15, 100 Hidden: true, 101 }, 102 cli.BoolFlag{ 103 Name: "filter-request", 104 Usage: "trace calls only with request bytes greater than this threshold, use with filter-size", 105 }, 106 cli.BoolFlag{ 107 Name: "filter-response", 108 Usage: "trace calls only with response bytes greater than this threshold, use with filter-size", 109 }, 110 cli.DurationFlag{ 111 Name: "response-duration", 112 Usage: "trace calls only with response duration greater than this threshold (e.g. `5ms`)", 113 }, 114 cli.StringFlag{ 115 Name: "filter-size", 116 Usage: "filter size, use with filter (see UNITS)", 117 }, 118 } 119 120 // traceCallTypes contains all call types and flags to apply when selected. 121 var traceCallTypes = map[string]func(o *madmin.ServiceTraceOpts) (help string){ 122 "storage": func(o *madmin.ServiceTraceOpts) string { o.Storage = true; return "Trace Storage calls" }, 123 "internal": func(o *madmin.ServiceTraceOpts) string { o.Internal = true; return "Trace Internal RPC calls" }, 124 "s3": func(o *madmin.ServiceTraceOpts) string { o.S3 = true; return "Trace S3 API calls" }, 125 "os": func(o *madmin.ServiceTraceOpts) string { o.OS = true; return "Trace Operating System calls" }, 126 "scanner": func(o *madmin.ServiceTraceOpts) string { o.Scanner = true; return "Trace Scanner calls" }, 127 "bootstrap": func(o *madmin.ServiceTraceOpts) string { o.Bootstrap = true; return "Trace Bootstrap operations" }, 128 "ilm": func(o *madmin.ServiceTraceOpts) string { o.ILM = true; return "Trace ILM operations" }, 129 "ftp": func(o *madmin.ServiceTraceOpts) string { o.FTP = true; return "Trace FTP operations" }, 130 131 "healing": func(o *madmin.ServiceTraceOpts) string { 132 o.Healing = true 133 return "Trace Healing operations (alias: heal)" 134 }, 135 "batch-replication": func(o *madmin.ServiceTraceOpts) string { 136 o.BatchReplication = true 137 return "Trace Batch Replication (alias: brep)" 138 }, 139 "batch-keyrotation": func(o *madmin.ServiceTraceOpts) string { 140 o.BatchKeyRotation = true 141 return "Trace Batch KeyRotation (alias: brot)" 142 }, 143 "batch-expiration": func(o *madmin.ServiceTraceOpts) string { 144 o.BatchExpire = true 145 return "Trace Batch Expiration (alias: bexp)" 146 }, 147 148 "decommission": func(o *madmin.ServiceTraceOpts) string { 149 o.Decommission = true 150 return "Trace Decommission operations (alias: decom)" 151 }, 152 "rebalance": func(o *madmin.ServiceTraceOpts) string { 153 o.Rebalance = true 154 return "Trace Server Pool Rebalancing operations" 155 }, 156 "replication-resync": func(o *madmin.ServiceTraceOpts) string { 157 o.ReplicationResync = true 158 return "Trace Replication Resync operations (alias: resync)" 159 }, 160 } 161 162 // traceCallTypes contains aliases (short versions) of 163 var traceCallTypeAliases = map[string]func(o *madmin.ServiceTraceOpts) string{ 164 "heal": traceCallTypes["healing"], 165 "decom": traceCallTypes["decommission"], 166 "resync": traceCallTypes["replication-resync"], 167 "brep": traceCallTypes["batch-replication"], 168 "brot": traceCallTypes["batch-keyrotation"], 169 } 170 171 func traceCallsHelp() string { 172 var help []string 173 o := madmin.ServiceTraceOpts{} 174 const padkeyLen = 19 175 for k, fn := range traceCallTypes { 176 pad := "" 177 if len(k) < padkeyLen { 178 pad = strings.Repeat(" ", padkeyLen-len(k)) 179 } 180 help = append(help, fmt.Sprintf(" %s: %s%s", k, pad, fn(&o))) 181 } 182 sort.Strings(help) 183 return strings.Join(help, "\n") 184 } 185 186 var adminTraceCmd = cli.Command{ 187 Name: "trace", 188 Usage: "Show HTTP call trace for all incoming and internode on MinIO", 189 Action: mainAdminTrace, 190 OnUsageError: onUsageError, 191 Before: setGlobalsFromContext, 192 Flags: append(adminTraceFlags, globalFlags...), 193 HideHelpCommand: true, 194 CustomHelpTemplate: `NAME: 195 {{.HelpName}} - {{.Usage}} 196 197 USAGE: 198 {{.HelpName}} [FLAGS] TARGET 199 200 FLAGS: 201 {{range .VisibleFlags}}{{.}} 202 {{end}} 203 CALL TYPES: 204 ` + traceCallsHelp() + ` 205 206 UNITS 207 --filter-size flags use with --filter-response or --filter-request accept human-readable case-insensitive number 208 suffixes such as "k", "m", "g" and "t" referring to the metric units KB, 209 MB, GB and TB respectively. Adding an "i" to these prefixes, uses the IEC 210 units, so that "gi" refers to "gibibyte" or "GiB". A "b" at the end is 211 also accepted. Without suffixes the unit is bytes. 212 213 EXAMPLES: 214 1. Show verbose console trace for MinIO server 215 {{.Prompt}} {{.HelpName}} -v -a myminio 216 217 2. Show trace only for failed requests for MinIO server 218 {{.Prompt}} {{.HelpName}} -v -e myminio 219 220 3. Show verbose console trace for requests with '503' status code 221 {{.Prompt}} {{.HelpName}} -v --status-code 503 myminio 222 223 4. Show console trace for a specific path 224 {{.Prompt}} {{.HelpName}} --path my-bucket/my-prefix/* myminio 225 226 5. Show console trace for requests with '404' and '503' status code 227 {{.Prompt}} {{.HelpName}} --status-code 404 --status-code 503 myminio 228 229 6. Show trace only for requests bytes greater than 1MB 230 {{.Prompt}} {{.HelpName}} --filter-request --filter-size 1MB myminio 231 232 7. Show trace only for response bytes greater than 1MB 233 {{.Prompt}} {{.HelpName}} --filter-response --filter-size 1MB myminio 234 235 8. Show trace only for requests operations duration greater than 5ms 236 {{.Prompt}} {{.HelpName}} --response-duration 5ms myminio 237 `, 238 } 239 240 const traceTimeFormat = "2006-01-02T15:04:05.000" 241 242 var colors = []color.Attribute{color.FgCyan, color.FgWhite, color.FgYellow, color.FgGreen} 243 244 func checkAdminTraceSyntax(ctx *cli.Context) { 245 if len(ctx.Args()) != 1 { 246 showCommandHelpAndExit(ctx, 1) // last argument is exit code 247 } 248 filterFlag := ctx.Bool("filter-request") || ctx.Bool("filter-response") 249 if filterFlag && ctx.String("filter-size") == "" { 250 // filter must use with filter-size flags 251 showCommandHelpAndExit(ctx, 1) 252 } 253 254 if ctx.Bool("all") && len(ctx.StringSlice("call")) > 0 { 255 fatalIf(errDummy().Trace(), "You cannot specify both --all and --call flags at the same time.") 256 } 257 } 258 259 func printTrace(verbose bool, traceInfo madmin.ServiceTraceInfo) { 260 if verbose { 261 printMsg(traceMessage{ServiceTraceInfo: traceInfo}) 262 } else { 263 printMsg(shortTrace(traceInfo)) 264 } 265 } 266 267 type matchString struct { 268 val string 269 reverse bool 270 } 271 272 type matchOpts struct { 273 statusCodes []int 274 methods []string 275 funcNames []string 276 apiPaths []string 277 nodes []string 278 reqHeaders []matchString 279 reqQueries []matchString 280 requestSize uint64 281 responseSize uint64 282 } 283 284 func (opts matchOpts) matches(traceInfo madmin.ServiceTraceInfo) bool { 285 // Filter request path if passed by the user 286 if len(opts.apiPaths) > 0 { 287 matched := false 288 for _, apiPath := range opts.apiPaths { 289 if pathMatch(path.Join("/", apiPath), traceInfo.Trace.Path) { 290 matched = true 291 break 292 } 293 } 294 if !matched { 295 return false 296 } 297 } 298 299 // Filter response status codes if passed by the user 300 if len(opts.statusCodes) > 0 { 301 matched := false 302 for _, code := range opts.statusCodes { 303 if traceInfo.Trace.HTTP != nil && traceInfo.Trace.HTTP.RespInfo.StatusCode == code { 304 matched = true 305 break 306 } 307 } 308 if !matched { 309 return false 310 } 311 312 } 313 314 // Filter request method if passed by the user 315 if len(opts.methods) > 0 { 316 matched := false 317 for _, method := range opts.methods { 318 if traceInfo.Trace.HTTP != nil && traceInfo.Trace.HTTP.ReqInfo.Method == method { 319 matched = true 320 break 321 } 322 } 323 if !matched { 324 return false 325 } 326 327 } 328 329 if len(opts.funcNames) > 0 { 330 matched := false 331 // Filter request function handler names if passed by the user. 332 for _, funcName := range opts.funcNames { 333 if nameMatch(funcName, traceInfo.Trace.FuncName) { 334 matched = true 335 break 336 } 337 } 338 if !matched { 339 return false 340 } 341 } 342 343 if len(opts.nodes) > 0 { 344 matched := false 345 // Filter request by node if passed by the user. 346 for _, node := range opts.nodes { 347 if nameMatch(node, traceInfo.Trace.NodeName) { 348 matched = true 349 break 350 } 351 } 352 if !matched { 353 return false 354 } 355 } 356 357 if len(opts.reqHeaders) > 0 && traceInfo.Trace.HTTP != nil { 358 matched := false 359 for _, hdr := range opts.reqHeaders { 360 headerFound := false 361 for traceHdr, traceVals := range traceInfo.Trace.HTTP.ReqInfo.Headers { 362 for _, traceVal := range traceVals { 363 if patternMatch(hdr.val, traceHdr+": "+traceVal) { 364 headerFound = true 365 goto exitFindingHeader 366 } 367 } 368 } 369 exitFindingHeader: 370 if !hdr.reverse && headerFound || hdr.reverse && !headerFound { 371 matched = true 372 goto exitMatchingHeader 373 } 374 } 375 exitMatchingHeader: 376 if !matched { 377 return false 378 } 379 } 380 381 if len(opts.reqQueries) > 0 && traceInfo.Trace.HTTP != nil { 382 matched := false 383 for _, qry := range opts.reqQueries { 384 queryFound := false 385 v, err := url.ParseQuery(traceInfo.Trace.HTTP.ReqInfo.RawQuery) 386 if err != nil { 387 continue 388 } 389 for traceQuery, traceVals := range v { 390 for _, traceVal := range traceVals { 391 if patternMatch(qry.val, traceQuery+"="+traceVal) { 392 queryFound = true 393 goto exitFindingQuery 394 } 395 } 396 } 397 exitFindingQuery: 398 if !qry.reverse && queryFound || qry.reverse && !queryFound { 399 matched = true 400 goto exitMatchingQuery 401 } 402 } 403 exitMatchingQuery: 404 if !matched { 405 return false 406 } 407 } 408 409 if opts.requestSize > 0 && traceInfo.Trace.HTTP.CallStats.InputBytes < int(opts.requestSize) { 410 return false 411 } 412 413 if opts.responseSize > 0 && traceInfo.Trace.HTTP.CallStats.OutputBytes < int(opts.responseSize) { 414 return false 415 } 416 417 return true 418 } 419 420 func matchingOpts(ctx *cli.Context) (opts matchOpts) { 421 opts.statusCodes = ctx.IntSlice("status-code") 422 opts.methods = ctx.StringSlice("method") 423 opts.funcNames = ctx.StringSlice("funcname") 424 opts.apiPaths = ctx.StringSlice("path") 425 opts.nodes = ctx.StringSlice("node") 426 for _, s := range ctx.StringSlice("request-header") { 427 opts.reqHeaders = append(opts.reqHeaders, matchString{ 428 reverse: strings.HasPrefix(s, "!"), 429 val: strings.TrimPrefix(s, "!"), 430 }) 431 } 432 for _, s := range ctx.StringSlice("request-query") { 433 opts.reqQueries = append(opts.reqQueries, matchString{ 434 reverse: strings.HasPrefix(s, "!"), 435 val: strings.TrimPrefix(s, "!"), 436 }) 437 } 438 439 var e error 440 var requestSize, responseSize uint64 441 if ctx.Bool("filter-request") && ctx.String("filter-size") != "" { 442 requestSize, e = humanize.ParseBytes(ctx.String("filter-size")) 443 fatalIf(probe.NewError(e).Trace(ctx.String("filter-size")), "Unable to parse input bytes.") 444 } 445 446 if ctx.Bool("filter-response") && ctx.String("filter-size") != "" { 447 responseSize, e = humanize.ParseBytes(ctx.String("filter-size")) 448 fatalIf(probe.NewError(e).Trace(ctx.String("filter-size")), "Unable to parse input bytes.") 449 } 450 opts.requestSize = requestSize 451 opts.responseSize = responseSize 452 return 453 } 454 455 // Calculate tracing options for command line flags 456 func tracingOpts(ctx *cli.Context, apis []string) (opts madmin.ServiceTraceOpts, e error) { 457 opts.Threshold = ctx.Duration("response-duration") 458 opts.OnlyErrors = ctx.Bool("errors") 459 460 if ctx.Bool("all") { 461 for _, fn := range traceCallTypes { 462 fn(&opts) 463 } 464 } 465 466 if len(apis) == 0 { 467 // If api flag is not specified, then we will 468 // trace only S3 requests by default. 469 opts.S3 = true 470 return 471 } 472 473 for _, api := range apis { 474 for _, api := range strings.Split(api, ",") { 475 fn, ok := traceCallTypes[api] 476 if !ok { 477 fn, ok = traceCallTypeAliases[api] 478 } 479 if !ok { 480 return madmin.ServiceTraceOpts{}, fmt.Errorf("unknown call name: `%s`", api) 481 } 482 fn(&opts) 483 } 484 } 485 return 486 } 487 488 // mainAdminTrace - the entry function of trace command 489 func mainAdminTrace(ctx *cli.Context) error { 490 // Check for command syntax 491 checkAdminTraceSyntax(ctx) 492 493 verbose := ctx.Bool("verbose") 494 stats := ctx.Bool("stats") 495 aliasedURL := ctx.Args().Get(0) 496 497 console.SetColor("Stat", color.New(color.FgYellow)) 498 499 console.SetColor("Request", color.New(color.FgCyan)) 500 console.SetColor("Method", color.New(color.Bold, color.FgWhite)) 501 console.SetColor("Host", color.New(color.Bold, color.FgGreen)) 502 console.SetColor("FuncName", color.New(color.Bold, color.FgGreen)) 503 504 console.SetColor("ReqHeaderKey", color.New(color.Bold, color.FgWhite)) 505 console.SetColor("RespHeaderKey", color.New(color.Bold, color.FgCyan)) 506 console.SetColor("HeaderValue", color.New(color.FgWhite)) 507 console.SetColor("RespStatus", color.New(color.Bold, color.FgYellow)) 508 console.SetColor("ErrStatus", color.New(color.Bold, color.FgRed)) 509 510 console.SetColor("Response", color.New(color.FgGreen)) 511 console.SetColor("Extra", color.New(color.FgBlue)) 512 console.SetColor("Body", color.New(color.FgYellow)) 513 for _, c := range colors { 514 console.SetColor(fmt.Sprintf("Node%d", c), color.New(c)) 515 } 516 // Create a new MinIO Admin Client 517 client, err := newAdminClient(aliasedURL) 518 if err != nil { 519 fatalIf(err.Trace(aliasedURL), "Unable to initialize admin client.") 520 return nil 521 } 522 523 ctxt, cancel := context.WithCancel(globalContext) 524 defer cancel() 525 526 opts, e := tracingOpts(ctx, ctx.StringSlice("call")) 527 fatalIf(probe.NewError(e), "Unable to start tracing") 528 529 mopts := matchingOpts(ctx) 530 531 // Start listening on all trace activity. 532 traceCh := client.ServiceTrace(ctxt, opts) 533 if stats { 534 filteredTraces := make(chan madmin.ServiceTraceInfo, 1) 535 ui := tea.NewProgram(initTraceStatsUI(ctx.Int("stats-n"), filteredTraces)) 536 var te error 537 go func() { 538 for t := range traceCh { 539 if t.Err != nil { 540 te = t.Err 541 ui.Kill() 542 return 543 } 544 if mopts.matches(t) { 545 filteredTraces <- t 546 } 547 } 548 }() 549 if _, e := ui.Run(); e != nil { 550 cancel() 551 if te != nil { 552 e = te 553 } 554 fatalIf(probe.NewError(e).Trace(aliasedURL), "Unable to fetch http trace statistics") 555 } 556 return nil 557 } 558 for traceInfo := range traceCh { 559 if traceInfo.Err != nil { 560 fatalIf(probe.NewError(traceInfo.Err), "Unable to listen to http trace") 561 } 562 if mopts.matches(traceInfo) { 563 printTrace(verbose, traceInfo) 564 } 565 } 566 567 return nil 568 } 569 570 // Short trace record 571 type shortTraceMsg struct { 572 Status string `json:"status"` 573 Host string `json:"host"` 574 Time time.Time `json:"time"` 575 Client string `json:"client"` 576 CallStats *callStats `json:"callStats,omitempty"` 577 Duration time.Duration `json:"duration"` 578 TTFB time.Duration `json:"timeToFirstByte"` 579 FuncName string `json:"api"` 580 Path string `json:"path"` 581 Query string `json:"query"` 582 StatusCode int `json:"statusCode"` 583 StatusMsg string `json:"statusMsg"` 584 Type string `json:"type"` 585 Error string `json:"error"` 586 Extra map[string]string `json:"extra"` 587 trcType madmin.TraceType 588 } 589 590 type traceMessage struct { 591 Status string `json:"status"` 592 madmin.ServiceTraceInfo 593 } 594 595 type requestInfo struct { 596 Time time.Time `json:"time"` 597 Proto string `json:"proto"` 598 Method string `json:"method"` 599 Path string `json:"path,omitempty"` 600 RawQuery string `json:"rawQuery,omitempty"` 601 Headers map[string]string `json:"headers,omitempty"` 602 Body string `json:"body,omitempty"` 603 } 604 605 type responseInfo struct { 606 Time time.Time `json:"time"` 607 Headers map[string]string `json:"headers,omitempty"` 608 Body string `json:"body,omitempty"` 609 StatusCode int `json:"statusCode,omitempty"` 610 } 611 612 type callStats struct { 613 Rx int `json:"rx"` 614 Tx int `json:"tx"` 615 Duration time.Duration `json:"duration"` 616 TTFB time.Duration `json:"timeToFirstByte"` 617 } 618 619 type verboseTrace struct { 620 Type string `json:"type"` 621 622 NodeName string `json:"host"` 623 FuncName string `json:"api"` 624 Time time.Time `json:"time"` 625 Duration time.Duration `json:"duration"` 626 Path string `json:"path"` 627 Error string `json:"error,omitempty"` 628 Message string `json:"message,omitempty"` 629 RequestInfo *requestInfo `json:"request,omitempty"` 630 ResponseInfo *responseInfo `json:"response,omitempty"` 631 CallStats *callStats `json:"callStats,omitempty"` 632 HealResult *madmin.HealResultItem `json:"healResult,omitempty"` 633 Extra map[string]string `json:"extra,omitempty"` 634 635 trcType madmin.TraceType 636 } 637 638 // return a struct with minimal trace info. 639 func shortTrace(ti madmin.ServiceTraceInfo) shortTraceMsg { 640 s := shortTraceMsg{} 641 t := ti.Trace 642 643 s.trcType = t.TraceType 644 s.Type = t.TraceType.String() 645 s.FuncName = t.FuncName 646 s.Time = t.Time 647 s.Path = t.Path 648 s.Error = t.Error 649 s.Host = t.NodeName 650 s.Duration = t.Duration 651 s.StatusMsg = t.Message 652 s.Extra = t.Custom 653 654 switch t.TraceType { 655 case madmin.TraceS3, madmin.TraceInternal: 656 s.Query = t.HTTP.ReqInfo.RawQuery 657 s.StatusCode = t.HTTP.RespInfo.StatusCode 658 s.StatusMsg = http.StatusText(t.HTTP.RespInfo.StatusCode) 659 s.Client = t.HTTP.ReqInfo.Client 660 s.CallStats = &callStats{} 661 s.CallStats.Duration = t.Duration 662 s.CallStats.Rx = t.HTTP.CallStats.InputBytes 663 s.CallStats.Tx = t.HTTP.CallStats.OutputBytes 664 s.CallStats.TTFB = t.HTTP.CallStats.TimeToFirstByte 665 } 666 return s 667 } 668 669 func (s shortTraceMsg) JSON() string { 670 s.Status = "success" 671 buf := &bytes.Buffer{} 672 enc := json.NewEncoder(buf) 673 enc.SetIndent("", " ") 674 // Disable escaping special chars to display XML tags correctly 675 enc.SetEscapeHTML(false) 676 677 fatalIf(probe.NewError(enc.Encode(s)), "Unable to marshal into JSON.") 678 return buf.String() 679 } 680 681 func (s shortTraceMsg) String() string { 682 var hostStr string 683 b := &strings.Builder{} 684 685 if s.Host != "" { 686 hostStr = colorizedNodeName(s.Host) 687 } 688 fmt.Fprintf(b, "%s ", s.Time.Local().Format(traceTimeFormat)) 689 690 switch s.trcType { 691 case madmin.TraceS3, madmin.TraceInternal: 692 case madmin.TraceBootstrap: 693 fmt.Fprintf(b, "[%s] %s %s %s", console.Colorize("RespStatus", strings.ToUpper(s.trcType.String())), console.Colorize("FuncName", s.FuncName), 694 hostStr, 695 s.StatusMsg, 696 ) 697 return b.String() 698 default: 699 if s.Error != "" { 700 fmt.Fprintf(b, "[%s] %s %s %s err='%s' %2s", console.Colorize("RespStatus", strings.ToUpper(s.trcType.String())), console.Colorize("FuncName", s.FuncName), 701 hostStr, 702 s.Path, 703 console.Colorize("ErrStatus", s.Error), 704 console.Colorize("HeaderValue", s.Duration)) 705 } else { 706 fmt.Fprintf(b, "[%s] %s %s %s %2s", console.Colorize("RespStatus", strings.ToUpper(s.trcType.String())), console.Colorize("FuncName", s.FuncName), 707 hostStr, 708 s.Path, 709 console.Colorize("HeaderValue", s.Duration)) 710 } 711 return b.String() 712 } 713 714 statusStr := fmt.Sprintf("%d %s", s.StatusCode, s.StatusMsg) 715 if s.StatusCode >= http.StatusBadRequest { 716 statusStr = console.Colorize("ErrStatus", statusStr) 717 } else { 718 statusStr = console.Colorize("RespStatus", statusStr) 719 } 720 721 fmt.Fprintf(b, "[%s] %s ", statusStr, console.Colorize("FuncName", s.FuncName)) 722 fmt.Fprintf(b, "%s%s", hostStr, s.Path) 723 724 if s.Query != "" { 725 fmt.Fprintf(b, "?%s ", s.Query) 726 } 727 fmt.Fprintf(b, " %s ", s.Client) 728 729 spaces := 15 - len(s.Client) 730 fmt.Fprintf(b, "%*s", spaces, " ") 731 fmt.Fprint(b, console.Colorize("HeaderValue", fmt.Sprintf(" %2s", s.CallStats.Duration.Round(time.Microsecond)))) 732 spaces = 12 - len(fmt.Sprintf("%2s", s.CallStats.Duration.Round(time.Microsecond))) 733 fmt.Fprintf(b, "%*s", spaces, " ") 734 fmt.Fprint(b, console.Colorize("Stat", " ⇣ ")) 735 fmt.Fprint(b, console.Colorize("HeaderValue", fmt.Sprintf(" %2s", s.CallStats.TTFB.Round(time.Nanosecond)))) 736 spaces = 10 - len(fmt.Sprintf("%2s", s.CallStats.TTFB.Round(time.Nanosecond))) 737 fmt.Fprintf(b, "%*s", spaces, " ") 738 fmt.Fprint(b, console.Colorize("Stat", " ↑ ")) 739 fmt.Fprint(b, console.Colorize("HeaderValue", humanize.IBytes(uint64(s.CallStats.Rx)))) 740 fmt.Fprint(b, console.Colorize("Stat", " ↓ ")) 741 fmt.Fprint(b, console.Colorize("HeaderValue", humanize.IBytes(uint64(s.CallStats.Tx)))) 742 743 return b.String() 744 } 745 746 // colorize node name 747 func colorizedNodeName(nodeName string) string { 748 nodeHash := fnv.New32a() 749 nodeHash.Write([]byte(nodeName)) 750 nHashSum := nodeHash.Sum32() 751 idx := nHashSum % uint32(len(colors)) 752 return console.Colorize(fmt.Sprintf("Node%d", colors[idx]), nodeName) 753 } 754 755 func (t traceMessage) JSON() string { 756 trc := verboseTrace{ 757 trcType: t.Trace.TraceType, 758 Type: t.Trace.TraceType.String(), 759 NodeName: t.Trace.NodeName, 760 FuncName: t.Trace.FuncName, 761 Time: t.Trace.Time, 762 Duration: t.Trace.Duration, 763 Path: t.Trace.Path, 764 Error: t.Trace.Error, 765 HealResult: t.Trace.HealResult, 766 Message: t.Trace.Message, 767 Extra: t.Trace.Custom, 768 } 769 770 if t.Trace.HTTP != nil { 771 rq := t.Trace.HTTP.ReqInfo 772 rs := t.Trace.HTTP.RespInfo 773 774 var ( 775 rqHdrs = make(map[string]string) 776 rspHdrs = make(map[string]string) 777 ) 778 for k, v := range rq.Headers { 779 rqHdrs[k] = strings.Join(v, " ") 780 } 781 for k, v := range rs.Headers { 782 rspHdrs[k] = strings.Join(v, " ") 783 } 784 785 trc.RequestInfo = &requestInfo{ 786 Time: rq.Time, 787 Proto: rq.Proto, 788 Method: rq.Method, 789 Path: rq.Path, 790 RawQuery: rq.RawQuery, 791 Body: string(rq.Body), 792 Headers: rqHdrs, 793 } 794 trc.ResponseInfo = &responseInfo{ 795 Time: rs.Time, 796 Body: string(rs.Body), 797 Headers: rspHdrs, 798 StatusCode: rs.StatusCode, 799 } 800 trc.CallStats = &callStats{ 801 Duration: t.Trace.Duration, 802 Rx: t.Trace.HTTP.CallStats.InputBytes, 803 Tx: t.Trace.HTTP.CallStats.OutputBytes, 804 TTFB: t.Trace.HTTP.CallStats.TimeToFirstByte, 805 } 806 } 807 buf := &bytes.Buffer{} 808 enc := json.NewEncoder(buf) 809 enc.SetIndent("", " ") 810 // Disable escaping special chars to display XML tags correctly 811 enc.SetEscapeHTML(false) 812 fatalIf(probe.NewError(enc.Encode(trc)), "Unable to marshal into JSON.") 813 814 // strip off extra newline added by json encoder 815 return strings.TrimSuffix(buf.String(), "\n") 816 } 817 818 func (t traceMessage) String() string { 819 var nodeNameStr string 820 b := &strings.Builder{} 821 822 trc := t.Trace 823 if trc.NodeName != "" { 824 nodeNameStr = fmt.Sprintf("%s ", colorizedNodeName(trc.NodeName)) 825 } 826 extra := "" 827 if len(t.Trace.Custom) > 0 { 828 for k, v := range t.Trace.Custom { 829 extra = fmt.Sprintf("%s %s=%s", extra, k, v) 830 } 831 extra = console.Colorize("Extra", extra) 832 } 833 switch trc.TraceType { 834 case madmin.TraceS3, madmin.TraceInternal: 835 if trc.HTTP == nil { 836 return "" 837 } 838 case madmin.TraceBootstrap: 839 fmt.Fprintf(b, "%s %s [%s] %s%s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Message, extra) 840 return b.String() 841 default: 842 if trc.Error != "" { 843 fmt.Fprintf(b, "%s %s [%s] %s%s err='%s' %s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Path, extra, console.Colorize("ErrStatus", trc.Error), trc.Duration) 844 } else { 845 fmt.Fprintf(b, "%s %s [%s] %s%s %s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[%s %s]", strings.ToUpper(trc.TraceType.String()), trc.FuncName)), trc.Time.Local().Format(traceTimeFormat), trc.Path, extra, trc.Duration) 846 } 847 return b.String() 848 } 849 850 ri := trc.HTTP.ReqInfo 851 rs := trc.HTTP.RespInfo 852 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[REQUEST %s] ", trc.FuncName))) 853 fmt.Fprintf(b, "[%s] %s\n", ri.Time.Local().Format(traceTimeFormat), console.Colorize("Host", fmt.Sprintf("[Client IP: %s]", ri.Client))) 854 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Method", fmt.Sprintf("%s %s", ri.Method, ri.Path))) 855 if ri.RawQuery != "" { 856 fmt.Fprintf(b, "?%s", ri.RawQuery) 857 } 858 fmt.Fprint(b, "\n") 859 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Method", fmt.Sprintf("Proto: %s\n", ri.Proto))) 860 host, ok := ri.Headers["Host"] 861 if ok { 862 delete(ri.Headers, "Host") 863 } 864 hostStr := strings.Join(host, "") 865 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Host", fmt.Sprintf("Host: %s\n", hostStr))) 866 for k, v := range ri.Headers { 867 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("ReqHeaderKey", 868 fmt.Sprintf("%s: ", k))+console.Colorize("HeaderValue", fmt.Sprintf("%s\n", strings.Join(v, "")))) 869 } 870 871 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Body", fmt.Sprintf("%s\n", string(ri.Body)))) 872 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Response", "[RESPONSE] ")) 873 fmt.Fprintf(b, "[%s] ", rs.Time.Local().Format(traceTimeFormat)) 874 fmt.Fprint(b, console.Colorize("Stat", fmt.Sprintf("[ Duration %2s TTFB %2s ↑ %s ↓ %s ]\n", trc.Duration.Round(time.Microsecond), trc.HTTP.CallStats.TimeToFirstByte.Round(time.Nanosecond), 875 humanize.IBytes(uint64(trc.HTTP.CallStats.InputBytes)), humanize.IBytes(uint64(trc.HTTP.CallStats.OutputBytes))))) 876 877 statusStr := console.Colorize("RespStatus", fmt.Sprintf("%d %s", rs.StatusCode, http.StatusText(rs.StatusCode))) 878 if rs.StatusCode != http.StatusOK { 879 statusStr = console.Colorize("ErrStatus", fmt.Sprintf("%d %s", rs.StatusCode, http.StatusText(rs.StatusCode))) 880 } 881 fmt.Fprintf(b, "%s%s\n", nodeNameStr, statusStr) 882 883 for k, v := range rs.Headers { 884 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("RespHeaderKey", 885 fmt.Sprintf("%s: ", k))+console.Colorize("HeaderValue", fmt.Sprintf("%s\n", strings.Join(v, ",")))) 886 } 887 if len(extra) > 0 { 888 fmt.Fprintf(b, "%s%s\n", nodeNameStr, extra) 889 } 890 fmt.Fprintf(b, "%s%s\n", nodeNameStr, console.Colorize("Body", string(rs.Body))) 891 fmt.Fprint(b, nodeNameStr) 892 return b.String() 893 } 894 895 type statItem struct { 896 Name string 897 Count int `json:"count"` 898 Duration time.Duration `json:"duration"` 899 Errors int `json:"errors,omitempty"` 900 CallStatsCount int `json:"callStatsCount,omitempty"` 901 CallStats callStats `json:"callStats,omitempty"` 902 TTFB time.Duration `json:"ttfb,omitempty"` 903 MaxTTFB time.Duration `json:"maxTTFB,omitempty"` 904 MaxDur time.Duration `json:"maxDuration"` 905 MinDur time.Duration `json:"minDuration"` 906 } 907 908 type statTrace struct { 909 Calls map[string]statItem `json:"calls"` 910 Started time.Time 911 mu sync.Mutex 912 } 913 914 func (s *statTrace) JSON() string { 915 s.mu.Lock() 916 defer s.mu.Unlock() 917 buf := &bytes.Buffer{} 918 enc := json.NewEncoder(buf) 919 enc.SetIndent("", " ") 920 // Disable escaping special chars to display XML tags correctly 921 enc.SetEscapeHTML(false) 922 fatalIf(probe.NewError(enc.Encode(s)), "Unable to marshal into JSON.") 923 924 // strip off extra newline added by json encoder 925 return strings.TrimSuffix(buf.String(), "\n") 926 } 927 928 func (s *statTrace) String() string { 929 return "" 930 } 931 932 func (s *statTrace) add(t madmin.ServiceTraceInfo) { 933 id := t.Trace.FuncName 934 s.mu.Lock() 935 defer s.mu.Unlock() 936 got := s.Calls[id] 937 if got.Name == "" { 938 got.Name = id 939 } 940 if got.MaxDur < t.Trace.Duration { 941 got.MaxDur = t.Trace.Duration 942 } 943 if got.MinDur <= 0 { 944 got.MinDur = t.Trace.Duration 945 } 946 if got.MinDur > t.Trace.Duration { 947 got.MinDur = t.Trace.Duration 948 } 949 got.Count++ 950 got.Duration += t.Trace.Duration 951 if t.Trace.Error != "" { 952 got.Errors++ 953 } 954 if t.Trace.HTTP != nil { 955 got.CallStatsCount++ 956 got.CallStats.Rx += t.Trace.HTTP.CallStats.InputBytes 957 got.CallStats.Tx += t.Trace.HTTP.CallStats.OutputBytes 958 got.TTFB += t.Trace.HTTP.CallStats.TimeToFirstByte 959 if got.MaxTTFB < t.Trace.HTTP.CallStats.TimeToFirstByte { 960 got.MaxTTFB = t.Trace.HTTP.CallStats.TimeToFirstByte 961 } 962 } 963 s.Calls[id] = got 964 } 965 966 func initTraceStatsUI(maxEntries int, traces <-chan madmin.ServiceTraceInfo) *traceStatsUI { 967 s := spinner.New() 968 s.Spinner = spinner.Points 969 s.Spinner.FPS = time.Second / 4 970 s.Style = lipgloss.NewStyle().Foreground(lipgloss.Color("205")) 971 console.SetColor("metrics-duration", color.New(color.FgWhite)) 972 console.SetColor("metrics-dur", color.New(color.FgGreen)) 973 console.SetColor("metrics-dur-med", color.New(color.FgYellow)) 974 console.SetColor("metrics-dur-high", color.New(color.FgRed)) 975 console.SetColor("metrics-error", color.New(color.FgYellow)) 976 console.SetColor("metrics-title", color.New(color.FgCyan)) 977 console.SetColor("metrics-top-title", color.New(color.FgHiCyan)) 978 console.SetColor("metrics-number", color.New(color.FgWhite)) 979 console.SetColor("metrics-number-secondary", color.New(color.FgBlue)) 980 console.SetColor("metrics-zero", color.New(color.FgWhite)) 981 stats := &statTrace{Calls: make(map[string]statItem, 20), Started: time.Now()} 982 go func() { 983 for t := range traces { 984 stats.add(t) 985 } 986 }() 987 return &traceStatsUI{ 988 started: time.Now(), 989 spinner: s, 990 maxEntries: maxEntries, 991 current: stats, 992 } 993 } 994 995 type traceStatsUI struct { 996 current *statTrace 997 started time.Time 998 spinner spinner.Model 999 quitting bool 1000 maxEntries int 1001 } 1002 1003 func (m *traceStatsUI) Init() tea.Cmd { 1004 return m.spinner.Tick 1005 } 1006 1007 func (m *traceStatsUI) Update(msg tea.Msg) (tea.Model, tea.Cmd) { 1008 if m.quitting { 1009 return m, tea.Quit 1010 } 1011 switch msg := msg.(type) { 1012 case tea.KeyMsg: 1013 switch msg.String() { 1014 case "q", "esc", "ctrl+c": 1015 m.quitting = true 1016 return m, tea.Quit 1017 default: 1018 return m, nil 1019 } 1020 case spinner.TickMsg: 1021 var cmd tea.Cmd 1022 m.spinner, cmd = m.spinner.Update(msg) 1023 return m, cmd 1024 } 1025 return m, nil 1026 } 1027 1028 func (m *traceStatsUI) View() string { 1029 var s strings.Builder 1030 1031 s.WriteString(fmt.Sprintf("%s %s\n", 1032 console.Colorize("metrics-top-title", "Duration: "+time.Since(m.current.Started).Round(time.Second).String()), m.spinner.View())) 1033 1034 // Set table header - akin to k8s style 1035 // https://github.com/olekukonko/tablewriter#example-10---set-nowhitespace-and-tablepadding-option 1036 table := tablewriter.NewWriter(&s) 1037 table.SetAutoWrapText(false) 1038 table.SetAutoFormatHeaders(true) 1039 table.SetHeaderAlignment(tablewriter.ALIGN_LEFT) 1040 table.SetAlignment(tablewriter.ALIGN_LEFT) 1041 table.SetCenterSeparator("") 1042 table.SetColumnSeparator("") 1043 table.SetRowSeparator("") 1044 table.SetHeaderLine(false) 1045 table.SetBorder(false) 1046 table.SetTablePadding("\t") // pad with tabs 1047 table.SetNoWhiteSpace(true) 1048 addRow := func(s string) { 1049 table.Append([]string{s}) 1050 } 1051 _ = addRow 1052 addRowF := func(format string, vals ...interface{}) { 1053 s := fmt.Sprintf(format, vals...) 1054 table.Append([]string{s}) 1055 } 1056 _ = addRowF 1057 var entries []statItem 1058 m.current.mu.Lock() 1059 totalCnt := 0 1060 dur := time.Since(m.current.Started) 1061 for _, v := range m.current.Calls { 1062 totalCnt += v.Count 1063 entries = append(entries, v) 1064 } 1065 m.current.mu.Unlock() 1066 if len(entries) == 0 { 1067 s.WriteString("(waiting for data)") 1068 return s.String() 1069 } 1070 sort.Slice(entries, func(i, j int) bool { 1071 if entries[i].Count == entries[j].Count { 1072 return entries[i].Name < entries[j].Name 1073 } 1074 return entries[i].Count > entries[j].Count 1075 }) 1076 if m.maxEntries > 0 && len(entries) > m.maxEntries { 1077 entries = entries[:m.maxEntries] 1078 } 1079 1080 table.Append([]string{ 1081 console.Colorize("metrics-top-title", "Call"), 1082 console.Colorize("metrics-top-title", "Count"), 1083 console.Colorize("metrics-top-title", "RPM"), 1084 console.Colorize("metrics-top-title", "Avg Time"), 1085 console.Colorize("metrics-top-title", "Min Time"), 1086 console.Colorize("metrics-top-title", "Max Time"), 1087 console.Colorize("metrics-top-title", "Avg TTFB"), 1088 console.Colorize("metrics-top-title", "Max TTFB"), 1089 console.Colorize("metrics-top-title", "Errors"), 1090 console.Colorize("metrics-top-title", "RX Avg"), 1091 console.Colorize("metrics-top-title", "TX Avg"), 1092 }) 1093 for _, v := range entries { 1094 if v.Count <= 0 { 1095 continue 1096 } 1097 errs := "0" 1098 if v.Errors > 0 { 1099 errs = console.Colorize("metrics-error", strconv.Itoa(v.Errors)) 1100 } 1101 avg := v.Duration / time.Duration(v.Count) 1102 avgTTFB := v.TTFB / time.Duration(v.Count) 1103 avgColor := "metrics-dur" 1104 if avg > 10*time.Second { 1105 avgColor = "metrics-dur-high" 1106 } else if avg > time.Second { 1107 avgColor = "metrics-dur-med" 1108 } 1109 1110 minColor := "metrics-dur" 1111 if v.MinDur > 10*time.Second { 1112 minColor = "metrics-dur-high" 1113 } else if v.MinDur > time.Second { 1114 minColor = "metrics-dur-med" 1115 } 1116 1117 maxColor := "metrics-dur" 1118 if v.MaxDur > 10*time.Second { 1119 maxColor = "metrics-dur-high" 1120 } else if v.MaxDur > time.Second { 1121 maxColor = "metrics-dur-med" 1122 } 1123 1124 rx := "-" 1125 tx := "-" 1126 if v.CallStatsCount > 0 { 1127 rx = humanize.IBytes(uint64(v.CallStats.Rx / v.CallStatsCount)) 1128 tx = humanize.IBytes(uint64(v.CallStats.Tx / v.CallStatsCount)) 1129 } 1130 table.Append([]string{ 1131 console.Colorize("metrics-title", metricsTitle(v.Name)), 1132 console.Colorize("metrics-number", fmt.Sprintf("%d ", v.Count)) + 1133 console.Colorize("metrics-number-secondary", fmt.Sprintf("(%0.1f%%)", float64(v.Count)/float64(totalCnt)*100)), 1134 console.Colorize("metrics-number", fmt.Sprintf("%0.1f", float64(v.Count)/dur.Minutes())), 1135 console.Colorize(avgColor, fmt.Sprintf("%v", avg.Round(time.Microsecond))), 1136 console.Colorize(minColor, v.MinDur), 1137 console.Colorize(maxColor, v.MaxDur), 1138 console.Colorize(avgColor, fmt.Sprintf("%v", avgTTFB.Round(time.Microsecond))), 1139 console.Colorize(maxColor, v.MaxTTFB), 1140 errs, 1141 rx, 1142 tx, 1143 }) 1144 } 1145 table.Render() 1146 return s.String() 1147 }