Delayed Evaluation Across Packages April 24th, 2011
Patrick Stein

For my networking layer library, I wanted to provide ubiquitous logging. At the same time, I did not want to tie the application to my choice of logging library. I wanted the user to be able to pass me a function where I could give them a logging category and something to log.

(in-package :unet)

(defvar *logger-function* nil)

(defmacro log-it (category thing-to-log)
  `(when *logger-function*
     (funcall *logger-function* ,category ,thing-to-log)))

This seems simple enough, right? Now, throughout my code, I can do things like:

(log-it :incoming-packet packet)
(log-it :list-of-unacked-packets (get-list-of-unacked-packets))
(etc)

The application can register a *logger-function* something like this:

(defun app-log-network-msgs (category thing-to-log)
  (cl-log:log-message category thing-to-log))

Here’s the problem though: most (all?) logging libraries are good about not evaluating any arguments beyond the category unless something is actually listening for messages of that category. This makes it reasonable to do stuff like this and only take the speed hit when it’s actually important to do so:

(log-it :excruciating-detail
        (mapcar #'get-excrutiating-detail (append everyone everything)))

With my macro above, I have no way of knowing whether something is listening on a particular category or not. Further, most logging libraries don’t offer a way to query that sort of information.

What to do?

What I wanted to do was to pass a macro from the application package into my networking library instead of passing a function. I spent way too long trying to find a way to make this work (especially considering I ran into the same trouble in October, 2009 trying to use some combination of (macroexpand ...) and (eval ...) to let the caller decide which forms to execute).

All it took was posting to comp.lang.lisp to answer my own question: Closures. I changed my macro to create a closure:

(defmacro log-it (category thing-to-log)
  `(when *logger-function*
     (funcall *logger-function* ,category #'(lambda () ,thing-to-log))))

Now, the application’s logger function changes slightly and my forms are only evaluated when the logging library evaluates them:

(defun app-log-network-msgs (category thing-to-log-generator)
  (cl-log:log-message category (funcall thing-to-log-generator))

Hopefully, I will remember next time I run into this.

USerial — v0.5.2011.04.21 released April 21st, 2011
Patrick Stein

I am releasing a new version of my USerial library.

This release extends the (make-slot-serializer ...) and (make-accessor-serializer ...) so that you can pass an existing instance into the unserializers with the :object parameter rather than having the factory form allocate a new instance.

This release also provides ways to serialize and unserialize from slots and accessors in other code to allow even greater flexibility:

(serialize-accessors* (:string person-name
                       :uint8  person-age
                       :string person-hair-color)
     *person-instance* :buffer buffer)

(unserialize-slots* (:string name
                     :uint8  age
                     :string hair-color)
     *person-instance* :buffer buffer)

The serialize-slots* and unserialize-accessors* macros are also available.

Here is the latest:

Edit: Special thanks to Elliott Slaughter. The above improvements came out of recommendations from him.

USerial — v0.4.2011.04.11 April 12th, 2011
Patrick Stein

Made an addition to the USerial library to support logging of binary messages (so far only cl-log supported).

(serialize-log :log-category :uint32 uint-to-log :string "string to log" ...)

Here is the latest tarball: userial_0.4.2011.04.11.tar.gz and its signature: userial_0.4.2011.04.11.tar.gz.asc.

Binary Logging with CL-Log April 6th, 2011
Patrick Stein

One of the things that my current work does better than anywhere I’ve worked before is logging. When something goes wrong, there is a log file that you can dig through to find all kinds of information about what you were doing and how things were going.

As I move forward programming a game with my UNet library, I want to make sure that I can easily log all the network traffic during testing runs at least.

In looking through the various Lisp logging packages out there, I decided on Nick Levine’s cl-log library.

I installed it in no time with quicklisp.

Then, I set to work trying to figure out how I could use it to log binary data.

Here’s what I ended up with. If you want to do something similar, this should give you a good starting point.

Serializing, unserializing, and categorizing

With my USerial library, I defined a serializer to keep track of the different categories of log messages. And, I made corresponding categories in cl-log.

(make-enum-serializer :log-category (:packet :error :warning :info))

(defcategory :packet)
(defcategory :error)
(defcategory :warning (or :error :warning))
(defcategory :info (or :warning :info))

Specializing the classes

There are two major classes that I specialized: base-message and base-messenger. For my toying around, I didn’t end up adding any functionality to the base-message class. I will show it here though so that you know you can do it.

(defclass serialized-message (base-message)
  ())

(defclass serialized-messenger (base-messenger)
  ((filename :initarg :filename :reader serialized-messenger-filename)))

Then, I overrode the messenger-send-message generic function to create a binary header with my USerial library and then write the header and the message out.

(defmethod messenger-send-message ((messenger serialized-messenger)
                                   (message serialized-message))
  (let ((header (make-buffer 16)))
    (serialize* (:uint64 (timestamp-universal-time
                              (message-timestamp message))
                 :log-category (message-category message)
                 :uint64 (buffer-length :buffer (message-description message)))
             :buffer header)
    (with-open-file (stream (serialized-messenger-filename messenger)
                            :direction :output
                            :if-does-not-exist :create
                            :if-exists :append
                            :element-type '(unsigned-byte 8))
      (write-sequence header stream)
      (write-sequence (message-description message) stream))))

Using it

To get things going, I then made a log manager that accepts my serialized-message type and started one of my serialized-messenger instances.

(setf (log-manager)
      (make-instance 'log-manager
                     :message-class 'serialized-message))

(start-messenger 'serialized-messenger :name "binary-logger"
                                       :filename "/tmp/binary-log.dat")

Once these were started, I made a little utility function to make it easy for me to make test messages and then invoked log-message a few times.

(defun make-info (string)
  (serialize :string string :buffer (make-buffer)))

(log-message :warning (make-info "Warning"))
(log-message :info (make-info "This is info"))

Conclusions

In all, it has taken me about four times as long to write blog post as it did to install cl-log with quicklisp, peek through the cl-log documentation and source code enough to figure out how to do this, and write all of the code.

To really use this, I will probably separate out the category of a message from the serialized type of the message. This will probably involve adding a field to the serialized-message class to track the message type, adding an initialize-instance :before method for that class to look through the arguments to pull out the type, and then adding the type as an extra argument to log-message.

RSS Feeds

l