Code to logging ratio?

Question

What is the ideal code to logging ratio? I'm not used to writing logs as most of the applications I've developed have not had much logging.

Recently though I've changed job, and I've noticed that you can't see the application code for the calls to log4net. I appreciate that this is useful but surely having too many debug statements is just as bad as not having any at all?

There are logging statements that tell you when every method starts and finishes and what they are returning. and when pretty much anything is done.

Would it not be easier to have some addon that used reflection to add the logging statements in at compile time so they didn't get in the way as you were trying to look at the code?

Also in these days of powerful IDEs and remote debugging is that much logging really nescisary?

Answer 1

There is actually a nice library for adding in logging after the fact as you say.

http://www.postsharp.org/

lets you do it via attribute based programming, among many other very useful things beyond just logging.

I agree that what you say is a little excessive for logging.

EDIT: SOme others bring up some good points, especially the banking scenario and other mission critical apps. May be necassary for extreme logging, or at least be able to turn it on and off if needed, or have various levels set.

Answer 2

That much logging is not necessary. There's no reason (in production) to know when each method starts and ends. Maybe you need that on certain methods, but having that much noise in the log files makes them nearly impossible to analyze effectively.

You should log when important things happen such as errors, user logins (audit log), transactions started, important data updated... so on and so forth. If you have a problem that you can't figure out from the logs, then you can add more to it if necessary... but only if necessary.

Also, just for your information, the adding logging in at compile time would be an example of what is called Aspect Oriented Programming. Logging would be the "cross cutting concern".

Answer 3

I personally believe that first of all there is no hard and fast rule, I have some applications that log a LOT, in and out of methods, and status updates through the middle. These applications though are scheduled processes, run hands off, and the logs are parsed by another application that stores success/failue.

I have found that in all reality, many user applications don't need large amounts of logging, as really if issues come up you will be debugging to trace the values there. Additionally you typically don't need the espense of logging.

However, it really depends on the project.

Answer 4

When you have a customer scenario (i.e., someone whose machine you don't get physical access to), the only things that are "too much logging" are repainting functions and nearly anything called by them (which should be nearly nothing). Or other functions that are called 100's of times per second during operation (program startup is ok, though, to have 100's of calls to get/set routines logged because, in my experience, that's where most of the problems originate).

Otherwise, you'll just be kicking yourself when you're missing some key log point that would definitively tell you what the problem is on the user's machine.

(Note: here I'm referring to the logging that happens when trace mode is enabled for developer-oriented logs, not user-oriented normal operation logs.)

Answer 5

Since log4net does a great job at not clogging up the resources, I tend to be a little verbose on logging because when you have to change to debug mode, the more info you have, the better. Here's what I typically log:

INFO Level

• The start and end of the method
• The start and end of any major loops
• The start of any major case/switch statements

DEBUG Level

• Any parameters passed into the method
• Any row counts from result sets I retrieve
• Any datarows that may contain suspicious data when being passed down to the method
• Any "generated" file paths, connection strings, or other values that could get mungled up when being "pieced together" by the environment.

ERROR Level

• Handled exceptions
• Invalid login attempts (if security is an issue)
• Bad data that I have intercepted forreporting

FATAL Level

• Unhandled exceptions.

Also having a lot of logging details prevents me from asking the user what they were doing when they got the error message. I can easily piece it together.

Answer 6

Complete log files are amazingly useful. Consider a situation where your application is deployed somewhere like a bank. You can't go in there and debug it by hand and they sure aren't going to send you their data. What you can get is a complete log which can point you to where the problem occured. Having a number of log levels is very helpful. Normally the application would run in a mode such that it only reports on fatal errors or serious errors. When you need to debug it a user can switch on the debug or trace output and get far more information.

The sort of logging you're seeing does seem excessive but I can't really say it is for certain without knowing more about the application and where it might be deployed.

Answer 7

I think another factor is the toolset/platform being used and the conventions that come with it. For example, logging seems to be quite pervasive in the J(2)EE world, whereas I can't remember ever writing a log statement in a Ruby on Rails application.

Answer 8

How many of those lines are logging by default? I've worked on a system very much like what you describe - just booting it up would cause over 20MB of logs to be written if logging was cranked way up, but even debugging we didn't turn it all the way up for all modules. By default it would log when a module of code was entered, and major system events. It was great for debugging since QA could just attach a log to a ticket, and even if it wasn't reproducible you could see what was going on when the problem happened. If you have serious multithreading going on then logging is still better than any IDE or debugger I've worked with.

Answer 9

Also in these days of powerful IDEs and remote debugging is that much logging really nescisary?

Yes, absolutely, although the mistake that many unskilled developers make is to try to fix bugs using the wrong method, usually tending towards logging when they should be debugging. There is a place for each, but there are at least a few areas where logging will almost always be necessary:

• For examining problems in realtime code, where pausing with the debugger would effect the result of the calculation (granted, logging will have a slight impact on timing in a realtime process like this, but how much depends greatly on the software)
• For builds sent to beta testers or other colleagues who may not have access to a debugger
• For dumping data to disk that may not be easy to view within a debugger. For instance, certain IDE's which cannot correctly parse STL structures.
• For getting a "feel" of the normal flow of your program
• For making code more readable in addition to commenting, like so:

// Now open the data file
fp = fopen("data.bin", "rb");

The above comment could just as easily be placed in a logging call:

const char *kDataFile = "data.bin";
log("Now opening the data file %s", kDataFile);
fp = fopen(kDataFile, "rb");

That said, you are in some ways correct. Using the logging mechanism as a glorified stack-trace logger will generate very poor quality logfiles, as it doesn't provide a useful enough failure point for the developer to examine. So the key here is obviously the correct and prudent use of logging calls, which I think boils down to the developer's discretion. You need to consider that you're essentially making the logfiles for yourself; your users don't care about them and will usually grossly misinterpret their contents anyways, but you can use them to at least determine why your program misbehaved.

Also, it's quite rare that a logfile will point you to the direct source of a certain bug. In my experience, it usually provides some insight into how you can replicate a bug, and then either by the process of replicating it or debugging it, find the cause of the problem.

Answer 10

When you come across a bug during the beta release of your application and can't reproduce it, you know that you should have done excessive logging. Same way if a client reports a bug but you can't reproduce it an excessive logging feature can save the day.

Answer 11

FYI, Jeff Atwood has put in his 2 cents about this exact question on his blog.

Answer 12

In my line of work, I write a lot of Windows services. For me, logging isn't a luxury,it's actually my only UI. When we deploy to production, we lose access to debugging and even the databases to which our services write and without logging we would have no way of knowing any specifics of issues that arise.

Having said that, I do believe that a concise logging style is the best approach. Log messages tend to be limited to the business logic of the application such as "received message from account xxx" than "entered function yyy". We do log exceptions, thread starts, echoing of environment settings and timings. Beyond that, we look to the debugger to identify logical errors in the development and QA phases.

Answer 13

I find that logging is much less necessary since I've started using TDD. It makes it much easier to determine where bugs lie. However, I find that logging statements can help understand what's going on in code. Sure, debuggers help give you a low-level idea of what's happening. But I find it easier when I can match a line of output to a line of code if I want to get a high level view of what's happening..

However, one thing that I should add is this: make sure your log statements include the module that the log statement is in! I can't count the number of times I've had to go back through and find where a log statement actually lies.

Answer 14

I must confess that when started programming I more or less logged all details as described by "Dillie-O".

Belive me ... it helped a lot during initial days of production deployment where we heavily relied on log files to solve hundreds of problems.

Once system become stable, I slowly started removing log entries as their value add started diminishing. (No log4j at those point in time)

I think, the ratio of code to log entries depends on the project and environment and it need not be a constant ratio.

Nowadays we've lot of flexibility in logging with packages like log4j, dynamic enablement of log level etc.

But if programmers doesn't use it appropriately, such as when to use when NOT to use INFO, DEBUG, ERROR etc. as well as details in log messages (I've seen log message like, "Hello X, Hello XX, Hello XXX etc." which only the programmer can understand) the ratio will continue to be high with less ROI.

Answer 15

I think "logs to code ratio" is a misunderstanding of the problem.

In my job I once in a while have a situation where a bug in a Java program cannot be reproduced outside the production environment and where the customer does NOT want it to happen again.

Then ALL you have available to you to fix the bug, is the information you yourself have put in the log files. No debugging sessions (that is forbidden in production environments anyway) - no poking at input data - nothing!

So the logs are your time machine back to when the bug happened, and since you cannot predict ahead of time what information you will need to fix a bug yet unknown - otherwise you could just fix the bug in the first place - you need to log lots of stuff...

Exactly WHAT stuff depends on the scenario, but basically enough to ensure that you are never in doubt what happens where :)

Naturally this means that a LOT of logging will happen. You will then create two logs - one with everything which is only kept around for long enough to ensure that you will not need it, and the other one with non-trivial information which can be kept for a lot longer.

Dismissing logging as excessive, is usually done by those who have not had to fix a bug with nothing else to go by :)