fix: Debug logging in File.ts works; better logging (#2472)

* fix: Enable logging to work in File.ts, by delaying creation to execution

* refactor: Extract function getFileLogger()

* chore: Logging now shows inputs to replaceTaskWithTasks()

* chore: Task logging is now debug(), not trace() - to match file-writing

* chore: Add more logging to QueryRenderer

* refactor: . Extract function logStartOfTaskEdit()

* refactor: . Extract function logEndOfTaskEdit()

* refactor: . Move logStartOfTaskEdit() & logEndOfTaskEdit() to LogTasksHelper.ts

Preparing to re-use them.

* fix: Remove accidental hard-coded string

* chore: Add more detailed logging to Task.toggle()

* refactor: . Move logging of task line number to logStartOfTaskEdit()

And add quotes around the file name.

* jsdoc: Document functions in LogTasksHelper.ts

* comment: Document intended alignment of debug output

src/File.ts

@@ -3,14 +3,19 @@ import { GlobalFilter } from './Config/GlobalFilter';
 import { type MockListItemCache, type MockTask, saveMockDataForTesting } from './lib/MockDataCreator';
 import type { Task } from './Task';
 import { logging } from './lib/logging';
+import { logEndOfTaskEdit, logStartOfTaskEdit } from './lib/LogTasksHelper';
 
 let metadataCache: MetadataCache | undefined;
 let vault: Vault | undefined;
 let workspace: Workspace | undefined;
 
 const supportedFileExtensions = ['md'];
 
-const logger = logging.getLogger('tasks.File');
+function getFileLogger() {
+    // For logging to actually produce debug output when enabled in settings,
+    // it appears that the logger cannot be created until execution time.
+    return logging.getLogger('tasks.File');
+}
 
 export type ErrorLoggingFunction = (message: string) => void;
 
@@ -55,7 +60,10 @@ export const replaceTaskWithTasks = async ({
         newTasks = [newTasks];
     }
 
-    logger.debug(`replaceTaskWithTasks entered. ${originalTask.path}`);
+    const logger = getFileLogger();
+    const codeLocation = 'replaceTaskWithTasks()';
+    logStartOfTaskEdit(logger, codeLocation, originalTask);
+    logEndOfTaskEdit(logger, codeLocation, newTasks);
 
     tryRepetitive({
         originalTask,
@@ -78,6 +86,7 @@ function warnAndNotice(message: string) {
 }
 
 function debugLog(message: string) {
+    const logger = getFileLogger();
     logger.debug(message);
 }
 
@@ -107,6 +116,7 @@ const tryRepetitive = async ({
     workspace: Workspace;
     previousTries: number;
 }): Promise<void> => {
+    const logger = getFileLogger();
     logger.debug(`tryRepetitive after ${previousTries} previous tries`);
     const retry = () => {
         if (previousTries > 10) {
@@ -281,6 +291,7 @@ function tryFindingExactMatchAtOriginalLineNumber(originalTask: Task | MockTask,
     const originalTaskLineNumber = originalTask.taskLocation.lineNumber;
     if (isValidLineNumber(originalTaskLineNumber, fileLines)) {
         if (fileLines[originalTaskLineNumber] === originalTask.originalMarkdown) {
+            const logger = getFileLogger();
             logger.debug(`Found original markdown at original line number ${originalTaskLineNumber}`);
             return originalTaskLineNumber;
         }

src/QueryRenderer.ts

@@ -174,7 +174,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
-        this.query.debug(`Render called: plugin state: ${state}; searching ${tasks.length} tasks`);
+        this.query.debug(`[render] Render called: plugin state: ${state}; searching ${tasks.length} tasks`);
 
         if (this.query.layoutOptions.explainQuery) {
             this.createExplanation(content);
@@ -192,7 +192,7 @@ class QueryRenderChild extends MarkdownRenderChild {
         const totalTasksCount = queryResult.totalTasksCount;
         this.addTaskCount(content, queryResult);
 
-        this.query.debug(`${totalTasksCount} tasks displayed`);
+        this.query.debug(`[render] ${totalTasksCount} tasks displayed`);
     }
 
     private renderErrorMessage(content: HTMLDivElement, errorMessage: string) {
@@ -490,21 +490,24 @@ class QueryRenderChild extends MarkdownRenderChild {
 
         const { postponedDate, newTasks } = createPostponedTask(task, dateTypeToUpdate, timeUnit, amount);
 
+        this.query.debug('[postpone]: getOnClickCallback() - before call to replaceTaskWithTasks()');
         await replaceTaskWithTasks({
             originalTask: task,
             newTasks,
         });
-
+        this.query.debug('[postpone]: getOnClickCallback() - after  call to replaceTaskWithTasks()');
         this.onPostponeSuccessCallback(button, dateTypeToUpdate, postponedDate);
     }
 
     private onPostponeSuccessCallback(button: HTMLButtonElement, updatedDateType: HappensDate, postponedDate: Moment) {
+        this.query.debug('[postpone]: onPostponeSuccessCallback() entered');
         // Disable the button to prevent update error due to the task not being reloaded yet.
         button.disabled = true;
         button.setAttr('title', 'You can perform this action again after reloading the file.');
 
         const successMessage = postponementSuccessMessage(postponedDate, updatedDateType);
         new Notice(successMessage, 5000);
         this.events.triggerRequestCacheUpdate(this.render.bind(this));
+        this.query.debug('[postpone]: onPostponeSuccessCallback() exiting');
     }
 }

src/Task.ts

@@ -13,6 +13,7 @@ import { StatusType } from './StatusConfiguration';
 import { TasksFile } from './Scripting/TasksFile';
 import { PriorityTools } from './lib/PriorityTools';
 import { logging } from './lib/logging';
+import { logEndOfTaskEdit, logStartOfTaskEdit } from './lib/LogTasksHelper';
 
 /**
  * When sorting, make sure low always comes after none. This way any tasks with low will be below any exiting
@@ -372,9 +373,8 @@ 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 codeLocation = 'toggle()';
+        logStartOfTaskEdit(logger, codeLocation, this);
 
         const newStatus = StatusRegistry.getInstance().getNextStatusOrCreate(this.status);
 
@@ -430,6 +430,7 @@ export class Task {
         // Write next occurrence before previous occurrence.
         newTasks.push(toggledTask);
 
+        logEndOfTaskEdit(logger, codeLocation, newTasks);
         return newTasks;
     }
 

src/lib/LogTasksHelper.ts

@@ -0,0 +1,28 @@
+import type { Task } from '../Task';
+import type { Logger } from './logging';
+
+/**
+ * Debug logging helper, for the start of Task-editing (or file-editing) operations
+ * @param logger
+ * @param codeLocation - a string description, such as 'callingFunctionName()'.
+ * @param originalTask
+ */
+export function logStartOfTaskEdit(logger: Logger, codeLocation: string, originalTask: Task) {
+    logger.debug(
+        `${codeLocation}: task line number: ${originalTask.taskLocation.lineNumber}. file path: "${originalTask.path}"`,
+    );
+    logger.debug(`${codeLocation} original: ${originalTask.originalMarkdown}`);
+}
+
+/**
+ * Debug logging helper, for the completion of Task-editing (or file-editing) operations
+ * @param logger
+ * @param codeLocation - a string description, such as 'callingFunctionName()'.
+ * @param newTasks
+ */
+export function logEndOfTaskEdit(logger: Logger, codeLocation: string, newTasks: Task[]) {
+    newTasks.map((task: Task, index: number) => {
+        // Alignment of task lines is intentionally consistent between logStartOfTaskEdit() and this:
+        logger.debug(`${codeLocation} ==> ${index + 1}   : ${task.toFileLineString()}`);
+    });
+}