A TypeError associated with attempting to read #baseLogData

[GeoffThorpeFT]

Node.js version: v14.19.3
Impacted package(s): logger

Steps to reproduce

1. We have some code in biz-ops-api that creates a proxy logger so that the graphql library can call it to produce logs of the queries that the API Explorer runs

2. I have swapped n-logger for logger here: https://github.com/Financial-Times/biz-ops-api/blob/main/server/lib/logger.js#L43

3. There is some code here that creates a proxy: https://github.com/Financial-Times/biz-ops-api/blob/main/server/lib/logger.js#L76-L102

4. Both the above appear to run without error. However ...

5. On execution of a graphql query the execution of the proxy/logger causes the following error:

{"level":"error","event":"LOG_METHOD_FAILURE","message":"Failed to log at level 'info'","error":{"name":"TypeError","code":"UNKNOWN","message":"Cannot read private member #baseLogData from an object whose class did not declare it","isOperational":false,"relatesToSystems":[],"cause":null,"stack":"TypeError: Cannot read private member #baseLogData from an object whose class did not declare it\n    at Proxy.log (/Users/geoff.thorpe/Documents/Repos/biz-ops-api/node_modules/@dotcom-reliability-kit/logger/lib/logger.js:335:64)\n    at Object.apply (/Users/geoff.thorpe/Documents/Repos/biz-ops-api/server/lib/logger.js:107:18)\n    at Proxy.info (/Users/geoff.thorpe/Documents/Repos/biz-ops-api/node_modules/@dotcom-reliability-kit/logger/lib/logger.js:436:8)\n    at Object.apply (/Users/geoff.thorpe/Documents/Repos/biz-ops-api/server/lib/logger.js:107:18)\n    at collectRequestMetrics (/Users/geoff.thorpe/Documents/Repos/biz-ops-api/server/lib/logger.js:117:9)\n    at ServerResponse.<anonymous> (/Users/geoff.thorpe/Documents/Repos/biz-ops-api/server/lib/logger.js:137:27)\n    at Object.onceWrapper (events.js:519:28)\n    at ServerResponse.emit (events.js:412:35)\n    at ServerResponse.emit (domain.js:475:12)\n    at onFinish (_http_outgoing.js:792:10)","statusCode":null,"data":{}}}

Expected behaviour

I would have expected a normal log output that contained the graphql query. The existing logger would have produced something like this:

info:  message=Request received graphql POST, event=ACCESS_LOG, start=1680077126437, path=/graphql, environment=undefined, requestId=76ab9550-ce08-11ed-a3bc-d1c371ada900, clientId=biz-ops-api-demo, clientUserId=geoff, endpoint=graphql, method=POST, , , bodyKeys=[operationName, variables, query], query=query IntrospectionQuery {
  __schema {
    queryType {
      name
    }
    mutationType {
      name
    }
    subscriptionType {
      name
    }
    types {
      ...FullType
    }
    directives {
      name
      description
      locations
      args {
        ...InputValue
      }
    }
  }
}

[rowanmanning]

I think we're gonna need @wheresrhys for this one because I don't understand JS proxy classes very well or what this code is doing. What I do know is that Proxy doesn't work with private fields on classes. So this isn't a bug with Reliability Kit, it's a known incompatibility between two JavaScript features.

Reliability Kit makes use of private fields a bunch (in this case #baseLogData) because it helps us lock down the packages, making sure that teams aren't able to use properties or methods that aren't part of the public API.

I think we have two options due to the incompatibility of private fields vs proxies (I'm gonna leave the issue open until Rhys chips in because he might have strong opinions here):

1. You stop proxying the logger in Biz Ops API and tackle request logging differently. We document in the migration guide that proxies will no longer work with the logger.

2. We remove use of private fields across Reliability Kit.

I don't want to go with option 2 as our use of private fields is pretty legitimate and I think there are probably other ways to solve request logging. These are the things we'd have to change to support proxies in the logger package alone (at a glance, there are probably more):

• Make the base log data public which reverses our desire to keep each logger mutable
• Make the internal list of transforms public, which would also make loggers mutable
• Make our internal deprecation warning tracker public

[wheresrhys]

I guess the alternative for us is to write a "proxy" manually by wrapping the library.

I think it should work @GeoffThorpeFT

[rowanmanning]

Thanks Rhys 🙂 does this mean you're happy if the resolution in Reliability Kit is that we document this in the n-logger migration guide?

[wheresrhys]

I guess leave it with us for now. If it turns out that wrapping is not workable then we may come back to you to discuss further. In the meantime documenting that logger is unproxyable would be a good addition 👍