Add logging and recording of requests #170

tateexon · 2024-06-14T21:38:49Z

Added two new command line arguments:

-l for logging level, defaults to 0, 1 adds requests, 2 adds the request body
-d to dump requests into a the specified file

This is needed for cases when a test needs access to what is posted as a request to the mock but we don't know the exact data, like a hash that was posted but need that hash later on in the test to post to another service. We don't need the responses dumped because the test should have access to the imposters they are using and thus already have access to that data.

I think this also covers what was originally wanted in #100 but maybe not exactly how it was imagined there.

I added a few changes to the Makefile and Dockerfile to make local testing a bit easier.

I made the request writer use a channel and run in a go function so it wouldn't run into issues of multiple concurrent requests trying to write into the dump file at once.

I fully realize this could cause the dump file to get very very large if this is used incorrectly in something like a load test but I am not sure how to handle that better outside of doing some kind of rotating log. I would hope people wouldn't use it for a case like that but I don't know what all the kinds of users of the tool are. I welcome all suggestions.

tateexon · 2024-06-14T21:53:54Z

@joanlopez I would like your thoughts on this please!

Note: This requires approval of: friendsofgo/killgrave#170 which may still need changes.

iljapavlovs · 2024-06-19T16:00:48Z

upvote for this feature, really missing this essential feature! @joanlopez

tateexon · 2024-06-19T19:22:49Z

@aperezg @joanlopez is there anything else I need to do before this can get reviewed?

joanlopez · 2024-06-20T06:08:15Z

@aperezg @joanlopez is there anything else I need to do before this can get reviewed?

It's fine for now, @tateexon - just trying to book some time to review it carefully! Thanks! 🙇🏻

tateexon · 2024-06-20T12:56:13Z

Sounds good. I will continue with my fork for now to unblock my QA team.

Note: This requires approval of: friendsofgo/killgrave#170 which may still need changes.

internal/app/cmd/cmd.go

internal/config.go

internal/server/http/dump.go

internal/server/http/server.go

internal/server/http/dump.go

- Handle cases where the dumpCh is full - Use bytes.NewReader

Base64 encode the body and attach it to the log that is output if there is a body

…type.

…1 adds requests, 2 adds request body

tateexon · 2024-06-28T14:47:56Z

I think I have hit all the review comments so far. Anything else @asad-urrahman ? Thanks for the reviews so far!

asad-urrahman

All Good

bigmeech · 2024-07-21T14:44:24Z

when is this getting merged in?

.gitignore

internal/app/cmd/cmd.go

internal/server/http/server.go

joanlopez · 2024-07-22T15:31:00Z

internal/server/http/dump.go

+}
+
+// copied from gorilla/handlers and modified to add the body
+// writeLog writes a log entry for req to w in Apache Common Log Format.


Not quite sure we want to use Apache Common Log Format, or perhaps something simpler. Or eventually something plugable/selectable, leaving the choice to the user.

If we do not want to use the apache common log format we can get rid of a lot of this and build our own custom handler. Was just doing what Asad wanted in his reviews. I am not tied to the format nor do I care as long as it is readable. If you have a preference for a default format please let me know and I will go with that so long as it will support the ability for a body to be present when wanted.

ripped out for now.

joanlopez · 2024-07-22T15:34:43Z

internal/server/http/dump.go

+	r.Body = io.NopCloser(bytes.NewReader(bodyBytes)) // Reset the body
+	body := string(bodyBytes)
+	// if content is binary, encode it to base64
+	if isBinaryContent(r) {


As you already have the body in bytes, I'd suggest to follow the opposite approach, only use something else other than Base64 if possible (like valid JSON contents), but defaulting to Base64, which is safer.

Reversed in: 6459695

joanlopez · 2024-07-22T15:36:06Z

internal/server/http/dump.go

+	if s.logLevel == 0 && !shouldRecordRequest(s) {
+		return ""
+	}
+	bodyBytes, err := io.ReadAll(r.Body)


I'd love to see some limits here. Does it really make sense to write the body over and over, especially if large? 🤔 What's the purpose?

It makes sense when you want the body logged out for tests to grab and use. This is provided in other mocking solutions in some way.

This is kind of the whole reason for the PR, I need the body for tests and yes it could be large and yes I will still want it.

We can definitely put a limit if needed. It would need to be configurable for when I want a very large body. What would you say a good limit would be?

Added a io.LimitedReader to read up to a configurable maximum bytes now: 78a8ae0

joanlopez · 2024-07-22T15:43:33Z

internal/server/http/dump.go

+		// Handle the case where the channel is full
+		log.Println("Channel is full, dropping request and logging it instead:")
+		return fmt.Errorf("request dump channel is full")


Why do you need to do so?
Couldn't you just record the request asynchronously?

It is getting recorded asynchronously but if that asynchronous channel is full we need to handle it.

Cleaned this up so it just logs an error if the channel is full

joanlopez · 2024-07-22T15:44:19Z

internal/server/http/dump.go

+}
+
+// Goroutine function to write requests to a JSON file
+func RequestWriter(filePath string, requestChan <-chan *RequestData) {


Looks like this function lacks proper control of its lifecycle, graceful shutdown, etc. Same for the channel, etc; please review.

Will look into adding a context to pass in and potentially move the for loop and file open outside of this function since that is the only way I think I can properly add that control but the server will need to pass the context along. I think I can do this.

Reworked this to have a context and a wait group to handle graceful shutdown.

joanlopez · 2024-07-22T15:46:04Z

internal/server/http/dump.go

+func RequestWriter(filePath string, requestChan <-chan *RequestData) {
+	file, err := os.OpenFile(filePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
+	if err != nil {
+		log.Fatalf("Failed to open file: %+v", err)


I'd love to see handling of this to happen before, in an outer surface.

This has been moved. We now use an io.Writer instead so the file open and defer are handled at higher layers.

joanlopez · 2024-07-22T15:47:04Z

internal/server/http/dump.go

+}
+
+// GetRecordedRequests reads the requests from the file and returns them as a slice of RequestData
+func getRecordedRequests(filePath string) ([]RequestData, error) {


If you adequately abstract the destination of the logs through io.Writer, you won't need to use real files for testing, which isn't.. ideal.

I think what you are saying makes sense, this function should have been in the test file anyways and not here since it is only being used in the tests.

joanlopez · 2024-07-22T15:49:43Z

internal/server/http/server.go

 }

 // NewServer initialize the mock server
-func NewServer(r *mux.Router, httpServer *http.Server, proxyServer *Proxy, secure bool, fs ImposterFs) Server {
+func NewServer(r *mux.Router, httpServer *http.Server, proxyServer *Proxy, secure bool, fs ImposterFs, CORSOptions []handlers.CORSOption, logLevel int, dumpRequestsPath string) Server {


If we're going to keep adding more and more options (three this time), I'd love to see options as functional arguments, in a separate package. Especially for those that aren't required, the rest can be kept as regular args.

Added a separate serverconfig package to handle extra args.

joanlopez · 2024-07-22T15:50:09Z

internal/server/http/server_test.go

@@ -67,7 +70,7 @@ func TestBuildProxyMode(t *testing.T) {
 		imposterFs, err := NewImposterFS("test/testdata/imposters")
 		require.NoError(t, err)

-		server := NewServer(router, httpServer, proxyServer, false, imposterFs)
+		server := NewServer(router, httpServer, proxyServer, false, imposterFs, nil, 0, "")


Smell that points to https://github.com/friendsofgo/killgrave/pull/170/files#r1686772983

Now handled with a serverconfig

joanlopez

Hi @tateexon,

I finally managed to do an initial review, and the TL;DR of my feedback is that this pull request is not only too large, but also mixes things that aren't strictly needed together/dependent among them.

So, before addressing the detailed comments, I'd suggest you to split this into multiple, independent PRs, including the smaller refactors, other improvements (like the uncaught error), and even the two flags added here (separate each, please).

Beyond making it much easier to review, and in the future to track changes, I think that some of the minor changes could be merged straight away (as-is), and we would really appreciate such contributions, while in parallel we can discuss the details around logging, and consider if we really want to add support for dumping requests at all (which I have my doubts, to be honest).

Meanwhile, I'll ping @aperezg, cause while I'd be happy and comfortable with merging your smaller changes, I'd love to get their approval as well for the larger changes.

Thanks! 🙇🏻

joanlopez · 2024-07-22T16:02:49Z

when is this getting merged in?

TBH, I'd love to see this merged sooner rather than later. However, the set of changes here is very large, and some are trickier to review, discuss and approve than others. That's why I just suggested @tateexon to split this into smaller PRs.

From your side @bigmeech, is there anything you're more interested about? Logging? Dumping? The minor fixes?

Thanks!

Use server config package in cmd, NewServer, and tests Move gorilla handlers logging copy paste to its own package Add gorilla license to the license file

…riter

Convert channel to *[]byte to make handling future log formats easier

add configuration for this

…m the body

tateexon · 2024-07-24T16:22:22Z

@joanlopez Thank you very much for the review!

I broke out a PR for the makefile and dockerfile changes.

I think I have hit most of your review comments and that brought a lot of change. I would like another review before I go in and add more tests just in case it needs a lot more change.

Some of the things that have changed:

the copied gorilla code is gone
we just output in json format now and we can add an option later to output in other formats as needed
used a context and wait group to cleanly handle shutdown for the request writer go routine
the request writer now uses an io.Writer instead of a file so the file handling and deferred close can be handled at higher layers where they make sense
reversed the order for when we base 64 encode
added a serverconfig package to functionally configure and add more options in the future using a With* syntax

bigmeech · 2024-07-27T05:10:33Z

when is this getting merged in?

TBH, I'd love to see this merged sooner rather than later. However, the set of changes here is very large, and some are trickier to review, discuss and approve than others. That's why I just suggested @tateexon to split this into smaller PRs.

From your side @bigmeech, is there anything you're more interested about? Logging? Dumping? The minor fixes?

Thanks!

Hi @joanlopez

Thanks for the work you have done in the PR. To answer your question actually there are a few stuffs I'd be interested in but I think the most important for me personally is responding to the client with a 400 bad request when the schema validation fails instead of only reporting the failed validation on the server logs. (at least this is what happens in the version i am using). Not sure how big of a change that would be.

Thanks.

tateexon added 3 commits June 14, 2024 15:21

Add logging of requests to file and/or to stdout

c46de61

Merge remote-tracking branch 'origin/main' into add_verbose_request_dump

2b9f1e1

merge conflict fixes

e8dff5f

tateexon changed the title ~~Add logging and reording of requests~~ Add logging and recording of requests Jun 14, 2024

tateexon added a commit to smartcontractkit/chainlink-testing-framework that referenced this pull request Jun 14, 2024

[TT-1275] Add retreiving of requests from killgrave

c1269aa

Note: This requires approval of: friendsofgo/killgrave#170 which may still need changes.

tateexon mentioned this pull request Jun 14, 2024

[TT-1275] Add retreiving of requests from killgrave smartcontractkit/chainlink-testing-framework#994

Merged

tateexon added a commit to smartcontractkit/chainlink-testing-framework that referenced this pull request Jun 20, 2024

[TT-1275] Add retreiving of requests from killgrave

ee50fe5

Note: This requires approval of: friendsofgo/killgrave#170 which may still need changes.

tateexon added a commit to smartcontractkit/chainlink-testing-framework that referenced this pull request Jun 20, 2024

[TT-1275] Add retreiving of requests from killgrave (#994)

44dea25

Note: This requires approval of: friendsofgo/killgrave#170 which may still need changes.

asad-urrahman reviewed Jun 21, 2024

View reviewed changes

tateexon added 5 commits June 22, 2024 09:47

Handle error in config for io.ReadAll

3c18bdc

- Sync file wrties in the RequestWriter

72b3f4e

- Handle cases where the dumpCh is full - Use bytes.NewReader

Wrap request gorilla/handlers#CustomLoggingHandler to log requests

acaa33c

Base64 encode the body and attach it to the log that is output if there is a body

clean up docker build warning

cd93b1f

use -v and update readme for version

b7bafe8

tateexon requested a review from asad-urrahman June 24, 2024 22:35

tateexon added 3 commits June 25, 2024 07:44

Only set the body as binary when the Content-Type Header is a binary …

ac2569a

…type.

Make binaryContentTypes global so it isn't building it every time.

8c2e34c

replace -v --verbose with -l --log-level with 3 settings, 0 default, …

fcc3cb7

…1 adds requests, 2 adds request body

asad-urrahman reviewed Jul 1, 2024

View reviewed changes

joanlopez self-assigned this Jul 22, 2024