[tmp] [#431] Temp debugging

taoensso · Jul 10, 2023 · f310ece · f310ece
1 parent e5d8e58
commit f310ece
Show file tree

Hide file tree

Showing 4 changed files with 34 additions and 12 deletions.
diff --git a/example-project/project.clj b/example-project/project.clj
@@ -1,4 +1,4 @@
-(defproject com.taoensso.examples/sente "1.18.1"
+(defproject com.taoensso.examples/sente "1.18.2-SNAPSHOT"
   :description "Sente, reference web-app example project"
   :url "https://github.com/ptaoussanis/sente"
   :license {:name "Eclipse Public License"
@@ -15,7 +15,7 @@
    [org.clojure/core.async    "1.6.673"]
    [nrepl                     "1.0.0"] ; Optional, for Cider
 
-   [com.taoensso/sente        "1.18.1"] ; <--- Sente
+   [com.taoensso/sente        "1.18.2-SNAPSHOT"] ; <--- Sente
    [com.taoensso/timbre       "6.2.1"]
 
    ;;; TODO Choose (uncomment) a supported web server -----------------------

diff --git a/example-project/src/example/server.clj b/example-project/src/example/server.clj
@@ -47,7 +47,7 @@
   (timbre/set-ns-min-level! level) ; Min log level for this           namespace
   (reset! min-log-level_    level))
 
-(set-min-log-level! :debug)
+(set-min-log-level! :report) ; Show only logs focused on [#431]
 
 ;;;; Define our Sente channel socket (chsk) server
 
@@ -75,7 +75,7 @@
 (add-watch connected-uids :connected-uids
   (fn [_ _ old new]
     (when (not= old new)
-      (timbre/infof "Connected uids change: %s" new))))
+      (timbre/reportf "[#431] connected uids changed: %s" new))))
 
 ;;;; Ring handlers
 

diff --git a/project.clj b/project.clj
@@ -1,4 +1,4 @@
-(defproject com.taoensso/sente "1.18.1"
+(defproject com.taoensso/sente "1.18.2-SNAPSHOT"
   :author "Peter Taoussanis <https://www.taoensso.com>"
   :description "Realtime web comms for Clojure/Script"
   :url "https://github.com/ptaoussanis/sente"

diff --git a/src/taoensso/sente.cljc b/src/taoensso/sente.cljc
@@ -455,7 +455,7 @@
               ;; The feature can be enabled early by manually providing a
               ;; `ws-ping-timeout-ms` val in opts.
               ;;
-              ws-ping-timeout-ms nil #_(enc/ms :secs 5) ; TODO Enable default val
+              ws-ping-timeout-ms (enc/ms :secs 5)
 
               send-buf-ms-ajax   100
               send-buf-ms-ws     30
@@ -771,6 +771,8 @@
               uid         (user-id-fn    ring-req client-id)
               ;; ?ws-key  (get-in ring-req [:headers "sec-websocket-key"])
 
+              gc-loop-id  (enc/uuid-str 4)
+
               receive-event-msg! ; Partial
               (fn self
                 ([event          ] (self event nil))
@@ -824,24 +826,34 @@
 
                      (timbre/infof "[ws/on-open] New server WebSocket sch for %s" (lid uid client-id))
 
-                     (when (connect-uid! :ws uid) (receive-event-msg! [:chsk/uidport-open uid]))
+                     (when (connect-uid! :ws uid)
+                       (timbre/report "[#431] ws uid port open" {:uid uid, :gid gc-loop-id})
+                       (receive-event-msg! [:chsk/uidport-open uid]))
+
                      (send-handshake! server-ch websocket?)
 
                      ;; Server-side loop to detect broken conns, Ref. #230
                      (when ws-kalive-ms
+                       (timbre/report "[#431] ws gc loop start" {:uid uid, :gid gc-loop-id})
                        (go-loop [udt-t0          udt-open
                                  ms-timeout      ws-kalive-ms
                                  expecting-pong? false]
 
                          (<! (async/timeout ms-timeout))
                          (when-let [[sch udt-t1] (get-in @conns_ [:ws uid client-id])]
                            ;; Does this loop retain sch ownership? Break if not.
+
+                           (when-not (identical? sch server-ch)
+                             (timbre/report "[#431] ws gc loop end" {:uid uid, :gid gc-loop-id}))
+
                            (when (identical? sch server-ch)
                              (let [;; No conn send/recv activity w/in kalive window?
                                    no-activity? (= udt-t1 udt-t0)]
 
                                (when no-activity?
 
+                                 (timbre/report "[#431] ws gc loop inactivity" {:uid uid, :gid gc-loop-id})
+
                                  ;; First send ping to client. In most cases the
                                  ;; send attempt itself should be sufficient to
                                  ;; trigger `:on-close` if the conn is broken.
@@ -934,12 +946,18 @@
                        _
                        (timbre/debugf "%s Server sch closed for %s"
                          log-prefix
-                         (lid uid client-id))]
+                         (lid uid client-id))
+
+                       ?udt-close
+                       (let [{:keys [updated? ?udt]}
+                             (upd-conn! conn-type uid client-id server-ch nil)]
+                         (when updated? (have ?udt)))]
 
-                   (when-let [udt-close
-                              (let [{:keys [updated? ?udt]}
-                                    (upd-conn! conn-type uid client-id server-ch nil)]
-                                (when updated? (have ?udt)))]
+                   (when websocket?
+                     (timbre/report "[#431] ws on-close"
+                       {:uid, uid, :gid gc-loop-id, :removed-sch? (boolean ?udt-close)}))
+
+                   (when-let [udt-close ?udt-close]
                      ;; Allow some time for possible reconnects (repoll,
                      ;; sole window refresh, etc.):
                      (go
@@ -956,6 +974,9 @@
                                    (swapped :swap/dissoc true)
                                    (swapped :swap/abort  false))))]
 
+                         (timbre/report "[#431] ws after-close"
+                           {:uid uid, :gid gc-loop-id, :disconnect? disconnect?})
+
                          (timbre/logf (if disconnect? :info :trace)
                            "%s Server sch on-close timeout for %s: %s"
                            log-prefix
@@ -969,6 +990,7 @@
                              (fn [?m] (if (empty? ?m) :swap/dissoc ?m)))
 
                            (when (upd-connected-uid! uid)
+                             (timbre/report "[#431] ws uid port close" {:uid uid, :gid gc-loop-id})
                              (receive-event-msg! [:chsk/uidport-close uid]))))))))
 
                :on-error