Live data from Hacker News

Log level 'error' should mean that something needs to be fixed

utcc.utoronto.ca

281–290 of 313 posts

Re: Log level 'error' should mean that something needs to be fixed

#281

Earlier quoted context omitted.

> An error is an event that someone should act on. Not necessarily you. Personally, I'd further qualify that. It should be logged as an error if the person who reads the logs would be responsible for fixing it. Suppose you run a photo gallery web site. If a user uploads a corrupt JPEG, and the server detects that it's corrupt and rejects it, then someone needs to do something, but from the point of view of the person…

Counter argument. How do you know the user uploaded a corrupted image and it didn't get corrupted by your internet connection, server hardware, or a bug in your software stack? You cannot accurately assign responsibility until you understand the problem.

This is just trolling. The JPEG is corrupt if the library that reads it says it is corrupt. You log it as a warning. If you upgrade the library or change your upstream reverse proxy, and starting getting 1000x the number of warnings, you can still recognize that and take action without personally inspecting each failed upload to be sure you haven't yet stumbled on the one edge case where the JPEG library is out of spec.

Re: Log level 'error' should mean that something needs to be fixed

#282

Earlier quoted context omitted.

There is no "connection string" in mail software that defines the remote host. The other party's MX records do that. If you are sending mail to thousands of remote hosts and one is unreachable, that is NOT a problem a mail administrator is going to be researching or trying to fix because they cannot, and it is not their problem. Either the email address is wrong, the remote host is down, or its DNS is misconfigured.…

OK yeah I think I see what you're saying, if the SMTP mailer is a hosted service and we're talking about the logs for the service itself then failed connections are not an error - this I agree with. I also wouldn't be logging anything transactional at all in this case - the transactional logs are for the user, they are functionality of the service itself in that case, and those logs should absolutely log a failure to…

It doesn't matter if it is a hosted service or if its just your local mail transfer agent, every "SMTP mailer" works the same way. There are lots of ways to send email that don't involve a locally administered SMTP mailer (such as an API which indeed has a connection string to a hosted service) but none would be described with that term.

Re: Log level 'error' should mean that something needs to be fixed

#283
post #45

How I'd personally like to treat them: - Critical / Fatal: Unrecoverable without human intervention, someone needs to get out of bed, now. - Error : Recoverable without human intervention, but not without data / state loss. Must be fixed asap. An assumption didn't hold. - Warning: Recoverable without intervention. Must have an issue created and prioritised. ( If business as usual, this could be downgrading to INFO. )…

I like to think of “warning” as something to alert on statistically, e.g. incorrect password attempt rate jumps from 0.4% of login attempts to 99%.

This sounds more like metrics than a log statement.

For me logs should complement metrics, and can in many instances be replaced by tracing if the spans are annotated sufficiently. But making metrics out of logs is both costly and a bit brittle.

Re: Log level 'error' should mean that something needs to be fixed

#284
post #161
post #153

Earlier quoted context omitted.

Simple: include those relevant details in the exceptions instead of hiding them.

It’s not that simple. First, this results in exception messages that are a concatenation of multiple levels of error escalation. These become difficult to read and have to be broken up again in reverse order. Second, it can lose information about at what exact time and in what exact order things happened. For example, cleanup operations during stack unwinding can also produce log messages, and then it’s not clear any…

> First, this results in exception messages that are a concatenation of multiple levels of error escalation. These become difficult to read and have to be broken up again in reverse order

Personally I don't mind it... the whole "$outer: $inner" convention naturally lends to messages that still parse in my brain and actually include the details in a pretty natural way. Something like:

"Error starting up: Could not connect to database: Could not read database configuration: Could not open config file: Permission denied"

Tells me the config file for the database has broken permissions. Because the permission denied error caused a failure opening the config file, which caused a failure reading the database configure, which caused a failure connecting to the database, which caused an error starting up. It's deterministic in that for "$outer: $inner", $inner always caused $outer.

Maybe it's just experience though, in a sense that it takes a lot of time and familiarity for someone to actually prefer the above. Non-technical people probably hate such messages and I don't necessarily blame them.

Re: Log level 'error' should mean that something needs to be fixed

#285

Earlier quoted context omitted.

You can have 0 parameters and the template is a string...

The point of my message is that you should avoid the `log(string)` signature. Even if it's appealing, it's an easy perf trap. There are many ideas if you look at SQL libs. In my example I used a different type but there other solutions. Be creative. logger.log(new Template("foo"))` logger.log("foo", []) logger.prepare("foo").log()

And none of those solve the issue.

You pass "foo" to Template. The Template will be instantiated before log ever sees it. You conveniently left out where the Foo string is computed from something that actually need computation.

Like both:

    new Template("doing X to " + thingBeingOperatedOn)

    new Template("doing " + expensiveDebugThing(thingBeingOperatedOn))
You just complicated everything to get the same class of error.

Heck even the existing good way of doing it, which is less complicated than your way, still isn't safe from it.

    logger("doing {}", expensiveDebugThing(thingBeingOperatedOn))
All your examples have the same issue, both with just string concatenation and more expensive calls. You can only get around an unknowing or lazy programmer if the compiler can be smart enough to entirely skip these (JIT or not - a JIT would need to see that these calls never amount to anything and decide to skip them after a while. Not deterministically useful of course).

Re: Log level 'error' should mean that something needs to be fixed

#286
post #92

Earlier quoted context omitted.

This is why it’s almost always wrong for library functions to log anything, even on ”errors”. Pass the status up through return values or exceptions. As a library author you have no clue as how an application might use it. Multi threading, retry loops and expected failures will turn what’s a significant event in one context into what’s not even worthy of a debug log in another. No rule without exceptions of course, o…

Depending on the language and logging framework, debug/trace logging can be acceptable in a library. But you have to be extra careful to make sure that it's ultimately a no-op. A common problem in Java is someone will drop a log that looks something like this `log.trace("Doing " + foo + " to " + bar);` The problem is, especially in a hot loop, that throw away string concatenation can ultimately be a performance probl…

> The problem is, especially in a hot loop ... The proper way to do something like this in java is either log.trace(..., ...) or if (log.traceEnabled()) log.trace(...)

The former still creates strings, for the garbage collector to mop up even when log.traceEnabled() is false, no?

Also, even if the former or latter is implemented as:

  fn trace(log, str, args...) {
     if (!log.tracing) return;
     // ...
  }
Most optimising JIT compilers will code hoist the if-condition when log.tracing is false, anyway.

Re: Log level 'error' should mean that something needs to be fixed

#287

Error log level should be renamed. It's just a terrible name that confuses usage.

Yeah, even alert/warn/info would be an improvement.

I hate the concept of “errors” in general. They’re an excuse to avoid responsibility, and ship broken software with known undefined behavior.

The very notion of an error basically means “there was behavior I chose to not handle and do anything about but which I knew would happen” which is essentially just negligence.

Re: Log level 'error' should mean that something needs to be fixed

#289

Earlier quoted context omitted.

Those conditions would be "Critical", no? The error vs warning distinction doesn't apply.

No, many applications need to be fault tolerant. Crashing your web stack because one route hit an error is a dumb idea. And no, calling it a warning is also dumb idea. It is an error. This article is a navel gazing expedition. They're kind of right but you can turn any warning into an error and vice versa depending on business needs that outweigh the technical categorisation.

A log entry marked "CRITICAL" does not imply crashing the web stack.

Re: Log level 'error' should mean that something needs to be fixed

#290

Earlier quoted context omitted.

The point of my message is that you should avoid the `log(string)` signature. Even if it's appealing, it's an easy perf trap. There are many ideas if you look at SQL libs. In my example I used a different type but there other solutions. Be creative. logger.log(new Template("foo"))` logger.log("foo", []) logger.prepare("foo").log()

And none of those solve the issue. You pass "foo" to Template. The Template will be instantiated before log ever sees it. You conveniently left out where the Foo string is computed from something that actually need computation. Like both: new Template("doing X to " + thingBeingOperatedOn) new Template("doing " + expensiveDebugThing(thingBeingOperatedOn)) You just complicated everything to get the same class of error.…

Yeah, it's hard to prevent a sufficiently motivated dev from shooting itself in the foot; but these still help.

> You conveniently left out where the Foo string is computed from something that actually need computation.

I left it out because the comment I was replying to was pointing that some logs don't have params.

For the approach using a `Template` class, the expectation would be that the doc would call out why this class exists in the first place as to enable lazy computation. Doing string concatenation inside a template constructor should raise a few eyebrows when writing or reviewing code.

I wrote `logger.log(new Template("foo"))` in my previous comment for brevity as it's merely an internet comment and not a real framework. In real code I would not even use stringy logs but structured data attached to a unique code. But since this thread discusses performance of stringy logs, I would expect log templates to be defined as statics/constants that don't contain any runtime value. You could also integrate them with metadata such as log levels, schemas, translations, codes, etc.

Regarding args themselves, you're right that they can also be expensive to compute in the first place. You may then design the args to be passed by a callback which would allow to defer the param computation.

A possible example would be:

    const OPERATION_TIMEOUT = new Template("the operation $operationId timed-out after $duration seconds", {level: "error", code: "E_TIMEOUT"});
    // ...
    function handler(...) {
      // ..
      logger.emit(OPERATION_TIMEOUT, () => ({operationId: "foo", duration: someExpensiveOperationToRetrieveTheDuration()}))
    }
This is still not perfect as you may need to compute some data before the log "just in case" you need it for the log. For example you may want to record the current time, do the operation. If the operation times out, you use the time recorded before the op to compute for how long it ran. If you did not time out and don't log, then getting the current system time is "wasted".

All I'm saying is that `logger.log(str)` is not the only possible API; and that splitting the definition of the log from the actual "emit" is a good pattern.

Post reply on HN