4 ms·

> 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-cod

> 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...
      - Spivak 6y ago
        I mean there's no reason you couldn't have a thread-local override to the log level and restore it after the function call. 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.
        the_af 6y ago
        Definitely. I was trying to argue something about intermixing logging with app logic :) It indeed seems to me the decision about what to log should be the caller's, not the callee's, and so it shouldn't be hardcoded within the latter.
      - wsargent 6y ago
        > Many Java logging systems allow you to enable/disable logging per package, but this is still not enough for a per function decision. I have something for that. [1] [1] https://tersesystems.github.io/blindsight/usage/conditional.html#when https://tersesystems.github.io/blindsight/usage/conditional....
- eska 6y ago
  I think this is mostly a result of the OOP ethos to think of actions on single objects, where each function call created a log message. This is then called in a loop. 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.
- wsargent 6y ago
  > 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? 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#DuplicateMessageFilter http://logback.qos.ch/manual/filters.html#DuplicateMessageFi... [2] https://tersesystems.github.io/terse-logback/guide/budget/ https://tersesystems.github.io/terse-logback/guide/budget/ [3] https://tersesystems.github.io/blindsight/usage/conditional.html https://tersesystems.github.io/blindsight/usage/conditional....
Chris2048 6y ago
> use a rate limiting logger with expiring delay Hmm, any examples of this?
- usefulcat 6y ago
  You just have to remember the last time a particular log message was logged, and don't log it again until until some amount of time has passed.
- BenoitP 6y ago
  Here is an example with a Logback's TurboFilter in Java [1] [2] [1] https://dzone.com/articles/limiting-repetitive-log-messages-with-logback https://dzone.com/articles/limiting-repetitive-log-messages-... [2] https://github.com/mahanhz/clean-architecture-example/blob/master/application/configuration/src/main/java/com/example/clean/app/configuration/log/ExpiringDuplicateMessageFilter.java https://github.com/mahanhz/clean-architecture-example/blob/m...
- wsargent 6y ago
  >> use a rate limiting logger with expiring delay > Hmm, any examples of this? https://tersesystems.github.io/terse-logback/guide/budget/ https://tersesystems.github.io/terse-logback/guide/budget/
Afton 6y ago
I interpret your last line as "If an E2E test fails because of a product bug, the result should be a unit test". 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!

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...
    - Spivak 6y ago
      I mean there's no reason you couldn't have a thread-local override to the log level and restore it after the function call. 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.
      - the_af 6y ago
        Definitely. I was trying to argue something about intermixing logging with app logic :) It indeed seems to me the decision about what to log should be the caller's, not the callee's, and so it shouldn't be hardcoded within the latter.
    - wsargent 6y ago
      > Many Java logging systems allow you to enable/disable logging per package, but this is still not enough for a per function decision. I have something for that. [1] [1] https://tersesystems.github.io/blindsight/usage/conditional.html#when https://tersesystems.github.io/blindsight/usage/conditional....
eska 6y ago
I think this is mostly a result of the OOP ethos to think of actions on single objects, where each function call created a log message. This is then called in a loop. 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.
wsargent 6y ago
> 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? 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#DuplicateMessageFilter http://logback.qos.ch/manual/filters.html#DuplicateMessageFi... [2] https://tersesystems.github.io/terse-logback/guide/budget/ https://tersesystems.github.io/terse-logback/guide/budget/ [3] https://tersesystems.github.io/blindsight/usage/conditional.html https://tersesystems.github.io/blindsight/usage/conditional....

Chris2048 6y ago

> use a rate limiting logger with expiring delay Hmm, any examples of this?

usefulcat 6y ago
You just have to remember the last time a particular log message was logged, and don't log it again until until some amount of time has passed.
BenoitP 6y ago
Here is an example with a Logback's TurboFilter in Java [1] [2] [1] https://dzone.com/articles/limiting-repetitive-log-messages-with-logback https://dzone.com/articles/limiting-repetitive-log-messages-... [2] https://github.com/mahanhz/clean-architecture-example/blob/master/application/configuration/src/main/java/com/example/clean/app/configuration/log/ExpiringDuplicateMessageFilter.java https://github.com/mahanhz/clean-architecture-example/blob/m...
wsargent 6y ago
>> use a rate limiting logger with expiring delay > Hmm, any examples of this? https://tersesystems.github.io/terse-logback/guide/budget/ https://tersesystems.github.io/terse-logback/guide/budget/

Afton 6y ago

I interpret your last line as "If an E2E test fails because of a product bug, the result should be a unit test". 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!