Skip to content

Commit a4128d7

Browse files
toma3233toma3233
authored
Merge pull request #25 from Azure/toma/resourceIdentifier
Using Resource Identifier for HTTP Request Logging
2 parents 0567e39 + d2e6383 commit a4128d7

File tree

2 files changed

+166
-188
lines changed

2 files changed

+166
-188
lines changed

‎http/common/logging/logging.go

+162-150
Original file line numberDiff line numberDiff line change
@@ -1,169 +1,181 @@
11
package logging
22

33
import (
4-
"log/slog"
5-
"net/http"
6-
"net/url"
7-
"strings"
8-
"time"
9-
10-
"github.com/Azure/aks-middleware/http/common"
11-
azcorePolicy "github.com/Azure/azure-sdk-for-go/sdk/azcore/policy"
4+
"log/slog"
5+
"net/http"
6+
"net/url"
7+
"strings"
8+
"time"
9+
10+
"github.com/Azure/aks-middleware/http/common"
11+
azcorePolicy "github.com/Azure/azure-sdk-for-go/sdk/azcore/policy"
12+
"github.com/Azure/azure-sdk-for-go/sdk/azcore/arm"
1213
)
1314

14-
var resourceTypes = map[string]bool{
15-
"resourcegroups": true,
16-
"storageaccounts": true,
17-
"operationresults": true,
18-
"asyncoperations": true,
19-
"checknameavailability": true,
15+
type LogRequestParams struct {
16+
Logger *slog.Logger
17+
StartTime time.Time
18+
Request interface{}
19+
Response *http.Response
20+
Error error
2021
}
2122

22-
type LogRequestParams struct {
23-
Logger *slog.Logger
24-
StartTime time.Time
25-
Request interface{}
26-
Response *http.Response
27-
Error error
23+
func trimToSubscription(rawURL string) string {
24+
// Find the index of "/subscriptions"
25+
if idx := strings.Index(rawURL, "/subscriptions"); idx != -1 {
26+
return rawURL[idx:]
27+
}
28+
return rawURL
29+
}
30+
31+
func sanitizeResourceType(rt string, rawURL string) string {
32+
// Keep only the substring after the last slash.
33+
if idx := strings.LastIndex(rt, "/"); idx != -1 && idx < len(rt)-1 {
34+
rt = rt[idx+1:]
35+
}
36+
// Remove everything after the first '?'.
37+
if idx := strings.Index(rt, "?"); idx != -1 {
38+
rt = rt[:idx]
39+
}
40+
rt = strings.ToLower(rt)
41+
42+
return rt
2843
}
2944

30-
// Shared logging function for REST API interactions
3145
func getMethodInfo(method string, rawURL string) string {
32-
urlParts := strings.Split(rawURL, "?api-version")
33-
// malformed url
34-
// check for v1 to ensure we aren't classifying restlogger as malformed
35-
if len(urlParts) < 2 && !strings.Contains(urlParts[0], "v1") {
36-
return method + " " + rawURL
37-
}
38-
parts := strings.Split(urlParts[0], "/")
39-
resource := urlParts[0]
40-
counter := 0
41-
// Start from the end of the split path and move backward
42-
// to get nested resource type
43-
for counter = len(parts) - 1; counter >= 0; counter-- {
44-
currToken := strings.ToLower(parts[counter])
45-
if strings.ContainsAny(currToken, "?/") {
46-
index := strings.IndexAny(currToken, "?/")
47-
currToken = currToken[:index]
48-
}
49-
if resourceTypes[currToken] {
50-
resource = currToken
51-
break
52-
}
53-
}
54-
55-
if method == "GET" {
56-
// resource name is specified, so it is a READ op
57-
if counter == len(parts)-1 {
58-
resource = resource + " - LIST"
59-
} else {
60-
resource = resource + " - READ"
61-
}
62-
}
63-
64-
// REST VERB + Resource Type
65-
methodInfo := method + " " + resource
66-
67-
return methodInfo
46+
// Trim the URL to ensure it starts with "/subscriptions"
47+
validURL := trimToSubscription(rawURL)
48+
49+
// First, try to parse validURL as a full resource ID.
50+
id, err := arm.ParseResourceID(validURL)
51+
if err != nil {
52+
// Retry by appending a false resource name ("dummy")
53+
// To be a valid resource ID, the URL must end with the resource name.
54+
fakeURL := validURL
55+
if !strings.HasSuffix(validURL, "/dummy") {
56+
fakeURL = validURL + "/dummy"
57+
}
58+
id, err = arm.ParseResourceID(fakeURL)
59+
if err != nil {
60+
// Fallback: if parsing still fails, use the full URL.
61+
return method + " " + rawURL
62+
}
63+
// We know a fake resource name was added.
64+
if method == "GET" {
65+
// For GET requests with a fake name, we assume it's a list operation.
66+
return method + " " + sanitizeResourceType(id.ResourceType.String(), rawURL) + " - LIST"
67+
}
68+
return method + " " + sanitizeResourceType(id.ResourceType.String(), rawURL)
69+
}
70+
71+
// If parsing was successful on the first try.
72+
if method == "GET" {
73+
op := " - READ"
74+
if strings.TrimSpace(id.Name) == "" {
75+
op = " - LIST"
76+
}
77+
return method + " " + sanitizeResourceType(id.ResourceType.String(), rawURL) + op
78+
}
79+
return method + " " + sanitizeResourceType(id.ResourceType.String(), rawURL)
6880
}
6981

7082
func trimURL(parsedURL url.URL) string {
71-
// Extract the `api-version` parameter
72-
apiVersion := parsedURL.Query().Get("api-version")
73-
74-
// Reconstruct the URL with only the `api-version` parameter
75-
baseURL := parsedURL.Scheme + "://" + parsedURL.Host + parsedURL.Path
76-
if apiVersion != "" {
77-
return baseURL + "?api-version=" + apiVersion
78-
}
79-
return baseURL
83+
// Extract the `api-version` parameter
84+
apiVersion := parsedURL.Query().Get("api-version")
85+
86+
// Reconstruct the URL with only the `api-version` parameter
87+
baseURL := parsedURL.Scheme + "://" + parsedURL.Host + parsedURL.Path
88+
if apiVersion != "" {
89+
return baseURL + "?api-version=" + apiVersion
90+
}
91+
return baseURL
8092
}
8193

8294
func LogRequest(params LogRequestParams) {
83-
var method, service, reqURL string
84-
switch req := params.Request.(type) {
85-
case *http.Request:
86-
method = req.Method
87-
service = req.Host
88-
reqURL = req.URL.String()
89-
90-
case *azcorePolicy.Request:
91-
method = req.Raw().Method
92-
service = req.Raw().Host
93-
reqURL = req.Raw().URL.String()
94-
default:
95-
return // Unknown request type, do nothing
96-
}
97-
98-
parsedURL, parseErr := url.Parse(reqURL)
99-
if parseErr != nil {
100-
params.Logger.With(
101-
"source", "ApiRequestLog",
102-
"protocol", "REST",
103-
"method_type", "unary",
104-
"code", "na",
105-
"component", "client",
106-
"time_ms", "na",
107-
"method", method,
108-
"service", service,
109-
"url", reqURL,
110-
"error", parseErr.Error(),
111-
).Error("error parsing request URL")
112-
} else {
113-
reqURL = trimURL(*parsedURL)
114-
}
115-
116-
methodInfo := getMethodInfo(method, reqURL)
117-
latency := time.Since(params.StartTime).Milliseconds()
118-
119-
var headers map[string]string
120-
if params.Response != nil {
121-
headers = extractHeaders(params.Response.Header)
122-
}
123-
124-
logEntry := params.Logger.With(
125-
"source", "ApiRequestLog",
126-
"protocol", "REST",
127-
"method_type", "unary",
128-
"component", "client",
129-
"time_ms", latency,
130-
"method", methodInfo,
131-
"service", service,
132-
"url", reqURL,
133-
"headers", headers,
134-
)
135-
136-
if params.Error != nil || params.Response == nil {
137-
logEntry.With("error", params.Error.Error(), "code", "na").Error("finished call")
138-
} else if 200 <= params.Response.StatusCode && params.Response.StatusCode < 300 {
139-
logEntry.With("error", "na", "code", params.Response.StatusCode).Info("finished call")
140-
} else {
141-
logEntry.With("error", params.Response.Status, "code", params.Response.StatusCode).Error("finished call")
142-
}
95+
var method, service, reqURL string
96+
switch req := params.Request.(type) {
97+
case *http.Request:
98+
method = req.Method
99+
service = req.Host
100+
reqURL = req.URL.String()
101+
102+
case *azcorePolicy.Request:
103+
method = req.Raw().Method
104+
service = req.Raw().Host
105+
reqURL = req.Raw().URL.String()
106+
default:
107+
return // Unknown request type, do nothing
108+
}
109+
110+
parsedURL, parseErr := url.Parse(reqURL)
111+
if parseErr != nil {
112+
params.Logger.With(
113+
"source", "ApiRequestLog",
114+
"protocol", "REST",
115+
"method_type", "unary",
116+
"code", "na",
117+
"component", "client",
118+
"time_ms", "na",
119+
"method", method,
120+
"service", service,
121+
"url", reqURL,
122+
"error", parseErr.Error(),
123+
).Error("error parsing request URL")
124+
} else {
125+
reqURL = trimURL(*parsedURL)
126+
}
127+
128+
methodInfo := getMethodInfo(method, reqURL)
129+
latency := time.Since(params.StartTime).Milliseconds()
130+
131+
var headers map[string]string
132+
if params.Response != nil {
133+
headers = extractHeaders(params.Response.Header)
134+
}
135+
136+
logEntry := params.Logger.With(
137+
"source", "ApiRequestLog",
138+
"protocol", "REST",
139+
"method_type", "unary",
140+
"component", "client",
141+
"time_ms", latency,
142+
"method", methodInfo,
143+
"service", service,
144+
"url", reqURL,
145+
"headers", headers,
146+
)
147+
148+
if params.Error != nil || params.Response == nil {
149+
logEntry.With("error", params.Error.Error(), "code", "na").Error("finished call")
150+
} else if 200 <= params.Response.StatusCode && params.Response.StatusCode < 300 {
151+
logEntry.With("error", "na", "code", params.Response.StatusCode).Info("finished call")
152+
} else {
153+
logEntry.With("error", params.Response.Status, "code", params.Response.StatusCode).Error("finished call")
154+
}
143155
}
144156

145157
func extractHeaders(header http.Header) map[string]string {
146-
headers := make(map[string]string)
147-
148-
// List of headers to extract
149-
headerKeys := []string{
150-
common.RequestCorrelationIDHeader,
151-
common.RequestAcsOperationIDHeader,
152-
common.RequestARMClientRequestIDHeader,
153-
}
154-
155-
// Convert header keys to lowercase
156-
lowerHeader := make(http.Header)
157-
for key, values := range header {
158-
lowerHeader[strings.ToLower(key)] = values
159-
}
160-
161-
for _, key := range headerKeys {
162-
lowerKey := strings.ToLower(key)
163-
if values, ok := lowerHeader[lowerKey]; ok && len(values) > 0 {
164-
headers[key] = values[0]
165-
}
166-
}
167-
168-
return headers
169-
}
158+
headers := make(map[string]string)
159+
160+
// List of headers to extract
161+
headerKeys := []string{
162+
common.RequestCorrelationIDHeader,
163+
common.RequestAcsOperationIDHeader,
164+
common.RequestARMClientRequestIDHeader,
165+
}
166+
167+
// Convert header keys to lowercase
168+
lowerHeader := make(http.Header)
169+
for key, values := range header {
170+
lowerHeader[strings.ToLower(key)] = values
171+
}
172+
173+
for _, key := range headerKeys {
174+
lowerKey := strings.ToLower(key)
175+
if values, ok := lowerHeader[lowerKey]; ok && len(values) > 0 {
176+
headers[key] = values[0]
177+
}
178+
}
179+
180+
return headers
181+
}

‎http/common/logging/logging_test.go

+4-38
Original file line numberDiff line numberDiff line change
@@ -101,26 +101,9 @@ var _ = Describe("LogRequest", func() {
101101
})
102102
})
103103

104-
Context("when URL is malformed", func() {
105-
It("logs the correct method with the entire URL", func() {
106-
parsedURL, err := url.Parse("https://management.azure.com/subscriptions/sub_id/resourceGroups/rg_name/providers/Microsoft.Storage/storageAccounts/account_name/api-version=version")
107-
Expect(err).To(BeNil())
108-
109-
params := logging.LogRequestParams{
110-
Logger: logger,
111-
StartTime: time.Now(),
112-
Request: &http.Request{Method: "GET", URL: parsedURL},
113-
Response: &http.Response{StatusCode: 200},
114-
Error: nil,
115-
}
116-
expected := "GET https://management.azure.com/subscriptions/sub_id/resourceGroups/rg_name/providers/Microsoft.Storage/storageAccounts/account_name/api-version=version"
117-
logging.LogRequest(params)
118-
Expect(logBuffer.String()).To(ContainSubstring(expected))
119-
})
120-
})
121-
Context("when the resource type is not found", func() {
122-
It("logs the correct method with the entire URL", func() {
123-
parsedURL, err := url.Parse("https://management.azure.com/subscriptions/sub_id/customResourceGroup/resource_name/providers/Microsoft.Storage/customResource/resource_name?api-version=version")
104+
Context("when using a custom resource type", func() {
105+
It("logs the correct method info", func() {
106+
parsedURL, err := url.Parse("http://nodeprovisioner-svc.nodeprovisioner.svc.cluster.local:80/subscriptions/26ad903f-2330-429d-8389-864ac35c4350/resourceGroups/e2erg-tomabraebld114261747-nRi/providers/Microsoft.ContainerService/managedclusters/e2eaks-Sfs/nodeBootstrapping")
124107
Expect(err).To(BeNil())
125108

126109
params := logging.LogRequestParams{
@@ -130,7 +113,7 @@ var _ = Describe("LogRequest", func() {
130113
Response: &http.Response{StatusCode: 200},
131114
Error: nil,
132115
}
133-
expected := "GET https://management.azure.com/subscriptions/sub_id/customResourceGroup/resource_name/providers/Microsoft.Storage/customResource/resource_name - READ"
116+
expected := "GET nodebootstrapping - LIST"
134117
logging.LogRequest(params)
135118
Expect(logBuffer.String()).To(ContainSubstring(expected))
136119
})
@@ -152,21 +135,4 @@ var _ = Describe("LogRequest", func() {
152135
Expect(logBuffer.String()).To(ContainSubstring(expected))
153136
})
154137
})
155-
Context("when there are zero query parameters", func() {
156-
It("logs the correct method with the entire URL", func() {
157-
parsedURL, err := url.Parse("https://management.azure.com/subscriptions/sub_id/resourceGroups/rg_name/providers/Microsoft.Storage/storageAccounts")
158-
Expect(err).To(BeNil())
159-
160-
params := logging.LogRequestParams{
161-
Logger: logger,
162-
StartTime: time.Now(),
163-
Request: &http.Request{Method: "GET", URL: parsedURL},
164-
Response: &http.Response{StatusCode: 200},
165-
Error: nil,
166-
}
167-
expected := "GET https://management.azure.com/subscriptions/sub_id/resourceGroups/rg_name/providers/Microsoft.Storage/storageAccounts"
168-
logging.LogRequest(params)
169-
Expect(logBuffer.String()).To(ContainSubstring(expected))
170-
})
171-
})
172138
})

0 commit comments

Comments
 (0)