clojure.tools.logging with log4j2 backend writes to NREPL but not REPL buffer

vladprevi commented 2 years ago

Expected behavior

When logging with clojure.tools.logging with log4j2 backend set via relevant clojure.tools.logging.imlp factory I expect log messages both in NREPL and in REPL buffer. Note that we have cider-redirect-server-output-to-repl set to true and cider-nrepl loadded.

Actual behavior

Log messages turn up in the NREPL only buffer, but not in REPL

but note that server output redirection to repl is set and works perfectly fine with e.g. logback backend.

Steps to reproduce the problem

With the following settings in your project.clj or similar in deps.edn:

Dependencies

[org.clojure/tools.logging "1.2.4"]
[org.apache.logging.log4j/log4j-api "2.18.0"]
[org.apache.logging.log4j/log4j-core "2.18.0"]
[org.apache.logging.log4j/log4j-1.2-api "2.18.0"]
[org.apache.logging.log4j/log4j-jcl "2.18.0"]
[org.apache.logging.log4j/log4j-jul "2.18.0"]
[org.apache.logging.log4j/log4j-slf4j-impl "2.18.0"]

JVM options that set the backend

:jvm-opts ["-Dlog4j2.configurationFile=log4j2.xml"
                  "-Dclojure.tools.logging.factory=clojure.tools.logging.impl/log4j2-factory"]

Some simple config `log4j2.xml` in your classpath

Use below or e.g. this .properties example provided by clojure.tools.logging.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="5">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%date %level %logger %message%n%throwable"/>
      <!-- <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> -->
    </Console>
  </Appenders>
  <Loggers>
    <Root level="info">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>
</Configuration>

Jack in as usual and try this code:

(ns user (:require [clojure.tools.logging :as log]))

;; these will register in NREPL buffer but not your repl
(log/error "foo")
(log/info "foo")

;; confirm your setup was pulled in
(System/getProperty "log4j2.configurationFile")
(System/getProperty "clojure.tools.logging.factory")
(.name (clojure.tools.logging.impl/log4j2-factory))
(.name log/*logger-factory*)

(.toString
 (.getConfiguration
  (.getContext
   (clojure.tools.logging.impl/get-logger
    log/*logger-factory*
    *ns*))))

(.getState
 (.getConfiguration
  (.getContext
   (clojure.tools.logging.impl/get-logger
    log/*logger-factory*
    *ns*))))

Fun observation and experiments that may help

Our log4j2 setup above rescans itself for changes every 5 seconds. If you do in fact change that xml config you'll notice that those log messages will now appear in REPL as you'd expect. Because in prod when deployed logs will end up in STDOUT and we're only having trouble with our dev setup, I thought I'd be clever and trigger reloading our logger from e.g. user.clj with this:

(.stop
 (.getConfiguration
  (.getContext
   (clojure.tools.logging.impl/get-logger
    log/*logger-factory*
    *ns*))))

(.reconfigure
 (.getContext
  (clojure.tools.logging.impl/get-logger
   log/*logger-factory*
   *ns*)))

It does in fact fixes the problem and message start logging in the REPL buffer. It has fun consequences however: killing the REPL will kill Emacs. What fun :)

Environment & Version information

CIDER version information

;; Connected to nREPL server - nrepl://localhost:52598
;; CIDER 1.4.0 (Kyiv), nREPL 0.9.0
;; Clojure 1.11.1, Java 18.0.1

Lein / Clojure CLI version

Leiningen 2.9.8 on Java 18.0.1 OpenJDK 64-Bit Server VM

Emacs version

GNU Emacs 28.1 (build 2, x86_64-apple-darwin21.4.0, NS appkit-2113.40 Version 12.3.1 (Build 21E258)) of 2022-05-09

Operating system

Mac OS Monterey 12.3.1

vemv commented 2 years ago

Hi, thanks for the accurate report!

Could you please consolidate your (nice) repro steps into a repository that one could simply clone and run?

Thanks - V

strssndktn commented 1 year ago

I encountered the same problem just now as well. I wanted to add some quick observations, in case they are helpful:

In my particular case the user.clj causes to actually requires large parts of my application, including jetty. This happens before any nrepl code actually runs. The static initializers in jetty cause the log4j2 backend to be initialized and sets up logging to stdout. If one breaks this dependency in user.clj and delays the require of the dependencies, the problem goes away and log messages to the repl start to flow.

It seems that log4j2 captures System.out before nrepl can bring it under its control. I also tried to ensure that nrepl's static initializers (if existing?) are executed before jetty's but that didn't help much.

vemv commented 1 year ago

Much useful input, thanks!

As you may be well aware of already, user.clj has a special semantic for the Clojure compiler - it's loaded before anything else.

Perhaps moving its contents to something like dev/dev.clj would allow nrepl code to take precedence?

strssndktn commented 1 year ago

Yep, I actually wanted to exploit the user.clj semantics of it being loaded early and available every time (controlled by deps.edn).

My solution is: I just had one dependency from my application's namespaces within a function in user.clj. Not requiring it directly in the ns block but using requiring-resolve from within the function solved the problem with just one additional line of code. It causes the dependencies to only get loaded whenever I call that function, which is my main entry point to the application anyway.

This bug probably belongs to cider-nrepl anyway, where the out middleware would probably have try to capture the *out* and *err* streams as soon as possible via static initializers and map it to some session. This might be nice but would have dubious semantics.

clojure-emacs / cider