Logging Prism's decisions. #323

XVincentX · 2019-05-27T11:12:50Z

All right, be prepared.

TL; DR

Prism can now log stuff from the negotiation.
The negotiation and logging process can't make Prism crash anymore for any reason.

Long version

The following PR, in theory, implements logging for the negotiator. Practically, though, this PR is laying down the foundation for the logging for the future hosted version as well and hopefully start moving Prism's code in a different direction.

There were some main principles I've been keeping in mind while writing the code for this stuff:

Prism should not process/format/react to the logs. Somebody else should do it; doing stuff on logs is usually slow and Prism should instead answer all the requests as fast as possible.
The negotiation process in Prism is currently composed by numerous and nested function calls and last thing I wanted to do is to carry over this logger parameter in all the function and having to deal with it everywhere
The logging cannot be a singleton defined somewhere — because the logging instance will be provided externally (Prism Http Server, in this case)
The logging process and the negotiation process should never make Prism crash. In any circumstance. I repeat, in ANY circumstances.

Let's now see how I've tamed them down.

Use Pino. If you go on their website the write that "it's the fastest logger on the world" but you can ignore that, that was not the reason why I went with it. The main points were:
- It's included with fastify — and so we're not introducing a new dependency. We've been shipping it since forever.
- Pino does not include any way to process/alert/react to logs; it simply outputs the log statements as JSON on the stdout (or any stream you provide to it). It means that all the processing must be off process and I think this is great. It means that, by design, there's no way somebody can make messes with logs and do any action that's logging dependant. You can't break what's not even included.

So where's the log processing happening in our case? In the CLI. You can see from the code that, whenever the production environment is detected (or the -m flag is passed) the CLI will effectively use the cluster module to fork the process, run Prism Server and funnel its stdout logs back to the CLI, where Signale will pretty print them. When Prism will be hosted somewhere, we'll likely do the same.

In case you're running the things locally to write code and test the stuff, you'll see that the fork is avoided and all is done in process. This is done fundamentally because it's going to be way easier to debug stuff in a single process. This is exactly the same that Jest does with the --runInBand flag.

You can see from the image what when the -m flag is specified, you'll find an additional process with node running — this is exactly the forking happening.

Note: if NODE_ENV===production the forking is enabled by default, so that if you use the CLI in a Docker Environment you get what the production behaviour.

Inject the logger through currying. Thanks to the partial application I can basically write a function that takes the regular arguments which returns a function needing an additional dependency to run.
const negotiate = (arg1, arg2, arg3) => logger => { // real body }. For this, I've employed fp-ts's reader implementation, that allows me to do exactly that: write code that has regular arguments and returns something that will need a logger to be executed. By leveraging chain and map method, intermediate functions can easily introspect and modify the result in the middle without having to worry about the logging presence. It'll be put as last step. Moreover, if one day we will want to make the Router start outputting logs as well — it's really easy. All we need to do is make the router spit up a Reader and chain it with the following one in the mocker. All good, profit.
See point 2. With Currying I can pretend the inner functions will eventually have a logger, it's resolution is happening in a completely different npm package; this is important to understand why I could not simply have a shared instance to require from somewhere.
This happened as an effect of the reader. Since the logger in injected at the end, the traditional try catch in the middle of the code to decorate the errors does not work anymore. I could have workaround this but I decided instead to change the approach and make sure the negotiation and the logging process never throws exceptions. Therefore the code has been modified to use the Either implementation that's included in fp-ts, which is not that hard to understand. If you check out the NegotiatorHelper.ts you can see there are not that many changes and more importantly nested exceptions are now been flattened — which is good. Clearly there are 1-2 things that aren't that cool but I'm on all of them. In particular:
- Jest should support wrapped helpers so I can remove my home made helpers Add the ability of creating matchers wrapping a value jestjs/jest#8540
- A built-in ReaderEither could let me remove some nested maps. I'm quite sure @gcanti will make it happen soon

Outstanding points

Refactor mock.ts to look a little bit more human
Resolve the null-ness of logger component
Understand whether we're logging enough or too much
CLI Readme Update
Deduplicate the testing helpers
General review and cleanup

SO-231

packages/core/src/factory.ts

chris-miaskowski · 2019-06-18T08:00:13Z

packages/core/src/logger.ts

@@ -0,0 +1,33 @@
+import * as pino from 'pino';


General inquiry: does pino work in browser context? Remember that one of the Prism's requirements is to be able to work both in nodejs and browser (e.g. we want to use it in request maker).

It caught my attention because I wasn't sure if core is actually a good place to store this stuff in. It looks that pino is mostly CLI specific (?)

Yes! http://getpino.io/#/docs/browser

Not entirely correct: the CLI is the place where the logs get captured from the stream and processed/visualised, but its usage spread in the whole application. Moreover, Pino implements the log4j interface so it should be, if needed, easily replaceable with anything we like in the future (Winston, Buyan). Does that clarify?

packages/http/package.json

chris-miaskowski

I had a first (but not final) look. It really looks good but there are two new libraries I'm completely unfamiliar with and need to take another closer look at it.

See if any of the comments I made make sense.

packages/core/src/factory.ts

chris-miaskowski · 2019-06-18T08:32:46Z

packages/http/src/mocker/negotiator/NegotiatorHelpers.ts

+          },
+          httpContent,
+        )
+        .map(contentNegotiationResult => ({


Oooooh! It's the Either's map! I got so confused by this. I thought you somehow ended up mapping arrays here... Very confusing. Not sure what to suggest here. Is there any function other than map that we could use?

hm.. why would mapping on Either be confusing?

I understand @chris-miaskowski's confusion. I had the same when I started to look into this in November.

Thing is the map we use on daily basis on an arrays and objects is a specialisation of a more general map that is basically the introspection in an "effect".

In case of an Array, the effect is the "repetition" of values
In case of an Object, the effect is the presence of multiple properties
On an Either though, the effect is that "something went correctly".

Array and Either are effectively wrapping/representing an effect.

packages/http/src/mocker/negotiator/NegotiatorHelpers.ts

chris-miaskowski · 2019-06-18T08:46:21Z

packages/http/src/mocker/negotiator/NegotiatorHelpers.ts

-          NOT_ACCEPTABLE,
-          `Could not find any content that satisfies ${mediaTypes.join(',')}`,
-        );
+            mediaType: 'text/plain',


Does that fix SO-265?
If it does make sure you have those tests in 631236f

See that WIP branch https://github.com/stoplightio/prism/tree/bug/so-265/inconsistent-content-negotiation

Ah now I realise the reason of that PR — I can merge that branch and see how it goes when we settle down on the code here.

@XVincentX do you still have that on your radar?

I have, I'm a little bit overwhelmed but I'll get it done.

chris-miaskowski · 2019-06-18T09:02:04Z

packages/http/src/mocker/negotiator/NegotiatorHelpers.ts

-    throw new Error('Requested status code is not defined in the schema.');
+
+      return result;
+    }).chain(responseByForcedStatusCode => {


What's the benefit of using chain vs if?

if and chain do two different things, they cannot be interchanged.

To keep it short, chain is just like a flatMap

[1,2,3,4].map(t=>t*2) = [2,4,6,8]
[1,2,3].flatMap(t=>[t, t * 2, t * 3]) = [1, 2, 3, 2, 4, 6, 3, 6, 9]

In this context in particular, chain unwraps the effect for you so if you have an Either — you can concatenate it with another Either

const operationThatMightFail = getDataFromInternet(); operationThatMightFail .map(operation => operation.result) .chain(result => postInternetDataSomewhere(result))

In this case you can see:

You receive an Either from a function that gets data from the internet or fails.

In case it passes, it will call the map function that will effectively transform the result

Pass the data to chain; a chain function can return another Either that will be "executed"/"unwrapped" for you automatically, flattening the final Either you have to deal with.

Does that help?

I never liked chain / bind names for it. flatMap is so obvious a name! :)

chris-miaskowski · 2019-06-18T09:06:08Z

packages/http/src/mocker/negotiator/NegotiatorHelpers.ts

+        return helpers
+          .negotiateOptionsBySpecificResponse(httpOperation, desiredOptions, responseByForcedStatusCode)
+          .chain(either =>
+            either.fold(


One of the goals was to improve readability but I can't tell this did the trick.
We're a increasing the cognitive complexity. Contributing to Prism is already hard (TypeScript, monorepo, workspaces/build and now we're adding functional programming on top of it - I have the feeling we're narrowing potential contributors to 0.00001% of developers ;) )

There is nothing to do with this comment other than maybe not using chains?

chain is a fundamental piece — I'll try to explain it in another of the comment you did.

You have a point though, this is indeed a case-limit that will be addressed soon by the library itself by providing a more specific interface to handle this use case. So you're not wrong here!

packages/http/src/mocker/negotiator/NegotiatorHelpers.ts

packages/cli/README.md

Co-Authored-By: Chris Miaskowski <chris@11sigma.com>

CHANGELOG.md

README.md

packages/cli/src/commands/mock.ts

philsturgeon · 2019-06-18T11:49:01Z

packages/cli/src/commands/mock.ts

-    if (dynamic) {
-      signale.star('Dynamic example generation enabled.');
-    }
+    if (cluster.isMaster) {


This change has so many new terms in it. cluster, stream, multipurpose, pino, master, signale, there is so much not mocking command leaking into the mocking command. I fear this will confuse the heck out of anyone who works on it.

Could you maybe make a stiry with sone notes how to refactor this? It's not just about reuse for a 2nd command, its a problem for understanding this one command.

Yeah ok, this is definitely confusing; let me try to come up with a better way to reorganise the thing.

@philsturgeon I've teared out stuff as much as possible here. 72336ba

It's still a monster, but it should be very well enclosed in two nice functions.

lag-of-death · 2019-06-18T12:15:27Z

packages/cli/src/commands/mock.ts

+}
+
+function pipeOutputToSignale(stream: Readable) {
+  function constructPrefix(logLine: LogDescriptor): string {


hm.. if I'm not mistaken, we can just move out constructPrefix from pipeOutputToSignale (?)

Yeah, I'll probably refactor this command and offload most of the shit in the createServer file and go from there, hopefully that's going to help a lot in this command specifically. Stay tuned for updates.

@XVincentX, I've seen that pipeOutputToSignale is now in another file. But can we also move constructPrefix out of pipeOutputToSignale? I don't see a need for constructPrefix to be defined inside pipeOutputToSignale (but maybe there is (?)). And also, how about pipeOutputToSignale -> pipeOutputToSignal ?

lag-of-death · 2019-06-18T12:16:43Z

packages/core/src/logger.ts

+    timestamp: false,
+  };
+
+  if (destination) return pino(options, destination);


sorry, I had to... maybe a ternary ;) ?

lag-of-death · 2019-06-18T12:19:31Z

packages/http/src/mocker/HttpMocker.ts

-      payloadGenerator = generate;
-    }
+    return withLogger(logger => {
+      // setting default values


would it be much work to make this a separate function? Just like negotiateResponse ?

XVincentX force-pushed the feat/logs branch 2 times, most recently from b1132c8 to ef47888 Compare May 27, 2019 14:20

XVincentX marked this pull request as ready for review May 27, 2019 16:13

XVincentX force-pushed the feat/logs branch 3 times, most recently from 31cf3b3 to a8077dd Compare May 28, 2019 11:43

XVincentX changed the title ~~Logging Prism~~ Logging Prism's decisions. May 28, 2019

XVincentX added 23 commits May 31, 2019 10:55

feat: add pino and its types

a70cf3a

feat: cluster prism-http and forward logs to the cli

746ffb8

refactor: do not export what's not used

e278478

feat: add main logging logic to core

46dfe0f

chore: remove settings file copied who knows from where

c11e69a

refactor: move away logger construction logic from cli

72a3ce8

chore: lock adjustments

e81117d

chore: better launch.json

6f47f4b

feat: export single logger instance

a5e7c27

chore: add success log level

cc7406d

feat: log negotiator invocations

054925b

test: remove

b98ec9d

refactor: close the worker when something goes wrong

a03cea9

chore: add chalk and colorise

32bc99f

feat: parentesis

208558a

feat: log negotiation for invalid responses

9dc481c

feat: create logger at server level

345d143

feat: send request id with each line if possible

c3c6122

feat: print request details when provided

e6dcef0

fix: use types for http methods

c584c43

refactor: logger can be provided as a component

fa4dc58

feat: add colour map

a094c84

refactor: move map to options

23a7a55

XVincentX requested a review from chris-miaskowski June 17, 2019 19:19

chris-miaskowski reviewed Jun 18, 2019

View reviewed changes

packages/core/src/factory.ts Show resolved Hide resolved

chris-miaskowski reviewed Jun 18, 2019

View reviewed changes

chris-miaskowski mentioned this pull request Jun 18, 2019

WIP tests: content negotiation #360

Closed

refactor: extract logEnabledFeature

4b486e3

XVincentX dismissed lag-of-death’s stale review via 4b486e3 June 18, 2019 09:15

philsturgeon previously approved these changes Jun 18, 2019

View reviewed changes

chris-miaskowski reviewed Jun 18, 2019

View reviewed changes

chore: better log message

94fb452

Co-Authored-By: Chris Miaskowski <chris@11sigma.com>

XVincentX dismissed stale reviews from philsturgeon via 94fb452 June 18, 2019 10:06

XVincentX requested review from lag-of-death, chris-miaskowski and philsturgeon June 18, 2019 11:41

philsturgeon reviewed Jun 18, 2019

View reviewed changes

CHANGELOG.md Show resolved Hide resolved

philsturgeon reviewed Jun 18, 2019

View reviewed changes

README.md Outdated Show resolved Hide resolved

philsturgeon reviewed Jun 18, 2019

View reviewed changes

XVincentX added 3 commits June 18, 2019 13:53

refactor: logCLIMessage

f0c348c

docs: fix

2199db6

refactor: avoid the interactive instance, we do not need it

6eb7174

lag-of-death reviewed Jun 18, 2019

View reviewed changes

refactor: put process helpers outside

72336ba

XVincentX requested review from philsturgeon and lag-of-death June 18, 2019 13:08

test: refactor and add

85aa60a

philsturgeon approved these changes Jun 18, 2019

View reviewed changes

Merge branch 'master' into feat/logs

5923c75

XVincentX merged commit 62c3f45 into master Jun 18, 2019

XVincentX deleted the feat/logs branch June 18, 2019 14:44

Logging Prism's decisions. #323

Logging Prism's decisions. #323

XVincentX commented May 27, 2019 •

edited

chris-miaskowski Jun 18, 2019

XVincentX Jun 18, 2019

chris-miaskowski left a comment

chris-miaskowski Jun 18, 2019

lag-of-death Jun 18, 2019

XVincentX Jun 18, 2019

chris-miaskowski Jun 18, 2019

XVincentX Jun 18, 2019

chris-miaskowski Jun 19, 2019

XVincentX Jun 19, 2019

chris-miaskowski Jun 18, 2019

XVincentX Jun 18, 2019

lag-of-death Jun 18, 2019

chris-miaskowski Jun 18, 2019

chris-miaskowski Jun 18, 2019

XVincentX Jun 18, 2019

philsturgeon Jun 18, 2019

XVincentX Jun 18, 2019

XVincentX Jun 18, 2019

XVincentX Jun 18, 2019

lag-of-death Jun 18, 2019

XVincentX Jun 18, 2019

lag-of-death Jun 18, 2019

lag-of-death Jun 18, 2019 •

edited

lag-of-death Jun 18, 2019

lag-of-death Jun 18, 2019

Logging Prism's decisions. #323

Logging Prism's decisions. #323

Conversation

XVincentX commented May 27, 2019 • edited

TL; DR

Long version

Outstanding points

Choose a reason for hiding this comment

Choose a reason for hiding this comment

chris-miaskowski left a 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

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

lag-of-death Jun 18, 2019 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

XVincentX commented May 27, 2019 •

edited

lag-of-death Jun 18, 2019 •

edited