runfix: Improve datadog logs (#15031)

Author: atomrc

src/script/audio/AudioRepository.ts

@@ -106,8 +106,6 @@ export class AudioRepository {
     Object.values(AudioType).forEach(audioId => {
       this.audioElements[audioId] = this.createAudioElement(`./audio/${audioId}.mp3`, preload);
     });
-
-    this.logger.info(`Sounds initialized (preload: '${preload}')`);
   }
 
   private stopAll(): void {
@@ -168,7 +166,7 @@ export class AudioRepository {
       case AUDIO_PLAY_PERMISSION.ALLOWED:
         try {
           await this.playAudio(audioElement, playInLoop);
-          this.logger.info(`Playing sound '${audioId}' (loop: '${playInLoop}')`);
+          this.logger.log(`Playing sound '${audioId}' (loop: '${playInLoop}')`);
         } catch (error) {
           this.logger.error(`Failed to play sound '${audioId}': ${error.message}`);
           throw error;
@@ -201,7 +199,6 @@ export class AudioRepository {
   readonly stop = (audioId: AudioType): void => {
     const audioElement = this.getSoundById(audioId);
     if (!audioElement?.paused) {
-      this.logger.info(`Stopping sound '${audioId}'`);
       audioElement.pause();
       audioElement.load();
     }

src/script/auth/main.tsx

@@ -78,7 +78,7 @@ const config = Config.getConfig();
 async function runApp() {
   const [min, max] = config.SUPPORTED_API_RANGE;
   const {domain} = await core.useAPIVersion(min, max, config.ENABLE_DEV_BACKEND_API);
-  await initializeDataDog(config, domain);
+  await initializeDataDog(config, {domain: domain});
 
   render(Root);
   if (module.hot) {

src/script/client/ClientRepository.ts

@@ -133,7 +133,7 @@ export class ClientRepository {
       const status = error.response?.status;
       const clientNotFoundBackend = status === HTTP_STATUS.NOT_FOUND;
       if (clientNotFoundBackend) {
-        this.logger.warn(`Local client '${clientId}' no longer exists on the backend`, error);
+        this.logger.warn(`Local client no longer exists on the backend`, error);
         throw new ClientError(ClientError.TYPE.NO_VALID_CLIENT, ClientError.MESSAGE.NO_VALID_CLIENT);
       }
 
@@ -246,8 +246,7 @@ export class ClientRepository {
   async getValidLocalClient(): Promise<ko.Observable<ClientEntity>> {
     try {
       const clientEntity = await this.getCurrentClientFromDb();
-      const clientPayload = await this.getClientByIdFromBackend(clientEntity.id);
-      this.logger.info(`Client with ID '${clientPayload.id}' (${clientPayload.type}) validated on backend`);
+      await this.getClientByIdFromBackend(clientEntity.id);
       const currentClient = this.clientState.currentClient;
 
       await this.clientService.putClientCapabilities(currentClient().id, {
@@ -374,7 +373,6 @@ export class ClientRepository {
    * @returns Resolves with all locally known clients except the current one
    */
   async getClientsForSelf(): Promise<ClientEntity[]> {
-    this.logger.info('Retrieving all clients of the self user from database');
     const {domain, id} = this.selfUser();
     const clientRecords = await this.getClientByUserIdFromDb({domain, id});
     const clientEntities = ClientMapper.mapClients(clientRecords, true, domain);
@@ -444,15 +442,15 @@ export class ClientRepository {
             delete clientsFromBackend[clientId];
 
             if (this.clientState.currentClient() && this.isCurrentClient(userId, clientId)) {
-              this.logger.warn(`Removing duplicate self client '${clientId}' locally`);
+              this.logger.warn(`Removing duplicate local self client`);
               await this.removeClient(userId, clientId);
             }
 
             // Locally known client changed on backend
             if (wasUpdated) {
               // Clear the previous client in DB (in case the domain changes the primary key will also change, thus invalidating the previous client)
               await this.clientService.deleteClientFromDb(client.meta.primary_key);
-              this.logger.info(`Updating client '${clientId}' of user '${userId.id}' locally`);
+              this.logger.info(`Updating local client`);
               promises.push(this.saveClientInDb(userId, client));
               continue;
             }
@@ -463,7 +461,7 @@ export class ClientRepository {
           }
 
           // Locally known client deleted on backend
-          this.logger.warn(`Removing client '${clientId}' of user '${userId.id}' locally`);
+          this.logger.warn(`Removing local client`);
           await this.removeClient(userId, clientId);
         }
 
@@ -475,7 +473,7 @@ export class ClientRepository {
           }
 
           // Locally unknown client new on backend
-          this.logger.debug(`New client '${clientId}' of user '${userId.id}' will be stored locally`);
+          this.logger.debug(`New client will be stored locally`);
           if (matchQualifiedIds(this.selfUser(), userId)) {
             this.onClientAdd({client: clientPayload as RegisteredClient});
           }
@@ -541,7 +539,7 @@ export class ClientRepository {
    * @param eventJson JSON data of 'user.client-add' event
    */
   private onClientAdd(eventJson: Pick<UserClientAddEvent, 'client'>): void {
-    this.logger.debug('Client of self user added', eventJson);
+    this.logger.debug('Client of self user added');
     amplify.publish(WebAppEvents.CLIENT.ADD, this.selfUser().qualifiedId, eventJson.client, true);
   }
 

src/script/client/ClientService.ts

@@ -26,15 +26,12 @@ import type {
 import type {QualifiedId} from '@wireapp/api-client/lib/user';
 import {container} from 'tsyringe';
 
-import {Logger, getLogger} from 'Util/Logger';
-
 import {APIClient} from '../service/APIClientSingleton';
 import type {ClientRecord} from '../storage';
 import {StorageService} from '../storage';
 import {StorageSchemata} from '../storage/StorageSchemata';
 
 export class ClientService {
-  private readonly logger: Logger;
   private readonly CLIENT_STORE_NAME: string;
 
   static get URL_CLIENTS(): string {
@@ -49,8 +46,6 @@ export class ClientService {
     private readonly storageService = container.resolve(StorageService),
     private readonly apiClient = container.resolve(APIClient),
   ) {
-    this.logger = getLogger('ClientService');
-
     this.CLIENT_STORE_NAME = StorageSchemata.OBJECT_STORE.CLIENTS;
   }
 
@@ -159,11 +154,9 @@ export class ClientService {
     }
 
     if (clientRecord === undefined) {
-      this.logger.info(`Client with primary key '${primaryKey}' not found in database`);
       return primaryKey;
     }
 
-    this.logger.info(`Loaded client record from database '${primaryKey}'`);
     return clientRecord;
   }
 
@@ -182,7 +175,6 @@ export class ClientService {
     clientPayload.meta.primary_key = primaryKey;
 
     return this.storageService.save(this.CLIENT_STORE_NAME, primaryKey, clientPayload).then(() => {
-      this.logger.info(`Client '${clientPayload.id}' stored with primary key '${primaryKey}'`);
       return clientPayload;
     });
   }

src/script/conversation/ConversationRepository.ts

@@ -489,7 +489,6 @@ export class ConversationRepository {
       const response = await this.conversationService.getConversationById(qualifiedId);
       const [conversationEntity] = this.mapConversations([response]);
 
-      this.logger.info(`Fetched conversation '${conversationId}' from backend`);
       this.saveConversation(conversationEntity);
 
       fetching_conversations[conversationId].forEach(({resolveFn}) => resolveFn(conversationEntity));
@@ -1943,6 +1942,31 @@ export class ConversationRepository {
   // Event callbacks
   //##############################################################################
 
+  private logConversationEvent(event: IncomingEvent, source: EventSource) {
+    if (event.type === CONVERSATION_EVENT.TYPING) {
+      // Prevent logging typing events
+      return;
+    }
+    const {time, from, qualified_conversation} = event;
+    const extra: Record<string, unknown> = {};
+    extra.messageId = 'id' in event && event.id;
+    const logMessage = `Conversation Event: '${event.type}' (Source: ${source})`;
+    switch (event.type) {
+      case ClientEvent.CONVERSATION.ASSET_ADD:
+        extra.contentType = event.data.content_type;
+        extra.size = event.data.content_length;
+        extra.status = event.data.status;
+
+      case ClientEvent.CONVERSATION.MESSAGE_ADD:
+        extra.sender = event.from_client_id;
+        break;
+
+      case ClientEvent.CONVERSATION.MESSAGE_DELETE:
+        extra.deletedMessage = event.data.message_id;
+    }
+    this.logger.info(logMessage, {time, from, qualified_conversation, ...extra});
+  }
+
   /**
    * Listener for incoming events.
    *
@@ -1951,9 +1975,7 @@ export class ConversationRepository {
    * @returns Resolves when event was handled
    */
   private readonly onConversationEvent = (event: IncomingEvent, source = EventRepository.SOURCE.STREAM) => {
-    const logObject = {eventJson: JSON.stringify(event), eventObject: event};
-    const logMessage = `Conversation Event: '${event.type}' (Source: ${source})`;
-    this.logger.info(logMessage, logObject);
+    this.logConversationEvent(event, source);
     return this.handleConversationEvent(event, source);
   };
 
@@ -1975,9 +1997,6 @@ export class ConversationRepository {
     const conversationId: QualifiedId = eventData?.conversationId
       ? {domain: '', id: eventData.conversationId}
       : qualified_conversation || {domain: '', id: conversation};
-    this.logger.info(
-      `Handling event '${type}' in conversation '${conversationId.id}/${conversationId.domain}' (Source: ${eventSource})`,
-    );
 
     const inSelfConversation = this.conversationState.isSelfConversation(conversationId);
     if (inSelfConversation) {

src/script/conversation/EventBuilder.ts

@@ -42,6 +42,7 @@ export interface BaseEvent {
   data?: unknown;
   from: string;
   id: string;
+  from_client_id?: string;
   qualified_conversation?: QualifiedId;
   qualified_from?: QualifiedId;
   server_time?: string;

src/script/event/EventRepository.ts

@@ -303,11 +303,9 @@ export class EventRepository {
       source = EventRepository.SOURCE.INJECTED;
     }
 
-    const id = 'id' in event ? event.id : 'ID not specified';
     const conversationId = 'conversation' in event && event.conversation;
     const inSelfConversation = conversationId === this.userState.self().id;
     if (!inSelfConversation) {
-      this.logger.info(`Injected event ID '${id}' of type '${event.type}' with source '${source}'`);
       return this.processEvent(event, source);
     }
     return undefined;
@@ -362,7 +360,7 @@ export class EventRepository {
         return event;
       }
       case EventValidation.OUTDATED_TIMESTAMP: {
-        this.logger.info(`Ignored outdated event type: '${event.type}'`);
+        this.logger.warn(`Ignored outdated event type: '${event.type}'`);
         return event;
       }
       case EventValidation.VALID:

src/script/main/app.ts

@@ -335,8 +335,7 @@ export class App {
   async initApp(clientType: ClientType, onProgress: (progress: number, message?: string) => void) {
     // add body information
     const [apiVersionMin, apiVersionMax] = this.config.SUPPORTED_API_RANGE;
-    const {domain} = await this.core.useAPIVersion(apiVersionMin, apiVersionMax, this.config.ENABLE_DEV_BACKEND_API);
-    await initializeDataDog(this.config, domain);
+    await this.core.useAPIVersion(apiVersionMin, apiVersionMax, this.config.ENABLE_DEV_BACKEND_API);
 
     const osCssClass = Runtime.isMacOS() ? 'os-mac' : 'os-pc';
     const platformCssClass = Runtime.isDesktopApp() ? 'platform-electron' : 'platform-web';
@@ -380,6 +379,7 @@ export class App {
       });
 
       const selfUser = await this.initiateSelfUser();
+      await initializeDataDog(this.config, selfUser.qualifiedId);
 
       onProgress(5, t('initReceivedSelfUser', selfUser.name()));
       telemetry.timeStep(AppInitTimingsStep.RECEIVED_SELF_USER);
@@ -462,7 +462,7 @@ export class App {
       telemetry.timeStep(AppInitTimingsStep.APP_LOADED);
 
       const loadTime = telemetry.report();
-      this.logger.info(`App loaded within ${loadTime}s for user "${selfUser.id}" and client "${clientEntity().id}"`);
+      this.logger.info(`App loaded within ${loadTime}s`);
 
       return selfUser;
     } catch (error) {

src/script/time/serverTimeHandler.ts

@@ -25,7 +25,7 @@ export const serverTimeHandler = {
   computeTimeOffset(serverTimeString: string): void {
     const timeOffset = Date.now() - new Date(serverTimeString).valueOf();
     this.timeOffset(timeOffset);
-    this.logger.info(`Current backend time is '${serverTimeString}'. Time offset updated to '${this.timeOffset()}' ms`);
+    this.logger.log(`Current backend time is '${serverTimeString}'. Time offset updated to '${this.timeOffset()}' ms`);
   },
 
   getTimeOffset(): number {

src/script/util/DataDog.ts

@@ -23,7 +23,7 @@ const uuidRegex = /([a-z\d]{8})-([a-z\d]{4})-([a-z\d]{4})-([a-z\d]{4})-([a-z\d]{
 
 let isDataDogInitialized = false;
 
-export async function initializeDataDog(config: Configuration, domain?: string) {
+export async function initializeDataDog(config: Configuration, user: {id?: string; domain: string}) {
   if (isDataDogInitialized) {
     return;
   }
@@ -37,10 +37,15 @@ export async function initializeDataDog(config: Configuration, domain?: string)
     return;
   }
 
+  const {domain, id: userId} = user ?? {};
+
   const replacer = (_match: string, p1: string) => `${p1}***`;
   const truncateDomain = (value: string) => `${value.substring(0, 3)}***`;
   const replaceAllStrings = (string: string) => string.replaceAll(uuidRegex, replacer);
   const replaceDomains = (string: string) => (domain ? string.replaceAll(domain, truncateDomain(domain)) : string);
+  const removeColors = (string: string) =>
+    string.replaceAll(/%c/g, '').replaceAll(/color:[^;]+; font-weight:[^;]+; /g, '');
+  const removeTimestamp = (string: string) => string.replaceAll(/\[\d+-\d+-\d+ \d+:\d+:\d+\] /g, '');
 
   const {datadogRum} = await import('@datadog/browser-rum');
 
@@ -72,8 +77,18 @@ export async function initializeDataDog(config: Configuration, domain?: string)
     forwardConsoleLogs: ['info', 'warn', 'error'], // For now those logs should be fine, we need to investigate if we need another logs in the future
     sessionSampleRate: 100,
     beforeSend: log => {
+      if (log.message.match(/@wireapp\/webapp\/avs/)) {
+        return false;
+      }
       log.view.url = '/';
-      log.message = replaceDomains(replaceAllStrings(log.message));
+      log.message = replaceDomains(replaceAllStrings(removeTimestamp(removeColors(log.message))));
+      return undefined;
     },
   });
+
+  if (userId) {
+    const id = userId.substring(0, 8);
+    datadogRum.setUser({id});
+    datadogLogs.setUser({id});
+  }
 }

src/script/view_model/WarningsContainer/WarningsState.ts

@@ -24,16 +24,13 @@ import {WebAppEvents} from '@wireapp/webapp-events';
 
 import {PrimaryModal} from 'Components/Modals/PrimaryModal';
 import {t} from 'Util/LocalizerUtil';
-import {getLogger} from 'Util/Logger';
 import {safeWindowOpen} from 'Util/SanitizationUtil';
 
 import {TYPE} from './WarningsTypes';
 
 import {Config} from '../../Config';
 import {PermissionState} from '../../notification/PermissionState';
 
-const logger = getLogger('WarningsViewModel');
-
 type WarningsState = {
   name: string;
   warnings: TYPE[];
@@ -60,7 +57,6 @@ const hideWarning = (type = getVisibleWarning()) => {
   const {warnings, removeWarning} = useWarningsState.getState();
   if (warnings.includes(type)) {
     removeWarning(type);
-    logger.info(`Dismissed warning of type '${type}'`);
   }
 };
 
@@ -74,8 +70,6 @@ const showWarning = (type: TYPE, info?: {name: string}) => {
     hideWarning(visibleWarning);
   }
 
-  logger.warn(`Showing warning of type '${type}'`);
-
   if (info) {
     setName(info.name);
   }
@@ -95,7 +89,6 @@ const closeWarning = (): void => {
 
   if (warnings.includes(warningToClose)) {
     removeWarning(warningToClose);
-    logger.info(`Dismissed warning of type '${warningToClose}'`);
   }
 
   switch (warningToClose) {