improve azurerm logs parsing

ms-henglu · Jul 31, 2023 · 89d5e35 · 89d5e35
1 parent 9da1162
commit 89d5e35
Show file tree

Hide file tree

Showing 6 changed files with 286 additions and 47 deletions.
diff --git a/main.go b/main.go
@@ -6,6 +6,7 @@ import (
 	"log"
 	"os"
 	"path"
+	"strings"
 
 	"github.com/ms-henglu/pal/formatter"
 	"github.com/ms-henglu/pal/formatter/azapi"
@@ -62,6 +63,13 @@ func main() {
 		log.Fatalf("[ERROR] failed to parse request traces: %v", err)
 	}
 
+	for _, t := range traces {
+		out := trace.VerifyRequestTrace(t)
+		if len(out) > 0 {
+			log.Printf("[WARN] verification failed: url %s\n%s", t.Url, strings.Join(out, "\n"))
+		}
+	}
+
 	switch mode {
 	case "oav":
 		format := formatter.OavTrafficFormatter{}

diff --git a/provider/azurerm.go b/provider/azurerm.go
@@ -16,38 +16,35 @@ type AzureRMProvider struct {
 }
 
 func (a AzureRMProvider) IsRequestTrace(l rawlog.RawLog) bool {
-	return l.Level == "DEBUG" && strings.Contains(l.Message, "provider.terraform-provider-azurerm") && strings.Contains(l.Message, "AzureRM Request:")
+	return l.Level == "DEBUG" && strings.Contains(l.Message, "AzureRM Request:")
 }
 
 func (a AzureRMProvider) IsResponseTrace(l rawlog.RawLog) bool {
-	return l.Level == "DEBUG" && strings.Contains(l.Message, "provider.terraform-provider-azurerm") && strings.Contains(l.Message, "AzureRM Response for")
+	return l.Level == "DEBUG" && strings.Contains(l.Message, "AzureRM Response for")
 }
 
 func (a AzureRMProvider) ParseRequest(l rawlog.RawLog) (*types.RequestTrace, error) {
 	urlPath := ""
 	method := ""
 	headers := make(map[string]string)
 	body := ""
-	for _, line := range strings.Split(l.Message, "\n") {
+
+	lines := strings.Split(l.Message, "\n")
+	i := 0
+	foundBodySegment := false
+	for ; i < len(lines); i++ {
+		line := lines[i]
 		switch {
-		case line == "":
-			continue
-		case strings.Contains(line, ": timestamp"):
-			index := strings.LastIndex(line, ": timestamp")
-			if utils.IsJson(line[0:index]) {
-				body = line[0:index]
-			} else {
-				lineTrimTimestamp := line[0:index]
-				key, value, err := utils.ParseHeader(lineTrimTimestamp)
-				if err == nil {
-					headers[key] = value
-				}
-			}
+		case strings.TrimSpace(line) == "":
+			foundBodySegment = true
 		case strings.Contains(line, ": "):
 			key, value, err := utils.ParseHeader(line)
 			if strings.HasPrefix(key, "provider.terraform-provider-azurerm") {
 				continue
 			}
+			if key == "AzureRM Request" {
+				continue
+			}
 			if err != nil {
 				return nil, err
 			}
@@ -58,6 +55,27 @@ func (a AzureRMProvider) ParseRequest(l rawlog.RawLog) (*types.RequestTrace, err
 				urlPath = parts[1]
 			}
 		}
+		if foundBodySegment {
+			break
+		}
+	}
+
+	if i+1 < len(lines) {
+		line := strings.Join(lines[i+1:], "\n")
+		if strings.Contains(line, ": timestamp") {
+			index := strings.LastIndex(line, ": timestamp")
+			if utils.IsJson(line[0:index]) {
+				body = line[0:index]
+			} else {
+				lineTrimTimestamp := line[0:index]
+				key, value, err := utils.ParseHeader(lineTrimTimestamp)
+				if err == nil {
+					headers[key] = value
+				}
+			}
+		} else {
+			body = line
+		}
 	}
 	return &types.RequestTrace{
 		TimeStamp: l.TimeStamp,
@@ -120,6 +138,8 @@ func (a AzureRMProvider) ParseResponse(l rawlog.RawLog) (*types.RequestTrace, er
 			if utils.IsJson(line[0:index]) {
 				body = line[0:index]
 			}
+		} else {
+			body = line
 		}
 	}
 

diff --git a/provider/azurerm_test.go b/provider/azurerm_test.go
@@ -130,6 +130,36 @@ func TestAzureRMProvider_ParseRequest(t *testing.T) {
 		log  string
 		want types.RequestTrace
 	}{
+		{
+			name: "azurerm PUT request trace",
+			log: `2023/07/28 14:03:39 [DEBUG] AzureRM Request: 
+PUT /subscriptions/00000000-0000-0000-0000-000000000000/resourcegroups/acctestSecRG-230728140330751068?api-version=2020-06-01 HTTP/1.1
+Host: management.azure.com
+User-Agent: Go/go1.20.6 (amd64-windows) go-autorest/v14.2.1 Azure-SDK-For-Go/v66.0.0 resources/2020-06-01 HashiCorp Terraform/1.5.3 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820
+Content-Length: 35
+Content-Type: application/json; charset=utf-8
+X-Ms-Correlation-Request-Id: 61f38736-e811-d8b4-befd-c3f5a39c3f35
+Accept-Encoding: gzip
+
+{"location":"westeurope","tags":{}}`,
+			want: types.RequestTrace{
+				Provider: "azurerm",
+				Method:   "PUT",
+				Host:     "management.azure.com",
+				Url:      "/subscriptions/00000000-0000-0000-0000-000000000000/resourcegroups/acctestSecRG-230728140330751068?api-version=2020-06-01",
+				Request: &types.HttpRequest{
+					Headers: map[string]string{
+						"Host":                        "management.azure.com",
+						"User-Agent":                  "Go/go1.20.6 (amd64-windows) go-autorest/v14.2.1 Azure-SDK-For-Go/v66.0.0 resources/2020-06-01 HashiCorp Terraform/1.5.3 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820",
+						"Content-Length":              "35",
+						"Content-Type":                "application/json; charset=utf-8",
+						"X-Ms-Correlation-Request-Id": "61f38736-e811-d8b4-befd-c3f5a39c3f35",
+						"Accept-Encoding":             "gzip",
+					},
+					Body: `{"location":"westeurope","tags":{}}`,
+				},
+			},
+		},
 		{
 			name: "azurerm GET request trace",
 			log: `2023-06-15T14:34:07.601+0800 [DEBUG] provider.terraform-provider-azurerm_v3.61.0_x5: AzureRM Request: 
@@ -248,9 +278,54 @@ func TestAzureRMProvider_ParseResponse(t *testing.T) {
 		log  string
 		want types.RequestTrace
 	}{
+		{
+			name: "azurerm GET response trace",
+			log: `2023/07/28 14:03:36 [DEBUG] AzureRM Response for https://management.azure.com//providers/Microsoft.Authorization/roleDefinitions/fbdf93bf-df7d-467e-a4d2-9458aa1360c8?api-version=2018-01-01-preview: 
+HTTP/2.0 200 OK
+Cache-Control: no-cache
+Content-Type: application/json; charset=utf-8
+Date: Fri, 28 Jul 2023 06:03:36 GMT
+Expires: -1
+Pragma: no-cache
+Set-Cookie: x-ms-gateway-slice=Production; path=/; secure; samesite=none; httponly
+Strict-Transport-Security: max-age=31536000; includeSubDomains
+Vary: Accept-Encoding
+X-Content-Type-Options: nosniff
+X-Ms-Correlation-Request-Id: 61f38736-e811-d8b4-befd-c3f5a39c3f35
+X-Ms-Ratelimit-Remaining-Tenant-Reads: 11999
+X-Ms-Request-Id: 1bd7e400-947e-482b-9ad5-cc7f7265a512
+X-Ms-Routing-Request-Id: JAPANEAST:20230728T060336Z:040e3cf8-3c01-461c-9ce0-c27f46037f58
+
+{"properties":{"roleName":"Cosmos DB Account Reader Role","type":"BuiltInRole","description":"Can read Azure Cosmos DB Accounts data","assignableScopes":["/"],"permissions":[{"actions":["Microsoft.Authorization/*/read","Microsoft.DocumentDB/*/read","Microsoft.DocumentDB/databaseAccounts/readonlykeys/action","Microsoft.Insights/MetricDefinitions/read","Microsoft.Insights/Metrics/read","Microsoft.Resources/subscriptions/resourceGroups/read","Microsoft.Support/*"],"notActions":[],"dataActions":[],"notDataActions":[]}],"createdOn":"2017-10-30T17:53:54.6005577Z","updatedOn":"2021-11-11T20:13:28.7911765Z","createdBy":null,"updatedBy":null},"id":"/providers/Microsoft.Authorization/roleDefinitions/fbdf93bf-df7d-467e-a4d2-9458aa1360c8","type":"Microsoft.Authorization/roleDefinitions","name":"fbdf93bf-df7d-467e-a4d2-9458aa1360c8"}`,
+			want: types.RequestTrace{
+				Provider:   "azurerm",
+				Method:     "",
+				StatusCode: 200,
+				Host:       "management.azure.com",
+				Url:        "/providers/Microsoft.Authorization/roleDefinitions/fbdf93bf-df7d-467e-a4d2-9458aa1360c8?api-version=2018-01-01-preview",
+				Response: &types.HttpResponse{
+					Headers: map[string]string{
+						"Cache-Control":                         "no-cache",
+						"Content-Type":                          "application/json; charset=utf-8",
+						"Date":                                  "Fri, 28 Jul 2023 06:03:36 GMT",
+						"Expires":                               "-1",
+						"Pragma":                                "no-cache",
+						"Set-Cookie":                            "x-ms-gateway-slice=Production; path=/; secure; samesite=none; httponly",
+						"Strict-Transport-Security":             "max-age=31536000; includeSubDomains",
+						"Vary":                                  "Accept-Encoding",
+						"X-Content-Type-Options":                "nosniff",
+						"X-Ms-Correlation-Request-Id":           "61f38736-e811-d8b4-befd-c3f5a39c3f35",
+						"X-Ms-Ratelimit-Remaining-Tenant-Reads": "11999",
+						"X-Ms-Request-Id":                       "1bd7e400-947e-482b-9ad5-cc7f7265a512",
+						"X-Ms-Routing-Request-Id":               "JAPANEAST:20230728T060336Z:040e3cf8-3c01-461c-9ce0-c27f46037f58",
+					},
+					Body: `{"properties":{"roleName":"Cosmos DB Account Reader Role","type":"BuiltInRole","description":"Can read Azure Cosmos DB Accounts data","assignableScopes":["/"],"permissions":[{"actions":["Microsoft.Authorization/*/read","Microsoft.DocumentDB/*/read","Microsoft.DocumentDB/databaseAccounts/readonlykeys/action","Microsoft.Insights/MetricDefinitions/read","Microsoft.Insights/Metrics/read","Microsoft.Resources/subscriptions/resourceGroups/read","Microsoft.Support/*"],"notActions":[],"dataActions":[],"notDataActions":[]}],"createdOn":"2017-10-30T17:53:54.6005577Z","updatedOn":"2021-11-11T20:13:28.7911765Z","createdBy":null,"updatedBy":null},"id":"/providers/Microsoft.Authorization/roleDefinitions/fbdf93bf-df7d-467e-a4d2-9458aa1360c8","type":"Microsoft.Authorization/roleDefinitions","name":"fbdf93bf-df7d-467e-a4d2-9458aa1360c8"}`,
+				},
+			},
+		},
 		{
 			name: "azurerm PUT response trace",
-			log: `2023-07-11T16:24:16.674+0800 [DEBUG] provider.terraform-provider-azurerm: AzureRM Response for https://management.azure.com/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu6421/providers/Microsoft.Insights/components/henglu9128?api-version=2020-02-02: 
+			log: `2023-07-11T16:24:16.674+0800 [DEBUG] provider.terraform-provider-azurerm: AzureRM Response for https://management.azure.com/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu6421/providers/Microsoft.Insights/components/henglu9128?api-version=2020-02-02: 
 HTTP/2.0 200 OK
 Access-Control-Expose-Headers: Request-Context
 Cache-Control: no-cache
@@ -270,7 +345,7 @@ X-Ms-Routing-Request-Id: SOUTHEASTASIA:20230711T082416Z:aa9250b0-9955-4821-ad66-
 X-Powered-By: ASP.NET
 
 {
-  "id": "/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu6421/providers/microsoft.insights/components/henglu9128",
+  "id": "/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu6421/providers/microsoft.insights/components/henglu9128",
   "name": "henglu9128",
   "type": "microsoft.insights/components",
   "location": "westeurope",
@@ -287,7 +362,7 @@ X-Powered-By: ASP.NET
     "ConnectionString": "InstrumentationKey=2d727e28-a681-48af-95aa-677daba464d6;IngestionEndpoint=https://westeurope-4.in.applicationinsights.azure.com/;LiveEndpoint=https://westeurope.livediagnostics.monitor.azure.com/",
     "Name": "henglu9128",
     "CreationDate": "2023-07-11T08:24:14.7161403+00:00",
-    "TenantId": "85b3dbca-5974-4067-9669-67a141095a76",
+    "TenantId": "00000000-0000-0000-0000-000000000000",
     "provisioningState": "Succeeded",
     "SamplingPercentage": 100.0,
     "RetentionInDays": 90,
@@ -306,7 +381,7 @@ X-Powered-By: ASP.NET
 				Method:     "",
 				StatusCode: 200,
 				Host:       "management.azure.com",
-				Url:        "/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu6421/providers/Microsoft.Insights/components/henglu9128?api-version=2020-02-02",
+				Url:        "/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu6421/providers/Microsoft.Insights/components/henglu9128?api-version=2020-02-02",
 				Response: &types.HttpResponse{
 					Headers: map[string]string{
 						"Access-Control-Expose-Headers": "Request-Context",
@@ -328,7 +403,7 @@ X-Powered-By: ASP.NET
 					},
 					Body: `
 {
-  "id": "/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu6421/providers/microsoft.insights/components/henglu9128",
+  "id": "/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu6421/providers/microsoft.insights/components/henglu9128",
   "name": "henglu9128",
   "type": "microsoft.insights/components",
   "location": "westeurope",
@@ -345,7 +420,7 @@ X-Powered-By: ASP.NET
     "ConnectionString": "InstrumentationKey=2d727e28-a681-48af-95aa-677daba464d6;IngestionEndpoint=https://westeurope-4.in.applicationinsights.azure.com/;LiveEndpoint=https://westeurope.livediagnostics.monitor.azure.com/",
     "Name": "henglu9128",
     "CreationDate": "2023-07-11T08:24:14.7161403+00:00",
-    "TenantId": "85b3dbca-5974-4067-9669-67a141095a76",
+    "TenantId": "00000000-0000-0000-0000-000000000000",
     "provisioningState": "Succeeded",
     "SamplingPercentage": 100.0,
     "RetentionInDays": 90,
@@ -364,7 +439,7 @@ X-Powered-By: ASP.NET
 		},
 		{
 			name: "azurerm GET response trace",
-			log: `2023-06-15T15:10:42.112+0800 [DEBUG] provider.terraform-provider-azurerm_v3.61.0_x5: AzureRM Response for https://management.azure.com/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourcegroups/henglu615aa?api-version=2020-06-01: 
+			log: `2023-06-15T15:10:42.112+0800 [DEBUG] provider.terraform-provider-azurerm_v3.61.0_x5: AzureRM Response for https://management.azure.com/subscriptions/00000000-0000-0000-0000-000000000000/resourcegroups/henglu615aa?api-version=2020-06-01: 
 HTTP/2.0 200 OK
 Cache-Control: no-cache
 Content-Type: application/json; charset=utf-8
@@ -379,13 +454,13 @@ X-Ms-Ratelimit-Remaining-Subscription-Reads: 11999
 X-Ms-Request-Id: c11a4994-287b-4ea7-ac13-ccf635682936
 X-Ms-Routing-Request-Id: SOUTHEASTASIA:20230615T071042Z:c11a4994-287b-4ea7-ac13-ccf635682936
 
-{"id":"/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}: timestamp=2023-06-15T15:10:42.112+0800`,
+{"id":"/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}: timestamp=2023-06-15T15:10:42.112+0800`,
 			want: types.RequestTrace{
 				Provider:   "azurerm",
 				Method:     "",
 				StatusCode: 200,
 				Host:       "management.azure.com",
-				Url:        "/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourcegroups/henglu615aa?api-version=2020-06-01",
+				Url:        "/subscriptions/00000000-0000-0000-0000-000000000000/resourcegroups/henglu615aa?api-version=2020-06-01",
 				Response: &types.HttpResponse{
 					Headers: map[string]string{
 						"Cache-Control":               "no-cache",
@@ -401,13 +476,13 @@ X-Ms-Routing-Request-Id: SOUTHEASTASIA:20230615T071042Z:c11a4994-287b-4ea7-ac13-
 						"X-Ms-Request-Id":         "c11a4994-287b-4ea7-ac13-ccf635682936",
 						"X-Ms-Routing-Request-Id": "SOUTHEASTASIA:20230615T071042Z:c11a4994-287b-4ea7-ac13-ccf635682936",
 					},
-					Body: `{"id":"/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}`,
+					Body: `{"id":"/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}`,
 				},
 			},
 		},
 		{
 			name: "azapi PUT response trace",
-			log: `2023-06-15T15:12:41.772+0800 [DEBUG] provider.terraform-provider-azurerm_v3.61.0_x5: AzureRM Response for https://management.azure.com/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourcegroups/henglu615aa?api-version=2020-06-01: 
+			log: `2023-06-15T15:12:41.772+0800 [DEBUG] provider.terraform-provider-azurerm_v3.61.0_x5: AzureRM Response for https://management.azure.com/subscriptions/00000000-0000-0000-0000-000000000000/resourcegroups/henglu615aa?api-version=2020-06-01: 
 HTTP/2.0 201 Created
 Content-Length: 233
 Cache-Control: no-cache
@@ -422,13 +497,13 @@ X-Ms-Ratelimit-Remaining-Subscription-Writes: 1199
 X-Ms-Request-Id: 99b0be99-5635-4044-9961-06772eb84bdc
 X-Ms-Routing-Request-Id: SOUTHEASTASIA:20230615T071241Z:99b0be99-5635-4044-9961-06772eb84bdc
 
-{"id":"/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}: timestamp=2023-06-15T15:12:41.772+0800
+{"id":"/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}: timestamp=2023-06-15T15:12:41.772+0800
 `,
 			want: types.RequestTrace{
 				Provider:   "azurerm",
 				StatusCode: 201,
 				Host:       "management.azure.com",
-				Url:        "/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourcegroups/henglu615aa?api-version=2020-06-01",
+				Url:        "/subscriptions/00000000-0000-0000-0000-000000000000/resourcegroups/henglu615aa?api-version=2020-06-01",
 				Method:     "",
 				Response: &types.HttpResponse{
 					Headers: map[string]string{
@@ -445,7 +520,7 @@ X-Ms-Routing-Request-Id: SOUTHEASTASIA:20230615T071241Z:99b0be99-5635-4044-9961-
 						"X-Ms-Request-Id":         "99b0be99-5635-4044-9961-06772eb84bdc",
 						"X-Ms-Routing-Request-Id": "SOUTHEASTASIA:20230615T071241Z:99b0be99-5635-4044-9961-06772eb84bdc",
 					},
-					Body: `{"id":"/subscriptions/85b3dbca-5974-4067-9669-67a141095a76/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}`,
+					Body: `{"id":"/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/henglu615aa","name":"henglu615aa","type":"Microsoft.Resources/resourceGroups","location":"westeurope","tags":{},"properties":{"provisioningState":"Succeeded"}}`,
 				},
 			},
 		},

diff --git a/rawlog/raw_log.go b/rawlog/raw_log.go
@@ -13,22 +13,29 @@ type RawLog struct {
 	Message   string
 }
 
-var rawLogRegex = regexp.MustCompile(`([\d+.:T\-]{28})\s\[([A-Z]+)]`)
+var regLayoutMap = map[*regexp.Regexp]string{
+	regexp.MustCompile(`([\d+.:T\-]{28})\s\[([A-Z]+)]`):  "2006-01-02T15:04:05.999-0700",
+	regexp.MustCompile(`([\d+.:T\- ]{19})\s\[([A-Z]+)]`): "2006-01-02 15:04:05",
+	regexp.MustCompile(`([\d+.:T/ ]{19})\s\[([A-Z]+)]`):  "2006/01/02 15:04:05",
+}
 
 func NewRawLog(message string) (*RawLog, error) {
-	matches := rawLogRegex.FindAllStringSubmatch(message, -1)
-	if len(matches) == 0 || len(matches[0]) != 3 {
-		return nil, fmt.Errorf("failed to parse log message: %s", message)
-	}
-	t, err := time.Parse("2006-01-02T15:04:05.999-0700", matches[0][1])
-	if err != nil {
-		return nil, fmt.Errorf("failed to parse timestamp: %v", err)
+	for reg, layout := range regLayoutMap {
+		matches := reg.FindAllStringSubmatch(message, -1)
+		if len(matches) == 0 || len(matches[0]) != 3 {
+			continue
+		}
+		t, err := time.Parse(layout, matches[0][1])
+		if err != nil {
+			continue
+		}
+		m := message[len(matches[0][0]):]
+		m = strings.Trim(m, " \n")
+		return &RawLog{
+			TimeStamp: t,
+			Level:     matches[0][2],
+			Message:   m,
+		}, nil
 	}
-	m := message[len(matches[0][0]):]
-	m = strings.Trim(m, " \n")
-	return &RawLog{
-		TimeStamp: t,
-		Level:     matches[0][2],
-		Message:   m,
-	}, nil
+	return nil, fmt.Errorf("failed to parse log message: %s", message)
 }