Use SLF4J for logging

[MrDOS]

This is a prototype of the functionality suggested in #193. It seems to work well enough. At the beginning of every JNI function, I call a setup macro which pushes a reference to the JNIEnv and jobj or jclass onto a thread-local stack; then I replace the report_error/report_warning/report/report_verbose functions with one which retrieves the current JNI context from that stack and uses it to look up and call the appropriate SLF4J logging function.

The result is very noisy. At the default DEBUG level of filtering, both Java and native code spam a lot of messages about their internal processes. If you enable TRACE-level output, you get a lot of extremely fine-level detail, mostly from report_verbose() in the native code. Stuff that no one would care about – like per-byte logging of data read. So even if this branch is already technically sound, I don't think it would be a good idea to cut a release including it until I've demoted more DEBUG-level logging statements to TRACE, and eliminated lots of the existing TRACE logs entirely.

I also want to look into how other libraries which integrate SLF4J keep output sparse and meaningful to downstream consumers, while still having lots of internal logging which is toggled off by default. I know there's got to be some way for libraries to log at higher levels but not spam the application log by default without requiring application developers to explicitly configure filtering of the library packages. Is that what markers are for? Will have to find out.

Note that this branch looks really long because it's based on #189. The work specific to this branch starts at the commit with the message “Use SLF4J for logging in the Java code.” (Currently f9a9596, but likely to change as I continue to work.)

[MrDOS]

Thank you for trying it. I just rebased onto #189 so you'll need to re-pull your branch if you want to make any more changes.

Back in fall, I went down a serious rabbit hole trying to analyze a bunch of other libraries to understand what levels they log at, and for what classifications of events. I'm still interested in picking that back up, but it might be more pragmatic to release sooner and refactor later. Before including this in a release, I would like to have clear instructions for where users can find the “off” switch, though. One interesting model I found in H2 was that it does all its logging through a single static logger instance:

private final Logger logger = LoggerFactory.getLogger("h2database");

That makes it ostensibly really easy for consumers to suppress any log messages they don't want by filtering for a single logger name. Not sure if that's really any easier than filtering against the gnu.io package, though.

[fwolter]

The projects I worked with are using the package/class name as the name of the logger. I think this is a reasonable approach as it gives max flexibility to the user. A filter can easily applied to a single class, then.

OpenHAB has a defintion of the logging levels. The granularity of logging levels is too fine for most (all?) openHAB addons. That's why mainly TRACE, DEBUG and WARN are used.

I think many of the log messages in nrjavaserial could be removed at all.

Before merging this we should add a default log4j config file, that the user can easily adjust the verbosity.

EDIT: Before merging we should document how to change the logging level. http://www.slf4j.org/faq.html#configure_logging

[MrDOS]

OpenHAB has a defintion of the logging levels.

That's a good style guide. Thank you for linking. I think my big concern/interest is in appropriate and consistent use of logging levels. I don't want to be too presumptuous about what's an error and what's really just debugging information. I guess I'll review each logging call.

Also, from that document:

Logging is not a replacement for using the debugger.

And how. Tracing on entering/exiting functions is everywhere in the C code, and I don't care for it at all. I'll pull that out, too.

we should document how to change the logging level.

Yeah, I've seen that documentation, too. I think that's a fine approach. In this day and age, I suspect almost all NRJavaSerial users are using SLF4j anyway, and probably have some idea of how to configure it. But a pointer in the right direction for anyone who isn't familiar would probably be a good idea.

[fwolter]

Logging is not a replacement for using the debugger.

And how. Tracing on entering/exiting functions is everywhere in the C code, and I don't care for it at all. I'll pull that out, too.

Fully agree!

I'm currently going through the code and try to make at least the DEBUG level usable.

[MrDOS]

Just so you're aware of my thoughts on merging this: after this functionality ready for merge, I'll probably rebase back onto the master branch. This code doesn't strictly require the new build system; it's just based on now it because it's way easier to try out changes to the native code on that foundation.

[fwolter]

Thanks for the invitation!

I observed a very high system load when the file descriptors reach the FD_SETSIZE limit. I assume that there's heavy trace logging, then. The JVM is so busy that I can't even adjust the log level to see which log message is causing it. I disabled trace logging in the native code locally for now.

Before tuning the logging further, I think it's a good idea to merge this and apply the formatter. WDYT?

[MrDOS]

TBH I think you've spent more time running this branch than I have, so you have a better sense of its stability than I do.

I would like to write a few words in the README about how to control/filter log output before merging. I'll try to do that soon.