Slashdot Mirror
Software Logging Schemes?
MySkippy writes "I've been a software engineer for just over 10 years, and I've seen a lot of different styles of logging in the applications I've worked on. Some were extremely verbose — about 1 logging line for every 2 lines of code. Others were very lacking, with maybe 1 line in 200 devoted to logging. I personally find that writing debug and informational messages about every 2 to 5 lines works well for debugging an issue, but can become cumbersome when reading through a log for analysis. I like to write warning messages when thresholds or limits are being approached — these tend to be infrequent. I log errors whenever I catch one (but I've never put a 'fatal' message in my code, because if it's truly a fatal error I probably didn't catch it). Recently I came across log4j and log4net and have begun using them both. That brings me to my question: how do the coders on Slashdot handle logging in their code?"
As usual, "it depends" on what you are trying to achieve. Nobody can give you a blanket recommendation. But I guess in general: the log files need to give you enough information, that can't be got in other ways, to solve any problem that comes up.
We have a realtime product that goes all over the world and talks to hardware that we can't always get access to ourselves. Therefore, we sometimes must debug our code remotely. Obviously, logging is critical to this. We keep sometimes hundreds of MB of logs and have archiving rules and a tool for users to collect them. Every layer of the system keeps it's own logs, and all logs have timestamps to milliseconds.
In our case we log all the data back and forth, and then every important decision the code makes. For example if it decides there is something wrong with incoming data, it must log that. Any action it decides to take must be logged. Any data that will be passed on to other layers/the outside world must be shown. Generally, whenever we forget to log some of this data we will later regret it ("why the hell is it ignoring that device state..."). We also log at startup, basically the whole system configuration so that we can reproduce it.
Callstacks when there is an exception can be very useful. However, a lot of "errors" (at least in our case) are not exceptions but rather unexpected data or behaviour. We rarely have a crash and in state-based systems a callstack doesn't tell you much about what's going on. So a callstack is not useful for all situations.
Other times, you just want logging to give you a clue where in the code it was so you can run up the debugger and step through it (you do know how to step through code in the debugger, right?). In that case, too much logging can just get in the way. It might be sufficient in a GUI or web app to say which screen/page and which button was clicked.
You'd hope users could report this kind of details, but not always: if the user is working in another language, in another country, with two layers of helpdesk between you and them, and they are busy doing other things when the problem occurs and only call in the issue an hour later, and the helpdesk takes a week to report it to you - you may just get a vague or even misleading report that no-one can remember when you ask questions. In those cases log files may be all you have to go on.
There is also a tradeoff between log detail and manageability. Besides the difficulty in reading long log files, having a lot of detail means maintaining a lot of extra code. It also means that log files can become unmanagably large. In our case those hundreds of MB of logs can be a huge problem for customers to send to us because they have low quality internet connections (small companies in Mexico for example).
For every expert, there is an equal and opposite expert. - Arthur C. Clarke
I find I usually end up with 3 levels of logging:
Normal operation, often with some notion of "Yes, I'm still running even though I haven't done anything else lately".
Details. Usually corresponding to processing steps.
Algorithm tracing. This includes things like logging SQL queries. This is usually only of interest to me.
...laura
I work on a large air traffic control system. Logging is a huge issue. Log files are collected centrally by a separate application. One important issue IMO is making the contents of your various log files meaningful to people who are not familiar with them.
If your system has objects of type A B and C which can be handled by different components of your system then your should make the logging system in those components print information about those objects in exactly the same way.
While you are at it, make the log format easily parsable by software. You don't want to be looking for a needle in a gigabyte size haystack of trace information without help from a tool which understands what it is looking for.
http://michaelsmith.id.au
I will add lots of logging to debug a specific problem and then rip it out when the problem is fixed. Permanent logging includes run time problems like serial communication errors, file not found, etc. I like to make various logging functions switchable, so user input can be logged for example, but only when needed. Once a program is running well, it should only log data for dire exceptions, unless regular accounting logs are needed.
"Otherwise don't do much logging because it will hurt application performance, sometimes drastically."
You're assuming that performance -- or, more precisely, CPU usage -- is important; in many cases, reliability (and being able to track down bugs after a crash) are far more important than CPU usage. With quad-core CPUs so cheap these days, we can easily afford to spend another thousand dollars to throw more processing power into a system which has cost a couple of hundred thousand dollars of programmer time to develop and will cost thousands of dollars an hour for any downtime.
My online applications log to a database, not a text file. Multiple applications on different machines can log to the same database table. There's no need for "log rotation"; old entries can be summarized and purged by date on the live database. With appropriate indexed fields, you can find key log entries in huge log files very rapidly.
Even program faults are logged to the database. If the program crashes, the top-level exception handler catches the event, does a traceback, opens a fresh database connection, and logs the traceback.
Don't coddle weak programmers... it's survival of the fittest out here. Either they learn to nourish themselves from the ample teat of a stack dump, or they must perish. It is for the good of our civilization. I know this seems harsh, young Jedi, but it is the way of the Elders of Assembler, from the ancient Time Before OO. Now go Forth and code.
Okay, joking aside. Parent has a great point -- logging can generate incredible volumes of text and can form a remarkable bottleneck, especially on VM systems where your OS may not be the only one hitting the disk.
So take advantage of Log4J/Net's ability to log at different severity levels and make logging globally configurable so you can enable/disable entirely at runtime. I'd recommend you log the following : object creation, scarce resource allocation, recoverable failure/error conditions and unrecoverable failures. Preface each severity level with a unique label so you can grep for it later. Even at the most verbose level, you can then grep your output to see only what's of interest to you (e.g. "unrecoverable:...").
If you're using log4j, don't use multiple hosts to write to the same nfs filesystem file. You'll run into blocking issues and log4j doesn't handle them correctly. The nirvana of clustered app logging is an async JMS queue. You fire off the message and forget it. You don't wait for file handles.
It's not CPU that's at a premium, it's disk IO. And on virtualized machines (such as is extremely popular in corporations and hosting farms) where there might be four different OSs running on the same physical hardware, disk becomes a scarce resource very, very quickly. And not only does your virtualized server go to shit, it takes the others down with it since they can't get timely disk access, either.
It depends on the app you're writing -- is it a web app, a database app, a userspace program written in C, a Perl/Ruby script, or.. At work we created our own logging library in C to emit log events for different levels, e.g. informational, debugging, warnings, errors, fatal messages. We then have wrappers around that library so that languages like Ruby can access that logging library. But on hindsight I think I would've just used syslog if I had to start over. :)
I don't, save the rain forest, hug a tree, prevent deforestation, stop logging now!
Segmentation fault: core dumped
I wrote up a two-part piece on logging best and worst practices a while back. See Part I and Part II if you are interested.
1 line of logging per 200 lines of code is way too much. 2 in 5 lines is absolutely insane. I've seen way too many systems where the logging made it totally unusable. People just don't realize the costs of logging everything.
There's absolutely no way to document anything this verbose. Without documentation, the logging is useless.
Agreed, logging every 2 to 5 lines gives you the kind of information that you should really be getting with a debugger. Of course, when you're trying to diagnose a specific problem, sometimes it can be easier to put log messages every line or two than to repeatedly step through the code with a debugger, but that's sort of the same thing, just a temporary debugging aid - most of that logging output should be removed once you've figured out what's going on. For general use, I think about one log call per function might be reasonable - more if it's a long function, or none if it's a short function that does something really simple. And even most of those should probably be disabled once you release the software.
Comment removed based on user account deletion
My logging is setup so I can quickly filter down to the type of data I want. It's more than just "information", "warning", and "error" - but by (cpp)file, module, etc. That way, if an issue arises, I can eliminate the cruft and see just what I need. Just takes planning.
Why can't all fpga/microcontroller manufacturers just release free optimizing compilers???
I work on a real-time embedded medical device, where both performance and reliability are vital. We've got constrained resources, and the system must be extremely responsive.
Our logging scheme is pretty cool. It's written so that two computers can log to a single hard drive, and each logging statement must define a log level. So, for example, if I'm writing GUI code, I can log to log_level_gui_info, log_level_gui_debug, log_level_gui_error, or any of a number of more specific log levels.
The idea is
So, we have two ways to filter out extraneous logging that we don't care about (one actually keeps the logging from happening, and one just filters it out during analysis), and we can log as freely as we like as long as we're smart about which levels we're using.
As much faith as we all have in our own code, nothing's as frustrating as trying to analyze a log that came in from the field where there's just no information about what went wrong.
I tend to do my debugging by inserting a lot of printf statements to indicate where in the program I currently am and the value of any critical variables at that time. As the output information is no longer needed (i.e. I fixed the bug it was attached to), I tend to cull out whatever isn't useful anymore. However, I tend to keep starting messages in function calls related to a routine I'm working on or making more than a trivial change to... since chances are, knowing me, I'm going to end up putting them back in there anyway once I create a new bug... and lets face it, it WILL happen.
Once I'm done, I go back, remove or comment out (usually just comment out) all the messages that have no redeeming value for a properly functioning program, and turn the rest into debug statements which print based on the debug level provided at execution time... or sometimes I use a mask to select which types of messages to display.
-Restil
Play with my webcams and lights here
I write code for Telecom test systems that need to run 24x7 processing highly varying requests from dozens of different client systems. Our system consists of dozens of different processes/components per host, with multiple hosts all invoking components on each other as needed (all via CORBA). There are very many paths that any request can take through our system.
In this environment we log VERY heavily since each request is close to unique and we need to be able to determine the path it took through the system, and why it did, and what happened, in the event of any bug report. Some of the haviest used modules can produce close to 1GB of log per day per host - upto a couple hundred lines of logging information per request per process that it passes thru. We use a custom printf-like log library written in C++ (that auto rotates the log files based on various criteria), a custom tail utility for dealing with the large log files (tail a log file from a given timestamp - done instantly via binary search on the timestamps) and a daily cron job to compress the older log files and move any older than 5 days off the production servers to someplace with more storage.
That should be about right...
On the other hand, broken code hurts application performance, sometimes drastically.
I'm an SQA engineer with years of experience working with large scale enterprise systems. Generally speaking the cost of unexpected outages or data corruption outweighs the cost of hardware. In such systems the costs of deployment activity itself can be such that you'd rather pay for more hardware to support extremely verbose logging.
Sure, boneheaded logging can cause unnecessary performance hits, the obvious example being logging in a loop when logging at entry and exit would have sufficed. But that's not what we are really talking about here. You posited that you should do as little logging as practically possible, and I believe that you are wrong.
Log lots and log often. Just do so intelligently. Use a logging framework (log4j, log4net, log4perl etc) and set the priority appropriately. Only use ERROR for real errors (unexpected code paths or data), use WARN when a performance metric is hitting a soft limit (to warn you before you hit that hard limit), and use DEBUG to verbosely log anything else of general interest. Rarely you might also want to log in an extremely verbose manner data that wouldn't ordinarily be interesting, and this should be logged at a TRACE level. Generally speaking if this is the case then the code itself is due for a refactor. FATAL should normally be reserved for errors that prevent correct startup - generally if an application runs correctly at startup then any potential faults that you see and handle now become ERRORs because there is nearly always something better an application can do than log FATAL and exit. As the OP observed, if you have a potential fault that kills your application and you don't see and handle it then you don't have the opportunity to log FATAL anyway.
By using a logging framework, many logging pitfalls can be avoided because the framework itself provides well tested facilities. eg, time-stamping, log rotation, file-handle management etc. In addition, using a framework allows the operator to tune the logging on a very granular level. This allows for a trade off to be made where if a performance impact is noted in a well used class then its logging can be reduced at runtime. Sure, there is still a small performance impact because the logging framework has to do a "if (logMessage.logLevel >= loggingClass.logLevel ) then {...}" comparision, but in the scale of things that impact is tiny.
My profession is not about finding and fixing bugs. It is about understanding the software that is being delivered and deployed. It is about understanding what defects exist (or may exist) and the possible implications of those defects. It is about reducing the risk of defects through analysis. Analysis of the software's functionality, analysis of the software's performance, analysis of the processes used to produce the software itself. You will never be yelled at for releasing software with a well understood and documented defect, but the shit will hit the fan when you release major defects that are not understood.
Logging is an _invaluable_ tool in this analysis. You'd be a fool to not use it effectively.
I work on set top boxes, and not every platform we port to has a good debugger (hell, its been years since I've seen a good debugger). Our logging system is all in house; multiple "levels" for each log statment, (noise,information,warnings,fatals,etc), with each module creating its own log id and setting its "preference level". It works well, but:
1) Useless logs.
Engineers not taking the time to write logs that are useful. "Got to here", "Value=1", etc. A few of us write enum-to-string functions and pass them to the logging system for cleaner output.
2) Running at the speed of 115200.
We've only got a serial port most times, with multiple threads trying to access it, there's got to be some synchronization, and this generally affects threads of any priority. Using a logger that caches and outputs logs at its own pace is nice.
this is my sig, there are many like it, but this one is mine.
First - let me give you my own perspective. I recommend having each subsystem log in such a fashion that you can easily grep to include or ignore that subsystem. For example for one package the following LVLx messages were the first four characters as follows:
LVL1 - basic startup and shutdown info ( a few lines per run)
LVL2 - Interactions with the database
LVL3 - Interactions with the file system
LVL4 - Detailed database interactions including each sql statement
LVL5 - amazingly verbose debug information including memory and variable allocations
In almost all cases, I recommend being able to set each level on or off. Your sysadmin (maybe yourself) will appreciate that ability.
If appropriate, I recommend an 'audit' record after each completed or aborted transaction. EG - after every order or every user change or whatever is important for accountability / business activity monitoring purposes.
This is the original question .
There is no code in the world that I can think of that needs a log line after every two steps in a procedure.
Any code in which timeouts can affect the result would require this kind of logging, which includes networking code or code that handshakes between multiple threads/processors. Example: debugging something like a new x/y/zmodem implementation is nigh impossible within a debugger because your side must respond within 10 seconds or the other side will start acting differently.
Afraid you're describing a very natural behavior that's unlikely to disappear. Developers (not just software) tend to work until each constraint is just met and then stop to work on the next constraint. E.g., get the load time down to the maximum acceptable time, then stop working on it.
... you are of the opposite sex, have no significant communicable diseases, and pay your own way.
I can see the t-shirts on ThinkGeek (which shares a corporate overlord with Slashdot) now...
God is my debugger.
Of course I didn't RTFA... why would I do that? You really are new here aren't you? Don't let my UID fool you.
1. Distinguish between serious -operational- issues and other issues. The sysadmin doesn't need to know that you had a pointer problem; there's nothing he can do about it. He does, however, want to know that a message was received and the appropriate action taken. Or that a connection was attempted but failed.
2. Be grep freindly. The first log entry related to a particular activity should have an ID of some sort in the log message which is then included in every additional log entry associated with that activity.
Moderating "-1, Disagree" is simple censorship. Have the guts to post your opinion.
I'd be careful about using multi-core as a crutch: if the logging code isn't written properly, it can still be a bottleneck. Last year at my office we had to excise our old logging library because it turned out that each function call to the log acquired a global critical section even if the log level threshold wasn't met. Multi core wouldn't help because it was highly likely that any given call to the log would block the calling thread.
I'm going to the casino. Don't gamble.
It might come back to haunt you later.
The society for a thought-free internet welcomes you.
And let's hope it never does disappear or we can kiss new software goodbye.
I wonder why, given the huge increase in the performance of computers over the last ten years and more, why it sill takes some games one to five minutes to load
There are more textures, and they are stored at a higher resolution than they used to be; The 3D models have more triangles; there are more sound effects, and the quality is higher; there is more music, and the quality is higher...It takes time to load all of this into memory.
ZuluPad, the wiki notepad on crack
That being said, you can add what ever logging you want as long as you do it outside the application code, such as through AOP (if you don't know what that is then google is your new best friend).
Logging through external means has a number of benefits. First you application code is relieved from unnecessary clutter. Second the logging can be added or removed as fit for the environment with no need for any runtime checking, which is perfect for turning of all logging in production environments. And lastly it enforces good coding practices as it makes sure people break up code in a way that makes external logging possible, which is how code should be written anyway.
The majority of all logging, dare I say all useful logging, is easy to summarize.
This is perfect for function/method interception since it comes down to something more specific.
So simply add the first logging to an interceptor that operates before the functions you want to log, and the second after the function.
If you find yourself needing detail inside the function then you need to break the function up into sub routines, so you can use this generic logging on the sub routines instead, or as well as.
...nothing's as frustrating as trying to analyze a log that came in from the field where there's just no information about what went wrong.
[ 56.529336] WARNING: A-fib detected /dev/paddles
[ 56.568802] INFO: charging defib
[ 56.741096] INFO: charging ccomplete
[ 57.218803] ALERT: shocking!
[ 58.061815] Buffer I/O error on
[ 58.163210] zapper[22402]: segfault at 000000c4 eip b321bf5f esp b320a870 error 6
BUG: unable to handle kernel NULL pointer dereference at virtual adress 00000000
printing eip: c013186b *pde = 00000000
Oops: 0000 [#1] SMP
Modules linked in: battery ipv6 paddles ac button battery cardiac_monitor thermal processor zapper fan
Man, I'd feel bad after that output...
There's no place like
And let's hope it never does disappear or we can kiss new software goodbye.
Some of that behavior I've seen, we'd be better off if it disappeared. Sometimes, simply expanding till limits are met is like the old saying "some day, computers will be the size of buildings, and have millions of vacuum tubes!"
Perhaps I'm just pessimistic because where I work they're in the process of replacing the huge, unwieldy FileMaker monstrosity that handles payroll.... with an even bigger, more unwieldy FileMaker monstrosity that does the same thing, but requires us to feed it more information (more detailed job codes, time tracked in 6 minute increments, etc). All this extra data will be used to generate reports explaining why we're always releasing late. Never mind that we've been badgering them to hire more people for months. No, it's clearly a time management issue! As the PHB in Dilbert once said, "I want hourly reports on why we're behind schedule!"
If a job's not worth doing, it's not worth doing right.
"Turning on verbose logging doesn't help you after the process has gone tits up."
How can you demonstrate that you have fixed the reported bug if you can't recreate it in the first place?
And did you exchange a walk on part in the war for a lead role in a cage? - Pink Floyd.
I think you might be missing the main reason. If we don't reduce software logging, pretty soon there will be no old growth software left.
all the best,
drew
FreeMusicPush If you want to see more Free Music made, listen to Free
I wonder why, given the huge increase in the performance of computers over the last ten years and more, why it sill takes some games one to five minutes to load.
The goal of almost any commercial product isn't to be 100% awesome in every possible way. It's to be adequate on most measures and awesome in the few that buyers care most about.
Game buyers care about volume and quality of content a lot more than load time. So even if some engineer figured out a way to cut load time in half, somebody would just add more content and bump up bit rates and quality levels until it was back to a tolerable load time.
Consider, the attitude of "just throwing more processing power" at something is driving up electricity usage at data centers and office buildings across the country. A responsible programmer in this day and age should consider the energy footprint their code will have. Yes, I am completely serious.