fix(serve): fix server listening logs (#9894)

Right now logs from `yarn rw serve` are a bit deceiving. `yarn rw serve` sets `NODE_ENV` to `'production'` if it's not already set. This changes the host the server ends up listening on: https://github.com/redwoodjs/redwood/blob/97296d4c57e6dffb4eee2489397a3486d11e24fd/packages/cli/src/commands/serve.js#L195-L198 https://github.com/redwoodjs/redwood/blob/97296d4c57e6dffb4eee2489397a3486d11e24fd/packages/cli/src/commands/serveBothHandler.js#L125-L128 Basically, if a user doesn't set `NODE_ENV`, `yarn rw serve` serves everything at `'0.0.0.0'`. But we've hardcoded `'localhost'` in our logs: https://github.com/redwoodjs/redwood/blob/97296d4c57e6dffb4eee2489397a3486d11e24fd/packages/cli/src/commands/serveBothHandler.js#L136-L141 At first it doesn't appear wrong if you go to http://localhost:8910. It's there. But that's only because `'0.0.0.0'` means listen on all ipv4 addresses. This may seem like a small change but it's a bug if your server is listening on localhost in Docker and on deploy providers. When you look at the serve logs in a container, this is giving the impression that something is misconfigured when everything is actually fine. Instead let's just use the return from `fastify.listen` or `fastify.listeningOrigin` which tell us where it's listening. #### Before <img width="600" alt="image" src="https://github.com/redwoodjs/redwood/assets/32992335/87013982-02c8-4f1f-beae-acc6f95a3a87"> #### After <img width="600" alt="image" src="https://github.com/redwoodjs/redwood/assets/32992335/1df0d7c0-f02a-43d7-be80-9de1b522288e"> --------- Co-authored-by: Tobbe Lundberg <[email protected]>
orgtoar · Jan 28, 2024 · 27353fe · 27353fe
1 parent 965132e
commit 27353fe
Show file tree

Hide file tree

Showing 11 changed files with 86 additions and 78 deletions.
diff --git a/packages/api-server/src/__tests__/createServer.test.ts b/packages/api-server/src/__tests__/createServer.test.ts
@@ -119,7 +119,9 @@ describe('createServer', () => {
 
     const lastCallIndex = consoleLogSpy.mock.calls.length - 1
 
-    expect(consoleLogSpy.mock.calls[lastCallIndex][0]).toMatch(/Listening on/)
+    expect(consoleLogSpy.mock.calls[lastCallIndex][0]).toMatch(
+      /Server listening at/
+    )
 
     // `console.warn` will be used if there's a `server.config.js` file.
     expect(consoleWarnSpy.mock.calls[0][0]).toMatchInlineSnapshot(`

diff --git a/packages/api-server/src/cliHandlers.ts b/packages/api-server/src/cliHandlers.ts
@@ -43,60 +43,67 @@ export const apiCliOptions = {
 export const apiServerHandler = async (options: ApiServerArgs) => {
   const { port, socket, apiRootPath } = options
   const tsApiServer = Date.now()
-  process.stdout.write(c.dim(c.italic('Starting API Server...\n')))
+  console.log(c.dim.italic('Starting API Server...'))
 
   let fastify = createFastifyInstance()
 
   // Import Server Functions.
   fastify = await withFunctions(fastify, options)
 
-  const http = startFastifyServer({
-    port,
-    socket,
-    fastify,
-  }).ready(() => {
-    console.log(c.italic(c.dim('Took ' + (Date.now() - tsApiServer) + ' ms')))
-
-    const on = socket
-      ? socket
-      : c.magenta(`http://localhost:${port}${apiRootPath}`)
-    console.log(`API listening on ${on}`)
-    const graphqlEnd = c.magenta(`${apiRootPath}graphql`)
-    console.log(`GraphQL endpoint at ${graphqlEnd}`)
+  fastify = await startFastifyServer({ port, socket, fastify })
+
+  fastify.ready(() => {
+    console.log(c.dim.italic('Took ' + (Date.now() - tsApiServer) + ' ms'))
+
+    // In the past, in development, we've prioritized showing a friendlier
+    // host than the listen-on-all-ipv6-addresses '[::]'. Here we replace it
+    // with 'localhost' only if 1) we're not in production and 2) it's there.
+    // In production it's important to be transparent.
+    //
+    // We have this logic for `apiServerHandler` because this is the only
+    // handler called by the watch bin (which is called by `yarn rw dev`).
+    let address = fastify.listeningOrigin
+    if (process.env.NODE_ENV !== 'production') {
+      address = address.replace(/http:\/\/\[::\]/, 'http://localhost')
+    }
+
+    const apiServer = c.magenta(`${address}${apiRootPath}`)
+    const graphqlEndpoint = c.magenta(`${apiServer}graphql`)
+
+    console.log(`API server listening at ${apiServer}`)
+    console.log(`GraphQL endpoint at ${graphqlEndpoint}`)
+
     sendProcessReady()
   })
   process.on('exit', () => {
-    http?.close()
+    fastify?.close()
   })
 }
 
 export const bothServerHandler = async (options: BothServerArgs) => {
   const { port, socket } = options
   const tsServer = Date.now()
-  process.stdout.write(c.dim(c.italic('Starting API and Web Servers...\n')))
+  console.log(c.dim.italic('Starting API and Web Servers...'))
   const apiRootPath = coerceRootPath(getConfig().web.apiUrl)
 
   let fastify = createFastifyInstance()
 
   await fastify.register(redwoodFastifyWeb)
   fastify = await withFunctions(fastify, { ...options, apiRootPath })
 
-  startFastifyServer({
-    port,
-    socket,
-    fastify,
-  }).ready(() => {
-    console.log(c.italic(c.dim('Took ' + (Date.now() - tsServer) + ' ms')))
-    const on = socket
-      ? socket
-      : c.magenta(`http://localhost:${port}${apiRootPath}`)
-    const webServer = c.green(`http://localhost:${port}`)
-    const apiServer = c.magenta(`http://localhost:${port}`)
-    console.log(`Web server started on ${webServer}`)
-    console.log(`API serving from ${apiServer}`)
-    console.log(`API listening on ${on}`)
-    const graphqlEnd = c.magenta(`${apiRootPath}graphql`)
-    console.log(`GraphQL endpoint at ${graphqlEnd}`)
+  fastify = await startFastifyServer({ port, socket, fastify })
+
+  fastify.ready(() => {
+    console.log(c.dim.italic('Took ' + (Date.now() - tsServer) + ' ms'))
+
+    const webServer = c.green(fastify.listeningOrigin)
+    const apiServer = c.magenta(`${fastify.listeningOrigin}${apiRootPath}`)
+    const graphqlEndpoint = c.magenta(`${apiServer}graphql`)
+
+    console.log(`Web server listening at ${webServer}`)
+    console.log(`API server listening at ${apiServer}`)
+    console.log(`GraphQL endpoint at ${graphqlEndpoint}`)
+
     sendProcessReady()
   })
 }

diff --git a/packages/api-server/src/createServer.ts b/packages/api-server/src/createServer.ts
@@ -161,20 +161,10 @@ export async function createServer(options: CreateServerOptions = {}) {
     done()
   })
 
-  // Just logging. The conditional here is to appease TS.
-  // `server.server.address()` can return a string, an AddressInfo object, or null.
-  // Note that the logging here ("Listening on...") seems to be duplicated, probably by `@redwoodjs/graphql-server`
   server.addHook('onListen', (done) => {
-    const addressInfo = server.server.address()
-
-    if (!addressInfo || typeof addressInfo === 'string') {
-      done()
-      return
-    }
-
     console.log(
-      `Listening on ${c.magenta(
-        `http://${addressInfo.address}:${addressInfo.port}${apiRootPath}`
+      `Server listening at ${c.magenta(
+        `${server.listeningOrigin}${apiRootPath}`
       )}`
     )
     done()

diff --git a/packages/api-server/src/fastify.ts b/packages/api-server/src/fastify.ts
@@ -47,7 +47,7 @@ export function loadFastifyConfig() {
   }
 
   if (!isServerConfigLoaded) {
-    console.log(`Loading server config from ${serverConfigPath} \n`)
+    console.log(`Loading server config from ${serverConfigPath}`)
     serverConfigFile = { ...require(serverConfigPath) }
     isServerConfigLoaded = true
   }

diff --git a/packages/api-server/src/plugins/lambdaLoader.ts b/packages/api-server/src/plugins/lambdaLoader.ts
@@ -22,7 +22,7 @@ export const LAMBDA_FUNCTIONS: Lambdas = {}
 
 export const setLambdaFunctions = async (foundFunctions: string[]) => {
   const tsImport = Date.now()
-  console.log(c.italic(c.dim('Importing Server Functions... ')))
+  console.log(c.dim.italic('Importing Server Functions... '))
 
   const imports = foundFunctions.map((fnPath) => {
     return new Promise((resolve) => {
@@ -42,15 +42,15 @@ export const setLambdaFunctions = async (foundFunctions: string[]) => {
       // TODO: Use terminal link.
       console.log(
         c.magenta('/' + routeName),
-        c.italic(c.dim(Date.now() - ts + ' ms'))
+        c.dim.italic(Date.now() - ts + ' ms')
       )
       return resolve(true)
     })
   })
 
   Promise.all(imports).then((_results) => {
     console.log(
-      c.italic(c.dim('...Done importing in ' + (Date.now() - tsImport) + ' ms'))
+      c.dim.italic('...Done importing in ' + (Date.now() - tsImport) + ' ms')
     )
   })
 }

diff --git a/packages/api-server/src/server.ts b/packages/api-server/src/server.ts
@@ -6,15 +6,29 @@ export interface HttpServerParams {
   fastify: FastifyInstance
 }
 
-export const startServer = ({
+export const startServer = async ({
   port = 8911,
   socket,
   fastify,
 }: HttpServerParams) => {
   const host = process.env.NODE_ENV === 'production' ? '0.0.0.0' : '::'
   const serverPort = socket ? parseInt(socket) : port
 
-  fastify.listen({ port: serverPort, host })
+  await fastify.listen({
+    port: serverPort,
+    host,
+    listenTextResolver: (address) => {
+      // In the past, in development, we've prioritized showing a friendlier
+      // host than the listen-on-all-ipv6-addresses '[::]'. Here we replace it
+      // with 'localhost' only if 1) we're not in production and 2) it's there.
+      // In production it's important to be transparent.
+      if (process.env.NODE_ENV !== 'production') {
+        address = address.replace(/http:\/\/\[::\]/, 'http://localhost')
+      }
+
+      return `Server listening at ${address}`
+    },
+  })
 
   fastify.ready(() => {
     fastify.log.trace(

diff --git a/packages/api-server/src/watch.ts b/packages/api-server/src/watch.ts
@@ -85,7 +85,7 @@ const buildAndRestart = async ({
     killApiServer()
 
     const buildTs = Date.now()
-    process.stdout.write(c.dim(c.italic('Building... ')))
+    console.log(c.dim.italic('Building...'))
 
     if (clean) {
       await cleanApiBuild()
@@ -96,7 +96,7 @@ const buildAndRestart = async ({
     } else {
       await buildApi()
     }
-    console.log(c.dim(c.italic('Took ' + (Date.now() - buildTs) + ' ms')))
+    console.log(c.dim.italic('Took ' + (Date.now() - buildTs) + ' ms'))
 
     const forkOpts = {
       execArgv: process.execArgv,

diff --git a/packages/cli/src/commands/serveApiHandler.js b/packages/cli/src/commands/serveApiHandler.js
@@ -53,23 +53,22 @@ export const apiServerHandler = async (options) => {
     }
   }
 
-  fastify.listen(listenOptions)
+  const address = await fastify.listen(listenOptions)
 
   fastify.ready(() => {
     fastify.log.trace(
       { custom: { ...fastify.initialConfig } },
       'Fastify server configuration'
     )
     fastify.log.trace(`Registered plugins \n${fastify.printPlugins()}`)
-    console.log(chalk.italic.dim('Took ' + (Date.now() - tsApiServer) + ' ms'))
 
-    const on = socket
-      ? socket
-      : chalk.magenta(`http://localhost:${port}${apiRootPath}`)
+    console.log(chalk.dim.italic('Took ' + (Date.now() - tsApiServer) + ' ms'))
 
-    console.log(`API listening on ${on}`)
-    const graphqlEnd = chalk.magenta(`${apiRootPath}graphql`)
-    console.log(`GraphQL endpoint at ${graphqlEnd}`)
+    const apiServer = chalk.magenta(`${address}${apiRootPath}`)
+    const graphqlEndpoint = chalk.magenta(`${apiServer}graphql`)
+
+    console.log(`API server listening at ${apiServer}`)
+    console.log(`GraphQL endpoint at ${graphqlEndpoint}`)
 
     sendProcessReady()
   })

diff --git a/packages/cli/src/commands/serveBothHandler.js b/packages/cli/src/commands/serveBothHandler.js
@@ -124,22 +124,18 @@ export const bothServerHandler = async (options) => {
     }
   }
 
-  fastify.listen(listenOptions)
+  const address = await fastify.listen(listenOptions)
 
   fastify.ready(() => {
-    console.log(chalk.italic.dim('Took ' + (Date.now() - tsServer) + ' ms'))
-
-    const on = socket
-      ? socket
-      : chalk.magenta(`http://localhost:${port}${apiRootPath}`)
-
-    const webServer = chalk.green(`http://localhost:${port}`)
-    const apiServer = chalk.magenta(`http://localhost:${port}`)
-    console.log(`Web server started on ${webServer}`)
-    console.log(`API serving from ${apiServer}`)
-    console.log(`API listening on ${on}`)
-    const graphqlEnd = chalk.magenta(`${apiRootPath}graphql`)
-    console.log(`GraphQL endpoint at ${graphqlEnd}`)
+    console.log(chalk.dim.italic('Took ' + (Date.now() - tsServer) + ' ms'))
+
+    const webServer = chalk.green(address)
+    const apiServer = chalk.magenta(`${address}${apiRootPath}`)
+    const graphqlEndpoint = chalk.magenta(`${apiServer}graphql`)
+
+    console.log(`Web server listening at ${webServer}`)
+    console.log(`API server listening at ${apiServer}`)
+    console.log(`GraphQL endpoint at ${graphqlEndpoint}`)
 
     sendProcessReady()
   })

diff --git a/packages/fastify/src/config.ts b/packages/fastify/src/config.ts
@@ -68,7 +68,7 @@ export function loadFastifyConfig() {
   }
 
   if (!isServerConfigLoaded) {
-    console.log(`Loading server config from ${serverConfigPath} \n`)
+    console.log(`Loading server config from ${serverConfigPath}`)
     serverConfigFile = { ...require(serverConfigPath) }
     isServerConfigLoaded = true
   }

diff --git a/packages/web-server/src/webServer.ts b/packages/web-server/src/webServer.ts
@@ -11,7 +11,7 @@ import type { ParsedOptions } from './types'
 
 export async function serveWeb(options: ParsedOptions = {}) {
   const start = Date.now()
-  console.log(chalk.italic.dim('Starting Web Server...'))
+  console.log(chalk.dim.italic('Starting Web Server...'))
 
   const distIndexExists = await fs.pathExists(
     path.join(getPaths().web.dist, 'index.html')
@@ -49,5 +49,5 @@ export async function serveWeb(options: ParsedOptions = {}) {
   })
 
   console.log(chalk.italic.dim('Took ' + (Date.now() - start) + ' ms'))
-  console.log(`Server listening at ${chalk.green(address)}`)
+  console.log(`Web server listening at ${chalk.green(address)}`)
 }