chore(logging): some optional debug logging

yjs and editor update logging can be very verbose.
Uncomment it but keep it disabled by default.

Can be enabled by setting the corresponding key in OCA.Text - i.e.
`window.OCA.Text.logWebSocketPolyfill = true`
in the browser console.

Signed-off-by: Max <[email protected]>

Author: max-nextcloud

src/components/Editor.vue

@@ -410,13 +410,13 @@ export default defineComponent({
 			if (!val) {
 				return
 			}
-			console.debug('Document is outdated')
+			logger.debug('Document is outdated')
 			if (this.dirty) {
-				console.debug('There are local edits, need to resolve conflict')
+				logger.debug('There are local edits, need to resolve conflict')
 				// handle conflict between active editing session and offline content
 			} else {
 				// clear the outdated cached content and reload without it.
-				console.debug(
+				logger.debug(
 					'No local edits... clearing storage and reloading the editor',
 				)
 				this.clearIndexedDb().then(() => {
@@ -442,8 +442,16 @@ export default defineComponent({
 	created() {
 		// The following can be useful for debugging ydoc updates
 		this.ydoc.on('update', function (update, origin, doc, tr) {
-			console.debug('ydoc update', update, origin, doc, tr)
-			logUpdate(update)
+			if (window.OCA.Text.logYjsUpdates) {
+				logger.debug('ydoc update', {
+					update,
+					origin,
+					doc,
+					tr,
+					content: doc.getXmlFragment('default').toJSON(),
+				})
+				logUpdate(update)
+			}
 		})
 		this.$attachmentResolver = null
 		if (this.active && this.hasDocumentParameters) {
@@ -452,6 +460,7 @@ export default defineComponent({
 		}
 	},
 	async beforeDestroy() {
+		logger.debug('beforeDestroy')
 		if (!this.richWorkspace) {
 			window.removeEventListener('beforeprint', this.preparePrinting)
 			window.removeEventListener('afterprint', this.preparePrinting)
@@ -556,6 +565,10 @@ export default defineComponent({
 			this.lowlightLoaded.then(() => {
 				this.syncService.startSync()
 				if (!documentState) {
+					logger.debug('loading initial content', {
+						content,
+						isRichEditor: this.isRichEditor,
+					})
 					setInitialYjsState(this.ydoc, content, {
 						isRichEditor: this.isRichEditor,
 					})
@@ -579,7 +592,9 @@ export default defineComponent({
 		},
 
 		onUpdate({ editor }) {
-			// this.debugContent(editor)
+			if (window.OCA.Text.logEditorUpdates) {
+				this.debugContent(editor)
+			}
 			const proseMirrorMarkdown = this.serialize()
 			this.emit('update:content', {
 				markdown: proseMirrorMarkdown,
@@ -651,7 +666,6 @@ export default defineComponent({
 			if (Object.prototype.hasOwnProperty.call(state, 'dirty')) {
 				// ignore initial loading and other automated changes before first user change
 				if (this.editor.can().undo() || this.editor.can().redo()) {
-					console.debug('Setting dirty to', state.dirty)
 					this.setDirty(state.dirty)
 					if (this.dirty) {
 						this.saveService.autosave()
@@ -707,6 +721,7 @@ export default defineComponent({
 		},
 
 		async disconnect() {
+			logger.debug('disconnecting')
 			await this.syncService.close()
 			this.unlistenSyncServiceEvents()
 			this.syncProvider?.destroy()
@@ -715,11 +730,13 @@ export default defineComponent({
 		},
 
 		async close() {
+			logger.debug('closing')
 			await this.syncService
 				.sendRemainingSteps()
 				.catch((err) =>
 					logger.warn('Failed to send remaining steps', { err }),
 				)
+			logger.debug('sent remaining steps')
 			await this.disconnect().catch((err) =>
 				logger.warn('Failed to disconnect', { err }),
 			)
@@ -767,17 +784,18 @@ export default defineComponent({
 		 * @param {object} editor The Tiptap editor
 		 */
 		debugContent(editor) {
+			// markdown, serialized from editor state by prosemirror-markdown
 			const proseMirrorMarkdown = this.serialize()
+			// HTML, serialized from markdown by markdown-it
 			const markdownItHtml = markdownit.render(proseMirrorMarkdown)
+			// HTML, as rendered in the browser by Tiptap
+			const tiptapHtml = editor.getHTML()
 
-			logger.debug(
-				'markdown, serialized from editor state by prosemirror-markdown',
-			)
-			console.debug(proseMirrorMarkdown)
-			logger.debug('HTML, serialized from markdown by markdown-it')
-			console.debug(markdownItHtml)
-			logger.debug('HTML, as rendered in the browser by Tiptap')
-			console.debug(editor.getHTML())
+			logger.debug('editor update', {
+				proseMirrorMarkdown,
+				markdownItHtml,
+				tiptapHtml,
+			})
 		},
 
 		/**

src/composables/useIndexedDbProvider.ts

@@ -6,6 +6,7 @@
 import { readonly, ref } from 'vue'
 import { IndexeddbPersistence } from 'y-indexeddb'
 import type { Doc } from 'yjs'
+import { logger } from '../helpers/logger.js'
 
 /**
  * Initialize a indexed db provider for the given ydoc
@@ -21,8 +22,11 @@ export function useIndexedDbProvider(
 ) {
 	const name = `${props.fileId}`
 	const indexedDbProvider = new IndexeddbPersistence(name, ydoc)
-	indexedDbProvider.on('synced', (provider: IndexeddbPersistence) => {
-		console.info('synced from indexeddb', provider)
+	indexedDbProvider.on('synced', async (provider: IndexeddbPersistence) => {
+		logger.info('synced from indexeddb', {
+			dirty: await provider.get('dirty'),
+			baseVersionEtag: await provider.get('baseVersionEtag'),
+		})
 	})
 	const dirty = ref(false)
 	indexedDbProvider.get('dirty').then((val) => {
@@ -58,6 +62,7 @@ export function useIndexedDbProvider(
 	 * Used to reset the browser state to load a new editing session.
 	 */
 	function clearIndexedDb() {
+		logger.info('clearing indexeddb')
 		return indexedDbProvider.clearData()
 	}
 

src/helpers/debug.js

@@ -11,6 +11,11 @@ if (!window.OCA.Text) {
 	window.OCA.Text = {}
 }
 
+// These can be changed in the browser console for more verbose logging.
+window.OCA.Text.logEditorUpdates = false
+window.OCA.Text.logWebSocketPolyfill = false
+window.OCA.Text.logYjsUpdates = false
+
 const editorComponents = window.OCA.Text.editorComponents ?? new Set()
 window.OCA.Text.editorComponents = editorComponents
 

src/helpers/logger.js renamed to src/helpers/logger.ts

@@ -10,6 +10,13 @@ import { stepsFromOpenData } from '../helpers/yjs'
 import getNotifyBus from './NotifyService'
 import type { Step, SyncService } from './SyncService'
 
+// Optional debug logging if window.OCA.Text.logWebSocketPolyfill is set.
+const debug = (message: string, context: object) => {
+	if (window.OCA?.Text?.logWebSocketPolyfill) {
+		debug(message, context)
+	}
+}
+
 /**
  *
  * @param syncService - the sync service to build upon
@@ -35,9 +42,10 @@ export default function initWebSocketPolyfill(
 			this.#notifyPushBus = getNotifyBus()
 			this.#notifyPushBus?.on('notify_push', this.#onNotifyPush.bind(this))
 			this.#url = url
-			logger.debug('WebSocketPolyfill#constructor', { url, fileId })
+			debug('WebSocketPolyfill#constructor', { url, fileId })
 
 			this.#onOpened = (data: OpenData) => {
+				debug('WebSocketPolyfill#onOpen', { data })
 				if (syncService.hasActiveConnection()) {
 					this.onopen?.()
 				}
@@ -46,9 +54,10 @@ export default function initWebSocketPolyfill(
 			syncService.bus.on('opened', this.#onOpened)
 
 			this.#onSync = ({ steps }: { steps: Step[] }) => {
+				debug('WebSocketPolyfill#onSync', { steps })
 				if (steps) {
 					this.#processSteps(steps)
-					logger.debug('synced ', {
+					debug('synced ', {
 						version: syncService.version,
 						steps,
 					})
@@ -95,7 +104,7 @@ export default function initWebSocketPolyfill(
 			// If `this.#processingVersion` is set, we're in the middle of applying steps of one version.
 			// If `isSyncStep1`, Yjs failed to integrate a message due to pending structs.
 			// Log and ask for recovery due to a not applied/missing step.
-			console.error(`Failed to process step ${this.#processingVersion}.`, {
+			logger.error(`Failed to process step ${this.#processingVersion}.`, {
 				lastSuccessfullyProcessed: syncService.version,
 				sendingSyncStep1: step,
 			})
@@ -110,14 +119,15 @@ export default function initWebSocketPolyfill(
 			syncService.bus.off('opened', this.#onOpened)
 			this.#notifyPushBus?.off('notify_push', this.#onNotifyPush.bind(this))
 			this.onclose?.(new CloseEvent('closing'))
-			logger.debug('Websocket closed')
+			debug('Websocket closed')
 		}
 
 		#onNotifyPush({
 			messageBody,
 		}: {
 			messageBody: { documentId: number; steps: string[] }
 		}) {
+			debug('WebSocketPolyfill#onNotifyPush', messageBody)
 			if (messageBody.documentId !== fileId) {
 				return
 			}