Repository: obsidian-tasks-group/obsidian-tasks (ts)

Issue:
Allow control of level of detail in logging messages
### Description

There is currently no way for users and developers to control the logging level in Tasks.

And some of the current debug output is unwanted.

In the first instance, provide a way for users to edit the settings, and change the logging level for different areas of Tasks.

A later, safer feature would be to add UI in Settings to control the debug output leves.

### Required Steps

- Review the changes to `src/Config/Settings.ts` in #1851 and pull them in as a new PR.
- Define some logger names and apply them to the existing code

### How to Test

_No response_
Make logging console messages toggle-able
### Discussed in https://github.com/obsidian-tasks-group/obsidian-tasks/discussions/1126

<div type='discussions-op-text'>

<sup>Originally posted by **lguenth** September  7, 2022</sup>
Hello Tasks team,
I've been really enjoying this plugin. It's completely replaced any external apps I was using. 

However, there is one minor detail I wish I could change: being able to turn off the constantly logged messages in console. Would it be possible to hide these with a setting? I could look into implementing this myself if this is something you would consider for approval.</div>

Pull request description:
feat: Add optional debug logging of searches and file handling
<!--- Provide a general summary of your changes in the Title above -->

# Description

Add some systematic debug logging of Tasks behaviour.

To turn this debug output on:

1. Run a new build of Tasks
2. Open Tasks Settings - this will add some new settings values to `.obsidian/plugins/obsidian-tasks-plugin/data.json`
3. Quit Obsidian
4. Edit the `loggingOptions` values: change `info` to one of the `ILogLevel` names in [src/lib/logging.ts](https://github.com/obsidian-tasks-group/obsidian-tasks/blob/main/src/lib/logging.ts) - in this case, change to `debug` to turn on the new debug output
5. Restart Obsidian and show the developer console
6. On mobile, the [Logstravaganza](https://github.com/czottmann/obsidian-logstravaganza) plugin may help - it should be enabled before Tasks is turned on.

I am unsure whether to document this, at this stage: it shows up some really obvious performance problems, and I am slightly minded to fix those first, and also invite its use in response to user support queries.

## Motivation and Context

Fixes #2159
- #2159

Fixes #2160
- #2160

Fixes #1126
- #1126


<!--- Why is this change required? What problem does it solve? -->
<!--- If it fixes an open issue, please link to the issue here. -->

## How has this been tested?

- Lots of manual testing in the Demo Vault
- A new test added

<!--- Please describe in detail how you tested your changes. -->
<!--- Include details of your testing environment, tests ran to see how -->
<!--- your change affects other areas of the code, etc. -->

## Screenshots (if appropriate)

Here is some sample output, with just `tasks.Query` set to `debug`. The unique `[id]` allows filtering in the console to follow the behaviour of a particular Tasks code block.

![image](https://github.com/obsidian-tasks-group/obsidian-tasks/assets/4840096/b1765bb1-89e8-49bc-b591-46d94dddd392)




## Types of changes

<!--- What types of changes does your code introduce? Put an `x` in all the boxes that apply: -->

Changes visible to users:

- [x] **New feature** (prefix: `feat` - non-breaking change which adds functionality)

Internal changes:

- [x] **Tests** (prefix: `test` - additions and improvements to unit tests and the smoke tests)

## Checklist

<!--- Go over all the following points, and put an `x` in all the boxes that apply. -->
<!--- If you're unsure about any of these, don't hesitate to ask. We're here to help! -->

- [x] My code follows the code style of this project and passes `yarn run lint`.
- [ ] My change requires a change to the documentation.
- [ ] I have [updated the documentation](https://publish.obsidian.md/tasks-contributing/Documentation/About+Documentation) accordingly.
- [x] My change has adequate [Unit Test coverage](https://publish.obsidian.md/tasks-contributing/Testing/About+Testing).

## Terms

<!--
By submitting this pull request, you must agree to follow our
[contributing guide](https://publish.obsidian.md/tasks-contributing) and
[Code of Conduct](https://github.com/obsidian-tasks-group/obsidian-tasks/blob/main/CODE_OF_CONDUCT.md).
Put an x in the boxes to confirm you agree.
-->

- [x] My contribution follow this project's [contributing guide](https://publish.obsidian.md/tasks-contributing)
- [x] I agree to follow this project's [Code of Conduct](https://github.com/obsidian-tasks-group/obsidian-tasks/blob/main/CODE_OF_CONDUCT.md)


Patch:
diff --git a/src/Cache.ts b/src/Cache.ts
index 278b96df..67ec1529 100644
--- a/src/Cache.ts
+++ b/src/Cache.ts
@@ -10,6 +10,7 @@ import { getSettings } from './Config/Settings';
 import { Lazy } from './lib/Lazy';
 import { TaskLocation } from './TaskLocation';
 // import { logging } from './lib/logging';
+import { logging } from './lib/logging';
 
 export enum State {
     Cold = 'Cold',
@@ -17,9 +18,9 @@ export enum State {
     Warm = 'Warm',
 }
 
-// const logger = logging.getLogger('tasks');
-
 export class Cache {
+    logger = logging.getLogger('tasks.Cache');
+
     private readonly metadataCache: MetadataCache;
     private readonly metadataCacheEventReferences: EventRef[];
     private readonly vault: Vault;
@@ -42,6 +43,8 @@ export class Cache {
     private loadedAfterFirstResolve: boolean;
 
     constructor({ metadataCache, vault, events }: { metadataCache: MetadataCache; vault: Vault; events: TasksEvents }) {
+        this.logger.debug('Creating Cache object');
+
         this.metadataCache = metadataCache;
         this.metadataCacheEventReferences = [];
         this.vault = vault;
@@ -51,6 +54,8 @@ export class Cache {
 
         this.tasksMutex = new Mutex();
         this.state = State.Cold;
+        this.logger.debug('Cache.constructor(): state = Cold');
+
         this.tasks = [];
 
         this.loadedAfterFirstResolve = false;
@@ -63,6 +68,8 @@ export class Cache {
     }
 
     public unload(): void {
+        this.logger.info('Unloading Cache');
+
         for (const eventReference of this.metadataCacheEventReferences) {
             this.metadataCache.offref(eventReference);
         }
@@ -85,6 +92,7 @@ export class Cache {
     }
 
     private notifySubscribers(): void {
+        this.logger.debug('Cache.notifySubscribers()');
         this.events.triggerCacheUpdate({
             tasks: this.tasks,
             state: this.state,
@@ -92,6 +100,7 @@ export class Cache {
     }
 
     private subscribeToCache(): void {
+        this.logger.debug('Cache.subscribeToCache()');
         const resolvedEventeReference = this.metadataCache.on('resolved', async () => {
             // Resolved fires on every change.
             // We only want to initialize if we haven't already.
@@ -112,12 +121,14 @@ export class Cache {
     }
 
     private subscribeToVault(): void {
+        this.logger.debug('Cache.subscribeToVault()');
         const { useFilenameAsScheduledDate } = getSettings();
 
         const createdEventReference = this.vault.on('create', (file: TAbstractFile) => {
             if (!(file instanceof TFile)) {
                 return;
             }
+            this.logger.debug(`Cache.subscribeToVault.createdEventReference() ${file.path}`);
 
             this.tasksMutex.runExclusive(() => {
                 this.indexFile(file);
@@ -129,6 +140,7 @@ export class Cache {
             if (!(file instanceof TFile)) {
                 return;
             }
+            this.logger.debug(`Cache.subscribeToVault.deletedEventReference() ${file.path}`);
 
             this.tasksMutex.runExclusive(() => {
                 this.tasks = this.tasks.filter((task: Task) => {
@@ -144,6 +156,7 @@ export class Cache {
             if (!(file instanceof TFile)) {
                 return;
             }
+            this.logger.debug(`Cache.subscribeToVault.renamedEventReference() ${file.path}`);
 
             this.tasksMutex.runExclusive(() => {
                 const fallbackDate = new Lazy(() => DateFallback.fromPath(file.path));
@@ -170,6 +183,7 @@ export class Cache {
     }
 
     private subscribeToEvents(): void {
+        this.logger.debug('Cache.subscribeToEvents()');
         const requestReference = this.events.onRequestCacheUpdate((handler) => {
             handler({ tasks: this.tasks, state: this.state });
         });
@@ -177,14 +191,20 @@ export class Cache {
     }
 
     private loadVault(): Promise<void> {
+        this.logger.debug('Cache.loadVault()');
         return this.tasksMutex.runExclusive(async () => {
             this.state = State.Initializing;
+            this.logger.debug('Cache.loadVault(): state = Initializing');
+
             await Promise.all(
                 this.vault.getMarkdownFiles().map((file: TFile) => {
                     return this.indexFile(file);
                 }),
             );
             this.state = State.Warm;
+            // TODO Why is this displayed twice:
+            this.logger.debug('Cache.loadVault(): state = Warm');
+
             // Notify that the cache is now warm:
             this.notifySubscribers();
         });
@@ -196,6 +216,12 @@ export class Cache {
             return;
         }
 
+        if (!file.path.endsWith('.md')) {
+            this.logger.warn('indexFile: WARNING: indexing non-markdown file: ' + file.path);
+        }
+
+        this.logger.debug('Cache.indexFile: ' + file.path);
+
         const oldTasks = this.tasks.filter((task: Task) => {
             return task.path === file.path;
         });
@@ -217,7 +243,7 @@ export class Cache {
             // This code kept for now, to allow for debugging during development.
             // It is too verbose to release to users.
             // if (this.getState() == State.Warm) {
-            //     console.debug(`Tasks unchanged in ${file.path}`);
+            //     this.logger.debug(`Tasks unchanged in ${file.path}`);
             // }
             return;
         }
@@ -225,8 +251,8 @@ export class Cache {
         // Temporary edit - See https://github.com/obsidian-tasks-group/obsidian-tasks/issues/2160
         /*
         if (this.getState() == State.Warm) {
-            // logger.debug(`Cache read: ${file.path}`);
-            console.debug(
+            // this.logger.debug(`Cache read: ${file.path}`);
+            this.logger.debug(
                 `At least one task, its line number or its heading has changed in ${file.path}: triggering a refresh of all active Tasks blocks in Live Preview and Reading mode views.`,
             );
         }
@@ -239,6 +265,7 @@ export class Cache {
         });
 
         this.tasks.push(...newTasks);
+        this.logger.debug('Cache.indexFile: ' + file.path + `: read ${newTasks.length} task(s)`);
 
         // All updated, inform our subscribers.
         this.notifySubscribers();
@@ -255,7 +282,7 @@ export class Cache {
         const linesInFile = fileLines.length;
 
         // Lazily store date extracted from filename to avoid parsing more than needed
-        // console.debug(`getTasksFromFileContent() reading ${file.path}`);
+        // this.logger.debug(`getTasksFromFileContent() reading ${file.path}`);
         const dateFromFileName = new Lazy(() => DateFallback.fromPath(file.path));
 
         // We want to store section information with every task so
@@ -278,7 +305,7 @@ export class Cache {
                         when Obsidian started up, it got the new file content, but still had the old cached
                         data about locations of list items in the file.
                      */
-                    console.log(
+                    this.logger.debug(
                         `${file.path} Obsidian gave us a line number ${lineNumber} past the end of the file. ${linesInFile}.`,
                     );
                     return tasks;
@@ -297,7 +324,7 @@ export class Cache {
 
                 const line = fileLines[lineNumber];
                 if (line === undefined) {
-                    console.log(`${file.path}: line ${lineNumber} - ignoring 'undefined' line.`);
+                    this.logger.debug(`${file.path}: line ${lineNumber} - ignoring 'undefined' line.`);
                     continue;
                 }
 
@@ -349,9 +376,9 @@ The error popup will only be shown when Tasks is starting up, but if the error p
 it will be shown in the console every time this file is edited during the Obsidian
 session.
 `;
-        console.error(msg);
+        this.logger.error(msg);
         if (e instanceof Error) {
-            console.error(e.stack);
+            this.logger.error(e.stack ? e.stack : 'Cannot determine stack');
         }
         if (this.state === State.Initializing) {
             new Notice(msg, 10000);
diff --git a/src/Config/Settings.ts b/src/Config/Settings.ts
index 4f5e8c2c..30338e31 100644
--- a/src/Config/Settings.ts
+++ b/src/Config/Settings.ts
@@ -131,13 +131,25 @@ const defaultSettings: Settings = {
         minLevels: {
             '': 'info',
             tasks: 'info',
-            Query: 'info',
+            'tasks.Cache': 'info', // Cache.ts
+            'tasks.Events': 'info', // TasksEvents.ts
+            'tasks.File': 'info', // File.ts
+            'tasks.Query': 'info', // Query.ts & QueryRenderer.ts
+            'tasks.Task': 'info', // Task.ts
         },
     },
 };
 
 let settings: Settings = { ...defaultSettings };
 
+function addNewOptionsToUserSettings<KeysAndValues>(defaultValues: KeysAndValues, userValues: KeysAndValues) {
+    for (const flag in defaultValues) {
+        if (userValues[flag] === undefined) {
+            userValues[flag] = defaultValues[flag];
+        }
+    }
+}
+
 /**
  * Returns the current settings as a object, it will also check and
  * update the flags to make sure they are all shown in the data.json
@@ -148,11 +160,10 @@ let settings: Settings = { ...defaultSettings };
  */
 export const getSettings = (): Settings => {
     // Check to see if there is a new flag and if so add it to the users settings.
-    for (const flag in Feature.settingsFlags) {
-        if (settings.features[flag] === undefined) {
-            settings.features[flag] = Feature.settingsFlags[flag];
-        }
-    }
+    addNewOptionsToUserSettings(Feature.settingsFlags, settings.features);
+
+    // Check to see if any new logging options need to be added to the user's settings.
+    addNewOptionsToUserSettings(defaultSettings.loggingOptions.minLevels, settings.loggingOptions.minLevels);
 
     // In case saves pre-dated StatusConfiguration.type
     // TODO Special case for symbol 'X' or 'x' (just in case)
diff --git a/src/File.ts b/src/File.ts
index 914cec04..7d25e4e6 100644
--- a/src/File.ts
+++ b/src/File.ts
@@ -10,7 +10,7 @@ let workspace: Workspace | undefined;
 
 const supportedFileExtensions = ['md'];
 
-const logger = logging.getLogger('tasks');
+const logger = logging.getLogger('tasks.File');
 
 export type ErrorLoggingFunction = (message: string) => void;
 
diff --git a/src/IQuery.ts b/src/IQuery.ts
index 31a9e41f..5e7d1ef1 100644
--- a/src/IQuery.ts
+++ b/src/IQuery.ts
@@ -67,4 +67,14 @@ export interface IQuery {
      * This is currently displayed as a <pre> block, retaining indentation.
      */
     explainQuery: () => string;
+
+    /**
+     * Write a debug log message.
+     *
+     * This is provided to allow the query rendering code to log progress on the rendering,
+     * including meaningful information about the query being rendered.
+     * @param message
+     * @param objects
+     */
+    debug(message: string, objects?: any): void;
 }
diff --git a/src/Query/Query.ts b/src/Query/Query.ts
index 30fb2e04..d486e69d 100644
--- a/src/Query/Query.ts
+++ b/src/Query/Query.ts
@@ -50,8 +50,7 @@ export class Query implements IQuery {
         this.source = source;
         this.filePath = path;
 
-        this.logger.debugWithId(this._queryId, 'Source Path', this.filePath);
-        this.logger.infoWithId(this._queryId, 'Source Query', this.source);
+        this.debug(`Creating query: ${this.formatQueryForLogging()}`);
 
         scan(source).forEach((rawLine: string) => {
             const line = this.expandPlaceholders(rawLine, path);
@@ -91,6 +90,10 @@ export class Query implements IQuery {
         });
     }
 
+    private formatQueryForLogging() {
+        return `[${this.source.split('\n').join(' ; ')}]`;
+    }
+
     private expandPlaceholders(source: string, path: string | undefined) {
         if (source.includes('{{') && source.includes('}}')) {
             if (this.filePath === undefined) {
@@ -254,7 +257,7 @@ Problem line: "${line}"`;
     }
 
     public applyQueryToTasks(tasks: Task[]): QueryResult {
-        this.logger.infoWithId(this._queryId, `Executing query: [${this.source}]`);
+        this.debug(`Executing query: ${this.formatQueryForLogging()}`);
 
         const searchInfo = new SearchInfo(this.filePath, tasks);
         try {
@@ -398,4 +401,8 @@ Problem line: "${line}"`;
         const randomString = randomArray.join('');
         return randomString;
     }
+
+    public debug(message: string, objects?: any): void {
+        this.logger.debugWithId(this._queryId, `"${this.filePath}": ${message}`, objects);
+    }
 }
diff --git a/src/QueryRenderer.ts b/src/QueryRenderer.ts
index c1fc0dee..5f41bb38 100644
--- a/src/QueryRenderer.ts
+++ b/src/QueryRenderer.ts
@@ -63,7 +63,8 @@ class QueryRenderChild extends MarkdownRenderChild {
     private readonly filePath: string;
 
     private query: IQuery;
-    private queryType: string;
+    // @ts-expect-error: TS6133: 'queryType' is declared but its value is never read
+    private queryType: string; // whilst there is only one query type, there is no point logging this value
 
     private renderEventRef: EventRef | undefined;
     private queryReloadTimeout: NodeJS.Timeout | undefined;
@@ -165,12 +166,7 @@ class QueryRenderChild extends MarkdownRenderChild {
 
     private async renderQuerySearchResults(tasks: Task[], state: State.Warm, content: HTMLDivElement) {
         // See https://github.com/obsidian-tasks-group/obsidian-tasks/issues/2160
-        const debug = false;
-        if (debug) {
-            console.debug(
-                `Render ${this.queryType} called for a block in active file "${this.filePath}", to select from ${tasks.length} tasks: plugin state: ${state}`,
-            );
-        }
+        this.query.debug(`Render called: plugin state: ${state}; searching ${tasks.length} tasks`);
 
         if (this.query.layoutOptions.explainQuery) {
             this.createExplanation(content);
@@ -186,10 +182,9 @@ class QueryRenderChild extends MarkdownRenderChild {
         await this.addAllTaskGroups(queryResult.taskGroups, content);
 
         const totalTasksCount = queryResult.totalTasksCount;
-        if (debug) {
-            console.debug(`${totalTasksCount} of ${tasks.length} tasks displayed in a block in "${this.filePath}"`);
-        }
         this.addTaskCount(content, queryResult);
+
+        this.query.debug(`${totalTasksCount} tasks displayed`);
     }
 
     private renderErrorMessage(content: HTMLDivElement, errorMessage: string) {
diff --git a/src/Task.ts b/src/Task.ts
index 6f07c12b..c8b7e428 100644
--- a/src/Task.ts
+++ b/src/Task.ts
@@ -12,6 +12,7 @@ import { TasksDate } from './Scripting/TasksDate';
 import { StatusType } from './StatusConfiguration';
 import { TasksFile } from './Scripting/TasksFile';
 import { PriorityTools } from './lib/PriorityTools';
+import { logging } from './lib/logging';
 
 /**
  * When sorting, make sure low always comes after none. This way any tasks with low will be below any exiting
@@ -366,6 +367,11 @@ export class Task {
      *
      */
     public toggle(): Task[] {
+        const logger = logging.getLogger('tasks.Task');
+        logger.trace(
+            `toggling task ${this.taskLocation.path} ${this.taskLocation.lineNumber} ${this.originalMarkdown}`,
+        );
+
         const newStatus = StatusRegistry.getInstance().getNextStatusOrCreate(this.status);
 
         let newDoneDate = null;
diff --git a/src/TasksEvents.ts b/src/TasksEvents.ts
index bcb498ff..514fb86b 100644
--- a/src/TasksEvents.ts
+++ b/src/TasksEvents.ts
@@ -2,6 +2,7 @@ import type { EventRef, Events as ObsidianEvents } from 'obsidian';
 
 import type { State } from './Cache';
 import type { Task } from './Task';
+import { logging } from './lib/logging';
 
 enum Event {
     CacheUpdate = 'obsidian-tasks-plugin:cache-update',
@@ -15,28 +16,34 @@ interface CacheUpdateData {
 
 export class TasksEvents {
     private obsidianEvents: ObsidianEvents;
+    logger = logging.getLogger('tasks.Events');
 
     constructor({ obsidianEvents }: { obsidianEvents: ObsidianEvents }) {
         this.obsidianEvents = obsidianEvents;
     }
 
     public onCacheUpdate(handler: (cacheData: CacheUpdateData) => void): EventRef {
+        this.logger.debug('TasksEvents.onCacheUpdate()');
         return this.obsidianEvents.on(Event.CacheUpdate, handler);
     }
 
     public triggerCacheUpdate(cacheData: CacheUpdateData): void {
+        this.logger.debug('TasksEvents.triggerCacheUpdate()');
         this.obsidianEvents.trigger(Event.CacheUpdate, cacheData);
     }
 
     public onRequestCacheUpdate(handler: (fn: (cacheData: CacheUpdateData) => void) => void): EventRef {
+        this.logger.debug('TasksEvents.onRequestCacheUpdate()');
         return this.obsidianEvents.on(Event.RequestCacheUpdate, handler);
     }
 
     public triggerRequestCacheUpdate(fn: (cacheData: CacheUpdateData) => void): void {
+        this.logger.debug('TasksEvents.triggerRequestCacheUpdate()');
         this.obsidianEvents.trigger(Event.RequestCacheUpdate, fn);
     }
 
     public off(eventRef: EventRef): void {
+        this.logger.debug('TasksEvents.off()');
         this.obsidianEvents.offref(eventRef);
     }
 }


Test patch:
diff --git a/tests/Config/Settings.test.ts b/tests/Config/Settings.test.ts
index d0ecb892..b1d0be98 100644
--- a/tests/Config/Settings.test.ts
+++ b/tests/Config/Settings.test.ts
@@ -1,7 +1,7 @@
 /**
  * @jest-environment jsdom
  */
-import { getSettings, isFeatureEnabled, toggleFeature } from '../../src/Config/Settings';
+import { getSettings, isFeatureEnabled, toggleFeature, updateSettings } from '../../src/Config/Settings';
 
 describe('settings-usage', () => {
     it('load default settings and validate features', () => {
@@ -24,4 +24,23 @@ describe('settings-usage', () => {
         const currentSettings = getSettings();
         expect(currentSettings.features['INTERNAL_TESTING_ENABLED_BY_DEFAULT']).toBe(false);
     });
+
+    it('should add new logging options to settings', () => {
+        // Arrange:
+        // Simulate the user have run an earlier version of Tasks with few logging options:
+        const initialLoggingOptions = {
+            minLevels: {
+                '': 'info',
+                tasks: 'info',
+            },
+        };
+        updateSettings({ loggingOptions: initialLoggingOptions });
+
+        // Act:
+        // getSettings() has responsibility for adding any new/missing settings:
+        const loggingOptions = getSettings();
+
+        // Assert:
+        expect(loggingOptions.loggingOptions.minLevels['tasks.Query']).toBeDefined();
+    });
 });