Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Api Logger Middleware - Unit tests #441

Merged
merged 7 commits into from
Jun 20, 2019
Merged

Conversation

KtorZ
Copy link
Member

@KtorZ KtorZ commented Jun 19, 2019

Issue Number

#352

Overview

  • I have written unit tests for the new logging middleware, using a mock server

Comments

Covers pretty much everything but response streams that we don't use anyway.

@KtorZ KtorZ requested a review from paweljakubas June 19, 2019 16:40
@KtorZ KtorZ self-assigned this Jun 19, 2019
, sensitive :: Int
} deriving Generic

instance ToJSON MkJson where
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if we have MkJson deriving Generic and we have

{-# LANGUAGE DeriveGeneric #-}

import GHC.Generics

aren't below instances equal to

instance ToJSON MkJson
instance FromJSON MkJson

???

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Indeed ^.^... I think I just like being explicit. Force of the habit.

, whatever :: Int
} deriving Generic

instance ToJSON ResponseJson where
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the same remark/question as above

, (Error, "500 Internal Server Error")
]

it "different request ids" $ \ctx -> do
Copy link
Contributor

@paweljakubas paweljakubas Jun 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we do not lose any request's log. but do we also have time order maintained in this setup? Maybe we do not have this kind of guarantee here? If we have, maybe it is worth showing it....

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmm. Good point. There's actually no tests about the timing of request at all. It could be worth adding a handcrafted "long" endpoint (like, over a second or so) and check that the computed time is indeed over a certain amount of time.

For the concurrent test... 🤔.. Perhaps it'll be sufficient to also make a single request to that endpoint, and expect to have only one set of log lines with a time above 1s?

What do you think?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(I mean, single request to the long endpoint in addition to the 100 requests to the other faster one)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

exactly, how the logging will behave when timeout, also crossed my mind!

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmm.. Timeout is only a client concern here. The server does not timeout so to speak, only the client closes the connection.

I am not actually 100% sure how servant / warp behaves in that case. I suppose they leave the handler until it completes and throwd when trying to write the response back to the client.. In any case, that's kinda out of scope for the middleware here which has no control over this.

Copy link
Contributor

@paweljakubas paweljakubas Jun 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking that maybe we can add one property to those unit tests. Here we can add long endpoint (this would strengthen the case) and we would generate 100 different endpoints queries. And in the property we would realize that combination of request twice and compare results of these two 100-request runs. With fast endpoints, then with long endpoints, or even better mix of short and long...Maybe it is overkill - but still it would give us more information what to expect from our logging engine just looking at the test suite.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤔 And what would we expect this property to be / demonstrate?

Copy link
Contributor

@paweljakubas paweljakubas Jun 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that when we run the set of 100 different queries the logging is deterministic in terms of logging time order when something is satisfied?(for example, when the response time order from mock server is the same in those two 100-request runs). Some logging engines does not guarantee this for sure because they have buffers working strangely...Just speculating ....

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, having something deterministic won't be that easy because we don't know what servant and the GHC runtimes does with the requests. Eventually, Servant creates one thread per request handler, but they get interleaved in a non deterministic order so I wouldn't rely too much on that. So, we can't be sure that if req#1 is received before req#2, it'll log req#1 before. Especially since there's a MVar read before the log entry, it can cause the thread to hang and pass on the focus to another thread. Plus, I don't think it really matters to have logs in order for this kind of scenarios. What matters is that all the logs are indeed there.

So, best we can do is really say that, after n requests, there should be entries regarding n different requests.

Copy link
Contributor

@paweljakubas paweljakubas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am really fond of this small mock server that illustrates what can we expect when using logging engine!

Copy link
Contributor

@rvl rvl left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good, I should do something similar for the DBLayer logs.

@KtorZ KtorZ force-pushed the KtorZ/api-logger-unit-tests branch from ed834e0 to 3e843a4 Compare June 20, 2019 09:24
@KtorZ
Copy link
Member Author

KtorZ commented Jun 20, 2019

@paweljakubas

  • Used concise notation for JSON instances
  • Turned the last test about requests ids into a property (in terms of the number of requests)
  • Added another endpoint on the mock server /long which only returns after 100 milliseconds (which is many orders of magnitude bigger than other endpoints!)
  • Added another property verifying that regardless of the interleaving of standard /get request and a single /long request, only one request had a time logged above 100ms (the long one) to increase confidence that request execution times are logged correctly.

@KtorZ KtorZ merged commit 2e29b8c into master Jun 20, 2019
@KtorZ KtorZ deleted the KtorZ/api-logger-unit-tests branch June 20, 2019 09:53
@KtorZ KtorZ mentioned this pull request Jun 20, 2019
10 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants