Merge pull request #1849 from neotyk/dev/event-type-logging

fix: better logging.

Author: neotyk

src/clj/athens/self_hosted/clients.clj

@@ -1,6 +1,7 @@
 (ns athens.self-hosted.clients
   "Client comms"
   (:require
+    [athens.common-events        :as common-events]
     [athens.common-events.schema :as schema]
     [athens.common.logging       :as log]
     [cognitect.transit           :as transit]
@@ -70,24 +71,26 @@
         valid-server-event?   (schema/valid-server-event? data)]
     (if (or valid-event-response?
             valid-server-event?)
-      (do
+      (let [type   (common-events/find-event-or-atomic-op-type data)
+            status (:event/status data)]
         (log/debug "Sending to username:" username
                    ", event-id:" (:event/id data)
-                   ", type:" (:event/type data)
-                   ", status:" (:event/status data))
+                   (if type
+                     (str ", type: " type)
+                     (str ", status: " status)))
         (http/send! channel (->transit data)))
       ;; TODO internal failure mode, collect in reporting
       (log/error "Not sending invalid event to username:" username
                  ", event-id:" (:event/id data)
-                 ", type:" (:event/type data)
+                 ", type:" (common-events/find-event-or-atomic-op-type data)
                  ", invalid schema:"
                  "event-response take:" (str (schema/explain-event-response data))
                  ", server-event take:" (str (schema/explain-server-event data))))))
 
 
 (defn broadcast!
   "Broadcasts event to all connected clients"
-  [{:event/keys [id type] :as event}]
-  (log/debug "Broadcasting event-id:" id "type:" type)
+  [{:event/keys [id] :as event}]
+  (log/debug "Broadcasting event-id:" id "type:" (common-events/find-event-or-atomic-op-type event))
   (doseq [client (keys @clients)]
     (send! client event)))

src/clj/athens/self_hosted/components/datascript.clj

@@ -1,6 +1,7 @@
 (ns athens.self-hosted.components.datascript
   (:require
     [athens.common-db                     :as common-db]
+    [athens.common-events                 :as common-events]
     [athens.common-events.resolver.atomic :as atomic]
     [athens.common.logging                :as log]
     [athens.self-hosted.event-log         :as event-log]
@@ -26,7 +27,7 @@
         (doseq [[id data] (if in-memory?
                             event-log/initial-events
                             (event-log/events fluree-conn))]
-          (log/debug "Processing" (pr-str id) "with" (pr-str data))
+          (log/info "Processing" (pr-str id) "with" (common-events/find-event-or-atomic-op-type data))
           (atomic/resolve-transact! conn data)
           (swap! total inc))
         (log/info "✅ Replayed" @total "events."))

src/clj/athens/self_hosted/components/web.clj

@@ -78,7 +78,7 @@
                                                                      (str "Invalid event: " (pr-str data))
                                                                      explanation)))
         (let [{:event/keys [id type]} data]
-          (log/debug "username:" username ", event-id:" id ", type:" type "received valid event")
+          (log/info "Received valid event" "username:" username ", event-id:" id ", type:" (common-events/find-event-or-atomic-op-type data))
           (let [{:event/keys [status]
                  :as         result} (valid-event-handler datascript fluree in-memory? server-password channel username data)]
             (log/debug "username:" username ", event-id:" id ", processed with status:" status)

src/clj/athens/self_hosted/web/presence.clj

@@ -15,15 +15,16 @@
 
 (defn- valid-password
   [conn channel id {:keys [session-intro]}]
-  (let [session-id (str (utils/random-uuid))
+  (let [username   (:username session-intro)
+        session-id (str (utils/random-uuid))
         session    (assoc session-intro :session-id session-id)]
-    (log/info channel "New Client Intro:" session-intro)
+    (log/info "New Client Intro:" session-intro)
     (clients/add-client! channel session)
     (clients/send! channel (common-events/build-presence-session-id-event session-id))
     (let [datoms (map ; Convert Datoms to just vectors.
                   (comp vec seq)
                   (d/datoms @conn :eavt))]
-      (log/debug channel "Sending" (count datoms) "eavt")
+      (log/debug "Sending" (count datoms) "eavt to" (pr-str username))
       (clients/send! channel
                      (common-events/build-db-dump-event datoms)))
     (clients/send! channel

src/cljc/athens/common_events.cljc

@@ -110,3 +110,20 @@
     {:event/id   event-id
      :event/type :op/atomic
      :event/op   atomic-op}))
+
+
+(defn find-event-or-atomic-op-type
+  "Finds `:event/type` or type of atomic op"
+  [event-or-op]
+  (let [event? (and (contains? event-or-op :event/type)
+                    (not= :op/atomic (:event/type event-or-op)))]
+    (if event?
+      (:event/type event-or-op)
+      (let [op      (or (:event/op event-or-op)
+                        event-or-op)
+            atomic? (:op/atomic? op)]
+        (if atomic?
+          (:op/type op)
+          (let [trigger (:op/trigger op)]
+            (or (:op/type trigger)
+                trigger)))))))

src/cljs/athens/events/remote.cljs

@@ -143,6 +143,7 @@
     (log/debug ":remote/reject-forwarded-event event:" (pr-str event))
     (let [db'            (update db :event-sync #(event-sync/remove % :memory id event))
           memory-log     (event-sync/stage-log (:event-sync db') :memory)]
+      (log/info ":remote/reject-forwarded-event memory-log count" (count memory-log))
       {:db db'
        ;; Rollback and reapply all events in the memory stage.
        ;; If there's no events to reapply, just mark as synced.
@@ -162,6 +163,7 @@
           memory-log   (event-sync/stage-log (:event-sync db') :memory)
           page-removes (graph-ops/contains-op? (:event/op event) :page/remove)]
       (log/debug ":remote/apply-forwarded-event new event?:" (pr-str new-event?))
+      (log/info ":remote/apply-forwarded-event memory-log count" (count memory-log))
       {:db db'
        :fx [[:dispatch-n (cond-> []
                            ;; Mark as synced if there's no events left in memory.

test/athens/common_events/utils_test.cljc

@@ -0,0 +1,30 @@
+(ns athens.common-events.utils-test
+  (:require
+    [athens.common-events                 :as sut]
+    [athens.common-events.graph.atomic    :as atomic-graph-ops]
+    [athens.common-events.graph.composite :as composite-graph-ops]
+    [clojure.test                         :as t]))
+
+
+(t/deftest find-event-or-atomic-op-type-test
+  (t/testing "event type extraction"
+    (let [event (sut/build-presence-offline-event "session-id")]
+      (t/is (= :presence/offline (sut/find-event-or-atomic-op-type event)))))
+
+  (t/testing "atomic operation extraction from op"
+    (let [op (atomic-graph-ops/make-block-save-op "block-uid" "block text")]
+      (t/is (= :block/save (sut/find-event-or-atomic-op-type op)))))
+
+  (t/testing "atomic operation extraction from event"
+    (let [event (sut/build-atomic-event
+                  (atomic-graph-ops/make-block-save-op "block-uid" "block text"))]
+      (t/is (= :block/save (sut/find-event-or-atomic-op-type event)))))
+
+  (t/testing "composite operation extraction from op"
+    (let [op (composite-graph-ops/make-consequence-op {:op/type :madeup/name} [])]
+      (t/is (= :madeup/name (sut/find-event-or-atomic-op-type op)))))
+
+  (t/testing "composite operation extraction from event"
+    (let [event (sut/build-atomic-event
+                  (composite-graph-ops/make-consequence-op {:op/type :madeup/name} []))]
+      (t/is (= :madeup/name (sut/find-event-or-atomic-op-type event))))))