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

Allow a user-provided logger for Server, Gateway and AER #3894

Merged
merged 19 commits into from
Mar 17, 2020

Conversation

abernix
Copy link
Member

@abernix abernix commented Mar 16, 2020

In general, Apollo Server and Apollo Gateway do very little outputting of messages (either informational or otherwise) to its console. Historically, both Server and Gateway have simply used various console methods (i.e. console.log) to output such messages without regard to "log levels" or other logger possibilities.

Using console methods does get the point across quite well in development, though it's less ideal for production environments which often demand a more structured approach to capturing their log messages across various stacks. For example, in containerized environments logs are often siphoned into various centralized log facilities and/or third party log providers (e.g. Datadog, Loggly, etc.).

Many users are already using existing loggers (like winston, log4js, bunyan and more) to report messages from their resolvers by exposing those logger implementations on their "context" using the context property to the ApolloServer constructor options. However, exposing a logger on the context doesn't allow Apollo Server to use it for its own important messaging and users should be able to opt into getting Apollo's own messages in the same log facilities.

Apollo Server will continue to be relatively quiet for now, but various sub-components (e.g. Gateway, Engine Reporting) are already outputting more and more important messages and warnings which deserve to get attention. In general, Apollo Gateway could certainly surface more logging (at various levels) and logger support would allow users to capture existing warnings and errors in one place.

Therefore, this introduces a relatively generic logger property to ApolloServer which will be made available on the GraphQLRequestContext that is already passed around in many places internally, received by various Gateway components (RemoteGraphQLDataSource), and also exposed to plugins, allowing well-considered plugins to utilize the same centralized log sink.

The ApolloGateway class will also support this logger, though for now, it will need to be passed in explicitly to both ApolloServer and ApolloGateway:

// For example purposes, I'm using `winston`, but you could
// create a logger with other packages linked in the footnotes.
const logger = require('winston').createLogger({
  transports: [
    new winston.transports.Console(),
    new winston.transports.File({ filename: 'combined.log' })
  ]
});;

const gateway = new ApolloGateway({
  logger,
});

const server = new ApolloServer({
  gateway,
  logger,
});

// other important details have been left out!

This will also allow granular logging at various levels, including scoped or tagged logging, since the request pipeline could be used to create a sub-instance of a logger. For example, different components can accept their own logger property which, when set, will override any more-parent logger and allow logs to be sorted according to user preference. Apollo Engine will be the first-subcomponent to get this treatment. (engine will automatically inherit from ApolloServer).

Similarly, for logger implementations that support the notion of creating a sub-logger from an existing logger, the plugin life-cycle hooks can be used to create a user-specific logger in the requestDidStart life-cycle. This can be helpful in applying a user-id tag to all log messages which happened within the scope of a particular request. If the same logger should be made available to resolvers via exposure on the context, such plugin implementation on requestDidStartshould also augment the already-createdcontext` with the scoped-logger. Currently, there may be some typing restrictions that make this problematic, but in theory, it's certainly possible.

Will consider supporting this if I can confirm all loggers support it.
The `logger` will be mutually exclusive to the `debug` property, which means
we'll need to (essentially) XOR them in the types with `never` types, which
cannot be done with an `interface`.
This is a mutually exclusive option to `debug` which enables logging of our
default logger when one is not provided by the user.
…ontext`.

A follow-up commit will make these required!
@abernix abernix force-pushed the abernix/logger-support branch 3 times, most recently from 2ca6be5 to 6b2384d Compare March 16, 2020 18:37
This is a more granular part of a larger project to introduce the concept of
a `logger` to various parts of the Apollo Server stack - including
`ApolloGateway` and `ApolloServer`.

Since this extension is most always initiated by `ApolloServer` itself, this
will generally be a property that is inherited by the configuration that
`ApolloServer` provides.

The intention is: if someone provides a `logger` at the `ApolloServer`
level, we will propagate it down to various sub-components, including the
`apollo-engine-reporting` extension.
In general, Apollo Server itself does very little outputting of messages
(either informational or otherwise) to its console.  Historically, Apollo
Server has simply used various `console` facilities (i.e. `console.log`) to
output such messages.

Using `console` methods does get the point across quite well in development,
though it's less ideal for production environments which often demand a more
structured approach to capturing their log messages across various stacks.
For example, in containerized environments logs are often siphoned into
various centralized log facilities and/or third party log providers (e.g.
Datadog, Loggly, etc.).

Many users are already using existing loggers (like [`winston`], [`log4js`],
[`bunyan`] and more) to report messages from their resolvers by exposing
those logger implementations on their "context" using the `context` property
to the `ApolloServer` constructor options.  However, exposing a logger on
the `context` doesn't allow Apollo Server to use it for its own important
messaging and users should be able to opt into getting Apollo's own messages
in the same log facilities.

Apollo Server will continue to be relatively quiet for now, but various
sub-components (e.g. Gateway, Engine Reporting) are already outputting more
and more important messages and warnings which deserve to get attention.

Therefore, this introduces a relatively generic `logger` property to
`ApolloServer` which will be made available on the `GraphQLRequestContext`
that is already passed around in many places internally, received by various
Gateway compoments, and also exposed to plugins, allowing well-considered
plugins to utilize the same centralized log sink.

This should also allow granular logging at various levels, including scoped
or tagged logging, since the request pipeline could be used to create a
sub-instance of a logger.  For example, different components can accept
their own `logger` property which, when set, will override any more-parent
`logger` and allow logs to be sorted according to user preference.  Apollo
Engine will be the first-subcomponent to get this treatment.

Similarly, for logger implementations that support the notion of creating a
sub-logger from an existing logger, the plugin life-cycle hooks can be used
to create a user-specific logger in the `requestDidStart` life-cycle.  This
can be helpful in applying a user-id tag to all log messages which happened
within the scope of a particular request.  If the same logger should be made
available to resolvers via exposure on the `context, such plugin
implementation on `requestDidStart` should also augment the already-created
`context` with the scoped-logger.
We're only testing the interface compatibility here, so the latest version
isn't really necessary.  Though this would be great to update!
@abernix abernix added this to the Release 2.12.0 milestone Mar 16, 2020
Copy link
Member

@trevor-scheer trevor-scheer left a comment

Choose a reason for hiding this comment

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

This looks great, @abernix. The new tests are always appreciated and make reviewing medium-larger PRs like this a breeze!

packages/apollo-gateway/src/index.ts Outdated Show resolved Hide resolved
packages/apollo-server-core/src/ApolloServer.ts Outdated Show resolved Hide resolved
packages/apollo-server-core/src/ApolloServer.ts Outdated Show resolved Hide resolved
packages/apollo-server-core/src/runHttpQuery.ts Outdated Show resolved Hide resolved
abernix and others added 8 commits March 17, 2020 13:39
You'd think I dictated these using Siri or something.

Thanks, @trevor-scheer.

Co-Authored-By: Trevor Scheer <trevor@apollographql.com>
This reverts the decomposition introduced by commit
8a19ecc, but also maintains the bit that
was added right after it in 780d7f4.

Specifically, I misjudged with the direction I was headed.  While my intent
was to have `debug` and `logger` be mutually exclusive, it turns out that in
order to preserve the existing behavior, I need to make sure that `debug:
true` is the thing that puts the default logger (`loglevel`) into the
appropriate level where it still prints out various legacy messages.

cc @trevor-scheer
In terms of verbosity, and as the name of this option suggests, the output
when `debugPrintReports` is enabled is is either an "info" or a "debug"
level message.

However, we are using `warn` here for compatibility reasons since the
`debugPrintReports` flag pre-dated the existence of log-levels and changing
this to also require `debug: true` (in addition to `debugPrintReports`) just
to reach the level of verbosity to produce the output would be a breaking
change.  The "warn" level is on by default.  There is a similar theory and
comment applied below.

cc @trevor-scheer
@abernix abernix changed the title Allow a user-provided logger implementation for Server, Gateway and AER. Allow a user-provided logger for Server, Gateway and AER Mar 17, 2020
@abernix abernix merged commit 656d3ff into release-2.12.0 Mar 17, 2020
@abernix abernix deleted the abernix/logger-support branch March 17, 2020 21:32
abernix added a commit that referenced this pull request Mar 17, 2020
While this package provided some simple functionality at one point or
another, it was neither actively maintained, properly typed, and as of #
fully-featured as of
#3894, no longer really
necessary.  Also, since it re-uses the same logger based on repeat requests
to `getLogger("name")` in a global context, it was responsible for
recursively wrapping our log function in tests with the same `methodFactory`
and causing our log messages to get longer and longer for each test which
used `ApolloGateway`.  This only affected tests, but was hard to track down
the cause!

The new `logger` functionality in the above PR should provide much more
flexibility here and `debug: true` on the `ApolloGateway` constructor can
replicate the same behavior.

Anyone who misses this behavior can utilize the new pluggable
logger to provide [`loglevel-debug`] themselves!

[`loglevel-debug`]: https://npm.im/loglevel-debug
abernix added a commit that referenced this pull request Mar 18, 2020
While this package provided some simple functionality at one point or
another, it was neither actively maintained, properly typed, and as of #
fully-featured as of
#3894, no longer really
necessary.  Also, since it re-uses the same logger based on repeat requests
to `getLogger("name")` in a global context, it was responsible for
recursively wrapping our log function in tests with the same `methodFactory`
and causing our log messages to get longer and longer for each test which
used `ApolloGateway`.  This only affected tests, but was hard to track down
the cause!

The new `logger` functionality in the above PR should provide much more
flexibility here and `debug: true` on the `ApolloGateway` constructor can
replicate the same behavior.

Anyone who misses this behavior can utilize the new pluggable
logger to provide [`loglevel-debug`] themselves!
abernix added a commit that referenced this pull request Jun 29, 2020
…r agent.

Use the `Logger` types which are now provided by `apollo-server-types` as a
base type for a "logger" now, introduced in the below-referenced PR.

Note: While it's now more within reach, this doesn't yet expose the `logger`
configurability at the top-level, nor does it try to leverage the `logger`
that is provided to `serverWillStart` since that will require additional
changes which are currently out of scope to accommodate the `dryRun` mode of
operation which currently forces the log-level to a specific level when
activated. Further, it does so using a `loglevel`-specific API.

Therefore, these changes are best described as being limited to the agent's
logger.

[Ref]: #3894
abernix added a commit that referenced this pull request Aug 7, 2020
…r agent. (#4329)

* chore(op-reg): Change to `Logger` types from `apollo-server-types` for agent.

Use the `Logger` types which are now provided by `apollo-server-types` as a
base type for a "logger" now, introduced in the below-referenced PR.

Note: While it's now more within reach, this doesn't yet expose the `logger`
configurability at the top-level, nor does it try to leverage the `logger`
that is provided to `serverWillStart` since that will require additional
changes which are currently out of scope to accommodate the `dryRun` mode of
operation which currently forces the log-level to a specific level when
activated. Further, it does so using a `loglevel`-specific API.

Therefore, these changes are best described as being limited to the agent's
logger.

[Ref]: #3894

* Fix typing error by removing unnecessary mock restoration.

This mock restoration shouldn't be necessary as we're mocking a method on an
object literal that's created within the scope of the test itself.
abernix added a commit to apollographql/federation that referenced this pull request Sep 4, 2020
abernix added a commit to apollographql/federation that referenced this pull request Sep 4, 2020
…phql/apollo-server#3894)

* Switch multi-argument `logger` pattern to single parameter invocations.

Will consider supporting this if I can confirm all loggers support it.

* Decompose `GatewayConfigBase` into types in preparation for `logger`.

The `logger` will be mutually exclusive to the `debug` property, which means
we'll need to (essentially) XOR them in the types with `never` types, which
cannot be done with an `interface`.

* gateway: Introduce `Logger` type and expose on `logger` config.

This is a mutually exclusive option to `debug` which enables logging of our
default logger when one is not provided by the user.

* tests: test various popular loggers: log4js, winston, bunyan, loglevel.

* Add optional `logger` to `GraphQLServiceContext` and `GraphQLRequestContext`.

A follow-up commit will make these required!

* Introduce optional `logger` property for `apollo-engine-reporting`.

This is a more granular part of a larger project to introduce the concept of
a `logger` to various parts of the Apollo Server stack - including
`ApolloGateway` and `ApolloServer`.

Since this extension is most always initiated by `ApolloServer` itself, this
will generally be a property that is inherited by the configuration that
`ApolloServer` provides.

The intention is: if someone provides a `logger` at the `ApolloServer`
level, we will propagate it down to various sub-components, including the
`apollo-engine-reporting` extension.

* Introduce optional `logger` for `ApolloServer` class.

In general, Apollo Server itself does very little outputting of messages
(either informational or otherwise) to its console.  Historically, Apollo
Server has simply used various `console` facilities (i.e. `console.log`) to
output such messages.

Using `console` methods does get the point across quite well in development,
though it's less ideal for production environments which often demand a more
structured approach to capturing their log messages across various stacks.
For example, in containerized environments logs are often siphoned into
various centralized log facilities and/or third party log providers (e.g.
Datadog, Loggly, etc.).

Many users are already using existing loggers (like [`winston`], [`log4js`],
[`bunyan`] and more) to report messages from their resolvers by exposing
those logger implementations on their "context" using the `context` property
to the `ApolloServer` constructor options.  However, exposing a logger on
the `context` doesn't allow Apollo Server to use it for its own important
messaging and users should be able to opt into getting Apollo's own messages
in the same log facilities.

Apollo Server will continue to be relatively quiet for now, but various
sub-components (e.g. Gateway, Engine Reporting) are already outputting more
and more important messages and warnings which deserve to get attention.

Therefore, this introduces a relatively generic `logger` property to
`ApolloServer` which will be made available on the `GraphQLRequestContext`
that is already passed around in many places internally, received by various
Gateway compoments, and also exposed to plugins, allowing well-considered
plugins to utilize the same centralized log sink.

This should also allow granular logging at various levels, including scoped
or tagged logging, since the request pipeline could be used to create a
sub-instance of a logger.  For example, different components can accept
their own `logger` property which, when set, will override any more-parent
`logger` and allow logs to be sorted according to user preference.  Apollo
Engine will be the first-subcomponent to get this treatment.

Similarly, for logger implementations that support the notion of creating a
sub-logger from an existing logger, the plugin life-cycle hooks can be used
to create a user-specific logger in the `requestDidStart` life-cycle.  This
can be helpful in applying a user-id tag to all log messages which happened
within the scope of a particular request.  If the same logger should be made
available to resolvers via exposure on the `context, such plugin
implementation on `requestDidStart` should also augment the already-created
`context` with the scoped-logger.

* To support Node.js 6, use older version of `log4js` for testing.

We're only testing the interface compatibility here, so the latest version
isn't really necessary.  Though this would be great to update!

* ResponseCache: when available, use `requestContext.logger` to log.

* gateway: when set, log using `requestContext.logger` in `executeQueryPlan`.

* Make `logger` required on `GraphQLServiceContext` + `GraphQLRequestContext`.

As promised in 62e99d76.

* Fix all the spelling mistakes.

You'd think I dictated these using Siri or something.

Thanks, @trevor-scheer.

Co-Authored-By: Trevor Scheer <trevor@apollographql.com>

* Add CHANGELOG for apollographql/apollo-server#3894.

* docs: Explain `logger` on `ApolloServer` and `EngineReportingOptions`.

* Kinda revert "Decompose `GatewayConfigBase` into types in prep..."

This reverts the decomposition introduced by commit
499051c, but also maintains the bit that
was added right after it in c6a8f8e.

Specifically, I misjudged with the direction I was headed.  While my intent
was to have `debug` and `logger` be mutually exclusive, it turns out that in
order to preserve the existing behavior, I need to make sure that `debug:
true` is the thing that puts the default logger (`loglevel`) into the
appropriate level where it still prints out various legacy messages.

cc @trevor-scheer

* docs: Explain `logger` on `ApolloGateway` in the API reference.

* Apply counter-intuitive severity to `debugPrintReports` messages.

In terms of verbosity, and as the name of this option suggests, the output
when `debugPrintReports` is enabled is is either an "info" or a "debug"
level message.

However, we are using `warn` here for compatibility reasons since the
`debugPrintReports` flag pre-dated the existence of log-levels and changing
this to also require `debug: true` (in addition to `debugPrintReports`) just
to reach the level of verbosity to produce the output would be a breaking
change.  The "warn" level is on by default.  There is a similar theory and
comment applied below.

cc @trevor-scheer

* docs: Note presence of `logger` in plugins' lifecycle  hooks.

Co-authored-by: Trevor Scheer <trevor@apollographql.com>
Apollo-Orig-Commit-AS: apollographql/apollo-server@656d3ff
abernix added a commit to apollographql/federation that referenced this pull request Sep 4, 2020
…graphql/apollo-server#3896)

While this package provided some simple functionality at one point or
another, it was neither actively maintained, properly typed, and as of #
fully-featured as of
apollographql/apollo-server#3894, no longer really
necessary.  Also, since it re-uses the same logger based on repeat requests
to `getLogger("name")` in a global context, it was responsible for
recursively wrapping our log function in tests with the same `methodFactory`
and causing our log messages to get longer and longer for each test which
used `ApolloGateway`.  This only affected tests, but was hard to track down
the cause!

The new `logger` functionality in the above PR should provide much more
flexibility here and `debug: true` on the `ApolloGateway` constructor can
replicate the same behavior.

Anyone who misses this behavior can utilize the new pluggable
logger to provide [`loglevel-debug`] themselves!
Apollo-Orig-Commit-AS: apollographql/apollo-server@0ca43f8
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Apr 21, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants