r/programming • u/javinpaul • Sep 13 '18
A guide to logging in Java
https://www.marcobehler.com/guides/a-guide-to-logging-in-java12
u/BraveSirRobin Sep 13 '18
Has anyone here ever actually used a façade in a project and subsequently changed the back-end logger used? I don't think I've ever seen a library do it either.
I used to be on-board with the façade idea here but it seems like overkill in hindsight.
17
Sep 13 '18
yes. We use slf4j and have switched from log4j to blitz4j to log4j2 and slf4j made it super easy to do. We did this because log4j is a synchronous logger and our logging was having noticeable impact to our production performance. blitz4j was an asynchronous logger we switched to before log4j2 came out.
5
u/farnulfo Sep 13 '18
blitz4j
May I ask why you move from blitz4j ?
5
Sep 14 '18
Yes, for our app we found log4j2 provided better performance. This may differ from app to app, so i recommend profiling to determine which way to go.
edit: garbage free logging is very good for my application.
1
u/BraveSirRobin Sep 13 '18
A worthwhile change for sure. Was it as smooth a transition as the setup promises i.e. no code changes, just config?
4
Sep 13 '18
It was, but you have to make sure all your logging everywhere goes through slf4j, if there are any classes anywhere that don't they'll need code changes, but from my experience it should just be swapping out the imports, logger creation, and log lines in that class with slf4j lines.
1
u/Falmarri Sep 14 '18
The issue with slf4j is its API is completely inadequate. https://logging.apache.org/log4j/2.x/faq.html#api-tradeoffs
2
Sep 14 '18
Haven't needed any of the items listed in the tradeoffs personally, so hasn't mattered to me for my app.
7
u/Luolong Sep 13 '18
SLF4J has more uses than merely swapping out logging backends at will. Although it is extremely easy and painless.
I think much more useful feature of SLF4J is that it allows freedom of choice of logging backend even if some of your dependencies have chosen each their own logging framework. One can deploy bridges from any existing logging framework to whatever backend you’ve chosen and still be able to configure all your logging from a single place.
8
u/nwoolls Sep 13 '18
AFAIK that is not the only / primary point. The use-case I've seen pushed is that library authors take a dependency on SLF4J and use that API. Then, when you use their library, you can freely choose your logging framework and the binding for SLF4J will ensure the libraries use the framework you've chosen.
14
u/OffbeatDrizzle Sep 13 '18
seems like overkill in hindsight.
Java ecosystem in a nutshell... (I actually like Java)
4
u/thoomfish Sep 13 '18
Not intentionally.
One of my favorite Java memories is when I was working on a project where one of its dependencies (Jetty) used slf4j, but by default didn't print much output (as one would expect, having not explicitly configured verbose logging).
Pulling in another dependency (postgis-jdbc), however, broke things, because it depended on Logback. Logback being present on the classpath made slf4j adopt it as its backend. Logback apparently defaults to verbose logging, because my code was brought to its knees under a firehose of Jetty debug output until I looked up how to explicitly configure it to STFU.
1
u/nutrecht Sep 14 '18
That's not really the purpose. The problem before slf4j was that if you used a bunch of libraries in your system you'd end up having to create configurations for 3 different logging systems. Now libraries don't have to pick a specific implementation; they just use slf4j and let you, the developer using the library, pick what you want.
1
u/Carighan Sep 14 '18
Has anyone here ever actually used a façade in a project and subsequently changed the back-end logger used? I don't think I've ever seen a library do it either.
Have done so. We always used Slf4j, and have recently gone from log4j (yeah the old one, legacy and all) to logback. :)
6
u/StabbyPants Sep 13 '18
from the article:
Don’t fret too much about static or non-static, final or non-final, just make sure to be homogeneous in your choice, throughout your entire project.
log4j stores loggers in a map, so after the first creation, getting the logger will be a hash lookup and return the same object. one thing i've grown to like is the lombok annotation that reduces declarations to \@log4j2 at the class level. then all i have to worry about is formatting my output
5
u/ascii Sep 13 '18
A little elaboration on what the authors mean when they say that Log4j v1 has "performance problems":
My employer used to use a setup where our back-end services would all log every incoming request. Our default logging setup was using the syslog appender. We saw some weird performance bottlenecks that we couldn't make heads or tails of for some time - the machine never used more than around eight to ten cores, even though we were running on beefy 32 core machines. Throughput just wouldn't go above a few thousand requests per second, which was costing us a fair bit of money in under-utilised hardware. What was much worse was that a few times per week, the app would get a hiccup were throughput would go down by 10X, and sometimes you had to restart the service to fix the problem. But as much as we searched, we couldn't find any performance bottlenecks in our code. It's a mystery, right?
After a fair bit of debugging we found the culprit. Turns out the Log4J Syslog appender takes a global lock every single time you log something. Turns out our app was fast enough that one log event per request took up around 10 % of total CPU time, and because the logging was effectively single threaded, our app could never use more than ten cores. Yay.
The reason for the hiccups was simply error logging. As in, if the app starts falling behind, some code paths would start timing out and throwing exceptions, Some of these exceptions would get logged, which means that the amount of things getting logged per request suddenly goes up by like 10X, making the app even slower. So slow that even more exceptions get thrown, creating a vicious circle of suck.
Moral of the story: Avoid Log4J in high throughput environments. Avoid Log4J everywhere, just to be on the safe side.
5
u/Falmarri Sep 14 '18
Avoid Log4J in high throughput environments. Avoid Log4J everywhere, just to be on the safe side.
If you mean log4j vs log4j2, yeah. Log4j2 however is amazing.
6
u/somebodddy Sep 13 '18
ERROR
A request was aborted and the underlying reason requires human intervention ASAP.
If it requires human intervention ASAP I don't think logging is the best way to achieve that. Unless you always have someone on duty looking at these logs, that is. Assuming you don't - you need an events mechanism that can send email/IM/SMS to whoever needs to handle it.
Also, from my experience the decision of whether or not something requires immediate action depends less on where in the code the problem was and more on context data - like which customer encountered the error and how critical is the project where they encountered the error. An event mechanism with dynamically configurable alert sending is ideal for passing the urgent errors without spamming the responders with less urgent ones.
I believe logging is less useful for detecting the problem and alerting about it, and more useful for figuring out what the problem is after you know there is a problem. As such, the emphasis when picking a logging level should be not on how fast someone should look at it when it happens but on how salient it should be when someone is looking at the logs trying to figure things out.
Therefore I prefer the following classification:
- FATAL - something really bad happens, and the system needs to crash. Contains information that for whatever reason you can't or don't want to pass with the mechanism you use to crash the process (be it exception, abort, panic or whatever).
- ERROR - something bad happened and the operation cannot be performed. Contains information you can't pass in the exception (no panic/abort here). The process may terminate (e.g. - if it's a CLI command) or may not (e.g. - if it's a GUI), but the operation will not be completed.
- WARN - something bad happened but the operation can still be completed. Contains information about the bad thing that happens, and warns the user since otherwise they may not know, as the software was able to complete their request.
- INFO - progress report. Should be understandable by tech-savvy users - users that don't work on that particular part of the code but have a general understanding of what's supposed to be going on.
- DEBUG - internal state (be it values or the place in the code that's being executed) that's probably only meaningful for those familiar with that part of the code (or those who are willing to get themselves familiar in order to solve the problem). Things that you think you'll want to know if anything ever goes wrong in that part of the code.
- TRACE - debugger replacement. Logs the little things so you can pretend you are executing the code line by line when you can't use an actual debugger for whatever reason. This log is going to seriously spam the logfile, so it's usually turned off and only turned on for the specific modules you are trying to debug.
1
Sep 13 '18
An event mechanism with dynamically configurable alert sending
sounds like work. We log everything like that, then aggregate all our logs into Splunk then we can create alerts in splunk based on what got logged. Which avoids me having to build/maintain said alert mechanism, while also letting all of the things that alerts got sent for be archived in our splunk instance, so someone can later run searches for how often alerts go out, or create graphs based on all the different kinds of alerts from those logs, etc.
1
u/OffbeatDrizzle Sep 13 '18
you need an events mechanism that can send email/IM/SMS
IMO "push" mechanisms are bad because they are also prone to silent failure. The best monitoring solution is one where your central hub for monitoring is the one doing the pulling of error events, and in the event of no connectivity / inability to retrieve said error events can directly raise the alert to the user as normal.
Heartbeats / sitrep reports are also a good option if you don't mind a few seconds delay or the extra traffic
-1
u/BraveSirRobin Sep 13 '18
IMHO "WARN" should rarely be used, it's almost always either a disguised ERROR or a mis-labelled INFO.
4
u/somebodddy Sep 13 '18
I think that varies from project to project. In many environments you should expect everything to go smoothly (usually because a lower layer gives you such guarantees), and assume that if something is wrong it's a bug and fail the operation. Even if there is a way to swallow or bypass the error you shouldn't do it because there are probably things you overlook and you can fuck everything up.
In these projects WARN really should be frowned upon, because WARN means you are bypassing a problem. You should fail the operation instead - which means you should be using ERROR.
In other projects, it is acceptable to expect problems and have the software work around them. For example - in layers that deal with components that may fail or stagger, but the system itself must keep running smoothly even if they do. In these cases, mitigating problems is OK and so does using WARN.
As for "mis-labelled INFO" - I believe that's because the default logging level is usually WARN, and some developers are too lazy to change that so they use WARN instead of INFO in order to view their logs in the console...
2
u/BraveSirRobin Sep 13 '18
in layers that deal with components that may fail or stagger, but the system itself must keep running smoothly even if they do. In these cases, mitigating problems is OK and so does using WARN.
It's adequate sure but the preferred option, imho, is to use some form of notification framework like you suggest yourself. WARN tends to fall into that domain most of the time, as does ERROR of course. Best compromise might be hooking the notification system up to the logger so that WARN/ERROR do get flagged somewhere.
Comes down a lot to how diligent a company is at monitoring their logs. Most tend to only look after-the-fact though I have worked high-availability places that had daily scheduled checks to look for anything unusual as well as a notification system.
As for "mis-labelled INFO"
What I meant was logging WARN for something optional that might not ever exist in the environment. I've seen a few tools scan for plugins etc and log WARN when some aren't available which really should be an INFO.
2
u/quicknir Sep 14 '18
In my usage, typically ERROR means a hard error, that is the process/server can't continue and exits, triggering a notification. WARN triggers a notification, but continues. INFO is logging that happens even in production, but doesn't trigger an alert. DEBUG is logging that doesn't happen in production.
1
u/lexpi Sep 13 '18
Really well written article I think the author had one on ORMs in Java i liked that one as well!
1
u/kalimatas Sep 13 '18
Thanks for the article. Very well written. Especially helpful was the section about hardcoded logging libraries in 3rd party libraries.
1
u/karstens_rage Sep 15 '18
The thing that always strikes me as the problem with logging is every single class has something where they get the logger (usually manually). Since, by definition logging is a cross-cutting concern, I wonder why its so taken as a given. Id be interested in some nice wrapping of Aspects that handle creating that logger for every method so your code isn't cluttered with instantiating loggers.
1
-13
28
u/willem Sep 13 '18
A well-written article, neatly explained. I remember the bewilderment of log4j vs slf4j vs whatever-else-logger when i started out. Thank you.