[backend/worker] Adapt logging strategy to improve the error management

opencti-platform/opencti-graphql/src/config/errors.js

@@ -7,14 +7,14 @@ export const error = (type, message, data) => {
   return new GraphQLError(message, { extensions: { code: type, data } });
 };
 
+// region TYPE_AUTH
 export const AUTH_FAILURE = 'AUTH_FAILURE';
 export const AuthenticationFailure = (reason, data) => error(AUTH_FAILURE, reason || 'Bad login or password', {
   http_status: 401,
   genre: CATEGORY_TECHNICAL,
   ...data,
 });
 
-// TYPE_AUTH
 export const AUTH_REQUIRED = 'AUTH_REQUIRED';
 export const AuthRequired = (data) => error(AUTH_REQUIRED, 'You must be logged in to do this.', {
   http_status: 401,
@@ -47,50 +47,79 @@ export const ForbiddenAccess = (message, data) => error(
   }
 );
 
-const RESOURCE_NOT_FOUND_ERROR = 'RESOURCE_NOT_FOUND';
-export const ResourceNotFoundError = (data) => error(RESOURCE_NOT_FOUND_ERROR, 'Resource not found', {
-  http_status: 404,
-  ...data,
-});
-
-// CATEGORY_TECHNICAL
-export const DatabaseError = (reason, data) => error('DATABASE_ERROR', reason || 'A database error has occurred', {
+export const AUTH_ERRORS = [
+  AUTH_FAILURE,
+  AUTH_REQUIRED,
+  OTP_REQUIRED,
+  OTP_REQUIRED_ACTIVATION,
+  FORBIDDEN_ACCESS
+];
+// endregion
+
+// region CATEGORY_TECHNICAL
+const DATABASE_ERROR = 'DATABASE_ERROR';
+export const DatabaseError = (reason, data) => error(DATABASE_ERROR, reason || 'A database error has occurred', {
   http_status: 500,
   genre: CATEGORY_TECHNICAL,
   ...data,
 });
 
-export const FilesystemError = (reason, data) => error('FILESYSTEM_ERROR', reason || 'A filesystem error has occurred', {
+const FILESYSTEM_ERROR = 'FILESYSTEM_ERROR';
+export const FilesystemError = (reason, data) => {
+  return error(FILESYSTEM_ERROR, reason || 'A filesystem error has occurred', {
+    http_status: 500,
+    genre: CATEGORY_TECHNICAL,
+    ...data,
+  });
+};
+
+const COMPLEX_SEARCH_ERROR = 'COMPLEX_SEARCH_ERROR';
+export const ComplexSearchError = (reason, data) => error(COMPLEX_SEARCH_ERROR, reason || 'A search error has occurred', {
   http_status: 500,
   genre: CATEGORY_TECHNICAL,
   ...data,
 });
 
-export const ComplexSearchError = (reason, data) => error('COMPLEX_SEARCH_ERROR', reason || 'A search error has occurred', {
+const CONFIGURATION_ERROR = 'CONFIGURATION_ERROR';
+export const ConfigurationError = (reason, data) => error(CONFIGURATION_ERROR, reason || 'A configuration error has occurred', {
   http_status: 500,
   genre: CATEGORY_TECHNICAL,
   ...data,
 });
 
-export const ConfigurationError = (reason, data) => error('CONFIGURATION_ERROR', reason || 'A configuration error has occurred', {
+const UNKNOWN_ERROR = 'UNKNOWN_ERROR';
+export const UnknownError = (reason, data) => error(UNKNOWN_ERROR, reason || 'An unknown error has occurred', {
   http_status: 500,
   genre: CATEGORY_TECHNICAL,
   ...data,
 });
 
-export const UnknownError = (reason, data) => error('UNKNOWN_ERROR', reason || 'An unknown error has occurred', {
+export const UNSUPPORTED_ERROR = 'UNSUPPORTED_ERROR';
+export const UnsupportedError = (reason, data) => error(UNSUPPORTED_ERROR, reason || 'Unsupported operation', {
   http_status: 500,
-  genre: CATEGORY_TECHNICAL,
+  genre: CATEGORY_BUSINESS,
   ...data,
 });
 
-export const UNSUPPORTED_ERROR = 'UNSUPPORTED_ERROR';
-export const UnsupportedError = (reason, data) => error(UNSUPPORTED_ERROR, reason || 'Unsupported operation', {
+export const EngineShardsError = (data) => error(DATABASE_ERROR, 'Engine execution fail, some shards are not available, please check your engine status', {
   http_status: 500,
   genre: CATEGORY_BUSINESS,
   ...data,
 });
 
+// noinspection JSUnusedGlobalSymbols
+export const TECHNICAL_ERRORS = [
+  DATABASE_ERROR,
+  FILESYSTEM_ERROR,
+  COMPLEX_SEARCH_ERROR,
+  CONFIGURATION_ERROR,
+  UNKNOWN_ERROR,
+  UNSUPPORTED_ERROR,
+];
+// endregion
+
+// region CATEGORY_FUNCTIONAL
+export const FUNCTIONAL_ERROR = 'FUNCTIONAL_ERROR';
 export const FunctionalError = (reason, data) => error('FUNCTIONAL_ERROR', reason || 'Business validation', {
   http_status: 400,
   genre: CATEGORY_BUSINESS,
@@ -104,20 +133,6 @@ export const AlreadyDeletedError = (data) => error(ALREADY_DELETED_ERROR, 'Alrea
   ...data,
 });
 
-const TYPE_LOCK = 'LOCK_ERROR';
-export const TYPE_LOCK_ERROR = 'ExecutionError';
-export const LockTimeoutError = (data, reason) => error(TYPE_LOCK, reason ?? 'Execution timeout, too many concurrent call on the same entities', {
-  http_status: 500,
-  genre: CATEGORY_BUSINESS,
-  ...data,
-});
-
-export const EngineShardsError = (data) => error('DATABASE_ERROR', 'Engine execution fail, some shards are not available, please check your engine status', {
-  http_status: 500,
-  genre: CATEGORY_BUSINESS,
-  ...data,
-});
-
 export const MISSING_REF_ERROR = 'MISSING_REFERENCE_ERROR';
 export const MissingReferenceError = (data) => error(MISSING_REF_ERROR, 'Element(s) not found', {
   http_status: 404,
@@ -132,3 +147,20 @@ export const ValidationError = (message, field, data) => error(VALIDATION_ERROR,
   field,
   ...(data ?? {}),
 });
+
+const TYPE_LOCK = 'LOCK_ERROR';
+export const TYPE_LOCK_ERROR = 'ExecutionError';
+export const LockTimeoutError = (data, reason) => error(TYPE_LOCK, reason ?? 'Execution timeout, too many concurrent call on the same entities', {
+  http_status: 500,
+  genre: CATEGORY_BUSINESS,
+  ...data,
+});
+
+export const FUNCTIONAL_ERRORS = [
+  FUNCTIONAL_ERROR,
+  ALREADY_DELETED_ERROR,
+  MISSING_REF_ERROR,
+  VALIDATION_ERROR,
+  TYPE_LOCK_ERROR
+];
+// endregion

opencti-platform/opencti-graphql/src/database/engine.js

@@ -1601,7 +1601,9 @@ export const elFindByIds = async (context, user, ids, opts = {}) => {
         throw DatabaseError('Find direct ids fail', { cause: err, query });
       });
       const elements = data.hits.hits;
-      if (elements.length > workingIds.length) logApp.warn('Search query returned more elements than expected', workingIds);
+      if (elements.length > workingIds.length) {
+        logApp.warn('Search query returned more elements than expected', workingIds);
+      }
       if (elements.length > 0) {
         const convertedHits = await elConvertHits(elements, { withoutRels });
         hits.push(...convertedHits);
@@ -3293,7 +3295,7 @@ export const elPaginate = async (context, user, indexName, options = {}) => {
   const { types = null, connectionFormat = true } = options;
   const body = await elQueryBodyBuilder(context, user, options);
   if (body.size > ES_MAX_PAGINATION && !bypassSizeLimit) {
-    logApp.warn('[SEARCH] Pagination limited to max result config', { size: body.size, max: ES_MAX_PAGINATION });
+    logApp.info('[SEARCH] Pagination limited to max result config', { size: body.size, max: ES_MAX_PAGINATION });
     body.size = ES_MAX_PAGINATION;
   }
   const query = {

opencti-platform/opencti-graphql/src/database/middleware.js

@@ -328,7 +328,7 @@ const loadElementMetaDependencies = async (context, user, elements, args = {}) =
           // - Access rights are asymmetric, should not happen for meta relationships.
           // - Relations is invalid, should not happen in platform data consistency.
           const relations = invalidRelations.map((v) => ({ relation_id: v.id, target_id: v.toId }));
-          logApp.warn('Targets of loadElementMetaDependencies not found', { relations });
+          logApp.info('Targets of loadElementMetaDependencies not found', { relations });
         }
         const inputKey = schemaRelationsRefDefinition.convertDatabaseNameToInputName(element.entity_type, key);
         const metaRefKey = schemaRelationsRefDefinition.getRelationRef(element.entity_type, inputKey);
@@ -2601,7 +2601,7 @@ const upsertElement = async (context, user, element, type, basePatch, opts = {})
           inputs.push(...buildAttributeUpdate(isFullSync, attribute, element[attributeKey], inputData));
         }
       } else {
-        logApp.warn('Discarding outdated attribute update mutation', { key: attributeKey });
+        logApp.info('Discarding outdated attribute update mutation', { key: attributeKey });
       }
     }
   }
@@ -2657,7 +2657,7 @@ const upsertElement = async (context, user, element, type, basePatch, opts = {})
           }
         }
       } else {
-        logApp.warn('Discarding outdated attribute update mutation', { key: inputField });
+        logApp.info('Discarding outdated attribute update mutation', { key: inputField });
       }
     }
   }
@@ -3323,7 +3323,7 @@ export const deleteInferredRuleElement = async (rule, instance, deletedDependenc
     }
   } catch (err) {
     if (err.name === ALREADY_DELETED_ERROR) {
-      logApp.warn(err);
+      logApp.info(err);
     } else {
       logApp.error(err);
     }

opencti-platform/opencti-graphql/src/database/redis.ts

@@ -10,7 +10,7 @@ import type { SentinelConnectionOptions } from 'ioredis/built/connectors/Sentine
 import conf, { booleanConf, configureCA, DEV_MODE, getStoppingState, loadCert, logApp, REDIS_PREFIX } from '../config/conf';
 import { asyncListTransformation, EVENT_TYPE_CREATE, EVENT_TYPE_DELETE, EVENT_TYPE_MERGE, EVENT_TYPE_UPDATE, isEmptyField, waitInSec } from './utils';
 import { isStixExportableData } from '../schema/stixCoreObject';
-import { DatabaseError, LockTimeoutError, UnsupportedError } from '../config/errors';
+import { DatabaseError, LockTimeoutError, TYPE_LOCK_ERROR, UnsupportedError } from '../config/errors';
 import { mergeDeepRightAll, now, utcDate } from '../utils/format';
 import { convertStoreToStix } from './stix-converter';
 import type { StoreObject, StoreRelation } from '../types/store';
@@ -390,12 +390,12 @@ export const lockResource = async (resources: Array<string>, opts: LockOptions =
   const extend = async () => {
     try {
       if (opts.retryCount !== 0) {
-        logApp.warn('Extending resources for long processing task', { locks, stack: initialCallStack });
+        logApp.info('Extending resources for long processing task', { locks, stack: initialCallStack });
       }
       lock = await lock.extend(maxTtl);
       queue();
     } catch (error) {
-      controller.abort('[REDIS] Failed to extend resource');
+      controller.abort({ name: TYPE_LOCK_ERROR });
     }
   };
   // If lock succeed we need to be sure that delete not occurred just before the resolution/lock
@@ -433,7 +433,6 @@ export const lockResource = async (resources: Array<string>, opts: LockOptions =
         await lock.release();
       } catch (e) {
         // Nothing to do here
-        logApp.warn('Failed to unlock resource', { locks });
       }
     },
   };

opencti-platform/opencti-graphql/src/graphql/loggerPlugin.js

@@ -1,9 +1,9 @@
-import { filter, head, includes, isEmpty, isNil } from 'ramda';
+import { filter, head, isEmpty, isNil } from 'ramda';
 import { stripIgnoredCharacters } from 'graphql/utilities';
 import conf, { appLogExtendedErrors, booleanConf, logApp } from '../config/conf';
 import { isEmptyField, isNotEmptyField } from '../database/utils';
 import { getMemoryStatistics } from '../domain/settings';
-import { ALREADY_DELETED_ERROR, AUTH_REQUIRED, FORBIDDEN_ACCESS, UNSUPPORTED_ERROR, VALIDATION_ERROR } from '../config/errors';
+import { AUTH_ERRORS, FORBIDDEN_ACCESS, FUNCTIONAL_ERRORS } from '../config/errors';
 import { publishUserAction } from '../listener/UserActionListener';
 
 const innerCompute = (inners) => {
@@ -122,32 +122,30 @@ export default {
             callMetaData.query_attributes = (callError.nodes ?? []).map((node) => graphQLNodeParser(node));
           }
           const errorCode = callError.extensions?.code ?? callError.name;
-          const isRetryableCall = isNotEmptyField(origin?.call_retry_number) && ![
-            UNSUPPORTED_ERROR,
-            ALREADY_DELETED_ERROR,
-            VALIDATION_ERROR,
-          ].includes(errorCode);
-          const isAuthenticationCall = includes(errorCode, [AUTH_REQUIRED]);
-          // Don't log for a simple missing authentication
+          // Don't error log for a simple missing authentication
+          // Specific audit log for forbidden access
+          const isAuthenticationCall = AUTH_ERRORS.includes(errorCode);
           if (isAuthenticationCall) {
+            // If not forbidden access, audit already handled
+            // Forbidden can be called in many places
+            if (errorCode === FORBIDDEN_ACCESS) {
+              await publishUserAction({
+                user: contextUser,
+                event_type: isWrite ? 'mutation' : 'read',
+                event_scope: 'unauthorized',
+                event_access: 'administration',
+                status: 'error',
+                context_data: {
+                  operation: context.operationName,
+                  input: context.request.variables,
+                }
+              });
+            }
             return;
           }
-          // Authentication problem can be logged in warning (dissoc variables to hide password)
-          // If worker is still retrying, this is not yet a problem, can be logged in warning until then.
-          if (isRetryableCall) {
+          // If functional error, log in warning
+          if (FUNCTIONAL_ERRORS.includes(errorCode)) {
             logApp.warn(callError, callMetaData);
-          } else if (errorCode === FORBIDDEN_ACCESS) {
-            await publishUserAction({
-              user: contextUser,
-              event_type: isWrite ? 'mutation' : 'read',
-              event_scope: 'unauthorized',
-              event_access: 'administration',
-              status: 'error',
-              context_data: {
-                operation: context.operationName,
-                input: context.request.variables,
-              }
-            });
           } else {
             // Every other uses cases are logged with error level
             logApp.error(callError, callMetaData);

opencti-platform/opencti-graphql/src/graphql/sseMiddleware.js

@@ -132,7 +132,7 @@ const computeUserAndCollection = async (req, res, { context, user, id }) => {
   if (!collection.stream_live) {
     res.statusMessage = 'This live stream is stopped';
     sendErrorStatusAndKillSession(req, res, 410);
-    logApp.warn('This live stream is stopped but still requested', { streamCollectionId: id });
+    logApp.info('This live stream is stopped but still requested', { streamCollectionId: id });
     return { error: 'This live stream is stopped' };
   }
   const streamFilters = JSON.parse(collection.filters);

opencti-platform/opencti-graphql/src/manager/garbageCollectionManager.ts

@@ -11,28 +11,24 @@ const BATCH_SIZE = conf.get('garbage_collection_manager:batch_size') || 10000;
 const DELETED_RETENTION_DAYS = conf.get('garbage_collection_manager:deleted_retention_days') || 7;
 
 /**
- * Search for N (batch_size) older than DELETED_RENTENTION_DAYS DeleteOpertions
+ * Search for N (batch_size) older than DELETED_RETENTION_DAYS DeleteOperations
  * Completely delete these deleteOperations
  */
 export const garbageCollectionHandler = async () => {
   const context = executionContext('garbage_collection_manager');
-  const deletedRentionDaysToConsider = Math.max(DELETED_RETENTION_DAYS, 1);
-  const deleteOperationsToManage = await findOldDeleteOperations(context, GARBAGE_COLLECTION_MANAGER_USER, deletedRentionDaysToConsider, BATCH_SIZE);
+  const deletedRetentionDaysToConsider = Math.max(DELETED_RETENTION_DAYS, 1);
+  const deleteOperationsToManage = await findOldDeleteOperations(context, GARBAGE_COLLECTION_MANAGER_USER, deletedRetentionDaysToConsider, BATCH_SIZE);
   let errorCount = 0;
   for (let i = 0; i < deleteOperationsToManage.length; i += 1) {
     try {
       const deleteOperation = deleteOperationsToManage[i];
       await confirmDelete(context, GARBAGE_COLLECTION_MANAGER_USER, deleteOperation.id);
     } catch (e) {
-      logApp.warn(e, { manager: 'GARBAGE_COLLECTION_MANAGER', id: deleteOperationsToManage[i].id });
+      logApp.error(e, { manager: '[OPENCTI-MODULE] Garbage collection', id: deleteOperationsToManage[i].id, errorCount });
       errorCount += 1;
     }
   }
-  if (errorCount > 0) {
-    logApp.error('[OPENCTI-MODULE] Garbage collection manager had errors during cleanup. Please have a look at previous warnings.', { count: deleteOperationsToManage.length, errorCount });
-  } else {
-    logApp.debug('[OPENCTI-MODULE] Garbage collection manager deletion process complete', { count: deleteOperationsToManage.length });
-  }
+  logApp.debug('[OPENCTI-MODULE] Garbage collection manager deletion process complete', { count: deleteOperationsToManage.length });
 };
 
 const GARBAGE_COLLECTION_MANAGER_DEFINITION: ManagerDefinition = {

opencti-platform/opencti-graphql/src/manager/ruleManager.ts

@@ -238,9 +238,7 @@ export const rulesCleanHandler = async (
           }
         }
       } catch (err: any) {
-        if (err.name === ALREADY_DELETED_ERROR) {
-          logApp.warn(err);
-        } else {
+        if (err.name !== ALREADY_DELETED_ERROR) {
           logApp.error(err, { manager: 'RULE_ENGINE' });
         }
       }

opencti-platform/opencti-graphql/src/manager/syncManager.js

@@ -58,7 +58,7 @@ const syncManagerInstance = (syncId) => {
       logApp.info(`[OPENCTI] Sync ${syncId}: listening ${eventSource.url} with id ${connectionId}`);
     });
     eventSource.on('error', (error) => {
-      logApp.error(error, { id: syncId, manager: 'SYNC_MANAGER' });
+      logApp.warn(error, { id: syncId, manager: 'SYNC_MANAGER' });
     });
   };
   const manageBackPressure = async (httpClient, { uri }, currentDelay) => {

opencti-platform/opencti-graphql/src/modules/deleteOperation/deleteOperation-domain.ts

@@ -315,7 +315,7 @@ export const restoreDelete = async (context: AuthContext, user: AuthUser, id: st
     const mainEntityRestoredId = result.id;
     if (mainEntityRestoredId !== main_entity_id) {
       upsertedElements[main_entity_id] = mainEntityRestoredId;
-      logApp.warn('Main entity has been restored with with different id (upsert)');
+      logApp.info('Main entity has been restored with with different id (upsert)');
     }
 
     // restore the relationships
@@ -337,11 +337,11 @@ export const restoreDelete = async (context: AuthContext, user: AuthUser, id: st
       }
       if (result.id && result.id !== relationshipInput.id) {
         upsertedElements[relationshipInput.id] = result.id;
-        logApp.warn('Relationship has been restored with different id (upsert)', { upsertId: result.id, originalId: relationshipInput.id });
+        logApp.info('Relationship has been restored with different id (upsert)', { upsertId: result.id, originalId: relationshipInput.id });
       }
       if (result.element && result.element.id && result.element.id !== relationshipInput.id) {
         upsertedElements[relationshipInput.id] = result.element.id;
-        logApp.warn('Relationship has been restored with different id (upsert)', { upsertId: result.element.id, originalId: relationshipInput.id });
+        logApp.info('Relationship has been restored with different id (upsert)', { upsertId: result.element.id, originalId: relationshipInput.id });
       }
     }