From 7b0389016c05c40a20639a4d0609bbd728250b68 Mon Sep 17 00:00:00 2001 From: David Wahler Date: Fri, 20 May 2022 00:06:05 +0000 Subject: [PATCH 1/3] feat: Add simple request logging to CLI --- cli/requestlogging.go | 38 ++++++++++++++++++++++++++++++++++++ cli/requestlogging_test.go | 40 ++++++++++++++++++++++++++++++++++++++ cli/root.go | 18 +++++++++++++++-- codersdk/client.go | 10 ++++++++++ 4 files changed, 104 insertions(+), 2 deletions(-) create mode 100644 cli/requestlogging.go create mode 100644 cli/requestlogging_test.go diff --git a/cli/requestlogging.go b/cli/requestlogging.go new file mode 100644 index 0000000000000..76a811c837489 --- /dev/null +++ b/cli/requestlogging.go @@ -0,0 +1,38 @@ +package cli + +import ( + "fmt" + "io" + "net/http" + "strconv" +) + +type loggingRoundTripper struct { + http.RoundTripper + io.Writer +} + +func newLoggingRoundTripper(writer io.Writer) http.RoundTripper { + return &loggingRoundTripper{ + Writer: writer, + } +} + +func (lrt loggingRoundTripper) RoundTrip(request *http.Request) (*http.Response, error) { + inner := lrt.RoundTripper + if inner == nil { + inner = http.DefaultTransport + } + + response, err := inner.RoundTrip(request) + + var displayedStatusCode string + if err != nil { + displayedStatusCode = "(err)" + } else { + displayedStatusCode = strconv.Itoa(response.StatusCode) + } + + _, _ = fmt.Fprintf(lrt.Writer, "%s %s %s\n", request.Method, request.URL.String(), displayedStatusCode) + return response, err +} diff --git a/cli/requestlogging_test.go b/cli/requestlogging_test.go new file mode 100644 index 0000000000000..23563d6a06333 --- /dev/null +++ b/cli/requestlogging_test.go @@ -0,0 +1,40 @@ +package cli_test + +import ( + "testing" + + "github.com/stretchr/testify/require" + + "github.com/coder/coder/cli/clitest" + "github.com/coder/coder/coderd/coderdtest" + "github.com/coder/coder/pty/ptytest" +) + +func TestRequestLogging(t *testing.T) { + t.Parallel() + t.Run("List", func(t *testing.T) { + t.Parallel() + client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerD: true}) + user := coderdtest.CreateFirstUser(t, client) + version := coderdtest.CreateTemplateVersion(t, client, user.OrganizationID, nil) + coderdtest.AwaitTemplateVersionJob(t, client, version.ID) + template := coderdtest.CreateTemplate(t, client, user.OrganizationID, version.ID) + workspace := coderdtest.CreateWorkspace(t, client, user.OrganizationID, template.ID) + coderdtest.AwaitWorkspaceBuildJob(t, client, workspace.LatestBuild.ID) + cmd, root := clitest.New(t, "ls", "--log-requests") + clitest.SetupConfig(t, client, root) + doneChan := make(chan struct{}) + pty := ptytest.New(t) + cmd.SetIn(pty.Input()) + cmd.SetOut(pty.Output()) + go func() { + defer close(doneChan) + err := cmd.Execute() + require.NoError(t, err) + }() + pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces 200") + pty.ExpectMatch(workspace.Name) + pty.ExpectMatch("Running") + <-doneChan + }) +} diff --git a/cli/root.go b/cli/root.go index a0e0a389561ed..8bb6f24c9a288 100644 --- a/cli/root.go +++ b/cli/root.go @@ -35,6 +35,7 @@ const ( varGlobalConfig = "global-config" varNoOpen = "no-open" varForceTty = "force-tty" + varLogRequests = "log-requests" ) func init() { @@ -91,11 +92,14 @@ func Root() *cobra.Command { cmd.PersistentFlags().String(varURL, "", "Specify the URL to your deployment.") cmd.PersistentFlags().String(varToken, "", "Specify an authentication token.") + cliflag.String(cmd.PersistentFlags(), varGlobalConfig, "", "CODER_CONFIG_DIR", configdir.LocalConfig("coderv2"), "Specify the path to the global `coder` config directory.") + cmd.PersistentFlags().Bool(varLogRequests, false, "Log requests made to remote API endpoints.") + + // Hidden flags for internal use. cliflag.String(cmd.PersistentFlags(), varAgentToken, "", "CODER_AGENT_TOKEN", "", "Specify an agent authentication token.") _ = cmd.PersistentFlags().MarkHidden(varAgentToken) cliflag.String(cmd.PersistentFlags(), varAgentURL, "", "CODER_AGENT_URL", "", "Specify the URL for an agent to access your deployment.") _ = cmd.PersistentFlags().MarkHidden(varAgentURL) - cliflag.String(cmd.PersistentFlags(), varGlobalConfig, "", "CODER_CONFIG_DIR", configdir.LocalConfig("coderv2"), "Specify the path to the global `coder` config directory.") cmd.PersistentFlags().Bool(varForceTty, false, "Force the `coder` command to run as if connected to a TTY.") _ = cmd.PersistentFlags().MarkHidden(varForceTty) cmd.PersistentFlags().Bool(varNoOpen, false, "Block automatically opening URLs in the browser.") @@ -126,7 +130,17 @@ func createClient(cmd *cobra.Command) (*codersdk.Client, error) { return nil, err } } - client := codersdk.New(serverURL) + logRequests, err := cmd.Flags().GetBool(varLogRequests) + if err != nil { + return nil, err + } + + var client *codersdk.Client + if logRequests { + client = codersdk.NewWithRoundTripper(serverURL, newLoggingRoundTripper(cmd.OutOrStderr())) + } else { + client = codersdk.New(serverURL) + } client.SessionToken = token return client, nil } diff --git a/codersdk/client.go b/codersdk/client.go index 0367c912a5bbe..70d7ac255d4da 100644 --- a/codersdk/client.go +++ b/codersdk/client.go @@ -26,6 +26,16 @@ func New(serverURL *url.URL) *Client { } } +// NewWithRoundTripper behaves like New, but allows specifying a custom implementation of http.RoundTripper. +func NewWithRoundTripper(serverURL *url.URL, roundTripper http.RoundTripper) *Client { + return &Client{ + URL: serverURL, + HTTPClient: &http.Client{ + Transport: roundTripper, + }, + } +} + // Client is an HTTP caller for methods to the Coder API. // @typescript-ignore Client type Client struct { From bfa8e083a2f42d4a60edd2112a81b265e45c90bc Mon Sep 17 00:00:00 2001 From: David Wahler Date: Fri, 20 May 2022 00:19:05 +0000 Subject: [PATCH 2/3] add more thorough tests --- cli/requestlogging_test.go | 49 +++++++++++++++++++++++++++++++------- 1 file changed, 41 insertions(+), 8 deletions(-) diff --git a/cli/requestlogging_test.go b/cli/requestlogging_test.go index 23563d6a06333..d9d1027e79051 100644 --- a/cli/requestlogging_test.go +++ b/cli/requestlogging_test.go @@ -1,12 +1,14 @@ package cli_test import ( + "net/url" "testing" "github.com/stretchr/testify/require" "github.com/coder/coder/cli/clitest" "github.com/coder/coder/coderd/coderdtest" + "github.com/coder/coder/codersdk" "github.com/coder/coder/pty/ptytest" ) @@ -15,12 +17,7 @@ func TestRequestLogging(t *testing.T) { t.Run("List", func(t *testing.T) { t.Parallel() client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerD: true}) - user := coderdtest.CreateFirstUser(t, client) - version := coderdtest.CreateTemplateVersion(t, client, user.OrganizationID, nil) - coderdtest.AwaitTemplateVersionJob(t, client, version.ID) - template := coderdtest.CreateTemplate(t, client, user.OrganizationID, version.ID) - workspace := coderdtest.CreateWorkspace(t, client, user.OrganizationID, template.ID) - coderdtest.AwaitWorkspaceBuildJob(t, client, workspace.LatestBuild.ID) + _ = coderdtest.CreateFirstUser(t, client) cmd, root := clitest.New(t, "ls", "--log-requests") clitest.SetupConfig(t, client, root) doneChan := make(chan struct{}) @@ -33,8 +30,44 @@ func TestRequestLogging(t *testing.T) { require.NoError(t, err) }() pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces 200") - pty.ExpectMatch(workspace.Name) - pty.ExpectMatch("Running") + <-doneChan + }) + + t.Run("NoAuthentication", func(t *testing.T) { + t.Parallel() + client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerD: true}) + cmd, root := clitest.New(t, "ls", "--log-requests") + clitest.SetupConfig(t, client, root) + doneChan := make(chan struct{}) + pty := ptytest.New(t) + cmd.SetIn(pty.Input()) + cmd.SetOut(pty.Output()) + go func() { + defer close(doneChan) + err := cmd.Execute() + require.Error(t, err) + }() + pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces 401") + <-doneChan + }) + + t.Run("InvalidUrl", func(t *testing.T) { + t.Parallel() + parsedURL, err := url.Parse("invalidprotocol://foobar") + require.NoError(t, err) + client := codersdk.New(parsedURL) + cmd, root := clitest.New(t, "ls", "--log-requests") + clitest.SetupConfig(t, client, root) + doneChan := make(chan struct{}) + pty := ptytest.New(t) + cmd.SetIn(pty.Input()) + cmd.SetOut(pty.Output()) + go func() { + defer close(doneChan) + err := cmd.Execute() + require.Error(t, err) + }() + pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces (err)") <-doneChan }) } From d90442de101e25f56b6bfccaef2b93056c033f48 Mon Sep 17 00:00:00 2001 From: David Wahler Date: Fri, 20 May 2022 19:11:08 +0000 Subject: [PATCH 3/3] change flag to --verbose, log request/response bodies --- cli/requestlogging.go | 86 +++++++++++++++++++++++++++++++++++--- cli/requestlogging_test.go | 12 +++--- cli/root.go | 15 ++++--- 3 files changed, 96 insertions(+), 17 deletions(-) diff --git a/cli/requestlogging.go b/cli/requestlogging.go index 76a811c837489..863b782ce36ce 100644 --- a/cli/requestlogging.go +++ b/cli/requestlogging.go @@ -1,21 +1,20 @@ package cli import ( + "bytes" "fmt" "io" "net/http" "strconv" + "strings" ) type loggingRoundTripper struct { http.RoundTripper io.Writer -} -func newLoggingRoundTripper(writer io.Writer) http.RoundTripper { - return &loggingRoundTripper{ - Writer: writer, - } + logRequestBodies bool + logResponseBodies bool } func (lrt loggingRoundTripper) RoundTrip(request *http.Request) (*http.Response, error) { @@ -24,6 +23,14 @@ func (lrt loggingRoundTripper) RoundTrip(request *http.Request) (*http.Response, inner = http.DefaultTransport } + var requestBody bytes.Buffer + if lrt.logRequestBodies { + teeReader := io.TeeReader(request.Body, &requestBody) + wrappedBody := &readCloser{teeReader, request.Body} + request = request.Clone(request.Context()) + request.Body = wrappedBody + } + response, err := inner.RoundTrip(request) var displayedStatusCode string @@ -32,7 +39,74 @@ func (lrt loggingRoundTripper) RoundTrip(request *http.Request) (*http.Response, } else { displayedStatusCode = strconv.Itoa(response.StatusCode) } + _, _ = fmt.Fprintf(lrt.Writer, "sending request: %s %s status: %s\n", request.Method, request.URL.String(), displayedStatusCode) + + if lrt.logRequestBodies { + printRequestBodyLog(lrt.Writer, request, &requestBody) + } + + if lrt.logResponseBodies { + response = wrapResponse(lrt.Writer, response) + } - _, _ = fmt.Fprintf(lrt.Writer, "%s %s %s\n", request.Method, request.URL.String(), displayedStatusCode) return response, err } + +type readCloser struct { + io.Reader + io.Closer +} + +func formatBody(contentType string, body *bytes.Buffer) string { + bareType, _, _ := strings.Cut(contentType, ";") + if bareType == "application/json" || strings.HasPrefix(bareType, "text/") { + return fmt.Sprintf("%s: %s", contentType, body.Bytes()) + } + return fmt.Sprintf("%s, %d bytes", contentType, body.Len()) +} + +func printRequestBodyLog(writer io.Writer, request *http.Request, body *bytes.Buffer) { + // omit bodies that are empty and expected to be empty + if body.Len() == 0 && emptyRequestExpected(request.Method) { + return + } + + message := formatBody(request.Header.Get("Content-Type"), body) + _, _ = fmt.Fprintf(writer, "\trequest body: %s\n", message) +} + +func emptyRequestExpected(method string) bool { + return !(method == "POST" || method == "PUT" || method == "PATCH") +} + +type responseBodyLogger struct { + writer io.Writer + + body io.ReadCloser + bodyContent bytes.Buffer + contentType string +} + +func wrapResponse(writer io.Writer, response *http.Response) *http.Response { + newResponse := new(http.Response) + *newResponse = *response + + logger := responseBodyLogger{ + writer: writer, + contentType: response.Header.Get("Content-Type"), + } + logger.body = &readCloser{io.TeeReader(response.Body, &logger.bodyContent), response.Body} + newResponse.Body = &logger + + return newResponse +} + +func (logger *responseBodyLogger) Read(p []byte) (int, error) { + return logger.body.Read(p) +} + +func (logger *responseBodyLogger) Close() error { + message := formatBody(logger.contentType, &logger.bodyContent) + _, _ = fmt.Fprintf(logger.writer, "\tresponse body: %s\n", message) + return logger.body.Close() +} diff --git a/cli/requestlogging_test.go b/cli/requestlogging_test.go index d9d1027e79051..cf550e6a3c286 100644 --- a/cli/requestlogging_test.go +++ b/cli/requestlogging_test.go @@ -18,7 +18,7 @@ func TestRequestLogging(t *testing.T) { t.Parallel() client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerD: true}) _ = coderdtest.CreateFirstUser(t, client) - cmd, root := clitest.New(t, "ls", "--log-requests") + cmd, root := clitest.New(t, "ls", "--verbose") clitest.SetupConfig(t, client, root) doneChan := make(chan struct{}) pty := ptytest.New(t) @@ -29,14 +29,14 @@ func TestRequestLogging(t *testing.T) { err := cmd.Execute() require.NoError(t, err) }() - pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces 200") + pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces status: 200") <-doneChan }) t.Run("NoAuthentication", func(t *testing.T) { t.Parallel() client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerD: true}) - cmd, root := clitest.New(t, "ls", "--log-requests") + cmd, root := clitest.New(t, "ls", "--verbose") clitest.SetupConfig(t, client, root) doneChan := make(chan struct{}) pty := ptytest.New(t) @@ -47,7 +47,7 @@ func TestRequestLogging(t *testing.T) { err := cmd.Execute() require.Error(t, err) }() - pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces 401") + pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces status: 401") <-doneChan }) @@ -56,7 +56,7 @@ func TestRequestLogging(t *testing.T) { parsedURL, err := url.Parse("invalidprotocol://foobar") require.NoError(t, err) client := codersdk.New(parsedURL) - cmd, root := clitest.New(t, "ls", "--log-requests") + cmd, root := clitest.New(t, "ls", "--verbose") clitest.SetupConfig(t, client, root) doneChan := make(chan struct{}) pty := ptytest.New(t) @@ -67,7 +67,7 @@ func TestRequestLogging(t *testing.T) { err := cmd.Execute() require.Error(t, err) }() - pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces (err)") + pty.ExpectMatch("GET " + client.URL.String() + "/api/v2/workspaces status: (err)") <-doneChan }) } diff --git a/cli/root.go b/cli/root.go index 8bb6f24c9a288..0da35bee9dcde 100644 --- a/cli/root.go +++ b/cli/root.go @@ -35,7 +35,7 @@ const ( varGlobalConfig = "global-config" varNoOpen = "no-open" varForceTty = "force-tty" - varLogRequests = "log-requests" + varVerbose = "verbose" ) func init() { @@ -93,7 +93,7 @@ func Root() *cobra.Command { cmd.PersistentFlags().String(varURL, "", "Specify the URL to your deployment.") cmd.PersistentFlags().String(varToken, "", "Specify an authentication token.") cliflag.String(cmd.PersistentFlags(), varGlobalConfig, "", "CODER_CONFIG_DIR", configdir.LocalConfig("coderv2"), "Specify the path to the global `coder` config directory.") - cmd.PersistentFlags().Bool(varLogRequests, false, "Log requests made to remote API endpoints.") + cmd.PersistentFlags().CountP("verbose", "v", "Print more verbose output. Can be specified multiple times.") // Hidden flags for internal use. cliflag.String(cmd.PersistentFlags(), varAgentToken, "", "CODER_AGENT_TOKEN", "", "Specify an agent authentication token.") @@ -130,14 +130,19 @@ func createClient(cmd *cobra.Command) (*codersdk.Client, error) { return nil, err } } - logRequests, err := cmd.Flags().GetBool(varLogRequests) + + verbosityLevel, err := cmd.Flags().GetCount(varVerbose) if err != nil { return nil, err } var client *codersdk.Client - if logRequests { - client = codersdk.NewWithRoundTripper(serverURL, newLoggingRoundTripper(cmd.OutOrStderr())) + if verbosityLevel >= 1 { + client = codersdk.NewWithRoundTripper(serverURL, &loggingRoundTripper{ + Writer: cmd.OutOrStderr(), + logRequestBodies: verbosityLevel >= 2, + logResponseBodies: verbosityLevel >= 3, + }) } else { client = codersdk.New(serverURL) }