log non-2xx graph api calls (#1860)

## Description

Adds logging for non-2xx http communication
within the graph API client.  Logging req/resp
metadata is turned off by default, and requires
either a cli flag or os env var to enable.

## Does this PR need a docs update or release note?

- [x]  No 

## Type of change

- [x] 🤖 Test

## Issue(s)

* #1858

## Test Plan

- [x] 💚 E2E
This commit is contained in:
Keepers 2022-12-20 09:47:03 -07:00 committed by GitHub
parent 6a2a0a8b68
commit 569b5c44b2
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 42 additions and 14 deletions

View File

@ -208,6 +208,7 @@ jobs:
CORSO_M365_TEST_USER_ID: ${{ secrets.CORSO_M365_TEST_USER_ID }} CORSO_M365_TEST_USER_ID: ${{ secrets.CORSO_M365_TEST_USER_ID }}
CORSO_SECONDARY_M365_TEST_USER_ID: ${{ secrets.CORSO_SECONDARY_M365_TEST_USER_ID }} CORSO_SECONDARY_M365_TEST_USER_ID: ${{ secrets.CORSO_SECONDARY_M365_TEST_USER_ID }}
CORSO_PASSPHRASE: ${{ secrets.INTEGRATION_TEST_CORSO_PASSPHRASE }} CORSO_PASSPHRASE: ${{ secrets.INTEGRATION_TEST_CORSO_PASSPHRASE }}
LOG_GRAPH_REQUESTS: true
run: | run: |
set -euo pipefail set -euo pipefail
go test \ go test \

View File

@ -52,11 +52,12 @@ jobs:
AZURE_CLIENT_ID: ${{ secrets.AZURE_CLIENT_ID }} AZURE_CLIENT_ID: ${{ secrets.AZURE_CLIENT_ID }}
AZURE_CLIENT_SECRET: ${{ secrets.AZURE_CLIENT_SECRET }} AZURE_CLIENT_SECRET: ${{ secrets.AZURE_CLIENT_SECRET }}
AZURE_TENANT_ID: ${{ secrets.AZURE_TENANT_ID }} AZURE_TENANT_ID: ${{ secrets.AZURE_TENANT_ID }}
CORSO_PASSPHRASE: ${{ secrets.CORSO_PASSPHRASE }} CORSO_LOAD_TESTS: true
CORSO_M365_LOAD_TEST_USER_ID: ${{ secrets.CORSO_M365_LOAD_TEST_USER_ID }} CORSO_M365_LOAD_TEST_USER_ID: ${{ secrets.CORSO_M365_LOAD_TEST_USER_ID }}
CORSO_M365_LOAD_TEST_ORG_USERS: ${{ secrets.CORSO_M365_LOAD_TEST_ORG_USERS }} CORSO_M365_LOAD_TEST_ORG_USERS: ${{ secrets.CORSO_M365_LOAD_TEST_ORG_USERS }}
CORSO_PASSPHRASE: ${{ secrets.CORSO_PASSPHRASE }}
IGNORE_LOAD_TEST_USER_ID: ${{ secrets.EXT_SDK_TEST_USER_ID }} IGNORE_LOAD_TEST_USER_ID: ${{ secrets.EXT_SDK_TEST_USER_ID }}
CORSO_LOAD_TESTS: true LOG_GRAPH_REQUESTS: true
run: | run: |
set -euo pipefail set -euo pipefail
go test \ go test \

View File

@ -1,7 +1,6 @@
package graph package graph
import ( import (
"context"
nethttp "net/http" nethttp "net/http"
"net/http/httputil" "net/http/httputil"
"os" "os"
@ -51,12 +50,7 @@ func CreateAdapter(tenant, client, secret string) (*msgraphsdk.GraphRequestAdapt
func CreateHTTPClient() *nethttp.Client { func CreateHTTPClient() *nethttp.Client {
clientOptions := msgraphsdk.GetDefaultClientOptions() clientOptions := msgraphsdk.GetDefaultClientOptions()
middlewares := msgraphgocore.GetDefaultMiddlewaresWithOptions(&clientOptions) middlewares := msgraphgocore.GetDefaultMiddlewaresWithOptions(&clientOptions)
// When true, additional logging middleware support added for http request
if os.Getenv(logGraphRequestsEnvKey) != "" {
middlewares = append(middlewares, &LoggingMiddleware{}) middlewares = append(middlewares, &LoggingMiddleware{})
}
httpClient := msgraphgocore.GetDefaultClient(&clientOptions, middlewares...) httpClient := msgraphgocore.GetDefaultClient(&clientOptions, middlewares...)
httpClient.Timeout = time.Second * 90 httpClient.Timeout = time.Second * 90
@ -68,12 +62,39 @@ type LoggingMiddleware struct{}
// Intercept implements the RequestInterceptor interface and decodes the parameters name // Intercept implements the RequestInterceptor interface and decodes the parameters name
func (handler *LoggingMiddleware) Intercept( func (handler *LoggingMiddleware) Intercept(
pipeline khttp.Pipeline, middlewareIndex int, req *nethttp.Request, pipeline khttp.Pipeline,
middlewareIndex int,
req *nethttp.Request,
) (*nethttp.Response, error) { ) (*nethttp.Response, error) {
requestDump, _ := httputil.DumpRequest(req, true) var (
logger.Ctx(context.TODO()).Infof("REQUEST: %s", string(requestDump)) ctx = req.Context()
resp, err = pipeline.Next(req, middlewareIndex)
)
return pipeline.Next(req, middlewareIndex) if resp == nil {
return resp, err
}
if (resp.StatusCode / 100) == 2 {
return resp, err
}
if logger.DebugAPI || os.Getenv(logGraphRequestsEnvKey) != "" {
respDump, _ := httputil.DumpResponse(resp, true)
metadata := []any{
"method", req.Method,
"url", req.URL,
"requestLen", req.ContentLength,
"status", resp.Status,
"statusCode", resp.StatusCode,
"request", string(respDump),
}
logger.Ctx(ctx).Errorw("non-2xx graph api response", metadata...)
}
return resp, err
} }
func StringToPathCategory(input string) path.CategoryType { func StringToPathCategory(input string) path.CategoryType {

View File

@ -13,10 +13,11 @@ import (
var ( var (
logCore *zapcore.Core logCore *zapcore.Core
loggerton *zap.SugaredLogger loggerton *zap.SugaredLogger
// logging level flag // logging level flag
// TODO: infer default based on environment.
llFlag = "info" llFlag = "info"
DebugAPI bool
readableOutput bool readableOutput bool
) )
@ -31,6 +32,7 @@ const (
) )
const ( const (
debugAPIFN = "debug-api-calls"
logLevelFN = "log-level" logLevelFN = "log-level"
readableLogsFN = "readable-logs" readableLogsFN = "readable-logs"
) )
@ -43,6 +45,8 @@ func AddLogLevelFlag(cmd *cobra.Command) {
fs := cmd.PersistentFlags() fs := cmd.PersistentFlags()
fs.StringVar(&llFlag, logLevelFN, "info", "set the log level to debug|info|warn|error") fs.StringVar(&llFlag, logLevelFN, "info", "set the log level to debug|info|warn|error")
fs.Bool(debugAPIFN, false, "add non-2xx request/response errors to logging")
fs.Bool( fs.Bool(
readableLogsFN, false, readableLogsFN, false,
"minimizes log output for console readability: removes the file and date, colors the level") "minimizes log output for console readability: removes the file and date, colors the level")
@ -57,6 +61,7 @@ func PreloadLogLevel() string {
fs := pflag.NewFlagSet("seed-logger", pflag.ContinueOnError) fs := pflag.NewFlagSet("seed-logger", pflag.ContinueOnError)
fs.ParseErrorsWhitelist.UnknownFlags = true fs.ParseErrorsWhitelist.UnknownFlags = true
fs.String(logLevelFN, "info", "set the log level to debug|info|warn|error") fs.String(logLevelFN, "info", "set the log level to debug|info|warn|error")
fs.BoolVar(&DebugAPI, debugAPIFN, false, "add non-2xx request/response errors to logging")
fs.BoolVar(&readableOutput, readableLogsFN, false, "minimizes log output: removes the file and date, colors the level") fs.BoolVar(&readableOutput, readableLogsFN, false, "minimizes log output: removes the file and date, colors the level")
// prevents overriding the corso/cobra help processor // prevents overriding the corso/cobra help processor
fs.BoolP("help", "h", false, "") fs.BoolP("help", "h", false, "")