Based on my experience writing servers in Java and the issues we faced
around system logging, I'd be inclined--if writing a similar system in
Lisp--to write a macro like:
(defmacro syslog (category message &rest args)
"Emit a message to the system log if the given logging category
is enabled."
`(when (loggable-p ,category)
(format *log-stream* ,message ,@args)))
The idea is that loggable-p would be implemented something like:
(defun loggable-p (catgory)
(gethash catgory *logging-categories*))
where *logging-categories* is manipulated at runtime via some
management interface to turn on and off specific categories. This
would allow me to sprinkle system logging throughout my code with
expressions like:
(syslog :debug-connections
"Average connection length: ~d~%" (compute-average-connection-length))
without worrying about paying the cost of recomputing the average
connection length when I'm not interested in logging the
:debug-connections category.
However, this opens up the possibility that someone else working on
the same project, unaware that syslog is a macro, not a function,
would write something like:
(syslog :debug-connections "Total connections ~d~%" (incf connection-count))
expecting connection-count to always be incremented, even when
:debug-connection messages aren't being logged.
Obviously how significant a risk this is depends on a bunch of factors
including the number of people working on the project, how utilities
such as syslog are documented, etc. But I was wondering if those of
you with experience building large systems in Lisp have any opinions
one way or another on the wisdom of making syslog a macro vs a
function.
-Peter
--
Peter Seibel ·····@javamonkey.com
Lisp is the red pill. -- John Fraser, comp.lang.lisp
"Peter Seibel" <·····@javamonkey.com> wrote in message ···················@javamonkey.com...
> Based on my experience writing servers in Java and the issues we faced
> around system logging, I'd be inclined--if writing a similar system in
> Lisp--to write a macro like:
>
> (defmacro syslog (category message &rest args)
> "Emit a message to the system log if the given logging category
> is enabled."
> `(when (loggable-p ,category)
> (format *log-stream* ,message ,@args)))
I would do:
(defun syslog (category message &rest args)
(declare (ignore category))
(when *log-stream*
(apply #'format *log-stream* message args)))
(defmacro syslog-when (categories message &body args)
(let ((category (gensym "CATEGORY")))
`(let ((,category (some 'loggable-p ',categories)))
(when ,category
(syslog ,category ,message ,@args)))))
(syslog-when (:debug-connections :warnings :all)
"Average connection length: ~d~%" (compute-average-connection-length))
An unambiguous syslog-when macro and a function
syslog. You can change syslog dynamically in
your application without recompiling a ton of
logging code. You might even make syslog
a method and gain lots of around, before and after
abilities, along with specialization on category.
Wade
"Wade Humeniuk" <····@nospam.nowhere> writes:
> "Peter Seibel" <·····@javamonkey.com> wrote in message ···················@javamonkey.com...
> > Based on my experience writing servers in Java and the issues we faced
> > around system logging, I'd be inclined--if writing a similar system in
> > Lisp--to write a macro like:
> >
> > (defmacro syslog (category message &rest args)
> > "Emit a message to the system log if the given logging category
> > is enabled."
> > `(when (loggable-p ,category)
> > (format *log-stream* ,message ,@args)))
>
>
> I would do:
>
> (defun syslog (category message &rest args)
> (declare (ignore category))
> (when *log-stream*
> (apply #'format *log-stream* message args)))
>
> (defmacro syslog-when (categories message &body args)
> (let ((category (gensym "CATEGORY")))
> `(let ((,category (some 'loggable-p ',categories)))
> (when ,category
> (syslog ,category ,message ,@args)))))
>
> (syslog-when (:debug-connections :warnings :all)
> "Average connection length: ~d~%" (compute-average-connection-length))
Yup. That's clearly better. Thanks. Though I'm curious why you
bothered to extract 'category' in syslog-when just to pass it into
syslog which ignores it. Is that on the grounds that you might later
want to change syslog to care about it? It would simplify the macro
some not to pass it at all:
(defmacro syslog-when (categories message &rest args)
`(when (some 'loggable-p ',categories)
(syslog ,message ,@args)))
> An unambiguous syslog-when macro and a function
> syslog. You can change syslog dynamically in
> your application without recompiling a ton of
> logging code. You might even make syslog
> a method and gain lots of around, before and after
> abilities, along with specialization on category.
I had thought about the benefits of having the macro call a syslogging
function rather than directly to FORMAT in order to allow easier
redefinition on the fly. But I didn't have a good naming convention
like the obvious-in-retrospect -when suffix for the macro. Also I like
how using a list of categories also makes it syntactically obvious
that syslog-when almost has to be a macro. (Well, unless someone is
defining functions on keyword symbols which seems like pretty bad
taste.)
-Peter
--
Peter Seibel ·····@javamonkey.com
Lisp is the red pill. -- John Fraser, comp.lang.lisp
> Yup. That's clearly better. Thanks. Though I'm curious why you
> bothered to extract 'category' in syslog-when just to pass it into
> syslog which ignores it. Is that on the grounds that you might later
> want to change syslog to care about it? It would simplify the macro
> some not to pass it at all:
>
> (defmacro syslog-when (categories message &rest args)
> `(when (some 'loggable-p ',categories)
> (syslog ,message ,@args)))
>
Since I would actually have syslog do:
(defun syslog (category message &rest args)
(when *log-stream*
(format *log-stream* "~A: ~A: " (current-data/time-string) category)
(apply #'format *log-stream* message args)
(force-output *log-stream*)))
and the possiblity to do things like
(defmethod syslog ((category (eql :resources-low-warning))
message &rest args)
(signal-user-alarm-console (make-condition 'system-resources-low
:message message
:args args)))
> > An unambiguous syslog-when macro and a function
> > syslog. You can change syslog dynamically in
> > your application without recompiling a ton of
> > logging code. You might even make syslog
> > a method and gain lots of around, before and after
> > abilities, along with specialization on category.
>
> I had thought about the benefits of having the macro call a syslogging
> function rather than directly to FORMAT in order to allow easier
> redefinition on the fly. But I didn't have a good naming convention
> like the obvious-in-retrospect -when suffix for the macro. Also I like
> how using a list of categories also makes it syntactically obvious
> that syslog-when almost has to be a macro. (Well, unless someone is
> defining functions on keyword symbols which seems like pretty bad
> taste.)
Syslog then needs a slight fixup
(defmacro syslog-when (categories message &body args)
(assert (and (listp categories) (every 'keywordp categories)))
(let ((category (gensym "CATEGORY")))
`(let ((,category (some 'loggable-p ',categories)))
(when ,category
(syslog ,category ,message ,@args)))))
Wade
From: Kenny Tilton
Subject: Re: Logging macro--is this good or bad form.
Date:
Message-ID: <3ECCC9EB.7000906@nyc.rr.com>
Peter Seibel wrote:
> Based on my experience writing servers in Java and the issues we faced
> around system logging, I'd be inclined--if writing a similar system in
> Lisp--to write a macro like:
>
> (defmacro syslog (category message &rest args)
> "Emit a message to the system log if the given logging category
> is enabled."
> `(when (loggable-p ,category)
> (format *log-stream* ,message ,@args)))
>
> The idea is that loggable-p would be implemented something like:
>
> (defun loggable-p (catgory)
> (gethash catgory *logging-categories*))
Digression: make loggable-p a gf. Then you can do stuff like:
(defun c-link (using-cell used-cell)
(syslog using-cell "c-link> cell ~a gets new dependency ~a"
using-cell used-cell)
...other code...)
and to minimize output:
(defmethod loggable-p ((c c-dependent))
(typep (c-model c) 'broken-widget))
> (syslog :debug-connections "Total connections ~d~%" (incf connection-count))
Fire the idiot. Or at least burst out laughing in their face for putting
functionality in a debugging statement that is likely to get chopped by
someone who does not notice it is doing actual work.
This actually happened to me -- I commented out all the yammering debug
print statements in someone else's code so I could see what I wanted to
see. Took me an hour to discover the vital functionality performed by
one of the debugging statements.
I howled "You never take out a debug statement?!", then I realized, no
he never takes out debug statements, which is how I ended up doing it.
:)
Note that reworking the syslog macro to get it to do the Right Thing
won't help if someone decides a given SYSLOG use can be dumped (and do
not notice the functionality being performed).
Just my two.
--
kenny tilton
clinisys, inc
http://www.tilton-technology.com/
---------------------------------------------------------------
"Everything is a cell." -- Alan Kay
Kenny Tilton <·······@nyc.rr.com> writes:
> > (syslog :debug-connections "Total connections ~d~%" (incf connection-count))
>
> Fire the idiot. Or at least burst out laughing in their face for
> putting functionality in a debugging statement that is likely to get
> chopped by someone who does not notice it is doing actual work.
I know what you mean. But to be fair to the hypothetical programmer,
it's also possible that they would be fine with possibility that the
logging statement, incf and all, might be chopped out. If, for
example, connection-count is *only* used to maintain the count for
this message, it would actually make sense to couple them--there'd be
no point in keeping around the incf if the message itself was chopped.
But the poor guy still got duped by thinking that syslog was a
function and that the incf was always going to get evaluated. I think
Wade's version of syslog-when makes it much more clear that it's a
macro, justifying in-face laughing, etc.
> This actually happened to me -- I commented out all the yammering
> debug print statements in someone else's code so I could see what I
> wanted to see. Took me an hour to discover the vital functionality
> performed by one of the debugging statements.
Heh. On a (sort of) related note. A buddy and I once spent many late
hours trying to track down a problem that was causing our new Java
server product to run incredibly slowly, but only on certain machines.
Our IS guy had set up some machines for our CEO to take on the road
for demos and on those machines the server could only accept about one
connection every five minutes. Needless to say, on our normal test
machines it ran fine. We banged our head against it for hours until
finally, around midnight, while staring at the inner accept loop for
the server for the 100th time, I noticed a debugging statement which,
when enabled, logged each connection. It helpfully included
information about where the connection came from, etc. Luckily,
somewhere in the back of my mind, there was one synapse that had a
just enough juice left to fire and remind me that the toString()
method on a InetAddress object tried to print the hostname as well as
the IP address. Of course the demo boxes didn't have names--they were
just using DHCP. So every time the server accepted a connection that
debug message paused the accept thread for five minutes waiting for
the reverse lookup to time out. Commenting out that one debug
statement fixed everything. Blech.[1]
Not the same as the problem you tracked down (and probably
self-inflicted in my case) but it does show there are plenty of ways
to lose.
-Peter
[1] I believe Sun fixed this "feature" of InetAddress in JDK 1.4.
--
Peter Seibel ·····@javamonkey.com
Lisp is the red pill. -- John Fraser, comp.lang.lisp