bio-logger is listed at biogems.info

bio-logger

This is a plugin for nailing down problems with big data parsers, so common in bioinformatics, and sane handling of errors and exceptions in different situations (log-act).

For example, using bio-logger, messages can be filtered from the program

log.filter { | level, sub_level, msg | sub_level == 3 or level <= ERROR }

or can be made to behave differently based on roles of the caller as

NormalUser
Developer (or FailOnError)
WebServer
FaultTolerant systems

One example of the use of having different behaviours, is when a program logs a warning to stdout when called as a user, but raises an exception when called as a developer. In Bioinformatics this is a common scenario when dealing with parsers. Large data files sometimes contain errors. As a user you want to continue and hope for the best (logging the error). As a developer you want to see how you can fix the problem. Waiting for a full run and checking the logs is tedious. The logger can be helpful here, and avoids sticking ‘temporary’ solutions in code.

bio-logger builds up on log4r functionality, which comes with multiple handlers, such as a rotating and remote logging, and is thread-safe. Next to adding filtering and behaviours, bio-logger introduces a more fine-grained approach for logging errors. I.e. within ‘debug’, ‘info’, ‘warn’, ‘error’ and ‘fatal’, an additional value (the sub_level) can be set to limit output and logging. This, again, can be helpful when dealing with huge log files. One way is to switch a not so important and validated DEBUG, INFO or WARN, to a higher sub level will take it out of the logs. Another option is to log only the messages of a certain value, or to regex on the message - i.e. you get othogonal differentiation of values and types (see the filter example below). This can also make sense when deploying applications under different scenarios.

Log4r is useful, compared to the standard Ruby logger, because it allows you to set reporting leaves by log type. I.e. if everything in BioRuby works, except for the BLAST parser, or some plugin, the logger can be tuned only to log BLAST debug level, and everything else at normal level.

In other words, bio-logger helps in tracking down problems and provide a way of avoiding sprinkling $stderr.print statements through the code base.

To support applications, bio-logger can also help parse command line switches:

add (multiple) loggers:

--logger stderr              Add stderr logger
--logger filen               Add filename logger

specify global log level:

--trace  debug               Show all messages 
--trace  warn                Show messages more serious than 'warn'
--trace  warn:3              Show messaged more serious that 'warn' level 3
--trace  "=3"                Show all messages with sub-level==3
--trace  "=sub_level == 3 or level <= ERROR" Set filter

overrides:

--trace  gff3:info:5         Override level for 'gff3' to info level 5
--trace  blast:debug         Override level for 'blast'
--trace  blast,gff3:debug    Override level for 'blast' and 'gff3' 
--trace  stderr:blast:debug  Override level for 'blast' on stderr

Earlier described behaviour, or ‘acting’, can be changed. This normally happens through library calls. There is one command line switch, which changes log-act:

--log-act FailOnError          Modify the logger for development

which will cause, for example, ‘error’ and ‘fatal’ to fail during development, for special calls to the logger (described below). New behaviour can be implemented by deriving from an existing class.

Install bio-logger

gem install bio-logger

Bio::Log API

In code there are more options. For example, it is possible to define multiple output streams, or split out different loggers to different streams. It is also possible to change behaviours by module.

require 'bio-logger'
include Bio::Log

# ==== Create loggers
log = LoggerPlus.new 'mylog'
log.outputters = Outputter.stderr

# create a second rotating log for BLAST
config = {
  "filename" => "log/blast.log",  # make sure the dir exists!
  "maxsize" => 16000,             # max file size
  "trunc" => false                # don't delete log
}
log2 = LoggerPlus.new 'blast'
log2.outputters = RollingFileOutputter.new("blast", config)

# ==== Output messages on 'mylog'
log.debug "This is a message with level DEBUG"
log.info "This is a message with level INFO"
log.warn "This is a message with level WARN"
log.error "This is a message with level ERROR"
log.fatal "This is a message with level FATAL"
log.warn3 "This is a message with level WARN:3"

# Restrict output to messages <=WARN:3
log.level = WARN
log.sub_level = 3
log.info("This is a message with level INFO")      # not logged
log.warn8("This is a message with level WARN:8")   # not logged
log.warn1("This is a message with level WARN:1")   # logged
log.warn("This is a message with level WARN")      # logged

# Restrict output for DEBUG, INFO, WARN to sub_level 3
log.filter { | level, sub_level, msg | sub_level == 3 or level <= ERROR }
log.warn8("This is a message with level WARN:8")   # not logged
log.warn3("This is a message with level WARN:3")   # logged
log.warn1("This is a message with level WARN:1")   # not logged
log.info3("This is a message with level INFO:3")   # logged
log.error("This is a message with level ERROR")    # logged
log.reset_filter

# Fetch the BLAST logger (assuming it exists)
blastlog = LoggerPlus['blast']
blastlog.warn("This is a message with level WARN") # logged

# Special logging behaviour
blastlog.error_("ERROR should not fail",:act => NormalUser.new)
dev = FailOnError.new
blastlog.info_("INFO should not fail",:act => dev)
blastlog.error_("As Developer ERROR should fail",:act => dev)

For parsing command line options with the OptionParser:

opts.on("--logger filename",String,"Log to file (default STDOUT)") do | name |
  Bio::Log::CLI.logger(name)
end

opts.on("--trace options",String,"Set log level (default INFO, see bio-logger)") do | s |
  Bio::Log::CLI.trace(s)
end

opts.on("-q", "--quiet", "Run quietly") do |q|
  Bio::Log::CLI.trace('error')
end

opts.on("-v", "--verbose", "Run verbosely") do |v|
  Bio::Log::CLI.trace('info')
end

# Realize settings
Bio::Log::CLI.configure('mylog')

Biogems

The recommended way to use bio-logger from within a biogem is to setup a logger in lib/bio-gemname.rb (where you replace gemname with the name of your gem, of course) like so:

# bioruby-gemname/lib/bio-gemname.rb
require 'bio-logger'
Bio::Log::LoggerPlus.new('bio-gemname')

Then the log can be written to anywhere within the biogem’s code e.g.

log = Bio::Log::LoggerPlus['bio-gemname']
log.debug "a debug message"

Documentation

The log4r documentation and source code can be used, as this Logger implementation passes everything down, except for the added methods.

See log4r.rubyforge.org/

See also the Specs in ./spec for more examples. Run the Specs with

rspec spec/*.rb

TODO

The current version is used in BioRuby parser plugins (e.g. github.com/pjotrp/bioruby-gff3-plugin/).

It may be interesting to run loggers as actors, so the are fully parallelized with the main application.

Cite

If you use this software, please cite dx.doi.org/10.1093/bioinformatics/btq475

Copyright

See LICENSE.txt for further details.