Add CIDER log middleware #773

r0man · 2023-06-12T12:07:41Z

Before submitting a PR make sure the following things have been done:

The commits are consistent with our contribution guidelines
You've added tests to cover your change(s)
All tests are passing
The new code is not generating reflection warnings
You've updated the README (if adding/changing middleware)

r0man · 2023-06-12T12:22:38Z

I added a description for this feature over here: clojure-emacs/cider#3352

vemv · 2023-06-12T12:28:37Z

Looking interesting!

Before any fine-grained reviewing, the most important thing that comes to mind is: does this functionality bring in any side-effect? Or otherwise alter the default behavior in CIDER or its underlying JVM?

The JVM/Clojure logging landscape is pretty complex, so if there's another moving piece in the stack, it could plausibly frustrate users.

r0man · 2023-06-12T12:33:29Z

Hi @vemv, I don't think it alters any existing behaviour, or at least not that I'm aware of. The code for specific log frameworks is all optional. The code adds an additional appender to a log framework. So this should be no different to for example adding a file or some other appender to the log framework.

vemv · 2023-06-12T12:36:32Z

Nice! I see. I see that no dependencies are brought in either - it's dynamic 👍

vemv

A quick pass from my side. It lgtm - kudos!

README.md

eastwood.clj

project.clj

src/cider/log/appender.clj

src/cider/log/event.clj

vemv · 2023-06-12T12:44:02Z

src/cider/log/framework.clj

+(def ^:dynamic *frameworks*
+  ['cider.log.framework.logback/framework
+   'cider.log.framework.jul/framework
+   ;; 'cider.log.framework.log4j2/framework


What's missing with log4j2?

I explained this in the open question over at the CIDER Emacs pull request.

Right now this works with Logback (which I am using) and Java Util Logging. There is some code for Log4j2 that passes some of the tests, but I couldn't make it working reliably. The issue seems that Log4j2 reloads its configuration when a new appender is added, and wipes out the changes. I tried most of the suggestions on Stackoverflow to get it working, but I'm giving up on this one. I already spent too much time on this. So, I propose to drop that code into a branch of the separated library. If anyone knows how to get it working, I'm willing to help, but I won't investigate this beast any further.

It's a bit unfortunate, but I'm really out of ideas and energy with this one.

Would it help if the nrepl logger wasn't dynamically added?

e.g. one could configure it such that it's instantiated as the JVM starts.

This would probably involve a .xml file or a user.clj file.

...this would not invalidate the current, dynamic approach, I'd see it instead of an additional, opt-in manner to run things.

It might, but I believe for this to work we would need to use gen-class to create an appender class that implements some Log4j2 interface and ship it, so that it can be referenced in the configuration file. And then somehow connect this with the atom to which events are added.

clojure-emacs/logjam#2

test/clj/cider/log/appender_test.clj

vemv · 2023-06-12T12:54:24Z

src/cider/nrepl/middleware.clj

@@ -16,6 +16,7 @@
    cider.nrepl/wrap-format
    cider.nrepl/wrap-info
    cider.nrepl/wrap-inspect
+    cider.nrepl/wrap-log


It comes to mind, is it easy to pre-configure this feature in user.clj?

e.g. I may always want to perform the same sequence of config steps.

@vemv I'm not sure I understand. Isn't this just the list of provided middlewares? Don't we want to always load it?

If you are concerned about performance, see my comment about the async logback logger. I think we can load it. Logs are only captured if an appender is added.

Sorry for the misunderstanding, my comment doesn't have anything to do with this specific LOC.

I meant, presumably each time I wanted logging, I should perform the same steps manually via Emacs interactions. I may want to leave it already configured (and collecting logs!) in user.clj, on a per-project basis.

So it would be sensible to have a minimal Clojure "API"?

So for the minimal Clojure API we have this one here:
https://github.com/r0man/cider-nrepl/blob/cider-log/src/cider/log/repl.clj
It's designed to be used by non-NREPL users and is used by my collegues.

But we can't use this on startup. Because the frameworks (and their state) are stored in different places. In this REPL namespace the state it bound to a var in the cider.log.repl namespace.

In NREPL, the framework and state are attached to the current session, so you can't use the REPL namespace for that, unless we mix those two states. I'm not sure if this approach to storing the state in the session is the right one, or if I should store it in a dynamic var as well. I took the current approach from the inspect middleware which saves state in the session.

Another option for stating this up automatically is to provide some hook on the ELISP side? I think it's enough to send a single NREPL message that attaches an appender to a given framework.

clojure-emacs/logjam#3

src/cider/log/appender.clj

vemv · 2023-06-12T18:24:46Z

As another thing that came to mind. I reckon that it would be neat to inspect remote logs from a production server.

Did you try out so? It might be a good benchmark for the capabilities that appear to be there e.g. "GC".

It would also be a good benchmark for the frontend side - I reckon there is pagination/limiting?

Anyway, please do not feel pressured to gold-plate your PR - I'm just trying to contribute some design aspects that might help in the early stages.

src/cider/log/specs.clj

vemv · 2023-06-12T18:34:55Z

src/cider/log/framework/logback.clj

@@ -0,0 +1,110 @@
+(ns cider.log.framework.logback


I recall that Logback offers an async mode that is disabled by default.

Do you think it would be a good idea to recommend enabling it? I'd be afraid of CIDER introducing any slowness in apps due to synchronous logging.

However if the logging itself doesn't involve running Clojure code at all, then it would not seem necessary.

I wasn't aware of the async log appender. I think it can be done, but reading https://stackoverflow.com/questions/47372092/when-not-to-use-asyncappender-in-logback-by-default I'm not convinced we will gain much for the added complexity and it's only for Logback.

Maybe its worth to mention that all this is opt in. So, if you don't call cider-log and attach an appender to a log framework there is no additional work being done. A production system for example, that ships NREPL middleware, will by default not do any extra work. Only if you connect to it and configure any appenders and consumers.

If you add an appender this is what happens on the hot path:

A log event is converted to a Clojure data structure

If you defined any filters for an appender (like a log level, or a regex) a filter function is called to decide if the event should be added to the appenders internal atom. If there are no filters defined, the filter function is the identity function.

If the event passes the filter it will be added to an atom

What happens next depends on if there are any consumers. A consumer is for example added for the *cider-log* buffer when you search/stream events to the client.

If there are any consumers, then in the hot path a filter function (again identity if there are no filters defined) is applied for each consumer. If the event passes the filter function then the event is sent in an NREPL message to the client. My guess is that sending back the event to the client is probably the most expensive operation. At least that's the only IO operation we are doing here.

I haven't noticed much slowdown when I use this during development (for which I see this as the main use case). But it really depends how much you log.

The only significant slowdown I noticed is on the Emacs side when you insert super long messages into a buffer. Because of that, I decided to add the cider-log-max-message-length variable that truncates messages on the Emacs side.

So I would suggest, let's keep this optimization for another day.

My guess is that sending back the event to the client is probably the most expensive operation.

Interesting, thanks for the analysis!

Imagine that logview happens to perform slowly for some corner case, or that otherwise the user's Emacs is slow due to misconfiguration or any unforeseen circumstance.

Would that client slowness affect the performance of JVM Clojure code? That would seem quite undesirable.

Right now, yes this would affect the Clojure code emitting log events. My proposed solution for now would be to either configure the log event filters of either the appender (so it does not add too many events to the in memory atom) and/or the filters of the consumer (so it does not send too many events to the client).

You can definitely bring down the thing if you are logging too crazy, but I think for a typical development system it should perform well enough.

I tested this a bit by emitting random log events in a couple of threads with this snippet:
https://github.com/r0man/cider-nrepl/blob/f6ef379bc6d522c11c5c2b676b131042c9ded3ec/test/clj/cider/nrepl/middleware/log_test.clj#L424

If I start spawning 5 threads each logging 1000 events with a 10ms delay I don't notice any lag when I edit or move around buffers. The *cider-log* buffer fills up with events pretty quickly and I believe logview actually can handle it quite well.

If you start more threads (I tried this now with 10) at some point logview doesn't colorize the events as quickly anymore and you see this in the cider-log buffer. Moving the cursor still seems to work fine though.

But eventually it will fall apart. But to be honest, with that amount of log events streaming into the cider-log buffer, this isn't the right tool for the job anymore. You should at least start to apply filters to find the interesting events at this point I believe.

clojure-emacs/logjam#4

src/cider/nrepl/middleware/log.clj

r0man · 2023-06-13T09:41:10Z

Btw, thanks @vemv and @bbatsov for the quick review.

r0man · 2023-06-13T11:16:04Z

As another thing that came to mind. I reckon that it would be neat to inspect remote logs from a production server.

Did you try out so? It might be a good benchmark for the capabilities that appear to be there e.g. "GC".

No, I did not try with a remote production server. I don't have access to prod and didn't setting it up for staging is also a bit involved. If we have it in a released JAR this will be easier and I can try it out.

It would also be a good benchmark for the frontend side - I reckon there is pagination/limiting?

There's some basic limit/offset pagination when you ask the NREPL server for events. By default, 500 events will be returned. But we don't really have an UI to paginate through events like in the inspector for example.

Right now you can set limit/offset, but there is no way to paginate easily to the next and previous pages.

I thought about it, but I actually didn't need it for my use case, and I feel it's a bit tricky to get right with all the logs flowing in. Probably offset based pagination is also not the right thing to do if you want a consistent view. Probably the offset should be relative to some event to have a stable view (since some event may roll-in in the meantime).

Anyway, please do not feel pressured to gold-plate your PR - I'm just trying to contribute some design aspects that might help in the early stages.

No worries, your ideas are welcome. :)

This is a bit more user friendly when typing in commands in the REPL. In Clojure 1.11 both, keyword arguments and a single options map, are supported.

r0man · 2023-06-19T10:40:27Z

This is a list of possible project names that I collected from various people:

datafy-logs
glass
hyperlog
logbox
logging glass
logjam
logmod
logmode/log.mode
logoscope (log under microscope)
logroll
pimp my logs
sherlog
wunderlog

If you have more ideas please add them!

How do we decide? Can everyone post their top 3 and we will see?

@vemv Could you help with setting up a project under the emacs-clojure organization in the same way we did for haystack?

r0man · 2023-06-19T10:44:50Z

This is my top 3 list:

logmode
logjam
sherlog

bbatsov · 2023-06-19T12:51:36Z

sherlog
logjam
logmod

vemv · 2023-06-19T13:09:30Z

1.- glass (in case it escaped, it's mostly a pun on "cider")
2.- logjam

ChatGPT didn't help with a 3.- 😔

bbatsov · 2023-06-19T14:29:36Z

I guess we kind of settled on logjam then! :D

vemv · 2023-06-19T14:30:31Z

I like its j!

Will create the repo with our usual infra later today.

r0man · 2023-06-19T15:24:08Z

Ok, sounds good to me. @vemv Thanks for setting up the repo!

vemv · 2023-06-19T15:32:55Z

Cheers. I'll create issues there for the remaining discussions (which of course are subject to be refined... no rush 🍻)

vemv · 2023-06-19T17:35:49Z

clojure-emacs/logjam#1
https://github.com/clojure-emacs/logjam/issues

bbatsov · 2023-06-19T18:03:19Z

This PR is still needed for the middleware part.

vemv · 2023-06-19T18:40:31Z

Ah, whoopsie, otoh it's somewhat questionable to have PR contents dramatically change

bbatsov · 2023-06-19T19:19:00Z

It's all the same to me, so whatever @r0man prefers. We can either re-open this one, or he can open a fresh one.

r0man · 2023-06-20T08:58:04Z

I can create a new PR, once I moved most things to the logjam repository.

r0man · 2023-06-20T09:41:44Z

Oh, and thanks for creating the issues @vemv . I just saw them now.

Add CIDER log middleware

c320457

r0man mentioned this pull request Jun 12, 2023

Add CIDER Log Mode clojure-emacs/cider#3352

Merged

5 tasks

vemv reviewed Jun 12, 2023

View reviewed changes

bbatsov reviewed Jun 12, 2023

View reviewed changes

src/cider/log/appender.clj Show resolved Hide resolved

vemv reviewed Jun 12, 2023

View reviewed changes

src/cider/log/specs.clj Outdated Show resolved Hide resolved

vemv reviewed Jun 12, 2023

View reviewed changes

bbatsov reviewed Jun 12, 2023

View reviewed changes

src/cider/nrepl/middleware/log.clj Show resolved Hide resolved

r0man added 8 commits June 13, 2023 10:12

Remove + from install profile

8d7c958

Prefix NREPL ops with cider

a16f5fd

Move java.util.logging config into test profile

2687e51

Clarify default-size and default-threshold doc strings

d37a305

Fix type hint of exception-name

9df2647

Move test.check to the test profile

1e7dea2

Use keep instead of remove nil?

12c820c

Move log specs to test dir

919cd39

r0man added 3 commits June 13, 2023 12:23

Instrument in test namespace

09fac63

Complete repl namespace specs

17f9a36

Remove obsolete disable-warning for deprecation

e195d14

r0man added 5 commits June 13, 2023 13:30

Add namespace doc strings and metadata

f7f92bb

Add changelog entry

874fc48

Use the next cider-nrepl version in metadata

ba09c4f

Add cider.nrepl/wrap-log to usage doc

59f4535

Add cider.nrepl/wrap-log to cider-middleware

d0bae21

r0man added 3 commits June 14, 2023 11:11

Add wrap-log to supplied middlewares

f249be0

Add log ops to supplied middleware

a1541ef

Accept keyword arguments in cider.log.repl

f6ef379

This is a bit more user friendly when typing in commands in the REPL. In Clojure 1.11 both, keyword arguments and a single options map, are supported.

This was referenced Jun 19, 2023

Log4j2 compatibility clojure-emacs/logjam#2

Open

Ability to set up logjam in advance for a given project clojure-emacs/logjam#3

Open

Don't let client slowness possibly block JVM threads clojure-emacs/logjam#4

Open

vemv closed this Jun 19, 2023

r0man mentioned this pull request Jun 26, 2023

Add CIDER log middleware #774

Merged

5 tasks

Add CIDER log middleware #773

Add CIDER log middleware #773

Conversation

r0man commented Jun 12, 2023 • edited Loading

r0man commented Jun 12, 2023

vemv commented Jun 12, 2023

r0man commented Jun 12, 2023

vemv commented Jun 12, 2023

vemv left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vemv commented Jun 12, 2023

vemv Jun 12, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

r0man Jun 19, 2023 • edited by vemv Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

r0man commented Jun 13, 2023

r0man commented Jun 13, 2023

r0man commented Jun 19, 2023 • edited Loading

r0man commented Jun 19, 2023

bbatsov commented Jun 19, 2023

vemv commented Jun 19, 2023

bbatsov commented Jun 19, 2023

vemv commented Jun 19, 2023

r0man commented Jun 19, 2023

vemv commented Jun 19, 2023

vemv commented Jun 19, 2023 • edited Loading

bbatsov commented Jun 19, 2023

vemv commented Jun 19, 2023

bbatsov commented Jun 19, 2023

r0man commented Jun 20, 2023

r0man commented Jun 20, 2023

r0man commented Jun 12, 2023 •

edited

Loading

vemv Jun 12, 2023 •

edited

Loading

r0man Jun 19, 2023 •

edited by vemv

Loading

r0man commented Jun 19, 2023 •

edited

Loading

vemv commented Jun 19, 2023 •

edited

Loading