The Grug Brained Developer (2022)

> 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-mon...

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

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

1 - https://logging.apache.org/log4net/index.html

2 - https://log4cpp.sourceforge.net/

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.

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

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.

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

[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.

Conditionals aren't free either, and conditionals - especially compile-time - on logging code are considered by some a bugprone anti-pattern as well.

The code that computes data for and assembles your log message may end up executing logic that affects the system elsewhere. If you put that code under conditional, your program will behave differently depending on the logging configuration; if you put it outside, you end up wasting potentially substantial amount of work building log messages that never get used.

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.)

This is getting a bit far into the weeds, but I've found that debug output which is disabled by default in all environments is quite safe. I agree that it would be a problem to leave it turned on in development, testing, or staging environments.

The whole concept of an “anti-pattern” is a discussion ender. It’s basically a signal that one party isn’t willing to consider the specific advantages and disadvantages of a particular approach in a given context.

FWIW, it seems like poor man's tracing. You'd get that and a lot more having opentelemetry setup (using Jaeger for UI locally)

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.

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

You are very attached to this "voluminous" point. What do you mean by it?

As I said, responding to another comment of yours, a distributed system I worked on produced a few GB a day. The logs were rotated daily. They were never transmitted anywhere, during normal operation. When things go wrong, sure, we look at them, and generate even more logging. But that was rare. I cannot stress enough how much of a non-issue log volume was in practice.

So I ask you to quantify: What counts (to you) as voluminous, as in daily log file sizes, and how many times they are sent over the network?

BTW, your username is a bit too on-the-nose, given the way you are arguing, using "anti-pattern" as a way to end all discussion.

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.

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.)

> You are very attached to this "voluminous" point. What do you mean by it?

I mean "a lot" or more specifically; "a whole lot."

Here is an exercise which illustrates this. For the purposes here, assume ASCII characters are used for log entries to make the math a bit easier.

Suppose the following:

  Each log statement is 100 characters.
  Each service invocation emits 50 log statements.
  Average transactions per second during high usage is 200tps.
  High usage is on average 2 hours per day.

  100 x 50 x 200 x 60 x 60 x 2 = 7_200_000_000 = 7.2GB / day

> So I ask you to quantify: What counts (to you) as voluminous, as in daily log file sizes, and how many times they are sent over the network?

The quantification is above and regarding log entries being sent over a network - in many production systems, log entries are unconditionally sent to a log aggregator and never stored in a local file system.

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

> BTW, your username is a bit too on-the-nose ...

Resorting to an ad hominem and non sequiturs are we? Really?

C'mon, you are better than that.

> 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

7.2G/day doesn't sound terrible. And I'd reduce it by a factor of 25, since in normal operation (i.e., not looking into a problem) I would have either 2 log statements per call (entry, exit), or none at all. It might be more than 2, if I needed detailed logging.

But in normal usage, even in the scenario you describe your argument about log volume is not convincing.

I'm not sure what point you are making with your scenario involving HTTP response codes. What if the HTTP server crashes, and doesn't send a response at all?

I don't know from Writer Monads. But if you only emitting log entries on some future failure or request, then that's potentially a lot of logging to keep somewhere. Where? Log aggregator? Local files? Memory? What about log volume? Does this writer monad implement log rotation? It sounds like you are sweeping a lot of the things you object to under this writer monad rug.

Let me be real clear about all calls and param values leading up to a failure.

- In normal operation, turn logging off completely, or turn on some level that produces tolerable log volume, (it seems like your threshold is much lower than mine).

- When a failure occurs: Restart the service with more logging enabled, (hence the all calls an param values), so that you have logging when the failure occurs again.

About local logs vs a log aggregator: The system I worked on was a shared nothing archive. To add storage and metadata capacity, you add nodes. Each node also stored its own log files. I get that this may not be the answer all the time, and that a log aggregator is useful in some scenarios. However, even in that case, your concerns about log volume seem overblown to me.

> I'm not sure what point you are making with your scenario involving HTTP response codes.

My point was to identify how common the "happy path" scenario is and was in direct response to:

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

Regarding your question:

> What if the HTTP server crashes, and doesn't send a response at all?

Again, the HTTP status codes were used to illustrate the frequency of successful invocations. But to your point, if an HTTP server crashes then log entries for in-flight workflows would likely not be emitted. A similar possibility also holds for local file system logging as buffering exists (sometimes on multiple levels).

> I don't know from Writer Monads.

No worries. All it is is a formal definition of a type having specific capabilities called "laws" in the functional programming world.

> But if you only emitting log entries on some future failure or request, then that's potentially a lot of logging to keep somewhere. Where? Log aggregator? Local files? Memory?

What is meant by "future failure" is a failure potentially encountered during the evaluation of a single invocation. In the context of a HTTP server, this would be the handling of each submission to a specific HTTP endpoint and verb. This is often defined within an IO Monad[0], but does not have to be, and is out of scope for this discussion.

The answer to the rest of your questions is the deferred log entry definitions are held in memory for the duration of the single service invocation, with any log emissions produced transmitted to a network-accesible log aggregator via the logging component used.

> Let me be real clear about all calls and param values leading up to a failure.

The scenario you kindly shared is understandable, yet is one which has been unacceptable in teams I have worked with. Losing the "first error" is not an option in those environments.

0 - https://en.wikibooks.org/wiki/Haskell/Understanding_monads/I...