Debugger quits on certain tools.logging forms

[lowecg]

When I run a log form that follows a certain pattern from the debugger, the debugger terminates and the function appears to return “QUIT”.

The log runs successfully outside of debugging.

I can repro the issue from the getting started REPL with the following edits:

deps.edn:

{:deps {org.clojure/clojure       {:mvn/version "1.12.0"}
        org.clojure/tools.logging {:mvn/version "1.3.0"}
        org.slf4j/slf4j-simple    {:mvn/version "2.0.16"}}}

hello_repl.clj

(ns get-started.hello-repl
  (:require [clojure.tools.logging :as log]))

"Welcome to the Getting Started REPL! 💜"

(defn debug-this [x]
  ;; these are fine
  (log/info "Plain output ok")
  (println :in 'debug-this :x x) 
  (println "Simple output ok")

  ;; the next line fails on step over (or continue)
  (log/info :in 'debug-this :x x)

  (inc x))

(comment
  (debug-this 1))

1. Jack-in, and running (debug-this 1) works.
2. Instrument debug-this using ctrl-alt-c i , then step over the second log/info line and the debugger immediately halts

@PEZ has successfully tried these forms in CIDER and suspects Calva is holding something incorrectly.

Initially discussed here:
https://clojurians.slack.com/archives/CBE668G4R/p1726308887145419

[PEZ]

Thanks!

I now ran the failing step with nrepl logging enabled and got this:

nrepl messages

1726313950133 -> sent 
{
  id: '7',
  op: 'debug-input',
  input: ':next',
  key: '27522913-c686-42ba-a6a4-44857205247d',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be'
}

1726313950136 <- received 
{
  err: '[nREPL-session-cabe63b7-acc9-4ae0-be37-8a4b07c187be] INFO mini.playground - :in debug-this :x 1\n',
  id: '13',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be'
}

1726313950137 <- received 4ms
{
  code: '#dbg\n' +
    '(defn debug-this [x]\n' +
    '  (log/info "Plain output ok")\n' +
    "  (println :in 'debug-this :x x)\n" +
    '  (println "Simple output ok")\n' +
    "  (log/info :in 'debug-this :x x) ;; this fails\n" +
    '  (inc x))',
  column: 1,
  coor: [ 6 ],
  'debug-value': 'nil',
  file: '/Users/pez/Projects/tests/debug-mini/src/mini/playground.clj',
  id: '7',
  'input-type': [
    'continue',       'locals',
    'inspect',        'trace',
    'here',           'continue-all',
    'next',           'out',
    'inject',         'stacktrace',
    'inspect-prompt', 'quit',
    'in',             'eval'
  ],
  key: '52b184ba-2b1d-452c-9324-3e9ea057d778',
  line: 4,
  locals: [ [ 'x', '1' ] ],
  'original-id': '11',
  'original-ns': 'mini.playground',
  prompt: [],
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be',
  status: [ 'need-debug-input' ]
}

1726313950166 -> sent 29ms
{
  id: '7',
  op: 'debug-input',
  input: ':quit',
  key: '52b184ba-2b1d-452c-9324-3e9ea057d778',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be'
}

1726313950174 <- received 38ms
{
  id: '13',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be',
  value: 'QUIT'
}

1726313950180 <- received 6ms
{
  err: 'Execution error (NullPointerException) at cider.nrepl.middleware.debug/abort! (debug.clj:141).\n' +
    'Cannot invoke "java.lang.Thread.stop()"\n',
  id: '13',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be'
}

1726313950180 <- received 0ms
{
  ex: 'class java.lang.NullPointerException',
  id: '13',
  'root-ex': 'class java.lang.NullPointerException',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be',
  status: [ 'eval-error' ]
}

1726313950180 <- received 0ms
{
  id: '13',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be',
  status: [ 'done' ]
}

1726313950186 <- received 6ms
{
  'changed-namespaces': {},
  id: '13',
  'repl-type': 'clj',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be',
  status: [ 'state' ]
}

1726313950232 -> sent 
{
  op: 'debug-instrumented-defs',
  id: '26',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be'
}

1726313950240 <- received 8ms
{
  id: '26',
  list: [ [ 'mini.playground', 'debug-this' ] ],
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be',
  status: [ 'done' ]
}

Where this part is probably the most interesting:

1726313950180 <- received 6ms
{
  err: 'Execution error (NullPointerException) at cider.nrepl.middleware.debug/abort! (debug.clj:141).\n' +
    'Cannot invoke "java.lang.Thread.stop()"\n',
  id: '13',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be'
}

1726313950180 <- received 0ms
{
  ex: 'class java.lang.NullPointerException',
  id: '13',
  'root-ex': 'class java.lang.NullPointerException',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be',
  status: [ 'eval-error' ]
}

So maybe it could be about the version of nrepl and cider-nrepl involved. I haven't checked which versions CIDER is using...

[PEZ]

Actually, the message sent just before we get the exception is the most interesting:

1726313950166 -> sent 29ms
{
  id: '7',
  op: 'debug-input',
  input: ':quit',
  key: '52b184ba-2b1d-452c-9324-3e9ea057d778',
  session: 'cabe63b7-acc9-4ae0-be37-8a4b07c187be'
}

Why are we sending :quit there? It makes zero sense.