log

tcllib log package

This page is about the Tcllib package log which is about message logging. Documentation can be found at http://tcllib.sourceforge.net/doc/log.html .

log mathematical operation

log is also an expr built-in function, "natural" logarithm to base e:

% expr log(2.71828182846)
1.0

log is also one of the TclX Commands that mirror the built-in functions. As of Tcl 8.5, the same functionality is available in the core as the ::tcl::mathfunc::log command.

Alternate logging packages

A side-by-side comparision to the second message logging package logger from tcllib can be found here [1 ].

Also take a look at the audit package at: [2 ]

ns_log[3 ] is a NaviServer command, useful for multi-threaded programs.

Discussion

LV writes: What are some tips for using this package? For instance, can someone provide a skeleton for using logs to a program. One using has several types of msgs in a program:

  • introductory (Hi, this is program ABC, and I am here to help you learn to tie your shoes)
  • progress (program ABC is now loading a 256 terabyte database about types of shoes ... loading ... loading ...)
  • success/results (program ABC has located your language environment)
  • failure (program ABC is unable to identify shoes called 'sandels')
  • completion (Well, thanks for stopping by to talk to me - y'all come back now, ya' hear?)

How would one code a skeleton for such an application (don't worry about the tcl to do the above actual coding - just the logs)?

[Good question(s), Larry.]

(2014-02-22): when I use this utility, I tend to make use of the five lower levels (error -- debug). My usage is roughly error for error handling, warning or notice for interesting events, and info or debug mostly for boring events. Even though the package doesn't force me to, I usually arrange suppression so that priority levels 1 -- x are enabled and x+1 -- 8 are suppressed, i.e. I don't have, say, emergency through warning enabled, notice suppressed, and info and debug enabled.

I set the reporting levels like this:

"in-detail"
every level is enabled. I use this when pursuing a specific bug (and yes, it usually means wading through lots of irrelevant stuff).
verbose
every level except debug is enabled. I switch it on to get an overview of what happens during execution.
normal
every level except info and debug are enabled. This is what I usually have on during development, often switching to verbose, seldom to "in-detail" or exceptional.
exceptional
every level except notice, info, and debug are enabled. I may use this when concentrating on warnings and errors.

I insert logging commands along these lines:

  • when something at least marginally noteworthy happens, I add a debug. This is typically on the first line of any proc or Snit method, or when setting an important variable, as a "passive assert", etc.
  • when something even more noteworthy happens, I add an info. This could be the first line of a significant proc or method, one of the steps during a program event, etc.
  • when a program event occurs, I add a notice. This is something like "have selected algorithm X".
  • when an "unusual" event occurs, I add a warning. This is for borderline events that are almost, but not quite, errors.
  • when an error is handled by a try or catch command, I add an error (I do not log at the point where the error occurs).

So, my methods don't really fit the skeleton referred to above. Messages of introduction, progress, success/results, and completion would probably be logged as notices in my programs, while messages of failure would be errors (or possibly warnings for lesser kinds of failures). In between those there would be lots of infos and debugs.


LV 2007 June 27 I'd still love the above questions answered, but here's something I've learned.

 $ tclsh
 % package require log
 1.2
 % ::log::lvSuppress debug         
 % ::log::lvIsSuppressed debug
 1
 % ::log::Puts debug "test"
 debug     test
 % ::log::log debug "test"
 % 

Note the following - it appears that log::Puts is going to output something regardless of whether the output is suppressed or not. Use log::log which then observes the supression mechanism.

The idea is this - log::log takes two arguments - an output level and the string to output. There are various levels available. The developer determines what kinds of output is desired for what types of things. The levels available include:

Error level:

  • emergency
  • alert
  • critical
  • error

Other level:

  • warning
  • notice
  • info
  • debug

These levels are nearly "policy free" - that is, there isn't a requirement to use them in any particular way. Instead, the developer decides when a particular level should be observed. Thus, one might use the debug level to output text that the user won't see when normally using the application. The developer can decide when the each level might be appropriate, allowing three levels of "end of the world" type situations.

I say "nearly policy free" because there is two policies relating to the relative ranking between levels. That is, debug has the lowest level of priority, emergency has the highest level, and the whole list is priority ranked in the order I list above .

By default, anything in the "error level" group of log messages results in output to stderr. Messages of the other levels are written to stdout. However, there are log commands to reconfigure other levels to go to stderr as well. There are also commands for coloring text, for invoking commands to produce the output in a GUI widget or whatever else you desire (sending info to a pager, etc.) There are also commands for suppressing/unsupressing output of a particular level, or all levels less than or equal a given level, testing whether a level is suppressed, etc.

Here's some info from AK about log:

The log package supresses four number of its eight levels by default. The suppressed levels are debug, info, notice, and warning. You have to unsuppress these levels to see messages for them.

The procedure log::Puts is an internal procedure which should not be called directly. It is the default output command and as such not responsible for the suppression of messages. That is done in higher layers, i.e. its callers. This means that log::Puts cannot be suppressed.

As for routing messages to stdout: By default everything from error on up is written by log::Puts to stderr. Everything else, including 'debug' is written to stdout.

Relevant commands to change things are:

  • lvSuppress - Change supression of one level, default: suppress.
  • lvSuppressLE - change suppression of everything below a specific level.
  • lvCmd, lvCmdForall - Change the output command for one or all levels (Default is log::Puts)
  • lvChannel, lvChannelForall - Change channel to write to for one or all levels (Relevant only for levels which use log::Puts as output command)
  • lvIsSuppressed, lv2cmd, lv2channel - Query levels for current suppression, output command, channel

PT writes: OK Seeing as I used this in TclSOAP and tkchat...:

 package require log;  # tcllib 1.0

 namespace eval mine {
    variable logLevel warning;  # set up the default level
 }

 # -------------------------------------------------------------------------
 # Description:
 #  Set the amount of logging you would like to see.  We use the tcllib log package for this so the level
 #  must be one of log::levels. The default is 'warning'.
 # Parameters:
 #  level - one of log::levels. See the tcllib log package documentation.
 #
 proc mine::setLogLevel {level} {
     variable logLevel
     set logLevel $level
     log::lvSuppressLE emergency 0; # unsuppress all
     log::lvSuppressLE $logLevel 1; # suppress all below selected
     log::lvSuppress $logLevel 0;   # unsupress selected.
     return $logLevel
 }
 # initialize the default package logging level
 if {[info exists mine::logLevel]} {
     mine::setLogLevel $mine::logLevel
 }

Add a -loglevel configuration option that calls to setLogLevel and then liberally splinkle your code with log::log debug "message" and so forth. So:

 proc mine::DoStuff {args} {
    log::log debug "starting to do stuff"
    if {! [doing stuff]} {
        log::log notice "we are not doing anything!"
    }
    set r [do more stuff]
    if {$r < 1} {
        log::log emergency "argh!"
    }
    log::log debug "stopping doing stuff"
  }

With this pseudo-procedure if the user has set their log level to debug then they will see all these messages printed out.

Raising the log level to notice will reduce the noise but keep the more significant messages. emergency is (IIRC) the higest level.

  • emergency
  • alert
  • critical
  • error
  • warning
  • notice <--- logLevel variable
  • info........x
  • debug.......x

The tkchat program uses log levels to provide debugging information for people having trouble and less information for those for whom it works. This program is probably a reasonable example of the use of this package. In this program we use debug and info for http status messages. The output appears at debug level and just the status at info level. Level error is used for reporting failures like timeouts and http protocol errors.

Efficiency when logging is turned off

HaO 2017-11-16: After a Discussion with Gerald Lester on TCLWS Logging performence , the following was pointed out:

If huge data structures are logged (like 8kB WSDL files in the upper example), one may avoid the string creation in the non logging case by the command list as follows:

So this creates the string and throws it away if not logged:

::log::log debug "Parsing WSDL $wsdlXML"

while this would just set up a list of pointers:

::log::log debut [list "Parsing WSDL" $wsdlXML]