Over the years I have come to the following rule: during the development design-code-test loop, if the code does not work the first time it gets a logging line where it failed. It helps with debugging right now, and makes a sharp edge surface by some definition. You don't know what you don't know, so you might as well have information gathering around entropy-generating places.
Other than that:
* Don't log in high throughput loops (test them extra!); if you must, use a rate limiting logger with expiring delay.
* Log important parameters
* Log assumptions. Especially about data. There's always way more entropy in data.
* This applies to user-reported bugs, which is a form of a failed assumption. All information necessary to debug the issue now must go to the log.
Also end-to-end testing >> unit testing
Looks deceptively simple. Typically a function implements some behaviour or computation, and hopefully does so correctly and efficiently. Its usage is, well, up to the user. With the requirement that we don't log in high-throughput loops, this is no longer the case: we also have to anticipate usage patterns.
To put that another way, you might not know at the time whether your function is going to be invoked from a high-throughput loop.
Is there a nice solution to this problem?
> Is there a nice solution to this problem?
There's two ways to do it from within the logging framework. The first way is that you can suppress duplicate messages with a filter, like the DuplicateMessageFilter [1]. It wouldn't be that hard to add a filter that looked for the message template, and could suppress based on other properties on the LoggingEvent, such as the request ID or the overall similarity of the event.
The second thing you can do is add a budget for your logger, which will only allow it to log a certain period in a window. This is something you can do with budget evaluators [2].
Depending on the layer you put over SLF4J, you can also add conditional logging [3], which puts the logic at the application layer. Under this model, you'd have a counter or circuit breaker in the condition that would short-circuit the logging.
[1] http://logback.qos.ch/manual/filters.html#DuplicateMessageFi...
[2] https://tersesystems.github.io/terse-logback/guide/budget/
[3] https://tersesystems.github.io/blindsight/usage/conditional....
Meanwhile the general case is actually that actions are performed on a collection of things, although this is often not obvious due to OOP design. But when working with collections it becomes obvious that log messages should be aggregates over collections ("2 out of items failed, errors: ..."). This then creates magnitudes less of logging. It's just not mainstream now.
Many Java logging systems allow you to enable/disable logging per package, but this is still not enough for a per function decision.
Logging is a hard problem.
I have something for that. [1]
[1] https://tersesystems.github.io/blindsight/usage/conditional....
[1] https://stackoverflow.com/questions/46062711/show-logs-only-...
[2] https://stackoverflow.com/questions/30248169/how-to-deal-wit...
The fact that logging is at all intermixed with business logic I think is the main problem. I should be able to take a fully working logless program and apply different logging profiles to it. What gets logged should be a function of the person invoking the program.
I've been fighting this fight for a decade now, and I'm pretty sure I've never won it for a whole team. The best I got was that people would pre-populate bug fix code reviews with reasons why they couldn't sensibly unit test this particular issue. If you have had better success, please tell me your secrets!
Hmm, any examples of this?
> Hmm, any examples of this?
[1] https://dzone.com/articles/limiting-repetitive-log-messages-...
[2] https://github.com/mahanhz/clean-architecture-example/blob/m...
https://tersesystems.github.io/terse-logback/guide/censor/
Or you can use logstash-logback-encoder, which has masking:
https://github.com/logstash/logstash-logback-encoder#masking
Completely disagree there. I've had quite a pleasant experience with journalctl. It has sane arguments and you can easily grep any relevant log messages from the journal. You can add custom fields to your log messages. You can even get the logs in JSON format to parse log message from any scripts. And you can even use the cursor feature of journalctl to keep reading the logs at regular intervals without having to keep a constantly running process and tail the logs.
I can understand people not liking systemd-journald on account of the binary logs, but I definitely don't understand calling journalctl the worst log viewing app.
Sadly $dayjob runs servers on linux and isn't going to merge the dtrace patches in there, and python's systemtap probes are… limited.
Apparently bcc can hook into USDT probes though, I should look into that: https://ish-ar.io/python_ebpf_tracing/
If you want more advanced, then you can look at libstapsdt [3] which enables JVM applications to create USDT probes.
[1] https://tersesystems.github.io/terse-logback/guide/instrumen...
[2] https://github.com/reactor/reactor-tools#reactor-debug-agent...
https://docs.oracle.com/en/operating-systems/oracle-linux/dt...
Regarding BPF, the book is a must have for anyone doing serious stuff with it.
https://www.informit.com/store/bpf-performance-tools-9780136...
If such hardware isn't being used, then yes, sanity should be questioned for supporting Uncle Larry's Linux.
Performance isn’t much of a problem though. Have different logging levels and only turn on a high level when you’re trying to nail down a particular STR.
[1] https://tersesystems.com/blog/2019/07/22/targeted-diagnostic...
Spoiler -- it totally can. Kirk Pepperdine talks about logging as a memory allocation bottleneck [1]
So I gave my usual logging rant at a workshop that I gave. I was in the Netherlands about a year or so ago. And that night, they went and stripped all the logging out of their transactional monitoring framework that they’re using, which wasn’t getting them the performance they wanted, which is why I was there giving the workshop in the first place. And when they stripped out all their logging, the throughput jumped by a factor of four. And they’re going like, “Oh, so now our performance problem not only went away, we’ve been tuning this thing so long that actually, when they got rid of the real problem, it went much faster than they needed, like twice as fast as what they needed to go.” – The Trouble with Memory
Unfortunately it can be kind of hard to track the memory allocation rate over time, and it's typically not the sort of thing you're focused on. I put together an audio queue that will play the memory allocation rate as a sine wave [2] so I can tell when it's getting to be a problem.
[1] https://www.infoq.com/presentations/jvm-60-memory/
[2] https://tersesystems.com/blog/2020/07/19/listening-to-jvm-me...
The second problem is to figure out if logging is affecting performance. Or if a couple of logs can overpower everything else in a specific edge case. This will need thoughtful rate limiting and a good knowledge of the use cases your system will be subjected to.
Third problem is journald. Those journal logs are the worst. The viewer journalctl is probably the worst log viewing app that exists. These log files also have the unique quality of not being of any use outside the system they were generated on. No way to open them in Windows. Even on Linux, the times are all wrong. I don't know if that is a problem with journalctl or my system.