1//go:build go1.16 2// +build go1.16 3 4// Copyright (c) Microsoft Corporation. All rights reserved. 5// Licensed under the MIT License. 6 7package runtime 8 9import ( 10 "bytes" 11 "fmt" 12 "io/ioutil" 13 "net/http" 14 "strings" 15 "time" 16 17 "github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/shared" 18 "github.com/Azure/azure-sdk-for-go/sdk/azcore/policy" 19 "github.com/Azure/azure-sdk-for-go/sdk/internal/diag" 20 "github.com/Azure/azure-sdk-for-go/sdk/internal/log" 21) 22 23type logPolicy struct { 24 options policy.LogOptions 25} 26 27// NewLogPolicy creates a RequestLogPolicy object configured using the specified options. 28// Pass nil to accept the default values; this is the same as passing a zero-value options. 29func NewLogPolicy(o *policy.LogOptions) policy.Policy { 30 if o == nil { 31 o = &policy.LogOptions{} 32 } 33 return &logPolicy{options: *o} 34} 35 36// logPolicyOpValues is the struct containing the per-operation values 37type logPolicyOpValues struct { 38 try int32 39 start time.Time 40} 41 42func (p *logPolicy) Do(req *policy.Request) (*http.Response, error) { 43 // Get the per-operation values. These are saved in the Message's map so that they persist across each retry calling into this policy object. 44 var opValues logPolicyOpValues 45 if req.OperationValue(&opValues); opValues.start.IsZero() { 46 opValues.start = time.Now() // If this is the 1st try, record this operation's start time 47 } 48 opValues.try++ // The first try is #1 (not #0) 49 req.SetOperationValue(opValues) 50 51 // Log the outgoing request as informational 52 if log.Should(log.Request) { 53 b := &bytes.Buffer{} 54 fmt.Fprintf(b, "==> OUTGOING REQUEST (Try=%d)\n", opValues.try) 55 writeRequestWithResponse(b, req, nil, nil) 56 var err error 57 if p.options.IncludeBody { 58 err = writeReqBody(req, b) 59 } 60 log.Write(log.Request, b.String()) 61 if err != nil { 62 return nil, err 63 } 64 } 65 66 // Set the time for this particular retry operation and then Do the operation. 67 tryStart := time.Now() 68 response, err := req.Next() // Make the request 69 tryEnd := time.Now() 70 tryDuration := tryEnd.Sub(tryStart) 71 opDuration := tryEnd.Sub(opValues.start) 72 73 if log.Should(log.Response) { 74 // We're going to log this; build the string to log 75 b := &bytes.Buffer{} 76 fmt.Fprintf(b, "==> REQUEST/RESPONSE (Try=%d/%v, OpTime=%v) -- ", opValues.try, tryDuration, opDuration) 77 if err != nil { // This HTTP request did not get a response from the service 78 fmt.Fprint(b, "REQUEST ERROR\n") 79 } else { 80 fmt.Fprint(b, "RESPONSE RECEIVED\n") 81 } 82 83 writeRequestWithResponse(b, req, response, err) 84 if err != nil { 85 // skip frames runtime.Callers() and runtime.StackTrace() 86 b.WriteString(diag.StackTrace(2, 32)) 87 } else if p.options.IncludeBody { 88 err = writeRespBody(response, b) 89 } 90 log.Write(log.Response, b.String()) 91 } 92 return response, err 93} 94 95// returns true if the request/response body should be logged. 96// this is determined by looking at the content-type header value. 97func shouldLogBody(b *bytes.Buffer, contentType string) bool { 98 contentType = strings.ToLower(contentType) 99 if strings.HasPrefix(contentType, "text") || 100 strings.Contains(contentType, "json") || 101 strings.Contains(contentType, "xml") { 102 return true 103 } 104 fmt.Fprintf(b, " Skip logging body for %s\n", contentType) 105 return false 106} 107 108// writes to a buffer, used for logging purposes 109func writeReqBody(req *policy.Request, b *bytes.Buffer) error { 110 if req.Raw().Body == nil { 111 fmt.Fprint(b, " Request contained no body\n") 112 return nil 113 } 114 if ct := req.Raw().Header.Get(shared.HeaderContentType); !shouldLogBody(b, ct) { 115 return nil 116 } 117 body, err := ioutil.ReadAll(req.Raw().Body) 118 if err != nil { 119 fmt.Fprintf(b, " Failed to read request body: %s\n", err.Error()) 120 return err 121 } 122 if err := req.RewindBody(); err != nil { 123 return err 124 } 125 logBody(b, body) 126 return nil 127} 128 129// writes to a buffer, used for logging purposes 130func writeRespBody(resp *http.Response, b *bytes.Buffer) error { 131 ct := resp.Header.Get(shared.HeaderContentType) 132 if ct == "" { 133 fmt.Fprint(b, " Response contained no body\n") 134 return nil 135 } else if !shouldLogBody(b, ct) { 136 return nil 137 } 138 body, err := Payload(resp) 139 if err != nil { 140 fmt.Fprintf(b, " Failed to read response body: %s\n", err.Error()) 141 return err 142 } 143 if len(body) > 0 { 144 logBody(b, body) 145 } else { 146 fmt.Fprint(b, " Response contained no body\n") 147 } 148 return nil 149} 150 151func logBody(b *bytes.Buffer, body []byte) { 152 fmt.Fprintln(b, " --------------------------------------------------------------------------------") 153 fmt.Fprintln(b, string(body)) 154 fmt.Fprintln(b, " --------------------------------------------------------------------------------") 155} 156