feat: fine tune logs

hoelger · hoelger · commit bae4848287de · 2025-04-13T18:06:42.000+02:00
diff --git a/app/actions/application.ts b/app/actions/application.ts
@@ -22,9 +22,11 @@ import AbortionSystem, {
   ABORTION_ERROR,
   ABORTION_MANUAL
 } from '../utils/abortionSystem';
+import { logger } from '../utils/tracer-logger.js';
 
 export const endApplicationProcess =
   (): ThunkAction => async (dispatch: Dispatch) => {
+    logger.info('End application process...');
     dispatch(returnToSearchPage());
     dispatch(setBotMessage(null));
     dispatch(taskFinished());
diff --git a/app/actions/bot.ts b/app/actions/bot.ts
@@ -30,6 +30,7 @@ import { electronRouting, setBrowserViewReady } from './electron';
 import type { LoginData } from '../reducers/configuration';
 import { LoginStatus } from '../reducers/configuration';
 import { setConfiguration } from './configuration';
+import { logger } from '../utils/tracer-logger.js';
 
 export function queueInvestigateFlat(flatId: string): ThunkAction {
   return async (dispatch: Dispatch, getState: GetState) => {
@@ -85,6 +86,7 @@ export function setShowOverlay(showOverlay: boolean): Action {
 }
 export const navigateToFlatPage =
   (flatId: string) => async (dispatch: Dispatch) => {
+    logger.trace('navigateToFlatPage');
     await sleep(10000);
     dispatch(setBotIsActing(true));
     dispatch(setBotMessage(`Wohnung ${flatId} suchen...`));
@@ -103,6 +105,7 @@ export const navigateToFlatPage =
     /* eslint-disable no-await-in-loop */
     while (AbortionSystem.nestedFunctionsMayContinue) {
       if (!(await puppetView.elementExists(flatTitleSelector))) {
+        // now the absence of the element signals the success - we're on the next page
         return true;
       }
 
@@ -127,6 +130,7 @@ export function taskFinished(): Action {
 }
 export function returnToSearchPage(forceReload: boolean = false) {
   return async (dispatch: Dispatch, getState: GetState) => {
+    logger.trace(`returnToSearchPage force:${forceReload}`);
     const { electron, configuration } = getState();
 
     if (electron.views.puppet.url === configuration.searchUrl && !forceReload) {
diff --git a/app/flat/assessment.ts b/app/flat/assessment.ts
@@ -1,3 +1,4 @@
+import { logger } from '../utils/tracer-logger.js';
 import type { Configuration } from '../reducers/configuration';
 import { getConfigurationFilterHash } from '../reducers/configuration';
 import type { FlatData, OverviewDataEntry, Verdict } from '../reducers/data';
@@ -9,6 +10,10 @@ export function assessFlat(
   overviewDataEntry: OverviewDataEntry,
   flatData?: FlatData
 ): Verdict {
+  logger.trace();
+  // logger.log("configuration:", configuration);
+  logger.log('overviewDataEntry:', overviewDataEntry);
+  logger.log('flatData:', flatData);
   let action: FlatAction = FlatAction.IGNORE;
   const reasons = [];
 
@@ -190,6 +195,8 @@ export function assessFlat(
     }
   }
 
+  logger.debug(`Have verdict ${action} [scope=${scope}]`);
+
   return {
     flatId: overviewDataEntry.id,
     configurationHash: getConfigurationFilterHash(configuration),
diff --git a/app/main.dev.ts b/app/main.dev.ts
@@ -22,6 +22,9 @@ const isProduction = process.env.NODE_ENV === 'production';
 const isDevelopment = process.env.NODE_ENV === 'development';
 const enableDebug = process.env.ENABLE_DEBUG === 'true';
 const enableDevtools = isDevelopment || enableDebug;
+logger.info(
+  `ENVIRONMENT prod:${isProduction} dev:${isDevelopment} debug:${enableDebug} tools:${enableDevtools}`
+);
 
 let isLaunching = true;
 
@@ -67,6 +70,7 @@ const appOnReady = async (store) => {
   }
 
   /* Initialize views... */
+  logger.info('Initialize views...');
 
   mainWindow = new BrowserWindow({
     show: false,
@@ -82,7 +86,9 @@ const appOnReady = async (store) => {
     options: WebPreferences,
     initialUrl: string
   ): WebContentsView => {
-    logger.trace('args : %s %j %s', name, options, initialUrl);
+    logger.trace(`name:${name}`);
+    logger.log(`initialUrl:${initialUrl}`);
+    logger.log('options:', options);
     if (mainWindow === undefined || mainWindow === null) {
       throw Error('Main window not defined!');
     }
@@ -169,6 +175,7 @@ const appOnReady = async (store) => {
   }
 
   /* Add event listeners... */
+  logger.info('Add event listeners...');
 
   const configurationViewDidFinishLoad = async () => {
     logger.trace();
@@ -203,6 +210,7 @@ const appOnReady = async (store) => {
   mainWindow.on('closed', () => mainWindowOnClosed());
   mainWindow.setMenuBarVisibility(false);
 
+  logger.info('Initialize AppUpdater...');
   AppUpdater.init();
   AppUpdater.onUpdateAvailable((version) => {
     store.dispatch(setAvailableVersion(version));
@@ -215,6 +223,7 @@ const appOnReady = async (store) => {
   AppUpdater.onDownloadProgress((percentage) => {
     store.dispatch(setUpdateDownloadProgress(percentage));
   });
+  logger.trace('DONE');
 };
 
 const configureStoreThen = async (store) => {
diff --git a/app/middleware/bot.ts b/app/middleware/bot.ts
@@ -29,6 +29,7 @@ import {
   URL_PARAMETER_SORT_NEWEST
 } from '../constants/urls';
 import { CAPTCHA_HINT } from '../constants/documentTitles';
+import { logger } from '../utils/tracer-logger.js';
 
 export default (store: Store & { dispatch: Dispatch }) =>
   (next: (action: Action) => void) =>
@@ -83,6 +84,7 @@ export default (store: Store & { dispatch: Dispatch }) =>
       }
 
       if (puppet.url.startsWith(URL_SEARCH_PAGE)) {
+        logger.info('Finished loading search page...');
         const {
           configuration: { experimentalFeatures }
         } = store.getState();
@@ -120,6 +122,7 @@ export default (store: Store & { dispatch: Dispatch }) =>
       }
 
       if (puppet.url.startsWith(URL_PREFIX_FLAT_LISTING)) {
+        logger.info('Finished loading flat expose page...');
         await store.dispatch(getFlatData());
         store.dispatch(refreshVerdicts());
       }
@@ -149,20 +152,24 @@ export default (store: Store & { dispatch: Dispatch }) =>
       // eslint-disable-next-line default-case
       switch (verdict.action) {
         case FlatAction.NOTIFY_VIEWING_DATE:
+          logger.info(`Notify me for flat ${flatId}...`);
           store.dispatch(
             sendFlatViewingNotificationMail(contactData, flatOverview)
           );
           break;
 
         case FlatAction.INVESTIGATE:
+          logger.info(`Schedule flat ${flatId} for investigation`);
           store.dispatch(queueInvestigateFlat(flatId));
           break;
 
         case FlatAction.APPLY:
+          logger.info(`Applying for flat ${flatId}...`);
           store.dispatch(generateApplicationTextAndSubmit(flatId));
           break;
 
         case FlatAction.DISCARD:
+          logger.info(`Discard flat ${flatId}`);
           store.dispatch(discardApplicationProcess(flatOverview));
           break;
       }
diff --git a/app/middleware/configuration.ts b/app/middleware/configuration.ts
@@ -1,3 +1,4 @@
+import { logger } from '../utils/tracer-logger.js';
 import { setSearchUrl } from '../actions/configuration';
 import { refreshVerdicts } from '../actions/data';
 import type { Action, Dispatch, Store } from '../reducers/types';
@@ -21,6 +22,7 @@ export default (store: Store & { dispatch: Dispatch }) =>
       getConfigurationFilterHash(store.getState().configuration) !==
       filterBeforeUpdate
     ) {
+      logger.info('Configuration filter changed...');
       store.dispatch(refreshVerdicts());
 
       if (action.type !== SET_SEARCH_URL) {
diff --git a/app/middleware/data.ts b/app/middleware/data.ts
@@ -1,3 +1,4 @@
+import { logger } from '../utils/tracer-logger.js';
 import type { Action, Dispatch, Store } from '../reducers/types';
 import { REFRESH_VERDICTS } from '../constants/actionTypes';
 import { VerdictScope } from '../reducers/data';
@@ -15,6 +16,8 @@ export default (store: Store) => (next: Dispatch) => async (action: Action) => {
     } = store.getState();
 
     if (overview) {
+      logger.debug(`overview ids:${Object.keys(overview)}`);
+      // logger.log(`full overview:${overview}`);
       // we need multiple parts of the state, thus cannot do the this logic in reducers [unclean]
       const configurationHash = getConfigurationFilterHash(configuration);
       Object.values(overview).forEach((entry: OverviewDataEntry) => {
@@ -32,9 +35,14 @@ export default (store: Store) => (next: Dispatch) => async (action: Action) => {
           return;
         }
 
+        logger.info(
+          `Refresh verdict for flat ${entry.id} [scope=${currentScope}]`
+        );
         const verdict = assessFlat(configuration, entry, flatData);
         store.dispatch(setVerdict(entry.id, verdict));
       });
+    } else {
+      logger.warn("Have no overview. Isn't this at least '{}'?");
     }
   }
 
diff --git a/app/middleware/electron.ts b/app/middleware/electron.ts
@@ -27,6 +27,7 @@ import { easeInOutCubic } from '../utils/easing';
 import resizeViews from '../utils/resizeViews';
 import scrollWhileIdle from '../utils/scrollWhileIdle';
 import ElectronUtils from '../utils/electronUtils';
+import { logger } from '../utils/tracer-logger.js';
 import { login } from '../actions/bot';
 import electronObjects from '../store/electronObjects';
 
@@ -36,13 +37,13 @@ export default (store: Store) =>
   async (action: Action) => {
     if (action.type === ELECTRON_ROUTING) {
       const { name, targetUrl } = action.payload;
+      logger.trace(`url:${targetUrl}`);
       store.dispatch(setBrowserViewReady(name, false));
       store.dispatch(setBrowserViewUrl(name, targetUrl));
       const browserView = electronObjects.views[name];
 
       if (browserView === undefined) {
-        // eslint-disable-next-line no-console
-        console.error(`No view registered for ${name}!`);
+        logger.error(`No view registered for ${name}!`);
       } else {
         browserView.webContents.loadURL(targetUrl);
       }
@@ -52,8 +53,7 @@ export default (store: Store) =>
       const { window } = electronObjects;
 
       if (window === undefined || window === null) {
-        // eslint-disable-next-line no-console
-        console.error('Main window not defined!');
+        logger.error('Main window not defined!');
         return;
       }
 
@@ -99,6 +99,7 @@ export default (store: Store) =>
     }
 
     if (action.type === HIDE_CONFIGURATION) {
+      logger.info('Close configuration...');
       const { immobilienScout24 } = store.getState().configuration;
       store.dispatch(login(immobilienScout24));
     }
diff --git a/app/middleware/logging.ts b/app/middleware/logging.ts
@@ -23,7 +23,7 @@ export default (_: Store) => (next: Dispatch) => (action: Action) => {
   if (action.constructor && action.constructor.name === 'AsyncFunction') {
     const actionAsAsyncFunction = action as unknown as Function;
     // eslint-disable-next-line no-console
-    console.log(
+    logger.debug(
       `[Async Function] ${
         actionAsAsyncFunction.name ||
         (actionAsAsyncFunction.prototype &&
@@ -32,16 +32,21 @@ export default (_: Store) => (next: Dispatch) => (action: Action) => {
       }`
     );
   } else if (!blackList.includes(action.type)) {
-    let { payload, type, ...action_less } = action;
+    let { payload, type, ...other } = action;
 
+    logger.debug(`ACTION ${type}`);
+
+    let message;
     if (payload && JSON.stringify(payload).length > payloadLengthLimit) {
       payload = `${JSON.stringify(action.payload).substr(
         0,
         payloadLengthLimit
       )}...`;
+      message = `payload(short):${payload} other:`;
+    } else {
+      message = `payload:${JSON.stringify(payload)} other:`;
     }
-
-    logger.debug( 'ACTION type:%s \tpayload:%j other:%j', type, payload, action_less);
+    logger.log(message, other);
   }
 
   return next(action);
diff --git a/app/middleware/persistence.ts b/app/middleware/persistence.ts
@@ -1,3 +1,4 @@
+import { logger } from '../utils/tracer-logger.js';
 import { WAKE_UP } from '../actions/infrastructure';
 import { setConfiguration } from '../actions/configuration';
 import persistentStore from '../utils/persistentStore';
@@ -8,18 +9,19 @@ import { setCache } from '../actions/cache';
 export default (store: Store) => (next: Dispatch) => (action: Action) => {
   if (action.type === WAKE_UP) {
     // currently without reducer
+    logger.info('Load configuration...');
     const configuration = persistentStore.get('configuration');
-
     if (configuration) {
       configuration.loaded = true;
       store.dispatch(setConfiguration(configuration));
     }
 
+    logger.info('Load cache...');
     const cache = persistentStore.get('cache');
-
     if (cache) {
       store.dispatch(setCache(cache));
     }
+    logger.trace('DONE');
   }
 
   // if action contains 'cache: true' then save it before state modification
diff --git a/app/middleware/scheduler.ts b/app/middleware/scheduler.ts
@@ -2,14 +2,18 @@ import type { Action, Dispatch, Store } from '../reducers/types';
 import { LAUNCH_NEXT_TASK } from '../constants/actionTypes';
 import { navigateToFlatPage, noop, returnToSearchPage } from '../actions/bot';
 import type { schedulerStateType } from '../reducers/scheduler';
+import type { dataStateType } from '../reducers/data';
 import { endApplicationProcess } from '../actions/application';
+import { logger } from '../utils/tracer-logger.js';
 
 export default (store: Store & { dispatch: Dispatch }) =>
   (next: Dispatch) =>
   async (action: Action) => {
     const {
+      data: { overview, flat, verdicts },
       scheduler
     }: {
+      data: dataStateType;
       scheduler: schedulerStateType;
     } = store.getState();
 
@@ -21,24 +25,33 @@ export default (store: Store & { dispatch: Dispatch }) =>
       }
 
       if (scheduler.queuedFlatIds.length === 0) {
-        setTimeout(
-          () => {
-            store.dispatch(returnToSearchPage(true));
-          },
-          60000 + Math.random() * 300000
+        // this is the seach-loop: if no investigation is scheduled, after a delay, we reload the (same) search page, which eventually will trigger launchNextTask
+        // try to be non-botty and wait between 1 and 6 minutes
+        const delay = 60_000 + Math.random() * 300_000;
+        setTimeout(() => {
+          store.dispatch(returnToSearchPage(true));
+        }, delay);
+        logger.trace(
+          `No investigation scheduled. Reload search page in ${delay / 1000}s`
         );
         return next(noop());
       }
 
-      const nextFlatId = scheduler.queuedFlatIds[0];
       const result = next(action);
+
+      const nextFlatId = scheduler.queuedFlatIds[0];
+      logger.debug(`Queue:${scheduler.queuedFlatIds}`);
+      logger.info(`Next Task: Wohnung ${nextFlatId} genauer anschauen...`);
+      if (!Object.keys(overview).includes(nextFlatId)) {
+        logger.warn('Current flat is not in overview!');
+      }
       const reachedFlatPage = await store.dispatch(
         navigateToFlatPage(nextFlatId)
       );
 
       if (!reachedFlatPage) {
         // eslint-disable-next-line no-console
-        console.error(`Flat page wasn't reached, aborting task.`);
+        logger.error(`Flat page wasn't reached, aborting task.`);
         store.dispatch(endApplicationProcess());
       }
 
diff --git a/app/reducers/configuration.ts b/app/reducers/configuration.ts
diff --git a/app/reducers/electron.ts b/app/reducers/electron.ts
diff --git a/app/reducers/index.ts b/app/reducers/index.ts
diff --git a/app/store/configureStore.ts b/app/store/configureStore.ts
diff --git a/app/utils/tracer-logger.js b/app/utils/tracer-logger.js
