Using the `mutate` function modifies the original request to the server

[ulfgebhardt]

• apollo-server Version: "apollo-server-express": "^2.25.2",
• Operating System (or Browser): not relevant
• Node Version: FROM node:12.19.0-alpine3.10
• apollo-log Version: ^1.1.0

Using the mutate function modifies the original request to the server when modified. It therefore cannot fulfill its purpose as it is and can lead to nasty errors.

How Do We Reproduce?

Modify the request variables during requestDidStart in ApolloLogPlugin({mutate: (data: LogMutateData) => {...}} and see the server use the newly modified variables in its request.

Expected Behavior

The logging framework should be separate from the graphql server. The influence should be apollo -> apollo-log and not in any case apollo-log -> apollo.

Actual Behavior

Using the mutate function modifies the original request to the server when modified.

Suggested solution/workaround

const plugins = [
  {...},
  ApolloLogPlugin({
    mutate: (data: LogMutateData) => {
      // We need to deep clone the object in order to not modify the actual request
      const dataCopy = copyInstance(data)

      // mask password if part of the query
      if (dataCopy.context.request.variables && dataCopy.context.request.variables.password) {
        dataCopy.context.request.variables.password = '***'
      }

      // mask token at all times
      dataCopy.context.context.token = '***'

      return dataCopy
    },
  }),
]

WIth:

const copyInstance = (instance: any) => {
  const data = Object.assign(
    Object.create(Object.getPrototypeOf(instance)),
    JSON.parse(JSON.stringify(instance)),
  )
  return data
}

This seems to work just fine - tho long terms test are not conducted yet.
Maybe the library can either document this problem or provide a solution which ensures performance (not cloning stuff on every request)

To ensure correct behaviour you can do the following:

console.log(data.context.request.variables)
console.log(dataCopy.context.request.variables)

References

This Problem occurred in: https://github.com/gradido/gradido

PR implementing suggested fix in our service: gradido/gradido#1477

Relevant files:

• https://github.com/gradido/gradido/blob/master/backend/src/server/plugins.ts

You can also use this project to reproduce the issue.
Feel free to get in touch on Discord: Dornhoeschen#4105

Further notices & Disclaimer

Please inform me if I am using your library wrongly leading to this error.

I believe this could also be the result of using apollo-server-express instead of apollo-server.

[shellscape]

This rule https://eslint.org/docs/rules/no-param-reassign exists for the same reason. It's considered bad practice, with a few exceptions, to modify incoming variables. If that's something you didn't understand or know, would it be helpful to add that to the docs?

[ulfgebhardt]

This doesnt solve the problem, because

mutate: (data: LogMutateData) => {
  const data2 = data
  data2.deeply.nested.field = 123
  console.log(data)
}

will hold the same result.

Neither JS nor Java do deep clone objects out of efficiency reasons.

Here is an article which could explain the general problem: https://www.geeksforgeeks.org/what-is-shallow-copy-and-deep-copy-in-javascript/

Note: We pivoted to use lodash.clonedeep - see gradido/gradido@a201cad

[shellscape]

Knowing that const data2 = data doesn't actually clone the data, and that the parameter reference will still be updated, is a JavaScript language fundamental.

So again, this still looks like you're reporting a documentation issue to me. e.g. you didn't feel that the documentation had enough information for you to be successful, and discover that you had to clone the object yourself.

[ulfgebhardt]

Yes, you might be right - that its just an documentation issue.

What I expected was that when I use the mutate functionality I could freely edit the data provided by data and not modify the outcome of the server query due to modified fields in the query. As stated above in the initial report I would never expect the log framework to effect the server and query outcome.

From the documentation I get:

### mutate
Type: Function Default: (data: Record<string, string>) => Record<string, string>

If specified, allows inspecting and mutating the data logged to the console for each message.

It supports the view, that you are allowed to mutate that data for logging purposes. It is not obvious that mutating would affect the server itself.

I will go with my proposed solution and just wanted to offer the insight - It also might not be obvious to other users and it could be useful to document this behaviour.

Furthermore I think it could be in the interest of this package to provide a way to decouple the data in the mutate() function from the data the server processes - maybe even in an intelligent way so that the cloning of the data only then occurs when its actually needed. (See my case - the data will now be cloned on every call).

At least I would expect an example how to decouple the data eg using lodash.clonedeep

[shellscape]

The issue is that it'd be incredibly inefficient in both memory and perf to clone each object from the server as it's provided to the log. If you've ever logged everything from an active server, you're aware that it's a literal deluge of logs.

We'll tag this as a documentation issue and make an update.