fix(Client): Do not throw error on bad message

package.json

@@ -52,7 +52,7 @@
     "typescript": "3.6.4"
   },
   "dependencies": {
-    "@stencila/logga": "^1.4.1",
+    "@stencila/logga": "^2.0.0",
     "@stencila/schema": "^0.31.0",
     "@types/ws": "^6.0.3",
     "ajv": "^6.10.2",

src/base/Client.test.ts

@@ -1,7 +1,7 @@
+import { nextLogData } from '../test/nextLogData'
 import { Client } from './Client'
 import { JsonRpcRequest } from './JsonRpcRequest'
 import { JsonRpcResponse } from './JsonRpcResponse'
-
 /**
  * Simple test client that implements the
  * `send` to echo back the
@@ -15,7 +15,12 @@ class TestClient extends Client {
   }
 }
 
-test('client', async () => {
+/**
+ * Test that calls to client methods
+ * get translated into a JSON-RPC request with
+ * `method` and `params`.
+ */
+test('calling methods', async () => {
   const client = new TestClient()
 
   expect(await client.manifest()).toEqual({
@@ -52,3 +57,41 @@ test('client', async () => {
     }
   })
 })
+
+/**
+ * Test that the client logs a message instead of
+ * throwing an error when sent bad responses
+ */
+test('receiving bad response', async () => {
+  const client = new TestClient()
+
+  // Because there is no async tick between the client receiving
+  // the request and generating the log entry, we need to create
+  // the promise for the next message before.
+  const nextMessage = async () => (await nextLogData()).message
+  let message
+
+  message = nextMessage()
+  // @ts-ignore that receive is protected
+  client.receive('Try parsing this as JSON, client!')
+  expect(await message).toMatch(/^Error parsing message as JSON/)
+
+  message = nextMessage()
+  // @ts-ignore that receive is protected
+  client.receive({ id: -1 })
+  expect(await message).toMatch(/^Response is missing id/)
+
+  message = nextMessage()
+  // @ts-ignore that receive is protected
+  client.receive({ id: 489629879 })
+  expect(await message).toMatch(/^No request found for response with id/)
+
+  message = nextMessage()
+  // @ts-ignore that requests is private
+  client.requests[42] = () => {
+    throw Error("Yo! I'm an error")
+  }
+  // @ts-ignore that receive is protected
+  client.receive({ id: 42 })
+  expect(await message).toMatch(/^Error thrown when handling message/)
+})

src/base/Client.ts

@@ -156,11 +156,21 @@ export abstract class Client implements Executor {
    * when a response is returned. Uses the `id` of the response to match it to the corresponding
    * request and resolve it's promise.
    *
+   * Logs errors, rather than throwing exceptions, if the server sends a bad
+   * response because this method is called asynchronously when a message
+   * is received and to avoid crashing the process.
+   *
    * @param message A JSON-RPC response (to a request) or a notification.
    */
   protected receive(message: string | JsonRpcResponse | JsonRpcRequest): void {
-    if (typeof message === 'string')
-      message = JSON.parse(message) as JsonRpcResponse | JsonRpcRequest
+    if (typeof message === 'string') {
+      try {
+        message = JSON.parse(message) as JsonRpcResponse | JsonRpcRequest
+      } catch (error) {
+        log.error(`Error parsing message as JSON: ${message}`)
+        return
+      }
+    }
     const { id } = message
 
     if (id === undefined) {
@@ -171,20 +181,31 @@ export abstract class Client implements Executor {
     }
 
     // Must be a response....
-    message = message as JsonRpcResponse
-    if (id < 0)
+
+    if (id < 0) {
       // A response with accidentally missing id
-      throw new JsonRpcError(
-        JsonRpcErrorCode.InternalError,
-        `Response is missing id: ${message}`
-      )
+      log.error(`Response is missing id: ${JSON.stringify(message)}`)
+      return
+    }
+
     const resolve = this.requests[id]
-    if (resolve === undefined)
-      throw new JsonRpcError(
-        JsonRpcErrorCode.InternalError,
-        `No request found for response with id: ${id}`
-      )
-    resolve(message)
+    if (resolve === undefined) {
+      log.error(`No request found for response with id: ${id}`)
+      return
+    }
+
+    try {
+      resolve(message as JsonRpcResponse)
+    } catch (error) {
+      const { message: errorMessage, stack } = error
+      log.error({
+        message: `Error thrown when handling message: ${errorMessage}\n${JSON.stringify(
+          message
+        )}`,
+        stack
+      })
+    }
+
     delete this.requests[id]
   }
 

src/cli.ts

@@ -30,7 +30,7 @@ const log = getLogger('executa:cli')
 
 replaceHandlers(data =>
   defaultHandler(data, {
-    level: options.debug !== undefined ? LogLevel.debug : LogLevel.info
+    maxLevel: options.debug !== undefined ? LogLevel.debug : LogLevel.info
   })
 )
 

src/console.ts

@@ -48,7 +48,7 @@ replaceHandlers(data => {
   const { level } = data
   if (level <= (options.debug !== undefined ? LogLevel.debug : LogLevel.warn)) {
     process.stderr.write(`--- `)
-    defaultHandler(data, { level: LogLevel.debug })
+    defaultHandler(data, { maxLevel: LogLevel.debug })
   }
 })
 

src/stdio/StdioClientServer.test.ts

@@ -1,16 +1,63 @@
 import path from 'path'
 import { StdioClient } from './StdioClient'
 import { testClient } from '../test/testClient'
+import { nextLogData } from '../test/nextLogData'
 
+// Some of these tests take time to run
+// due to spawning a ts-node process, so
+// increase timeout to avoid this:
+// https://travis-ci.org/stencila/executa/jobs/614741283#L381
 jest.setTimeout(30 * 1000)
 
 describe('StdioClient and StdioServer', () => {
   const testServer = (arg = ''): string =>
     `npx ts-node --files ${path.join(__dirname, 'stdioTestServer.ts')} ${arg}`
 
-  test('all-is-ok', async () => {
+  const nextMessage = async () =>
+    (await nextLogData(['executa:client', 'executa:stdio:client'])).message
+
+  test('main', async () => {
     const client = new StdioClient(testServer())
     await testClient(client)
+
+    // Do not await the next two calls to `decode` - they do not
+    // resolve due to the bad message
+
+    client.decode('send bad message').catch(error => {
+      throw error
+    })
+    expect(await nextMessage()).toMatch(
+      /^Error parsing message as JSON: ah hah/
+    )
+
+    client.decode('crash now!').catch(error => {
+      throw error
+    })
+    expect(await nextMessage()).toMatch(
+      /^Server exited prematurely with exit code 1 and signal null/
+    )
+
     await client.stop()
   })
+
+  // These tests add ~5s to test run time (involve starting more ts-node processes)
+  // and are somewhat redundant given last 'crash now' test above.
+  // So to keep test run times low during development they are only run on CI.
+  if (process.env.CI !== undefined) {
+    test('crash-on-start', async () => {
+      const client = new StdioClient(testServer('crash-on-start'))
+      expect(await nextMessage()).toMatch(
+        /^Server exited prematurely with exit code 1 and signal null/
+      )
+      await client.stop()
+    })
+
+    test('exit-prematurely', async () => {
+      const client = new StdioClient(testServer('exit-prematurely'))
+      expect(await nextMessage()).toMatch(
+        /^Server exited prematurely with exit code 0 and signal null/
+      )
+      await client.stop()
+    })
+  }
 })

src/stdio/stdioTestServer.ts

@@ -1,30 +1,42 @@
 /**
  * Used as a test server by `StdioClientServer.test.ts`
  *
- * Call with one of these args to simulate various errors:
+ * Run with one of these args to simulate various errors:
  *
  * - `crash-on-start`
  * - `exit-prematurely`
- * - `crash-on-request`
+ *
+ * Or call the decode method e.g.
+ *
+ * - `client.decode('crash now!')`
  */
 
 import { StdioServer } from './StdioServer'
+import { BaseExecutor } from '../base/BaseExecutor'
+import { Node } from '@stencila/schema'
+
+class TestExecutor extends BaseExecutor {
+  decode(content: string): Promise<Node> {
+    if (content === 'send bad message') {
+      process.stdout.write('Hah hah, a bad message to try to crash you!')
+      return Promise.resolve('bad message sent')
+    } else if (content === 'crash now!') {
+      setTimeout(() => process.exit(1), 100)
+      return Promise.resolve('crashing soon')
+    } else return super.decode(content)
+  }
+}
 
+const executor = new TestExecutor()
 const server = new StdioServer()
 
 const arg = process.argv[2]
 if (arg === 'crash-on-start') {
   process.exit(1)
 } else if (arg === 'exit-prematurely') {
   setTimeout(() => process.exit(0), 500)
-} else if (arg === 'crash-on-request') {
-  // Mess with the server's executor so that when a request comes in it fails.
-  // @ts-ignore that executor is private
-  server.executor = {
-    decode: () => process.exit(1)
-  }
 }
 
-server.run().catch(error => {
+server.start(executor).catch(error => {
   throw error
 })

src/test/nextLogData.ts

@@ -0,0 +1,19 @@
+import { addHandler, LogData, removeHandler } from '@stencila/logga'
+
+/**
+ * Get a promise that resolves to the next log data that
+ * matches the supplied tags.
+ *
+ * @param tags A list of tags that the log data must have
+ */
+export const nextLogData = (tags?: string[]): Promise<LogData> => {
+  return new Promise(resolve => {
+    const handler = addHandler(
+      (logData: LogData) => {
+        resolve(logData)
+        removeHandler(handler)
+      },
+      { tags }
+    )
+  })
+}