5 ms·

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 ar

by 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.
      - 1y ago
- geophile 1y ago
  > There is no value for logging "function entry/exit, with param values" when all collaborations succeed and the system operates as intended. Well, I agree completely, but those conditions are a tall order. The whole point of debugging (by whatever means you prefer) is for those situations in which things don't succeed or operate as intended. If I have a failure, and suspect a major subsystem, I sure do want to see all calls and param values leading up to a failure. In addition to this point, you have constructed a strawman in which logging is on all the time. Have you ever looked at syslog? On my desktop Linux system, output there counts as voluminous. It isn't so much space, or so CPU-intensive that I would consider disabling syslog output (even if I could). The large distributed system I worked on would produce a few GB per day, and the logs were rotated. A complete non-issue. And for the rare times that something did fail, we could turn up logging with precision and get useful information.
  - AdieuToLogic 1y ago
    >> There is no value for logging "function entry/exit, with param values" when all collaborations succeed and the system operates as intended. > Well, I agree completely, but those conditions are a tall order. Every successful service invocation satisfies "all collaborations succeed and the system operates as intended." Another way to state this is every HTTP `1xx`, `2xx`, and `3xx` response code produced by an HTTP service qualifies as such. > The whole point of debugging (by whatever means you prefer) is for those situations in which things don't succeed or operate as intended. Providing sufficient context in the presence of errors, or "situations in which things don't succeed or operate as intended", was addressed thusly: If detailed method invocation history is a requirement, consider using the Writer Monad 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). > If I have a failure, and suspect a major subsystem, I sure do want to see all calls and param values leading up to a failure. See above. > In addition to this point, you have constructed a strawman in which logging is on all the time. No, I addressed your original premise in the context of a production web application, where logging is configured during deployment. See also your own contradiction by previously asserting, "I sure do want to see all calls and param values leading up to a failure." So which is it? Did I construct a strawman "in which logging is on all the time"? Or do you "want to see all calls and param values leading up to a failure", which requires "logging is on all the time"? > Have you ever looked at syslog? This is a strawman. Syslog is a component for logging and has nothing to do with the programs which use it. > The large distributed system I worked on would produce a few GB per day, and the logs were rotated. A complete non-issue. If this is the same system you described in a different comment also in this thread, I identified a standard industry practice of log entries produced by application nodes in a production environment being unconditionally sent to a log aggregator and not stored in a local file system. The reasons for this are well documented.
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)

by strken 1y ago

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.
    - 1y ago
geophile 1y ago
> There is no value for logging "function entry/exit, with param values" when all collaborations succeed and the system operates as intended. Well, I agree completely, but those conditions are a tall order. The whole point of debugging (by whatever means you prefer) is for those situations in which things don't succeed or operate as intended. If I have a failure, and suspect a major subsystem, I sure do want to see all calls and param values leading up to a failure. In addition to this point, you have constructed a strawman in which logging is on all the time. Have you ever looked at syslog? On my desktop Linux system, output there counts as voluminous. It isn't so much space, or so CPU-intensive that I would consider disabling syslog output (even if I could). The large distributed system I worked on would produce a few GB per day, and the logs were rotated. A complete non-issue. And for the rare times that something did fail, we could turn up logging with precision and get useful information.
- AdieuToLogic 1y ago
  >> There is no value for logging "function entry/exit, with param values" when all collaborations succeed and the system operates as intended. > Well, I agree completely, but those conditions are a tall order. Every successful service invocation satisfies "all collaborations succeed and the system operates as intended." Another way to state this is every HTTP `1xx`, `2xx`, and `3xx` response code produced by an HTTP service qualifies as such. > The whole point of debugging (by whatever means you prefer) is for those situations in which things don't succeed or operate as intended. Providing sufficient context in the presence of errors, or "situations in which things don't succeed or operate as intended", was addressed thusly: If detailed method invocation history is a requirement, consider using the Writer Monad 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). > If I have a failure, and suspect a major subsystem, I sure do want to see all calls and param values leading up to a failure. See above. > In addition to this point, you have constructed a strawman in which logging is on all the time. No, I addressed your original premise in the context of a production web application, where logging is configured during deployment. See also your own contradiction by previously asserting, "I sure do want to see all calls and param values leading up to a failure." So which is it? Did I construct a strawman "in which logging is on all the time"? Or do you "want to see all calls and param values leading up to a failure", which requires "logging is on all the time"? > Have you ever looked at syslog? This is a strawman. Syslog is a component for logging and has nothing to do with the programs which use it. > The large distributed system I worked on would produce a few GB per day, and the logs were rotated. A complete non-issue. If this is the same system you described in a different comment also in this thread, I identified a standard industry practice of log entries produced by application nodes in a production environment being unconditionally sent to a log aggregator and not stored in a local file system. The reasons for this are well documented.

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)