Table of Contents
- 2 Links
- 3 Portability
- 4 Background
- 5 Distinguishing features
- 6 Basics
- 7 Logging
- 8 Tracing
- 9 Replay
- 10 Testing
- 11 Persistence
- 12 Safety
- 13 Events reference
- 14 Journals reference
- 15 Bundles reference
- 16 Streamlets reference
- 17 Glossary
[in package JOURNAL with nicknames JRN]
JOURNAL ASDF System
- Version: 0.1.0
- Description: A library for logging, tracing, testing and persistence.
- Licence: MIT, see COPYING.
- Author: Gábor Melis firstname.lastname@example.org
- Homepage: http://github.com/melisgl/journal
- Bug tracker: http://github.com/melisgl/journal/issues
- Source control: GIT
Tested on ABCL, CCL, CLISP, CMUCL, ECL, and SBCL. AllegroCL Express
edition runs out of heap while running the tests. On Lisps that seem
to lack support for disabling and enabling of interrupts, such as
ABCL and CLISP, durability is compromised, and any attempt to
SYNC-JOURNAL (see Synchronization strategies and Safety) will be a
Logging, tracing, testing, and persistence are about what happened during code execution. Recording machine-readable logs and traces can be repurposed for white-box testing. More, when the code is rerun, selected frames may return their recorded values without executing the code, which could serve as a mock framework for writing tests. This ability to isolate external interactions and to reexecute traces is sufficient to reconstruct the state of a program, achieving simple persistence not unlike a journaling filesystem or Event Sourcing.
Journal is the library to log, trace, test and persist. It has a
single macro at its heart:
JOURNALED, which does pretty much what
was described. It can be thought of as generating two events around
its body: one that records the name and an argument list (as in a
function call), and another that records the return values. In
(defmacro journaled (name args &body body) `(progn (record-event `(:in ,name :args ,args)) (let ((,return-values (multiple-value-list (progn ,@body)))) (record-event `(:out ,name :values ,return-values)) (values-list ,return-values))))
The Journal library is this idea taken to its logical conclusion.
5 Distinguishing features
As a logging facility
Nested contexts and single messages
Customizable content and format
Human- or machine-readable output
#68200.234: ("some-context") #68200.234: Informative log message #68200.250: => NIL
See Logging for a complete example.
Ability to handle non-local exits
Customizable content and format
Optional timestamps, internal real- and run-time
(FOO 2.1) (1+ 2.1) => 3.1 =E "SIMPLE-ERROR" "The assertion (INTEGERP 3.1) failed."
See Tracing for a complete example.
As a test framework
White-box testing based on execution traces
Isolation of external dependencies
(define-file-bundle-test (test-user-registration :directory "registration") (let ((username (replayed ("ask-username") (format t "Please type your username: ") (read-line)))) (add-user username) (assert (user-exists-p username))))
See Testing for a complete example.
As a solution for persistence
Event Sourcing: replay interactions with the external world
Unchanged control flow
Easy to implement history, undo
(defun my-resumable-autosaving-game-with-history () (with-bundle (bundle) (play-guess-my-number)))
See Persistence for a complete example.
JOURNALED macro does both recording and replaying of events,
possibly at the same time. Recording is easy: events generated by
JOURNALED are simply written to a journal, which is a sequence of
events much like a file. What events are generated is described in
JOURNALED. Replay is much more involved, thus it gets its own
section. The journals used for recording and replaying are specified
WITH-JOURNALING or by
The Journals reference is presented later, but for most purposes
creating them (e.g. with
and maybe querying their contents with
LIST-EVENTS will suffice.
Some common cases of journal creation are handled by the convenience
Built on top of journals, Bundles juggle repeated replay-and-record cycles focussing on persistence.
[generic-function] TO-JOURNAL DESIGNATOR
Return the journal designated by
DESIGNATORor signal an error. The default implementation:
[macro] WITH-JOURNALING (&KEY RECORD REPLAY REPLAY-EOJ-ERROR-P) &BODY BODY
JOURNAL, then events generated by enclosed
JOURNALEDblocks are written to that journal (with exceptions, see the
JOURNAL, then the generated events are matched against events from that journal according to the rules of Replay.
JOURNAL-ERRORis signalled, if
JOURNALthat has been previously recorded to by another
WITH-JOURNALING(that is, if its
:NEW), or if
JOURNALthat is not a complete recording of successful replay (i.e. its
:COMPLETED). These checks are intended to catch mistakes that would render the new or existing records unusable for replay. When
RECORDjournal is marked
REPLAY-EOJ-ERROR-Pcontrols whether an
END-OF-JOURNALis signalled when a new event is being matched to the replay journal from which there are no more events to read. If there was a
REPLAY-FAILUREduring execution, then
END-OF-JOURNALis not signalled.
BODYcompletes successfully, but
REPLAYhas unprocessed events, then signal
RECORDjournals can be nested and run independently.
[macro] JOURNALED (NAME &KEY (LOG-RECORD :RECORD) VERSION ARGS VALUES CONDITION INSERTABLE REPLAY-VALUES REPLAY-CONDITION) &BODY BODY
JOURNALEDgenerates events upon entering and leaving the dynamic extent of
BODY(also known as the journaled block), which we call the In-events and Out-events. Between generating the two events,
BODYis typically executed normally (except for Replaying the outcome).
Where the generated events are written is determined by the
:RECORDargument of the enclosing
WITH-JOURNALING. If there is no enclosing
NIL, then event recording is turned off and
JOURNALEDimposes minimal overhead.
NAMEcan be of any type except
NULL, not evaluated. For names, and for anything that gets written to a journal, a non-keyword symbol is a reasonable choice as it can be easily made unique. However, it also exposes the package structure, which might make reading stuff back more difficult. Keywords and strings do not have this problem.
ARGScan be of any type, but is typically a list.
(journaled (name :version version :args args) ...)
creates an event like this:
`(:in ,name :version ,version :args ,args)
:ARGS may be omitted if they are
are used for Replay.
(:out foo :version 1 :values (42))
1 in the example) are the same
as in the in-event: they are the corresponding arguments of
OUTCOME are filled in differently depending on
how the block finished its execution.
:NLX. Indicates whether a journaled block:
returned normally (
:VALUES, see values outcome),
unwound on an expected condition (
:CONDITION, see condition outcome),
unwound on an unexpected condition (
:ERROR, see error outcome),
[glossary-term] values outcome
(journaled (foo) (values 7 t)) ;; generates the out-event (:out foo :values (7 t))
The list of return values of the block is transformed by the
JOURNALED, whose default is
#'IDENTITY. Also see Working with unreadable values).
[glossary-term] condition outcome
If the block unwound due to a condition, and
CONDITIONargument (a function whose default is
(CONSTANTLY NIL)) returns non-NIL when invoked on it, then
:CONDITIONand the outcome is this return value:
(journaled (foo :condition (lambda (c) (prin1-to-string c))) (error "xxx")) ;; generates the out-event (:out foo :condition "xxx")
Conditions thus recognized are those that can be considered to be part of normal execution. Just like return values, these expected conditions may be required to match what's in the replay journal. Furthermore, given a suitable
JOURNALED, they may be replayed without running the block.
[glossary-term] error outcome
JOURNALEDblock unwound due to a condition, but
NILwhen invoked on it, then
:ERRORand the outcome the string representations of the type of the condition and the condition itself.
(journaled (foo) (error "xxx")) ;; generates the out-event (:out foo :error ("simple-error" "xxx"))
The conversion to string is performed with
WITH-STANDARD-IO-SYNTAX. This scheme is intended to avoid leaking random implementation details into the journal, which would make
READing it back difficult.
In contrast with condition outcomes, error outcomes are what the code is not prepared to handle or replay in a meaningful way.
[glossary-term] nlx outcome
(catch 'xxx (journaled (foo) (throw 'xxx nil))) ;; generates the out-event (:out foo :nlx nil)
Currently, nlx outcomes are detected rather heuristically as there is no portable way to detect what really caused the unwinding of the stack.
There is a further grouping of outcomes into expected and unexpected.
[glossary-term] expected outcome
[glossary-term] unexpected outcome
6.3 Working with unreadable values
The events recorded often need to be readable. This is always
FILE-JOURNALs, often with
PPRINT-JOURNALs. By choosing an appropriate identifier or
string representation of the unreadable object to journal, this is
not a problem in practice.
JOURNALED provides the
hook for this purpose.
EXTERNAL-EVENTs, whose outcome is replayed (see
Replaying the outcome), we also need to be able to reverse the
VALUES, and this is what the
REPLAY-VALUES argument of
JOURNALED is for.
Let's see a complete example.
(defclass user () ((id :initarg :id :reader user-id))) (defmethod print-object ((user user) stream) (print-unreadable-object (user stream :type t) (format stream "~S" (slot-value user 'id)))) (defvar *users* (make-hash-table)) (defun find-user (id) (gethash id *users*)) (defun add-user (id) (setf (gethash id *users*) (make-instance 'user :id id))) (defvar *user7* (add-user 7)) (defun get-message () (replayed (listen :values (values-> #'user-id) :replay-values (values<- #'find-user)) (values *user7* "hello"))) (jtrace user-id find-user get-message) (let ((bundle (make-file-bundle "/tmp/user-example/"))) (format t "Recording") (with-bundle (bundle) (get-message)) (format t "~%Replaying") (with-bundle (bundle) (get-message))) .. Recording .. (GET-MESSAGE) .. (USER-ID #<USER 7>) .. => 7 .. => #<USER 7>, "hello" .. Replaying .. (GET-MESSAGE) .. (FIND-USER 7) .. => #<USER 7>, T .. => #<USER 7>, "hello" ==> #<USER 7> => "hello"
The point of this example that for to be able to journal the return
USER object must be transformed to
something readable. On the
replaces the user object with its id in the
but the original user object is returned.
(:OUT GET-MESSAGE :VERSION :INFINITY :VALUES (7 "hello"))
The user object is looked up according to
:REPLAY-VALUES and is
returned along with
[function] VALUES-> &REST FNS
A utility to create a function suitable as the
VALUESfunction is called with the list of values returned by the block and returns a transformed set of values that may be recorded in a journal. While arbitrary transformations are allowed,
VALUES->handles the common case of transforming individual elements of the list independently by calling the functions in FN with the values of the list of the same position.
(funcall (values-> #'1+) '(7 :something)) => (8 :SOMETHING)
#'1+is applied only to the first element of the values list. The list of functions is shorter than the values list, so
:SOMETHINGis not transformed. A value can be left explicitly untransformed by specifying #'
NILas the function:
(funcall (values-> #'1+ nil #'symbol-name) '(7 :something :another)) => (8 :SOMETHING "ANOTHER")
[function] VALUES<- &REST FNS
The inverse of
VALUES->, this returns a function suitable as the
JOURNALED. It does pretty much what
VALUES->does, but the function returned returns the transformed list as multiple values instead of as a list.
(funcall (values<- #'1-) '(8 :something)) => 7 => :SOMETHING
[function] LIST-EVENTS &OPTIONAL (JOURNAL (RECORD-JOURNAL))
Return a list of all the events in the journal designated by
SYNC-JOURNALfirst, to make sure that all writes are taken into account.
[function] EVENTS-TO-FRAMES EVENTS
Convert a flat list of events, such as those returned by
LIST-EVENTS, to a nested list representing the frames. Each frame is a list of the form
(<in-event> <nested-frames>* <out-event>?). Like in
EVENTSmay be a
(events-to-frames '((:in foo :args (1 2)) (:in bar :args (7)) (:leaf "leaf") (:out bar :values (8)) (:out foo :values (2)) (:in foo :args (3 4)) (:in bar :args (8)))) => (((:IN FOO :ARGS (1 2)) ((:IN BAR :ARGS (7)) (:LEAF "leaf") (:OUT BAR :VALUES (8))) (:OUT FOO :VALUES (2))) ((:IN FOO :ARGS (3 4)) ((:IN BAR :ARGS (8)))))
Note that, as in the above example, incomplete frames (those without an
OUT-EVENT) are included in the output.
[function] EXPECTED-TYPE TYPE
Return a function suitable as the
JOURNALED, which returns the type of its single argument as a string if it is of
[function] PRINT-EVENTS EVENTS &KEY STREAM
(print-events '((:in log :args ("first arg" 2)) (:in versioned :version 1 :args (3)) (:out versioned :version 1 :values (42 t)) (:out log :condition "a :CONDITION outcome") (:in log-2) (:out log-2 :nlx nil) (:in external :version :infinity) (:out external :version :infinity :error ("ERROR" "an :ERROR outcome")))) .. .. (:IN LOG :ARGS ("first arg" 2)) .. (:IN VERSIONED :VERSION 1 :ARGS (3)) .. (:OUT VERSIONED :VERSION 1 :VALUES (42 T)) .. (:OUT LOG :CONDITION "a :CONDITION outcome") .. (:IN LOG-2) .. (:OUT LOG-2 :NLX NIL) .. (:IN EXTERNAL :VERSION :INFINITY) .. (:OUT EXTERNAL :VERSION :INFINITY :ERROR ("ERROR" "an :ERROR outcome")) => ; No value
[function] PPRINT-EVENTS EVENTS &KEY STREAM (PRETTIFIER 'PRETTIFY-EVENT)
PRINT-EVENTS, but produces terser, more human readable output.
(pprint-events '((:in log :args ("first arg" 2)) (:in versioned :version 1 :args (3)) (:leaf "This is a leaf, not a frame.") (:out versioned :version 1 :values (42 t)) (:out log :condition "a :CONDITION outcome") (:in log-2) (:out log-2 :nlx nil) (:in external :version :infinity) (:out external :version :infinity :error ("ERROR" "an :ERROR outcome")))) .. .. (LOG "first arg" 2) .. (VERSIONED 3) v1 .. This is a leaf, not a frame. .. => 42, T .. =C "a :CONDITION outcome" .. (LOG-2) .. =X .. (EXTERNAL) ext .. =E "ERROR" "an :ERROR outcome" => ; No value
The function given as the
PRETTIFIERargument formats individual events. The above output was produced with
PRETTIFY-EVENT. For a description of
PRETTIFIER's arguments see
[function] PRETTIFY-EVENT EVENT DEPTH STREAM
STREAMin a somewhat human-friendly format. This is the function
PPRINT-EVENTS, and Tracing use by default. In addition to the basic example in
PPRINT-EVENTS, decoration on events is printed before normal, indented output like this:
(pprint-events '((:leaf "About to sleep" :time "19:57:00" :function "FOO"))) .. .. 19:57:00 FOO: About to sleep
DEPTHis the nesting level of the
EVENT. Top-level events have depth 0.
PRETTIFY-EVENTprints indents the output, after printing the decorations, by 2 spaces per depth.
Instead of collecting events and then printing them, events can be pretty-printed to a stream as they generated. This is accomplished with Pretty-printing journals, discussed in detail later, in the following way:
(let ((journal (make-pprint-journal))) (with-journaling (:record journal) (journaled (foo) "Hello"))) .. .. (FOO) .. => "Hello"
6.6 Error handling
[condition] JOURNALING-FAILURE SERIOUS-CONDITION
Signalled during the dynamic extent of
WITH-JOURNALINGwhen an error threatens to leave the journaling mechanism in an inconsistent state. These include I/O errors encountered reading or writing journals by
SYNC-JOURNAL, but also
STORAGE-CONDITIONs, assertion failures, and errors calling
CONDITIONfunction arguments. Crucially, this does not apply to non-local exits from other code, such as
JOURNALEDblocks, whose error handling is largely unaltered (see Out-events and Replay failures).
In general, any non-local exit from critical parts of the code is turned into a
JOURNALING-FAILUREto protect the integrity of the
RECORD-JOURNAL. The condition that caused the unwinding is in
NILif it was a pure non-local exit like
THROW. This is a
SERIOUS-CONDITION, not to be handled within
JOURNALING-FAILURE, the journaling mechanism cannot be trusted anymore. The
REPLAY-JOURNALmight have failed a read and be out-of-sync. The
RECORD-JOURNALmay have missing events (or even half-written events with
SYNC, see Synchronization strategies), and further writes to it would risk replayability, which is equivalent to database corruption. Thus, upon signalling
JOURNAL-STATEis set to
:COMPLETEDif the journal is in state
:LOGGINGand the transition to
:RECORDINGwas reflected in storage,
else it is set to
JOURNALING-FAILURE, any further attempt within the affected
WITH-JOURNALINGto use the critical machinery mentioned above (
LOGGED, etc) resignals the same journal failure condition. As a consequence, the record journal cannot be changed and the only way to recover is to leave
WITH-JOURNALING. This does not affect processing in other threads, which by design cannot write to the record journal.
Note that in contrast with
REPLAY-FAILURE, which necessitate leaving
WITH-JOURNALINGto recover from, the other conditions -
STREAMLET-ERROR- are subclasses of
ERRORas the their handling need not be so heavy-handed.
- [reader] JOURNALING-FAILURE-EMBEDDED-CONDITION JOURNALING-FAILURE (:EMBEDDED-CONDITION)
SIGNAL: this is not an
EXTERNAL-EVENThad an unexpected outcome while in
:RECORDING. Upon signalling this condition,
JOURNAL-STATEis set to
:LOGGING, thus no more events can be recorded that will affect replay of the journal being recorded. The event that triggered this condition is recorded in state
:LOGGING, with its version downgraded. Since Replay (except Invoked) is built on the assumption that control flow is deterministic, an unexpected outcome is significant because it makes this assumption to hold unlikely.
[condition] DATA-EVENT-LOSSAGE JOURNALING-FAILURE
[condition] JOURNAL-ERROR ERROR
[condition] END-OF-JOURNAL JOURNAL-ERROR
This might be signalled by the replay mechanism if
REPLAY-EOJ-ERROR-Pis true. Unlike
REPLAY-FAILUREs, this does not affect
RECORD-JOURNAL. At a lower level, it is signalled by
READ-EVENTupon reading past the end of the
Before we get into the details, here is a self contained example that demonstrates typical use.
(defvar *communication-log* nil) (defvar *logic-log* nil) (defvar *logic-log-level* 0) (defun call-with-connection (port fn) (framed (call-with-connection :log-record *communication-log* :args `(,port)) (funcall fn))) (defun fetch-data (key) (let ((value 42)) (logged ((and (<= 1 *logic-log-level*) *logic-log*)) "The value of ~S is ~S." key value) value)) (defun init-logging (&key (logic-log-level 1)) (let* ((stream (open "/tmp/xxx.log" :direction :output :if-does-not-exist :create :if-exists :append)) (journal (make-pprint-journal :stream (make-broadcast-stream (make-synonym-stream '*standard-output*) stream)))) (setq *communication-log* journal) (setq *logic-log* journal) (setq *logic-log-level* logic-log-level))) (init-logging) (call-with-connection 8080 (lambda () (fetch-data :foo))) .. .. (CALL-WITH-CONNECTION 8080) .. The value of :FOO is 42. .. => 42 => 42 (setq *logic-log-level* 0) (call-with-connection 8080 (lambda () (fetch-data :foo))) .. .. (CALL-WITH-CONNECTION 8080) .. => 42 => 42 (ignore-errors (call-with-connection 8080 (lambda () (error "Something unexpected.")))) .. .. (CALL-WITH-CONNECTION 8080) .. =E "SIMPLE-ERROR" "Something unexpected."
Default to muffling
Imagine a utility library called glib.
(defvar *glib-log* nil) (defvar *patience* 1) (defun sl33p (seconds) (logged (*glib-log*) "Sleeping for ~As." seconds) (sleep (* *patience* seconds)))
Glib follows the recommendation to have a special variable globally
NIL by default. The value of
*GLIB-LOG* is the journal to
which glib log messages will be routed. Since it's
NIL, the log
messages are muffled, and to record any log message, we need to
change its value.
Routing logs to a journal
Let's send the logs to a
(setq *glib-log* (make-pprint-journal :log-decorator (make-log-decorator :time t))) (sl33p 0.01) .. .. 2020-08-31T12:45:23.827172+02:00: Sleeping for 0.01s.
That's a bit too wordy. For this tutorial, let's stick to less verbose output:
(setq *glib-log* (make-pprint-journal)) (sl33p 0.01) .. .. Sleeping for 0.01s.
To log to a file:
(setq *glib-log* (make-pprint-journal :stream (open "/tmp/glib.log" :direction :output :if-does-not-exist :create :if-exists :append)))
If we were recording a journal for replay and wanted to include glib logs in the journal, we would do something like this:
(with-journaling (:record t) (let ((*glib-log* :record)) (sl33p 0.01) (journaled (non-glib-stuff :version 1))) (list-events)) => ((:LEAF "Sleeping for 0.01s.") (:IN NON-GLIB-STUFF :VERSION 1) (:OUT NON-GLIB-STUFF :VERSION 1 :VALUES (NIL)))
We could even
(SETQ *GLIB-LOG* :RECORD) to make it so that glib
messages are included by default in the
RECORD-JOURNAL. In this
example, the special
*GLIB-LOG* acts like a log category for all
the log messages of the glib library (currently one).
Rerouting a category
Next, we route
*GLIB-LOG* to wherever
*APP-LOG* is pointing by
*GLIB-LOG* to the symbol
*APP-LOG* (see Log record).
(defvar *app-log* nil) (let ((*glib-log* '*app-log*)) (setq *app-log* nil) (logged (*glib-log*) "This is not written anywhere.") (setq *app-log* (make-pprint-journal :pretty nil)) (sl33p 0.01)) .. .. (:LEAF "Sleeping for 0.01s.")
Finally, to make routing decisions conditional we need to change
(defvar *glib-log-level* 1) (defun sl33p (seconds) (logged ((and (<= 2 *glib-log-level*) *glib-log*)) "Sleeping for ~As." (* *patience* seconds)) (sleep seconds)) ;;; Check that it all works: (let ((*glib-log-level* 1) (*glib-log* (make-pprint-journal))) (format t "~%With log-level ~A" *glib-log-level*) (sl33p 0.01) (setq *glib-log-level* 2) (format t "~%With log-level ~A" *glib-log-level*) (sl33p 0.01)) .. .. With log-level 1 .. With log-level 2 .. Sleeping for 0.01s.
Nested log contexts
(defun callv (var value symbol &rest args) "Call SYMBOL-FUNCTION of SYMBOL with VAR dynamically bound to VALUE." (framed ("glib:callv" :log-record *glib-log* :args `(,var ,value ,symbol ,@args)) (progv (list var) (list value) (apply (symbol-function symbol) args)))) (callv '*print-base* 2 'print 10) .. .. ("glib:callv" *PRINT-BASE* 2 PRINT 10) .. 1010 .. => 10 => 10 (let ((*glib-log-level* 2)) (callv '*patience* 7 'sl33p 0.01)) .. .. ("glib:callv" *PATIENCE* 7 SL33P 0.01) .. Sleeping for 0.07s. .. => NIL
7.1 Customizing logs
Here, we discuss how to make logs more informative.
JOURNAL-LOG-DECORATORadds additional data to
LOG-EVENTs as they are written to the journal. This data is called decoration and it is to capture the context in which the event was triggered. See
MAKE-LOG-DECORATORfor a typical example. Decorations, since they can be on
LOG-EVENTs only, do not affect Replay. Decorations are most often used with Pretty-printing.
[accessor] JOURNAL-LOG-DECORATOR JOURNAL (:LOG-DECORATOR = NIL)
If non-NIL, a function to add decoration to
LOG-EVENTs before they are written to a journal. The only allowed transformation is to append a plist to the event, which is a plist itself. The keys can be anything.
[function] MAKE-LOG-DECORATOR &KEY THREAD TIME REAL-TIME RUN-TIME
Return a function suitable as
JOURNAL-LOG-DECORATORthat may add the name of the thread, a timestamp, the internal real-time or run-time (both in seconds) to events.
RUN-TIMEare boolean-valued symbols.
(funcall (make-log-decorator :thread t :time t :real-time t :run-time t) (make-leaf-event :foo)) => (:LEAF :FOO :TIME "2020-08-31T13:38:58.129178+02:00" :REAL-TIME 66328.82 :RUN-TIME 98.663 :THREAD "worker")
7.2 Log record
WITH-BUNDLE control replaying and recording
within their dynamic extent, which is rather a necessity because
Replay needs to read the events in the same order as the
blocks are being executed. However,
LOG-EVENTs do not affect replay
so we can allow more flexibility in routing them.
LOG-RECORD argument of
LOGGED controls where
LOG-EVENTs are written both within
WITH-JOURNALING and without. The
algorithm to determine the target journal is this:
NIL, then it is returned.
JOURNAL, then it is returned.
LOG-RECORDis symbol (other than
NIL), then the
SYMBOL-VALUEof that symbol is assigned to
LOG-RECORDand we go to step 1.
If the return value is
NIL, then the event will not be written
anywhere, else it is written to the journal returned.
Events may be written to
LOG-RECORD even without an enclosing
WITH-JOURNALING, and it does not affect the
it is a
JOURNAL-ERROR to write to a
:COMPLETED journal (see
When multiple threads log to the same journal it is guaranteed that individual events are written atomically, but frames from different threads do not necessarily nest. To keep the log informative, the name of thread may be added to the events as decoration.
Also see notes on thread Safety.
7.3 Logging with
[macro] LOGGED (&OPTIONAL (LOG-RECORD :RECORD)) FORMAT-CONTROL &REST FORMAT-ARGS
(with-journaling (:record t) (logged () "Hello, ~A." "world") (list-events)) => ((:LEAF "Hello, world."))
LOG-EVENTs with no separate in- and out-events. They have an
EVENT-NAMEand no other properties. Use
LOGGEDfor point-in-time textual log messages, and
FRAMED) to provide context.
Also see Log record.
(defun foo (x) (sleep 0.12) (1+ x)) (defun bar (x) (foo (+ x 2)) (error "xxx")) (jtrace foo bar) (ignore-errors (bar 1)) .. .. (BAR 1) .. (FOO 3) .. => 4 .. =E "SIMPLE-ERROR" "xxx"
It can also include the name of the originating thread and timestamps in the output:
(let ((*trace-thread* t) (*trace-time* t)) (ignore-errors (bar 1))) .. .. 2020-09-02T19:58:19.415204+02:00 worker: (BAR 1) .. 2020-09-02T19:58:19.415547+02:00 worker: (FOO 3) .. 2020-09-02T19:58:19.535766+02:00 worker: => 4 .. 2020-09-02T19:58:19.535908+02:00 worker: =E "SIMPLE-ERROR" "xxx"
(let ((*trace-real-time* t) (*trace-run-time* t)) (ignore-errors (bar 1))) .. .. #16735.736 !68.368: (BAR 1) .. #16735.736 !68.369: (FOO 3) .. #16735.857 !68.369: => 4 .. #16735.857 !68.369: =E "SIMPLE-ERROR" "xxx"
Customizing the content and the format
If these options are insufficient, the content and the format of the trace can be customized:
(let ((*trace-journal* (make-pprint-journal :pretty '*trace-pretty* :prettifier (lambda (event depth stream) (format stream "~%Depth: ~A, event: ~S" depth event)) :stream (make-synonym-stream '*error-output*) :log-decorator (lambda (event) (append event '(:custom 7)))))) (ignore-errors (bar 1))) .. .. Depth: 0, event: (:IN BAR :ARGS (1) :CUSTOM 7) .. Depth: 1, event: (:IN FOO :ARGS (3) :CUSTOM 7) .. Depth: 1, event: (:OUT FOO :VALUES (4) :CUSTOM 7) .. Depth: 0, event: (:OUT BAR :ERROR ("SIMPLE-ERROR" "xxx") :CUSTOM 7)
In the above,
*TRACE-JOURNAL* was bound locally to keep the example
from wrecking the global default, but the same effect could be
[macro] JTRACE &REST NAMES
JTRACEtakes a list of symbols. When functions denoted by those
NAMESare invoked, their names, arguments and outcomes are printed in human readable form to
*TRACE-OUTPUT*. These values may not be readable,
JTRACEdoes not care.
The format of the output is the same as that of
PPRINT-EVENTS. Behind the scenes,
JTRACEencapsulates the global functions with
NAMESin wrapper that behaves as if
FOOin the example above was defined like this:
(defun foo (x) (framed (foo :args `(,x) :log-record *trace-journal*) (1+ x)))
JTRACEis invoked with no arguments, it returns the list of symbols currently traced.
On Lisps other than SBCL, where a function encapsulation facility is not available or it is not used by Journal,
SYMBOL-FUNCTION. This solution loses the tracing encapsulation when the function is recompiled. On these platforms,
(JTRACE)also retraces all functions that should be traced, but aren't.
The main advantage of
CL:TRACEis the ability to trace errors, not just normal return values. As it is built on
JOURNALED, it can also detect - somewhat heuristically -
THROWs and similar.
[macro] JUNTRACE &REST NAMES
[variable] *TRACE-PRETTY* T
[variable] *TRACE-THREAD* NIL
Controls whether to decorate the trace with the name of the originating thread. See
[variable] *TRACE-TIME* NIL
Controls whether to decorate the trace with a timestamp. See
[variable] *TRACE-REAL-TIME* NIL
Controls whether to decorate the trace with the internal real-time. See
[variable] *TRACE-RUN-TIME* NIL
Controls whether to decorate the trace with the internal run-time. See
[variable] *TRACE-JOURNAL* #<PPRINT-JOURNAL :NEW>
LOG-EVENTs. By default it is a
PPRINT-JOURNALthat sets up a
*TRACE-OUTPUT*and sends its output there. It pays attention to
*TRACE-PRETTY*, and its log decorator is affected by
*TRACE-THREAD*. However, by changing
PPRINT-JOURNAL-PRETTIFIERcontent and output can be customized.
8.1 Slime integration
(defun slime-toggle-jtrace-fdefinition (spec) "Toggle JTRACE." (interactive (list (slime-read-from-minibuffer "j(un)trace: " (slime-symbol-at-point)))) (message "%s" (slime-eval ;; Silently fail if Journal is not loaded. `(cl:when (cl:find-package :journal) (cl:funcall (cl:find-symbol (cl:symbol-name :swank-toggle-jtrace) :journal) ,spec))))) (define-key slime-mode-map (kbd "C-c C-j") 'slime-toggle-jtrace-fdefinition) (define-key slime-repl-mode-map (kbd "C-c C-j") 'slime-toggle-jtrace-fdefinition)
During replay, code is executed normally with special rules for
blocks. There are two modes for dealing with blocks: replaying the
code or replaying the outcome. When code is replayed, upon entering
and leaving a block, the events generated are matched to events read
from the journal being replayed. If the events don't match, a
REPLAY-FAILURE is signaled which marks the record journal as having
failed the replay. This is intended to make sure that the state of
the program during the replay matches the state at the time of
recording. In the other mode, when the outcome is replayed, a block
may not be executed at all, but its recorded outcome is
reproduced (e.g. the recorded return values are returned).
Replay can be only be initiated with
WITH-JOURNALING (or its close
WITH-BUNDLE). After the per-event processing described below,
WITH-JOURNALING finishes, it might signal
there are unprocessed non-log events left in the replay journal.
Replay is deemed successful or failed depending on whether all
events are replayed from the replay journal without a
REPLAY-FAILURE. A journal that records events from a successful
replay can be used in place of the journal that was replayed, and so
on. The logic of replacing journals with their successful replays is
automated by Bundles.
WITH-JOURNALING does not allow replay from
journals that were failed replays themselves. The mechanism, in
terms of which tracking success and failure of replays is
implemented, revolves around
EVENT-VERSIONs, which we discuss next.
:NEW: This journal was just created, but never recorded to.
:REPLAYING: Replaying events has started, some events may have been replayed successfuly, but there are more, non-log events to replay.
:RECORDING: All events from the replay journal were successfully replayed and now new events are being recorded without being matched to the replay journal.
:FAILED: The journal is to be discarded. It encountered a
REPLAY-FAILUREwithout completing the replay and reaching
:COMPLETED: All events were successfully replayed and
WITH-JOURNALINGfinished or a
The state transitions are:
:NEW -> :REPLAYING (on entering WITH-JOURNALING) :REPLAYING -> :MISMATCHED (on REPLAY-FAILURE) :REPLAYING -> :FAILED (on REPLAY-INCOMPLETE) :REPLAYING -> :FAILED (on JOURNALING-FAILURE) :REPLAYING -> :RECORDING (on successfully replaying all events) :MISMATCHED -> :FAILED (on leaving WITH-JOURNALING) :RECORDING -> :LOGGING (on RECORD-UNEXPECTED-OUTCOME) :RECORDING/:LOGGING -> :COMPLETED (on leaving WITH-JOURNALING) :RECORDING/:LOGGING -> :COMPLETED (on JOURNALING-FAILURE)
:NEWis the starting state. It is a
JOURNAL-ERRORto attempt to write to journals in
:COMPLETED. Note that once in
:RECORDING, the only possible terminal state is
9.1 Journaled for replay
The following arguments of
JOURNALED control behaviour under replay.
EXTERNAL-EVENTs may be replayed with the insert replay strategy (see The replay strategy). Does not affect
LOG-EVENTs, that are always _insert_ed. Note that inserting
:REPLAYINGis often not meaningful (e.g. asking the user for input may lead to a
PEEK-REPLAY-EVENTfor an example on how to properly insert these kinds of
REPLAY-CONDITION, a function or
NIL, may be called with
EVENT-OUTCOME(the return value of the function provided as
:CONDITION) when replaying and
NILis equivalent to the
ERRORfunction. Replaying conditions is cumbersome and best avoided.
[variable] *FORCE-INSERTABLE* NIL
The default value of the
VERSIONED-EVENTs. Binding this to
Tallows en-masse structural upgrades in combination with
WITH-REPLAY-FILTER. Does not affect
EXTERNAL-EVENTs. See Upgrades and replay.
An event's version is either
NIL, a positive fixnum, or
:INFINITY, which correspond to
EXTERNAL-EVENTs, respectively, and have an increasingly strict behaviour with regards to Replay. All
EVENTs have versions. The versions of the in- and out-events belonging to the same frame are the same.
NILcalled log events. During Replay, they are never matched to events from the replay journal, and log events in the replay do not affect events being recorded either. These properties allow log events to be recorded in arbitrary journals with
LOG-RECORDargument. The convenience macro
FRAMEDis creating frames of log-events, while the
LOGGEDgenerates a log-event that's a
Events with a positive integer
EVENT-VERSIONare called versioned events. In Replay, they undergo consistency checks unlike
LOG-EVENTs, but the rules for them are less strict than for
EXTERNAL-EVENTs. In particular, higher versions are always considered compatible with lower versions, they become an upgrade in terms of the The replay strategy, and versioned events can be inserted into the record without a corresponding replay event with
:INFINITYare called external events. They are like
VERSIONED-EVENTs whose version was bumped all the way to infinity, which rules out easy, non-matching upgrades. Also, they are never inserted to the record without a matching replay event (see The replay strategy).
In return for these restrictions, external events can be replayed without running the corresponding block (see Replaying the outcome). This allows their out-event variety, called data events, to be non-deterministic. Data events play a crucial role in Persistence.
Built on top of
JOURNALED, the macros below record a pair of
In-events and Out-events, but differ in how they are replayed and
the requirements on their blocks. The following table names the
EVENT produced (
Event), how In-events are
In-e.), whether the block is always run (
Out-events are replayed (
Out-e.), whether the block must be
Det) or side-effect free (
| | Event | In-e. | Run | Out-e. | Det | SEF | |----------+-----------+--------+-----+--------+-----+-----| | FRAMED | log | skip | y | skip | n | n | | CHECKED | versioned | match | y | match | y | n | | REPLAYED | external | match | n | replay | n | y | | INVOKED | versioned | replay | y | match | y | n |
Note that the replay-replay combination is not implemented because there is nowhere to return values from replay-triggered functions.
[macro] FRAMED (NAME &KEY LOG-RECORD ARGS VALUES CONDITION) &BODY BODY
BODYis always run and no
REPLAY-FAILUREs are triggered.
BODYis not required to be deterministic and it may have side-effects.
[macro] CHECKED (NAME &KEY (VERSION 1) ARGS VALUES CONDITION INSERTABLE) &BODY BODY
BODY- which must be deterministic - is always run and
REPLAY-FAILUREs are triggered when the events generated do not match the events in the replay journal.
BODYmay have side-effects.
For further discussion of determinism, see
[macro] REPLAYED (NAME &KEY ARGS VALUES CONDITION INSERTABLE REPLAY-VALUES REPLAY-CONDITION) &BODY BODY
IN-EVENTis checked for consistency with the replay (as with
BODYis not run (assuming it has a recorded expected outcome) and the outcome in the
OUT-EVENTis reproduced (see Replaying the outcome). For this scheme to work,
BODYto be side-effect free, but it may be non-deterministic.
Invoked refers to functions and blocks defined by
FLET-INVOKED. Invoked frames may be recorded in response to asynchronous events, and at replay the presence of its in-event triggers the execution of the function associated with the name of the event.
- is deterministic in this sense. On the other hand, Invoked encodes
IN-EVENTwhat function to call next, introducing non-deterministic control flow.
By letting events choose the code to run, Invoked resembles typical Event Sourcing frameworks. When Invoked is used exclusively, the journal becomes a sequence of events. In contrast,
JOURNALEDand its wrappers put code first, and the journal will be a projection of the call tree.
- is deterministic in this sense. On the other hand, Invoked encodes in its
[macro] DEFINE-INVOKED FUNCTION-NAME ARGS (NAME &KEY (VERSION 1) INSERTABLE) &BODY BODY
DEFINE-INVOKEDis intended for recording asynchronous function invocations like event or signal handlers. It defines a function that records
ARGSset to the actual arguments. At replay, it is invoked whenever the recorded
IN-EVENTbecomes the replay event.
CHECKEDrolled into one,
DEFINE-INVOKEDdefines a top-level function with
ARGS(only simple positional arguments are allowed) and wraps
NAME, the same
BODY. Whenever an
IN-EVENTbecomes the replay event and it has a
DEFINE-INVOKEDdefined with the name of the event, then
FUNCTION-NAMEis invoked with
BODY's return values are recorded as usual, the defined function returns no values to make it less likely to affect control flow in a way that's not possible to reproduce when the function is called by the replay mechanism.
(defvar *state*) (define-invoked foo (x) ("foo") (setq *state* (1+ x))) (define-invoked bar (x) ("bar") (setq *state* (+ 2 x))) (if (zerop (random 2)) (foo 0) (bar 1))
The above can be alternatively implemented with
REPLAYEDexplicitly encapsulating the non-determinism:
(let ((x (replayed (choose) (random 2)))) (if (zerop x) (checked (foo :args `(,x)) (setq *state* (1+ x))) (checked (bar :args `(,x)) (setq *state* (+ 2 x)))))
[macro] FLET-INVOKED DEFINITIONS &BODY BODY
DEFINE-INVOKED, but with
DEFUN. The event name and the function are associated in the dynamic extent of
WITH-JOURNALINGdoes not change the bindings. The example in
DEFINE-INVOKEDcan be rewritten as:
(let ((state nil)) (flet-invoked ((foo (x) ("foo") (setq state (1+ x))) (bar (x) ("bar") (setq state (+ 2 x)))) (if (zerop (random 2)) (foo 0) (bar 1))))
Consider replaying the same code repeatedly, hoping to make progress in the processing. Maybe based on the availability of external input, the code may error out. After each run, one has to decide whether to keep the journal just recorded or stick with the replay journal. A typical solution to this would look like this:
(let ((record nil)) (loop (setq record (make-in-memory-journal)) (with-journaling (:record record :replay replay) ...) (when (and ;; RECORD is a valid replay of REPLAY ... (eq (journal-state record) :completed) ;; ... and is also significantly different from it ... (journal-diverged-p record)) ;; so use it for future replays. (setq replay record))))
This is pretty much what bundles automate. The above becomes:
(let ((bundle (make-in-memory-bundle))) (loop (with-bundle (bundle) ...)))
[macro] WITH-BUNDLE (BUNDLE) &BODY BODY
This is like
REPLAY-JOURNALis the last successfully completed one in
BUNDLE, and the
RECORD-JOURNALis a new one created in
WITH-BUNDLEfinishes, the record journal is in
To avoid accumulating useless data, the new record is immediately deleted when
WITH-BUNDLEfinishes if it has not diverged from the replay journal (see
:FAILEDjournals are always divergent in this sense, they are deleted instead based on whether there is already a previous failed journal in the bundle and the new record is identical to that journal (see
It is a
JOURNAL-ERRORto have concurrent or nested
WITH-BUNDLEs on the same bundle.
9.3 The replay strategy
The replay process for both In-events and Out-events starts by
determining how the generated event (the new event from now on)
shall be replayed. Roughly, the decision is based on the
VERSION of the new event and the replay event (the next event to be
read from the replay). There are four possible strategies:
upgrade: The new event is not matched to any replay event, but an event is consumed from the replay journal. This happens if next new event has the same name as the replay event, but its version is higher.
insert: The new event is not matched to any replay event, and no events are consumed from the replay journal, which may be empty. This is always the case for new
LOG-EVENTs and when there are no more events to read from the replay journal (unless
VERSIONED-EVENTs, it is affected by setting
INSERTABLEto true (see Journaled for replay).
The out-event's strategy is always insert if the strategy for the corresponding in-event was insert.
The strategy is determined by the following algorithm, invoked whenever an event is generated by a journaled block:
Log events are not matched to the replay. If the new event is a log event or a
REPLAY-FAILUREhas been signalled before (i.e. the record journal's
:MISMATCHED), then insert is returned.
Else, log events to be read in the replay journal are skipped, and the next unread, non-log event is peeked at (without advancing the replay journal).
end of replay: If there are no replay events left, then:
WITH-JOURNALING(the default), insert is returned.
REPLAY-EOJ-ERROR-Pis true, then
mismatched name: Else, if the next unread replay event's name is not
EQUALto the name of the new event, then:
REPLAY-NAME-MISMATCHis signalled if
NIL, else insert is returned.
matching name: Else, if the name of the next unread event in the replay journal is
EQUALto the name of new event, then it is chosen as the replay event.
If the replay event's version is higher than the new event's version, then
If the two versions are equal, then match is returned.
If the new event's version is higher, then upgrade is returned.
:INFINITYis considered higher than any integer and equal to itself.
| new event | end-of-replay | mismatched name | matching name | |-----------+-------------------+-------------------+---------------| | Log | insert | insert | insert | | Versioned | insert/eoj-error | insert/name-error | match-version | | External | insert/eoj-error | insert/name-error | match-version |
Version matching (
match-version above) is based which event has a
| replay event | = | new event | |-----------------+-------+-----------| | downgrade-error | match | upgrade |
[glossary-term] replay event
The replay event is the next event to be read from
REPLAY-JOURNALwhich is not to be skipped. There may be no replay event if there are no more unread events in the replay journal.
Events from the replay journal are read when they are
:UPGRADEd (see The replay strategy), when nested events are echoed while Replaying the outcome, or when there is an Invoked defined with the same name as the replay event.
The replay event is available via
9.4 Matching in-events
If the replay strategy is match, then, for in-events, the matching process continues like this:
At this point, two things might happen:
EXTERNAL-EVENTs, the corresponding replay
OUT-EVENTis looked at. If there is one, meaning that the frame finished with an expected outcome, then its outcome will be replayed (see Replaying the outcome). If the
OUT-EVENTis missing, then
EXTERNAL-EVENTs behave like
VERSIONED-EVENTs, and the block is executed.
9.4.1 Replaying the outcome
The journaled block is not executed.
To keep execution and the replay journal in sync, events of frames nested in the current one are skipped over in the replay journal.
All events (including
LOG-EVENTs) skipped over are echoed to the record journal. This serves to keep a trail of what happened during the original recording. Note that functions corresponding to Invoked frames are called when their
IN-EVENTis skipped over.
The out-event corresponding to the in-event being processed is then read from the replay journal and is recorded again (to allow recording to function properly).
To be able to reproduce the outcome in the replay journal, some
assistance may be required from
If the replay event has normal return (i.e.
:VALUES), then the recorded return values (in
EVENT-OUTCOME) are returned immediately as in
(VALUES-LIST (EVENT-OUTCOME REPLAY-EVENT)). If
REPLAY-VALUESis specified, it is called instead of
VALUES-LIST. See Working with unreadable values for an example.
Similarly, if the replay event has unwound with an expected condition (has
:CONDITION), then the recorded condition (in
EVENT-OUTCOME) is signalled as IN
(ERROR (EVENT-OUTCOME REPLAY-EVENT)). If
REPLAY-CONDITIONis specified, it is called instead of
REPLAY-CONDITIONmust not return normally.
9.5 Matching out-events
If there were no Replay failures during the matching of the
IN-EVENT, and the conditions for Replaying the outcome were not
met, then the block is executed. When the outcome of the block is
OUT-EVENT is triggered and is matched to the replay
journal. The matching of out-events starts out as in
The replay strategy with checks for
If the replay strategy is insert or upgrade, then the out-event
is written to
RECORD-JOURNAL, consuming an event with a matching
name from the
REPLAY-JOURNAL in the latter case. If the strategy is
Else, the replay event is consumed and the new event is written the
Note that The replay strategy for the in-event and the out-event of
the same frame may differ if the corresponding out-event is not
REPLAY-JOURNAL, which may be the case when the recording
process failed hard without unwinding properly, or when an
unexpected outcome triggered the transition to
9.6 Replay failures
[condition] REPLAY-FAILURE SERIOUS-CONDITION
A common superclass (never signalled itself) for all kinds of mismatches between the events produced and the replay journal. Signalled only in
:REPLAYINGand only once per
WITH-JOURNALING. If a
REPLAY-FAILUREis signalled for an
EVENT, then the event will be recorded, but
RECORD-JOURNALwill transition to
JOURNALING-FAILURE, this is a serious condition because it is to be handled outside the enclosing
WITH-JOURNALING. If a
REPLAY-FAILUREwere to be handled inside the
WITH-JOURNALING, keep in mind that in
:MISMATCHED, replay always uses the insert replay strategy (see The replay strategy).
- [reader] REPLAY-FAILURE-NEW-EVENT REPLAY-FAILURE (:NEW-EVENT)
- [reader] REPLAY-FAILURE-REPLAY-EVENT REPLAY-FAILURE (:REPLAY-EVENT)
- [reader] REPLAY-FAILURE-REPLAY-JOURNAL REPLAY-FAILURE (= '(REPLAY-JOURNAL))
[condition] REPLAY-NAME-MISMATCH REPLAY-FAILURE
[condition] REPLAY-VERSION-DOWNGRADE REPLAY-FAILURE
[condition] REPLAY-ARGS-MISMATCH REPLAY-FAILURE
[condition] REPLAY-OUTCOME-MISMATCH REPLAY-FAILURE
[condition] REPLAY-UNEXPECTED-OUTCOME REPLAY-FAILURE
[condition] REPLAY-INCOMPLETE REPLAY-FAILURE
Signaled if there are unprocessed non-log events in
WITH-JOURNALINGfinishes and the body of
WITH-JOURNALINGreturned normally, which is to prevent this condition to cancel an ongoing unwinding. No restarts are provided.
This restart forces The replay strategy to be
REPLAY-OUTCOME-MISMATCH. This is intended for upgrades, and extreme care must be taken not to lose data.
9.7 Upgrades and replay
The replay mechanism is built on the assumption that the tree of
frames is the same when the code is replayed as it was when the
replay journal was originally recorded. Thus, non-deterministic
control flow poses a challenge, but non-determinism can be isolated
EXTERNAL-EVENTs. However, when the code changes, we might find
the structure of frames in previous recordings hard to accommodate.
In this case, we might decide to alter the structure, giving up some
of the safety provided by the replay mechanism. There are various
tools at our disposal to control this tradeoff between safety and
We can insert individual frames with
INSERTABLE, upgrade frames by bumping
VERSION, and filter frames with
WITH-REPLAY-FILTER. This option allows for the most consistency checks.
Or we may decide to keep the bare minimum of the replay journal around, and discard everything except for
EXTERNAL-EVENTs. This option is equivalent to
(let ((*force-insertable* t)) (with-replay-filter (:skip '((:name nil))) 42))
Rerecording the journal without replay might be another option if there are no
EXTERNAL-EVENTs to worry about.
Finally, we can rewrite the replay journal using the low-level interface (see Streamlets reference). In this case, extreme care must be taken not to corrupt the journal (and lose data) as there are no consistency checks to save us.
With that, let's see how
[macro] WITH-REPLAY-STREAMLET (VAR) &BODY BODY
REPLAY-JOURNALfor reading with
READ-POSITIONon it to the event next read by the Replay mechanism (which is never a
LOG-EVENT). The low-level Reading from streamlets api is then available to inspect the contents of the replay. It is an error if
(when (replay-journal) (with-replay-streamlet (streamlet) (peek-event streamlet))
PEEK-REPLAY-EVENTtakes into account
:MAP, and it may return
:SKIPis in effect and what events are to be skipped cannot be decided until the next in-event generated by the code.
Imagine a business process for paying an invoice. In the first version of this process, we just pay the invoice:
We have left the implementation of PAY blank. In the second version, we need to get an approval first:
(when (replayed (get-approval) (= (random 2) 0)) (replayed (pay)))
Replaying a journal produced by the first version of the code with the second version would run into difficulties because inserting
EXTERNAL-EVENTs is tricky.
We have to first decide how to handle the lack of approval in the first version. Here, we just assume the processes started by the first version get approval automatically. The implementation is based on a dummy
PROCESSblock whose version is bumped when the payment process changes and is inspected at the start of journaling.
When v1 is replayed with v2, we introduce an
GET-APPROVALblock that just returns
T. When replaying the code again, still with v2, the
GET-APPROVALblock will be upgraded to
(let ((bundle (make-in-memory-bundle))) ;; First version of the payment process. Just pay. (with-bundle (bundle) (checked (process :version 1)) (replayed (pay))) ;; Second version of the payment process. Only pay if approved. (loop repeat 2 do (with-bundle (bundle) (let ((replay-process-event (peek-replay-event))) (checked (process :version 2)) (when (if (and replay-process-event (< (event-version replay-process-event) 2)) ;; This will be upgraded to :INFINITY the second ;; time around the LOOP. (checked (get-approval :insertable t) t) (replayed (get-approval) (= (random 2) 0))) (replayed (pay)))))))
[macro] WITH-REPLAY-FILTER (&KEY MAP SKIP NO-REPLAY-OUTCOME) &BODY BODY
WITH-REPLAY-FILTERperforms journal upgrade during replay by allowing events to be transformed as they are read from the replay journal or skipped if they match some patterns. For how to add new blocks in a code upgrade, see
:INSERTABLEargument. In addition, it also allows some control over Replaying the outcome.
MAP: A function called with an event read from the replay journal which returns a transformed event. See Events reference.
MAPtakes effect before before
SKIP: In addition to filtering out
LOG-EVENTs (which always happens during replay), filter out all events that belong to descendant frames that match any of its
SKIPpatterns. Filtered out events are never seen by
JOURNALEDas it replays events.
SKIPpatterns are of the format
(&KEY NAME VERSION<), where
VERSION<is a valid
NIL, which acts as a wildcard.
SKIPis for when
JOURNALEDblocks are removed from the code, which would render replaying previously recorded journals impossible. Note that, for reasons of safety, it is not possible to filter
WITH-REPLAY-FILTERaffects only the immediately enclosing
WITH-REPLAY-FILTERnested within another in the same
SKIPpatterns of its parent, to which it adds its own. The
MAPfunction is applied to before the parent's
;; Match events with name FOO and version 1, 2, 3 or 4 (:name foo :version< 5) ;; Match events with name BAR and any version (:name bar :version< :infinity) ;; Same as the previous (:name bar) ;; Match all names (:name nil) ;; Same as the previous ()
Skipping can be thought of as removing nodes of the tree of frames, connecting its children to its parent. The following example removes frames
J1frame from within
J3, and the third
(let ((journal (make-in-memory-journal))) ;; Record trees J1 -> J2 -> J3 -> J1, and J1. (with-journaling (:record journal) (checked (j1) (checked (j2) (checked (j3) (checked (j1) 42)))) (checked (j1) 7)) ;; Filter out all occurrences of VERSIONED-EVENTs named J1 and ;; J2 from the replay, leaving only J3 to match. (with-journaling (:replay journal :record t :replay-eoj-error-p t) (with-replay-filter (:skip '((:name j1) (:name j2))) (checked (j3) 42))))
Having discussed the Replay mechanism, next are Testing and Persistence, which rely heavily on replay. Suppose we want to unit test user registration. Unfortunately, the code communicates with a database service and also takes input from the user. A natural solution is to create mocks for these external systems to unshackle the test from the cumbersome database dependency and to allow it to run without user interaction.
(defparameter *db* (make-hash-table)) (defun set-key (key value) (replayed ("set-key" :args `(,key ,value)) (format t "Updating db~%") (setf (gethash key *db*) value) nil)) (defun get-key (key) (replayed ("get-key" :args `(,key)) (format t "Query db~%") (gethash key *db*))) (defun ask-username () (replayed ("ask-username") (format t "Please type your username: ") (read-line))) (defun maybe-win-the-grand-prize () (checked ("maybe-win-the-grand-prize") (when (= 1000000 (hash-table-count *db*)) (format t "You are the lucky one!")))) (defun register-user (username) (unless (get-key username) (set-key username `(:user-object :username ,username)) (maybe-win-the-grand-prize)))
Now we write a test that records these interactions in a file when it's run for the first time.
(define-file-bundle-test (test-user-registration :directory (asdf:system-relative-pathname :journal "test/registration/")) (let ((username (ask-username))) (register-user username) (assert (get-key username)) (register-user username) (assert (get-key username)))) ;; Original recording: everything is executed JRN> (test-user-registration) Please type your username: joe Query db Updating db Query db Query db Query db => NIL
On reruns, none of the external stuff is executed. The return values
of the external
JOURNALED blocks are replayed from the journal:
;; Replay: all external interactions are mocked. JRN> (test-user-registration) => NIL
Should the code change, we might want to upgrade carefully (see Upgrades and replay) or just rerecord from scratch:
JRN> (test-user-registration :rerecord t) Please type your username: joe Query db Updating db Query db Query db Query db => NIL
Thus satisfied that our test runs, we can commit the journal file in the bundle into version control. Its contents are:
(:IN "ask-username" :VERSION :INFINITY) (:OUT "ask-username" :VERSION :INFINITY :VALUES ("joe" NIL)) (:IN "get-key" :VERSION :INFINITY :ARGS ("joe")) (:OUT "get-key" :VERSION :INFINITY :VALUES (NIL NIL)) (:IN "set-key" :VERSION :INFINITY :ARGS ("joe" (:USER-OBJECT :USERNAME "joe"))) (:OUT "set-key" :VERSION :INFINITY :VALUES (NIL)) (:IN "maybe-win-the-grand-prize" :VERSION 1) (:OUT "maybe-win-the-grand-prize" :VERSION 1 :VALUES (NIL)) (:IN "get-key" :VERSION :INFINITY :ARGS ("joe")) (:OUT "get-key" :VERSION :INFINITY :VALUES ((:USER-OBJECT :USERNAME "joe") T)) (:IN "get-key" :VERSION :INFINITY :ARGS ("joe")) (:OUT "get-key" :VERSION :INFINITY :VALUES ((:USER-OBJECT :USERNAME "joe") T)) (:IN "get-key" :VERSION :INFINITY :ARGS ("joe")) (:OUT "get-key" :VERSION :INFINITY :VALUES ((:USER-OBJECT :USERNAME "joe") T))
Note that when this journal is replayed, new
required to match the replay. So after the original recording, we
can check by eyeballing that the record represents a correct
execution. Then on subsequent replays, even though
MAYBE-WIN-THE-GRAND-PRIZE sits behind
REGISTER-USER and is hard
to test with
ASSERTs, the replay mechanism verifies that it is
called only for new users.
This record-and-replay style of testing is not the only possibility: direct inspection of a journal with the low-level events api (see Events reference) can facilitate checking non-local invariants.
[macro] DEFINE-FILE-BUNDLE-TEST (NAME &KEY DIRECTORY (EQUIVALENTP T)) &BODY BODY
Define a function with
NAMEfor record-and-replay testing. The function's
BODYis executed in a
WITH-BUNDLEto guarantee replayability. The bundle in question is a
DIRECTORY. The function has a single keyword argument,
RERECORDis true, the bundle is deleted with
DELETE-FILE-BUNDLEto start afresh.
BODYreturns normally, and it is a replay of a previous run, and
EQUIVALENTP, then it is ASSERTed that the record and replay journals are
EQUIVALENT-REPLAY-JOURNALS-P. If this check fails,
RECORD-JOURNALis discarded when the function returns. In addition to the replay consistency, this checks that no inserts or upgrades were performed (see The replay strategy).
10.1 Testing on multiple levels
REPLAYEDs (that is, frames of
EXTERNAL-EVENTs) is not
obviously useful since the outer
REPLAYED will be replayed by
outcome, and the inner one will be just echoed to the record
journal. However, if we turn off Replaying the outcome for the
outer, the inner will be replayed.
This is useful for testing layered communication. For example, we
might have written code that takes input from an external
READ-LINE) and does some complicated
READ-FROM-STRING) before returning the input in a form
suitable for further processing. Suppose we wrap
READ-FROM-STRING for Persistence because putting it around
READ-LINE would expose low-level protocol details in the journal,
making protocol changes difficult.
However, upon realizing that
READ-FROM-STRING was not the best tool
for the job and switching to
PARSE-INTEGER, we want to test by
replaying all previously recorded journals. For this, we prevent the
REPLAYED from being replayed by outcome with
(let ((bundle (make-in-memory-bundle))) ;; Original with READ-FROM-STRING (with-bundle (bundle) (replayed ("accept-number") (values (read-from-string (replayed ("input-number") (read-line)))))) ;; Switch to PARSE-INTEGER and test by replay. (with-bundle (bundle) (with-replay-filter (:no-replay-outcome '("accept-number")) (replayed ("accept-number") ;; 1+ is our bug. (values (1+ (parse-integer (replayed ("input-number") (read-line)))))))))
input-number block is replayed by outcome, and
PARSE-INTEGER is called with the string
READ-LINE returned in the
original invocation. The outcome of the outer
checked as if it was a
VERSIONED-EVENT and we get a
REPLAY-OUTCOME-MISMATCH due to the bug.
11.1 Persistence tutorial
Let's write a simple game.
(defun play-guess-my-number () (let ((my-number (replayed (think-of-a-number) (random 10)))) (format t "~%I thought of a number.~%") (loop for i upfrom 0 do (write-line "Guess my number:") (let ((guess (replayed (read-guess) (values (parse-integer (read-line)))))) (format t "You guessed ~D.~%" guess) (when (= guess my-number) (checked (game-won :args `(,(1+ i)))) (format t "You guessed it in ~D tries!" (1+ i)) (return)))))) (defparameter *the-evergreen-game* (make-in-memory-bundle))
Unfortunately, the implementation is lacking in the input validation
department. In the transcript below,
PARSE-INTEGER fails with
junk in string when the user enters
not a number:
CL-USER> (handler-case (with-bundle (*the-evergreen-game*) (play-guess-my-number)) (error (e) (format t "Oops. ~A~%" e))) I thought of a number. Guess my number: 7 ; real user input You guessed 7. Guess my number: not a number ; real user input Oops. junk in string "not a number"
Replay and extension
CL-USER> (with-bundle (*the-evergreen-game*) (play-guess-my-number)) I thought of a number. Guess my number: You guessed 7. Guess my number: ; New recording starts here 5 ; real user input You guessed 5. Guess my number: 4 ; real user input You guessed 4. Guess my number: 2 ; real user input You guessed 2. You guessed it in 4 tries!
We can now replay this game many times without any user interaction:
CL-USER> (with-bundle (*the-evergreen-game*) (play-guess-my-number)) I thought of a number. Guess my number: You guessed 7. Guess my number: You guessed 5. Guess my number: You guessed 4. Guess my number: You guessed 2. You guessed it in 4 tries!
The generated events
This simple mechanism allows us to isolate external interactions and write tests in record-and-replay style based on the events produced:
CL-USER> (list-events *the-evergreen-game*) ((:IN THINK-OF-A-NUMBER :VERSION :INFINITY) (:OUT THINK-OF-A-NUMBER :VERSION :INFINITY :VALUES (2)) (:IN READ-GUESS :VERSION :INFINITY) (:OUT READ-GUESS :VERSION :INFINITY :VALUES (7)) (:IN READ-GUESS :VERSION :INFINITY :ARGS NIL) (:OUT READ-GUESS :VERSION :INFINITY :VALUES (5)) (:IN READ-GUESS :VERSION :INFINITY :ARGS NIL) (:OUT READ-GUESS :VERSION :INFINITY :VALUES (4)) (:IN READ-GUESS :VERSION :INFINITY :ARGS NIL) (:OUT READ-GUESS :VERSION :INFINITY :VALUES (2)) (:IN GAME-WON :VERSION 1 :ARGS (4)) (:OUT GAME-WON :VERSION 1 :VALUES (NIL)))
In fact, being able to replay this game at all already checks it
GAME-WON event that the number of tries calculation is
In addition, thus being able to reconstruct the internal state of
the program gives us persistence by replay. If instead of a
IN-MEMORY-BUNDLE, we used a
FILE-BUNDLE, the game would have been
saved on disk without having to write any code for saving and
loading the game state.
Persistence by replay, also known as Event Sourcing, is appropriate when the external interactions are well-defined and stable. Storing events shines in comparison to persisting state when the control flow is too complicated to be interrupted and resumed easily. Resuming execution in deeply nested function calls is fraught with such peril that it is often easier to flatten the program into a state machine, which is as pleasant as manually managing continuations.
In contrast, the Journal library does not favour certain styles of
control flow, and only requires that non-determinism is packaged up
REPLAYED, which allows it to reconstruct the state of the program
from the recorded events at any point during its execution and
resume from there.
11.2 Synchronization to storage
In the following, we explore how journals can serve as a
persistence mechanism and the guarantees they offer. The high-level
summary is that journals with
SYNC can serve as a durable and
consistent storage medium. The other two
ACID properties, atomicity and
isolation, do not apply because Journal is single-client and does
not need transactions.
[glossary-term] aborted execution
Aborted execution is when the operating system or the application crashes, calls
abort(), is killed by a
SIGKILLsignal or there is a power outage. Synchronization guarantees are defined in face of aborted execution and do not apply to hardware errors, Lisp or OS bugs.
[glossary-term] data event
Data events are the only events that may be non-deterministic. They record information which could change if the same code were run multiple times. Data events typically correspond to interactions with the user, servers or even the random number generator. Due to their non-determinism, they are the only parts of the journal not reproducible by rerunning the code. In this sense, only data events are not redundant with the code and whether other events are persisted does not affect durability. There are two kinds of data events:
11.2.1 Synchronization strategies
When a journal or bundle is created (see
SYNC option determines when - as a
RECORD-JOURNAL - the recorded
JOURNAL-STATE changes are persisted durably. For
FILE-JOURNALs, persisting means calling something like
IN-MEMORY-JOURNALs, a user defined function is called to
persist the data.
NIL: Never synchronize. A
FILE-JOURNAL's file may be corrupted on aborted execution. In
SYNC-FNis never called.
T: This is the no data loss setting with minimal synchronization. It guarantees consistency (i.e. no corruption) and durability up to the most recent data event written in
:RECORDINGor for the entire record journal in states
:COMPLETEDis guaranteed when leaving
WITH-JOURNALINGat the latest.
Values other than
Tare reserved for future extensions. Using them triggers a
11.2.2 Synchronization with in-memory journals
IN-MEMORY-JOURNALs do not have any built-in
persistent storage backing them, but with
SYNC-FN, persistence can
be tacked on. If non-NIL,
SYNC-FN must be a function of a single
SYNC-FN is called according to
Synchronization strategies, and upon normal return the journal must
be stored durably.
The following example saves the entire journal history when a new
data event is recorded. Note how
SYNC-TO-DB is careful to
*DB* only if it is called with a journal that has not
failed the replay (as in Replay failures) and is sufficiently
different from the replay journal as determined by
(defparameter *db* ()) (defun sync-to-db (journal) (when (and (member (journal-state journal) '(:recording :logging :completed)) (journal-divergent-p journal)) (setq *db* (journal-events journal)) (format t "Saved ~S~%New events from position ~S~%" *db* (journal-previous-sync-position journal)))) (defun make-db-backed-record-journal () (make-in-memory-journal :sync-fn 'sync-to-db)) (defun make-db-backed-replay-journal () (make-in-memory-journal :events *db*)) (with-journaling (:record (make-db-backed-record-journal) :replay (make-db-backed-replay-journal)) (replayed (a) 2) (ignore-errors (replayed (b) (error "Whoops")))) .. Saved #((:IN A :VERSION :INFINITY) .. (:OUT A :VERSION :INFINITY :VALUES (2))) .. New events from position 0 .. Saved #((:IN A :VERSION :INFINITY) .. (:OUT A :VERSION :INFINITY :VALUES (2)) .. (:IN B :VERSION :INFINITY) .. (:OUT B :ERROR ("SIMPLE-ERROR" "Whoops"))) .. New events from position 2 ..
In a real application, external events often involve unreliable or
high-latency communication. In the above example, block
an error, say, to simulate some kind of network condition. Now a new
journal for replay is created and initialized with the saved
events and the whole process is restarted.
(defun run-with-db () (with-journaling (:record (make-db-backed-record-journal) :replay (make-db-backed-replay-journal)) (replayed (a) (format t "A~%") 2) (replayed (b) (format t "B~%") 3))) (run-with-db) .. B .. Saved #((:IN A :VERSION :INFINITY) .. (:OUT A :VERSION :INFINITY :VALUES (2)) .. (:IN B :VERSION :INFINITY) .. (:OUT B :VERSION :INFINITY :VALUES (3))) .. New events from position 0 .. => 3
Note that on the rerun, block
A is not executed because external
events are replayed simply by reproducing their outcome, in this
case returning 2. See Replaying the outcome. Block
B, on the
other hand, was rerun because it had an unexpected outcome the first
time around. This time it ran without error, a data event was
If we were to invoke the now completed
RUN-WITH-DB again, it would
simply return 3 without ever invoking
(run-with-db) => 3
SYNC-FN can be optimized to to reuse
the sequence of events in the replay journal up until the point of
11.2.3 Synchronization with file journals
SYNC determines when the events written to the
RECORD-JOURNAL and its
JOURNAL-STATE will be persisted durably in
the file. Syncing to the file involves two calls to
is not cheap.
Syncing events to files is implemented as follows.
When the journal file is created, its parent directory is immediately fsynced to make sure that the file will not be lost on aborted execution.
When an event is about to be written the first time after file creation or after a sync, a transaction start marker is written to the file.
Any number of events may be subsequently written until syncing is deemed necessary (see Synchronization strategies).
At this point,
fsync()is called to flush all event data and state changes to the file, and the transaction start marker is overwritten with a transaction completed marker and another
When reading back this file (e.g. for replay), an open transaction marker is treated as the end of file.
Note that this implementation assumes that after writing the start
transaction marker a crash cannot leave any kind of garbage bytes
around: it must leave zeros. This is not true for all filesytems.
For example, ext3/ext4 with
data=writeback can leave garbage
Changes to journals come in two varieties: adding an event and
JOURNAL-STATE. Both are performed by
unless the low-level streamlet interface is used (see
Streamlets reference). Using
JOURNALED wrapped in a
WITH-BUNDLE, or Log record without
Every journal is guaranteed to have at most a single writer active at any time. Writers are
WITH-BUNDLE, but also any journals used as
LOG-RECORD(unless that journal is the
RECORD-JOURNAL) have a log writer stored in the journal object.
WITH-BUNDLEhave dynamic extent as writers, but log writers of journals have indefinite extent: once a journal is used as a
LOG-RECORDthere remains a writer.
Attempting to create a second writer triggers a
Writing to the same journal via
LOG-RECORDfrom multiple threads concurrently is possible since this doesn't create multiple writers. It is ensured with locking that events are written atomically. Frames can be interleaved, but these are
LOG-EVENTs, so this does not affect replay.
The juggling of replay and record journals performed by
WITH-BUNDLEis also thread-safe.
It is ensured that there is at most one
FILE-JOURNALobject in the same Lisp image is backed by the same file.
Similarly, there is at most
FILE-BUNDLEobject for a directory.
Currently, there is no protection against multiple OS processes
writing the same
Journal is designed to be async-unwind safe, but not reentrant.
Interrupts are disabled only for the most critical cleanup forms. If
a thread is killed without unwinding, that constitutes
aborted execution, so guarantees about Synchronization to storage apply, but
JOURNAL objects written by the thread are not safe to access, and
the Lisp should probably be restarted.
13 Events reference
Events are normally triggered upon entering and leaving the
dynamic extent of a
JOURNALED block (see In-events and
Out-events) and also by
LOGGED. Apart from being part of the
low-level substrate of the Journal library, working with events
directly is sometimes useful when writing tests that inspect
recorded events. Otherwise, skip this entire section.
1), which feature
prominently in The replay strategy. After the examples in
In-events and Out-events, the following example is a reminder of
how events look in the simplest case.
(with-journaling (:record t) (journaled (foo :version 1 :args '(1 2)) (+ 1 2)) (logged () "Oops") (list-events)) => ((:IN FOO :VERSION 1 :ARGS (1 2)) (:OUT FOO :VERSION 1 :VALUES (3)) (:LEAF "Oops"))
[function] EVENT= EVENT-1 EVENT-2
EVENT-2represent the same event. In- and out-events belonging to the same frame are not the same event.
EVENT-OUTCOMEis not compared when
:ERRORto avoid undue dependence on implementation specific string representations. This function is useful in conjunction with
MAKE-OUT-EVENTto write tests.
[function] EVENT-NAME EVENT
The name of an event can be of any type. It is often a symbol or a string. When replaying, names may be compared with
EVENTs have names. The names of the in- and out-events belonging to the same frame are the same.
13.1 Event versions
[function] EVENT-VERSION EVENT
Return the version of
[function] LOG-EVENT-P EVENT
[function] VERSIONED-EVENT-P EVENT
[function] EXTERNAL-EVENT-P EVENT
[function] IN-EVENT-P EVENT
[function] MAKE-IN-EVENT &KEY NAME VERSION ARGS
[function] EVENT-ARGS IN-EVENT
Return the arguments of
IN-EVENT, normally populated with the
OUT-EVENTs are triggered upon leaving the dynamic extent of the
EVENT-OUTCOME. See Out-events for a more introductory treatment.
[function] OUT-EVENT-P EVENT
[function] MAKE-OUT-EVENT &KEY NAME VERSION EXIT OUTCOME
[function] EVENT-EXIT OUT-EVENT
[function] EXPECTED-OUTCOME-P OUT-EVENT
OUT-EVENThas an expected outcome.
[function] UNEXPECTED-OUTCOME-P OUT-EVENT
OUT-EVENThas an unexpected outcome.
[function] EVENT-OUTCOME OUT-EVENT
Leaf events are triggered by
OUT-EVENTs, which represent a frame, leaf events stand alone and thus cannot have children. They are also the poorest of their kind: they only have an
NIL, which makes them
[function] LEAF-EVENT-P EVENT
[function] MAKE-LEAF-EVENT NAME
14 Journals reference
In Basics, we covered the bare minimum needed to work with journals. Here we go into the details.
A journal is, conceptually, a sequence of events.
JOURNALis an abstract base class. In case of
FILE-JOURNALs, the events are stored in a file, while for
IN-MEMORY-JOURNALs, they are in a Lisp array. When a journal is opened, it is possible to perform I/O on it (see Streamlets reference), which is normally taken care of by
WITH-JOURNALING. For this reason, the user's involvement with journals normally only consists of creating and using them in
[reader] JOURNAL-STATE JOURNAL (:STATE)
[reader] JOURNAL-SYNC JOURNAL (:SYNC = NIL)
SYNCargument specified at instantiation. See Synchronization strategies.
[function] SYNC-JOURNAL &OPTIONAL (JOURNAL (RECORD-JOURNAL))
Durably persist all preceding writes made to
JOURNALduring an enclosing
LOG-RECORDfrom any thread. Writes made in a
WITH-JOURNALINGin another thread are not persisted. The changes in question are
WRITE-EVENTcalls and state changes. This is a noop
NIL. This function is safe to call from any thread.
[reader] JOURNAL-REPLAY-MISMATCH JOURNAL (= NIL)
JOURNAL-DIVERGENT-P, then this is a list of two elements: the
READ-POSITIONs in the
REPLAY-JOURNALof the first events that were different (ignoring
LOG-EVENTs). It is
[function] JOURNAL-DIVERGENT-P JOURNAL
WITH-JOURNALINGrecorded any event so far in this journal which was not
EQUALto its replay event or it had no corresponding replay event. This completely ignores
LOG-EVENTs in both journals being compared, and is updated continuously during Replay. It plays a role in
WITH-BUNDLEdeciding when a journal is important enough to keep, and also in Synchronization with in-memory journals.
The position of the first mismatch that is available via
14.1 Comparing journals
After replay finished (i.e.
WITH-JOURNALING completed), we can ask
the question whether there were any changes produced. This is
answered in the strictest sense by
somewhat more functionally by
[generic-function] IDENTICAL-JOURNALS-P JOURNAL-1 JOURNAL-2
[generic-function] EQUIVALENT-REPLAY-JOURNALS-P JOURNAL-1 JOURNAL-2
See if two journals are equivalent when used the for
IDENTICAL-JOURNALS-P, but it ignores
LOG-EVENTs and allows events with
:ERRORto differ in their outcomes, which may very well be implementation specific, anyway. Also, it considers two groups of states as different
The rest of section is about concrete subclasses of
14.2 In-memory journals
[class] IN-MEMORY-JOURNAL JOURNAL
IN-MEMORY-JOURNALs are backed by a non-persistent, Lisp array of events. Much quicker than
FILE-JOURNALs, they are ideal for smallish journals persisted manually (see Synchronization with in-memory journals for an example).
They are also useful for writing tests based on what events were generated. They differ from
FILE-JOURNALs in that events written to
IN-MEMORY-JOURNALs are not serialized (and deserialized on replay) with the following consequences for the objects recorded by
ARGSarguments, but also the return
1) of the block, or the value returned by
[function] MAKE-IN-MEMORY-JOURNAL &KEY (EVENTS NIL EVENTSP) STATE (SYNC NIL SYNCP) SYNC-FN
(make-in-memory-journal :events '((:in foo :version 1)) :state :completed)
EVENTSargument is provided, then
:NEW, else to
SYNC-FNwill be invoked on the
SYNC-FN, else to
NIL. For a description of possible values, see Synchronization strategies. For more discussion, see Synchronization with in-memory journals.
[reader] JOURNAL-EVENTS IN-MEMORY-JOURNAL (:EVENTS)
A sequence of events in the journal. Not to be mutated by client code.
[reader] JOURNAL-PREVIOUS-SYNC-POSITION IN-MEMORY-JOURNAL (= 0)
The length of
JOURNAL-EVENTSat the time of the most recent invocation of
14.3 File journals
[class] FILE-JOURNAL JOURNAL
FILE-JOURNALis a journal whose contents and
JOURNAL-STATEare persisted in a file. This is the
JOURNALsubclass with out-of-the-box persistence, but see File bundles for a more full-featured solution for repeated Replays.
Since serialization in
FILE-JOURNALs is built on top of Lisp
WRITE, everything that
JOURNALEDrecords in events (i.e. its
ARGSarguments, but also the return
1) of the block, or the value returned by
CONDITION) must be readable.
File journals are human-readable, and editable by hand with some care. When editing, the following needs to be remembered:
The first character of the file represents its
JOURNAL-STATE. It is a
:FAILED), or a
If the journal has
SYNC(see Synchronization strategies), then in between events, there may be
CHAR-CODE127 and 6).
#\Delmarks the end of the journal contents which may be read back: it's kind of an uncommitted-transaction marker for the events that follow it.
#\Ackcharacters, of which there may be many in the file, mark the sequence of events until the next marker of either kind as valid (or committed).
#\Ackcharacters are ignored when reading the journal.
Thus, when editing a file, don't change the first character and leave the
#\Delcharacter, if any, where it is. Also see Synchronization with file journals.
[function] MAKE-FILE-JOURNAL PATHNAME &KEY SYNC
If there is already an existing
FILE-JOURNALbacked by the same file, then that object is returned. If the existing object has different options (e.g. it has
NILhere), then a
If there is already an existing
FILE-JOURNALbacked by the same file, the
:NEW, but the file doesn't exist, then the existing object is invalidated: attempts to write will fail with
JOURNAL-ERROR. If the existing journal object is being written, then invalidation fails with a
JOURNAL-ERROR. After invalidation, a new
FILE-JOURNALobject is created.
[reader] PATHNAME-OF FILE-JOURNAL (:PATHNAME)
The pathname of the file backing the journal.
14.4 Pretty-printing journals
[class] PPRINT-JOURNAL JOURNAL
When an event is written to a
PPRINT-JOURNALit writes that event to a stream in a customizable format. They are intended for producing prettier output for Logging and Tracing, but they do not support reads so they cannot be used as a
REPLAY-JOURNAL, or in
LIST-EVENTS, for example. On the other hand, events written to
PPRINT-JOURNALs need not be readable.
[function] MAKE-PPRINT-JOURNAL &KEY (STREAM (MAKE-SYNONYM-STREAM '*STANDARD-OUTPUT*)) (PRETTY T) (PRETTIFIER 'PRETTIFY-EVENT) LOG-DECORATOR
[accessor] PPRINT-JOURNAL-STREAM PPRINT-JOURNAL (:STREAM = *STANDARD-OUTPUT*)
The stream where events are dumped. May be set any time to another
[accessor] PPRINT-JOURNAL-PRETTY PPRINT-JOURNAL (:PRETTY = T)
[accessor] PPRINT-JOURNAL-PRETTIFIER PPRINT-JOURNAL (:PRETTIFIER = 'PRETTIFY-EVENT)
15 Bundles reference
BUNDLEconsists of a sequence of journals which are all reruns of the same code, hopefully making more and more progress towards completion. These journals are Replays of the previous successful one, extending it with new events. Upon replay (see
WITH-BUNDLE), the latest journal in the bundle in
:COMPLETEDplays the role of the replay journal, and a new journal is added to the bundle for recording. If the replay succeeds, this new journal eventually becomes
:COMPLETEDand takes over the role of the replay journal for future replays until another replay succeeds. When the bundle is created and it has no journals yet, the replay journal is an empty, completed one.
[accessor] MAX-N-FAILED BUNDLE (:MAX-N-FAILED = 1)
MAX-N-FAILEDis non-NIL, and the number of journals of
:FAILEDin the bundle exceeds its value, then some journals (starting with the oldest) are deleted.
[accessor] MAX-N-COMPLETED BUNDLE (:MAX-N-COMPLETED = 1)
MAX-N-COMPLETEDis non-NIL, and the number of journals of
:COMPLETEDin the bundle exceeds its value, then some journals (starting with the oldest) are deleted.
15.1 In-memory bundles
[class] IN-MEMORY-BUNDLE BUNDLE
BUNDLEthat is built on
IN-MEMORY-BUNDLEs have limited utility as a persistence mechanism and are provided mainly for reasons of symmetry and for testing. See Synchronization with in-memory journals for an example of how to achieve persistence without bundles.
[function] MAKE-IN-MEMORY-BUNDLE &KEY (MAX-N-FAILED 1) (MAX-N-COMPLETED 1) SYNC SYNC-FN
15.2 File bundles
[class] FILE-BUNDLE BUNDLE
[reader] DIRECTORY-OF FILE-BUNDLE (:DIRECTORY)
[function] MAKE-FILE-BUNDLE DIRECTORY &KEY (MAX-N-FAILED 1) (MAX-N-COMPLETED 1) SYNC
If there is already a
FILE-BUNDLEwith the same directory (according to
TRUENAME), return that object is returned if it has the same
[function] DELETE-FILE-BUNDLE DIRECTORY
Delete all journal files (
DIRECTORY. Delete the directory if empty after the journal files were deleted, else signal an error. Existing
FILE-BUNDLEobjects are not updated, so
MAKE-FILE-JOURNALwith FORCE-RELOAD may be required.
16 Streamlets reference
16.1 Opening and closing
[reader] JOURNAL STREAMLET (:JOURNAL)
JOURNALthat was passed to
OPEN-STREAMLET. This is the journal
[generic-function] OPEN-STREAMLET JOURNAL &KEY DIRECTION
[generic-function] CLOSE-STREAMLET STREAMLET
STREAMLET, which was returned by
OPEN-STREAMLET. After closing,
STREAMLETmay not longer be used for IO.
[generic-function] MAKE-STREAMLET-FINALIZER STREAMLET
NILor a function of no arguments suitable as a finalizer for
STREAMLET. That is, the function closes
STREAMLET, but holds no reference to it. This is intended for streamlets which are not dynamic-extent, so using
WITH-OPEN-JOURNALis not appropriate.
[generic-function] OPEN-STREAMLET-P STREAMLET
Return true if
STREAMLETs are open until they have been explicitly closed with
[function] INPUT-STREAMLET-P STREAMLET
STREAMLETwas opened for input (the
[function] OUTPUT-STREAMLET-P STREAMLET
STREAMLETwas opened for input (the
[macro] WITH-OPEN-JOURNAL (VAR JOURNAL &KEY (DIRECTION :INPUT)) &BODY BODY
This is like
WITH-OPEN-FILE. Open the journal designated by
DIRECTIONalong, and bind
VARto the resulting
VARis bound to
NILand no streamlet is created.
[condition] STREAMLET-ERROR ERROR
16.2 Reading from streamlets
[generic-function] READ-EVENT STREAMLET &OPTIONAL EOJ-ERROR-P
Read the event at the current read position from
STREAMLETand move the read position to the event after. If there are no more events, signal
[generic-function] READ-POSITION STREAMLET
[generic-function] SET-READ-POSITION STREAMLET POSITION
Set the read position of
POSITION, which must have been acquired from
[macro] SAVE-EXCURSION (STREAMLET) &BODY BODY
BODY, and make sure to restore the saved read position.
[generic-function] PEEK-EVENT STREAMLET
Read the next event from
STREAMLETwithout changing the read position, or return
NILif there is no event to be read.
[method] PEEK-EVENT (STREAMLET STREAMLET)
16.3 Writing to streamlets
[generic-function] WRITE-EVENT EVENT STREAMLET
STREAMLET. Writing always happens at the end of
STREAMLET's journal regardless of the
READ-POSITIONand the read position is not changed. Signals
[method] WRITE-EVENT EVENT (JOURNAL JOURNAL)
For convenience, it is possible to write directly to a
JOURNAL, in which case the journal's internal output streamlet is used. This internal streamlet is opened for
:OUTPUTand may be used by
[generic-function] WRITE-POSITION STREAMLET
Return an integer that identifies the position of the next event to be written to
[generic-function] REQUEST-COMPLETED-ON-ABORT STREAMLET
Make it so that upon aborted execution
JOURNALwill be in
:COMPLETEDwhen loaded fresh (e.g.
FILE-JOURNALfrom a file). Any previously written events must be persisted before making this change. Before
REQUEST-COMPLETED-ON-ABORTis called, a journal must be reloaded in state
It is permissible to defer carrying out this request until the next
SYNC-STREAMLETcall. If the request was carried out, return true. If it was deferred, return
[generic-function] SYNC-STREAMLET STREAMLET
If an asynchronous event, say a
C-c, is delivered to a thread running Lisp or foreign code called from Lisp, a Lisp condition is typically signalled. If the handler for this condition unwinds the stack, then we have an asynchronous unwind. Another example is
BT:INTERRUPT-THREADwhich, as it can execute arbitrary code, may unwind the stack in the target thread.
[glossary-term] boolean-valued symbol
A solution is to have streams look up their own print-pretty flag with
(SYMBOL-VALUE (STREAM-PRETTY-PRINT STREAM))and have the caller specify the dynamic variable they want:
(defvar *print-pretty-1* nil) (setf (stream-print-pretty stream-1) '*print-pretty-1*) (let ((*print-pretty-1* t)) (spaghetti stream-1 stream-2))
Note that if the default
'*PRINT-PRETTY*, then we have the normal Common Lisp behaviour. Setting
Talso works, because they are self-evaluating.
[glossary-term] non-local exit
This is a term from the Common Lisp ANSI standard. If a form does not return normally, but control is transferred via
THROW, then it is said to have performed a non-local exit. This definition of a non-local exit includes
In Common Lisp, readable objects are those that can be printed readably. Anything written to stream-based journals needs to be readable.