Merge pull request #12304 from logseq/debug/add-tx-log

feat(rtc): add debug-log tool for rtc

src/main/frontend/handler/export.cljs

@@ -7,6 +7,7 @@
             [frontend.handler.assets :as assets-handler]
             [frontend.handler.export.common :as export-common-handler]
             [frontend.handler.notification :as notification]
+            [frontend.handler.user :as user-handler]
             [frontend.idb :as idb]
             [frontend.persist-db :as persist-db]
             [frontend.state :as state]
@@ -90,6 +91,24 @@
    (p/catch (fn [error]
               (js/console.error error)))))
 
+(defn export-repo-as-debug-log-sqlite!
+  [repo]
+  (if-not (and (state/get-auth-id-token) (user-handler/rtc-group?))
+    (notification/show! "Debug log export is limited to team members." :warning)
+    (->
+     (p/let [data (state/<invoke-db-worker-direct-pass :thread-api/export-debug-log-db repo)]
+       (if-not data
+         (notification/show! "Debug log db is not available for this graph." :warning)
+         (let [filename (file-name (str repo "_debug-log") "sqlite")
+               url (js/URL.createObjectURL (js/Blob. #js [data]))
+               anchor (.createElement js/document "a")]
+           (set! (.-href anchor) url)
+           (set! (.-download anchor) filename)
+           (.click anchor)
+           (js/URL.revokeObjectURL url))))
+     (p/catch (fn [error]
+                (js/console.error error))))))
+
 ;;;;;;;;;;;;;;;;;;;;;;;;;
 ;; Export to roam json ;;
 ;;;;;;;;;;;;;;;;;;;;;;;;;

src/main/frontend/persist_db/browser.cljs

@@ -34,7 +34,8 @@
         (->> (m/watch state/state)
              (m/eduction
               (map #(select-keys % [:git/current-repo :config
-                                    :auth/id-token :auth/access-token :auth/refresh-token]))
+                                    :auth/id-token :auth/access-token :auth/refresh-token
+                                    :user/info]))
               (dedupe)))
         <init-sync-done? (p/deferred)
         task (m/reduce

src/main/frontend/worker/db_worker.cljs

@@ -28,6 +28,7 @@
             [frontend.worker.rtc.client-op :as client-op]
             [frontend.worker.rtc.core :as rtc.core]
             [frontend.worker.rtc.db-listener]
+            [frontend.worker.rtc.debug-log :as rtc-debug-log]
             [frontend.worker.rtc.migrate :as rtc-migrate]
             [frontend.worker.search :as search]
             [frontend.worker.shared-service :as shared-service]
@@ -94,12 +95,15 @@
       nil)))
 
 (def repo-path "/db.sqlite")
+(def debug-log-path "/debug-log/db.sqlite")
 
 (defn- <export-db-file
-  [repo]
-  (p/let [^js pool (<get-opfs-pool repo)]
-    (when pool
-      (.exportFile ^js pool repo-path))))
+  ([repo]
+   (<export-db-file repo repo-path))
+  ([repo path]
+   (p/let [^js pool (<get-opfs-pool repo)]
+     (when pool
+       (.exportFile ^js pool path)))))
 
 (defn- <import-db
   [^js pool data]
@@ -153,27 +157,28 @@
       (restore-data-from-addr db addr))))
 
 (defn- close-db-aux!
-  [repo ^Object db ^Object search ^Object client-ops]
+  [repo ^Object db ^Object search ^Object client-ops ^Object debug-log]
   (swap! *sqlite-conns dissoc repo)
   (swap! *datascript-conns dissoc repo)
   (swap! *client-ops-conns dissoc repo)
   (when db (.close db))
   (when search (.close search))
   (when client-ops (.close client-ops))
+  (when debug-log (.close debug-log))
   (when-let [^js pool (worker-state/get-opfs-pool repo)]
     (.pauseVfs pool))
   (swap! *opfs-pools dissoc repo))
 
 (defn- close-other-dbs!
   [repo]
-  (doseq [[r {:keys [db search client-ops]}] @*sqlite-conns]
+  (doseq [[r {:keys [db search client-ops debug-log]}] @*sqlite-conns]
     (when-not (= repo r)
-      (close-db-aux! r db search client-ops))))
+      (close-db-aux! r db search client-ops debug-log))))
 
 (defn close-db!
   [repo]
-  (let [{:keys [db search client-ops]} (get @*sqlite-conns repo)]
-    (close-db-aux! repo db search client-ops)))
+  (let [{:keys [db search client-ops debug-log]} (get @*sqlite-conns repo)]
+    (close-db-aux! repo db search client-ops debug-log)))
 
 (defn reset-db!
   [repo db-transit-str]
@@ -198,8 +203,9 @@
                 (.unpauseVfs pool))
             db (new (.-OpfsSAHPoolDb pool) repo-path)
             search-db (new (.-OpfsSAHPoolDb pool) (str "search" repo-path))
-            client-ops-db (new (.-OpfsSAHPoolDb pool) (str "client-ops-" repo-path))]
-      [db search-db client-ops-db])))
+            client-ops-db (new (.-OpfsSAHPoolDb pool) (str "client-ops-" repo-path))
+            debug-log-db (new (.-OpfsSAHPoolDb pool) (str "debug-log" repo-path))]
+      [db search-db client-ops-db debug-log-db])))
 
 (defn- enable-sqlite-wal-mode!
   [^Object db]
@@ -208,34 +214,37 @@
 
 (defn- gc-sqlite-dbs!
   "Gc main db weekly and rtc ops db each time when opening it"
-  [sqlite-db client-ops-db datascript-conn {:keys [full-gc?]}]
+  [sqlite-db client-ops-db debug-log-db datascript-conn {:keys [full-gc?]}]
   (let [last-gc-at (:kv/value (d/entity @datascript-conn :logseq.kv/graph-last-gc-at))]
     (when (or full-gc?
               (nil? last-gc-at)
               (not (number? last-gc-at))
               (> (- (common-util/time-ms) last-gc-at) (* 3 24 3600 1000))) ; 3 days ago
-      (println :debug "gc current graph")
+      (log/info :gc-sqlite-dbs "gc current graph")
       (doseq [db (if @*publishing? [sqlite-db] [sqlite-db client-ops-db])]
         (sqlite-gc/gc-kvs-table! db {:full-gc? full-gc?})
         (.exec db "VACUUM"))
+      (rtc-debug-log/gc! debug-log-db)
       (ldb/transact! datascript-conn [{:db/ident :logseq.kv/graph-last-gc-at
                                        :kv/value (common-util/time-ms)}]))))
 
 (defn- <create-or-open-db!
   [repo {:keys [config datoms] :as opts}]
   (when-not (worker-state/get-sqlite-conn repo)
-    (p/let [[db search-db client-ops-db :as dbs] (get-dbs repo)
+    (p/let [[db search-db client-ops-db debug-log-db :as dbs] (get-dbs repo)
             storage (new-sqlite-storage db)
             client-ops-storage (when-not @*publishing?
                                  (new-sqlite-storage client-ops-db))
             db-based? true]
       (swap! *sqlite-conns assoc repo {:db db
                                        :search search-db
-                                       :client-ops client-ops-db})
+                                       :client-ops client-ops-db
+                                       :debug-log debug-log-db})
       (doseq [db' dbs]
         (enable-sqlite-wal-mode! db'))
       (common-sqlite/create-kvs-table! db)
       (when-not @*publishing? (common-sqlite/create-kvs-table! client-ops-db))
+      (rtc-debug-log/create-tables! debug-log-db)
       (search/create-tables-and-triggers! search-db)
       (ldb/register-transact-pipeline-fn!
        (fn [tx-report]
@@ -274,7 +283,7 @@
                               config (select-keys opts [:import-type :graph-git-sha]))]
             (ldb/transact! conn initial-data {:initial-db? true})))
 
-        (gc-sqlite-dbs! db client-ops-db conn {})
+        (gc-sqlite-dbs! db client-ops-db debug-log-db conn {})
 
         (let [migration-result (db-migrate/migrate conn)]
           (when (client-op/rtc-db-graph? repo)
@@ -564,6 +573,23 @@
   (p/let [data (<export-db-file repo)]
     (Comlink/transfer data #js [(.-buffer data)])))
 
+(def-thread-api :thread-api/export-debug-log-db
+  [repo]
+  (when-let [^js db (worker-state/get-sqlite-conn repo :debug-log)]
+    (.exec db "PRAGMA wal_checkpoint(2)"))
+  (-> (p/let [data (<export-db-file
+                    repo
+                    debug-log-path)]
+        (when data
+          (Comlink/transfer data #js [(.-buffer data)])))
+      (p/catch (fn [error]
+                 (throw error)))))
+
+(def-thread-api :thread-api/reset-debug-log-db
+  [repo]
+  (when-let [^js db (worker-state/get-sqlite-conn repo :debug-log)]
+    (rtc-debug-log/reset-tables! db)))
+
 (def-thread-api :thread-api/import-db
   [repo data]
   (when-not (string/blank? repo)
@@ -705,10 +731,10 @@
 
 (def-thread-api :thread-api/gc-graph
   [repo]
-  (let [{:keys [db client-ops]} (get @*sqlite-conns repo)
+  (let [{:keys [db client-ops debug-log]} (get @*sqlite-conns repo)
         conn (get @*datascript-conns repo)]
     (when (and db conn)
-      (gc-sqlite-dbs! db client-ops conn {:full-gc? true})
+      (gc-sqlite-dbs! db client-ops debug-log conn {:full-gc? true})
       nil)))
 
 (def-thread-api :thread-api/vec-search-embedding-model-info

src/main/frontend/worker/rtc/db_listener.cljs

@@ -2,6 +2,7 @@
   "listen datascript changes, infer operations from the db tx-report"
   (:require [frontend.worker.db-listener :as db-listener]
             [frontend.worker.rtc.client-op :as client-op]
+            [frontend.worker.rtc.debug-log :as rtc-debug-log]
             [frontend.worker.rtc.gen-client-op :as gen-client-op]))
 
 (comment
@@ -12,9 +13,10 @@
 (defmethod db-listener/listen-db-changes :gen-rtc-ops
   [_
    {:keys [repo same-entity-datoms-coll id->same-entity-datoms]}
-   {:keys [_tx-data tx-meta db-before db-after]}]
+   {:keys [tx-data tx-meta db-before db-after]}]
   (when (and (client-op/rtc-db-graph? repo)
              (:persist-op? tx-meta true))
+    (rtc-debug-log/log-tx! repo tx-data tx-meta)
     (let [e->a->add?->v->t (update-vals
                             id->same-entity-datoms
                             gen-client-op/entity-datoms=>a->add?->v->t)

src/main/frontend/worker/rtc/debug_log.cljs

@@ -0,0 +1,61 @@
+(ns frontend.worker.rtc.debug-log
+  "RTC debug logging stored in per-graph sqlite db."
+  (:require [frontend.worker.state :as worker-state]
+            [lambdaisland.glogi :as log]))
+
+(defn create-tables!
+  [^js db]
+  (when db
+    (.exec db "CREATE TABLE IF NOT EXISTS tx_log (id INTEGER PRIMARY KEY AUTOINCREMENT, created_at DATETIME DEFAULT CURRENT_TIMESTAMP NOT NULL, tx_data TEXT, tx_meta TEXT)")
+    (.exec db "CREATE TABLE IF NOT EXISTS messages (id INTEGER PRIMARY KEY AUTOINCREMENT, created_at DATETIME DEFAULT CURRENT_TIMESTAMP NOT NULL, direction TEXT NOT NULL, message TEXT NOT NULL)")))
+
+(defn reset-tables!
+  [^js db]
+  (when db
+    (.exec db "DROP TABLE IF EXISTS tx_log")
+    (.exec db "DROP TABLE IF EXISTS messages"))
+  (create-tables! db))
+
+(defn gc!
+  [^js db]
+  (when db
+    (doseq [table ["tx_log" "messages"]]
+      (try
+        (.exec db (str "DELETE FROM " table " WHERE id <= (SELECT id FROM " table " ORDER BY id DESC LIMIT 1 OFFSET 10000)"))
+        (catch :default e
+          (log/error :rtc-debug-log-gc-failed {:table table :error e}))))
+    (.exec db "VACUUM")))
+
+(defn- safe-str
+  [value]
+  (try
+    (pr-str value)
+    (catch :default _
+      (str value))))
+
+(defn- insert!
+  [^js db sql params]
+  (try
+    (.exec db #js {:sql sql
+                   :bind (clj->js params)})
+    (catch :default e
+      (log/error :rtc-debug-log-insert-failed e))))
+
+(defn log-tx!
+  [repo tx-data tx-meta]
+  (when repo
+    (when-let [db (worker-state/get-sqlite-conn repo :debug-log)]
+      (insert! db
+               "INSERT INTO tx_log (tx_data, tx_meta) VALUES (?1, ?2)"
+               [(safe-str tx-data) (safe-str tx-meta)])
+      (log/debug :log-tx tx-meta))))
+
+(defn log-ws-message!
+  ([direction message]
+   (log-ws-message! (worker-state/get-current-repo) direction message))
+  ([repo direction message]
+   (when (and repo message)
+     (when-let [db (worker-state/get-sqlite-conn repo :debug-log)]
+       (insert! db
+                "INSERT INTO messages (direction, message) VALUES (?1, ?2)"
+                [(name direction) (str message)])))))

src/main/frontend/worker/rtc/ws.cljs

@@ -5,6 +5,7 @@
   (:require [cljs-http-missionary.client :as http]
             [frontend.common.missionary :as c.m]
             [frontend.worker.flows :as worker-flows]
+            [frontend.worker.rtc.debug-log :as rtc-debug-log]
             [frontend.worker.rtc.exception :as r.ex]
             [frontend.worker.rtc.malli-schema :as rtc-schema]
             [missionary.core :as m]))
@@ -137,6 +138,7 @@
   (m/sp
     (let [decoded-message (rtc-schema/data-to-ws-coercer message)
           message-str (js/JSON.stringify (clj->js (rtc-schema/data-to-ws-encoder decoded-message)))]
+      (rtc-debug-log/log-ws-message! :send message-str)
       (m/? ((:send mws) message-str)))))
 
 (defn- recv-flow*
@@ -144,6 +146,9 @@
   [m-ws]
   (assert (some? (:recv-flow m-ws)) m-ws)
   (m/eduction
+   (map (fn [message]
+          (rtc-debug-log/log-ws-message! :recv message)
+          message))
    (map #(js->clj (js/JSON.parse %) :keywordize-keys true))
    (map (fn [m]
           (if (contains?

src/main/frontend/worker/state.cljs

@@ -38,6 +38,8 @@
                        :auth/access-token nil
                        :auth/refresh-token nil
 
+                       :user/info nil
+
                        :rtc/downloading-graph? false
 
                        ;; thread atoms, these atoms' value are syncing from ui-thread
@@ -46,7 +48,7 @@
 (defonce *rtc-ws-url (atom nil))
 
 (defonce *sqlite (atom nil))
-;; repo -> {:db conn :search conn :client-ops conn}
+;; repo -> {:db conn :search conn :client-ops conn :debug-log conn}
 (defonce *sqlite-conns (atom {}))
 ;; repo -> conn
 (defonce *datascript-conns (atom nil))
@@ -61,7 +63,7 @@
 (defn get-sqlite-conn
   ([repo] (get-sqlite-conn repo :db))
   ([repo which-db]
-   (assert (contains? #{:db :search :client-ops} which-db) which-db)
+   (assert (contains? #{:db :search :client-ops :debug-log} which-db) which-db)
    (get-in @*sqlite-conns [repo which-db])))
 
 (defn get-datascript-conn

src/main/logseq/api.cljs

@@ -83,6 +83,8 @@
 (def ^:export clear_right_sidebar_blocks api-app/clear_right_sidebar_blocks)
 (def ^:export push_state api-app/push_state)
 (def ^:export replace_state api-app/replace_state)
+(def ^:export export_debug_log_db api-app/export_debug_log_db)
+(def ^:export reset_debug_log_db api-app/reset_debug_log_db)
 
 ;; db
 (def ^:export q api-db/q)

src/main/logseq/api/app.cljs

@@ -8,6 +8,7 @@
             [frontend.db.utils :as db-utils]
             [frontend.handler.command-palette :as palette-handler]
             [frontend.handler.config :as config-handler]
+            [frontend.handler.export :as export-handler]
             [frontend.handler.plugin :as plugin-handler]
             [frontend.handler.recent :as recent-handler]
             [frontend.handler.route :as route-handler]
@@ -172,3 +173,13 @@
       (if-let [page-name (and page? (:name params))]
         (route-handler/redirect-to-page! page-name {:anchor (:anchor query) :push false})
         (rfe/replace-state k params query)))))
+
+(def export_debug_log_db
+  (fn []
+    (when-let [repo (state/get-current-repo)]
+      (export-handler/export-repo-as-debug-log-sqlite! repo))))
+
+(def reset_debug_log_db
+  (fn []
+    (when-let [repo (state/get-current-repo)]
+      (state/<invoke-db-worker-direct-pass :thread-api/reset-debug-log-db repo))))