Server hook returns malformed response when content type is Protobuf
Closed this issue · 11 comments
Hey,
Thank you for the quick responses to our previous issues, much appreciated!
I've been trying to print out the server response onto the console using the responseSenthook, and it neatly prints out the response when the content type requested is JSON:
INFO: response sent back to Haberdasher using method MakeHatBrown with content type JSON, response code: 200, response body: {"inches":12,"color":"brown","name":"cowboy"}
However, when calling the same method with requested content type being Protobuf, it prints the following:
INFO: response sent back to Haberdasher using method MakeHatBrown with content type Protobuf, response code: 200, response body: browncowboy
In either case, the response printed out when calling the client is { inches: 12, color: 'brown', name: 'cowboy' }
Or am I wrong and this is the intended behaviour? I'm just wondering how useful this format is especially when responses are large and they become very hard to read when printed
This is the server hook part of the code:
app.on("responseSent", (context, response) => {
console.log(`INFO: response sent back to ${context.service} using method ${context.method} with content type ${context.contentType},
response code: ${response.statusCode}, response body: ${response.body}`)
});
The version of twirpscript I'm using is v0.0.33 (latest tag)
node v16.13.1
yarn v1.22.11
Hey @PatriciaHudakova this is because the response body is encoded. When the encoding format is JSON, it is still readable because JSON is a human readable encoding. protobuf is not a human readable encoding, which is why console.log ing the encoded body isn’t very helpful.
This is one of the main motivations for Twirp having a JSON format — it’s easier to debug with simple tools than protobuf.
If you wanted a JSON like representation when console.log ing you would need to deserialize the protobuf.
ah that makes sense 😅 thank you!
No problem! What’s your use case @PatriciaHudakova? Are you debugging, exploring or trying to improve the general DX during development?
I recently added request logging (which can be disabled via the debug config property) and thought about including responses, but was concerned about console spam for large responses — the current logging is bounded, but responses could be arbitrarily large. I used Rails as the logging inspiration.
Heya, a little bit of exploring and a little bit of trying to improve the DX, was just trying to see to what extent the hooks would be useful when you have multiple response types being returned for different RPC-based calls in protobuf. Since the hooks are on the server level, the hooks themselves wouldn't be able to "know" what object to deserialise the protobuf into, so I would have to deserialise this into JSON and log it within the handling function I assume.
Ah I see your point about the logging, yes if the responses are super large than it would spam the console, but I also think logging responses can be very valuable and if you're able to disable it when the length starts becoming an issue, then I think it would be good 👀 Or perhaps being able to disable the request and response logging separately, that way you could have the requests but not responses? Or is the effort required for this not worth the outcome?
I've made the service and method properties now point to generated objects instead of simply being strings (eg previously these were "Haberdasher" and "MakeHat" and now these properties point to generated objects.
This means you can do something like the following:
app.on('requestRouted', (ctx, req) => {
console.log(`Received request body: ${ctx.contentType === 'Protobuf' ? ctx.method.input.decode(req.body) : req.body`);
});
app.on('requestPrepared', (ctx, res) => {
console.log(`Sent: ${ctx.contentType === 'Protobuf' ? ctx.method.output.decode(res.body) : res.body`);
});
I think the overall utility of requestRouted and requestPrepared could be improved, and I'm thinking about changing the second callback argument from the request/response to be the deserialized input / deserialized output from the handler.
I'll publish an update with the above once I've fleshed out the API.
ah that's super awesome, thanks for this!
This has been published in v0.0.34
hey @tatethurston, thank you for this, I was able to upgrade to v0.0.34 and regenerate the files, I've copied the hook example given in the v0.0.34 notes and I get a compile error Property 'body' does not exist on type 'IncomingMessage'.ts(2339) when calling req.body 👀 could I be missing something?
It's the same for requestRouted and responsePrepared where the body doesn't exist on type Size and Hat
Hey @PatriciaHudakova requestRouted is now called with the input to your handler and responsePrepared is now called with the output. These are the request.body and response.body respectively, so there isn't any deserialization required.
Thanks for letting me know about requestRecieved -- I've updated the typescript types in v0.0.35.
😅😅😅😅😅 sorry about this, now I'm getting Argument of type 'string | Buffer | null | undefined' is not assignable to parameter of type 'ByteSource'. Type 'undefined' is not assignable to type 'ByteSource'.ts(2345) as an error on the req.body inside the decode() on the requestReceived hook
I'll have to think on this. I could likely strengthen the type signature to drop the null | undefined, but you'll still run into an issue in the JSON case, because TS won't like Buffer in a template string, and JSON.stringify won't accept Buffer | string.
You could cast (though you lose some type safety, and this would break if a client sent an empty request body):
app.on("requestReceived", (ctx, req) => {
console.log(
`Received request body: ${
ctx.contentType === "Protobuf"
? ctx.method.input.decode(req.body as Buffer)
: (req.body as string)
}`
);
});
I would recommend sidestepping the manual decoding though and use requestRouted instead:
app.on('requestRouted', (_ctx, input) =>
console.log(`Received request body: ${input}`)
Does that work for your use case?