1// Copyright (c) 2015-2021 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 18package cmd 19 20import ( 21 "bytes" 22 "context" 23 "fmt" 24 "hash/fnv" 25 "net/http" 26 "path" 27 "strings" 28 "time" 29 30 "github.com/dustin/go-humanize" 31 "github.com/fatih/color" 32 "github.com/minio/cli" 33 json "github.com/minio/colorjson" 34 "github.com/minio/madmin-go" 35 "github.com/minio/mc/pkg/probe" 36 "github.com/minio/pkg/console" 37) 38 39var adminTraceFlags = []cli.Flag{ 40 cli.BoolFlag{ 41 Name: "verbose, v", 42 Usage: "print verbose trace", 43 }, 44 cli.BoolFlag{ 45 Name: "all, a", 46 Usage: "trace all call types", 47 }, 48 cli.StringSliceFlag{ 49 Name: "call", 50 Usage: "trace only matching Call types (values: `s3`, `internal`, `storage`, `os`)", 51 }, 52 cli.StringFlag{ 53 Name: "response-threshold", 54 Usage: "trace calls only with response duration greater than this threshold (e.g. `5ms`)", 55 }, 56 57 cli.IntSliceFlag{ 58 Name: "status-code", 59 Usage: "trace only matching status code", 60 }, 61 cli.StringSliceFlag{ 62 Name: "method", 63 Usage: "trace only matching HTTP method", 64 }, 65 cli.StringSliceFlag{ 66 Name: "funcname", 67 Usage: "trace only matching func name", 68 }, 69 cli.StringSliceFlag{ 70 Name: "path", 71 Usage: "trace only matching path", 72 }, 73 cli.BoolFlag{ 74 Name: "errors, e", 75 Usage: "trace only failed requests", 76 }, 77} 78 79var adminTraceCmd = cli.Command{ 80 Name: "trace", 81 Usage: "show http trace for MinIO server", 82 Action: mainAdminTrace, 83 OnUsageError: onUsageError, 84 Before: setGlobalsFromContext, 85 Flags: append(adminTraceFlags, globalFlags...), 86 HideHelpCommand: true, 87 CustomHelpTemplate: `NAME: 88 {{.HelpName}} - {{.Usage}} 89 90USAGE: 91 {{.HelpName}} [FLAGS] TARGET 92 93FLAGS: 94 {{range .VisibleFlags}}{{.}} 95 {{end}} 96EXAMPLES: 97 1. Show verbose console trace for MinIO server 98 {{.Prompt}} {{.HelpName}} -v -a myminio 99 100 2. Show trace only for failed requests for MinIO server 101 {{.Prompt}} {{.HelpName}} -v -e myminio 102 103 3. Show verbose console trace for requests with '503' status code 104 {{.Prompt}} {{.HelpName}} -v --status-code 503 myminio 105 106 4. Show console trace for a specific path 107 {{.Prompt}} {{.HelpName}} --path my-bucket/my-prefix/* myminio 108 109 5. Show console trace for requests with '404' and '503' status code 110 {{.Prompt}} {{.HelpName}} --status-code 404 --status-code 503 myminio 111`, 112} 113 114const timeFormat = "2006-01-02T15:04:05:000" 115 116var ( 117 colors = []color.Attribute{color.FgCyan, color.FgWhite, color.FgYellow, color.FgGreen} 118) 119 120func checkAdminTraceSyntax(ctx *cli.Context) { 121 if len(ctx.Args()) != 1 { 122 cli.ShowCommandHelpAndExit(ctx, "trace", 1) // last argument is exit code 123 } 124} 125 126func printTrace(verbose bool, traceInfo madmin.ServiceTraceInfo) { 127 if verbose { 128 printMsg(traceMessage{ServiceTraceInfo: traceInfo}) 129 } else { 130 printMsg(shortTrace(traceInfo)) 131 } 132} 133 134func matchTrace(ctx *cli.Context, traceInfo madmin.ServiceTraceInfo) bool { 135 statusCodes := ctx.IntSlice("status-code") 136 methods := ctx.StringSlice("method") 137 funcNames := ctx.StringSlice("funcname") 138 apiPaths := ctx.StringSlice("path") 139 140 if len(statusCodes) == 0 && len(methods) == 0 && len(funcNames) == 0 && len(apiPaths) == 0 { 141 // no specific filtering found trace all the requests 142 return true 143 } 144 145 // Filter request path if passed by the user 146 if len(apiPaths) > 0 { 147 matched := false 148 for _, apiPath := range apiPaths { 149 if pathMatch(path.Join("/", apiPath), traceInfo.Trace.ReqInfo.Path) { 150 matched = true 151 break 152 } 153 } 154 if !matched { 155 return false 156 } 157 } 158 159 // Filter response status codes if passed by the user 160 if len(statusCodes) > 0 { 161 matched := false 162 for _, code := range statusCodes { 163 if traceInfo.Trace.RespInfo.StatusCode == code { 164 matched = true 165 break 166 } 167 } 168 if !matched { 169 return false 170 } 171 172 } 173 174 // Filter request method if passed by the user 175 if len(methods) > 0 { 176 matched := false 177 for _, method := range methods { 178 if traceInfo.Trace.ReqInfo.Method == method { 179 matched = true 180 break 181 } 182 } 183 if !matched { 184 return false 185 } 186 187 } 188 189 if len(funcNames) > 0 { 190 matched := false 191 // Filter request function handler names if passed by the user. 192 for _, funcName := range funcNames { 193 if nameMatch(funcName, traceInfo.Trace.FuncName) { 194 matched = true 195 break 196 } 197 } 198 if !matched { 199 return false 200 } 201 } 202 203 return true 204} 205 206// Calculate tracing options for command line flags 207func tracingOpts(ctx *cli.Context) (opts madmin.ServiceTraceOpts, e error) { 208 209 if t := ctx.String("response-threshold"); t != "" { 210 d, e := time.ParseDuration(t) 211 if e != nil { 212 return opts, fmt.Errorf("Unable to parse threshold argument: %w", e) 213 } 214 opts.Threshold = d 215 } 216 217 opts.OnlyErrors = ctx.Bool("errors") 218 219 if ctx.Bool("all") { 220 opts.All = true // Deprecated 221 222 opts.S3 = true 223 opts.Internal = true 224 opts.Storage = true 225 opts.OS = true 226 return 227 } 228 229 apis := ctx.StringSlice("call") 230 if len(apis) == 0 { 231 // If api flag is not specified, then we will 232 // trace only S3 requests by default. 233 opts.S3 = true 234 return 235 } 236 237 for _, api := range apis { 238 switch api { 239 case "storage": 240 opts.Storage = true 241 case "internal": 242 opts.Internal = true 243 case "s3": 244 opts.S3 = true 245 case "os": 246 opts.OS = true 247 } 248 } 249 250 return 251} 252 253// mainAdminTrace - the entry function of trace command 254func mainAdminTrace(ctx *cli.Context) error { 255 // Check for command syntax 256 checkAdminTraceSyntax(ctx) 257 258 verbose := ctx.Bool("verbose") 259 aliasedURL := ctx.Args().Get(0) 260 261 console.SetColor("Stat", color.New(color.FgYellow)) 262 263 console.SetColor("Request", color.New(color.FgCyan)) 264 console.SetColor("Method", color.New(color.Bold, color.FgWhite)) 265 console.SetColor("Host", color.New(color.Bold, color.FgGreen)) 266 console.SetColor("FuncName", color.New(color.Bold, color.FgGreen)) 267 268 console.SetColor("ReqHeaderKey", color.New(color.Bold, color.FgWhite)) 269 console.SetColor("RespHeaderKey", color.New(color.Bold, color.FgCyan)) 270 console.SetColor("HeaderValue", color.New(color.FgWhite)) 271 console.SetColor("RespStatus", color.New(color.Bold, color.FgYellow)) 272 console.SetColor("ErrStatus", color.New(color.Bold, color.FgRed)) 273 274 console.SetColor("Response", color.New(color.FgGreen)) 275 console.SetColor("Body", color.New(color.FgYellow)) 276 for _, c := range colors { 277 console.SetColor(fmt.Sprintf("Node%d", c), color.New(c)) 278 } 279 // Create a new MinIO Admin Client 280 client, err := newAdminClient(aliasedURL) 281 if err != nil { 282 fatalIf(err.Trace(aliasedURL), "Unable to initialize admin client.") 283 return nil 284 } 285 286 ctxt, cancel := context.WithCancel(globalContext) 287 defer cancel() 288 289 opts, e := tracingOpts(ctx) 290 fatalIf(probe.NewError(e), "Unable to start tracing") 291 292 // Start listening on all trace activity. 293 traceCh := client.ServiceTrace(ctxt, opts) 294 for traceInfo := range traceCh { 295 if traceInfo.Err != nil { 296 fatalIf(probe.NewError(traceInfo.Err), "Unable to listen to http trace") 297 } 298 if matchTrace(ctx, traceInfo) { 299 printTrace(verbose, traceInfo) 300 } 301 } 302 return nil 303} 304 305// Short trace record 306type shortTraceMsg struct { 307 Status string `json:"status"` 308 Host string `json:"host"` 309 Time time.Time `json:"time"` 310 Client string `json:"client"` 311 CallStats callStats `json:"callStats"` 312 FuncName string `json:"api"` 313 Path string `json:"path"` 314 Query string `json:"query"` 315 StatusCode int `json:"statusCode"` 316 StatusMsg string `json:"statusMsg"` 317 318 StorageStats storageStats `json:"storageStats"` 319 OSStats osStats `json:"osStats"` 320 Type madmin.TraceType `json:"type"` 321} 322 323type traceMessage struct { 324 Status string `json:"status"` 325 madmin.ServiceTraceInfo 326} 327 328type requestInfo struct { 329 Time time.Time `json:"time"` 330 Proto string `json:"proto"` 331 Method string `json:"method"` 332 Path string `json:"path,omitempty"` 333 RawQuery string `json:"rawQuery,omitempty"` 334 Headers map[string]string `json:"headers,omitempty"` 335 Body string `json:"body,omitempty"` 336} 337 338type responseInfo struct { 339 Time time.Time `json:"time"` 340 Headers map[string]string `json:"headers,omitempty"` 341 Body string `json:"body,omitempty"` 342 StatusCode int `json:"statusCode,omitempty"` 343} 344 345type callStats struct { 346 Rx int `json:"rx"` 347 Tx int `json:"tx"` 348 Duration time.Duration `json:"duration"` 349 Ttfb time.Duration `json:"timeToFirstByte"` 350} 351 352type osStats struct { 353 Duration time.Duration `json:"duration"` 354 Path string `json:"path"` 355} 356 357type storageStats struct { 358 Duration time.Duration `json:"duration"` 359 Path string `json:"path"` 360} 361 362type verboseTrace struct { 363 Type madmin.TraceType `json:"type"` 364 365 NodeName string `json:"host"` 366 FuncName string `json:"api"` 367 Time time.Time `json:"time"` 368 369 RequestInfo requestInfo `json:"request"` 370 ResponseInfo responseInfo `json:"response"` 371 CallStats callStats `json:"callStats"` 372 373 StorageStats storageStats `json:"storageStats"` 374 OSStats osStats `json:"osStats"` 375} 376 377// return a struct with minimal trace info. 378func shortTrace(ti madmin.ServiceTraceInfo) shortTraceMsg { 379 s := shortTraceMsg{} 380 t := ti.Trace 381 382 s.Type = t.TraceType 383 s.FuncName = t.FuncName 384 s.Time = t.Time 385 386 switch t.TraceType { 387 case madmin.TraceStorage: 388 s.Path = t.StorageStats.Path 389 s.Host = t.NodeName 390 s.StorageStats.Duration = t.StorageStats.Duration 391 case madmin.TraceOS: 392 s.Path = t.OSStats.Path 393 s.Host = t.NodeName 394 s.OSStats.Duration = t.OSStats.Duration 395 case madmin.TraceHTTP: 396 s.Host = t.NodeName 397 s.Path = t.ReqInfo.Path 398 s.Query = t.ReqInfo.RawQuery 399 s.StatusCode = t.RespInfo.StatusCode 400 s.StatusMsg = http.StatusText(t.RespInfo.StatusCode) 401 s.Client = t.ReqInfo.Client 402 s.CallStats.Duration = t.CallStats.Latency 403 s.CallStats.Rx = t.CallStats.InputBytes 404 s.CallStats.Tx = t.CallStats.OutputBytes 405 406 // Support older versions of MinIO server 407 s.Time = t.ReqInfo.Time 408 } 409 return s 410} 411 412func (s shortTraceMsg) JSON() string { 413 s.Status = "success" 414 buf := &bytes.Buffer{} 415 enc := json.NewEncoder(buf) 416 enc.SetIndent("", " ") 417 // Disable escaping special chars to display XML tags correctly 418 enc.SetEscapeHTML(false) 419 420 fatalIf(probe.NewError(enc.Encode(s)), "Unable to marshal into JSON.") 421 return buf.String() 422} 423 424func (s shortTraceMsg) String() string { 425 var hostStr string 426 var b = &strings.Builder{} 427 428 if s.Host != "" { 429 hostStr = colorizedNodeName(s.Host) 430 } 431 fmt.Fprintf(b, "%s ", s.Time.Local().Format(timeFormat)) 432 433 switch s.Type { 434 case madmin.TraceStorage: 435 fmt.Fprintf(b, "[%s] %s %s %s %2s", console.Colorize("RespStatus", "STORAGE"), console.Colorize("FuncName", s.FuncName), 436 hostStr, 437 s.Path, 438 console.Colorize("HeaderValue", s.StorageStats.Duration)) 439 return b.String() 440 case madmin.TraceOS: 441 fmt.Fprintf(b, "[%s] %s %s %s %2s", console.Colorize("RespStatus", "OS"), console.Colorize("FuncName", s.FuncName), 442 hostStr, 443 s.Path, 444 console.Colorize("HeaderValue", s.OSStats.Duration)) 445 return b.String() 446 } 447 448 statusStr := fmt.Sprintf("%d %s", s.StatusCode, s.StatusMsg) 449 if s.StatusCode >= http.StatusBadRequest { 450 statusStr = console.Colorize("ErrStatus", statusStr) 451 } else { 452 statusStr = console.Colorize("RespStatus", statusStr) 453 } 454 455 fmt.Fprintf(b, "[%s] %s ", statusStr, console.Colorize("FuncName", s.FuncName)) 456 fmt.Fprintf(b, "%s%s", hostStr, s.Path) 457 458 if s.Query != "" { 459 fmt.Fprintf(b, "?%s ", s.Query) 460 } 461 fmt.Fprintf(b, " %s ", s.Client) 462 463 spaces := 15 - len(s.Client) 464 fmt.Fprintf(b, "%*s", spaces, " ") 465 fmt.Fprint(b, console.Colorize("HeaderValue", fmt.Sprintf(" %2s", s.CallStats.Duration.Round(time.Microsecond)))) 466 spaces = 12 - len(fmt.Sprintf("%2s", s.CallStats.Duration.Round(time.Microsecond))) 467 fmt.Fprintf(b, "%*s", spaces, " ") 468 fmt.Fprint(b, console.Colorize("Stat", " ↑ ")) 469 fmt.Fprint(b, console.Colorize("HeaderValue", humanize.IBytes(uint64(s.CallStats.Rx)))) 470 fmt.Fprint(b, console.Colorize("Stat", " ↓ ")) 471 fmt.Fprint(b, console.Colorize("HeaderValue", humanize.IBytes(uint64(s.CallStats.Tx)))) 472 473 return b.String() 474} 475 476// colorize node name 477func colorizedNodeName(nodeName string) string { 478 nodeHash := fnv.New32a() 479 nodeHash.Write([]byte(nodeName)) 480 nHashSum := nodeHash.Sum32() 481 idx := nHashSum % uint32(len(colors)) 482 return console.Colorize(fmt.Sprintf("Node%d", colors[idx]), nodeName) 483} 484 485func (t traceMessage) JSON() string { 486 t.Status = "success" 487 rqHdrs := make(map[string]string) 488 rspHdrs := make(map[string]string) 489 rq := t.Trace.ReqInfo 490 rs := t.Trace.RespInfo 491 for k, v := range rq.Headers { 492 rqHdrs[k] = strings.Join(v, " ") 493 } 494 for k, v := range rs.Headers { 495 rspHdrs[k] = strings.Join(v, " ") 496 } 497 trc := verboseTrace{ 498 Type: t.Trace.TraceType, 499 NodeName: t.Trace.NodeName, 500 FuncName: t.Trace.FuncName, 501 Time: t.Trace.Time, 502 RequestInfo: requestInfo{ 503 Time: rq.Time, 504 Proto: rq.Proto, 505 Method: rq.Method, 506 Path: rq.Path, 507 RawQuery: rq.RawQuery, 508 Body: string(rq.Body), 509 Headers: rqHdrs, 510 }, 511 ResponseInfo: responseInfo{ 512 Time: rs.Time, 513 Body: string(rs.Body), 514 Headers: rspHdrs, 515 StatusCode: rs.StatusCode, 516 }, 517 CallStats: callStats{ 518 Duration: t.Trace.CallStats.Latency, 519 Rx: t.Trace.CallStats.InputBytes, 520 Tx: t.Trace.CallStats.OutputBytes, 521 Ttfb: t.Trace.CallStats.TimeToFirstByte, 522 }, 523 OSStats: osStats{ 524 Duration: t.Trace.OSStats.Duration, 525 Path: t.Trace.OSStats.Path, 526 }, 527 StorageStats: storageStats{ 528 Duration: t.Trace.StorageStats.Duration, 529 Path: t.Trace.StorageStats.Path, 530 }, 531 } 532 buf := &bytes.Buffer{} 533 enc := json.NewEncoder(buf) 534 enc.SetIndent("", " ") 535 // Disable escaping special chars to display XML tags correctly 536 enc.SetEscapeHTML(false) 537 fatalIf(probe.NewError(enc.Encode(trc)), "Unable to marshal into JSON.") 538 539 // strip off extra newline added by json encoder 540 return strings.TrimSuffix(buf.String(), "\n") 541} 542 543func (t traceMessage) String() string { 544 var nodeNameStr string 545 var b = &strings.Builder{} 546 547 trc := t.Trace 548 if trc.NodeName != "" { 549 nodeNameStr = fmt.Sprintf("%s ", colorizedNodeName(trc.NodeName)) 550 } 551 552 switch trc.TraceType { 553 case madmin.TraceStorage: 554 fmt.Fprintf(b, "%s %s [%s] %s %s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[STORAGE %s]", trc.FuncName)), trc.Time.Local().Format(timeFormat), trc.StorageStats.Path, trc.StorageStats.Duration) 555 return b.String() 556 case madmin.TraceOS: 557 fmt.Fprintf(b, "%s %s [%s] %s %s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[OS %s]", trc.FuncName)), trc.Time.Local().Format(timeFormat), trc.OSStats.Path, trc.OSStats.Duration) 558 return b.String() 559 } 560 561 ri := trc.ReqInfo 562 rs := trc.RespInfo 563 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Request", fmt.Sprintf("[REQUEST %s] ", trc.FuncName))) 564 fmt.Fprintf(b, "[%s] %s\n", ri.Time.Local().Format(timeFormat), console.Colorize("Host", fmt.Sprintf("[Client IP: %s]", ri.Client))) 565 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Method", fmt.Sprintf("%s %s", ri.Method, ri.Path))) 566 if ri.RawQuery != "" { 567 fmt.Fprintf(b, "?%s", ri.RawQuery) 568 } 569 fmt.Fprint(b, "\n") 570 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Method", fmt.Sprintf("Proto: %s\n", ri.Proto))) 571 host, ok := ri.Headers["Host"] 572 if ok { 573 delete(ri.Headers, "Host") 574 } 575 hostStr := strings.Join(host, "") 576 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Host", fmt.Sprintf("Host: %s\n", hostStr))) 577 for k, v := range ri.Headers { 578 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("ReqHeaderKey", 579 fmt.Sprintf("%s: ", k))+console.Colorize("HeaderValue", fmt.Sprintf("%s\n", strings.Join(v, "")))) 580 } 581 582 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Body", fmt.Sprintf("%s\n", string(ri.Body)))) 583 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("Response", "[RESPONSE] ")) 584 fmt.Fprintf(b, "[%s] ", rs.Time.Local().Format(timeFormat)) 585 fmt.Fprint(b, console.Colorize("Stat", fmt.Sprintf("[ Duration %2s ↑ %s ↓ %s ]\n", trc.CallStats.Latency.Round(time.Microsecond), humanize.IBytes(uint64(trc.CallStats.InputBytes)), humanize.IBytes(uint64(trc.CallStats.OutputBytes))))) 586 587 statusStr := console.Colorize("RespStatus", fmt.Sprintf("%d %s", rs.StatusCode, http.StatusText(rs.StatusCode))) 588 if rs.StatusCode != http.StatusOK { 589 statusStr = console.Colorize("ErrStatus", fmt.Sprintf("%d %s", rs.StatusCode, http.StatusText(rs.StatusCode))) 590 } 591 fmt.Fprintf(b, "%s%s\n", nodeNameStr, statusStr) 592 593 for k, v := range rs.Headers { 594 fmt.Fprintf(b, "%s%s", nodeNameStr, console.Colorize("RespHeaderKey", 595 fmt.Sprintf("%s: ", k))+console.Colorize("HeaderValue", fmt.Sprintf("%s\n", strings.Join(v, ",")))) 596 } 597 fmt.Fprintf(b, "%s%s\n", nodeNameStr, console.Colorize("Body", string(rs.Body))) 598 fmt.Fprint(b, nodeNameStr) 599 return b.String() 600} 601