2

Some of our customers from time to time report an unexpected behavior in one feature of our software and we suspect that we have a bug.

The feature itself and the kind of bug is not interesting for the purpose of this discussion, but just to fix the idea the broken piece is a command scheduler. From time time to time scheduled commands are lost and they are not executed at the schedueled time of the day. We are not currently able to reproduce this issue in a controlled way.

By investigating the service in charge of implementing the broken feature we noticed that the current implementation has an insufficient number of logs and this makes understanding the runtime behavior quite difficult. So, we decided to improve the logging in order to have better insights about the runtime behavior in the customer installation.

While reasoning about this problem I asked myself a basic question: is it a good choice depending on debug level logs in order to have a full understanding of what's going in a software product ? Is there a better way to handle this kind of situation ?

The point is that no one is going to run a software in production by enabling debug level logs (at least not in standard scenarios). When debug level logs are enabled plenty of logs are written and this can harm the log store in terms of storage consumption and performance.

So, the first problem is that debug level logs are not enabled by default in production and this means that when a problem arises for the first time you don't have your precious logs which can help you fully understand what exactly happened. You just observe an unexpected behavior, but you don't have a clear idea of the root cause.

This point can be very harmful because, in many cases, the pattern to reproduce an unexpected behavior is unknown or not very clear. This means that, once the debug level logs are enabled in order to carry on the investigation, it is entirely possible that you won't be able to reproduce the issue observed before and you are stuck unable to understand the root cause.

Are there better alternatives than low level logs to handle these scenarios ?

  • Depending on the technology you are working with, you might be able to use remote debugging, which allows you to put breakpoints and step through your code in production – overloading Mar 25 at 20:13
  • Yes, sometimes you very definitely do "run logs in production!" – Mike Robinson Mar 26 at 20:20
6

When you cannot reproduce a bug like a broken command scheduler outside of a production environment, and cannot mirror the production environment in your testing environment in a "similar enough" manner, logging, despite the drawbacks mentioned in the question, is IMHO still the best tool you have.

So in case you need "debug level logs", but your current logging mechanism will eat up to much storage or performance to be useful in production, I would recommend to optimize the logging. For example,

  • make sure you cannot only configure the logging "horizontally" (like "minimal", "standard", and "debugging" level), but also vertically (per "module"). That could be used to set the log level to "debugging" for the command scheduler, but keep it at "minimal" for the rest of the system

  • to optimize space, make sure debug logs are not longer kept than necessary. For example, if you can detect that a bug has occured within an hour after it occured, make it possible to delete "debug" log entries automatically which are older than, lets say, two hours.

  • optimize for speed by utilizing parallelization - maybe managing the log entries and writing them to disk can be done by an asynchronous logging service? Of course, that could become a source of extra errors, but it may be worth a try, if your logging system is not already implemented that way.

Optimization is very case-dependent, so there is not a one-size-fits-all solution for this, but I guess you get the general idea.

As an alternative to logging (or at least to "broad logging"), it could help if you try to implement a mechanics to detect when a specific bug occured automatically ASAP, and then write a post-mortem dump to disk. I don't mean this in the narrow sense of a persisted memory image of a crashed process, but as any kind of custom dump, implemented by yourself, containing all the information about the current state of the system which might be useful for finding the root cause of the issue.

How this has to look like, and if this will make sense for your case depends heavily on the details of the system, but there are definitely lots of systems where this has worked well in the past.

|improve this answer|||||
  • A variance of the post-mortem dump: Monolog (a logging library for PHP) has a so-called "fingers crossed" handler. It keeps lower level messages in memory until a high enough level gets logged, then the entire stack is persisted. Otherwise, the stack is discarded when it's no longer relevant. – Duroth Mar 27 at 15:37
1

I don't know about "Best", but these come to mind:

First of all, your intuition is correct,
Yes, sometimes the operational logs fail to cover the first occurence well.
but it's goal is to catch it not debug it.

  • .NET's IntelliTrace Gives an idea to keep multiple logs:

    • WarnLevel - kept forever
    • Debug - pruned after # days
      It won't help with performance, but will clean-up the log-store
      (most loggers can do that easily by configuration)
  • One more idea is to make a "Dynamic" log level.
    The log level rises as func of how many errors occur.
    (Note: I think this solution is too complicated and not worth the effort)

|improve this answer|||||
  • Yeah, if you look at /var/log on any "production" Linux/Unix system, you'll see that it's stuffed with logs. Your laptop (Mac or PC or Linux) keeps logs. Your phone keeps logs. And then we have nifty tools like logrotate which can automatically "gzip" logs and eventually discard them. – Mike Robinson Mar 26 at 20:22
1

The problem is:

  1. You want to log everything if there is a problem.
  2. You don’t want to log anything if there is no problem.
  3. You don’t know if there is going to be a problem.

If your code can recognise that there is s problem after it happened, you could solve this with quite a bit of work:
You have logging code for everything. However, the logging code only stores the logging statements in a buffer, at minimal cost. You tell the logger when you start and finish a complex operation and when an error is detected. Only when the operation is finished and detected an error on the way, then you store all the logging statements in your persistent store, otherwise you only store production logging statements.

That system doesn’t have to be all or nothing: If you didn’t tell the logger that an operation started, it ignores debug logs and only writes production logs, as it does now.

|improve this answer|||||

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.