| Visible Workings > Ruby-Trace User's Guide |
The Ruby-Trace
User's Guide |
Server Programs |
This section describes using Ruby-trace with larger programs. Larger programs probably are not started from the command line, so they probably need to log to disk. They are probably composed of semi-independent subsystems, each of which may need to be traced differently.
At this point, we need to talk a bit more about what kind of thing $trace is. It is a Connector object, so called because it connects topics with particular themes to certain destinations. (The definitions of these terms will be introduced in due course.) Simple programs could avoid knowing about Connectors by requiring the appropriate file. Server programs need to do a bit of specific initialization.
The simplest way to log to disk is to execute a statement like this early in your program:
$trace = Trace::Connector.debugging_buffer_and_file
This class method causes trace messages to flow to two destinations. A destination is an object that accepts trace messages and does something useful with them. The first destination is the buffer already described in Tracing simple programs. It records trace messages at or above the event threshold. The second is a logfile whose default name is "Tracelog.txt". (To change the default name, give your preferred name as an argument to the call.) The logfile records trace messages at or above the announce threshold.
The effect is that the logfile holds low-frequency, high-importance messages, while the buffer holds more frequent messages that are probably only important if a problem happens. In that case, you can "drain" the buffer into the logfile with this command:
$trace.drain('buffer', 'file')
See "drain-example.rb" in the doc/examples subdirectory.
Messages in logfiles look a bit different than messages printed to standard output. They have timestamps:
usage-example-2.rb:11:in `initialize' at 2001/07/20 00:05:31
= announce: User interface starts.
The timestamps appear both on messages printed directly to the logfile and also on those drained from the buffer. The format can be changed. See LogfileDestination#format= in the API.
The thresholds of the two destinations can be controlled independently. At runtime, a destination is controlled using this method:
set_threshold(aDestinationName, aLevelName)
The following calls set the logfile threshold to warning and the buffer threshold to debug:
$trace.set_threshold('file', 'warning')
$trace.set_threshold('buffer', 'debug')
At launch time, the two destinations obey the environment variable TRACEENV. It consists of a series of trace environment commands separated by spaces, semicolons, or colons. Each trace environment command has this format:
-aDestinationName-threshold=aLevelName
(There's more to the format than this, but this is enough for now.)
So the same effect as the above two calls can be had with this environment:
TRACEENV="-file-threshold=warning -buffer-threshold=debug"
You may want each new invocation of the server to use a new log file. It's convenient to identify each with a timestamp. This can be done by putting the tag %t in the logfile's name.
$trace = Trace::Connector.debugging_buffer_and_file 'Tracelog.%t.txt'
results in a logfile like this:
Tracelog.20010719125656.txt
That logfile was created at 12:56:56 on July 19, 2001. Each time the server starts, it will create a new logfile. The timestamp format is such that an alphabetical file listing of the logfiles is in the order in which they were created.
Note: this is a way of handling backup files that I've used in the past. It works OK, but I'm considering replacing it (or adding to it) with one or two other alternatives. The first alternative would always retain the first backup file (since it contains startup logging likely to be useful in the future). It would also always cycle through backup files starting with '000', instead of adding to the most recent backup file. (This makes more sense if we don't care about preserving the logs from previous runs.) The second alternative would reopen the backup file at periodic intervals (like once a day) instead of based on file size. There'll be discussion on the mailing list.
If the logfile name contains the tag %b, an existing file will be renamed instead of overwritten. As an example, suppose no logfile exists and your program initializes tracing this way:
$trace = Trace::Connector.debugging_buffer_and_file 'Tracelog%b.txt'
The first time you run the server, there will be a single logfile:
Tracelog.txt
If you shutdown and restart, you'll then have two files:
Tracelog.000.txt # contains the log for run 1 Tracelog.txt # contains the log for run 2
If you shutdown and restart again, you'll still have two files:
Tracelog.000.txt # contains the log for run 2 (the log for run 1 is gone) Tracelog.txt # contains the log for run 3
(Notice that the backup file has had "%b" replaced by ".000" - you needn't add a period.)
A more typical use of backup files would be this:
$trace = Trace::Connector.debugging_buffer_and_file('Tracelog%b.txt',
"a",
10000000,
"010")
When tracing is initialized, the logfile is appended to. (The default choice is "w", which means to create a new logfile after renaming the old to a backup file.) The logfile will be closed, renamed, and reopened when it exceeds 10 megabytes in size. (The limit isn't guaranteed to be exact, but it should usually be within a few percent of the actual size.) Finally, up to eleven backup files are used. The first is has '.000'; the last has '.010'. If all the backup files exist, the oldest is overwritten.
There's no difference between making a backup file because the file fills up and because tracing is initialized. Suppose the tracing system is initialized as above, except that the file is opened with mode "w" (which forces overwriting instead of appending). At first, there are no logfiles in the file system. Then 25 megabytes of log are written. At that point, there are three logfiles:
Tracelog.000.txt # contains the first 10 megabytes Tracelog.001.txt # contains the second 10 megabytes Tracelog.txt # the current logfile
If the server is halted and restarted, there will be four log files:
Tracelog.000.txt # contains the first 10 megabytes Tracelog.001.txt # contains the second 10 megabytes Tracelog.002.txt # the final part of the first run Tracelog.txt # the logfile from the second run
Suppose that you've discovered a bug in the accounting subsystem of your server. You'd like verbose level messages from that subsystem. From the rest of the system, you want warning or higher level messages to give your debugging some context, but nothing more detailed. To be able to control a subsystem's threshold independently, you must associate it with a particular data structure, called a topic. Here's how. (See "topic-example.rb" in the doc/examples subdirectory. )
$trace = Trace::Connector.debugging_buffer_and_file
accounting_trace = $trace.topic('accounting')
Topics accept the same level messages you've already seen:
accounting_trace.error "Impossible event #{event} in state #{state}."
accounting_trace.verbose_value { "state" }
The output looks a bit different than what you've seen before, because the topic name is included:
topic-example.rb:10 at 2001/07/20 00:27:27
= accounting error: Impossible event explode in state crashed.
To set the accounting subsystem's logfile threshold to verbose, you could use either this method at runtime:
accounting_trace.set_threshold('file', 'verbose')
or set the environment thusly:
TRACEENV="accounting-file-threshold=verbose"
How, though, is the rest of the system instructed to set the threshold to announce? In one of two ways. The first way uses a Connector method:
$trace.theme_and_destination_use_default('debugging', 'file', 'warning')
(The meaning of "theme" is defined later.) The second way uses TRACEENV again:
TRACEENV="global-debugging-file-default=warning"
It's awkward to pass topics around. Here are some ways to make them widely accessible. (See "topic-access-example.rb" in the doc/examples subdirectory. )
If the subsystem has a method to itself, it's convenient to make the trace topic a method constant:
module Accounting
Trace = $trace.topic('accounting')
...
Trace.announce 'Accounting subsystem starts; OZ domain.'
...
end
Connector#topic can be called multiple times with the same string. It always returns the same topic. So each class that makes up a subsystem can have a class variable that shares a topic object with all the others:
class Payroll
@@trace = $trace.topic('accounting')
...
@@trace.announce 'Payroll shaving pension fund #{shave} fractional percent.'
...
end
class Receivables
@@trace = $trace.topic('accounting')
...
end
Finally, you can install a method on the global $trace object that returns a specific method:
$trace.topic('accounting')
$trace.add_method_for_topic('accounting')
...
$trace.accounting.event 'Starting reconciliation'
This will fail (with a Trace::Exception) if the topic name is invalid or already used for some other purpose. So, while you can create a topic named "hi, mom!" or "clone", you can't create methods for them. You can still retrieve those topics from the Connector indirectly:
$trace.topic_with_name('hi, mom!').error "It's not true that I never think of you, mom."
A Connector object accepts level messages because it's a subclass of Topic. It is, specifically, the topic named the empty string.
$trace == $trace.topic_with_name('') -> true
Suppose you'd like to use Ruby-trace to record usage data. You might desire three levels of detail.
To allow users to perform the most common tasks without a single wasted motion, you might want to record each gesture they make.
To know where streamlining is most useful, you might record each feature a user uses. Use of a feature might entail many gestures, culminating in the press of an OK or APPLY button in a dialog.
Finally, to increase the chance that your product's features are what users want, you might try to record the tasks they're trying to perform. A particular task (a use case) would be deduced from sequences of dialogs.
You could use Ruby-trace's predefined levels (error, warning, and the like) to record this data, but it would be confusing and awkward. It would be better to make a clear distinction between usage data and debugging data. Ruby-trace's themes do that. A theme is essentially a list of levels, from most general to most detailed. A Topic can be defined to use a particular theme's levels, and a Connector can be instructed to control routing of messages with that theme. Here's how. (See "usage-example-1.rb" in the doc/examples subdirectory.)
Let's suppose that we're adding usage tracing to a program that already uses a buffer and logfile for debugging. We'll reuse those destinations for this new purpose. This is done in three steps. First, a new theme is added to the Connector:
$trace = Trace::Connector.debugging_buffer_and_file {
add_theme('usage', %w{task feature gesture})
theme_and_destination_use_default('usage', 'buffer', 'gesture')
theme_and_destination_use_default('usage', 'file', 'task')
}
The first line within the block creates the theme. The next two lines tell the Connector how to handle messages for topics that have the 'usage' theme. The buffer should receive gesture messages and higher. The log file should receive only task messages; lower level messages will be discarded by default.
The next step is to create a topic:
topic = $trace.topic('usage', 'theme'=>'usage')
$trace.add_method_for_topic(topic.name)
The last step is to scatter appropriate trace calls throughout the code:
$trace.usage.feature 'word count'
That will result in a log file with debugging and usage messages intermixed:
usage-example-1.rb:11:in `initialize' at 2001/07/20 00:02:03
= announce: User interface starts.
usage-example-1.rb:15:in `task_completes' at 2001/07/20 00:02:03
= usage task: User has turned off all helpful suggestions.
That mixing may be unsatisfactory. If so, usage tracing can be sent to a different destination. (See "usage-example-2.rb" in the doc/examples subdirectory.) That requires editing the code that creates $trace:
$trace = Trace::Connector.debugging_buffer_and_file {
add_theme('usage', %w{task feature gesture})
add_destination(LogfileDestination.new('usage_file', 'Usagelog.txt'))
theme_and_destination_use_default('usage', 'usage_file', 'task')
}
Notice that a default threshold is set only for messages from topics with theme usage destined for the usage log file. That's because we never plan to send messages from a usage topic to the debugging buffer or logfile.
Next, the code that creates the usage topic needs to be changed:
topic = $trace.topic('usage', 'theme'=>'usage', 'destination'=>'usage_file')
$trace.add_method_for_topic(topic.name)
None of the calls to trace methods need be changed.
There is a threshold associated with every destination a topic can send to. This threshold is calculated as follows:
If the topic has had the threshold explicitly set, that's it.
Otherwise, if the topic has a default threshold, that's used.
Otherwise, the "global" threshold that applies to all topics is used.
This baroque arrangement allows flexible control.
If you want more detail across the board, you change the global threshold.
But if you want even more detail about a particular topic, you set its default.
Having done that, you may continue debugging or running the program until you get to a point where you want the ultimate detail. So you set the topic's threshold explicitly.
Once you're past that point, you can tell the topic to forget the explicit threshold and revert to the topic default threshold.
And you may later tell the topic to forget its default threshold and just obey the global threshold.
These three methods control thresholds at runtime:
- Topic#set_threshold(destination_name, level_name)
- If level_name is "none", no messages flow. If it's "default", any explicit setting of the threshold is forgotten.
- Topic#set_default_threshold(destination_name, level_name)
- Sets the default threshold. Topic#set_threshold takes precedence. level_name can be "none". If it's "default", the topic's default threshold is forgotten, and the global default threshold is used instead.
- Connector#set_theme_and_destination_use_default(theme_name, destination_name, level_name)
- All topics with the given theme have the given destination's default threshold set to the given level. This has effect only if the topic has no explicit nor default threshold. level_name can be "none".
Trace environment commands control thresholds at program launch time. The commands are contained in the value of the environment variable TRACEENV. They are separated by spaces, commas, or colons. There are three commands:
- topic-destination-threshold=level
- Calls Topic#set_threshold on the topic named topic.
- topic-destination-default=level
- Calls Topic#set_default_threshold on the topic named topic.
- global-theme-destination-default=level
- Calls Connector#set_theme_and_destination_use_default
Server Programs |
Please send comments on this document to marick@visibleworkings.com. The ruby-trace mailing list is at at http://groups.yahoo.com/group/ruby-trace.
Copyright © 2001 by Brian Marick. This material may be distributed only subject to the terms and conditions set forth in the Open Publication License, draft v1.0 or later (the latest version is presently available at http://www.opencontent.org/openpub).