feat(logging): enhanced error logging capabilities

CHANGELOG.md

@@ -9,10 +9,15 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Added
 
+- Message interpolation of logged errors, transforming error message placeholders into human-readable text (default locale)
+
 ### Changed
 
 - Moved registration of `cds.compile.to.gql` and `cds.compile.to.graphql` targets from `@sap/cds` to `@cap-js/graphql`
 - Improve merging of custom `graphql` protocol configuration with plugin default configuration
+- Errors representing client errors (`4xx` range) are now logged as warnings instead of errors
+- Exclude the stack trace of the outer logged error message in multiple error scenarios, as the inner stack trace already
+contained the precise initial segment of the outer stack trace.
 
 ### Fixed
 

lib/resolvers/error.js

@@ -1,10 +1,13 @@
 const cds = require('@sap/cds')
+const { i18n } = cds.env
 const LOG_CDS = cds.log()
 const LOG_GRAPHQL = cds.log('graphql')
-const { normalizeError } = require('@sap/cds/libx/_runtime/common/error/frontend')
 const { GraphQLError } = require('graphql')
 const { IS_PRODUCTION } = require('../utils')
 
+// FIXME: importing internal modules from @sap/cds is discouraged and not recommended for external usage
+const { normalizeError, isClientError } = require('@sap/cds/libx/_runtime/common/error/frontend')
+
 const _reorderProperties = error => {
   // 'stack' and 'stacktrace' to cover both common cases that a custom error formatter might return
   let { code, message, details, stack, stacktrace } = error
@@ -31,14 +34,45 @@ const _cdsToGraphQLError = (context, err) => {
 }
 
 const _ensureError = error => (error instanceof Error ? error : new Error(error))
+const _clone = obj => Object.create(Object.getPrototypeOf(obj), Object.getOwnPropertyDescriptors(obj))
 
 const handleCDSError = (context, error) => {
   error = _ensureError(error)
-  // TODO: choose log level depending on type of error analogous to OData adapter
-  if (LOG_CDS._error) LOG_CDS.error(error)
+  _log(error)
   return _cdsToGraphQLError(context, error)
 }
 
+// TODO: Revise this logging functionality, as it's not specific to protocol adapters.
+// This function should be relocated and/or cleaned up when the new abstract/generic
+// protocol adapter is designed and implemented.
+const _log = error => {
+  // log errors and warnings only
+  if (LOG_CDS.level <= cds.log.levels.WARN) return
+
+  // Clone of the original error object to prevent mutation and unintended side-effects.
+  // Notice that the cloned error is logged to standard output in its default language,
+  // whereas the original error message is locale-dependent as it is usually sent in the
+  // HTTP response to HTTP Clients to be displayed in the user interface.
+  let error2log = _clone(error)
+  if (error.details) {
+    error2log.details = error.details.map(error => _clone(error))
+
+    // Excluding the stack trace for the outer error as the inner stack trace already
+    // contains the initial segment of the outer stack trace.
+    delete error2log.stack
+  }
+
+  error2log = normalizeError(error2log, { locale: i18n.default_language }, error => error).error
+
+  // determine if the status code represents a client error (4xx range)
+  if (isClientError(error2log)) {
+    if (LOG_CDS._warn) LOG_CDS.warn(error2log)
+  } else {
+    // server error
+    if (LOG_CDS._error) LOG_CDS.error(error2log)
+  }
+}
+
 const formatError = error => {
   // CDS errors have already been logged and already have a stacktrace in extensions
   if (error.originalError?._cdsError) return error

lib/resolvers/response.js

@@ -3,8 +3,8 @@ const { handleCDSError } = require('./error')
 const setResponse = async (context, response, key, value) => {
   try {
     response[key] = await value
-  } catch (e) {
-    response[key] = handleCDSError(context, e)
+  } catch (error) {
+    response[key] = handleCDSError(context, error)
   }
 }
 

test/tests/error-handling-prod.test.js

@@ -8,6 +8,15 @@ describe('graphql - error handling in production', () => {
   // Prevent axios from throwing errors for non 2xx status codes
   axios.defaults.validateStatus = false
 
+  beforeEach(() => {
+    jest.spyOn(console, 'warn')
+    jest.spyOn(console, 'error')
+  })
+
+  afterEach(() => {
+    jest.clearAllMocks()
+  })
+
   describe('Errors thrown by CDS', () => {
     test('Single @mandatory validation error', async () => {
       const query = gql`
@@ -33,6 +42,17 @@ describe('graphql - error handling in production', () => {
       const response = await POST('/graphql', { query })
       expect(response.data).toMatchObject({ errors })
       expect(response.data.errors[0].extensions).not.toHaveProperty('stacktrace') // No stacktrace in production
+      expect(console.warn.mock.calls[0][1]).toMatchObject({
+        code: '400',
+        element: 'notEmptyI',
+        entity: 'ValidationErrorsService.A',
+        message: 'Value is required',
+        numericSeverity: 4,
+        target: 'notEmptyI',
+        type: 'cds.Integer',
+        value: undefined,
+        stack: expect.any(String)
+      })
     })
 
     test('Multiple @mandatory validation errors', async () => {
@@ -137,6 +157,38 @@ describe('graphql - error handling in production', () => {
       expect(response.data.errors[0].extensions).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
       expect(response.data.errors[0].extensions.details[0]).not.toHaveProperty('stacktrace') // No stacktrace in production
       expect(response.data.errors[0].extensions.details[1]).not.toHaveProperty('stacktrace') // No stacktrace in production
+      expect(console.warn.mock.calls[0][1]).toMatchObject({
+        code: '400',
+        message: 'Multiple errors occurred. Please see the details for more information.',
+        details: [
+          {
+            args: ['inRange'],
+            code: '400',
+            element: 'inRange',
+            entity: 'ValidationErrorsService.C',
+            message: 'Value is required',
+            numericSeverity: 4,
+            target: 'inRange',
+            type: 'cds.Integer',
+            value: undefined,
+            stack: expect.any(String)
+          },
+          {
+            args: ['"foo"', '"high", "medium", "low"'],
+            code: '400',
+            element: 'oneOfEnumValues',
+            entity: 'ValidationErrorsService.C',
+            enum: ['@assert.range', 'type', 'enum'],
+            message: 'Value "foo" is invalid according to enum declaration {"high", "medium", "low"}',
+            numericSeverity: 4,
+            target: 'oneOfEnumValues',
+            type: 'cds.String',
+            value: 'foo',
+            stack: expect.any(String)
+          }
+        ]
+      })
+      expect(console.warn.mock.calls[0][1]).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
     })
   })
 
@@ -310,6 +362,29 @@ describe('graphql - error handling in production', () => {
       expect(response.data.errors[0].extensions).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
       expect(response.data.errors[0].extensions.details[0]).not.toHaveProperty('stacktrace') // No stacktrace in production
       expect(response.data.errors[0].extensions.details[1]).not.toHaveProperty('stacktrace') // No stacktrace in production
+      expect(console.error.mock.calls[0][1]).toMatchObject({
+        code: '500',
+        message: 'Multiple errors occurred. Please see the details for more information.',
+        details: [
+          {
+            code: 'Some-Custom-Code1',
+            message: 'Some Custom Error Message 1',
+            numericSeverity: 4,
+            status: 418,
+            target: 'some_field',
+            stack: expect.any(String)
+          },
+          {
+            code: 'Some-Custom-Code2',
+            message: 'Some Custom Error Message 2',
+            numericSeverity: 4,
+            status: 500,
+            target: 'some_field',
+            stack: expect.any(String)
+          }
+        ]
+      })
+      expect(console.error.mock.calls[0][1]).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
     })
 
     test('Thrown error is modified in srv.on(error) handler', async () => {