feat: make RequestLoggingMiddleware non-experimental and call toString on MiddlewareMessages #1268

anitarua · 2024-05-08T00:12:28Z

Addresses https://github.com/momentohq/dev-eco-issue-tracker/issues/811

Adds a toString method to MiddlewareMessage that prints extra details for CacheClient and LeaderboardClient requests (as those are the only two with middlewares enabled for now).

Affects only the NodeJS SDK, similar changes can be made in web sdk as desired.

Snippet of what the logs look like now:

[2024-05-08T00:24:36.541Z] DEBUG (Momento: RequestLoggingMiddleware): Logging middleware: request 43 onRequestMetadata: {"cache":["js-sdk-doc-examples-cache-77092f86e4002a9e"]}
[2024-05-08T00:24:36.541Z] DEBUG (Momento: RequestLoggingMiddleware): Logging middleware: request 43 onRequestBody: request type: _DictionarySetRequest, request size: 55, details: DictionarySetRequest with dictionary name "test-dictionary" and ttl 60000 ms and refresh ttl true and fields (field "key1" | value "value1"), (field "key2" | value "value2"), 
[2024-05-08T00:24:36.592Z] DEBUG (Momento: RequestLoggingMiddleware): Logging middleware: request 43 onResponseMetadata: {"content-type":["application/grpc"],"access-control-allow-credentials":["true"],"vary":["origin, access-control-request-method, access-control-request-headers"],"access-control-expose-headers":["grpc-status,grpc-message,grpc-encoding,grpc-accept-encoding"],"date":["Wed, 08 May 2024 00:24:35 GMT"]}
[2024-05-08T00:24:36.592Z] DEBUG (Momento: RequestLoggingMiddleware): Logging middleware: request 43 onResponseBody: response type: _DictionarySetResponse, response size: 0
[2024-05-08T00:24:36.592Z] DEBUG (Momento: RequestLoggingMiddleware): Logging middleware: request 43 onResponseStatus: status code: 0

I've also got a full output file of log statements from running the doc example snippets file with this middleware enabled, just let me know if you want it!

anitarua · 2024-05-08T00:29:31Z

packages/client-sdk-nodejs/src/config/middleware/request-logging-middleware.ts

      this.requestId,
      // eslint-disable-next-line @typescript-eslint/no-unsafe-member-access
-      request.constructor.name,


this used to just print MiddlewareMessage rather than the request type

I think there are probably a few other places in the middleware where calling constructorName() will be more useful but haven't tracked them all down yet

anitarua · 2024-05-08T00:31:43Z

packages/client-sdk-nodejs/src/config/middleware/middleware.ts

+    return this._grpcMessage.constructor.name;
+  }
+
+  // Note: APIs that use streaming interceptors (e.g. GetBatch and SetBatch)


there were no middleware messages shown for GetBatch or SetBatch when I tested locally

pgautier404 · 2024-05-08T20:02:34Z

packages/client-sdk-nodejs/src/config/middleware/middleware.ts

+        const request = this._grpcMessage as cache.cache_client._SetRequest;
+        return `SetRequest with key "${TEXT_DECODER.decode(
+          request.cache_key
+        )}" and value "${TEXT_DECODER.decode(request.cache_body)}" and ttl ${


request.cache_body could contain megabytes of data. We used a truncateString() utility method in the response classes to limit the amount of output from toString(). I'm guessing in a situation where someone is using a middleware logger they're going to want to see absolutely everything, but I thought it might be worth discussion.

that's a good callout. I think for now let's just leave it the way Anita has it (logging the whole item) and see if we get feedback.

pgautier404 · 2024-05-08T20:27:04Z

packages/client-sdk-nodejs/src/config/middleware/middleware.ts

+          request.cache_key
+        )}" and value "${TEXT_DECODER.decode(
+          request.cache_body
+        )}" and condition "${request.condition}"`;


This is missing the ttl_milliseconds. I think it might also be worthwhile to log the condition value here for requests that require one like present_and_not_equal.

confirmed conditions are logged as strings

[2024-05-13T19:26:52.702Z] DEBUG (Momento: RequestLoggingMiddleware): Logging middleware: request 14 onRequestBody: request type: _SetIfRequest, request size: 44, details: {"key":"test-key","value":"test-field","condition":"present_and_not_equal","ttl_milliseconds":60000}

cprice404 · 2024-05-08T20:25:03Z

packages/client-sdk-nodejs/src/config/middleware/middleware.ts

+        const request = this._grpcMessage as cache.cache_client._SetRequest;
+        return `SetRequest with key "${TEXT_DECODER.decode(
+          request.cache_key
+        )}" and value "${TEXT_DECODER.decode(request.cache_body)}" and ttl ${


that's a good callout. I think for now let's just leave it the way Anita has it (logging the whole item) and see if we get feedback.

cprice404 · 2024-05-08T20:32:21Z

packages/client-sdk-nodejs/src/config/middleware/middleware.ts

+
+  // Note: APIs that use streaming interceptors (e.g. GetBatch and SetBatch)
+  // will not see these debug messages
+  toString(): string {


thank you so much for doing all of this! i have a few suggestions, i apologize for not discussing this with you in more depth before you started on the ticket. If any of these seem too onerous, they are not urgent, and I can add a commit and some point to help out with the tedious parts. :)

For detailed logs like this it's really valuable to structure the log output as JSON or some other format that is easy to parse programmatically. So, I know it's going to be repetitive, but I'd probably define an interface for each one, like GetRequestLogFormat, and then the implementation should create an instance of the interface and then call JSON.stringify on it.

JSON.stringify might fail on binary data so we should test that briefly before doing all of the rest of the work, and if it does, decide what we want to do about it. I have a few ideas we can discuss if it happens.

We will need a big switch statement no matter what, but I think it would be best if each case in the switch just called a single function to do the conversion for the given request/response type, so that we have a separate function that does the actual work for each conversion.

It would be really awesome to have a unit test that would assert that we have defined the necessary conversion functions for all of the possible types. kinda like what we are doing here:

client-sdk-javascript/packages/core/test/unit/clients/imomentocache-interface.test.ts

Lines 15 to 19 in 0831824

const cacheInterfaceMembers = cacheInterface

.getMethods()

.map(m => m.getName())

.sort();

console.log(`Cache interface members: ${cacheInterfaceMembers.join(',')}`);

. That way if a new release of the protos adds a new request/response type, we will get a compile-time reminder to add support for it.

I know the list above is a lot of tedious changes so feel free to approach it incrementally in between other tasks, or ask for volunteers to help with some subset of the types, etc. (I am very willing to contribute!)

Thanks for the feedback! And my bad for not checking in before diving in first haha 😅

Sounds like a good plan for revisions. It looks like JSON.stringify would treat binary data like a list:

const binaryData = Uint8Array.of(108, 111, 108); console.log(JSON.stringify({ data: binaryData })); // prints '{"data":{"0":108,"1":111,"2":108}}'

But I think we'll be able to get around this using the TextDecoder when creating an instance of each *RequestLogFormat interface:

console.log(JSON.stringify({ data: TEXT_DECODER.decode(binaryData) })); // prints '{"data":"lol"}'

sounds good. TEXT_DECODER.decode might throw an error if the bytes aren't utf-8 though, so we might have to figure out what we want to do for those cases.

and no worries re: checking in, I should have put a note in the ticket description.

packages/client-sdk-nodejs/src/config/middleware/middleware.ts

anitarua · 2024-05-13T19:34:29Z

Current state of the PR:

I've made a first pass at creating logging format interfaces and conversion functions for each request type.
- Note: there were a few overlapping ones (e.g. Get, Delete, etc) so I made a common one for those, but if completely separate is preferred, that's fine too.
The switch statement calls JSON.stringify(<conversion function>) for each request type.
Does not yet handle the case of: "TEXT_DECODER.decode might throw an error if the bytes aren't utf-8 though"
Does not yet include a unit test to assert that all desired conversion functions are present

anitarua · 2024-05-13T19:36:29Z

Example output file from running docs examples snippets locally:
output.txt

…g on MiddlewareMessages

cprice404 · 2024-05-16T22:34:21Z

rebased, now will pick up from where anita left off.

cprice404 · 2024-05-17T21:52:16Z

I think I'm done with this for now. It's not perfect and probably warrants some discussion on Monday but I think it's probably a reasonable direction.

anitarua · 2024-05-20T19:08:35Z

packages/client-sdk-nodejs/src/config/middleware/middleware.ts

+  // Note: APIs that use streaming interceptors (e.g. GetBatch and SetBatch)
+  // will not see these debug messages
+  toLogFormat(): RequestLog {
+    const requestToLogConverter = CacheRequestToLogInterfaceConverter.get(


ooh much nicer than the giant switch statement

anitarua · 2024-05-20T19:10:03Z

packages/client-sdk-nodejs/test/unit/config/middleware/cache-request-logging.test.ts

+  });
+
+  describe('supported cache request types', () => {
+    it('should have a converter for all known cache request types', () => {


bruuuuuuuce · 2024-06-05T16:52:55Z

Spent some time playing around with this pr this morning, I think it looks good. I really like that last test that was added to ensure we have logging for all request types. I wonder if it would be good in our canaries/integration tests to enable this middleware so we have it being tested across all of our apis in an environment on a regular cadence.

One nit that I saw was the jsdoc for the class

RequestLoggingMiddleware

Still has comments about how it is experimental.

This middleware implements per-request logging which can be used for
debugging.  The log format is currently considered experimental; in a
future release, once the log format is considered stable, this class will
be renamed to remove the Experimental prefix.

Once we remove this text blurb I am on this pr

anitarua · 2024-06-05T18:18:07Z

@bruuuuuuuce I removed that part in cdf6b28

bruuuuuuuce

anitarua commented May 8, 2024

View reviewed changes

anitarua marked this pull request as ready for review May 8, 2024 00:32

anitarua requested review from cprice404 and a team May 8, 2024 00:32

pgautier404 reviewed May 8, 2024

View reviewed changes

cprice404 reviewed May 8, 2024

View reviewed changes

pgautier404 reviewed May 8, 2024

View reviewed changes

packages/client-sdk-nodejs/src/config/middleware/middleware.ts Outdated Show resolved Hide resolved

pgautier404 reviewed May 8, 2024

View reviewed changes

packages/client-sdk-nodejs/src/config/middleware/middleware.ts Outdated Show resolved Hide resolved

pgautier404 reviewed May 8, 2024

View reviewed changes

packages/client-sdk-nodejs/src/config/middleware/middleware.ts Outdated Show resolved Hide resolved

pgautier404 reviewed May 8, 2024

View reviewed changes

packages/client-sdk-nodejs/src/config/middleware/middleware.ts Outdated Show resolved Hide resolved

feat: make RequestLoggingMiddleware non-experimental and call toStrin…

f3b94ee

…g on MiddlewareMessages

cprice404 force-pushed the logging-middleware branch from 13050d3 to 3ff5131 Compare May 16, 2024 22:33

chore: finish implementing request log converters

8500cfc

cprice404 force-pushed the logging-middleware branch from 25ced9e to 8500cfc Compare May 17, 2024 21:50

cprice404 requested review from malandis, bruuuuuuuce and a team May 17, 2024 21:51

anitarua commented May 20, 2024

View reviewed changes

remove experimental note from jsdocs

cdf6b28

bruuuuuuuce approved these changes Jun 5, 2024

View reviewed changes

cprice404 merged commit 139602f into main Jun 7, 2024
13 checks passed

cprice404 deleted the logging-middleware branch June 7, 2024 23:00

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: make RequestLoggingMiddleware non-experimental and call toString on MiddlewareMessages #1268

feat: make RequestLoggingMiddleware non-experimental and call toString on MiddlewareMessages #1268

anitarua commented May 8, 2024 •

edited

Loading

anitarua May 8, 2024

anitarua May 13, 2024

anitarua May 8, 2024

pgautier404 May 8, 2024

cprice404 May 8, 2024

pgautier404 May 8, 2024

anitarua May 13, 2024

cprice404 May 8, 2024

cprice404 May 8, 2024

anitarua May 8, 2024

cprice404 May 8, 2024

cprice404 May 8, 2024

anitarua commented May 13, 2024

anitarua commented May 13, 2024

cprice404 commented May 16, 2024

cprice404 commented May 17, 2024

anitarua May 20, 2024

anitarua May 20, 2024

bruuuuuuuce commented Jun 5, 2024

anitarua commented Jun 5, 2024

bruuuuuuuce left a comment

	const cacheInterfaceMembers = cacheInterface
	.getMethods()
	.map(m => m.getName())
	.sort();
	console.log(`Cache interface members: ${cacheInterfaceMembers.join(',')}`);

feat: make RequestLoggingMiddleware non-experimental and call toString on MiddlewareMessages #1268

feat: make RequestLoggingMiddleware non-experimental and call toString on MiddlewareMessages #1268

Conversation

anitarua commented May 8, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

anitarua commented May 13, 2024

anitarua commented May 13, 2024

cprice404 commented May 16, 2024

cprice404 commented May 17, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bruuuuuuuce commented Jun 5, 2024

anitarua commented Jun 5, 2024

bruuuuuuuce left a comment

Choose a reason for hiding this comment

anitarua commented May 8, 2024 •

edited

Loading