Introduced a custom NATS logger facade #1076

stefanLeo · 2024-02-09T13:01:56Z

Rewired all STDOUTS to this facade and added extensive unit tests.

Added new logs for dns resolving and socketdataport timeout to showcase usage in 2 examples where logging can be valuable.
No other NATS code or APIs have been touched - also not the log process provisioning code.
This may then be done upon request as well as making the facades interface more convenient with parameters, log level filtering in the stdoutlogger, etc...

Happy tor receive your feedback and change things as per request.
@scottf FYI and thx again for your time :-)

… logger facade. Added new logs for dns resolving and socketdataport timeout to showcase usage in 2 examples where logging can be valuable.

scottf · 2024-02-09T15:45:11Z

src/main/java/io/nats/client/support/INatsLogger.java

@@ -0,0 +1,32 @@
+// Copyright 2020 The NATS Authors


Nit: Update the date to 2024

scottf · 2024-02-09T15:46:45Z

src/main/java/io/nats/client/support/INatsLogger.java

+ * nats.java library consumers.
+ * An exemplary default implementation of this interface logging to STDOUT can be found in this repo.
+ */
+public interface INatsLogger {


Please change to NatsLogger since we don't use I anywhere else. Just being consistent, right or wrong.

scottf · 2024-02-09T17:29:40Z

@stefanLeo Ok so this is not bad, but I can't use it this way. I was okay with only providing a way to handle existing trace statements, not add logging.

I would add a field in Options that accepts a TraceLogger implementations.
The default implementation NatsTraceLogger given by the factory, the output of _trace has to be exactly the same as it was before.
```
String timeStr = DateTimeFormatter.ISO_TIME.format(LocalDateTime.now());
"[" + timeStr + "] connect trace: " + message
```
Consider that someone might already be relying on this exact format in their logs, we cannot break this behavior.
I would prepare 2 default implementations, one when isTraceConnection is true and one when it's false. The false is completely empty (no-op), reducing the need to call if (trace) { _trace(...); }, just call the impl directly.

I see you made some changes to ServerPool and SocketDataPortWithWriteTimeout. The best I can offer is if you need logging in here is you will have to write your own and provide them in Options. The logging in SocketDataPortWithWriteTimeout is actually not meant to be logged. It's actually a workaround for java socket write not having a write timeout like it has a read timeout, i.e. not an error situation, but an error handling situation.

Added Noop Logger as default logger Added Logger to Options builder Added Log levels verification to StdOutLogger Changed NatsConnection log generation to user LOGGER methods Changed Log Levels for DNS & SocketDataPortWithWriteTimeout to not log to STDOUT per default.

stefanLeo · 2024-02-10T21:30:01Z

I did incorporate all of your feedback. Thx. I hope I did understand your last point correct... I can change it again if I got it wrong.

The lib should now behave exactly as before this PR in the default option and connecttrace option.

I left in den DNS and Sockettimeout logs for now, but reduced their log level which means noone will ever see them unless explicitly asked for. If you insist on removing them I will do so. I think providing more logs is better than less and then let the custom logger provided by the lib consumer decide what he/she wants to log or not. Otherwise people are basically blind in production if something happens or have to override and maybe copy code just to get some information about what has happened, which is also dangerous at times...

scottf

If you want to replace the NATS trace logger per connection, I'm perfectly okay with that.
I would make a trace logger interface, a way to set it in the options and some changes in NatsConnection.
NatsConnection can use an anonymous no-op implementation if one is not supplied in options and isTraceConnection is false. It can use a backward compatible anonymous implementation if one is not supplied but the isTraceConnection is true.
There should be no other logging additions to the PR. If we start adding logging and it touches performance even a millisecond, I'm going to get dinged left and right for slowing the client down.
I need to check with other client devs to see about their clients to even see what logging they provide, if any.

scottf · 2024-02-11T13:09:20Z

src/main/java/io/nats/client/impl/NatsConnection.java

@@ -46,6 +43,7 @@

 class NatsConnection implements Connection {

+    private final static NatsLoggerFacade LOGGER = NatsLoggerFacade.getLogger(NatsConnection.class);


LOGGER cannot be static. It must be specific to the instance of the connection, because the dev may want to log connections differently.

OK will change.
Pls. see https://www.slf4j.org/faq.html#declared_static for why I chose static in the first place. I.e. from a performance (CPU, Heap) PoV and "commonness" static is preferred. If IOC has higher prio it has to be an instance variable.

I think howver you meant someting differnt - you meant that every connection could have its own "logger" implementation that differes from others.. If yes then this has to change maybe on another level as well (in the facade) ... Will provide a change for this.

scottf · 2024-02-11T13:09:42Z

src/main/java/io/nats/client/Options.java

    /**
     * Property used to configure a builder from a Properties object. {@value}, see
     * {@link Builder#errorListener(ErrorListener) errorListener}.
     */
-    public static final String PROP_ERROR_LISTENER = PFX + "callback.error";
+    public static final String PROP_LOGGER = PFX + "callback.error";


Does not seem like the correct property name.

:-) woah must have been too late... Fixed.

scottf · 2024-02-11T22:46:38Z

This is what I was thinking: #1077

Made logger instances connection specific where needed Moved log level validation to facade which reduces GC pressure as less objects are created if level is set to OFF within the logger

stefanLeo · 2024-02-12T14:31:10Z

I did now make the logger connection specific where needed and removed nooplogger again. This can be covered much better by log levels and should also improve performance as less objects are created in case logging is disabled. So i.e., it is closer to NoOpLogger than it was before.

Let me know if I have to remove the logs I added - these should not affect performance at all as they are not on the ciritical path.
I was thinking about at a single threadpool for decoupling calls to provided/custom loggers in the first place, but thought that might be an overkill and people can still do so on their own and most logging frameworks anyhow do that today. I can add that however if you think this is beneficial.

Regarding log and perfomrance in general: I think the world is turning that way as you also do with NATS server adding open telemetry support in 3.11, which I think is an awesome feature. I.e., everyone is adding not only logs but metrics and traces.
At least the C# 2.0 NATS client is producing some logs. Go Client only limited but still providing logs. JS seems to have some console logs as well.. So we are in good company ;-)

scottf · 2024-02-12T15:17:20Z

As far as the trace logging I'd prefer to use the PR I built as it is consistent with plugging in something per connection.
I've been talking with the client lead. The feedback I'm getting is that adding logging must have a solid use case behind it and cannot affect performance. Connection logging is probably safe since it's not a time sensitive operation like publishing a large volume of messages.
That being said, I'd like to understand your reason for adding the logging where you did and how important it really is.
Also, there is already ConnectionListener which is used for async connection events and can be overridden with a custom implementation. We can certainly add some api to the interface (and have default implementations so as to maintain backward compatibility), and the user's implementation can use whatever logging they want.
The point of all this is that I'm not sure that this is necessary and really need a good reason to be able to defend this to my lead.
Like the place you added to the function that calls connect. This can easily be accomplished by the user logging just before they call this and with trace and/or connection listener it feels like there is already enough information.

scottf · 2024-02-12T21:35:15Z

@stefanLeo Copied from #1077

Yes. Fully understood. So the use cases are from my PoV:

Have an easy integration to grab whatever you log deep inside your code and ingest into my custom logging framework incl. the timestamps etc.
I fully agree that excessive logging ist not a good idea here, but adding logs at some critical points can help a lot with troubleshooting especially for new users who do not yet know what is important for nats to add to as listeners etc...
If the lib provides its set of logs it is much easier for you as a maintainer to debug/analyse issues on a customer site or if anyone opens a bug...
After all it is then your logs and not just some provided by some custom injected logging that may be compleltely wrong and/or it takes you ages to understand those logs.
So far for logging in general. Specifically: With DNS we had issues with the DNS server during failover tests in Openshift which led to reconnection timeouts of 30+ secs. It took us one week to figure out that the dns part was problematic using a profiling techniques. I.e., imho whenever something you request from an external system you should log it and the returned result in case it is something that does not happen all the time e.g.. connection interruptions or abortions, dns resolving, config parsing issues,... things like that.
Simply to make everyones life easier when having to troubleshoot issues or integrate nats.

Introduced a custom NATS logger facade and rewired all STDOUTs to the…

b006f01

… logger facade. Added new logs for dns resolving and socketdataport timeout to showcase usage in 2 examples where logging can be valuable.

scottf requested changes Feb 9, 2024

View reviewed changes

Merge branch 'main' into main

bee12c7

SLeonhar added 2 commits February 10, 2024 21:56

Merge remote-tracking branch 'origin/main'

eaa0c52

scottf requested changes Feb 11, 2024

View reviewed changes

SLeonhar added 3 commits February 12, 2024 11:29

Fixed Options

b1a3738

Logger instance is not static anymore.

d070ca8

Removed NoOpLogger in favor of log level handling

a287475

Made logger instances connection specific where needed Moved log level validation to facade which reduces GC pressure as less objects are created if level is set to OFF within the logger

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Introduced a custom NATS logger facade #1076

Introduced a custom NATS logger facade #1076

stefanLeo commented Feb 9, 2024 •

edited

scottf Feb 9, 2024

scottf Feb 9, 2024

scottf commented Feb 9, 2024

stefanLeo commented Feb 10, 2024

scottf left a comment

scottf Feb 11, 2024

stefanLeo Feb 12, 2024

stefanLeo Feb 12, 2024

scottf Feb 11, 2024

stefanLeo Feb 12, 2024

scottf commented Feb 11, 2024

stefanLeo commented Feb 12, 2024

scottf commented Feb 12, 2024

scottf commented Feb 12, 2024 •

edited

		@@ -46,6 +43,7 @@

		class NatsConnection implements Connection {

		private final static NatsLoggerFacade LOGGER = NatsLoggerFacade.getLogger(NatsConnection.class);

Introduced a custom NATS logger facade #1076

Are you sure you want to change the base?

Introduced a custom NATS logger facade #1076

Conversation

stefanLeo commented Feb 9, 2024 • edited

scottf Feb 9, 2024

Choose a reason for hiding this comment

scottf Feb 9, 2024

Choose a reason for hiding this comment

scottf commented Feb 9, 2024

stefanLeo commented Feb 10, 2024

scottf left a comment

Choose a reason for hiding this comment

scottf Feb 11, 2024

Choose a reason for hiding this comment

stefanLeo Feb 12, 2024

Choose a reason for hiding this comment

stefanLeo Feb 12, 2024

Choose a reason for hiding this comment

scottf Feb 11, 2024

Choose a reason for hiding this comment

stefanLeo Feb 12, 2024

Choose a reason for hiding this comment

scottf commented Feb 11, 2024

stefanLeo commented Feb 12, 2024

scottf commented Feb 12, 2024

scottf commented Feb 12, 2024 • edited

stefanLeo commented Feb 9, 2024 •

edited

scottf commented Feb 12, 2024 •

edited