Add CIDER log middleware #773
Conversation
|
I added a description for this feature over here: clojure-emacs/cider#3352 |
|
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. |
|
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. |
|
Nice! I see. I see that no dependencies are brought in either - it's dynamic 👍 |
src/cider/log/framework.clj
Outdated
| (def ^:dynamic *frameworks* | ||
| ['cider.log.framework.logback/framework | ||
| 'cider.log.framework.jul/framework | ||
| ;; 'cider.log.framework.log4j2/framework |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
| @@ -16,6 +16,7 @@ | |||
| cider.nrepl/wrap-format | |||
| cider.nrepl/wrap-info | |||
| cider.nrepl/wrap-inspect | |||
| cider.nrepl/wrap-log | |||
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
@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.
There was a problem hiding this comment.
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"?
There was a problem hiding this comment.
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.
|
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. |
| @@ -0,0 +1,110 @@ | |||
| (ns cider.log.framework.logback | |||
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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
identityfunction. - 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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
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.
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).
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.
|
This is a list of possible project names that I collected from various people:
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? |
|
This is my top 3 list:
|
|
|
1.- glass (in case it escaped, it's mostly a pun on "cider") ChatGPT didn't help with a |
|
I guess we kind of settled on |
|
I like its Will create the repo with our usual infra later today. |
|
Ok, sounds good to me. @vemv Thanks for setting up the repo! |
|
Cheers. I'll create issues there for the remaining discussions (which of course are subject to be refined... no rush 🍻) |
|
This PR is still needed for the middleware part. |
|
Ah, whoopsie, otoh it's somewhat questionable to have PR contents dramatically change |
|
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. |
|
I can create a new PR, once I moved most things to the logjam repository. |
|
Oh, and thanks for creating the issues @vemv . I just saw them now. |
Before submitting a PR make sure the following things have been done: