4 ms·

> A point that may be pedantic: I don't add (and then remove) "print" statements. I add logging code, that stays forever. For a major interface, I'll usually st

> A point that may be pedantic: I don't add (and then remove) "print" statements. I add logging code, that stays forever. For a major interface, I'll usually start with INFO level debugging, to document function entry/exit, with param values. This is an anti-pattern which results in voluminous log "noise" when the system operates as expected. To the degree that I have personally seen gigabytes per day produced by employing it. It also can litter the solution with transient concerns once thought important and are no longer relevant. If detailed method invocation history is a requirement, consider using the Writer Monad[0] and only emitting log entries when either an error is detected or in an "unconditionally emit trace logs" environment (such as local unit/integration tests). 0 - https://williamyaoh.com/posts/2020-07-26-deriving-writer-monad.html https://williamyaoh.com/posts/2020-07-26-deriving-writer-mon...

strken 1y ago
It's absolutely not an anti-pattern if you have appropriate tools to handle different levels of logging, and especially not if you can filter debug output by area. You touch on this, but it's a bit strange to me that the default case is assumed to be "all logs all the time". I usually roll my own wrapper around an existing logging package, but https://www.npmjs.com/package/debug https://www.npmjs.com/package/debug is a good example of what life can be like if you're using JS. Want to debug your rate limiter? Write `DEBUG=app:middleware:rate-limiter npm start` and off you go.
- AdieuToLogic 1y ago
  > It's absolutely not an anti-pattern if you have appropriate tools to handle different levels of logging, and especially not if you can filter debug output by area. It is an anti-pattern due to what was originally espoused: I add logging code, that stays forever. For a major interface, I'll usually start with INFO level debugging, to document function entry/exit, with param values. There is no value for logging "function entry/exit, with param values" when all collaborations succeed and the system operates as intended. Note that service request/response logging is its own concern and is out of scope for this discussion. Also, you did not address the non-trivial cost implications of voluminous log output. > You touch on this, but it's a bit strange to me that the default case is assumed to be "all logs all the time". Regarding the above, production-ready logging libraries such as Logback[0], log4net[1], log4cpp[2], et al, allow for run-time configuration to determine what "areas" will have their entries emitted. So "all logs all the time" is a non sequitur in this context. What is relevant is the technique identified of emitting execution context when it matters and not when it doesn't. As to your `npm` example, I believe this falls under the scenario I explicitly identified thusly: ... an "unconditionally emit trace logs" environment (such as local unit/integration tests). 0 - https://logback.qos.ch/ https://logback.qos.ch/ 1 - https://logging.apache.org/log4net/index.html https://logging.apache.org/log4net/index.html 2 - https://log4cpp.sourceforge.net/ https://log4cpp.sourceforge.net/
  - strken 1y ago
    I understand that you explained some exceptions to the rule, but I disagree with two things: the assumption of incompetence on the part of geophile to not make logging conditional in some way, and adding the label of "anti-pattern" to something that's evidently got so much nuance to it. > the non-trivial cost implications of voluminous log output If log output is conditional at compile time there are no non-trivial cost implications, and even at runtime the costs are often trivial.
    - AdieuToLogic 1y ago
      > ... I disagree with two things: the assumption of incompetence on the part of geophile to not make logging conditional in some way ... I assumed nothing of the sort. What I did was identify an anti-pattern and describe an alternative which experience has shown to be a better approach. "Incompetence" is your word, not mine. > ... and adding the label of "anti-pattern" to something that's evidently got so much nuance to it. I fail to see the nuance you apparently can see. >> the non-trivial cost implications of voluminous log output > If log output is conditional at compile time there are no non-trivial cost implications, and even at runtime the costs are often trivial. Cloud deployment requires transmission of log entries to one or more log aggregators in order to be known. By definition, this involves network I/O. Network communication is orders of magnitude slower than local I/O. Useless logging of "function entry/exit, with param values" increases pressure on network I/O. Unless logging is allowed to be lossy, which it never is, transmission must be completed when log buffers are near full capacity. Provisioning production systems having excessive logging can often require more resources than those which do not excessively log. Thus disproving: > ... even at runtime the costs are often trivial. When considering the implication of voluminous log output in a production environment.
      - strken 1y ago
        As I said, conditional. As in, you add logging to your code but you either remove it at compile time or you check your config at run time. By definition, work you don't do is not done.
- TeMPOraL 1y ago
  I know a lot of people do that in all kinds of software (especially enterprise), still, I can't help but notice this is getting close to Greenspunning[0] territory. What you describe is leaving around hand-rolled instrumentation code that conditionally executes expensive reporting actions, which you can toggle on demand between executions. Thing is, this is already all done automatically for you[1] - all you need is the right build flag to prevent optimizing away information about function boundaries, and then you can easily add and remove such instrumentation code on the fly with a debugger. I mean, tracing function entry and exit with params is pretty much the main task of a debugger. In some way, it's silly that we end up duplicating this by hand in our own projects. But it goes beyond that; a lot of logging and tracing I see is basically hand-rolling an ad hoc, informally-specified, bug-ridden, slow implementation of 5% of GDB. Why not accept you need instrumentation in production too, and run everything in a lightweight, non-interactive debugging session? It's literally the same thing, just done better, and couple layers of abstraction below your own code, so it's more efficient too. -- [0] - https://en.wikipedia.org/wiki/Greenspun%27s_tenth_rule https://en.wikipedia.org/wiki/Greenspun%27s_tenth_rule [1] - Well, at least in most languages used on the backend, it is. I'm not sure how debugging works in Node at the JS level, if it exists at all.
  - strken 1y ago
    I agree that logging all functions is reinventing the wheel. I think there's still value in adding toggleable debug output to major interfaces. It tells you exactly what and where the important events are happening, so that you don't need to work out where to stick your breakpoints.
  - geophile 1y ago
    A logging library is very, very far from a Turing complete language, so no Greenspunning. (Yes, I know about that Java logger fiasco from a few years ago. Not my idea.) I don't want logging done automatically for me, what I want is too idiosyncratic. While I will log every call on major interfaces, I do want to control exactly what is printed. Maybe some parameter values are not of interest. Maybe I want special formatting. Maybe I want the same log line to include something computed inside the function. Also, most of my logging is not on entry/exit. It's deeper down, to look at very specific things. Look, I do not want a debugger, except for tiny programs, or debugging unit tests. In a system with lots of processes, running on lots of nodes, if a debugger is even possible to use, it is just too much of a PITA, and provides far too miniscule a view of things. I don't want to deal with running to just before the failure, repeatedly, resetting the environment on each attempt, blah, blah, blah. It's a ridiculous way to debug a large and complex system. What a debugger can do, that is harder with logging, is to explore arbitrary code. If I chase a problem into a part of my system that doesn't have logging, okay, I add some logging, and keep it there. That's a good investment in the future. (This new logging is probably at a detailed level like DEBUG, and therefore only used on demand. Obvious, but it seems like a necessary thing to point out in this conversation.)
- williamdclt 1y ago
  FWIW, it seems like poor man's tracing. You'd get that and a lot more having opentelemetry setup (using Jaeger for UI locally)
panstromek 1y ago
I don't quite like littering the code with logs, but I understand there's a value to it. The problem is that if you only log problems or "important" things, then you have a selection bias in the log and don't have a reference of how the log looks like when the system operates normally. This is useful when you encounter unknown problem and need to find unusual stuff in the logs. This unusual stuff is not always an error state, it might be some aggregate problem (something is called too many times, something is happening in problematic order, etc.)
- geophile 1y ago
  I don't know what's "important" at the beginning. In my work, logging grows as I work on the system. More logging in more complex or fragile parts. Sometimes I remove logging where it provides no value.
- AdieuToLogic 1y ago
  > The problem is that if you only log problems or "important" things, then you have a selection bias in the log and don't have a reference of how the log looks like when the system operates normally. A case can be made for only logging the steps performed up to and including an error. This even excludes logging "important things" other than those satisfying system/functional requirements (such as request/response audit logs). It is reminiscent of "the Unix philosophy", but different in important ways, and is essentially: Capture what would be log entries if a there is a future unrecoverable error. If an error is encountered, emit *all* log entries starting from the earliest point (such as receiving an external event or a REST endpoint request) up to and including the information detailing the unrecoverable error. If the workflow succeeds, including producing an expected failed workflow response (such as a validation error), discard the deferred log entries. What constitutes the deferred log entries accumulated along the way is specific to the workflow and/or domain model. While using a functional programming language and employing referentially transparent[0] abstractions (such as the Writer Monad) usually makes implementing this pattern much simpler than when using an imperative language, it can be successfully done with the latter given sufficient discipline and the workflow implementation being referentially transparent[0]. An important complement to the above is to employ other industry standard verification activities, such as unit/feature/integration tests. 0 - https://en.wikipedia.org/wiki/Referential_transparency https://en.wikipedia.org/wiki/Referential_transparency

strken 1y ago

It's absolutely not an anti-pattern if you have appropriate tools to handle different levels of logging, and especially not if you can filter debug output by area. You touch on this, but it's a bit strange to me that the default case is assumed to be "all logs all the time". I usually roll my own wrapper around an existing logging package, but https://www.npmjs.com/package/debug https://www.npmjs.com/package/debug is a good example of what life can be like if you're using JS. Want to debug your rate limiter? Write `DEBUG=app:middleware:rate-limiter npm start` and off you go.

AdieuToLogic 1y ago
> It's absolutely not an anti-pattern if you have appropriate tools to handle different levels of logging, and especially not if you can filter debug output by area. It is an anti-pattern due to what was originally espoused: I add logging code, that stays forever. For a major interface, I'll usually start with INFO level debugging, to document function entry/exit, with param values. There is no value for logging "function entry/exit, with param values" when all collaborations succeed and the system operates as intended. Note that service request/response logging is its own concern and is out of scope for this discussion. Also, you did not address the non-trivial cost implications of voluminous log output. > You touch on this, but it's a bit strange to me that the default case is assumed to be "all logs all the time". Regarding the above, production-ready logging libraries such as Logback[0], log4net[1], log4cpp[2], et al, allow for run-time configuration to determine what "areas" will have their entries emitted. So "all logs all the time" is a non sequitur in this context. What is relevant is the technique identified of emitting execution context when it matters and not when it doesn't. As to your `npm` example, I believe this falls under the scenario I explicitly identified thusly: ... an "unconditionally emit trace logs" environment (such as local unit/integration tests). 0 - https://logback.qos.ch/ https://logback.qos.ch/ 1 - https://logging.apache.org/log4net/index.html https://logging.apache.org/log4net/index.html 2 - https://log4cpp.sourceforge.net/ https://log4cpp.sourceforge.net/
- strken 1y ago
  I understand that you explained some exceptions to the rule, but I disagree with two things: the assumption of incompetence on the part of geophile to not make logging conditional in some way, and adding the label of "anti-pattern" to something that's evidently got so much nuance to it. > the non-trivial cost implications of voluminous log output If log output is conditional at compile time there are no non-trivial cost implications, and even at runtime the costs are often trivial.
  - AdieuToLogic 1y ago
    > ... I disagree with two things: the assumption of incompetence on the part of geophile to not make logging conditional in some way ... I assumed nothing of the sort. What I did was identify an anti-pattern and describe an alternative which experience has shown to be a better approach. "Incompetence" is your word, not mine. > ... and adding the label of "anti-pattern" to something that's evidently got so much nuance to it. I fail to see the nuance you apparently can see. >> the non-trivial cost implications of voluminous log output > If log output is conditional at compile time there are no non-trivial cost implications, and even at runtime the costs are often trivial. Cloud deployment requires transmission of log entries to one or more log aggregators in order to be known. By definition, this involves network I/O. Network communication is orders of magnitude slower than local I/O. Useless logging of "function entry/exit, with param values" increases pressure on network I/O. Unless logging is allowed to be lossy, which it never is, transmission must be completed when log buffers are near full capacity. Provisioning production systems having excessive logging can often require more resources than those which do not excessively log. Thus disproving: > ... even at runtime the costs are often trivial. When considering the implication of voluminous log output in a production environment.
    - strken 1y ago
      As I said, conditional. As in, you add logging to your code but you either remove it at compile time or you check your config at run time. By definition, work you don't do is not done.
TeMPOraL 1y ago
I know a lot of people do that in all kinds of software (especially enterprise), still, I can't help but notice this is getting close to Greenspunning[0] territory. What you describe is leaving around hand-rolled instrumentation code that conditionally executes expensive reporting actions, which you can toggle on demand between executions. Thing is, this is already all done automatically for you[1] - all you need is the right build flag to prevent optimizing away information about function boundaries, and then you can easily add and remove such instrumentation code on the fly with a debugger. I mean, tracing function entry and exit with params is pretty much the main task of a debugger. In some way, it's silly that we end up duplicating this by hand in our own projects. But it goes beyond that; a lot of logging and tracing I see is basically hand-rolling an ad hoc, informally-specified, bug-ridden, slow implementation of 5% of GDB. Why not accept you need instrumentation in production too, and run everything in a lightweight, non-interactive debugging session? It's literally the same thing, just done better, and couple layers of abstraction below your own code, so it's more efficient too. -- [0] - https://en.wikipedia.org/wiki/Greenspun%27s_tenth_rule https://en.wikipedia.org/wiki/Greenspun%27s_tenth_rule [1] - Well, at least in most languages used on the backend, it is. I'm not sure how debugging works in Node at the JS level, if it exists at all.
- strken 1y ago
  I agree that logging all functions is reinventing the wheel. I think there's still value in adding toggleable debug output to major interfaces. It tells you exactly what and where the important events are happening, so that you don't need to work out where to stick your breakpoints.
- geophile 1y ago
  A logging library is very, very far from a Turing complete language, so no Greenspunning. (Yes, I know about that Java logger fiasco from a few years ago. Not my idea.) I don't want logging done automatically for me, what I want is too idiosyncratic. While I will log every call on major interfaces, I do want to control exactly what is printed. Maybe some parameter values are not of interest. Maybe I want special formatting. Maybe I want the same log line to include something computed inside the function. Also, most of my logging is not on entry/exit. It's deeper down, to look at very specific things. Look, I do not want a debugger, except for tiny programs, or debugging unit tests. In a system with lots of processes, running on lots of nodes, if a debugger is even possible to use, it is just too much of a PITA, and provides far too miniscule a view of things. I don't want to deal with running to just before the failure, repeatedly, resetting the environment on each attempt, blah, blah, blah. It's a ridiculous way to debug a large and complex system. What a debugger can do, that is harder with logging, is to explore arbitrary code. If I chase a problem into a part of my system that doesn't have logging, okay, I add some logging, and keep it there. That's a good investment in the future. (This new logging is probably at a detailed level like DEBUG, and therefore only used on demand. Obvious, but it seems like a necessary thing to point out in this conversation.)
williamdclt 1y ago
FWIW, it seems like poor man's tracing. You'd get that and a lot more having opentelemetry setup (using Jaeger for UI locally)

panstromek 1y ago

I don't quite like littering the code with logs, but I understand there's a value to it. The problem is that if you only log problems or "important" things, then you have a selection bias in the log and don't have a reference of how the log looks like when the system operates normally. This is useful when you encounter unknown problem and need to find unusual stuff in the logs. This unusual stuff is not always an error state, it might be some aggregate problem (something is called too many times, something is happening in problematic order, etc.)

geophile 1y ago
I don't know what's "important" at the beginning. In my work, logging grows as I work on the system. More logging in more complex or fragile parts. Sometimes I remove logging where it provides no value.
AdieuToLogic 1y ago
> The problem is that if you only log problems or "important" things, then you have a selection bias in the log and don't have a reference of how the log looks like when the system operates normally. A case can be made for only logging the steps performed up to and including an error. This even excludes logging "important things" other than those satisfying system/functional requirements (such as request/response audit logs). It is reminiscent of "the Unix philosophy", but different in important ways, and is essentially: Capture what would be log entries if a there is a future unrecoverable error. If an error is encountered, emit *all* log entries starting from the earliest point (such as receiving an external event or a REST endpoint request) up to and including the information detailing the unrecoverable error. If the workflow succeeds, including producing an expected failed workflow response (such as a validation error), discard the deferred log entries. What constitutes the deferred log entries accumulated along the way is specific to the workflow and/or domain model. While using a functional programming language and employing referentially transparent[0] abstractions (such as the Writer Monad) usually makes implementing this pattern much simpler than when using an imperative language, it can be successfully done with the latter given sufficient discipline and the workflow implementation being referentially transparent[0]. An important complement to the above is to employ other industry standard verification activities, such as unit/feature/integration tests. 0 - https://en.wikipedia.org/wiki/Referential_transparency https://en.wikipedia.org/wiki/Referential_transparency