Allow custom loggers

[jamesmeneghello]

Story

As a server

I want to be able to specify a custom logger

So that logs passed to my log aggregator can be in custom formats.

Acceptance criteria

• Server logs can be sent to a configurable logger instead of console.*

Context

More context: errors like these get logged to console, which in our application gets picked up by container logging, which gets dragged context-less into Datadog and pollutes the namespace / error handling. Our server logging is using winston outputting as JSON, so a console.error appears instead as about 30 error log lines in DD. Being able to specify a custom logger would allow us just to pass it to the existing logger and be handled identically to the rest of our logs.

[enisdenjo]

Those console logs were added to put emphasis on uncaught internal errors that shouldn't occur.

Still, I understand your point; however, integrating custom logging capabilities is something I am not keen on doing, it is somewhat tedious work - I have to extend the options at appropriate places with logging hooks, decide about log levels, maintain places someone would want to log and make sure to pass helpful arguments, etc.

However, you can hook up your own logging system with precision and decide yourself how/where/what to log by implementing makeServer yourself. Taking inspiration from the "Server usage with ws" recipe, here's a derivative:

import ws from 'ws';
import {
  makeServer,
  GRAPHQL_TRANSPORT_WS_PROTOCOL,
  CloseCode,
} from 'graphql-ws';
import { logger, createLoggerContext } from './my-logger';

// your own websocket server
const wss = new ws.Server();
const keepAlive = 12_000;

const server = makeServer({
  // ...options
});

const ctx = createLoggerContext({
  instanceId,
  startTime,
  // ...other helpful info
});

wss.once('error', (err) => {
  logger.error(
    ctx,
    'Internal error emitted on the WebSocket server. ' +
      'Please check your implementation.',
    err,
  );
});

wss.on('connection', (socket, request) => {
  const ctx = ctx.subContextWith({ socket, request });

  logger.debug(ctx, 'New connection');

  socket.once('error', (err) => {
    logger.error(ctx, 'Internal error emitted on a WebSocket socket', err);

    // close socket gracefully
    socket.close(CloseCode.InternalServerError, 'Internal server error');
  });

  let pongWait: NodeJS.Timeout | null = null;
  const pingInterval = setInterval(() => {
    if (socket.readyState === socket.OPEN) {
      pongWait = setTimeout(() => {
        logger.warn(ctx, 'Client is away, terminating connection');
        socket.terminate();
      }, keepAlive);

      socket.once('pong', () => {
        logger.trace(ctx, 'Pong received', Date.now());
        if (pongWait) {
          clearTimeout(pongWait);
          pongWait = null;
        }
      });

      logger.trace(ctx, 'Pinging...', Date.now());
      socket.ping();
    }
  }, keepAlive);

  const closed = server.opened(
    {
      protocol: socket.protocol,
      send: (data) =>
        new Promise((resolve, reject) => {
          if (socket.readyState !== socket.OPEN) return resolve();
          logger.trace(ctx, 'Sending message', data);
          socket.send(data, (err) => (err ? reject(err) : resolve()));
        }),
      close: (code, reason) => socket.close(code, reason),
      onMessage: (cb) =>
        socket.on('message', async (event) => {
          logger.trace(ctx, 'Received message', event);
          try {
            await cb(String(event));
          } catch (err) {
            logger.error(
              ctx,
              'Internal error occurred during message handling',
              err,
            );
            socket.close(
              CloseCode.InternalServerError,
              'Internal server error',
            );
          }
        }),
    },
    { socket, request },
  );

  socket.once('close', (code, reason) => {
    if (pongWait) clearTimeout(pongWait);
    if (pingInterval) clearInterval(pingInterval);
    if (code === CloseCode.SubprotocolNotAcceptable)
      logger.warn(
        ctx,
        `Client does not implement the ${GRAPHQL_TRANSPORT_WS_PROTOCOL} protocol`,
      );
    closed(code, String(reason));
  });
});

[jamesmeneghello]

Perfect, thank you!

[paulruescher]

@enisdenjo I'm running into the same problem as James, and would prefer to not maintain our own implementation of useServer. Would you be open to a pull request (by me) for custom logging? Even if it's as simple as being able to pass in a logger instance that conforms to console?

[enisdenjo]

The reason why I'd prefer a custom integration is because maintaining the places people want to log is a never-ending story - everyone's potentially interested in something different.

[paulruescher]

Sorry, it's unclear if you'd accept a pull-request for this.

[enisdenjo]

I need convincing that a logger is worth maintaining.

But, do push a PR, I want to see what you had in mind. We can discuss more there and others can join in too.