StackOverflowError in cider.nrepl.middleware.out

[lassemaatta]

Expected behavior

Logging with clojure.tools.logging should work when running application over emacs/cider repl.

Actual behavior

A StackOverflowException is thrown when logging is attempted:

...
[java.io.PrintWriter write "PrintWriter.java" 542]
[jdk.internal.reflect.GeneratedMethodAccessor3 invoke nil -1]
[jdk.internal.reflect.DelegatingMethodAccessorImpl invoke "DelegatingMethodAccessorImpl.java" 43]
[java.lang.reflect.Method invoke "Method.java" 566]
[clojure.lang.Reflector invokeMatchingMethod "Reflector.java" 167]
[clojure.lang.Reflector invokeInstanceMethod "Reflector.java" 102]
[cider.nrepl.middleware.out$forking_printer$fn__55622 invoke "out.clj" 59]
[cider.nrepl.middleware.out.proxy$java.io.Writer$ff19274a write nil -1]
[java.io.PrintWriter write "PrintWriter.java" 542]
...

Steps to reproduce the problem

1. Using org.clojure/tools.logging 1.1.0
2. Invoke (clojure.tools.logging/debug "hello") within a try block
3. catch any Errors and see the StackOverflowError

Version 0.26.0 does not exhibit this issue (tested by overriding version in profiles.clj).

Also, running the application through lein repl does not exhibit this issue.

Environment & Version information

cider-nrepl version

0.27.0

Java version

openjdk version "11.0.12" 2021-07-20
OpenJDK Runtime Environment (build 11.0.12+7)
OpenJDK 64-Bit Server VM (build 11.0.12+7, mixed mode)

Operating system

Linux archlinux 5.14.7-arch1-1 #1 SMP PREEMPT Wed, 22 Sep 2021 21:35:11 +0000 x86_64 GNU/Linux

[vemv]

Thanks! I assume the section of the stracktrace is repeating? Do you see any different lines?

(Especially at its beginning)

[lassemaatta]

Yeah, that section of the stack trace seemed to be the loop. I managed to grab the StackOverflowError object and tap> it into reveal, but the stack trace was just filled with that repeating section without any hints on where it all started.

[vemv]

Thanks. With a bit of luck we might be able to repro this by exercising t.logging within our test suite.

[vemv]

Are you using log-capture!? Sounds like a possible culprit

In any case, what logging impl (https://github.com/clojure/tools.logging#selecting-a-logging-implementation) are you using?

[vemv]

Here's my attempt at a repro e514b3a , build is still green.

Feel free to check out that commit and suggest anything that might make that logging setup more similar to yours.

[lassemaatta]

I played around with -XX:MaxJavaStackTraceDepth=<number> and managed to grab the beginning of the stack trace

 ...
 [cider.nrepl.middleware.out$forking_printer$fn__55983 invoke "out.clj" 59]
 [cider.nrepl.middleware.out.proxy$java.io.Writer$ff19274a write nil -1]
 [java.io.PrintWriter write "PrintWriter.java" 542]                                                      <- Here again
 [jdk.internal.reflect.GeneratedMethodAccessor3 invoke nil -1]
 [jdk.internal.reflect.DelegatingMethodAccessorImpl invoke "DelegatingMethodAccessorImpl.java" 43]
 [java.lang.reflect.Method invoke "Method.java" 566]
 [clojure.lang.Reflector invokeMatchingMethod "Reflector.java" 167]
 [clojure.lang.Reflector invokeInstanceMethod "Reflector.java" 102]
 [cider.nrepl.middleware.out$forking_printer$fn__55983 invoke "out.clj" 59]
 [cider.nrepl.middleware.out.proxy$java.io.Writer$ff19274a write nil -1]
 [java.io.PrintWriter write "PrintWriter.java" 542]                                                      <- Start of the loop
 [java.io.PrintWriter write "PrintWriter.java" 559]
 [cider.nrepl.middleware.out$print_stream$fn__56035 invoke "out.clj" 96]
 [cider.nrepl.middleware.out.proxy$java.io.OutputStream$ff19274a write nil -1]
 [java.io.PrintStream write "PrintStream.java" 559]
 [java.io.FilterOutputStream write "FilterOutputStream.java" 108]
 [ch.qos.logback.core.joran.spi.ConsoleTarget$1 write "ConsoleTarget.java" 37]
 [ch.qos.logback.core.OutputStreamAppender writeBytes "OutputStreamAppender.java" 199]
 [ch.qos.logback.core.OutputStreamAppender subAppend "OutputStreamAppender.java" 231]
 [ch.qos.logback.core.OutputStreamAppender append "OutputStreamAppender.java" 102]
 [ch.qos.logback.core.UnsynchronizedAppenderBase doAppend "UnsynchronizedAppenderBase.java" 84]
 [ch.qos.logback.core.spi.AppenderAttachableImpl appendLoopOnAppenders "AppenderAttachableImpl.java" 51]
 [ch.qos.logback.classic.Logger appendLoopOnAppenders "Logger.java" 270]
 [ch.qos.logback.classic.Logger callAppenders "Logger.java" 257]
 [ch.qos.logback.classic.Logger buildLoggingEventAndAppend "Logger.java" 421]
 [ch.qos.logback.classic.Logger filterAndLog_0_Or3Plus "Logger.java" 383]
 [ch.qos.logback.classic.Logger warn "Logger.java" 688]
 [clojure.tools.logging$eval9989$fn__9994 invoke "logging.clj" 326]
 [clojure.tools.logging.impl$eval9715$fn__9729$G__9706__9740 invoke "impl.clj" 16]
 [clojure.tools.logging$log_STAR_ invokeStatic "logging.clj" 63]
 [clojure.tools.logging$log_STAR_ invoke "logging.clj" 42]
 [core.web.router$fn__144757$fn__144758 invoke "router.clj" 152]                       <- Our code calling `clojure.tools.logging/warn`
 ...

As you can see, we're using logback-classic (1.2.3) as the logger implementation.

I also noticed that I can't trigger this issue by just calling clojure.tools.logging from the cider REPL, it works just fine. I also tried doing it within a future or a delay, but still it works. But when the logging happens within our HTTP stack we get the overflow situation.

As far as I know we aren't doing anything special wrt. logging. I can find no references to log-capture!.

[vemv]

I'll take a look again later

In the meantime, looks like you can remove the ConsoleAppender from your logback.xml? That should fix things - no printlning means no fighting for *out* / System/out.

Personally it's something I do for all my work apps - for a different reason: having logging output in CIDER is far too noisy. And Emacs doesn't exactly excel at handling abundant output.

You can always set up a FileAppender and tail -f it (or less +F it - recommended!).

[vemv]

Released cider-nrepl 0.27.2. You can set it in cider.el via.