Runtime.UnhandledPromiseRejection, Error: called start() with surprising state invoking serverWillStart

[dep]

This is a very strange behavior indeed. We just started seeing this in our GQL stack this morning. I've reset out development environment to our stable branch to ensure that this is not related to a recent code change we have made, but the problem persists. I have been unable to find the source of this issue, and has left me quite befuddled.

{
    "errorType": "Runtime.UnhandledPromiseRejection",
    "errorMessage": "Error: called start() with surprising state invoking serverWillStart",
    "reason": {
        "errorType": "Error",
        "errorMessage": "called start() with surprising state invoking serverWillStart",
        "stack": [
            "Error: called start() with surprising state invoking serverWillStart",
            "    at ApolloServer.<anonymous> (/var/task/node_modules/apollo-server-core/dist/ApolloServer.js:230:23)",
            "    at Generator.next (<anonymous>)",
            "    at /var/task/node_modules/apollo-server-core/dist/ApolloServer.js:8:71",
            "    at new Promise (<anonymous>)",
            "    at __awaiter (/var/task/node_modules/apollo-server-core/dist/ApolloServer.js:4:12)",
            "    at ApolloServer._start (/var/task/node_modules/apollo-server-core/dist/ApolloServer.js:226:16)",
            "    at ApolloServer.<anonymous> (/var/task/node_modules/apollo-server-core/dist/ApolloServer.js:280:22)",
            "    at Generator.next (<anonymous>)",
            "    at /var/task/node_modules/apollo-server-core/dist/ApolloServer.js:8:71",
            "    at new Promise (<anonymous>)"
        ]
    },
    "promise": {},
    "stack": [
        "Runtime.UnhandledPromiseRejection: Error: called start() with surprising state invoking serverWillStart",
        "    at process.on (/var/runtime/index.js:37:15)",
        "    at process.emit (events.js:203:15)",
        "    at process.EventEmitter.emit (domain.js:448:20)",
        "    at emitPromiseRejectionWarnings (internal/process/promises.js:140:18)",
        "    at process._tickCallback (internal/process/next_tick.js:69:34)"
    ]
}

[glasser]

I assume you've upgraded to the newly release v2.22.0, which changes how startup works?

Can you share what your code that sets up your ApolloServer looks like, including:

• Exactly which package you're importing ApolloServer from
• What exact version of each package starting with apollo-server you're using?

[glasser]

For debugging:

• This means _start got called with state serverWillStart
• This could be from an explicit start call but that's unlikely since that requires the user to change their own code
• The calls in ensureStarting and ensureStarted shouldn't happen from that state
• It could be from the listen call if we're using apollo-server, though it's unclear what would cause start to begin before you call listen
• It could be from a willStart call though they don't exist any more

One concern would be that this is a bug I've introduced that shows up if you are using v2.22 of apollo-server-core along with older versions of, say, apollo-server or apollo-server-express. I may not have thought carefully enough about those interactions. If that's the case, the easy fix should be to upgrade those packages too, though I should try to make sure that this problem doesn't occur.

The reason this is an UnhandledPromiseRejection is likely that you are calling an async function (like server.listen() if you're using apollo-server) without awaiting it or using .catch (which I've unfortunately realized recently is what our docs encourage).

[glasser]

(If your deployment doesn't involve checking in a package-lock.json then it's quite likely that you'll end up installing the latest version of transitive dependencies like apollo-server-core even if your direct dependencies haven't changed.)

[dep]

Thanks for the replies. I did an update of apollo-server from 2.21.0 to 2.22.1 and this seems to have fixed it! 👍🏻 I'll definitely look in to using package-lock.json in the future, too.

[glasser]

Can you share what your code looks like? I'm still not positive I understand how the issue occurred.

[glasser]

I believe that apollo-server-core v2.22.2 is now more fully compatible with pre-v2.22 versions of integrations packages like apollo-server, apollo-server-lambda (especially), apollo-server-express, etc.

[dep]

@glasser

Can you share what your code looks like? I'm still not positive I understand how the issue occurred.

I can try to share the relevant bits:

package.json:

{
  "name": "foobar",
  "main": "graphql.js",
  "license": "ISC",
  "directories": {
    "test": "src"
  },
  "devDependencies": {
    "@cloudvox/eslint-config": "13.1.10",
    "@cloudvox/mocha-config": "13.4.9",
    "chai": "4.3.0",
    "depcheck": "1.4.0",
    "enzyme": "3.11.0",
    "enzyme-adapter-react-16": "1.15.5",
    "eslint": "7.21.0",
    "eslint-config-airbnb": "18.2.0",
    "eslint-import-resolver-typescript": "2.3.0",
    "eslint-plugin-import": "2.22.1",
    "eslint-plugin-jsx-a11y": "6.4.1",
    "eslint-plugin-mocha": "8.0.0",
    "eslint-plugin-mocha-no-only": "1.1.1",
    "eslint-plugin-react": "7.20.6",
    "jsdom": "16.4.0",
    "mocha": "8.2.1",
    "react": "16.14.0",
    "react-dom": "16.13.1",
    "sinon": "9.2.1",
    "sinon-chai": "3.5.0",
    "source-map-support": "0.5.19",
    "ts-node": "9.0.0",
    "typescript": "4.2.2"
  },
  "dependencies": {
    "apollo-datasource": "0.7.2",
    "apollo-datasource-rest": "0.9.7",
    "apollo-server": "2.21.0",
    "apollo-server-lambda": "2.21.0",
    "apollo-server-testing": "2.19.0",
    "aws-sdk": "2.787.0",
    "bcryptjs": "2.4.3",
    "casual-browserify": "1.5.19",
    "graphql": "15.5.0",
    "graphql-parse-resolve-info": "4.11.0",
    "graphql-tag": "2.11.0",
    "graphql-tools": "7.0.4",
    "ioredis": "^4.17.3",
    "lodash": "4.17.21",
    "middy": "0.36.0",
    "mysql2": "2.2.5",
    "rollbar": "2.21.0",
    "sequelize": "6.5.0"
  }
}

graphql.js (aka., our Lambda function, and apologies for the stuff you don't care about)

const { ApolloServer } = require('apollo-server-lambda');
const Rollbar = require('rollbar');
const middy = require('middy');
const { cors } = require('middy/middlewares');
const { get } = require('./utils/redis.account');
const { verifiedAccessKeys } = require('./utils/verify.access.keys');
const { loadAccountAccessData } = require('./utils/accountAccess.helpers');
const { schema } = require('./schema');
const { createStore } = require('./datasources');
const { fixtures } = require('./fixtures/fixtures');
/** Domains */
const { AccountInformation } = require('./domains/accountInformation');
const { AudioFiles } = require('./domains/audioFiles');
const { AvailableNumbers } = require('./domains/availableNumbers');
const { Billing } = require('./domains/billing');
const { BroadcastGroups } = require('./domains/broadcastGroups');
const { CallDistributors } = require('./domains/callDistributors');
const { CallFlowSets } = require('./domains/callFlows');
const { Clicks } = require('./domains/clicks');
const { FindMe } = require('./domains/findMe');
const { IVR } = require('./domains/ivr');
const { LeadFlow } = require('./domains/leadFlow');
const { Locations } = require('./domains/locations');
const { PhoneDirectories } = require('./domains/phoneDirectories');
const { PhoneNumbers } = require('./domains/phoneNumbers');
const { PostCallActions } = require('./domains/postCallActions');
const { PreCallActions } = require('./domains/preCallActions');
const { RegisteredNumbers } = require('./domains/registeredNumbers');
const { ReportingGroups } = require('./domains/reportingGroups');
const { Routes } = require('./domains/routes');
const { Schedules } = require('./domains/schedules');
const { ScheduleRouters } = require('./domains/scheduleRouters');
const { StoreLocators } = require('./domains/storeLocators');
const { Survos } = require('./domains/survos');
const { Tags } = require('./domains/tags');
const { UserProfile } = require('./domains/userProfile');
const { VirtualReceptionists } = require('./domains/virtualReceptionists');
const { VoicemailGreetings } = require('./domains/voicemailGreetings');

const rollbar = new Rollbar({
    accessToken: process.env.ROLLBAR_TOKEN,
    captureUncaught: true,
    captureUnhandledRejections: true,
});

const getHashedCookie = cookie => cookie.split('AUTHTOKEN=')[1];

// eslint-disable-next-line require-await
const createHandler = async () => {
    const store = await createStore();

    // Set up data sources (Organic, database)
    const dataSources = () => ({
        accountInformationDB: new AccountInformation.Database({ store }),
        audioFilesAPI: new AudioFiles.API(),
        availableNumbersAPI: new AvailableNumbers.API(),
        billingDB: new Billing.Database({ store }),
        broadcastGroupsDB: new BroadcastGroups.Database({ store }),
        callFlowsDB: new CallFlowSets.Database({ store }),
        callDistributorsDB: new CallDistributors.Database({ store }),
        clicksDB: new Clicks.Database({ store }),
        findMeDB: new FindMe.Database({ store }),
        ivrDB: new IVR.Database({ store }),
        leadFlowDB: new LeadFlow.Database({ store }),
        locationsDB: new Locations.Database({ store }),
        phoneDirectoriesDB: new PhoneDirectories.Database({ store }),
        phoneNumbersAPI: new PhoneNumbers.API(),
        phoneNumbersCRBN: new PhoneNumbers.CRBN(),
        phoneNumbersDB: new PhoneNumbers.Database({ store }),
        postCallActionsDB: new PostCallActions.Database({ store }),
        preCallActionsDB: new PreCallActions.Database({ store }),
        registeredNumbersAPI: new RegisteredNumbers.API(),
        registeredNumbersDB: new RegisteredNumbers.Database({ store }),
        reportingGroupsDB: new ReportingGroups.Database({ store }),
        routesAPI: new Routes.API(),
        routesDB: new Routes.Database({ store }),
        scheduleRoutersDB: new ScheduleRouters.Database({ store }),
        schedulesDB: new Schedules.Database({ store }),
        storeLocatorsDB: new StoreLocators.Database({ store }),
        survosDB: new Survos.Database({ store }),
        tagsDB: new Tags.Database({ store }),
        userProfileDB: new UserProfile.Database({ store }),
        virtualReceptionistsDB: new VirtualReceptionists.Database({ store }),
        voicemailGreetingsDB: new VoicemailGreetings.Database({ store }),
    });

    const server = new ApolloServer({
        schema,
        mocks: process.env.NODE_ENV === 'local' && fixtures, // Comment out to use localhost datasources
        dataSources,
        context: async req => {
            const COOKIE =
                req.event.headers.Cookie ||
                req.event.headers['X-Cookie'] ||
                req.event.headers['x-cookie'];

            const API_KEYS =
                (req.event.headers['X-Access-Key'] && req.event.headers['X-Secret-Key']) ||
                (req.event.headers['x-access-key'] && req.event.headers['x-secret-key']);

            /* GQL can be authenticated by either a cookie or with API keys */
            if (req.event.headers && (COOKIE || API_KEYS)) {
                /* If a cookie is on the request header, we authenticate using
                 * the cookie and the redis cache. Otherwise, we
                 * authenticate using an access/secret key pair */
                const userDataItems = COOKIE ? await get(
                    `Redis_PHPSESSIONS_${getHashedCookie(COOKIE)}`,
                ) : await verifiedAccessKeys(req);

                if (userDataItems === null) {
                    throw Error('Session Authentication could not be found.');
                }

                /* Currently COOKIE users get more information off the Redis cache.
                 * Will be reconciled with:
                 * https://dialogtech.atlassian.net/browse/ATLAS-1715 */
                if (COOKIE) {
                    const { accountAccessIds, subAccountAccessIds } = await loadAccountAccessData(userDataItems, store);

                    return {
                        accessLevelId: userDataItems.accessLevelId,
                        accountAccessIds,
                        accountId: userDataItems.accountId,
                        cookie: COOKIE,
                        csrId: userDataItems.csrId,
                        event: req.event,
                        packageId: userDataItems.packageId,
                        subAccountAccessIds,
                        userId: userDataItems.userId,
                    };
                }

                return {
                    event: req.event,
                    accountId: userDataItems.accountId,
                    access_key: userDataItems.accessKey,
                    secret_key: userDataItems.secretKey,
                };
            }

            /* If nothing is passed, and we're on localhost,
             * just set the DT Developer ID for convenience */
            if (process.env.NODE_ENV === 'local') {
                return {
                    req,
                    userId: 1,
                    accountId: 1,
                };
            }

            throw Error('GraphQL Authentication Failed');
        },
        formatError: error => {
            if (process.env.NODE_ENV !== 'local') {
                rollbar.log(
                    `[GraphQL.error (${process.env.NODE_ENV})] ${error.message}`,
                    error,
                );
            }

            return error;
        },
        playground: (process.env.NODE_ENV !== 'prod') ? {
            settings: {
                'schema.polling.enable': false,
            },
        } : false,
    });

    return Promise.resolve(server.createHandler());
};

exports.graphqlHandler = middy((event, context, callback) => {
    // eslint-disable-next-line no-param-reassign
    context.callbackWaitsForEmptyEventLoop = false;
    createHandler().then(handler => handler(event, context, callback));
}).use(cors());

[glasser]

@dep-dt Ah, you didn't mention in the first message that you're using Lambda. Yeah, combining apollo-server-core v2.22.0 or v2.22.1 with older apollo-server-lambda was definitely 100% unusable. v2.22.2 should fix this (as should upgrading apollo-server-lambda).

[dep]

Thanks! Apologies for omitting that (very important) detail originally. Appreciate the help

[statusunknown418]

Hi also got this problem using apollo-server-micro insider a nextjs fullstack app, I solved it by just storing the server.start() function in a constant like this const startServer = server.start() and then using it inside the default export of the cors function

[glasser]

@AlvaroAquijeDiaz I have an open PR to upgrade the nextjs examples to use Apollo Server 3 (using apollo-server-express instead of the less featureful apollo-server-micro); they have not merged it yet for some reason. vercel/next.js#30082

[statusunknown418]

@glasser I think that may be because apollo-server-express doesn't have the createHandler method, that's needed for serverless and nextjs stuff I guess.