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

[thedavidprice]

Originally posted by @esteban-url in https://github.com/redwoodjs/redwood/issues/2120#issuecomment-808518699

⚠️ 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

```sh $ 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. (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:510:13) api | at Generator.next () api | at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71 api | at new Promise () 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. (/Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/src/ApolloServer.ts:594:12) api | at Generator.next () api | at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71 api | at new Promise () 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

```sh $ 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

```sh $ 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. (/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 () api esbuild | at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71 api esbuild | at new Promise () 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. (/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 () api esbuild | at /Users/esteban/files/my-redwood-app/node_modules/apollo-server-core/dist/ApolloServer.js:8:71 api esbuild | at new Promise () 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 (https://github.com/apollographql/apollo-server/issues/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