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