[patch] v0.28 rw dev results in API Apollo Server Node "Error: called start() with surprising state"

[thedavidprice]

Originally posted by @esteban-url in #2120 (comment)

⚠️ This is a PATCH candidate for v0.28

---

I'm running into the problem when spinning up a brand new app

$ yarn create redwood-app my-redwood-app <- looks good
$ cd my-redwood-app
$ yarn redwood dev <- 💣

api | /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:230
api |                 throw new Error(`called start() with surprising state ${initialState.phase}`);
api |                       ^
api |
api | Error: called start() with surprising state invoking serverWillStart

complete output

$ yarn redwood dev
yarn run v1.22.10
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/redwood dev
  ✔ Generating the Prisma client...
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/cross-env NODE_ENV=development yarn dev-server
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/webpack-dev-server --config ../node_modules/@redwoodjs/core/config/webpack.development.js
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/dev-server
api | Running at 'http://localhost:8911'
api | Watching files in '/Users/esteban/files/my-redwood-app/api/src/functions'
web | ℹ ｢wds｣: Project is running at http://localhost:8910/
web | ℹ ｢wds｣: webpack output is served from /
web | ℹ ｢wds｣: Content not from webpack is served from /Users/esteban/files/my-redwood-app/web
web | ℹ ｢wds｣: 404s will fallback to /index.html
api | Done. Took 2609ms.
api | /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:230
api |                 throw new Error(`called start() with surprising state ${initialState.phase}`);
api |                       ^
api |
api | Error: called start() with surprising state invoking serverWillStart
api |     at ApolloServer.<anonymous> (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:510:13)
api |     at Generator.next (<anonymous>)
api |     at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api |     at new Promise (<anonymous>)
api |     at __awaiter (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:4:12)
api |     at ApolloServer._start (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:226:16)
api |     at ApolloServer.<anonymous> (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:594:12)
api |     at Generator.next (<anonymous>)
api |     at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api |     at new Promise (<anonymous>)
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
api | cd "/Users/esteban/files/my-redwood-app/api" && yarn cross-env NODE_ENV=development yarn dev-server exited with code 1
^C
web | cd "/Users/esteban/files/my-redwood-app/web" && yarn webpack-dev-server --config ../node_modules/@redwoodjs/core/config/webpack.development.js  exited with code SIGINT

so I tried the esbuild flag
$ yarn rw dev --esbuild <- again it throws errors

error Command "rw-api-server-watch" not found.

complete output

$ yarn rw dev --esbuild
yarn run v1.22.10
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/rw dev --esbuild
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/cross-env ESBUILD=1
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/cross-env NODE_ENV=development NODE_OPTIONS=--enable-source-maps yarn rw-api-server-watch
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/webpack-dev-server --config ../node_modules/@redwoodjs/core/config/webpack.development.js
error Command "rw-api-server-watch" not found.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
api esbuild | yarn cross-env NODE_ENV=development NODE_OPTIONS=--enable-source-maps yarn rw-api-server-watch exited with code 1
web esbuild | ℹ ｢wds｣: Project is running at http://localhost:8910/
web esbuild | ℹ ｢wds｣: webpack output is served from /
web esbuild | ℹ ｢wds｣: Content not from webpack is served from /Users/esteban/files/my-redwood-app/web
web esbuild | ℹ ｢wds｣: 404s will fallback to /index.html
error Command failed with signal "SIGKILL".
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
web esbuild | yarn cross-env ESBUILD=1 && cd "/Users/esteban/files/my-redwood-app/web" && yarn webpack-dev-server --config ../node_modules/@redwoodjs/core/config/webpack.development.js  exited with code 1
✨  Done in 116.16s.

so then i added as @peterp suggested
$ yarn workspace api add @redwoodjs/api-server <- bunch of warning but otherwise it looks good

except it still errors out when running dev
yarn rw dev --esbuild

api esbuild | /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:510
api esbuild |       throw new Error(
api esbuild |             ^
api esbuild |
api esbuild | Error: called start() with surprising state invoking serverWillStart

complete output

$ yarn rw dev --esbuild
yarn run v1.22.10
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/rw dev --esbuild
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/cross-env NODE_ENV=development NODE_OPTIONS=--enable-source-maps yarn rw-api-server-watch
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/cross-env ESBUILD=1
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/webpack-dev-server --config ../node_modules/@redwoodjs/core/config/webpack.development.js
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/rw-api-server-watch
api esbuild | Building API...
api esbuild | Built in 118 ms
api esbuild | Importing API...
api esbuild | Imported in 718 ms
api esbuild | Listening on http://localhost:8911
api esbuild |
api esbuild | /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:510
api esbuild |       throw new Error(
api esbuild |             ^
api esbuild |
api esbuild | Error: called start() with surprising state invoking serverWillStart
api esbuild |     at ApolloServer.<anonymous> (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:230:23)
api esbuild |         -> /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:510:13
api esbuild |     at Generator.next (<anonymous>)
api esbuild |     at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api esbuild |     at new Promise (<anonymous>)
api esbuild |     at __awaiter (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:4:12)
api esbuild |     at ApolloServer._start (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:226:16)
api esbuild |         -> /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:504:25
api esbuild |     at ApolloServer.<anonymous> (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:280:22)
api esbuild |         -> /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:594:12
api esbuild |     at Generator.next (<anonymous>)
api esbuild |     at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api esbuild |     at new Promise (<anonymous>)
web esbuild | ℹ ｢wds｣: Project is running at http://localhost:8910/
web esbuild | ℹ ｢wds｣: webpack output is served from /
web esbuild | ℹ ｢wds｣: Content not from webpack is served from /Users/esteban/files/my-redwood-app/web
web esbuild | ℹ ｢wds｣: 404s will fallback to /index.html

hope this helps ☺️

[thedavidprice]

Confirming I have reproduced this locally. However, I am only receiving a WARNING. My guess is that this is a Node.js <> Apollo Server version issue. I'm currently on Node: 14.15.4. My guess is that @esteban-url is on Node 15.

Possible fix --> upgrading Apollo Server package version in @redwoodjs/api

We didn't see this in CI because we run against Node.js v14 and it's a Warning, not an error.

api | (node:88398) UnhandledPromiseRejectionWarning: Error: called start() with surprising state invoking serverWillStart
api |     at ApolloServer.<anonymous> (/Users/price/Repos/xx-delete/node_modules/apollo-server-core/src/ApolloServer.ts:510:13)
api |     at Generator.next (<anonymous>)
api |     at /Users/price/Repos/xx-delete/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api |     at new Promise (<anonymous>)
api |     at __awaiter (/Users/price/Repos/xx-delete/node_modules/apollo-server-core/dist/ApolloServer.js:4:12)
api |     at ApolloServer._start (/Users/price/Repos/xx-delete/node_modules/apollo-server-core/dist/ApolloServer.js:226:16)
api |     at ApolloServer.<anonymous> (/Users/price/Repos/xx-delete/node_modules/apollo-server-core/src/ApolloServer.ts:594:12)
api |     at Generator.next (<anonymous>)
api |     at /Users/price/Repos/xx-delete/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api |     at new Promise (<anonymous>)
api | (Use `node --trace-warnings ...` to show where the warning was created)
api | (node:88398) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
api | (node:88398) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
^C
api |

[thedavidprice]

Upgrading to apollo-server-lambda@2.22.1 did not resolve. But we should do this as well.

[Tobbe]

$ yarn rw info
yarn run v1.22.4
$ C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\.bin\rw info

  System:
    OS: Windows 10 10.0.19041
  Binaries:
    Node: 15.4.0 - ~\AppData\Local\Temp\yarn--1616809200213-0.921961881187467\node.CMD
    Yarn: 1.22.4 - ~\AppData\Local\Temp\yarn--1616809200213-0.921961881187467\yarn.CMD
  Browsers:
    Chrome: 89.0.4389.90
    Edge: Spartan (44.19041.423.0), Chromium (89.0.774.63)
  npmPackages:
    @redwoodjs/core: ^0.28.0 => 0.28.0

$ yarn rw dev
yarn run v1.22.4
$ C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\.bin\rw dev
  √ Generating the Prisma client...
$ C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\.bin\cross-env NODE_ENV=development yarn dev-server
$ C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\.bin\webpack-dev-server --config ../node_modules/@redwoodjs/core/config/webpack.development.js
$ C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\.bin\dev-server
api | Running at 'http://localhost:8911'
api | Watching files in 'C:\Users\tobbe\dev\redwood\my-redwood-app\api\src\functions'
web | i ｢wds｣: Project is running at http://localhost:8910/
web | i ｢wds｣: webpack output is served from /
web | i ｢wds｣: Content not from webpack is served from C:\Users\tobbe\dev\redwood\my-redwood-app\web
web | i ｢wds｣: 404s will fallback to /index.html
api | Done. Took 7192ms.
api | C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\apollo-server-core\dist\ApolloServer.js:230
api |                 throw new Error(`called start() with surprising state ${initialState.phase}`);
api |                       ^
api |
api | Error: called start() with surprising state invoking serverWillStart
api |     at ApolloServer.<anonymous> (C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\apollo-server-core\src\ApolloServer.ts:510:13)
api |     at Generator.next (<anonymous>)
api |     at C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\apollo-server-core\dist\ApolloServer.js:8:71
api |     at new Promise (<anonymous>)
api |     at __awaiter (C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\apollo-server-core\dist\ApolloServer.js:4:12)
api |     at ApolloServer._start (C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\apollo-server-core\dist\ApolloServer.js:226:16)
api |     at ApolloServer.<anonymous> (C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\apollo-server-core\src\ApolloServer.ts:594:12)
api |     at Generator.next (<anonymous>)
api |     at C:\Users\tobbe\dev\redwood\my-redwood-app\node_modules\apollo-server-core\dist\ApolloServer.js:8:71
api |     at new Promise (<anonymous>)
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
error Command failed with exit code 1.
api | cd "C:\Users\tobbe\dev\redwood\my-redwood-app\api" && yarn cross-env NODE_ENV=development yarn dev-server exited with code 1

This was with a brand new app.

It still works, as in it launches to this page in my web browser

But maybe if I had an actual graphql api things wouldn't go so well...

[NickR49]

  System:
    OS: Linux 5.4 Ubuntu 20.04.2 LTS (Focal Fossa)
    Shell: 5.0.17 - /bin/bash
  Binaries:
    Node: 14.16.0 - /tmp/yarn--1616811987873-0.7720234792724772/node
    Yarn: 1.22.10 - /tmp/yarn--1616811987873-0.7720234792724772/yarn
  Browsers:
    Chrome: 89.0.4389.90
    Firefox: 87.0
  npmPackages:
    @redwoodjs/core: ^0.28.0 => 0.28.0 

I've done the tutorial. The app runs fine locally but the deployed app fails with GraphQL calls - a 502 response.
I see this in the GraphQL function (via Netlify) -

2:07:18 PM: 2021-03-27T01:07:18.755Z	undefined	ERROR	Unhandled Promise Rejection 	{"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/src/node_modules/apollo-server-core/dist/ApolloServer.js:230:23)","    at Generator.next (<anonymous>)","    at /var/task/src/node_modules/apollo-server-core/dist/ApolloServer.js:8:71","    at new Promise (<anonymous>)","    at __awaiter (/var/task/src/node_modules/apollo-server-core/dist/ApolloServer.js:4:12)","    at ApolloServer._start (/var/task/src/node_modules/apollo-server-core/dist/ApolloServer.js:226:16)","    at ApolloServer.<anonymous> (/var/task/src/node_modules/apollo-server-core/dist/ApolloServer.js:280:22)","    at Generator.next (<anonymous>)","    at /var/task/src/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.<anonymous> (/var/runtime/index.js:35:15)","    at process.emit (events.js:314:20)","    at processPromiseRejections (internal/process/promises.js:209:33)","    at processTicksAndRejections (internal/process/task_queues.js:98:32)"]}

2:07:18 PM: 2021-03-27T01:07:18.764Z	undefined	INFO	Unexpected Top Level Error: TypeError: Failed to get next!

2:07:18 PM: [ERROR] [1616807238763] LAMBDA_RUNTIME Failed to get next invocation. Http Response code: 403

When running locally I get this is the yarn rw dev logs -

api | (node:361016) UnhandledPromiseRejectionWarning: Error: called start() with surprising state invoking serverWillStart
api |     at ApolloServer.<anonymous> (/home/nick/dev/side/redwood/wordplay-redwood/node_modules/apollo-server-core/src/ApolloServer.ts:510:13)
api |     at Generator.next (<anonymous>)
api |     at /home/nick/dev/side/redwood/wordplay-redwood/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api |     at new Promise (<anonymous>)
api |     at __awaiter (/home/nick/dev/side/redwood/wordplay-redwood/node_modules/apollo-server-core/dist/ApolloServer.js:4:12)
api |     at ApolloServer._start (/home/nick/dev/side/redwood/wordplay-redwood/node_modules/apollo-server-core/dist/ApolloServer.js:226:16)
api |     at ApolloServer.<anonymous> (/home/nick/dev/side/redwood/wordplay-redwood/node_modules/apollo-server-core/src/ApolloServer.ts:594:12)
api |     at Generator.next (<anonymous>)
api |     at /home/nick/dev/side/redwood/wordplay-redwood/node_modules/apollo-server-core/dist/ApolloServer.js:8:71
api |     at new Promise (<anonymous>)

[esteban-url]

here's my the output @thedavidprice

yarn run v1.22.10
$ /Users/esteban/files/my-redwood-app/node_modules/.bin/redwood info

  System:
    OS: macOS 11.2.3
    Shell: 5.8 - /bin/zsh
  Binaries:
    Node: 15.1.0 - /var/folders/2w/rf6n92bn5b55yt05wx0x0htm0000gn/T/yarn--1616821424418-0.5146509066665363/node
    Yarn: 1.22.10 - /var/folders/2w/rf6n92bn5b55yt05wx0x0htm0000gn/T/yarn--1616821424418-0.5146509066665363/yarn
  Databases:
    SQLite: 3.32.3 - /usr/bin/sqlite3
  Browsers:
    Chrome: 89.0.4389.90
    Firefox: 78.0.1
    Safari: 14.0.3
  npmPackages:
    @redwoodjs/core: ^0.28.0 => 0.28.0

✨  Done in 2.80s.

[esteban-url]

@Tobbe yes i can confirm when you try to hit the graphql endpoint it fails too.

this is the error:

web | [HPM] Error occurred while trying to proxy request /graphql from localhost:8910 to http://[::1]:8911 (ECONNREFUSED) (https://nodejs.org/api/errors.html#errors_common_system_errors)

[peterp]

I pinned the apollo-server-core version (using yarn resolutions) to 2.18.2 and the problem went away.

It appears that they attempted to fix a bug in apollo-server-core in the latest release:

v2.22.1
apollo-server-core: Fix a regression in v2.22.0 where startup errors could be thrown as part of the GraphQL response instead of redacted in one edge case. PR #5064

But instead... they ended up breaking things.

[peterp]

I've reported this over here (apollographql/apollo-server#5066), but I think the root cause of why we didn't pick this up is because we do not ship a yarn.lock file anymore:

[peterp]

I'll proceed to add a yarn.lock file to the create-redwood-app template

[glasser]

Upgrading to apollo-server-lambda@2.22.1 did not resolve. But we should do this as well.

@thedavidprice The exact same issue occurs even when all apollo-server* packages are at 2.22.1? I see how I introduced a regression in v2.22 that occurs if you don't upgrade both packages to v2.22 at the same time (which I will work on resolving on Monday) but if you're also seeing the exact same error message with apollo-server-lambda when both packages are on v2.22.1 then the fix I'm imagining might not be sufficient.

[glasser]

@peterp I believe apollo-server-core@2.22.2 should be compatible with the older version of apollo-server-lambda, so you should be able to remove the resolution override now (I don't think npm/yarn will choose to install the broken 2.22.0/2.22.1 versions now that 2.22.2 is out). I also encourage you to upgrade apollo-server-lambda to v2.22.2; let me know if there's some reason that upgrade doesn't work!

[thedavidprice]

Thanks @glasser Peter has been focused on a different issue and it's now late for him.

I'll dig into this now. Agreed about upgrading to v2.22.2 and can take that for a spin.

[thedavidprice]

PR here #2153