Replace logging system

[collinsmith]

It's about time to start looking into refactoring all logging to use a dedicated logger library with more refined controls and the ability to implement structured logging. I'd like to move away from using consts to control my log output and into using filters and preferably a way to output the log in a tree structure to improve readability. It should support being able to control log level at a global level and log level (i.e., release versions can set global log level to error and debug versions can leave it off and use log level set per class to improve ability to trace issues). Right now I've been looking into Log4j 2, but Logback looks good too.

[collinsmith]

After a few days of heavy research, I found a method using Log4J 2 to log messages how I want, but frankly, I don't like the verbosity of it. This method relies on MDC (map) or NDC (stack), but since those exist outside of the Logger, it means wrapping code in try-catch blocks to make sure the set values are unset. This makes the code look too noisy.

I'm opting for creating my own Logger implementation that has an API similar to that of Rust's slog structured logger crate. I can optimize this impl to be pretty performant, so I'm not super concerned. I'll also drop support for slf4j since I'm not going to use most of the features. The only impl detail I need to figure out is adding support for Java string format args. These tank performance 5-10x over Log4J's "{}", val syntax (probably due to temp copy strings), but whatever -- I can probably do a subset since I'm really only after a few specific things -- converting ints to 0 padded hex 0x%08X, byte array prints as hex octets [4A 4D], etc. I'm going to give up tons of features by not using a logging library, but I can always treat my own impl as a wrapper for something later, since I'm really only after adding structure.

---

This api will probably look something like below. I'm going to play with it.

Logger log = Logger.getLogger(Foo.class);
Logger child = Logger.getLogger(Foo.class).child(Bar.class).with("key", "value").build();

Each Logger will have an associated map that's immutable once created. This should allow for output like in slog

[collinsmith]

After playing around with multiple ideas, I decided to go with wrapping Log4J for the time being.

MDCLayout is a basic wrapper on top of a PatternLayout which will manage the compact context map tree and print the normal PatternLayout messages. This allows the PatternLayout functionality to remain, and MDCLayout can be turned off whenever needed, since it just manages the tree structure of the output.

I created Log utils class to support Log.*f(), e.g., Log.tracef("%s", obj); functions that generate StringFormattedMessage instances from passed arguments. This should allow me to have the best of both worlds by leaving most log messages as ParameterizedMessage and only using string formatting where absolutely necessary without the added verbosity of checking log level before evaluating a bunch of String.format calls.

I wanted as lightweight of an implementation of printing a compact MDC as possible, so I opted to created CTX utils class which uses its own context map, implemented as an OrderedMap. This allows me to cheaply access a context map and also it's ordering to print the log messages in a tree format. The original ThreadContext is still used for compatibility in the background, but MDCLayout only uses CTX for the output. This will likely need to be reevaluated in the future as a source of issues -- CTX is not thread local and there will probably be issues that come up from adding/removing KV pairs in a multi-threaded environment. There is already an issue with pushing multiple KV pairs without log events between them.

As an aside: CTX will probably need to be converted into a ThreadContextMap impl to fix threading support issues. I'd also like to look into being able to enable/disable this compact format in favor of appending the context map (possible during runtime). I don't anticipate this being difficult, just append the context map as a string when disabled.

[collinsmith]

I did some digging and experimentation with ThreadContextMap implementations, including rewriting DefaultThreadContextMap to use an OrderedMap, and it fundamentally won't work for my purposes. There are copies of the data made everywhere, and in the log event themselves, these are of type JdkMapAdapterStringMap which does a copy by creating a new HashMap which obviously does not preserve ordering. It just was not designed for this use-case.

To use the default implementation and deprecate CTX, I can make the sacrifice of printing the entire context map when it has changed. I don't want to do this, but I don't hate this idea -- maybe I'll take the route of printing the diff

After looking into this -- it will take more time than I planned to implement performing a diff of the previous depths. I'm going to shelve it, keep the impl that deprecates CTX and come back to the diff idea later.

[collinsmith]

I'm actually pretty happy with it. With this impl strategy, full mode will be useful for standard, and compact for development.

Compact mode

Full mode

[collinsmith]

This has been resolved. TODO: update logging across the board.