Hi,
I have made a simple logging facility for my packages, with some ideas
from Hunchentoot, and I wanted to make sure that it behaves correctly
when logging to the same file from two threads.
With the current implementation (see the code below or at
http://paste.lisp.org/display/56125), I use special variables to hold
the log file and stream, so I should define them inside threads (I don't
want to directly setf the global variable since different packages may
be using it). This means that two threads with the same logging file
will each set up their own stream.
I tested with SBCL and it looks like when opening the file in :append
mode, the file position is automatically updated so apparently there is
no problem. But I don't know if this behavior should be expected by all
lisp implementations.
Is this a reasonable thing to do? Would it be portable?
Thanks in advance,
Evan
(defvar *log-stream* *standard-output*
"stream to which to log messages")
(defvar *log-level* :warning
"current log level, one of :none, :error, :warning :info, :debug")
(defvar *log-level-default* :error
"default log level")
(defvar *log-file* nil
"file to log messages to")
(defvar *log-stream-lock* (sb-thread:make-mutex :name "log-stream-lock")
"A lock to prevent two threads from writing to the log stream at the
same time.")
(defvar *log-levels* '((:none . 0)
(:error . 1)
(:warning . 2)
(:info . 3)
(:debug . 4)))
;; helper function
(defun log-level-value (log-level)
(cdr (assoc log-level *log-levels*)))
;; helper function
(defun validate-log-level (log-level)
(or (car (assoc log-level *log-levels*))
*log-level-default*))
;; helper function
(defun aux-validate-log-level (log-level)
(etypecase log-level
(keyword log-level)
(t `(validate-log-level ,log-level))))
(defmacro with-logging ((&key log-file
(log-level :warning)
(default-log-level :error)
(log-stream *standard-output*))
&body body)
"set up logging to a file or a stream"
(let ((bindings
`((*log-level* ,(aux-validate-log-level log-level))
(*log-level-default* ,(aux-validate-log-level default-log-level)))))
(if log-file
`(let ((*log-file* ,log-file)
,@bindings)
;; FIXME?: since the same file may be opened several times,
;; the lines in the file may end up in wrong order accross
;; different threads
;;
;; => after test with SBCL, it seems not to have any problem
;; when the stream is opened with :append, the messages are
;; properly inserted at the end of the file even with
;; multiple threads.
(with-open-file (*log-stream* *log-file*
:direction :output
:if-exists :append
:if-does-not-exist :create)
,@body))
`(let ((*log-stream* ,log-stream)
(*log-file* nil)
,@bindings)
,@body))))
(defun log-force-output ()
(sb-thread:with-recursive-lock (*log-stream-lock*)
(force-output *log-stream*)))
(defun log-msg (level control-string &rest format-arguments)
"log message at log-level LEVEL. CONTROL-STRING and
FORMAT-ARGUMENTS are as in format."
(let ((level (validate-log-level level)))
(when (<= (log-level-value level)
(log-level-value *log-level*))
(let* ((msg (apply #'format nil control-string format-arguments))
(msg (format nil "~a: ~a" (string-downcase level) msg)))
(sb-thread:with-recursive-lock (*log-stream-lock*)
(write-string msg *log-stream*)
(write-char #\Newline *log-stream*)
(log-force-output))
msg))))
(defun log-msg* (control-string &rest format-arguments)
"same as LOG-MSG but using the default log level."
(apply #'log-msg *log-level-default* control-string format-arguments))
#+nil
(with-output-to-string (out)
(with-logging (:log-stream out
:default-log-level :info)
(log-msg :error "test")
(log-msg :info "test")
(log-msg :debug "test")
(log-msg :warning "test ~d" 1)
(log-msg* "test default")))
On 2008-02-19, Evan Monroig <·········@obakechan.net> wrote:
> I tested with SBCL and it looks like when opening the file in :append
> mode, the file position is automatically updated so apparently there is
> no problem. But I don't know if this behavior should be expected by all
> lisp implementations.
No. SBCL implements :APPEND using O_APPEND. Other Lisps only implement
exactly what the spec says, so they seek to the end of the file in OPEN,
but subsequent writes will not seek.
If your code is for Unix only, you could use implementation-specific
functions to get the file descriptor, and use FFI with fcntl(2) to set
the O_APPEND flag.
Alternatively, grab a lock before writing to the stream, and seek to the
end using FILE-POSITION manually. (Beware that other processes (not
threads) would still overwrite each other's output.)
d.
From: Richard M Kreuter
Subject: Re: multiple streams to the same file
Date:
Message-ID: <87wsp1kkmc.fsf@progn.net>
David Lichteblau <···········@lichteblau.com> writes:
> On 2008-02-19, Evan Monroig <·········@obakechan.net> wrote:
>> I tested with SBCL and it looks like when opening the file in :append
>> mode, the file position is automatically updated so apparently there is
>> no problem. But I don't know if this behavior should be expected by all
>> lisp implementations.
>
> No. SBCL implements :APPEND using O_APPEND. Other Lisps only implement
> exactly what the spec says, so they seek to the end of the file in OPEN,
> but subsequent writes will not seek.
>
> If your code is for Unix only, you could use implementation-specific
> functions to get the file descriptor, and use FFI with fcntl(2) to set
> the O_APPEND flag.
But note that even if you set O_APPEND on the file descriptor,
probably nothing guarantees that any particular Lisp-level output
operation will correspond to a single write(2) system call, and so you
might still find that different writers' outputs will be interleaved.
--
RmK
On 2008-02-19, Richard M Kreuter <·······@progn.net> wrote:
> But note that even if you set O_APPEND on the file descriptor,
> probably nothing guarantees that any particular Lisp-level output
> operation will correspond to a single write(2) system call, and so you
> might still find that different writers' outputs will be interleaved.
Okay...
So in practise, for a "reasonably portable" solution, also
- call FORCE-OUTPUT after each line in the log file
- check that the stream's buffer is larger than a typical line.
To really get it right, lobby your vendor to implement streams on top of
a documented lower layer that by-passes buffering (think DEVICE-WRITE)
and use that instead?
d.
From: Richard M Kreuter
Subject: Re: multiple streams to the same file
Date:
Message-ID: <87r6f8lsrv.fsf@progn.net>
David Lichteblau <···········@lichteblau.com> writes:
> On 2008-02-19, Richard M Kreuter <·······@progn.net> wrote:
>> But note that even if you set O_APPEND on the file descriptor,
>> probably nothing guarantees that any particular Lisp-level output
>> operation will correspond to a single write(2) system call, and so
>> you might still find that different writers' outputs will be
>> interleaved.
>
> Okay...
>
> So in practise, for a "reasonably portable" solution, also
> - call FORCE-OUTPUT after each line in the log file
> - check that the stream's buffer is larger than a typical line.
Right, though the second point, in general, requires doing the
external-format conversion, to know whether a line will be bigger than
a buffer (or else to restrict yourself to fixed-width
external-formats).
Also, some kinds of write() failures (e.g., a full disk, lost network
connection) can result in partial writes, and an implementation is
likely to enqueue the unwritten data for a future write() attempt
(which future attempt might succeed if the failure was transient).
> To really get it right, lobby your vendor to implement streams on
> top of a documented lower layer that by-passes buffering (think
> DEVICE-WRITE) and use that instead?
Yeah, probably.
Short of that, if you've a suitable binding to platform-specific
features, you could roll your own protocol for exclusive file access
(e.g., acquire a record lock on a file beside the output file around
writes, or open the file with flags that get you exclusive access, if
the platform supports that).
--
RmK
Richard M Kreuter <·······@progn.net> writes:
> David Lichteblau <···········@lichteblau.com> writes:
>> On 2008-02-19, Richard M Kreuter <·······@progn.net> wrote:
>
>>> But note that even if you set O_APPEND on the file descriptor,
>>> probably nothing guarantees that any particular Lisp-level output
>>> operation will correspond to a single write(2) system call, and so
>>> you might still find that different writers' outputs will be
>>> interleaved.
>>
>> So in practise, for a "reasonably portable" solution, also
>> - call FORCE-OUTPUT after each line in the log file
>> - check that the stream's buffer is larger than a typical line.
[snip]
>> To really get it right, lobby your vendor to implement streams on
>> top of a documented lower layer that by-passes buffering (think
>> DEVICE-WRITE) and use that instead?
>
> Yeah, probably.
>
> Short of that, if you've a suitable binding to platform-specific
> features, you could roll your own protocol for exclusive file access
> (e.g., acquire a record lock on a file beside the output file around
> writes, or open the file with flags that get you exclusive access, if
> the platform supports that).
Thanks to both of you for the replies. This is not so simple that I
actually thought. I didn't know about O_APPEND, this is nice to know.
Since I use a lock before writing to the stream, with this approach I
conclude that the threads will not interfere with each other, and will
properly append to the file if it is open with O_APPEND, but different
processes might interfere with each other.
So this leaves the problem of different processes writing to the file at
the same time, with writes not being atomic. From your discussions my
options are:
1. do nothing => the log file will not break as long as I don't start
two SBCLs and no other application writes to the file.
2. ensure that I perform atomic writes (but as David said it requires
cooperation from the implementation)
3. use file locks => won't break as long as no other application that
doesn't understand my locks writes to the file.
4. use OS-level locks => then I have to close the file and reopen it at
each write if I have different processes.
I think that I will go for (1) since in my case it doesn't make sense to
use the same log file for two applications. I might combine it with (3)
just in case, since that looks quite straightforward to implement.
Thanks,
Evan
On 20 feb, 05:57, Evan Monroig <·········@obakechan.net> wrote:
> Thanks to both of you for the replies. This is not so simple that I
> actually thought. I didn't know about O_APPEND, this is nice to know.
>
> Since I use a lock before writing to the stream, with this approach I
> conclude that the threads will not interfere with each other, and will
> properly append to the file if it is open with O_APPEND, but different
> processes might interfere with each other.
>
> So this leaves the problem of different processes writing to the file at
> the same time, with writes not being atomic. From your discussions my
> options are:
>
> 1. do nothing => the log file will not break as long as I don't start
> two SBCLs and no other application writes to the file.
>
> 2. ensure that I perform atomic writes (but as David said it requires
> cooperation from the implementation)
>
> 3. use file locks => won't break as long as no other application that
> doesn't understand my locks writes to the file.
>
> 4. use OS-level locks => then I have to close the file and reopen it at
> each write if I have different processes.
>
> I think that I will go for (1) since in my case it doesn't make sense to
> use the same log file for two applications. I might combine it with (3)
> just in case, since that looks quite straightforward to implement.
If you're in a unix environment, what about delegating the logging
task to syslog ().
You can interface to syslog unix client library quickly with CFFI or
implement the basic BSD protocol. It is incredibly simple.
Regards,
rogersm.
··········@gmail.com" <·········@gmail.com> writes:
> If you're in a unix environment, what about delegating the logging
> task to syslog ().
>
> You can interface to syslog unix client library quickly with CFFI or
> implement the basic BSD protocol. It is incredibly simple.
>
> Regards,
> rogersm.
Thanks for the suggestion, this is nice to know.
Regards,
Evan