How can I make my logging more useful? [duplicate]

Question

I tend to find that after I build an application, the logs emitted by it become near useless and completely unparseable, and has the problem of being really verbose, while not outputting important stuff. Example:

    Apr  9 21:49:58.648 [    DEBUG] - Read configuration successfully
    Apr  9 21:49:58.649 [     INFO] - Kirisurf started
    [{nqzosnpdzvgr5umswrnmidd3n56zipl3 54.238.54.12:2380 200 [1 2 3] true} {wq7q5idgpkopb5vbh4qmhpne42so4uue 129.97.134.129:12345 200 [0 2 3] true} {3szie5c2keiqpubsktanxlf6$
    xifwi76 203.178.133.11:12345 200 [1 0 3] true} {wmxp2o6q2z5rm5rwprnry33lbwt4ikrn 133.68.253.242:12345 200 [0 1 2] true}]
    Apr  9 21:49:58.985 [    ALERT] - Enfreshen!
    Apr  9 21:49:58.985 [    ALERT] - Freshened!
    Apr  9 21:49:58.985 [    ALERT] - Enfreshen!
    Apr  9 21:49:58.985 [    ALERT] - Enfreshen!
    Apr  9 21:49:58.985 [    DEBUG] - Into buildings sc
    Wtfwtf
    Wtfwtf
    Wtfwtf
    Apr  9 21:49:58.985 [    ALERT] - Enfreshen!
    Apr  9 21:49:58.985 [    ALERT] - Enfreshen!
    Apr  9 21:49:58.985 [    DEBUG] - Into buildings sc
    Wtfwtf
    Wtfwtf
    Apr  9 21:49:58.985 [    DEBUG] - [{wmxp2o6q2z5rm5rwprnry33lbwt4ikrn 133.68.253.242:12345 200 [0 1 2] true} {wq7q5idgpkopb5vbh4qmhpne42so4uue 129.97.134.129:12345 200 [0 
    2 3] true} {nqzosnpdzvgr5umswrnmidd3n56zipl3 54.238.54.12:2380 200 [1 2 3] true}]
    Wtfwtf
    Apr  9 21:49:58.985 [    DEBUG] - Into buildings sc
    Wtfwtf
    Wtfwtf

For example, nobody will ever know what Wtfwtf means. In fact, it was just a debug printf statement I threw in to see whether a certain part of the code got stuck. The huge strings of public keys don't have descriptions of what they are. In fact, they are dumps of a circuit state datastructure. Nobody will ever know what the references to freshness are. Nobody will ever know that sc stands for "subcircuit", which is a jargon term nobody except me uses.

However, I really can't think of any way to clean this up. I could of course use more specific terminology and remove the wtfwtf, but looking at the logging output still doesn't tell you anything about what the program is doing (namely, finding a path in a graph of network nodes, and establishing a route through them).

I also have the problem of debugging. If I remove these ugly logging statements things may become difficult to debug. What's the tradeoff? Of course I use the debug logging level, but I don't want to pollute it so much that it becomes useless for debugging, filling with junk from known not buggy code.

Answer 1

The problem with logs is developers use logs to help them debug software rather than those using the software. They add messages that make only sense to them and remove the messages when they are not needed. This is poor practice.

Log entries like "Wtfwtf" only help a developer that can search for that string in the code. A better solution is to log something that makes sense to an operator or customer. That helps both the developer and the operator or customer.

In your case, I would:

1. Log information when it makes sense to a customer or operator, not developer. If the developer wants to log debug information, that's fine but strip it out in production, turn it off by default (by a logging level) or clearly differentiate it from other messages.
2. Provide lots of information. Having an error when user does operation X on Y? Include the user name, details of Y, the date, etc. Most systems log too little information rather than too much.
3. Do not log security sensitive or privacy sensitive information, like passwords or encryption keys. Be careful of logging stack traces or things that show the internal layout of code, too.
4. Log all errors, even if they seem unimportant, and what the system did (retried, aborted, different behaviour).
5. Do not log performance information or other things a log is not suited for. On Windows, for example, use Windows performance counters instead.
6. Use a consistent log entry format. For example, you may want to import logs into a database to provide some metrics for management or quickly search across multiple log files for information. Ensure each log entry has the same structure, dates and times have the same format and any enumerated values have defined and consistently used values. In your case, ensure any "ugly" debugging messages are at least written in the correct format.
7. Log using UTC dates and times. Daylight saving changes are common causes of issues. It also helps being able to correlate issues from different servers or log files easily.
8. Consider log retention/archiving/disposal. Log files can grow very quickly, consuming space and making them hard to search through. For example, create a new file each day and delete files older than a month. If a new log file is created when the program is run, give it a unique name so logs from older runs are not overwritten.
9. If logs have different audiences, log them to different locations. For example, log security sensitive information (audit information) separately. It is often needed for compliance and should not be tampered with.
10. Logs are rarely localized to different languages but logs may need to contain strings containing different character sets. Use a suitable encoding (e.g. UTF-8) consistently.

One easy way to address many of these is consider a logging framework like log4J or log4net. These provide a structured format, allow the log to be written to different or multiple locations (e.g. a database) and often use a separate thread pool to prevent logging becoming a bottleneck. It will also protect you from CRLF injection where someone may accidentally or maliciously try to manipulate log entries.

If the software is used internally, your organization may have logging or monitoring standards that cover some of this, particularly the log format and retention.

Regarding working out what to log, what are the steps in the algorithm? Subdivide the algorithm into steps and log the result of each one. Pretend you are the program explaining to a human how you came up with your results. It's like showing your working when doing a mathematics problem at school. Start with the high level steps then work deeper.

In your case, you describe the application it as "finding a path in a graph of network nodes and establishing a route through them". It sounds like there are two stages: finding the path then establishing it. Log those. Next, what is involved in finding a path? Sounds like an enumeration of a directed graph. Are there any optimizations that can exclude parts of the graph or recommend others? Include any details on them. As for creating a path, log the details of each device, whether the connections were successfully created and so on.

Answer 2

Usually it is said that logging is for operators of your software. However, this is not entirely true, since DEBUG logs are usually turned on while developing, for the benefit of the developers.

I tend to regard the different levels as interesting to different roles:

• DEBUG: developers only
• INFO: operators / developers
• WARNING: operators
• ERROR/CRITICAL: users

"Developers" are people with access to the source code; "operators" are people with access to the configuration and all system interfaces (the user interface and possibly an administrative interface); and "users" are people who just have access to one interface, namely the intended user's interface.

That means, when an error happens, a developer can restart the application with an entirely different code; an operator can restart it with just a different configuration; and a user can just retry with a different input.

Just like, in an exception, you should put enough information to let client code recover from the exceptional situation, in a log statement you should put enough information to let the person reading it change whatever he/she can change on the system, in order to accomplish whatever was his/her intention.

So, if it is a DEBUG statement, state which variables or methods did not satisfy which condition, if it is a WARNING, state which part of the system is non-responsive and has to be restarted or reconfigured, and if it is an ERROR, state what input was wrong and why it could not be processed.

Remember you can't possibly know what must be done (that is why operators exist), but also remember that at the point of logging you have all informations on what is going wrong.

Just my two cents.

Answer 3

This is what I'm doing in my latest project -- for the first time, so haven't totally tested in production.

#9384752 --- Jan 4, 2014 4:58:16 >>> FAILED :: [Chart] render <<< chart.class.php @ 43

And it parses like:

• #9384752 Unique identifier in order to find/mark each separated line easier.
• --- A very visible and eye-friendly separator.
• Jan 4, 2014 4:58:16 Human readable date/time
• >>> A very visible and eye-friendly separator.
• FAILED Record status.
• :: Again, separator.
• [Chart] Module name.
• render The actual log message.
• <<< Separator.
• chart.class.php File name.
• @ Separator.
• 43 Line number.

The idea is to have a useful Debug logs -- in the above example, so I tried to make it readable as much as possible. Those ---, >>> and <<<, they all help me read the log easier. Also it is easier to Search between logs -- e.g. >>> FAILED :: is unique within the entire record, so can be a keyword for jumping between records with no need to skip between similar words in the log messages itself. Parsing log records with Regular Expressions or string functions is much easier as well.

Also the Record Identifier helps me address that specific record later or when assigning tasks to other developers.

The Log Message itself is quite short as I hate to get lost between tons of words and have to read them to understand what's going on. In the above example I can simply understand that:

render method of Chart module, located in chart.class.php has failed at line 43.

Literally in a second.

So the key points are:

• Make it usable
• Make it readable and eye-friendly
• Make it search-friendly
• Address the problem, as short as possible, but include the necessary information
• Locate where does did the error happen

P.S. As I said this is the first time I'm using this format in a project, so there are potentially design-flaws that I'm not aware of.

P.P.S. This is my developer-friendly debug logs, so someone might not find it very suitable for other logging purposes.