Logging with Beacon
Logging is a pervasive analysis tool, but most logging systems focus on text. There is a historical reason for this, but we can certainly do better. Particularly in Pharo, where everything is an object, it should follow that logs should be made of objects and that scrolling endlessly through large text files should make room for more sensible engineering approaches.
Enter Beacon.
Beacon is an engine based solely on Announcements, and its goal is both to be usable in practice and be elegantly slim. How slim?
'Beacon-Core' asPackage linesOfCode
The basic structure is similar to any other logger. Objects log BeaconSignal
objects that are captured by a receiving announcer. To make things easy, there exists a global announcer in the Beacon class. The beacon announcer does not do anything by itself. To actually produce an effect either on some sort of a stream like the Transcript, or on some sort of a recording support, it needs a dedicated SignalLogger
.
Take a look at some simple examples. In the first one, we record signal objects that are logged in between the starting and stopping of the recorder:
MemoryLogger start. ContextStackSignal emit. MemoryLogger stop.
In the second one, we simply output to the transcript the textual representation of the signals logged within the scope of a TranscriptLogger
:
Transcript open.
TranscriptLogger runDuring: [
StringSignal emit: 'This is a message'. ]
Basic signals
Beacon works with Announcements. However, for logging purposes, we typically need a timestamp. To this end, BeaconSignal
offers a handy Announcement
that stores the current timestamp during the initialization.
The code also ships with three concrete signals for convenience:
- StringSignal
is used for simple string messages. This is used mostly for example purposes, and it is actually not meant to be used much in practice. Why not? Because it’s a string.
- WrapperSignal
is useful to log an arbitrary object without necessarily creating a class for it. It is not meant to be used extensively but can prove useful for quick prototypes.
- ContextStackSignal
is a utility useful for capturing the current stack as objects (how cool is that!).
Other than that, each application is expected to define its own, much like how it is supposed to define Exceptions and Announcements.
O yes. Another thing to remember is that each signal is triggered using an emit instance side message. That is it.
Basic loggers
To achieve anything useful, we need a SignalLogger
to bind the general Beacon
to a concrete medium, such as a stream. The core engine comes with a couple of concrete bounded beacons.
As seen in the previous examples, we have seen a MemoryLogger that records the signals in an ordered collection, and a TranscriptLogger
that outputs the textual representation to the Transcript. Similarly, we can also output a textual representation to any custom string stream:
String streamContents: [ :stream |
(CustomStreamLogger with: stream)
runDuring: [
StringSignal emit: 'This is a message' ] ]
No quaint text formatting
One common logging concept that did not make it in the engine is that of a formatter. This is typically an essential piece of text-focused logging engines.
Perhaps there are cases in which it can still be useful for having special formatting on top of Beacon. If needed, most common of the formatting use cases can be achieved through concrete bounded beacons. For example, the StringStreamLogger uses polymorphism to delegate the printing to the Signal hierarchy (via SignalSerializer
). This is enough.
Given that serialization should focus on objects, formatting text is neither essential nor general enough to warrant more prominent modelling. Once we have objects, we can approach presenting them through smarter tools.
Inspecting Beacon objects
Beacon comes with a dedicated set of inspector extensions. For example, inspecting the snippet below, we see the list of signals that updates every time a new signal is recorded:
MemoryLogger runDuring: [ 1 to: 100 do: [ :x | StringSignal emit: x asString. x asBeaconSignal emit ] ]
As signals are mapped on separate classes, they can also come with dedicated views that can be made available for inspection. For example, inspecting a ContextStackSignal
shows the methods from the stack:
ContextStackSignal emit
Filtering signal objects
Logging can quickly spawn a ton of data. Filtering is essential in this situation.
But, Beacon has no tags and no levels. Why not? Because these filtering methods pose a rather arbitrary constraint as they require us to know in advance at what level we want a certain logging event to be. They might work well in some situations. However, when using logging for debugging purposes we mainly want to see only the events we nominally need and not others.
An approach for this problem is to take advantage of objects. Indeed, the Announcement framework allows us to register our interest for a set of announcement types of our choice. For example, consider the snippet below:
MemoryLogger new
runFor: StringSignal, ContextStackSignal
during: [
StringSignal emit: 'This should be recorded.'.
ContextStackSignal emit.
DummySignal new emit ]
The execution will only log the first two signals, but not the dummy one. For each application, we can define various combinations of arbitrary signals that should be logged together without having an extra need of levels and tags.
Of course, applications can still create their own specialized BoundedBeacons and introduce another level of filtering if it makes sense within that application. However, please note that the default filtering mechanism offers developers an incentive to design fine-grained logging classes that can be easily picked up at a later time. That can only be for the better.
Filtering signal data
Another filtering issue is related to the data associated with a signal object. Let’s take a concrete example of ContextStackSignal whose goal is to capture the current stack. This, in turn, can lead to including an extensive object graph that can induce penalties either in form or extra memory or time required to store it.
To limit the size, we use two mechanisms. First, the ContextStackSignal
does not store the actual context objects. Instead it only stores the references (i.e., Ring definitions) to the methods being present in the stack. Indeed, this is not quite a stack, but it is a reasonable approximation for the point of view of logging. A benefit of doing so is that the logged objects become constant and thus they are better suited for longer-term inspection.
Second, ContextStackSignal
makes use of the Announcement mechanism of only capturing more expensive data only if there exists at least one logger in it. This happens through Announcement>>#prepareForDelivery
. Thus, the stack will only be captured if someone is interested in that signal for a concrete purpose, and not when it is created in the code. This is great because it ensures that we only pay the price when there is a value associated with it.
Logging exceptions
Logging is often used for keeping track of exceptions. Beacon offers out-of-the-box support for this:
MemoryLogger runDuring: [ [1/0] on: Error do: [:e | e emit] ]
In this example, the code raises an exception that is captured as a signal.
Debugging with Beacon
Up to now, we have mostly looked at global signals that are captured by a global Beacon
and passed to other global SignalLogger
objects. These globals make it cheap to add a new log entry and have it captured in a central place. Yet, the engine does not limit the usage to these globals. The last example from above shows that we can equally well collect the results through an instance of a SignalLogger
.
This becomes interesting when we want to debug selectively only a dedicated scenario without having to dig through the entire log that might contain many irrelevant details.
For example, let's say we want to understand how text styling works in Brick. To this end, we'd like to understand what is the path that leads to styling and how often is styling triggered. A quick code search reveals an interesting method: BrTextEditorModel>>#styleText
. A debugger would be useful, but we cannot just add a halt in that editor because this will prevent us from using the editor in the first place (this is especially problematic when the debugger uses that editor). Instead, we emit a signal for debugging purposes. We can do this dynamically by installing a meta-link:
| methodNode link | methodNode := (BrTextEditorModel>>#styleText) ast. link := MetaLink new metaObject: [ ContextStackSignal emit ]; selector: #value; arguments: #(). methodNode link: link.
Now that the logging is in place, we create an element, we simulate several keystrokes and we capture the signals:
| editor element | editor := BrTextEditor new. element := BrEditorElement new. element editor: editor. element requestFocus. MemoryLogger new runDuring: [ BlSpace simulateKeyDownOn: element key: BlKeyboardKey a. BlSpace simulateKeyUpOn: element key: BlKeyboardKey a. ].
Executing the snippet results in three signals, one for each keystroke event.
Debugging the text editor that can be used by a debugger can appear as an extreme case. Indeed, it is, but even if it is extreme and likely to appear less often in practice, we showed that we can accommodate this case as well. Furthermore, situations in which we cannot utilize breakpoints do appear in other forms, especially in systems that rely on parallel processes which cannot be stopped.
Logging any announcements from any announcer
Not only can we use multiple instances for bindings, but we do not necessarily need the Beacon global announcer either. By using Announcements as the transmission engine, we can also log the transmissions of announcements from any announcer. To achieve this, we simply have to point a bounded beacon to the announcer. For example:
| announcer logger |
announcer := Announcer new.
logger := MemoryLogger for: announcer.
logger
runFor: Announcement
during: [ announcer announce: Announcement new asBeaconSignal ].
The only thing we need to do is to transform the announcement into a signal.
This feature is particularly interesting given that the Announcements framework is the primary means of communication between decoupled objects in Pharo. As announcements tend to be hard to debug, logging the activity of an announcer inexpensively can save a lot of trouble.