Configuring logging

[kbrah]

Hi,

I have an issue with the logging configuration. My project uses logback, which formats the logs to ecs format. However when sente throws and logs an exception, it does not go through logback. Instead I believe it's logged directly to stderr(?). I tried to use a custom timbre config and a custom appender that disables println appender and relogs the message with clojure.tools.logging. The config seems to work when I manually log things with timbre but does not apply to sente. Any ideas how to solve this issue?

(defn log-appender []
  {:enabled? true
   :fn (fn [{:keys [level ?err msg_]}]
         (log/log level ?err @msg_))})

  (timbre/with-merged-config {:appenders {:json-appender (log-appender)
                                          :println {:enabled? false}}}

[ptaoussanis]

@kbrah Hi there!

Your Timbre config looks correct, I suspect that the issue is that you may want to use merge-config! rather than with-merged-config.

The "with-x" utils all establish a binding that's only relevant for the specific enclosed body.

Hopefully that helps / makes sense?

BTW I'm expecting to switch Sente from Timbre to tools.logging in a future release.

[kbrah]

Thanks for the reply!

I tried the merge-config! but didn't see any difference in the results. The specific exception that is not processed properly is No more than 1024 pending takes are allowed on a single channel . Could it be something with this specific exception that causes it not to be logged correctly.

Do you have any timeline estimate for when the transition to tools.logging would be implemented?

Currently our solution is to just redirect stderr to /dev/null to avoid producing a huge amount of log lines. That should be fine except now the exception is not visible in our logs at all. (Normally Logback will output everything to stdout as far as I understand).

[ptaoussanis]

The specific exception that is not processed properly is No more than 1024 pending takes are allowed on a single channel . Could it be something with this specific exception that causes it not to be logged correctly.

Could you show me an example of what the log output you're seeing for this looks like? That exception isn't generated by Sente, but by Clojure's core.async.

Depending on where+when it's actually occurring, it's possible that Sente (and so Timbre) is not actually doing the logging.

That particular exception generally shouldn't happen under normal behaviour, and with correct buffering. There's some extra context (very old discussion) here.

But we've got two potential issues on the table:

1. Getting the logging behaviour you want (logging this exception to logback).
2. Avoiding this exception in the first place.

• For (1), it'd help to know what log output you're seeing. This'll let us confirm if the logging call is actually being issued by Timbre or not.

• For (2), the same log output would also be handy - but might also need to know more about how you're using Sente.

[kbrah]

Here's an example of the exception

Exception in thread "async-dispatch-214987" java.lang.AssertionError: Assert failed: No more than 1024 pending takes are allowed on a single channel.
 at clojure.lang.AFn.run(AFn.java:22), at clojure.lang.AFn.run(AFn.java:22)
 at clojure.lang.AFn.run(AFn.java:22), at clojure.lang.AFn.run(AFn.java:22)
 at clojure.core.async.impl.concurrent$counted_thread_factory$reify__884$fn__885.invoke(concurrent.clj:29), at clojure.core.async.impl.concurrent$counted_thread_factory$reify__884$fn__885.invoke(concurrent.clj:29)
 at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:974), at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:974)
 at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834$state_machine__6142__auto____17917$fn__17919.invoke(sente.cljc:625), at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834$state_machine__6142__auto____17917$fn__17919.invoke(sente.cljc:625)
 at clojure.lang.AFn.run(AFn.java:22), at clojure.lang.AFn.run(AFn.java:22)
 at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834.invoke(sente.cljc:624), at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834.invoke(sente.cljc:624)
 at clojure.core.async.impl.channels.ManyToManyChannel.take_BANG_(channels.clj:239), at clojure.core.async.impl.channels.ManyToManyChannel.take_BANG_(channels.clj:239)
 at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834$state_machine__6142__auto____17917$fn__17919.invoke(sente.cljc:625), at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834$state_machine__6142__auto____17917$fn__17919.invoke(sente.cljc:625)
 at clojure.core.async.impl.ioc_macros$take_BANG_.invokeStatic(ioc_macros.clj:982), at clojure.core.async.impl.ioc_macros$take_BANG_.invokeStatic(ioc_macros.clj:982)
 at clojure.lang.AFn.run(AFn.java:22), at clojure.lang.AFn.run(AFn.java:22)
 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642), at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
 at clojure.core.async.impl.ioc_macros$take_BANG_.invokeStatic(ioc_macros.clj:982), at clojure.core.async.impl.ioc_macros$take_BANG_.invokeStatic(ioc_macros.clj:982)
 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642), at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
 at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834$state_machine__6142__auto____17917.invoke(sente.cljc:624), at taoensso.sente$make_channel_socket_server_BANG_$send_fn__17422$fn__17834$state_machine__6142__auto____17917.invoke(sente.cljc:624)
 at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:976), at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:976)
 at clojure.core.async.impl.ioc_macros$take_BANG_.invokeStatic(ioc_macros.clj:982), at clojure.core.async.impl.ioc_macros$take_BANG_.invokeStatic(ioc_macros.clj:982)
 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642), at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
 at clojure.core.async.impl.ioc_macros$run_state_machine.invokeStatic(ioc_macros.clj:972), at clojure.core.async.impl.ioc_macros$run_state_machine.invokeStatic(ioc_macros.clj:972)
 at clojure.lang.AFn.run(AFn.java:22), at clojure.lang.AFn.run(AFn.java:22)
 at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:976), at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:976)
 at clojure.core.async.impl.ioc_macros$take_BANG_.invoke(ioc_macros.clj:981), at clojure.core.async.impl.ioc_macros$take_BANG_.invoke(ioc_macros.clj:981)
(< (.size takes) impl/MAX-QUEUE-SIZE), (< (.size takes) impl/MAX-QUEUE-SIZE)

I was able to produce a similar exception locally with the (dotimes [_ 50000] (go (<! (async/timeout (+ 50 (rand-int 100)))))) and it was not logged by logback. Indeed it seems that the logging issue is not caused by sente/timbre.

I'm not too familiar with this code base but here are the main parts that I could find where sente is being used

;; Create EDN channel socket server
(let [packer :edn
      chsk-server (sente/make-channel-socket-server!
                   (get-sch-adapter) {:packer        packer
                                      :csrf-token-fn nil
                                      :user-id-fn    ring-req->uid-in-topic})

      {:keys [ch-recv send-fn connected-uids
              ajax-get-or-ws-handshake-fn]}
      chsk-server]

  (def ring-ajax-get-or-ws-handshake-edn ajax-get-or-ws-handshake-fn)
  (def ch-chsk-edn ch-recv)
  (def chsk-send-edn! send-fn)
  (def connected-uids-edn connected-uids))

(defn edn-event-handler [ev-msg]
  (case env
    "dev" (event-msg-handler (assoc ev-msg :endpoint :edn))
    "unit-test" (event-msg-handler (assoc ev-msg :endpoint :edn))
    (future (event-msg-handler (assoc ev-msg :endpoint :edn)))))


;;;; Sente event router (our `event-msg-handler` loop)

(defonce router_ (atom nil))

(defn stop-router! []
  (when-let [stop-fn @router_]
    (stop-fn)))

(defn start-router! []
  (stop-router!)
  (reset! router_ (sente/start-server-chsk-router! ch-chsk-edn #'edn-event-handler)))

;;;; Ring request handler

(defn handler [ring-req]
  (ring-ajax-get-or-ws-handshake-edn ring-req))

(defn start! []
  (when (parse-property :sente-debug-mode)
    (sente/set-min-log-level! :debug))
  (start-router!))

(defn stop! []
  (stop-router!))

[kbrah]

I think I managed to get the logging working by creating a Thread/setDefaultUncaughtExceptionHandler

(Thread/setDefaultUncaughtExceptionHandler
(fn [thread ex]
(log/error ex "Uncaught exception in thread" (.getName thread))))

I'm yet to confirm this in production because it has not happened there yet.

I'm sure the issue of the exception being thrown is still there though, so if you have any clues what to look for as the source would be greatly appreciated!