Enforce that tests don't log (#5227)

When `npm test` prints out a million "starting usage reporting" logs, it
gets in the way of finding failing tests. This change stops tests from
logging and makes them fail if they do log. (You can run with
ALLOW_CONSOLE=t locally to disable this behavior.)

jest.config.base.js

@@ -3,7 +3,10 @@ const { defaults } = require("jest-config");
 module.exports = {
   testEnvironment: "node",
     setupFiles: [
-      "<rootDir>/../apollo-server-env/dist/index.js"
+      "<rootDir>/../apollo-server-env/dist/index.js",
+    ],
+    setupFilesAfterEnv: [
+      "<rootDir>/../../jest.setup.js",
     ],
     preset: "ts-jest",
     testMatch: null,

jest.setup.js

@@ -0,0 +1,28 @@
+// It's awkward to read `npm test` output if it is littered with console logs.
+// This (from https://github.com/facebook/jest/issues/6121) makes the test fail
+// if it writes anything to console. (Feel free to set $ALLOW_CONSOLE if you are
+// logging while developing and want to see if your tests pass.)
+//
+// Typically you can turn off the info/debug in tests by passing a loglevel
+// logger with level WARN to the logger option to `new ApolloServer`.
+if (!process.env.ALLOW_CONSOLE) {
+  let usedConsole = false;
+  ['log', 'error', 'warn', 'info', 'debug'].forEach((key) => {
+    const originalFn = console[key];
+    console[key] = (...args) => {
+      usedConsole = true;
+      originalFn(...args);
+    };
+  });
+
+  jasmine.getEnv().addReporter({
+    specStarted: (result) => (jasmine.currentTest = result),
+  });
+
+  afterEach(() => {
+    if (usedConsole && !jasmine.currentTest.failedExpectations.length) {
+      usedConsole = false;
+      throw Error('To keep unit test output readable, tests should not write to the console. To test logging behavior, pass a logger to the class under test.');
+    }
+  });
+}

packages/apollo-server-cloud-functions/src/__tests__/googleCloudApollo.test.ts

@@ -40,14 +40,14 @@ const createCloudFunction = async (options: CreateAppOptions = {}) => {
 
 describe('googleCloudApollo', () => {
   it('handles requests with path set to null', async () => {
-    const app = await createCloudFunction();
-    const res = await request(app)
-      .get('/')
-      .set('Accept', 'text/html');
+    const app = await createCloudFunction({
+      graphqlOptions: { schema: Schema, playground: { endpoint: 'xxx' } },
+    });
+    const res = await request(app).get('/').set('Accept', 'text/html');
     expect(res.status).toEqual(200);
   });
 });
 
 describe('integration:CloudFunction', () => {
-  testSuite({createApp: createCloudFunction, serverlessFramework: true});
+  testSuite({ createApp: createCloudFunction, serverlessFramework: true });
 });

packages/apollo-server-core/src/plugin/usageReporting/__tests__/plugin.test.ts

@@ -2,6 +2,7 @@ import { addMocksToSchema } from '@graphql-tools/mock';
 import { makeExecutableSchema } from '@graphql-tools/schema';
 import { graphql } from 'graphql';
 import { Request } from 'node-fetch';
+import loglevel from 'loglevel';
 import {
   makeHTTPRequestHeaders,
   ApolloServerPluginUsageReporting,
@@ -13,6 +14,9 @@ import nock from 'nock';
 import { gunzipSync } from 'zlib';
 import { ApolloServerPluginUsageReportingOptions } from '../options';
 
+const quietLogger = loglevel.getLogger('quiet');
+quietLogger.setLevel(loglevel.levels.WARN);
+
 describe('end-to-end', () => {
   async function runTest({
     pluginOptions = {},
@@ -81,6 +85,7 @@ describe('end-to-end', () => {
     const pluginInstance = ApolloServerPluginUsageReporting({
       ...pluginOptions,
       sendReportsImmediately: true,
+      logger: quietLogger,
     });
 
     const context = await pluginTestHarness({

packages/apollo-server-integration-testsuite/src/ApolloServer.ts

@@ -3,6 +3,7 @@ import { sha256 } from 'js-sha256';
 import { URL } from 'url';
 import express = require('express');
 import bodyParser = require('body-parser');
+import loglevel from 'loglevel';
 
 import { Report, Trace } from 'apollo-reporting-protobuf';
 
@@ -55,6 +56,9 @@ import resolvable, { Resolvable } from '@josephg/resolvable';
 import FakeTimers from '@sinonjs/fake-timers';
 import { AddressInfo } from 'net';
 
+const quietLogger = loglevel.getLogger('quiet');
+quietLogger.setLevel(loglevel.levels.WARN);
+
 export function createServerInfo<AS extends ApolloServerBase>(
   server: AS,
   httpServer: http.Server,
@@ -935,6 +939,7 @@ export function testApolloServer<AS extends ApolloServerBase>(
                 ApolloServerPluginUsageReporting({
                   endpointUrl: reportIngress.getUrl(),
                   maxUncompressedReportSize: 1,
+                  logger: quietLogger,
                   ...usageReportingOptions,
                 }),
                 ...plugins,
@@ -1895,6 +1900,7 @@ export function testApolloServer<AS extends ApolloServerBase>(
                   reportIntervalMs: 1,
                   maxAttempts: 3,
                   requestAgent,
+                  logger: quietLogger,
                   reportErrorFunction(error: Error) {
                     reportErrorPromiseResolve(error);
                   },
@@ -2004,6 +2010,7 @@ export function testApolloServer<AS extends ApolloServerBase>(
         const { url: uri } = await createApolloServer({
           typeDefs: allTypeDefs,
           resolvers,
+          logger: quietLogger,
         });
 
         const apolloFetch = createApolloFetch({ uri });
@@ -2034,6 +2041,7 @@ export function testApolloServer<AS extends ApolloServerBase>(
         const { url: uri } = await createApolloServer({
           typeDefs: allTypeDefs,
           resolvers,
+          logger: quietLogger,
         });
 
         const apolloFetch = createApolloFetchAsIfFromGateway(uri);
@@ -2202,10 +2210,6 @@ export function testApolloServer<AS extends ApolloServerBase>(
               shouldReadFromCache: (
                 requestContext: GraphQLRequestContext<any>,
               ) => {
-                console.debug(
-                  'shouldReadFromCache',
-                  requestContext.request.query,
-                );
                 if (
                   requestContext.request.http!.headers.get('no-read-from-cache')
                 )
@@ -2674,6 +2678,7 @@ export function testApolloServer<AS extends ApolloServerBase>(
         await createApolloServer({
           gateway,
           apollo: { key: 'service:tester:1234abc', graphVariant: 'staging' },
+          logger: quietLogger,
         });
 
         expect(optionsSpy).toHaveBeenLastCalledWith({

packages/apollo-server-plugin-operation-registry/src/__tests__/ApolloServerPluginOperationRegistry.test.ts

@@ -17,6 +17,7 @@ import {
 } from 'apollo-graphql';
 import gql from 'graphql-tag';
 import { print } from 'graphql';
+import loglevel from 'loglevel';
 import {
   hashApiKey,
   nockStorageSecret,
@@ -41,6 +42,13 @@ const mockHttpRequestContextForExecuteOperation: Required<Pick<
   http: { method: 'GET', headers: new Headers(), url: '/mocked' },
 };
 
+// Hacky way of turning off debug and info logs during tests.
+beforeEach(() => {
+  loglevel
+  .getLogger('apollo-server:apollo-server-plugin-operation-registry')
+  .setLevel(loglevel.levels.WARN);
+});
+
 describe('Operation registry plugin', () => {
   it('will instantiate when not called with options', () => {
     expect(plugin()()).toHaveProperty('serverWillStart');