feat(logging): selective error message logging by error type (#131)

* feat(logging): enhanced logging capabilities

Previously, all errors were logged as generic errors. This enhancement introduces selective logging of warnings and errors based on their error type. Errors representing client errors (4xx range) are now logged as warnings instead of errors. Additionally, message interpolation has been introduced to resolve error message placeholders into human-readable text.

Co-authored-by: Marcel Schwarz <[email protected]>

---------

Co-authored-by: Marcel Schwarz <[email protected]>

Author: arleytm

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 () => {