weblogs : azul : Alejandro Forero Cuervo - Activity Log

env

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(RegexpGroupsColors('^(\S+)(=.*)$', Bold, ''))

date

Not a very useful script, it should probably be improved.

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(CharsDict({':': Blue, '/': Blue}))

diff

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(Rules(RegexpGroupsColors('^((?:> |\\+).*)$', Green),
          RegexpGroupsColors('^(<(?: .*|)|-.*)$', Red)),
    Rules(RegexpGroupsColors('^(diff: Try `)(.*)(\' for more information.)$', Red, Red + Bold, Red),
          ConstantColor(Red)))

df

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(Header(
    ConstantColor(Cyan),
    Table([RowConstant(c) for c in [Bold, '', '', '', Bold]])))

file

For the file command, we group the types of files into a few different categories and colorize them separatelly. We have more categories than we have colors, which means that we have to map some different categories to the same color. This is not as bad as it sounds, as they tend to be related.

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

TEXT = (
    '(?:Non-ISO extended|ISO-8859|ASCII|UTF-8 Unicode) (?:English |mail )?text(?:, with very long lines)?',
    'troff or preprocessor input text',
    'magic text file for file\(1\) cmd',
    '(?:XML 1.0|HTML) document text',
    )

IMAGE = (
    '(?:JPEG|PNG) image data(?:.*)',
    )

VIDEO = (
    'Microsoft ASF',
    )

AUDIO = (
    'MPEG ADTS.*',
    'MP3 file.*',
    )

CODE = (
    '(?:ASCII |ISO-8859 |UTF-8 Unicode )?(?:Lisp/Scheme|C\+\+|C|Java) program text',
    )

EXECUTABLE = (
    'ELF 32-bit LSB (?:shared object|executable(?:.*))',
    '(?:a )?(?:perl|python|Bourne(?:-Again)? shell) script text executable',
    )

DOCUMENT = (
    'PDF document, version [0-9.]+',
    'Microsoft Office Document',
    )

SPREADSHEET = (
    'OpenDocument Spreadsheet',
    )

BINARY_OTHER = (
    'Berkeley DB \(Hash, version 8, native byte-order\)',
    'data',
    'timezone data',
    )

CONTAINER = (
    '(?:bzip2|gzip) compressed data',
    'POSIX tar archive',
    'Zip archive data.*',
    )

SPECIAL = (
    'symbolic link to `.*\'',
    '(?:writable, )?regular file, no read permission',
    'directory',
    )

colors = {
    TEXT: Blue,
    IMAGE: Yellow,
    VIDEO: Yellow,
    AUDIO: Yellow,
    CODE: Green,
    EXECUTABLE: Green,
    DOCUMENT: Cyan,
    SPREADSHEET: Cyan,
    BINARY_OTHER: Magenta,
    CONTAINER: Magenta,
    SPECIAL: Red,
    }

rules = []
for entries, color in colors.items():
  for e in entries:
    rules.append(RegexpGroupsColors('^(%s)$' % e, color))

Run(RegexpGroups('^(.*: *)(.*)$', [ConstantColor(''), Rules(*rules)]))

groups

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(Table([RowDict(dict((i, Bold) for i in ['root', 'wheel']))]))

host

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(Rules(
    RegexpGroupsColors('^(.* has address )([0-9.]*)$', '', Bold),
    RegexpGroupsColors('^(.* mail is handled by )(.*)$', '', Bold)))

ifconfig

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(Rules(
    RegexpGroupsColors('^([^ ]+)( .*)$', Bold, ''),
    RegexpGroupsColors('^( *inet addr:)([0-9.]+) (.*)$', '', Bold, '')))

ls

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(None,
    Rules(RegexpGroupsColors('^(ls: (?:cannot (?:access|open) )?)(.*)(: (?:Permission denied|No such file or directory))$',
                             Red, Red + Bold, Red),
          ConstantColor(Red)))

md5sum

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(Table([RowHash(), RowConstant('')]), ConstantColor(Red))

mount

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(RegexpGroupsColors('^(\S+)( on )(\S+)( type )(\S+)( \\()(.*)(\\))$', Bold, '', Bold, '', Bold, '', Bold, ''),
    Rules(RegexpGroupsColors(
              '^(mount: can\'t find )(.*)( in /etc/fstab or /etc/mtab)$',
              Red, Red + Bold, Red),
          RegexpGroupsColors(
              '^(mount: according to )(.*)(, )(.*)( is already mounted on )(.*)$',
              Red, Red + Bold, Red, Red + Bold, Red, Red + Bold),
          ConstantColor(Red)))

ping

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(Header(
    RegexpGroupsColors('^(PING )([^ ]*)( \\()([0-9.]+)(\\) .*)$', Underline, Bold + Underline, Underline, Bold + Underline, Underline),
    Rules(RegexpGroupsColors('^([0-9]+ bytes from .+(?: ?\\([0-9.]+\\))?: icmp_seq=)([0-9]+)( ttl=)([0-9]+)( time=)([0-9.]+ [a-z]+)$',
                             '', Bold, '', Bold, '', Bold),
          RegexpGroupsColors('^(From )(.*)( icmp_seq=)([0-9]+)( )(Destination Host Unreachable|Time to live exceeded)$',
                             '', Bold, '', Bold, '', Red + Bold))))

rm

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *

Run(None,
    Rules(RegexpGroupsColors(
              '^(rm: cannot remove (?:directory )?`)(.*)(\': .*)$',
              Red, Red + Bold, Red),
          ConstantColor(Red)))

route

#!/usr/bin/python
from colorize import *

Run(Header(ConstantColor(Cyan + Underline),
           Header(ConstantColor(Cyan + Underline),
                  Table([RowConstant(c) for c in [Bold, Bold, '', '', '', '', '', Bold]]))))

svn

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize

from colorize import *
import sys

def Stdout(args):
  if len(args) == 1:
    return None
  op = args[1]
  if op == 'diff':
    return Rules(
        RegexpGroupsColors('^((?:> |\\+).*)$', Green),
        RegexpGroupsColors('^(<(?: .*|)|-.*)$', Red))
  if op in ['commit', 'ci']:
    return Rules(
        RegexpGroupsColors('^(Committed revision )([0-9]+)(\\.)$', '', Bold, ''),
        RegexpGroupsColors('^(Sending\s*)(.*)$', '', Bold))
  if op in ['up', 'update']:
    return Rules(
        RegexpGroupsColors('^(At revision |Updated to revision )([0-9]+)(\\.)$', '', Bold, ''),
        RegexpGroupsColors('^(A\s+.*)$', Green),
        RegexpGroupsColors('^(D\s+.*)$', Red))
  if op in ['stat']:
    return Rules(
        RegexpGroupsColors('^(A\s+.*)$', Green),
        RegexpGroupsColors('^(D\s+.*)$', Red))
  if op in ['add']:
    return RegexpGroupsColors('^(A\s+.*)$', Green)
  if op in ['ps', 'propset']:
    return RegexpGroupsColors('^(Property \')(.*)(\' set on \')(.*)(\')$', '', Bold, '', Bold, '')
  if op in ['pd', 'propdel']:
    return RegexpGroupsColors('^(Property \')(.*)(\' )(deleted)( on \')(.*)(\')$', '', Bold, '', Green, '', Bold, '')
  return None

def Stderr(args):
  if len(args) == 1:
    return RegexpGroupsColors('^(Type \')(.*)(\' for usage.)$', '', Bold, '')
  return None
 
Run(Stdout(sys.argv), Stderr(sys.argv))

Header

#!/usr/bin/python
# Copyright 2010, Alejandro Forero Cuervo
# http://azul.freaks-unidos.net/colorize
#
# This program is free software: you can redistribute it and/or modify it under
# the terms of the GNU General Public License as published by the Free Software
# Foundation, either version 3 of the License, or (at your option) any later
# version.
#
# This program is distributed in the hope that it will be useful, but WITHOUT
# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
# FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
# details.
#
# You should have received a copy of the GNU General Public License along with
# this program.  If not, see <http://www.gnu.org/licenses/>.

Dependencies

import fcntl
import math
import os
import re
import struct
import sys
import termios

Color sequences

This section defines particular color sequences. Note that you may combine font types (eg. Bold) with particular colors simply by appending them, as in Green + Bold.

Bold = '\033[1m'
Underline = '\033[2m'
Reverse = '\033[3m'

Black = '\033[0;30m'
Red = '\033[0;31m'
Green = '\033[0;32m'
Yellow = '\033[0;33m'
Blue = '\033[34m'
Magenta = '\033[35m'
Cyan = '\033[36m'
White = '\033[37m'

BgBlack = '\033[0;40m'
BgRed = '\033[0;41m'
BgGreen = '\033[0;42m'
BgYellow = '\033[0;43m'
BgBlue = '\033[44m'
BgMagenta = '\033[45m'
BgCyan = '\033[46m'
BgWhite = '\033[47m'

Reset = '\033[0m'

Colorize a string

The primitive that applies a particular color to a string. It returns a list of strings that should be appended to print the original string with a given color.

def Colorize(string, color):
  if color:
    return [color, string, Reset]
  return [string]

Standard handlers

A handler will be a function that receives a sequence with all the lines that need to be colorized (corresponding to either the standard output or the standard error of a program) and prints them, colorized, to the current process's standard output.

This section defines the standard handlers with which coloring rules are defined. The programming interface was designed with the goal of making the coloring rules reflect their intention as much as possible.

class Handler(object):
  def Run(self, lines):
    for line in lines:
      print self.ColorLine(line)

  def ColorLine(self, line):
    return line

  def GetSize(self):
    return struct.unpack('hh', fcntl.ioctl(1, termios.TIOCGWINSZ, ' ' * 4))

class HandlerList(Handler):
  def ColorLine(self, line):
    tokens = self.ColorTokens(line)
    if tokens is None:
      return line
    return ''.join(tokens)

  def ColorTokens(self, line):
    return None

class ColorDict(HandlerList):
  def __init__(self, dict, default=None):
    self.dict = dict
    self.default = default

  def ColorTokens(self, line):
    return Colorize(line, self.dict.get(line, self.default))

def ConstantColor(color):
  return ColorDict({}, color)

class HashColors(HandlerList):
  def __init__(self, colors):
    self.colors = colors

  def ColorTokens(self, line):
    for option in [4, 3, 5, 6, 2]:
      if len(line) % option == 0:
        splits = option
        break
    else:
      option = 4
    substring_length = int(math.ceil(len(line) / splits))
    assert 0 < substring_length
    for i in xrange(splits):
      substring = line[substring_length * i:substring_length * (i + 1)]
      for i in Colorize(substring, self.colors[hash(substring) % len(self.colors)]):
        yield i

def Hash():
  return HashColors([Red, Green, Yellow, Blue, Magenta, Cyan])

class Header(Handler):
  def __init__(self, header, body):
    self.header = header
    self.body = body

  def Run(self, lines):
    try:
      header_line = lines.next()
    except StopIteration:
      return
    self.header.Run([header_line])
    self.body.Run(lines)

class Row(object):
  def __init__(self, token_handler):
    self.token_handler = token_handler

  def Colorize(self, space, text):
    yield space
    yield self.token_handler.ColorLine(text)

def RowConstant(color):
  return Row(ConstantColor(color))

def RowDict(dict, default=None):
  return Row(ColorDict(dict, default))

def RowHash():
  return Row(Hash())

class Table(HandlerList):
  def __init__(self, rows):
    self.rows = rows

  TOKEN = re.compile('^( *)([^ ]+)(.*)')

  def _ConsumeToken(self, line):
    match = self.TOKEN.match(line)
    if match:
      return match.group(1), match.group(2), match.group(3)
    return '', line, ''

  def ColorTokens(self, line):
    index = 0
    while line:
      space, token, line = self._ConsumeToken(line)
      for s in self.rows[index].Colorize(space, token):
        yield s
      index = min(index + 1, len(self.rows) - 1)

class CharsFunction(HandlerList):
  def __init__(self, color_function):
    self.color_function = color_function

  def ColorTokens(self, line):
    for char in line:
      for s in Colorize(char, self.color_function(char)):
        yield s

def CharsDict(dict, default=None):
  return CharsFunction(lambda x: dict.get(x, default))

class RegexpGroups(HandlerList):
  def __init__(self, regexp_text, handlers):
    self.expr = re.compile(regexp_text)
    self.handlers = handlers

  def ColorTokens(self, line):
    match = self.expr.match(line)
    if not match:
      return None
    output = []
    index = 0
    for text in match.groups():
      output.append(self.handlers[index].ColorLine(text))
      index = min(index + 1, len(self.handlers) - 1)
    return output

def RegexpGroupsColors(expr, *colors):
  return RegexpGroups(expr, [ConstantColor(c) for c in colors])

class Rules(HandlerList):
  def __init__(self, *rules):
    self.rules = rules

  def ColorTokens(self, line):
    for rule in self.rules:
      result = rule.ColorTokens(line)
      if result:
        return result
    return line

Wrapping a command

To wrap a command, the user should create a Python script which imports colorize and calls the Run method. In practice, we expect a directory to contain all the colorize scripts and nothing more, to be inserted at the beginning of the PATH environment variable. The scripts in that directory should be named after the commands they wrap: the Run function will modify the PATH environment variable internally to remove the directory with the wrapper and execute the actual program.

def _CleanPath(args):
  path = os.getenv('PATH').split(':')
  path_current = os.path.dirname(os.path.abspath(os.path.expanduser(args[0])))
  path_clean = [p for p in path if os.path.abspath(os.path.expanduser(p)) != path_current]
  os.environ['PATH'] = ':'.join(path_clean)

def _YieldLines(file):
  while True:
    try:
      line = file.readline()
      if not line:
        return
      yield line[:-1]
    except KeyboardInterrupt:
      pass

def Run(handler_out, handler_err=None):
  for file, handler in ((sys.stdout, handler_out), (sys.stderr, handler_err)):
    if handler and os.isatty(file.fileno()):
      read_end, write_end = os.pipe()
      if os.fork():
        os.close(write_end)
        if file == sys.stderr:
          os.dup2(2, 1)
        handler.Run(_YieldLines(os.fdopen(read_end)))
        sys.exit(0)
      os.close(read_end)
      os.dup2(write_end, file.fileno())

  args = sys.argv
  _CleanPath(args)
  program = [os.path.basename(args[0])] + args[1:]
  os.execvp(program[0], program)
  sys.exit(-1)  # execvp failed

Format conversion

We wrote two programs for format conversion.

factory

Transforms a factory of fuels described in a higher level language into the actual format in the contest. In this language one can create individual machines (with as many inputs as desired) and compose them to create new ones.

convert

Our general program for converting formats, from human-readable to trits and back, both for cars, fuels and their individual components. It takes care of normalizing cars when outputting them as trits. We tested it on all the cars by converting them to human-readable and back.

Generating factories of fuels

The following is a list of programs we wrote for converting a fuel into a factory that produces it:

prog

A few interesting machines, created in the language implemented by factory.

fuel

Given a string of trits, output a machine that produces it (followed by an infinite stream of 0). The machine is described in the language implemented by factory and uses some of the machines from prog. These machines have 9 + 3n gates, where n is the length of the string of trits produced.

fuel-v2

An improvement on fuel, this produces machines with around 2 + 2n gates on average. Sadly, we only wrote this less than two hours before the end of the contest.

fuel-v3

A further improvement on fuel, producing machines with around 1 + 1.67n gates, which we finished just as the contest did.

We realized rather late, just before the end of the contest, that we could significantly improve the algorithms to produce factories for a given fuel string (to produce shorter factories).

The fuel-v3 will produce a factory with n sub-machines, one for each character, each with one input and one output. Given an even distribution of trits, this will require 1 * 1/3 + 2 * 1/3 + 2 * 1/3 = 1.67 gates per trit. The first sub-machine is picked based on the first character in the output that needs to be produced:

0

The machine is a single gate, with it's outputs connected to the output gate and to it's right input (X 0R).

1

The machine has two gates, with output's connected to 0L 1R and X 0R. The input goes to 1L.

2

The machine has two gates, with output's connected to 0L 1L and X 0R. The input goes to 1R.

To compute the rest of the factory, we check what output needs to be fed as the input to the first sub-machine so that, after the first cycle, it will produce the expected output (minus the first character, which it produced in the first cycle). Once that is determined, we apply this procedure recursively.

Solving cars

Creating cars

Our approach for creating new cars was simple yet, we think, effective:

• Produce a random fuel.
• Produce many pipes randomly.
• Pick all pairs of pipes (upper, lower) from the pool that lead to valid chambers.
• Pick the 20 chambers with smallest ratio of the dot product of (upper - lower) with itself and the dot product of lower with itself. In other words, the most demanding possible chambers.
• Make sure that the car can't be solved by any of our approaches.

When we last looked, close to the end of the contest, only one other team managed to provide fuels for our cars.

Cars DB

We quickly came to the conclusion that we needed a cars database allowing multiple programs to communicate. Creating one turned out to be a very good idea.

We decided to standarize on a plain-text files database, which turned out to be a very good idea, making it trivial to write new code that interacted with the database (for example, to count the number of cars one simply had to ls cars | wc -l, to count the number of solved cars ls cars/solution* | wc -l sufficed, etc.).

We also decided to use Subversion to synchronize the database across multiple machines and even across the same machine to avoid concurrency problems. This turned out to be a very bad idea: towards the end of the contest, as the rate at which new cars were being created increased significantly, Subversion did not scale to the rate of changes and became the bottleneck. Like the contest organizers, we didn't expect the rate at which cars would be created towards the end. We had to cut down to two the number of processes doing periodic syncs/commits and we had to disable writing all but the most essential information to the database.

We had a couple of programs operating on the cars DB, most written as a couple of shell scripts calling our actual programs. They all operated independently, often in different machines.

fuel-submitter and fuel-resubmitter

These programs would periodically scan the database for new solutions that had not been submitted yet. The fuel-submitter was pretty simple, it received the ID of a car and it's solution and would log in, submit the solution and log out. As it became evident that this wouldn't scale, given the rate at which we were producing solutions towards the end (and also in the face of fuel-v2, which meant we would have to submit a new solution for every car we had already solved), we created the fuel-resubmitter, which actually scanned the cars DB for new cars and would submit all the solutions it found in a single session. Uploading solutions (along with keeping the Subversion repository functioning with a high rate of commits) became the bottleneck. When, a few hours before the end of the contest, we found that we had more solutions than we would be able to submit, we split the set of solutions in 8 and ran a separate fuel-resubmitter process for each. In the end, we had a significant pool of fuels that we didn't get to submit.

downloader

The downloader would periodically poll the list of cars for new ones. The first version parsed the original HTML, obviously breaking when this was changed. The second version used the new page provided by the contest organizers. Upon finding new cars, it would just add their code to the cars DB.

solvers

The solvers look for new cars in the DB and try to find fuels for them. These are actually two, one that uses the brute-force solver and one that uses the linear-programming approach.

visualization

We wrote a simple tool to produce an HTML page with a sortable table with all the cars and relevant information about them (number of teams that solved them, size, have we solved them?, etc.).

score

We wrote a simple script to download the highscore every 10 minutes. We wanted to do some charts of the scores but never got around to it.

We think having this set of tools operating automatically greatly helped us. It freed us from having to do this manually and, more importantly, it meant that we reacted very quickly to new cars appearing, even while we slept.

Every car in the cars DB was represented as a directory. For each, we created the following files:

code and code-human

The code of the car (in trits and as a Python expression).

solution, solution-brute, solution-manual

The solution to a car, in human readable form, if known. The actual file used depends on the method used to find it.

last-revision

The last version of the factory-generating procedure used to generate a factory to submit as a solution (based on the solution files). This corresponds to a revision in the repository.

date

The date in which the car was created.

failed-brute

An empty file whose existance indicates that the brute-force algorithm has been run for this car.

upload-text

A log with data obtained from the server upon uploading this solution.

fuel-count

The number of teams that have submitted fuel for this car.

Near the end of the context we stopped adding many of these files to the repository, in order to speed up things.

Enabling logging

All calls to the logging function (described below) should happen within the evaluation of a procedure passed to a call to with-logging. In other words, you need to wrap your entire program in a lambda form and pass it to with-logging. with-logging also receives the default name of the current program, which is used to determine where the information will be logged.

Here is one example:

(with-logging
  "svnwiki-post-commit-hook"
  (lambda ()
    (update-svn-repository)
    (generate-static-files)
    (report-success)))

A program should only call with-logging once.

Logging a simple condition

To log a simple condition, use an expression such as:

(log-info "Loading file: ~A" path)

This will result in a line such as the following added to your log file:

info: Tue May 25 18:45:20 2010: 18257: Loading file: moon.jpeg

All the escape sequences supported by the format-modular procedure, which is used internally, are supported.

The following macros are provided, one for each severity level. They all have the same interface:

• log-fatal
• log-error
• log-warning
• log-info
• log-debug

Additionally, a logging macro is provided. It has the same interface but receives a severity (as a symbol, such as 'warning) as its first argument, before the format string.

Logging information about an expression

Typically, you will want to log information about the start and finish of the evaluation of an expression. In this case, wrap the expression in a lambda form and pass it before the format string.

For example, instead of:

(load-image path)

Use:

(log-info (lambda () (load-image path)) "Loading file: ~A" path)

This will result in two lines being logged, one at the start of the evaluation of the expression and one at the end:

info: Tue May 25 23:51:36 2010: 11782: > g1: Loading file: mars.jpeg
info: Tue May 25 23:51:39 2010: 11782: < g1: Loading file: mars.jpeg

The > and < signs indicate the beginning and the end of the evaluation. g1 is a unique ID for each call, which is useful to match these lines into pairs. If additional calls to the logging procedures happen during the evaluation of the procedure, these will be logged between the > and the < lines.

The result of the evaluation of the calls to these logging macros is, of course, the value returned by the wrapped procedure.

Enabling logging of debug severity

By default, conditions of type debug will not be logged, as they tend to be significantly verbose. To enable them, set the LOG_DEBUG environment variable.

Disabling logging altogether

If you don't want any logs to be generated, just set the LOG_DIR environment variable to the empty string. The performance impact of the logging calls will be very small.

Log directory

Logs will be stored in the directory pointed to by any of the following environment variables (in order of preference):

• LOG_DIR
• TMPDIR
• TEMP
• TMP

If none is set, they will be stored in /tmp.

A sub-directory of this directory will be created, named log-PROGRAM-DATE-PID, where

• PROGRAM is the string set in the call to with-logging (in the source code of the program) or the value of the LOG_PROGRAM environment variable if set,
• DATE is the date in which with-logging was called (which usually corresponds to the start of the execution of the program), and
• PID is the process ID.

All the logs will be stored in this directory.

Size of logs

The system tries to keep all log files under a certain size. If a log file is not empty and adding a certain entry to it would cause this size to be exceeded, the log will be closed and a new one will be opened. This lets us keep the total size of all the logs (for a given run) under a certain limit by erasing older logs.

The maximum size defaults to 1MB but maybe overriden by setting the LOG_SIZE environment variable (to the desired number of bytes).

Note that larger sizes mean larger files and less flexibility for when to erase which logs, but smaller sizes increase the number of times the logging facility has to close a log and start a new one.

Log file names

Logs will be stored in files called SEVERITY-VERSION-DATE, where

• SEVERITY is one of the severities of the system.
• VERSION is an increasing number. Every time a log reaches its desired size, the logging facility will increase the version number and create a new log.
• DATE is the date in which the log was created, which corresponds (roughly) with the timestamp on its first entry.

Number of logs to keep

By default, the system will only keep the 2 most recent logs for each of the severities. As soon as the third log is started, the system will erase the oldest log.

You can set the number of logs to keep by setting the LOG_COLLECT environment variable.

Chicken Header

Scheme Library: simple-logging

Author

Alejandro Forero Cuervo <azul@freaks-unidos.net>

Category

io

License

GPL-3

Exports

(logging logging-proc) with-logging get-logging-dir (log-fatal logging-proc) (log-error logging-proc) (log-warning logging-proc) (log-info logging-proc) (log-debug logging-proc)

Dependencies

(import scheme chicken)
(use posix extras srfi-1 data-structures format-compiler)

Global variables

We define a few global variables to keep our state. They are initialized by initialize-global-state.

*logging-directory* will point to the directory in which all logs will be generated. This is initialized by with-logging. We use this to indicate if logging is enabled: if no logging should take place, with-logging should leave this set to #f. In this case, the semantics of the other variables are undefined.

(define *logging-directory* #f)

*severities* will contain a list of all the severities supported, in descending priority. Each element in the list is a pair with the priority and a boolean indicating if messages for it should be logged.

(define *severities* #f)

*logs-to-keep* counts the number of logs to keep (for any given severity). Older logs will be erased as new ones are created. This comes from the LOG_COLLECT environment variable.

(define *logs-to-keep* #f)

*log-size* contains the desired maximum size for the logs. Logs will not be allowed to grow beyond this size (assuming that no single logged entry is larger than this size). The value comes from the environment variable LOG_SIZE.

(define *log-size* #f)

Now we need an assoc list with information about the current logs for each severity. We use an assoc list since the number of severities is fairly small. The entries in the list are lists with a severity and a log-file record (defined below).

(define *log-files* #f)

Log files

We keep information about the current log for each severity (in the *log-files* global list) in the form of a log-file record. This record has the following fields:

file

The file handle for the log (as returned by open-output-file).

version

A count for the number of logs that have been generated for this severity. The current log will have this number as the VERSION part of it's path. The first log generated starts with version set to 0 and, as it fills up (see LOG_SIZE) and a new log has to be created, the version is increased.

length

A count of the number of bytes that have been written to the current log file.

path

The full path to the log file.

(define-record log-file file version length path)

with-logging

The with-logging function, one of the entry points, is pretty simple: it initializes the global variables, evaluates a procedure of no arguments, closes any logs opened during it's evaluation and returns whatever the procedure returned.

(define (with-logging program-name thunk)
  (initialize-global-state program-name)
  (let ((result (thunk)))
    (close-all-open-logs)
    result))

Initializing global state

initialize-global-state sets the values of the global variables based on the program name passed to the with-logging procedure.

If the LOG_DIR environment variable is set to the empty directory (signifying that no logging should take place), we make sure to set *logging-directory* to #f, to avoid any logging from happening. This only matters if with-logging is called multiple times, which programs should avoid.

We reset *log-files* so that multiple calls to with-logging will work. However, programs should only make one call to with-logging and perform all their logic in the thunk they pass to it.

(define (initialize-global-state program-name)
  (cond
    ((equal? (getenv "LOG_DIR") "")
     (set! *logging-directory* #f))
    (else
     (set! *severities*
       `((fatal #t)
         (error #t)
         (warning #t)
         (info #t)
         (debug ,(getenv "LOG_DEBUG"))))
     (set! *logging-directory*
       (format #f "~A/log-~A-~A-~A"
         (get-logging-dir)
         (or (getenv "LOG_PROGRAM") program-name)
         (current-seconds)
         (current-process-id)))
     (set! *logs-to-keep* (string->number (or (getenv "LOG_COLLECT") "2")))
     (set! *log-size* (string->number (or (getenv "LOG_SIZE") "1048576")))
     (set! *log-files* '()))))

Closing all logs

Now we provide a simple function to close all open logs:

(define (close-all-open-logs)
  (when *logging-directory*
    (for-each (compose close-output-port log-file-file cadr) *log-files*)))

Paths

We provide get-logging-dir, a procedure with the logic for extracting the path in which the logs' directory should be created:

(define (get-logging-dir)
  (or (getenv "LOG_DIR")
      (getenv "TMPDIR")
      (getenv "TEMP")
      (getenv "TMP")
      "/tmp"))

Open logging files

The open-log-file receives a severity and it's corresponding log-file record as the file parameter (or #f if no log has not been created for the severity), opens a new log file for the severity and returns its corresponding log-file record.

• Verifies that the logging directory exists, creating it otherwise.
• If a log was already opened for the severity, it closes it.
• If a log old enough to be erased exists (which is determined by checking if the current version is greater than *logs-to-keep*), erases it.
• Returns a new log-file record with the updated information.

This function should only be called if *logging-directory* is (and, therefore, all the other global variables are) set.

(define (open-log-file severity file)
  (assert *logging-directory*)
  (condition-case (create-directory *logging-directory*) (e (exn) #f))
  (when (and file (log-file-file file))
    (close-output-port (log-file-file file))
    (when (and (positive? *logs-to-keep*)
               (>= (log-file-version file) *logs-to-keep*))
      (condition-case (delete-file (log-file-path file)) (e (exn) #f))))
  (let* ((version (if file (+ (log-file-version file) 1) 0))
         (path (format #f "~A/~A-~A-~A"
                       *logging-directory*
                       severity
                       version
                       (current-seconds))))
    (make-log-file (open-output-file path) 0 version path)))

Log string with severity

Now the basic plumbing function, which logs a string to the log of a given severity. It does the following:

• Stores the (severity file) pair (where file is a log-file record) for the current severity as the file variable.
• If the file didn't exist (which happens for the first entry to be logged for a severity), creates it (calling open-log-file). Updates *log-files* to keep track of it.
• If the file existed (and, therefore, is not empty), checks if the new line would cause it to exceed the desired log size. If so, opens a new log file (also calling open-log-file).
• Writes the string to the file and updates the byte count.

We use an auxiliary get-new-length function which returns the byte count that the file will have once the string str has been appended to it. We have to make this a function (as opposed to just keeping the returned value) as the file may change during the course of the execution (when a log is rotated).

This function should only be called if *logging-directory* is (and, therefore, all the other global variables are) set.

(define (logging-with-severity severity str)
  (assert *logging-directory*)
  (let ((file (assoc severity *log-files*)))
    (define (get-new-length)
      (+ (log-file-length (cadr file))
         (string-length str)
         (string-length "\n")))
    (cond
      ((not file)
       (set! file `(,severity ,(open-log-file severity #f)))
       (set! *log-files* (cons file *log-files*)))
      ((> (get-new-length) *log-size*)
       (set-car! (cdr file) (open-log-file severity (cadr file)))))
    (assert file)
    (assert (log-file? (cadr file)))
    (assert (port? (log-file-file (cadr file))))
    (write-line str (log-file-file (cadr file)))
    (log-file-length-set! (cadr file) (get-new-length))))

Log information about an evaluation

When a procedure is passed to the logging-proc procedure (defined below), we want to log information about the time its execution starts and the time it finishes. We expect this to be quite a common way of generating logging information, as it captures a bit more information about the stack than single logging entries do.

This does the following:

• Generate a unique symbol, by means of gensym, to identify this evaluation.
• Log the start of the evaluation, a string starting with >, by means of log-str.
• Call the procedure and capture its return value, to return it.
• Log the end of the evaluation, a string starting with <, also by means of log-str.

(define (log-call position severity proc fmt . args)
  (if *logging-directory*
    (let* ((id (gensym)) (str (format #f " ~A ~?" id fmt args)))
      (log-str position severity ">~A" str)
      (let ((result (proc)))
        (log-str position severity "<~A" str)
        result))
    (proc)))

Log a string

When no procedure is passed to the logging function, we need to call logging-with-severity once for each severity lesser than or equal to the requested severity. We take care of assembling the string to be logged and then just do the required calls to logging-with-severity.

If the requested severity is invalid (not found in *severities*), we default to a recursive call with severity set to warning (and with some additional information about how the severity was improperly set).

(define (log-str position severity fmt . args)
  (when *logging-directory*
    (let ((str (format #f
                       "~A: ~A: ~A: ~A: ~?"
                       severity
                       (or position "[unknown]")
                       (seconds->string (current-seconds))
                       (current-process-id)
                       fmt
                       args))
          (severities (find-tail (lambda (s) (eq? (car s) severity))
                                 *severities*)))
      (cond
        (severities
         (for-each
           (lambda (s)
             (when (cadr s)
               (logging-with-severity (car s) str)))
           severities))
        ((assoc 'warning *severities*)
         (log-str position 'warning "Invalid logging severity: ~A: ~?" severity fmt args))))))

Logging entry points

We now provide the logging macro and the logging-proc procedure. We use a macro simply to capture the position in the source code on which the original expression occurred.

(define (logging-proc position severity fmt . args)
  (let ((result (apply (if (procedure? fmt) log-call log-str)
                       position severity fmt args)))
    (when (eq? severity 'fatal)
      (exit 1))
    result))

(define-syntax (logging x r c)
  (cons* (r 'logging-proc) (get-line-number x) (cdr x)))

We provide the convenience wrappers:

(define-syntax (log-fatal x r c) (cons* (r 'logging-proc) (get-line-number x) ''fatal (cdr x)))
(define-syntax (log-error x r c) (cons* (r 'logging-proc) (get-line-number x) ''error (cdr x)))
(define-syntax (log-warning x r c) (cons* (r 'logging-proc) (get-line-number x) ''warning (cdr x)))
(define-syntax (log-info x r c) (cons* (r 'logging-proc) (get-line-number x) ''info (cdr x)))
(define-syntax (log-debug x r c) (cons* (r 'logging-proc) (get-line-number x) ''debug (cdr x)))

) ; end of module definition