6 ms·

I feel that logging is a seriously hard problem and even experienced programmers struggle with it. It is almost impossible to anticipate what information will b

I feel that logging is a seriously hard problem and even experienced programmers struggle with it. It is almost impossible to anticipate what information will be useful later. So the first problem is to figure out the right logs at the right places. 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.

jimbob45 6y ago
I agree. Our architecture is partially built around logging every method called. Although it’s useful information, it still makes our product more difficult to program for. 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.
- wsargent 6y ago
  You can also hook up your logging to a feature flag system, so it's only activated for a single user. [1] [1] https://tersesystems.com/blog/2019/07/22/targeted-diagnostic-logging-in-production/ https://tersesystems.com/blog/2019/07/22/targeted-diagnostic...
BenoitP 6y ago
> So the first problem is to figure out the right logs at the right places. 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
- MaxBarraclough 6y ago
  > Don't log in high throughput loops 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?
  - maest 6y ago
    Sounds like you don't have enough information to make a decision when developing the function so thw logging behaviour should be configurable by the user.
    - MaxBarraclough 6y ago
      Yes, I suppose a simple parameter would do the job. Probably not worth anything fancy.
      - the_af 6y ago
        A parameter where? Obviously not in the code of the function itself; polluting your application code with flags such as log=true|false is obviously a no-go. Especially since logging is only one such "cross cutting concern", one of many, and you simply cannot go polluting your code with all of them because it leads to a mess. 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.
        BenoitP 6y ago
        Logging filtering is available per class in Logback [1], as well as having Markers which can target individual logging statements [2] [1] https://stackoverflow.com/questions/46062711/show-logs-only-from-one-class-using-logback https://stackoverflow.com/questions/46062711/show-logs-only-... [2] https://stackoverflow.com/questions/30248169/how-to-deal-with-logging-in-production-code-logback-slf4j https://stackoverflow.com/questions/30248169/how-to-deal-wit...
greggman3 6y ago
You forgot also making sure you aren't logging things you shouldn't log. Some are obvious maybe like passwords. Others might be less obvious like the title of every window on the user's desktop which Facebook Oculus logs. Those titles end up including every page of every website you've visited, the title of every document you've edited, and every video you've watched.
- NetOpWibby 6y ago
  Is this a bug or a feature?
- wsargent 6y ago
  Ideally the data should be filtered before it gets to logging in the first place, but if not, you can add another layer of defense by employing censors: https://tersesystems.github.io/terse-logback/guide/censor/ 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 https://github.com/logstash/logstash-logback-encoder#masking
  - wsargent 6y ago
    There's also Witchcraft Logging, which has the concept of "safe" parameters and is available in Go, Rust, and Clojure: https://docs.rs/witchcraft-log/0.3.0/witchcraft_log/ https://docs.rs/witchcraft-log/0.3.0/witchcraft_log/
masklinn 6y ago
To me that's why the original promise of dtrace was so nice, the idea of being able to dynamically turn logging on and off from the outside at locations never intended to log anything without even touching the source code sounded wonderful. 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/ https://ish-ar.io/python_ebpf_tracing/
- pjmlp 6y ago
  Depends on which flavour of Linux one goes by. https://docs.oracle.com/en/operating-systems/oracle-linux/dtrace-tutorial/E50705.pdf 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-9780136554820 https://www.informit.com/store/bpf-performance-tools-9780136...
  - masklinn 6y ago
    I would strongly doubt the sanity of anyone getting their linux distro from oracle.
    - pjmlp 6y ago
      Luckily most Fortune 500 management boards think otherwise, so I get to enjoy nice tools.
    - kyuudou 6y ago
      In cases like HPC and other performance-centric workloads, mainline kernel just doesn't have the hardware support needed for more exotic stuff like Infiniband and Mellanox cards, high-end SSD etc. Oracle got tired of waiting for sufficient support to be included which is why IIRC OEL UEK was created. If such hardware isn't being used, then yes, sanity should be questioned for supporting Uncle Larry's Linux.
- wsargent 6y ago
ed_elliott_asc 6y ago
It is but if you log decisions you make and why and stupid things like variables at various stages then you at least have half a chance.
crazy_hombre 6y ago
> The viewer journalctl is probably the worst log viewing app that exists 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.
wsargent 6y ago
> The second problem is to figure out if logging is affecting performance. 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/ https://www.infoq.com/presentations/jvm-60-memory/ [2] https://tersesystems.com/blog/2020/07/19/listening-to-jvm-metrics-with-javasound/ https://tersesystems.com/blog/2020/07/19/listening-to-jvm-me...

jimbob45 6y ago

I agree. Our architecture is partially built around logging every method called. Although it’s useful information, it still makes our product more difficult to program for. 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.

wsargent 6y ago
You can also hook up your logging to a feature flag system, so it's only activated for a single user. [1] [1] https://tersesystems.com/blog/2019/07/22/targeted-diagnostic-logging-in-production/ https://tersesystems.com/blog/2019/07/22/targeted-diagnostic...

BenoitP 6y ago

> So the first problem is to figure out the right logs at the right places. 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

MaxBarraclough 6y ago
> Don't log in high throughput loops 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?
- maest 6y ago
  Sounds like you don't have enough information to make a decision when developing the function so thw logging behaviour should be configurable by the user.
  - MaxBarraclough 6y ago
    Yes, I suppose a simple parameter would do the job. Probably not worth anything fancy.
    - the_af 6y ago
      A parameter where? Obviously not in the code of the function itself; polluting your application code with flags such as log=true|false is obviously a no-go. Especially since logging is only one such "cross cutting concern", one of many, and you simply cannot go polluting your code with all of them because it leads to a mess. 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.
      - BenoitP 6y ago
        Logging filtering is available per class in Logback [1], as well as having Markers which can target individual logging statements [2] [1] https://stackoverflow.com/questions/46062711/show-logs-only-from-one-class-using-logback https://stackoverflow.com/questions/46062711/show-logs-only-... [2] https://stackoverflow.com/questions/30248169/how-to-deal-with-logging-in-production-code-logback-slf4j https://stackoverflow.com/questions/30248169/how-to-deal-wit...

greggman3 6y ago

You forgot also making sure you aren't logging things you shouldn't log. Some are obvious maybe like passwords. Others might be less obvious like the title of every window on the user's desktop which Facebook Oculus logs. Those titles end up including every page of every website you've visited, the title of every document you've edited, and every video you've watched.

NetOpWibby 6y ago
Is this a bug or a feature?
wsargent 6y ago
Ideally the data should be filtered before it gets to logging in the first place, but if not, you can add another layer of defense by employing censors: https://tersesystems.github.io/terse-logback/guide/censor/ 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 https://github.com/logstash/logstash-logback-encoder#masking
- wsargent 6y ago
  There's also Witchcraft Logging, which has the concept of "safe" parameters and is available in Go, Rust, and Clojure: https://docs.rs/witchcraft-log/0.3.0/witchcraft_log/ https://docs.rs/witchcraft-log/0.3.0/witchcraft_log/

masklinn 6y ago

To me that's why the original promise of dtrace was so nice, the idea of being able to dynamically turn logging on and off from the outside at locations never intended to log anything without even touching the source code sounded wonderful. 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/ https://ish-ar.io/python_ebpf_tracing/

pjmlp 6y ago
Depends on which flavour of Linux one goes by. https://docs.oracle.com/en/operating-systems/oracle-linux/dtrace-tutorial/E50705.pdf 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-9780136554820 https://www.informit.com/store/bpf-performance-tools-9780136...
- masklinn 6y ago
  I would strongly doubt the sanity of anyone getting their linux distro from oracle.
  - pjmlp 6y ago
    Luckily most Fortune 500 management boards think otherwise, so I get to enjoy nice tools.
  - kyuudou 6y ago
    In cases like HPC and other performance-centric workloads, mainline kernel just doesn't have the hardware support needed for more exotic stuff like Infiniband and Mellanox cards, high-end SSD etc. Oracle got tired of waiting for sufficient support to be included which is why IIRC OEL UEK was created. If such hardware isn't being used, then yes, sanity should be questioned for supporting Uncle Larry's Linux.
wsargent 6y ago

ed_elliott_asc 6y ago

It is but if you log decisions you make and why and stupid things like variables at various stages then you at least have half a chance.

crazy_hombre 6y ago

> The viewer journalctl is probably the worst log viewing app that exists 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.

wsargent 6y ago

> The second problem is to figure out if logging is affecting performance. 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/ https://www.infoq.com/presentations/jvm-60-memory/ [2] https://tersesystems.com/blog/2020/07/19/listening-to-jvm-metrics-with-javasound/ https://tersesystems.com/blog/2020/07/19/listening-to-jvm-me...