Logging support #402

Slava · 2016-06-09T22:01:16Z

This PR builds on top of #396 and provides a new option logFn that is called by GraphQL.js with the following events:

Resolver starts execution
Resolver finished execution
Resolver threw an error
Resolver's subtree starts execution (for a compound type)
Resolver's subtree finished execution
Resolver's subtree threw an error

This logging allows external users of the graphql module to tap into the execution time-line for profiling or logging/debugging.

Note that this is not intended to be a logging system available from resolver's code. For that, we expect users of the library to pass their logging mechanism through the context property.

Slava · 2016-06-09T23:41:53Z

The tests pass locally. Can anyone please help me to understand why eslint complains about Flowtype type hints on Travis CI?

leebyron · 2016-06-10T16:50:32Z

This is pretty sweet, I'm not sure why the flow errors are being introduced.

leebyron · 2016-06-10T16:51:13Z

Ah, it looks like when the flow version was recently upgraded, it started catching new errors which are live in the library. I'll investigate.

coveralls · 2016-06-10T21:56:50Z

Coverage increased (+0.02%) to 98.31% when pulling abf51ce on meteor:logging-support into 572bbda on graphql:master.

leebyron · 2016-06-10T22:18:40Z

It's a bit hard to review this with the stacked PRs (I really wish Github had better support for this), but now that the previous has landed, perhaps you can rebase this?

leebyron · 2016-06-10T22:19:16Z

I also landed a few minor follow-ups after your PR, so hopefully that doesn't cause too much rebase pain. Sorry for that in advance.

Slava · 2016-06-10T22:20:00Z

Yeah, I am working on rebasing it. Will update soon.

Slava · 2016-06-10T22:30:17Z

@leebyron I updated the PR. Similar to the previous time, the eslint errors on Travis CI don't make much sense to me. Tests pass locally.

leebyron · 2016-06-10T22:36:32Z

The eslint errors look relevant actually. In a follow-up I unified the names of variables such that exePath is now path.

Slava · 2016-06-10T22:44:16Z

@leebyron oh, sorry! Seems like I didn't fetch after your follow ups second time. Should be good now.

KyleAMathews · 2016-06-10T23:27:17Z

Is info the same thing as the context object? Or will it be possible to pass a request or transaction id that gets passed to this logFn?

Slava · 2016-06-11T00:23:29Z

@KyleAMathews no, info is not the same as the context object, it is the same as the info object passed to a resolver function.

In the code as it is now, there is no way to do it unless you pass a log function that is aware of some higher-level context.

helfer · 2016-06-11T00:28:29Z

@KyleAMathews There may be several requests processed concurrently at any given time, so I think the best way to do what you ask for is to create a new log function for every request, and generate the ID when you create that function. That's what I've been doing for tracing and timing executions in apollo server.

KyleAMathews · 2016-06-11T02:08:46Z

@helfer ah that sounds very doable. I implemented http://lightstep.com/ recently (which is 💯 ) and manually instumented some really important flows but this will let me instrument everything which is really exciting.

Been hoping for this for a while :-) thanks @Slava! #109

Slava · 2016-06-17T21:32:03Z

The tests are failing on Travis because the eslint plugin was borked in recent versions (around 6 days ago). The workaround is to force a different version of the eslint plugin:

npm install [email protected]

Allows graphql to log whenever the executor enters or leaves a subtree; an error occurs; or a resolver starts/ends execution.

…path`

Slava · 2016-07-13T22:31:58Z

@leebyron rebased the PR!

leebyron · 2016-07-21T20:10:28Z

Thank you, @Slava! I haven't forgotten about this and want to give it proper focus very soon.

Just for some context as to how I'd like to approach this, I'd like to take a step back and propose a handful of alternative logging APIs and have a discussion around the pros/cons of each.

Slava · 2016-07-21T22:13:49Z

@leebyron thanks for talking another look at this! I will be happy to look at alternative API designs.

sibelius · 2017-03-23T18:48:30Z

I think this should be outside graphql-js core

take a look on these resources: graphql-compose/graphql-perf#2

you can wrap all your resolvers to do logging and performance metrics on them

what do you think @leebyron ?

baer · 2017-04-20T23:31:16Z

@sibelius Instrumenting resolvers can be really helpful but there are certain metrics, like knowing if a deprecated field is still being called by clients, that could be more easily accessed if GraphQL exposed some instrumentation APIs. For example, the Apollo Optics project accomplishes this by walking the schema and instrumenting it field by field which would be made much easier if GraphQL just supported instrumentation natively.

sibelius · 2017-04-21T00:14:22Z

@baer what would be the benefit of "natively" approach from the apollo optics approach?

baer · 2017-04-25T18:15:11Z

Instrumenting field-by-field in the way they have to do it is not terribly graceful. It would be an improvement if GraphQl provided a generic way to add higher order functions to all resolvers since in this case things like performance, timings, and API usage data is so foundational that it may not make sense for this to be implemented in user-land.

baer

This PR is 👏. I'd love to help move it forward if you'd like another set of hands.

baer · 2017-07-13T05:24:09Z

src/execution/logging.js

+ *  of patent rights can be found in the PATENTS file in the same directory.
+ */
+
+export const TAG = {


What's the purpose of logging RESOLVER_ERROR or SUBTREE_ERROR if you've already got the exeContext.errors Array?

baer · 2017-07-13T05:28:25Z

src/execution/logging.js

+ */
+
+export const TAG = {
+  SUBTREE_START: 'SUBTREE_START',


Isn't a SUBTREE just a non-leaf node? I don't understand what the reason to log here is since the RESOLVER will log immediately after. Seems redundant but I'm probably missing something.

baer · 2017-07-13T05:29:26Z

src/graphql.js

 */
 export function graphql(
  schema: GraphQLSchema,
  requestString: string,
  rootValue?: mixed,
  contextValue?: mixed,
  variableValues?: ?{[key: string]: mixed},
-  operationName?: ?string
+  operationName?: ?string,
+  logFn?: (tag: string, payload: mixed, info: mixed) => void


It seems like there are two main cases that this PR will need to account for:

Timing information

Inspection of poorly performing resolvers

Timings
Since the logging of *_START and *_END are separate, in order to measure resolver timings similar to what Apollo Optics does, this function should probably guarantee either a key like query:<path>:<fieldName> or enough information about a resolver to construct one. I see that it accepts path (in some places) already, but that is likely not quite enough, especially if multiple queries are running at once.

Inspection
My guess is that it will eventually be useful to folks to log all sorts of information about poorly performing resolvers, much more than just the path or key. For example, if an Array resolver has a search/filter argument, it would be helpful to know which filters are running slowly. Rather than a payload and info of type mixed, why not just pass the same or similar objects to what a resolver function receives?

chrisregnier · 2017-11-15T01:50:44Z

This looks fantastic!

One thing I'd suggest though is that the terminology seems a little odd. I think 'logFn' is a little specific and makes me think I should be providing a logger. I'd suggest something like 'onSignal' since firing signals seems more appropriate for the purpose here.

BadgerBadgerBadgerBadger · 2018-05-03T14:49:41Z

Any updates on this?

prantlf · 2019-08-17T16:53:42Z

An example using the instrumentation could implement an output compatible with https://github.com/apollographql/apollo-tracing.

langpavel · 2019-11-23T02:13:53Z

I'm heavily for logging support 👍 but honestly,
I'm don't understand code changes introduced.
This PR looks like bigger and interesting goal…
Please, explain all in details and then this may be accepted.

vanthome · 2020-03-13T21:38:05Z

This is desperately needed for debugging scenarios where single field resolvers fail not on the root level. Will this make it in?

ghost added the CLA Signed label Jun 9, 2016

Slava mentioned this pull request Jun 9, 2016

Pass through the logFn option to execute graphql/express-graphql#97

Closed

KyleAMathews mentioned this pull request Jun 11, 2016

Generate metrics for requested fields #404

Closed

ghost added the CLA Signed label Jul 12, 2016

Slava added 4 commits July 13, 2016 14:26

Add support for loggerFn

a066954

Allows graphql to log whenever the executor enters or leaves a subtree; an error occurs; or a resolver starts/ends execution.

Normalize the payload to the log function to always have a property `…

e6633a1

…path`

add missing log

b1eff58

Promise -> Promise<*>

816ab8e

ghost added the CLA Signed label Jul 14, 2016

ghost added the CLA Signed label Jul 21, 2016

helfer mentioned this pull request Jul 29, 2016

Test coverage apollographql/apollo-server#62

Closed

stubailo mentioned this pull request Aug 12, 2016

Execution & Error Logging #284

Closed

leebyron force-pushed the master branch from fda2afd to da8fe62 Compare May 26, 2017 16:58

baer mentioned this pull request May 26, 2017

Request: Global Error Handler #773

Closed

baer reviewed Jul 13, 2017

View reviewed changes

IvanGoncharov force-pushed the master branch from e7509a6 to 16f5ca0 Compare June 26, 2019 17:05

vanthome mentioned this pull request Mar 13, 2020

object validation creates misleading non null error #1989

Closed

IvanGoncharov closed this Jan 27, 2021

IvanGoncharov deleted the branch graphql:master January 27, 2021 11:10

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging support #402

Logging support #402

Slava commented Jun 9, 2016

Slava commented Jun 9, 2016

leebyron commented Jun 10, 2016

leebyron commented Jun 10, 2016

coveralls commented Jun 10, 2016

leebyron commented Jun 10, 2016

leebyron commented Jun 10, 2016

Slava commented Jun 10, 2016

Slava commented Jun 10, 2016

leebyron commented Jun 10, 2016

Slava commented Jun 10, 2016

KyleAMathews commented Jun 10, 2016

Slava commented Jun 11, 2016

helfer commented Jun 11, 2016

KyleAMathews commented Jun 11, 2016

Slava commented Jun 17, 2016

Slava commented Jul 13, 2016

leebyron commented Jul 21, 2016

Slava commented Jul 21, 2016

sibelius commented Mar 23, 2017 •

edited

Loading

baer commented Apr 20, 2017

sibelius commented Apr 21, 2017

baer commented Apr 25, 2017 •

edited

Loading

baer left a comment

baer Jul 13, 2017

baer Jul 13, 2017

baer Jul 13, 2017

chrisregnier commented Nov 15, 2017

BadgerBadgerBadgerBadger commented May 3, 2018

prantlf commented Aug 17, 2019

langpavel commented Nov 23, 2019

vanthome commented Mar 13, 2020

Logging support #402

Logging support #402

Conversation

Slava commented Jun 9, 2016

Slava commented Jun 9, 2016

leebyron commented Jun 10, 2016

leebyron commented Jun 10, 2016

coveralls commented Jun 10, 2016

leebyron commented Jun 10, 2016

leebyron commented Jun 10, 2016

Slava commented Jun 10, 2016

Slava commented Jun 10, 2016

leebyron commented Jun 10, 2016

Slava commented Jun 10, 2016

KyleAMathews commented Jun 10, 2016

Slava commented Jun 11, 2016

helfer commented Jun 11, 2016

KyleAMathews commented Jun 11, 2016

Slava commented Jun 17, 2016

Slava commented Jul 13, 2016

leebyron commented Jul 21, 2016

Slava commented Jul 21, 2016

sibelius commented Mar 23, 2017 • edited Loading

baer commented Apr 20, 2017

sibelius commented Apr 21, 2017

baer commented Apr 25, 2017 • edited Loading

baer left a comment

Choose a reason for hiding this comment

baer Jul 13, 2017

Choose a reason for hiding this comment

baer Jul 13, 2017

Choose a reason for hiding this comment

baer Jul 13, 2017

Choose a reason for hiding this comment

chrisregnier commented Nov 15, 2017

BadgerBadgerBadgerBadger commented May 3, 2018

prantlf commented Aug 17, 2019

langpavel commented Nov 23, 2019

vanthome commented Mar 13, 2020

sibelius commented Mar 23, 2017 •

edited

Loading

baer commented Apr 25, 2017 •

edited

Loading