In complex applications, one of the reasons for logging is to track bugs. However, as logs grow larger, the task of finding errors becomes increasingly difficult. You'll have a better chance of discovering the problem if your log isn't clogged with miscellaneous unrelated messages. However, sometimes an innocuous message contains a clue. This article resolves these seemingly contradictory insights by introducing the concept of paired messages.
In complex applications, you end up logging a lot of messages in pairs: "Start receiving data for client jt2001," "End receiving data for client jt2001," etc. But most likely, the pairs are far apart. Between the two messages in a pair, you will find other messages, stating what happened between the start of an action and the end of the same action. A paired message is composed of two messages: one that describes the start of an action, and one that describes the end of the same action. The first message (the one describing the start of the action) must occur first. The second message is written later when the action ends.
If the second message in the pair is written to the log, the action completes successfully. The strategy described in this article eliminates completed pairs from the log so that the log contains only:
This article describes how you can hunt for errors in your programs using a Isolated Messages Log. I have implemented the Isolated Messages Log in Windows, using Visual C++ v6. However, it should be easily ported to other platforms as well.
Figure 1 shows an example of Isolated Messages Log and Figure 2 shows a small part of an ALL Messages Log.
1. Write all messages to both the ALL Messages Log and the Isolated Messages Log.
2. Periodically refresh the Isolated Messages Log to remove completed pairs.
You can refresh the Isolated Messages Log either manually or automatically (see the later section titled "Refreshing").
The first step is to write messages to the logs. The CPairedMessagesLog class (available for download at <www.cuj.com/code>) writes each message to the Isolated Messages Log and the ALL Messages Log.
Say you have a reference to a CPairedMessagesLog object. How do you write to it?
In order to uniquely identify a paired message, you assign it a unique message ID. Non-paired messages don't need an ID.
When writing a paired message, you can do it in two ways:
1. Automatically -- a Message ID is automatically assigned:
CPairedMessagesLog<>::paired_log MessageLog = log.next_paired(); MessageLog << "Start receiving from [" << nSatteliteNo << "] satellite" << std::endl; // ... user code MessageLog << "End receiving from [" << nSatteliteNo << "] satellite" << std::endl;2. Manually -- you get a message ID or provide your own unique message ID:
// get a Message ID, OR provide your own CPairedMessagesLog<>::message_id_type MessageID = log.nextmessageid(); log.paired( MessageID) << "Start receiving from [" << nSatteliteNo << "] satellite" << std::endl; // ... user code log.paired( MessageID) << "End receiving data from [" << nSatteliteNo << "] satellite" << std::endl;Writing a non-paired message is done like this:
log.not_paired() << "Satellite [" << nSatelliteNo << "] has been checked: no malfunctions." << std::endl;As you can see, writing the message is done in an STL-stream manner. You use operator << to write any type of data. Terminating a message is done with std::endl. Actually, it must end with std::endl (see the sidebar, "std::endl Usage").
As a matter of fact, the functions paired, non_paired, and next_paired all return STL stream objects. That is, you can pass them to functions that accept std::basic_stream< char_type> arguments or even use manipulators to write to them.
You can also indent messages (see the sidebar, "Indenting Messages").
1) CPairedMessagesLog( strLogFileName, strAllMessagesLogFileName). This definition is almost self-explanatory, with one more detail: the refresh type is "Auto Refresh at 10 seconds" (see "Refreshing" below).
2) CPairedMessagesLog( CPairedMessagesLog::Settings settings). This further refines the settings of the CPairedMessagesLog. Listing 1 shows the definition of the Settings class (also, see "Refreshing" below).
Notes:
The following types of refreshing are allowed:
Disadvantage: this type of refreshing might be inefficient when large amounts of data get written to the log very fast.
Disadvantage: in case the application crashes, you might lose some data.
Also, you can manually refresh at any time by calling the Refresh function. You can even implement a mechanism to Refresh the Isolated Messages Log just before your application crashes.
The default refresh is auto refresh at 10 seconds.
As I said before, the paired, non_paired, and next_paired functions all return STL stream objects. As a matter of fact, paired and next_paired return a COnePairedMessageLog object, and non_paired returns a CNonPairedLog object.
So, when you write:
log.next_paired(); << "Start receiving from [" << nSatteliteNo << "] satellite" << std::endl;when std::endl is written, the COnePairedMessageLog stream is flushed, which in turn calls OnNewMessage, which calls WritePairedMessage for this message.
And when you write:
log.not_paired() << "Satellite [" << nSatelliteNo << "] has been checked: no malfunctions." << std::endl;when std::endl is written, the CNonPairedLog stream is flushed, which in turn calls OnNewMessage, which calls WriteNonPairedMessage for this message.
Internally, when the Isolated Messages Log is rewritten (refreshed), you must make sure you preserve the order of messages (un-paired and non-paired). For the un-paired messages, this is a simple task since each message has an ID. However, it's not so easy with the non-paired messages. Somehow, you must know where each non-paired message is to be written, related to the other un-paired messages. In order to accomplish this, I have made each non-paired message belong to a paired message. For example, the "satellite [5] has been checked" non-paired message will always be written after the paired message with the ID of 6. When refreshing, it will write all un-paired messages with IDs less or equal than 6 and then write the "satellite [5] has been checked" non-paired message, and so on. Having each non-paired message be written after a certain paired message is enough to preserve the order of messages while refreshing.
Note that I'm not saying anything about the full paired messages. This is because once a full paired message has been written to the log (i.e., the start and end of an action), the action will have completed successfully. So, it will be removed from the Isolated Messages Log. Therefore, you don't need to worry about full paired messages.
I have a class, do_for_each_file_t, which does a certain action for all files in a given folder plus its subfolders. In order to improve its performance, I have allowed executing actions for different files in parallel (assuming that each action operates only on the file to which it is assigned).
On the main thread, I have created two threads. On the first thread, I examine all files in a given folder, checking if a word is found. After a while (five seconds), the expiry thread is started, which starts deleting files. Soon after, the application might crash. This is because it will most likely try to examine an already deleted file.
This simulates a very simple proxy with a cache mechanism. It allows a search function (search through cached files) and expires unaccessed files once in a while. Of course, it has a bug. Since searching is done with multithreading, it should check whether a file exists before trying to read from it!
By examining Figure 2 (which contains the last lines of an ALL Messages Log), you can see the context of the crash, which shows that most of the files have been processed correctly. The last line shows that the file that most likely caused the crash is 31[1].gif. This should give you an indication that the bug appeared while expiration and searching were executed in parallel. This will lead you, when searching, to first check if the file exists before reading from it.
Notes:
Implementing an expiring mechanism is not an easy task. You can do it by having a maximum number of un-paired messages kept internally (say, 1,000 un-paired messages). If you reach this limit, you should remove half of the un-paired messages and log this information somewhere. You can choose to remove the oldest messages, but you have to keep an extra property for each paired message: the time when the start of the action has been written. You also should do the same for non-paired messages.
Another improvement would be to have an additional template parameter for the internal log classes. Instead of using std::basic_ofstream logs, you could use another log class. For instance, instead of writing to a file, you might want to write to a window.
And last but not least, you might want each message to be preceded by the time it's been written. This is useful only for the ALL Messages Log file. To do this, you should modify the WritePairedMessage/WriteNonPairedMessage functions.
I recommend you implement these improvements only if necessary.