journal
2022-04-01
A library for logging, tracing, testing and persistence.
# Journal manual
###### \[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 <mega@retes.hu>
- Homepage: [http://github.com/melisgl/journal](http://github.com/melisgl/journal)
- Bug tracker: [http://github.com/melisgl/journal/issues](http://github.com/melisgl/journal/issues)
- Source control: [GIT](https://github.com/melisgl/journal.git)
## Links
Here is the [official repository](https://github.com/melisgl/journal)
and the [HTML
documentation](http://melisgl.github.io/mgl-pax-world/journal-manual.html)
for the latest version.
## Portability
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
runtime error.
## Background
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][mock-object]
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][journaling-fs] or [Event
Sourcing][event-sourcing].
[mock-object]: https://en.wikipedia.org/wiki/Mock_object
[journaling-fs]: https://en.wikipedia.org/wiki/Journaling_file_system
[event-sourcing]: https://martinfowler.com/eaaDev/EventSourcing.html
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
Lisp-like pseudocode:
```
(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.
## 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.
##### Compared to CL:TRACE
- 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
- Record-and-replay testing
```
(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.
## Basics
The 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
by WITH-JOURNALING or by WITH-BUNDLE.
The @JOURNALS-REFERENCE is presented later, but for most purposes
creating them (e.g. with MAKE-IN-MEMORY-JOURNAL, MAKE-FILE-JOURNAL)
and maybe querying their contents with LIST-EVENTS will suffice.
Some common cases of journal creation are handled by the convenience
function TO-JOURNAL.
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 DESIGNATOR or
signal an error. The default implementation:
- returns DESIGNATOR itself if it is of type JOURNAL,
- returns a new IN-MEMORY-JOURNAL if DESIGNATOR is T,
- returns a new FILE-JOURNAL if DESIGNATOR is a PATHNAME.
- [macro] WITH-JOURNALING (&KEY RECORD REPLAY REPLAY-EOJ-ERROR-P) &BODY BODY
Turn recording and/or replaying of events on or off for the
duration of BODY. Both RECORD and REPLAY should be a JOURNAL
designator (in the sense of TO-JOURNAL) or NIL.
If RECORD designates a JOURNAL, then events generated by enclosed
JOURNALED @BLOCKs are written to that journal (with exceptions, see
the LOG-RECORD argument of JOURNALED). If REPLAY designates a
JOURNAL, then the generated events are matched against events from
that journal according to the rules of @REPLAY.
A JOURNAL-ERROR is signalled, if RECORD is a JOURNAL that has been
previously recorded to by another WITH-JOURNALING (that is, if its
JOURNAL-STATE is not :NEW), or if REPLAY is a JOURNAL that is not a
complete recording of successful replay (i.e. its JOURNAL-STATE is
not :COMPLETED). These checks are intended to catch mistakes that
would render the new or existing records unusable for replay. When
WITH-JOURNALING finishes, the RECORD journal is marked :COMPLETED or
:FAILED in its JOURNAL-STATE.
REPLAY-EOJ-ERROR-P controls whether an END-OF-JOURNAL is 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 JOURNALING-FAILURE
or a REPLAY-FAILURE during execution, then END-OF-JOURNAL is not
signalled.
If BODY completes successfully, but REPLAY has unprocessed events,
then signal REPLAY-INCOMPLETE.
WITH-JOURNALING for different RECORD journals can be nested and run
independently.
- [glossary-term] block
A journaled block, or simply block, is a number of forms wrapped in
JOURNALED. When a block is executed, a @FRAME is created.
- [glossary-term] frame
A frame is an IN-EVENT, OUT-EVENT pair, which are created when a
@BLOCK is entered and left, respectively.
- [function] RECORD-JOURNAL
Return the journal in which events are currently being
recorded (see WITH-JOURNALING and WITH-BUNDLE) or NIL.
- [function] REPLAY-JOURNAL
Return the journal from which events are currently being
replayed (see WITH-JOURNALING and WITH-BUNDLE) or NIL.
- [macro] JOURNALED (NAME &KEY (LOG-RECORD :RECORD) VERSION ARGS VALUES CONDITION INSERTABLE REPLAY-VALUES REPLAY-CONDITION) &BODY BODY
JOURNALED generates 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,
BODY is typically executed normally (except for
@REPLAYING-THE-OUTCOME).
Where the generated events are written is determined by the :RECORD
argument of the enclosing WITH-JOURNALING. If there is no enclosing
WITH-JOURNALING and LOG-RECORD is NIL, then event recording is
turned off and JOURNALED imposes minimal overhead.
- NAME can be of any type except [NULL][type], 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.
- ARGS can be of any type, but is typically a list.
Also see in @LOG-RECORD in the @LOGGING section. For a description
of VERSION, INSERTABLE, REPLAY-VALUES and REPLAY-CONDITION, see
@JOURNALED-FOR-REPLAY.
### In-events
Upon entering a @BLOCK, JOURNALED generates an IN-EVENT,
which conceptually opens a new @FRAME. These in-events are created
from the NAME, VERSION and ARGS arguments of JOURNALED. For example,
```
(journaled (name :version version :args args) ...)
```
creates an event like this:
```
`(:in ,name :version ,version :args ,args)
```
where :VERSION and :ARGS may be omitted if they are NIL. Versions
are used for @REPLAY.
### Out-events
Upon leaving a @BLOCK, JOURNALED generates and OUT-EVENT, closing
the @FRAME opened by the corresponding in-event. These out-events
are property lists like this:
```
(:out foo :version 1 :values (42))
```
Their NAME and VERSION (`FOO` and `1` in the example) are the same
as in the in-event: they are the corresponding arguments of
JOURNALED. EXIT and OUTCOME are filled in differently depending on
how the block finished its execution.
- [type] EVENT-EXIT
One of :VALUES, :CONDITION, :ERROR and :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),
- unwound by performing a @NON-LOCAL-EXIT of some other kind such as
a throw (:NLX, see NLX-OUTCOME).
The first two are EXPECTED-OUTCOMEs, while the latter two are
UNEXPECTED-OUTCOMEs.
- [glossary-term] values outcome
If the JOURNALED @BLOCK returns normally, [EVENT-EXIT][type] is
:VALUES and the outcome is the list of values returned:
```
(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 VALUES
argument of JOURNALED, whose default is `#'IDENTITY`. Also see
@WORKING-WITH-UNREADABLE-VALUES).
- [glossary-term] condition outcome
If the @BLOCK unwound due to a condition, and JOURNALED's
CONDITION argument (a function whose default is `(CONSTANTLY NIL)`)
returns non-NIL when invoked on it, then [EVENT-EXIT][type] is
:CONDITION and 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 REPLAY-CONDITION in JOURNALED, they
may be replayed without running the @BLOCK.
- [glossary-term] error outcome
If the JOURNALED @BLOCK unwound due to a condition, but
JOURNALED's CONDITION argument returns NIL when invoked on it, then
[EVENT-EXIT][type] is :ERROR and 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 PRINC in
WITH-STANDARD-IO-SYNTAX. This scheme is intended to avoid leaking
random implementation details into the journal, which would make
`READ`ing 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
If the JOURNALED @BLOCK performed a @NON-LOCAL-EXIT that was not
due to a condition, then [EVENT-EXIT][type] is :NLX and the outcome
is NIL.
```
(catch 'xxx
(journaled (foo)
(throw 'xxx nil)))
;; generates the out-event
(:out foo :nlx nil)
```
Note that CONDITION-OUTCOMEs and ERROR-OUTCOMEs are also due to
@NON-LOCAL-EXITs, but are distinct from nlx outcomes.
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
An OUT-EVENT is said to have an expected outcome if it had a
VALUES-OUTCOME or a CONDITION-OUTCOME, or equivalently, when its
[EVENT-EXIT][type] is :VALUES or :CONDITION.
- [glossary-term] unexpected outcome
An OUT-EVENT is said to have an unexpected outcome if it had an
ERROR-OUTCOME or an NLX-OUTCOME, or equivalently, when its
[EVENT-EXIT][type] is :ERROR or :NLX.
### Working with unreadable values
The events recorded often need to be @READABLE. This is always
required with FILE-JOURNALs, often with IN-MEMORY-JOURNALs, but
never 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 VALUES
hook for this purpose.
With EXTERNAL-EVENTs, whose outcome is replayed (see
@REPLAYING-THE-OUTCOME), we also need to be able to reverse the
transformation of 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
values of `GET-MESSAGE`, the `USER` object must be transformed to
something @READABLE. On the `Recording` run, `(VALUES-> #'USER-ID)`
replaces the user object with its id in the EVENT-OUTCOME recorded,
but the original user object is returned.
When `Replaying`, the journaled OUT-EVENT is replayed (see
@REPLAYING-THE-OUTCOME):
```
(:OUT GET-MESSAGE :VERSION :INFINITY :VALUES (7 "hello"))
```
The user object is looked up according to :REPLAY-VALUES and is
returned along with `"hello"`.
- [function] VALUES-> &REST FNS
A utility to create a function suitable as the VALUES
argument of JOURNALED. The VALUES function 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)
```
Note how `#'1+` is applied only to the first element of the values
list. The list of functions is shorter than the values list, so
`:SOMETHING` is not transformed. A value can be left explicitly
untransformed by specifying #'IDENTITY or NIL as 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 REPLAY-VALUES argument of 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
```
### Utilities
- [function] LIST-EVENTS &OPTIONAL (JOURNAL (RECORD-JOURNAL))
Return a list of all the events in the journal designated by
JOURNAL. Calls SYNC-JOURNAL first, 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
PRINT-EVENTS, EVENTS may be a JOURNAL.
```
(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 CONDITION argument of JOURNALED,
which returns the type of its single argument as a string if it is
of TYPE, else NIL.
### Pretty-printing
- [function] PRINT-EVENTS EVENTS &KEY STREAM
Print EVENTS to STREAM as lists, starting a new line for each
event and indenting them according to their nesting structure.
EVENTS may be a JOURNAL, in which case LIST-EVENTS is called on it
first.
```
(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)
Like 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 PRETTIFIER argument formats individual
events. The above output was produced with PRETTIFY-EVENT. For a
description of PRETTIFIER's arguments see PRETTIFY-EVENT.
- [function] PRETTIFY-EVENT EVENT DEPTH STREAM
Write EVENT to STREAM in a somewhat human-friendly format. This
is the function PPRINT-JOURNAL, 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
```
DEPTH is the nesting level of the EVENT. Top-level events have depth
0. PRETTIFY-EVENT prints 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 @PPRINT-JOURNALS, discussed in detail later, in
the following way:
```
(let ((journal (make-pprint-journal)))
(with-journaling (:record journal)
(journaled (foo) "Hello")))
..
.. (FOO)
.. => "Hello"
```
Note that @PPRINT-JOURNALS are not tied to WITH-JOURNALING and are
most often used for @LOGGING and @TRACING.
### Error handling
- [condition] JOURNALING-FAILURE SERIOUS-CONDITION
Signalled during the dynamic extent of
WITH-JOURNALING when an error threatens to leave the journaling
mechanism in an inconsistent state. These include I/O errors
encountered reading or writing journals by WITH-JOURNALING,
JOURNALED, LOGGED, WITH-REPLAY-FILTER, SYNC-JOURNAL, but also
STORAGE-CONDITIONs, assertion failures, and errors calling
JOURNALED's VALUES and CONDITION function
arguments. Crucially, this does not apply to non-local exits from
other code, such as JOURNALED @BLOCKs, 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-FAILURE to protect the integrity of the
RECORD-JOURNAL. The condition that caused the unwinding is in
JOURNALING-FAILURE-EMBEDDED-CONDITION, or NIL if it was a pure
@NON-LOCAL-EXIT like THROW. This is a SERIOUS-CONDITION, not to be
handled within WITH-JOURNALING.
After a JOURNALING-FAILURE, the journaling mechanism cannot be
trusted anymore. The REPLAY-JOURNAL might have failed a read and be
out-of-sync. The RECORD-JOURNAL may have missing events (or even
half-written events with FILE-JOURNALs without SYNC, see
@SYNCHRONIZATION-STRATEGIES), and further writes to it would risk
replayability, which is equivalent to database corruption. Thus,
upon signalling JOURNALING-FAILURE, JOURNAL-STATE is set to
- :COMPLETED if the journal is in state :RECORDING or :LOGGING and
the transition to :RECORDING was reflected in storage,
- else it is set to :FAILED.
After a JOURNALING-FAILURE, any further attempt within the affected
WITH-JOURNALING to use the critical machinery mentioned
above (JOURNALED, 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 JOURNALING-FAILURE and REPLAY-FAILURE,
which necessitate leaving WITH-JOURNALING to recover from, the other
conditions - JOURNAL-ERROR, and STREAMLET-ERROR - are subclasses of
[ERROR][condition] as the their handling need not be so
heavy-handed.
- [reader] JOURNALING-FAILURE-EMBEDDED-CONDITION JOURNALING-FAILURE (:EMBEDDED-CONDITION)
- [condition] RECORD-UNEXPECTED-OUTCOME
Signalled (with SIGNAL: this is not an
[ERROR][condition]) by JOURNALED when a VERSIONED-EVENT or an
EXTERNAL-EVENT had an UNEXPECTED-OUTCOME while in JOURNAL-STATE
:RECORDING. Upon signalling this condition, JOURNAL-STATE is 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.
Also see REPLAY-UNEXPECTED-OUTCOME.
- [condition] DATA-EVENT-LOSSAGE JOURNALING-FAILURE
Signalled when a DATA-EVENT is about to be recorded
in JOURNAL-STATE :MISMATCHED or :LOGGING. Since the data event will
not be replayed that constitutes data loss.
- [condition] JOURNAL-ERROR ERROR
Signalled by WITH-JOURNALING, WITH-BUNDLE and by
@LOG-RECORD. It is also signalled by the low-level streamlet
interface (see @STREAMLETS-REFERENCE).
- [condition] END-OF-JOURNAL JOURNAL-ERROR
This might be signalled by the replay mechanism if
WITH-JOURNALING's REPLAY-EOJ-ERROR-P is true. Unlike
REPLAY-FAILUREs, this does not affect JOURNAL-STATE of
RECORD-JOURNAL. At a lower level, it is signalled by READ-EVENT upon
reading past the end of the JOURNAL if EOJ-ERROR-P.
## Logging
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
bound to 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 PPRINT-JOURNAL:
```
(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)))
```
##### Capturing logs in WITH-JOURNALING's RECORD-JOURNAL
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
binding `*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.")
```
Note how pretty-printing was turned off and we see the LEAF-EVENT
generated by LOGGED in its raw plist form.
##### Conditional routing
Finally, to make routing decisions conditional we need to change
`SL33P`:
```
(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
LOGGED is for single messages. JOURNALED, or in this example FRAMED,
can provide nested context:
```
(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
```
### Customizing logs
Customizing the output format is possible if we don't necessarily
expect to be able to read the logs back programmatically. There is
an example in @TRACING, which is built on @PPRINT-JOURNALS.
Here, we discuss how to make logs more informative.
- [glossary-term] decoration
JOURNAL-LOG-DECORATOR adds 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-DECORATOR for 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-DECORATOR that may add
the name of the thread, a timestamp, the internal real-time or
run-time (both in seconds) to events. THREAD, TIME, REAL-TIME and
RUN-TIME are @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")
```
### Log record
WITH-JOURNALING and 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 JOURNALED
@BLOCKs are being executed. However, LOG-EVENTs do not affect replay
so we can allow more flexibility in routing them.
The LOG-RECORD argument of JOURNALED and LOGGED controls where
LOG-EVENTs are written both within WITH-JOURNALING and without. The
algorithm to determine the target journal is this:
1. If LOG-RECORD is :RECORD, then `(RECORD-JOURNAL)` is returned.
2. If LOG-RECORD is NIL, then it is returned.
3. If LOG-RECORD is a JOURNAL, then it is returned.
4. If LOG-RECORD is symbol (other than NIL), then the SYMBOL-VALUE
of that symbol is assigned to LOG-RECORD and 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.
This is reminiscent of SYNONYM-STREAMs, also in that it is possible
end up in cycles in the resolution. For this reason, the algorithm
stop with a JOURNAL-ERROR after 100 iterations.
##### Interactions
Events may be written to LOG-RECORD even without an enclosing
WITH-JOURNALING, and it does not affect the JOURNAL-STATE. However,
it is a JOURNAL-ERROR to write to a :COMPLETED journal (see
JOURNAL-STATE).
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.
### Logging with LEAF-EVENTs
- [macro] LOGGED (&OPTIONAL (LOG-RECORD :RECORD)) FORMAT-CONTROL &REST FORMAT-ARGS
LOGGED creates a single LEAF-EVENT whose name is the string
constructed by FORMAT. For example:
```
(with-journaling (:record t)
(logged () "Hello, ~A." "world")
(list-events))
=> ((:LEAF "Hello, world."))
```
LEAF-EVENTs are LOG-EVENTs with no separate in- and out-events. They
have an EVENT-NAME and no other properties. Use LOGGED for
point-in-time textual log messages, and JOURNALED with VERSION
NIL (i.e. FRAMED) to provide context.
Also see @LOG-RECORD.
## Tracing
JTRACE behaves similarly to CL:TRACE, but deals @NON-LOCAL-EXITs
gracefully.
##### Basic tracing
```
(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"
```
##### Log-like output
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"
```
##### Profiler-like output
```
(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
achieved by `SETF`ing PPRINT-JOURNAL-PRETTIFIER,
PPRINT-JOURNAL-STREAM and JOURNAL-LOG-DECORATOR.
- [macro] JTRACE &REST NAMES
Like CL:TRACE, JTRACE takes a list of symbols. When functions
denoted by those NAMES are invoked, their names, arguments and
outcomes are printed in human readable form to *TRACE-OUTPUT*. These
values may not be @READABLE, JTRACE does not care.
The format of the output is the same as that of PPRINT-EVENTS.
Behind the scenes, JTRACE encapsulates the global functions with
NAMES in wrapper that behaves as if `FOO` in the example above was
defined like this:
```
(defun foo (x)
(framed (foo :args `(,x) :log-record *trace-journal*)
(1+ x)))
```
If JTRACE is 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, JTRACE simply sets
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 JTRACE over CL:TRACE is 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
Like CL:UNTRACE, JUNTRACE makes it so that the global functions
denoted by the symbols NAMES are no longer traced by JTRACE. When
invoked with no arguments, it untraces all traced functions.
- [variable] *TRACE-PRETTY* T
If *TRACE-PRETTY* is true, then JTRACE produces output like
PPRINT-EVENTS, else it's like PRINT-EVENTS.
- [variable] *TRACE-THREAD* NIL
Controls whether to decorate the trace with the name of the
originating thread. See MAKE-LOG-DECORATOR.
- [variable] *TRACE-TIME* NIL
Controls whether to decorate the trace with a timestamp. See
MAKE-LOG-DECORATOR.
- [variable] *TRACE-REAL-TIME* NIL
Controls whether to decorate the trace with the internal real-time.
See MAKE-LOG-DECORATOR.
- [variable] *TRACE-RUN-TIME* NIL
Controls whether to decorate the trace with the internal run-time.
See MAKE-LOG-DECORATOR.
- [variable] *TRACE-JOURNAL* #\<PPRINT-JOURNAL :NEW\>
The JOURNAL where JTRACE writes LOG-EVENTs. By default it is a
PPRINT-JOURNAL that sets up a SYNONYM-STREAM to *TRACE-OUTPUT* and
sends its output there. It pays attention to *TRACE-PRETTY*, and its
log decorator is affected by *TRACE-TIME* and *TRACE-THREAD*.
However, by changing JOURNAL-LOG-DECORATOR and
PPRINT-JOURNAL-PRETTIFIER content and output can be customized.
### Slime integration
[Slime](https://common-lisp.net/project/slime/) by default binds
`C-c C-t` to toggling CL:TRACE. To integrate JTRACE into Slime, add
the following ELisp snippet to your Emacs initialization file or
load `src/journal.el`:
```elisp
(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)
```
Since JTRACE lacks some features of CL:TRACE, most notably that of
tracing non-global functions, it is assigned a separate binding,
`C-c C-j`.
## Replay
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
kin WITH-BUNDLE). After the per-event processing described below,
when WITH-JOURNALING finishes, it might signal REPLAY-INCOMPLETE if
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 [JOURNAL-STATE][type] and
[EVENT-VERSION][type]s, which we discuss next.
- [type] JOURNAL-STATE
JOURNAL's state, with respect to replay, is updated during
WITH-JOURNALING. This possible states are:
- **: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.
- **:MISMATCHED**: There was a REPLAY-FAILURE. In this state,
VERSIONED-EVENTs generated are downgraded to LOG-EVENTs,
EXTERNAL-EVENTs and INVOKED trigger a DATA-EVENT-LOSSAGE.
- **:RECORDING**: All events from the replay journal were
successfully replayed and now new events are being recorded
without being matched to the replay journal.
- **:LOGGING**: There was a RECORD-UNEXPECTED-OUTCOME. In this
state, VERSIONED-EVENTs generated are downgraded to LOG-EVENTs,
EXTERNAL-EVENTs and INVOKED trigger a DATA-EVENT-LOSSAGE.
- **:FAILED**: The journal is to be discarded. It encountered a
JOURNALING-FAILURE or a REPLAY-FAILURE without completing the
replay and reaching :RECORDING.
- **:COMPLETED**: All events were successfully replayed and
WITH-JOURNALING finished or a JOURNALING-FAILURE occurred while
:RECORDING or :LOGGING.
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)
:NEW is the starting state. It is a JOURNAL-ERROR to attempt to
write to journals in :COMPLETED. Note that once in :RECORDING, the
only possible terminal state is :COMPLETED.
### Journaled for replay
The following arguments of JOURNALED control behaviour under replay.
- VERSION: see [EVENT-VERSION][type] below.
- INSERTABLE controls whether VERSIONED-EVENTs and 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 EXTERNAL-EVENTs while :REPLAYING
is often not meaningful (e.g. asking the user for input may lead
to a REPLAY-FAILURE). See PEEK-REPLAY-EVENT for an example on how
to properly insert these kinds of EXTERNAL-EVENTs.
- REPLAY-VALUES, a function or NIL, may be called with EVENT-OUTCOME
when replaying and :VERSION :INFINITY. NIL is equivalent to
VALUES-LIST. See `VALUES<-` for an example.
- REPLAY-CONDITION, a function or NIL, may be called with
EVENT-OUTCOME (the return value of the function provided as
:CONDITION) when replaying and :VERSION is :INFINITY. NIL is
equivalent to the ERROR function. Replaying conditions is
cumbersome and best avoided.
- [variable] *FORCE-INSERTABLE* NIL
The default value of the INSERTABLE argument of JOURNALED for
VERSIONED-EVENTs. Binding this to T allows en-masse structural
upgrades in combination with WITH-REPLAY-FILTER. Does not affect
EXTERNAL-EVENTs. See @UPGRADES-AND-REPLAY.
- [type] EVENT-VERSION
An event's version is either NIL, a positive fixnum, or :INFINITY,
which correspond to LOG-EVENTs, VERSIONED-EVENTs, and
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.
- [type] LOG-EVENT
Events with [EVENT-VERSION][type] NIL called 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 JOURNALED's LOG-RECORD argument. The convenience macro
FRAMED is creating frames of log-events, while the LOGGED generates
a log-event that's a LEAF-EVENT.
- [type] VERSIONED-EVENT
Events with a positive integer [EVENT-VERSION][type] are 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
JOURNALED's INSERTABLE.
If a VERSIONED-EVENT has an UNEXPECTED-OUTCOME,
RECORD-UNEXPECTED-OUTCOME is signalled.
- [type] EXTERNAL-EVENT
Events with [EVENT-VERSION][type] :INFINITY are 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.
If an EXTERNAL-EVENT has an UNEXPECTED-OUTCOME,
RECORD-UNEXPECTED-OUTCOME is signalled.
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
type of EVENT produced (`Event`), how @IN-EVENTS are
replayed (`In-e.`), whether the block is always run (`Run`), how
@OUT-EVENTS are replayed (`Out-e.`), whether the block must be
deterministic (`Det`) or side-effect free (`SEF`).
| | 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
A wrapper around JOURNALED to produce @FRAMEs of LOG-EVENTs. That
is, VERSION is always NIL, and some irrelevant arguments are
omitted. The related LOGGED creates a single LEAF-EVENT.
With FRAMED, BODY is always run and no REPLAY-FAILUREs are
triggered. BODY is not required to be deterministic and it may have
side-effects.
- [macro] CHECKED (NAME &KEY (VERSION 1) ARGS VALUES CONDITION INSERTABLE) &BODY BODY
A wrapper around JOURNALED to produce @FRAMEs of VERSIONED-EVENTs.
VERSION defaults to 1. CHECKED is for ensuring that supposedly
deterministic processing does not veer off the replay.
With CHECKED, 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. BODY may have side-effects.
For further discussion of determinism, see REPLAYED.
- [macro] REPLAYED (NAME &KEY ARGS VALUES CONDITION INSERTABLE REPLAY-VALUES REPLAY-CONDITION) &BODY BODY
A wrapper around JOURNALED to produce @FRAMEs of EXTERNAL-EVENTs.
VERSION is :INFINITY. REPLAYED is for primarily for marking and
isolating non-deterministic processing.
With REPLAYED, the IN-EVENT is checked for consistency with the
replay (as with CHECKED), but BODY is not run (assuming it has a
recorded EXPECTED-OUTCOME) and the outcome in the OUT-EVENT is
reproduced (see @REPLAYING-THE-OUTCOME). For this scheme to work,
REPLAYED requires its BODY to be side-effect free, but it may be
non-deterministic.
- [glossary-term] Invoked
Invoked refers to functions and blocks defined by DEFINE-INVOKED or
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.
On one hand, FRAMED, CHECKED, REPLAYED or plain JOURNALED have
@IN-EVENTS that are always predictable from the code and the
preceding events. The control flow - on the level of recorded frames
- is deterministic in this sense. On the other hand, Invoked encodes
in its IN-EVENT what function to call next, introducing
non-deterministic control flow.
By letting events choose the code to run, Invoked resembles typical
[Event Sourcing][event-sourcing] frameworks. When Invoked is used
exclusively, the journal becomes a sequence of events. In contrast,
JOURNALED and its wrappers put code first, and the journal will be a
projection of the call tree.
- [macro] DEFINE-INVOKED FUNCTION-NAME ARGS (NAME &KEY (VERSION 1) INSERTABLE) &BODY BODY
DEFINE-INVOKED is intended for recording asynchronous function
invocations like event or signal handlers. It defines a function
that records VERSIONED-EVENTs with ARGS set to the actual arguments.
At replay, it is invoked whenever the recorded IN-EVENT becomes the
REPLAY-EVENT.
DEFUN and CHECKED rolled into one, DEFINE-INVOKED defines a
top-level function with FUNCTION-NAME and ARGS (only simple
positional arguments are allowed) and wraps CHECKED with NAME, the
same ARGS and INSERTABLE around BODY. Whenever an IN-EVENT becomes
the REPLAY-EVENT and it has a DEFINE-INVOKED defined with the name
of the event, then FUNCTION-NAME is invoked with EVENT-ARGS.
While 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 REPLAYED explicitly
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
Like DEFINE-INVOKED, but with FLET instead of DEFUN. The event
name and the function are associated in the dynamic extent of BODY.
WITH-JOURNALING does not change the bindings. The example in
DEFINE-INVOKED can 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))))
```
### Bundles
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)
...)))
```
With FILE-JOURNALs, the motivating example above would be even more
complicated, but FILE-BUNDLEs work the same way as
IN-MEMORY-BUNDLEs.
- [macro] WITH-BUNDLE (BUNDLE) &BODY BODY
This is like WITH-JOURNALING where the REPLAY-JOURNAL is the last
successfully completed one in BUNDLE, and the RECORD-JOURNAL is a
new one created in BUNDLE. When WITH-BUNDLE finishes, the record
journal is in JOURNAL-STATE :FAILED or :COMPLETED.
To avoid accumulating useless data, the new record is immediately
deleted when WITH-BUNDLE finishes if it has not diverged from the
replay journal (see JOURNAL-DIVERGENT-P). Because :FAILED journals
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
IDENTICAL-JOURNALS-P).
It is a JOURNAL-ERROR to have concurrent or nested WITH-BUNDLEs on
the same bundle.
### 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 NAME and
VERSION of the new event and the REPLAY-EVENT (the next event to be
read from the replay). There are four possible strategies:
- **match**: A new in-event must match the replay event in its ARGS.
See @MATCHING-IN-EVENTS for details. A new out-event must match
the replay event's EXIT and OUTCOME, see @MATCHING-OUT-EVENTS.
- **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
REPLAY-EOJ-ERROR-P). For VERSIONED-EVENTs, it is affected by
setting JOURNALED's INSERTABLE to true (see
@JOURNALED-FOR-REPLAY).
The out-event's strategy is always *insert* if the strategy for
the corresponding in-event was *insert*.
- Also, END-OF-JOURNAL, REPLAY-NAME-MISMATCH and
REPLAY-VERSION-DOWNGRADE may be signalled. See the algorithm below
details.
The strategy is determined by the following algorithm, invoked
whenever an event is generated by a journaled @BLOCK:
1. Log events are not matched to the replay. If the new event is a
log event or a REPLAY-FAILURE has been signalled before (i.e. the
record journal's JOURNAL-STATE is :MISMATCHED), then **insert**
is returned.
2. 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:
- If REPLAY-EOJ-ERROR-P is NIL in WITH-JOURNALING (the
default), **insert** is returned.
- If REPLAY-EOJ-ERROR-P is true, then **`END-OF-JOURNAL`**
is signalled.
- **mismatched name**: Else, if the next unread replay event's
name is not EQUAL to the name of the new event, then:
- For VERSIONED-EVENTs, **REPLAY-NAME-MISMATCH** is
signalled if INSERTABLE is NIL, else **insert** is
returned.
- For EXTERNAL-EVENTs, **REPLAY-NAME-MISMATCH** is
signalled.
- **matching name**: Else, if the name of the next unread event
in the replay journal is EQUAL to 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 **REPLAY-VERSION-DOWNGRADE** is
signalled.
- If the two versions are equal, then **match** is returned.
- If the new event's version is higher, then **upgrade** is
returned.
Where :INFINITY is considered higher than any integer and
equal to itself.
In summary:
| 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
higher version:
| replay event | = | new event |
|-----------------+-------+-----------|
| downgrade-error | match | upgrade |
- [glossary-term] replay event
The replay event is the next event to be read from REPLAY-JOURNAL
which is not to be skipped. There may be no replay event if there
are no more unread events in the replay journal.
An event in the replay journal is skipped if it is a LOG-EVENT or
there is a WITH-REPLAY-FILTER with a matching :SKIP. If :SKIP is in
effect, the replay event may be indeterminate.
Events from the replay journal are read when they are `:MATCH`ed or
`:UPGRADE`d (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 PEEK-REPLAY-EVENT.
### Matching in-events
If the replay strategy is *match*, then, for in-events, the
matching process continues like this:
- If the [EVENT-ARGS][] are not EQUAL, then **`REPLAY-ARGS-MISMATCH`**
signalled.
- At this point, two things might happen:
- For VERSIONED-EVENTs, the @BLOCK will be executed as normal
and its outcome will be matched to the REPLAY-EVENT (see
@MATCHING-OUT-EVENTS).
- For EXTERNAL-EVENTs, the corresponding replay OUT-EVENT is
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-EVENT is
missing, then EXTERNAL-EVENTs behave like VERSIONED-EVENTs,
and the @BLOCK is executed.
#### Replaying the outcome
So, if an in-event is triggered that matches the replay,
EVENT-VERSION is :INFINITY, then normal execution is altered in the
following manner:
- 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-EVENT is 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 REPLAY-VALUES and REPLAY-CONDITION:
- If the REPLAY-EVENT has normal return (i.e. EVENT-EXIT :VALUES),
then the recorded return values (in EVENT-OUTCOME) are returned
immediately as in `(VALUES-LIST (EVENT-OUTCOME REPLAY-EVENT))`. If
REPLAY-VALUES is 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 EVENT-EXIT :CONDITION), then the recorded
condition (in EVENT-OUTCOME) is signalled as
IN `(ERROR (EVENT-OUTCOME REPLAY-EVENT))`. If REPLAY-CONDITION is
specified, it is called instead of ERROR. REPLAY-CONDITION must
not return normally.
WITH-REPLAY-FILTER's NO-REPLAY-OUTCOME can selectively turn off
replaying the outcome. See @TESTING-ON-MULTIPLE-LEVELS, for an
example.
### 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
determined, an 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 EVENT-NAME and
[EVENT-VERSION][function].
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
*match*, then:
- If the new event has an UNEXPECTED-OUTCOME, then
**REPLAY-UNEXPECTED-OUTCOME** is signalled. Note that the replay
event always has an EXPECTED-OUTCOME due to the handling of
RECORD-UNEXPECTED-OUTCOME.
- If the new event has an EXPECTED-OUTCOME, then unless the new and
REPLAY-EVENT's EVENT-EXITs are `EQ` and their EVENT-OUTCOMEs are
EQUAL, **REPLAY-OUTCOME-MISMATCH** is signalled.
- Else, the replay event is consumed and the new event is written
the RECORD-JOURNAL.
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
present in 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 JOURNAL-STATE
:LOGGING.
### 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 JOURNAL-STATE :REPLAYING and only once
per WITH-JOURNALING. If a REPLAY-FAILURE is signalled for an EVENT,
then the event will be recorded, but RECORD-JOURNAL will transition
to JOURNAL-STATE :MISMATCHED. Like JOURNALING-FAILURE, this is a
serious condition because it is to be handled outside the enclosing
WITH-JOURNALING. If a REPLAY-FAILURE were 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
Signaled when the new event's and REPLAY-EVENT's
EVENT-NAME are not EQUAL. The REPLAY-FORCE-INSERT,
REPLAY-FORCE-UPGRADE restarts are provided.
- [condition] REPLAY-VERSION-DOWNGRADE REPLAY-FAILURE
Signaled when the new event and the REPLAY-EVENT
have the same EVENT-NAME, but the new event has a lower version. The
REPLAY-FORCE-UPGRADE restart is provided.
- [condition] REPLAY-ARGS-MISMATCH REPLAY-FAILURE
Signaled when the new event's and REPLAY-EVENT's
EVENT-ARGS are not EQUAL. The REPLAY-FORCE-UPGRADE restart is
provided.
- [condition] REPLAY-OUTCOME-MISMATCH REPLAY-FAILURE
Signaled when the new event's and REPLAY-EVENT's
EVENT-EXIT and/or EVENT-OUTCOME are not EQUAL. The
REPLAY-FORCE-UPGRADE restart is provided.
- [condition] REPLAY-UNEXPECTED-OUTCOME REPLAY-FAILURE
Signaled when the new event has an
UNEXPECTED-OUTCOME. Note that the REPLAY-EVENT always has an
EXPECTED-OUTCOME due to the logic of RECORD-UNEXPECTED-OUTCOME. No
restarts are provided.
- [condition] REPLAY-INCOMPLETE REPLAY-FAILURE
Signaled if there are unprocessed non-log events in
REPLAY-JOURNAL when WITH-JOURNALING finishes and the body of
WITH-JOURNALING returned normally, which is to prevent this
condition to cancel an ongoing unwinding. No restarts are
provided.
- [restart] REPLAY-FORCE-INSERT
This restart forces @THE-REPLAY-STRATEGY to be :INSERT, overriding
REPLAY-NAME-MISMATCH. This is intended for upgrades, and extreme
care must be taken not to lose data.
- [restart] REPLAY-FORCE-UPGRADE
This restart forces @THE-REPLAY-STRATEGY to be :UPGRADE, overriding
REPLAY-NAME-MISMATCH, REPLAY-VERSION-DOWNGRADE,
REPLAY-ARGS-MISMATCH, REPLAY-OUTCOME-MISMATCH. This is intended for
upgrades, and extreme care must be taken not to lose data.
### 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
with 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
flexibility:
- We can insert individual frames with JOURNALED's INSERTABLE,
upgrade frames by bumping JOURNALED's VERSION, and filter frames
with WITH-REPLAY-FILTER. This option allows for the most
consistency checks.
- The REPLAY-FORCE-UPGRADE and REPLAY-FORCE-INSERT restarts allow
overriding @THE-REPLAY-STRATEGY, but their use requires great care
to be taken.
- 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 WITH-REPLAY-FILTER works.
- [macro] WITH-REPLAY-STREAMLET (VAR) &BODY BODY
Open REPLAY-JOURNAL for reading with WITH-OPEN-JOURNAL set the
READ-POSITION on 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 REPLAY-JOURNAL is NIL.
- [function] PEEK-REPLAY-EVENT
Return the REPLAY-EVENT to be read from REPLAY-JOURNAL. This is
roughly equivalent to
```
(when (replay-journal)
(with-replay-streamlet (streamlet)
(peek-event streamlet))
```
except PEEK-REPLAY-EVENT takes into account WITH-REPLAY-FILTER
:MAP, and it may return `(:INDETERMINATE)` if WITH-REPLAY-FILTER
:SKIP is 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:
```
(replayed (pay))
```
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 `PROCESS` block 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 INSERTABLE, versioned
`GET-APPROVAL` block that just returns T. When replaying the code
again, still with v2, the `GET-APPROVAL` block will be upgraded to
:INFINITY.
```
(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-FILTER performs 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 JOURNALED's :INSERTABLE argument. 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. MAP
takes effect before before SKIP.
- 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 SKIP patterns. Filtered
out events are never seen by JOURNALED as it replays events. SKIP
patterns are of the format `(&KEY NAME VERSION<)`, where VERSION<
is a valid [EVENT-VERSION][type], and NAME may be NIL, which acts
as a wildcard.
SKIP is for when JOURNALED @BLOCKs 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 EXTERNAL-EVENTs.
- NO-REPLAY-OUTCOME is a list of EVENT-NAMEs. @REPLAYING-THE-OUTCOME
is prevented for frames with EQUAL names. See
@TESTING-ON-MULTIPLE-LEVELS for an example.
WITH-REPLAY-FILTER affects only the immediately enclosing
WITH-JOURNALING. A WITH-REPLAY-FILTER nested within another in the
same WITH-JOURNALING inherits the SKIP patterns of its parent, to
which it adds its own. The MAP function is applied to before the
parent's MAP.
Examples of SKIP patterns:
```
;; 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 `J1` and `J2` from around `J3`, the `J1` frame from within
`J3`, and the third `J1` frame.
```
(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))))
```
## Testing
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][mock-object] for these external
systems to unshackle the test from the cumbersome database
dependency and to allow it to run without user interaction.
We do this below by wrapping external interaction in JOURNALED with
:VERSION :INFINITY (see @REPLAYING-THE-OUTCOME).
```
(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 VERSIONED-EVENTs are
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 NAME for record-and-replay testing. The
function's BODY is executed in a WITH-BUNDLE to guarantee
replayability. The bundle in question is a FILE-BUNDLE created in
DIRECTORY. The function has a single keyword argument, RERECORD. If
RERECORD is true, the bundle is deleted with DELETE-FILE-BUNDLE to
start afresh.
Furthermore, if BODY returns 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-JOURNAL is discarded when the function returns. In
addition to the replay consistency, this checks that no inserts or
upgrades were performed (see @THE-REPLAY-STRATEGY).
### Testing on multiple levels
Nesting 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
system (READ-LINE) and does some complicated
processing (READ-FROM-STRING) before returning the input in a form
suitable for further processing. Suppose we wrap REPLAYED around
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
outer REPLAYED from being replayed by outcome with
WITH-REPLAY-FILTER:
```
(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)))))))))
```
The inner `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 `accept-number` block
checked as if it was a VERSIONED-EVENT and we get a
REPLAY-OUTCOME-MISMATCH due to the bug.
## Persistence
### 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))
```
##### Original recording
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
Instead of fixing this bug, we just restart the game from the
beginning, @REPLAYING-THE-OUTCOME of external interactions marked
with REPLAYED:
```
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!
```
##### It's evergreen
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
through the `GAME-WON` event that the number of tries calculation is
correct.
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.
##### Discussion
Persistence by replay, also known as [Event
Sourcing][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][continuation].
[continuation]: https://en.wikipedia.org/wiki/Continuation
In contrast, the Journal library does not favour certain styles of
control flow, and only requires that non-determinism is packaged up
in 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.
### 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](https://en.wikipedia.org/wiki/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 `SIGKILL` signal 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:
- An EXTERNAL-EVENT that is also an OUT-EVENT.
- The IN-EVENT of an INVOKED function, which lies outside the
normal, deterministic control flow.
#### Synchronization strategies
When a journal or bundle is created (see MAKE-IN-MEMORY-JOURNAL,
MAKE-FILE-JOURNAL, MAKE-IN-MEMORY-BUNDLE, MAKE-FILE-BUNDLE), the
SYNC option determines when - as a RECORD-JOURNAL - the recorded
events and JOURNAL-STATE changes are persisted durably. For
FILE-JOURNALs, persisting means calling something like `fsync()`,
while for 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 IN-MEMORY-JOURNALs, SYNC-FN is 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
JOURNAL-STATE :RECORDING or for the entire record journal in
states :FAILED and :COMPLETED. :FAILED or :COMPLETED is guaranteed
when leaving WITH-JOURNALING at the latest.
- Values other than NIL and T are reserved for future extensions.
Using them triggers a JOURNAL-ERROR.
#### Synchronization with in-memory journals
Unlike FILE-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
argument, an IN-MEMORY-JOURNAL. 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
overwrite `*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
JOURNAL-DIVERGENT-P.
```
(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 `B` signals
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
triggered and SYNC-FN invoked.
If we were to invoke the now completed `RUN-WITH-DB` again, it would
simply return 3 without ever invoking SYNC-FN:
```
(run-with-db)
=> 3
```
With JOURNAL-REPLAY-MISMATCH, SYNC-FN can be optimized to to reuse
the sequence of events in the replay journal up until the point of
divergence.
#### Synchronization with file journals
For 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 `fsync()`, and
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
`fsync()` is performed.
- 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
around][ext4-writeback].
[ext4-writeback]: https://ext4.wiki.kernel.org/index.php/Ext3_Data=Ordered_vs_Data=Writeback_mode
## Safety
##### Thread safety
Changes to journals come in two varieties: adding an event and
changing the JOURNAL-STATE. Both are performed by JOURNALED only
unless the low-level streamlet interface is used (see
@STREAMLETS-REFERENCE). Using JOURNALED wrapped in a
WITH-JOURNALING, WITH-BUNDLE, or @LOG-RECORD without WITH-JOURNALING
is thread-safe.
- Every journal is guaranteed to have at most a single writer active
at any time. Writers are WITH-JOURNALING and 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-JOURNALING and WITH-BUNDLE have dynamic extent as writers,
but log writers of journals have indefinite extent: once a journal
is used as a LOG-RECORD there remains a writer.
- Attempting to create a second writer triggers a JOURNAL-ERROR.
- Writing to the same journal via LOG-RECORD from 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-BUNDLE is also thread-safe.
- It is ensured that there is at most one FILE-JOURNAL object in the
same Lisp image is backed by the same file.
- Similarly, there is at most FILE-BUNDLE object for a directory.
##### Process safety
Currently, there is no protection against multiple OS processes
writing the same FILE-JOURNAL or FILE-BUNDLE.
##### Signal safety
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 apply, but
JOURNAL objects written by the thread are not safe to access, and
the Lisp should probably be restarted.
## 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.
All EVENTs have EVENT-NAME and EVENT-VERSION, 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"))
```
So a JOURNALED @BLOCK generates an IN-EVENT and an OUT-EVENT, which
are simple property lists. The following reference lists these
properties, there semantics and the functions to read them.
- [type] EVENT
An event is either an IN-EVENT, an OUT-EVENT or a LEAF-EVENT.
- [function] EVENT= EVENT-1 EVENT-2
Return whether EVENT-1 and EVENT-2 represent the same event. In-
and out-events belonging to the same @FRAME are *not* the same
event. EVENT-OUTCOME is not compared when EVENT-EXIT is :ERROR to
avoid undue dependence on implementation specific string
representations. This function is useful in conjunction with
MAKE-IN-EVENT and MAKE-OUT-EVENT to 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 EQUAL. All EVENTs
have names. The names of the in- and out-events belonging to the
same @FRAME are the same.
### Event versions
- [function] EVENT-VERSION EVENT
Return the version of EVENT of type EVENT-VERSION.
- [function] LOG-EVENT-P EVENT
See if EVENT is a LOG-EVENT.
- [function] VERSIONED-EVENT-P EVENT
See if EVENT is a VERSIONED-EVENT.
- [function] EXTERNAL-EVENT-P EVENT
See if EVENT is an EXTERNAL-EVENT.
### In-events
- [type] IN-EVENT
IN-EVENTs are triggered upon entering the dynamic extent of a
JOURNALED @BLOCK. IN-EVENTs have EVENT-NAME,
[EVENT-VERSION][function], and EVENT-ARGS. See @IN-EVENTS for a more
introductory treatment.
- [function] IN-EVENT-P EVENT
See if EVENT is a IN-EVENT.
- [function] MAKE-IN-EVENT &KEY NAME VERSION ARGS
Create an IN-EVENT with NAME, VERSION (of type EVENT-VERSION) and
ARGS as its EVENT-NAME, [EVENT-VERSION][function] and EVENT-ARGS.
- [function] EVENT-ARGS IN-EVENT
Return the arguments of IN-EVENT, normally populated with the ARGS
form in JOURNALED.
### Out-events
- [type] OUT-EVENT
OUT-EVENTs are triggered upon leaving the dynamic extent of the
JOURNALED @BLOCK. OUT-EVENTs have EVENT-NAME,
[EVENT-VERSION][function], [EVENT-EXIT][function] and EVENT-OUTCOME.
See @OUT-EVENTS for a more introductory treatment.
- [function] OUT-EVENT-P EVENT
See if EVENT is an OUT-EVENT.
- [function] MAKE-OUT-EVENT &KEY NAME VERSION EXIT OUTCOME
Create an OUT-EVENT with NAME, VERSION (of type EVENT-VERSION),
EXIT (of type EVENT-EXIT), and OUTCOME as its EVENT-NAME,
[EVENT-VERSION][function], [EVENT-EXIT][function] and
EVENT-OUTCOME.
- [function] EVENT-EXIT OUT-EVENT
Return how the journaled @BLOCK finished. See [EVENT-EXIT][type]
for the possible types.
- [function] EXPECTED-OUTCOME-P OUT-EVENT
See if OUT-EVENT has an EXPECTED-OUTCOME.
- [function] UNEXPECTED-OUTCOME-P OUT-EVENT
See if OUT-EVENT has an UNEXPECTED-OUTCOME.
- [function] EVENT-OUTCOME OUT-EVENT
Return the outcome of the @FRAME (or loosely speaking of a @BLOCK)
to which OUT-EVENT belongs.
### Leaf-events
- [type] LEAF-EVENT
Leaf events are triggered by LOGGED. Unlike IN-EVENTs and
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 EVENT-NAME. Their VERSION is always NIL, which
makes them LOG-EVENTs.
- [function] LEAF-EVENT-P EVENT
See if EVENT is a LEAF-EVENT.
- [function] MAKE-LEAF-EVENT NAME
Create a LEAF-EVENT with NAME.
## Journals reference
In @JOURNAL-BASICS, we covered the bare minimum needed to work with
journals. Here we go into the details.
- [class] JOURNAL
A journal is, conceptually, a sequence of events.
JOURNAL is 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
WITH-JOURNALING.
- [reader] JOURNAL-STATE JOURNAL (:STATE)
Return the state of JOURNAL, which is of type
[JOURNAL-STATE][TYPE].
- [reader] JOURNAL-SYNC JOURNAL (:SYNC = NIL)
The SYNC argument specified at instantiation. See
@SYNCHRONIZATION-STRATEGIES.
- [function] SYNC-JOURNAL &OPTIONAL (JOURNAL (RECORD-JOURNAL))
Durably persist all preceding writes made to JOURNAL during an
enclosing WITH-JOURNALING or via LOG-RECORD from any thread. Writes
made in a WITH-JOURNALING in another thread are not persisted. The
changes in question are WRITE-EVENT calls and state changes. This is
a noop JOURNAL-SYNC is NIL. This function is safe to call from any
thread.
- [reader] JOURNAL-REPLAY-MISMATCH JOURNAL (= NIL)
If JOURNAL-DIVERGENT-P, then this is a list of two
elements: the READ-POSITIONs in the RECORD-JOURNAL and
REPLAY-JOURNAL of the first events that were different (ignoring
LOG-EVENTs). It is NIL, otherwise.
- [function] JOURNAL-DIVERGENT-P JOURNAL
See if WITH-JOURNALING recorded any event so far in this journal
which was not EQUAL to 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-BUNDLE deciding 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
JOURNAL-REPLAY-MISMATCH.
### 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 IDENTICAL-JOURNALS-P, and
somewhat more functionally by EQUIVALENT-REPLAY-JOURNALS-P.
Also see JOURNAL-DIVERGENT-P.
- [generic-function] IDENTICAL-JOURNALS-P JOURNAL-1 JOURNAL-2
Compare two journals in a strict sense: whether
they have the same JOURNAL-STATE and the lists of their events (as
in LIST-EVENTS) are EQUAL.
- [generic-function] EQUIVALENT-REPLAY-JOURNALS-P JOURNAL-1 JOURNAL-2
See if two journals are equivalent when used the
for REPLAY in WITH-JOURNALING. EQUIVALENT-REPLAY-JOURNALS-P is like
IDENTICAL-JOURNALS-P, but it ignores LOG-EVENTs and allows events
with EVENT-EXIT :ERROR to differ in their outcomes, which may very
well be implementation specific, anyway. Also, it considers two
groups of states as different :NEW, :REPLAYING, :MISMATCHED, :FAILED
vs :RECORDING, :LOGGING, COMPLETED.
The rest of section is about concrete subclasses of [JOURNAL][class].
### 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
JOURNALED (i.e. its NAME, ARGS arguments, but also the return VALUES
of the block, or the value returned by CONDITION):
- These objects need not be @READABLE.
- Their identity (`EQ`ness) is not lost.
- They must **must not be mutated** in any way.
- [function] MAKE-IN-MEMORY-JOURNAL &KEY (EVENTS NIL EVENTSP) STATE (SYNC NIL SYNCP) SYNC-FN
By default, creates an empty IN-MEMORY-JOURNAL in JOURNAL-STATE
:NEW, which is suitable for recording. To make a replay journal, use
:STATE :COMPLETED with some sequence of EVENTS:
```
(make-in-memory-journal :events '((:in foo :version 1)) :state :completed)
```
If the EVENTS argument is provided, then STATE defaults to :NEW,
else to :COMPLETED.
SYNC determines when SYNC-FN will be invoked on the RECORD-JOURNAL.
SYNC defaults to T if 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-EVENTS at the time of the
most recent invocation of SYNC-FN.
### File journals
- [class] FILE-JOURNAL JOURNAL
A FILE-JOURNAL is a journal whose contents and
JOURNAL-STATE are persisted in a file. This is the [JOURNAL][class]
subclass 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 READ
and WRITE, everything that JOURNALED records in events (i.e. its
NAME, ARGS arguments, but also the return VALUES 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 `#\Space` (for state :NEW, :REPLAYING, :MISMATCHED and
:FAILED), or a `#\Newline` (for state :RECORDING, :LOGGING and
:COMPLETED).
- If the journal has SYNC (see @SYNCHRONIZATION-STRATEGIES), then in
between events, there may be `#\Del` (also called `#\Rubout`) or
`#\Ack` characters (CHAR-CODE 127 and 6). `#\Del` marks 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.
`#\Ack` characters, 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). `#\Ack` characters are ignored when reading
the journal.
Thus, when editing a file, don't change the first character and
leave the `#\Del` character, if any, where it is. Also see
@SYNCHRONIZATION-WITH-FILE-JOURNALS.
- [function] MAKE-FILE-JOURNAL PATHNAME &KEY SYNC
Return a FILE-JOURNAL backed by the file with PATHNAME. The file is
created when the journal is opened for writing. For a description of
SYNC, see @SYNCHRONIZATION-STRATEGIES.
If there is already an existing FILE-JOURNAL backed by the same
file, then that object is returned. If the existing object has
different options (e.g. it has SYNC T while the SYNC argument is NIL
here), then a JOURNAL-ERROR is signalled.
If there is already an existing FILE-JOURNAL backed by the same
file, the JOURNAL-STATE is not :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-JOURNAL object is created.
- [reader] PATHNAME-OF FILE-JOURNAL (:PATHNAME)
The pathname of the file backing the journal.
### Pretty-printing journals
- [class] PPRINT-JOURNAL JOURNAL
When an event is written to a PPRINT-JOURNAL it
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
Creates a PPRINT-JOURNAL.
- [accessor] PPRINT-JOURNAL-STREAM PPRINT-JOURNAL (:STREAM = \*STANDARD-OUTPUT\*)
The stream where events are dumped. May be set any
time to another STREAM.
- [accessor] PPRINT-JOURNAL-PRETTY PPRINT-JOURNAL (:PRETTY = T)
Whether to use PPRINT-JOURNAL-PRETTIFIER or write
events in as the property lists they are. A
@BOOLEAN-VALUED-SYMBOL.
- [accessor] PPRINT-JOURNAL-PRETTIFIER PPRINT-JOURNAL (:PRETTIFIER = 'PRETTIFY-EVENT)
A function like PRETTIFY-EVENT that writes its an
event to a stream. Only used when PPRINT-JOURNAL-PRETTY, this is
the output format customization knob. Also see @DECORATIONs.
## Bundles reference
In @BUNDLES, we covered the repeated replay problem that
WITH-BUNDLE automates. Here we provide a reference for the bundle
classes.
- [class] BUNDLE
This is an abstract base class. Direct subclasses
are IN-MEMORY-BUNDLE and FILE-BUNDLE.
A BUNDLE consists 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 JOURNAL-STATE :COMPLETED plays
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 :COMPLETED and 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)
If MAX-N-FAILED is non-NIL, and the number of
journals of [JOURNAL-STATE][type] :FAILED in the bundle exceeds
its value, then some journals (starting with the oldest) are
deleted.
- [accessor] MAX-N-COMPLETED BUNDLE (:MAX-N-COMPLETED = 1)
If MAX-N-COMPLETED is non-NIL, and the number of
journals of [JOURNAL-STATE][type] :COMPLETED in the bundle exceeds
its value, then some journals (starting with the oldest) are
deleted.
### In-memory bundles
- [class] IN-MEMORY-BUNDLE BUNDLE
An IN-MEMORY-BUNDLE is a BUNDLE that is built on
IN-MEMORY-JOURNALs. 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
Create a new IN-MEMORY-BUNDLE with [MAX-N-FAILED][(accessor
bundle)] and [MAX-N-COMPLETED][(accessor bundle)]. SYNC and SYNC-FN
are passed on to MAKE-IN-MEMORY-JOURNAL.
### File bundles
- [class] FILE-BUNDLE BUNDLE
A FILE-BUNDLE is a BUNDLE that is built on
FILE-JOURNALs. It provides easy replay-based persistence.
- [reader] DIRECTORY-OF FILE-BUNDLE (:DIRECTORY)
The directory where the files backing the
FILE-JOURNALs in the FILE-BUNDLE are kept.
- [function] MAKE-FILE-BUNDLE DIRECTORY &KEY (MAX-N-FAILED 1) (MAX-N-COMPLETED 1) SYNC
Return a FILE-BUNDLE object backed by FILE-JOURNALs in DIRECTORY.
See [MAX-N-FAILED][(accessor bundle)] and
[MAX-N-COMPLETED][(accessor bundle)]. For a description of SYNC, see
@SYNCHRONIZATION-STRATEGIES.
If there is already a FILE-BUNDLE with the same directory (according
to TRUENAME), return that object is returned if it has the same
MAX-N-FAILED, MAX-N-COMPLETED and SYNC options, else JOURNAL-ERROR
is signalled.
- [function] DELETE-FILE-BUNDLE DIRECTORY
Delete all journal files (`*.jrn`) from DIRECTORY. Delete the
directory if empty after the journal files were deleted, else signal
an error. Existing FILE-BUNDLE objects are not updated, so
MAKE-FILE-JOURNAL with FORCE-RELOAD may be required.
## Streamlets reference
This section is relevant mostly for implementing new kinds of
JOURNALs in addition to FILE-JOURNALs and IN-MEMORY-JOURNALs. In
normal operation, STREAMLETs are not worked with directly.
### Opening and closing
- [class] STREAMLET
A STREAMLET is a handle to perform I/O on a
JOURNAL. The high-level stuff (WITH-JOURNALING, JOURNALED, etc) is
built on top of streamlets.
- [reader] JOURNAL STREAMLET (:JOURNAL)
The JOURNAL that was passed to OPEN-STREAMLET.
This is the journal STREAMLET operates on.
- [generic-function] OPEN-STREAMLET JOURNAL &KEY DIRECTION
Return a STREAMLET suitable for performing I/O on
JOURNAL. DIRECTION (defaults to :INPUT) is one of :INPUT, :OUTPUT,
:IO and it has the same purpose as the similarly named argument of
CL:OPEN.
- [generic-function] CLOSE-STREAMLET STREAMLET
Close STREAMLET, which was returned by
OPEN-STREAMLET. After closing, STREAMLET may not longer be used for
IO.
- [generic-function] MAKE-STREAMLET-FINALIZER STREAMLET
Return NIL or 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-JOURNAL
is not appropriate.
- [generic-function] OPEN-STREAMLET-P STREAMLET
Return true if STREAMLET is open. STREAMLETs are
open until they have been explicitly closed with CLOSE-STREAMLET.
- [function] INPUT-STREAMLET-P STREAMLET
See if STREAMLET was opened for input (the DIRECTION argument of
OPEN-STREAMLET was :INPUT or :IO).
- [function] OUTPUT-STREAMLET-P STREAMLET
See if STREAMLET was opened for input (the DIRECTION argument of
OPEN-STREAMLET was :OUTPUT or :IO).
- [macro] WITH-OPEN-JOURNAL (VAR JOURNAL &KEY (DIRECTION :INPUT)) &BODY BODY
This is like WITH-OPEN-FILE. Open the journal designated by
JOURNAL (see TO-JOURNAL) with OPEN-STREAMLET, passing DIRECTION
along, and bind VAR to the resulting STREAMLET. Call CLOSE-STREAMLET
after BODY finishes. If JOURNAL is NIL, then VAR is bound to NIL and
no streamlet is created.
- [condition] STREAMLET-ERROR ERROR
Like CL:STREAM-ERROR: failures regarding trying to
perform I/O on a closed STREAMLET or of the wrong DIRECTION. Actual
I/O errors are *not* encapsulated in STREAMLET-ERROR.
### Reading from streamlets
- [generic-function] READ-EVENT STREAMLET &OPTIONAL EOJ-ERROR-P
Read the event at the current read position from
STREAMLET and move the read position to the event after. If there
are no more events, signal END-OF-JOURNAL or return NIL depending on
EOJ-ERROR-P. Signals STREAMLET-ERROR if STREAMLET is not
INPUT-STREAMLET-P or not OPEN-STREAMLET-P.
- [generic-function] READ-POSITION STREAMLET
Return an integer that identifies the position of
the next event to be read from STREAMLET. `SETF`able, see
SET-READ-POSITION.
- [generic-function] SET-READ-POSITION STREAMLET POSITION
Set the read position of STREAMLET to POSITION,
which must have been acquired from READ-POSITION.
- [macro] SAVE-EXCURSION (STREAMLET) &BODY BODY
Save READ-POSITION of STREAMLET, execute BODY, and make sure to
restore the saved read position.
- [generic-function] PEEK-EVENT STREAMLET
Read the next event from STREAMLET without changing
the read position, or return NIL if there is no event to be read.
- [method] PEEK-EVENT (STREAMLET STREAMLET)
This is a slow default implementation, which relies on
SAVE-EXCURSION and READ-EVENT.
### Writing to streamlets
- [generic-function] WRITE-EVENT EVENT STREAMLET
Write EVENT to STREAMLET. Writing always happens at
the end of STREAMLET's journal regardless of the READ-POSITION and
the read position is not changed. Signals STREAMLET-ERROR if
STREAMLET is not OUTPUT-STREAMLET-P or not OPEN-STREAMLET-P.
- [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 :OUTPUT and may be used by
LOG-RECORD.
- [generic-function] WRITE-POSITION STREAMLET
Return an integer that identifies the position of
the next event to be written to STREAMLET.
- [generic-function] REQUEST-COMPLETED-ON-ABORT STREAMLET
Make it so that upon ABORTED-EXECUTION STREAMLET's
JOURNAL will be in JOURNAL-STATE :COMPLETED when loaded fresh (e.g.
FILE-JOURNAL from a file). Any previously written events must be
persisted before making this change. Before
REQUEST-COMPLETED-ON-ABORT is called, a journal must be reloaded in
state :FAILED.
It is permissible to defer carrying out this request until the next
SYNC-STREAMLET call. If the request was carried out, return true. If
it was deferred, return NIL.
- [generic-function] SYNC-STREAMLET STREAMLET
Durably persist the effects of all preceding
WRITE-EVENT calls made via STREAMLET to its journal and any deferred
REQUEST-COMPLETED-ON-ABORT in this order.
## Glossary
- [glossary-term] async-unwind
If an asynchronous event, say a `SIGINT` triggered by `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-THREAD which, as it can execute
arbitrary code, may unwind the stack in the target thread.
- [glossary-term] boolean-valued symbol
Imagine writing two STREAMs with a spaghetti of functions and
wanting to have pretty-printed output on one of them. Unfortunately,
binding *PRINT-PRETTY* to T will affect writes to both streams.
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 `STREAM-PRINT-PRETTY` is `'*PRINT-PRETTY*`,
then we have the normal Common Lisp behaviour. Setting
`STREAM-PRINT-PRETTY` to NIL or T also works, because they are
self-evaluating.
If not by CL:STREAMs, boolean-valued symbols are used by
MAKE-LOG-DECORATOR and PPRINT-JOURNALs.
- [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 `GO`, RETURN,
RETURN-FROM or THROW, then it is said to have performed a non-local
exit. This definition of a non-local exit includes EVENT-EXIT
:CONDITION, :ERROR and :NLX.
- [glossary-term] readable
In Common Lisp, readable objects are those that can be printed readably.
Anything written to stream-based journals needs to be readable.
* * *
###### \[generated by [MGL-PAX](https://github.com/melisgl/mgl-pax)\]