Debugging a duplicated behavior with GTInspector

I have just spent a beautiful 15 minutes tracking a bug down. It was so exciting that afterwards I decided to spend 2 days documenting the experience because I think it offers an elaborate example of how transformative development workflows can be with moldable tools in a live environment.

The bug in question was reported recently and it is related to the GTDebugger version that we introduced recently in Pharo.

The problem looks as follows. Triggering an action from the context menu of a stack seems to trigger twice the action. This is particularly visible when a window is spawned twice, such as when trying to see the implementors of a method from the stack.

This is a tricky problem, and it can come from all sorts of places. What is certain, is that at some point there are two executions of spawning the implementors window. The debugger defines this action in the GTMoldableDebugger>>browseMessages method. We put a breakpoint in the method, and indeed, it is being executed twice. Exploring the stack in both cases does not seem to reveal anything meaningful. The stack looks the same, so likely the problem comes from different objects, not from different messages.

To reason about this, we need a different presentation. Ideally, we would like to see the complete execution and check the points in which the execution branches. This information is not apparent in a classic debugger because it mainly shows only the active stack and we are interested in the tree.

Nevertheless, as the tree is what we care about we should be able to build it. To do this, we utilize the Beacon logging engine, and we replace the breakpoint with a logging statement that records the stack of contexts (ContextStackSignal log).

GTMoldableDebugger>>browseMessages
    "Present a menu of all messages sent by the current message.
    Open a message set browser of all implementors of the message chosen.”

    self currentMessageName ifNotNil: [
        ContextStackSignal log.
        self systemNavigation browseAllImplementorsOf: self currentMessageName ]

We turn on recording with RecordingBeacon start. We trigger the problem again: we inspect 42 answer, and then look for implementors. And we start exploring the recordings with GTInspector.

RecordingBeacon instance recordings collect: #stack

As expected there are two such collection of stacks, where the elements in each stack are context objects.

We switch to the Raw inspector presentation of the collection object, and we try to visualize the entries in the two stack in one picture. We use the RTMondrian builder of Roassal to script the visualization. We concatenate the stack entries in one set, we draw edges between consecutive entries, and we arrange the graph in a tree. We use a set because some of the entries will be the same:

| view |
view := RTMondrian new.
view shape label text: [:each | each gtDisplayString truncate: 50 ] .
view nodes: (self first, self second) asSet.
self first
    overlappingPairsDo: [ :a :b |
        view edges
            connectFrom: [:x | b ]
            to: [:x | a ] ].
self second
    overlappingPairsDo: [ :a :b |
        view edges
            connectFrom: [:x | b ]
            to: [:x | a ] ].
view layout tree.
view.

Executing in place this script shows us the execution tree.

There seems to be one place which branches the execution. Let’s zoom in to see the details.

We see that the stack on both branches looks the same in terms of the executed methods. Let’s see if the difference is in the objects that are executing the two branches. For this, we inspect the context before the branching happens.

We look at the receiver.

It’s a SubscriptionRegistry which is used by objects interested in announcements. At a closer look, we notice that all announcement, such as GLMMenuItemSelected, seem to be registered twice. This points us towards the direction of a bug in Glamour, the browsing engine on top of which the GTDebugger is implemented. Glamour uses this type of announcements to bind what happens in the concrete Morphic world, and the logical model of the browser.

Armed with this new hypothesis, we can now create a smaller experiment in which we isolate the creation of a FastTable-based list in Glamour.

GLMCompositePresentation new
    with: [ :c |
        c fastList selectionAct: #inspect entitled: 'Value' ];
    openOn: (1 to: 42)

And indeed, in the resulting browser, executing the action via the contextual menu results in two inspector being opened. This means that the problem is actually not related to the GTDebugger but to Glamour. At the same time, a replacing fastList with list does not exhibit the problem, which means that our bug is located somewhere in the binding between FastTable and Glamour. This hypothesis would make sense given that the FastTable support was only recently introduced in Glamour and thus, it can still have bugs.

To figure it out, we would need to debug this. We could try putting a breakpoint in installActionsOnModel:fromPresentation:, but that would imply that if we would use the GTDebugger, our image would go in a loop with the breakpoint trying to spawn a debugger, and the opening of the debugger hitting a new breakpoint.

So, we take the same route as before, and we insert a logging statement that captures the current stack. This time, we look only at methods because it is probably enough:

installActionsOnModel: aMorphicModel fromPresentation: aPresentation
    MethodStackSignal log.
    aMorphicModel when: GLMMenuItemSelected do: [ :ann | ann action morphicActOn: aPresentation ].
    aMorphicModel when: GLMKeyStroke do: [ :ann | ann action actOn: aPresentation ].

This logging statement is placed deep in Glamour. As the GTInspector is based on Glamour, looking at the global log recorder would reveal many appearances of this log entry that are not related to our problem. So, we scope the recording only to the execution of the creation of our browser:

RecordingBeacon new
    runDuring: [
        GLMCompositePresentation new
            with: [ :c |
                c fastList
                    selectionAct: #inspect
                    entitled: 'Value' ];
            openOn: (1 to: 42) ].

Inspecting the result shows us the recordings.

There are three such recordings. One is related to the window rendering, and two are related to FastTable. We explore the first one, and it is being called from the render: method. We explore the second one, and it comes from a method called dataSourceUpdated::

We look at the dataSourceUpdated: method (notice how we essentially have a postmortem debugger in the inspector):

And indeed, this method erroneously calls installActionsOnModel:fromPresentation::

dataSourceUpdated: announcement
    tableModel ifNotNil: [ self unsubscribeDataSource: tableModel ].
    tableModel := announcement newDataSource.
    self installActionsOnModel: tableModel fromPresentation: tableModel glamourPresentation.
    self initializeAnnouncementForDataSource

Now we know where the problem comes from, but we are not done yet. We still have to document our finding. In this case, the most appropriate way is to write a red functional test to capture the problem of multiple announcements with the same type being registered for a FastTable:

testNoDuplicateRegistrationOfAnnouncementsOnDataSource
    | table amountOfMenuItemSelectedSubscriptions |
    window := GLMCompositePresentation new
            with: [ :c |
                c fastList selectionAct: #inspect entitled: 'Value' ];
            openOn: (1 to: 42).
    table := self find: FTTableMorph in: window.
    amountOfMenuItemSelectedSubscriptions := table dataSource announcer subscriptions glmSubscriptions count: [ :each | each announcementClass = GLMMenuItemSelected ].
    self assert: amountOfMenuItemSelectedSubscriptions equals: 1

Then we remove the troubling line, and check that the test is green.

Now we are done.

Remarks

Let’s take a step back and look at the ingredients of this session. We guided all our steps through hypotheses following the humane assessment philosophy. As a consequence, at every point we knew where we were and why we were there. And we guided our actions by testing these hypotheses through custom made analyses.

To make this practical, we need tools that allow us to go through these scenarios inexpensively and live. With Pharo this is now a reality.

Looking at the details, our analysis involved actions such as:

• recording the stack through a logger,
• inspecting the stack postmortem with the inspector,
• visualizing multiple stacks together, or
• scoping the recording to a particular part of the execution.

Granted, these are typically perceived as advanced actions, but they really are not that complicated.

One thing that might appear hard is the idea of recording the execution context and then utilizing the inspector to debug. I reported on this technique before. On that occasion, I did it by directly inspecting thisContext. In the current case I used Beacon because (1) it makes it even easier to capture the stack as a log signal and offer it for later inspection (e.g., ContextStackSignal log), and (2) it has a convenient way to scope log capturing.

Another thing is the use of visualization which proved to be essential for solving our problem. It helped us analyze the two initial stacks in one meaningful picture that helped us quickly discover the point to look at (i.e., the branching point). This was possible exactly because we could embed that Roassal visualization right in place with little effort. It does require some learning, but together with the deep integration in the Glamorous Toolkit it brings with it a complete new way of exploring objects.

In my book, this session counts as cool. If you agree, we just labelled a debugging session as cool. And this is not at all an isolated case. It is actually rather common in my world. That is because debugging, and assessment in general, is an exciting activity. Can you say the same? If not, I invite you to start exploring what Pharo has to offer and go beyond the typical routine. You will be surprised.

Guiding a rename effort with GTInspector

After a debate on the Pharo mailing list, we ended up choosing to rename all variations of the example* pragmas to gtExample*. Furthermore, as a second step, we also wanted all methods annotated with gtExample* to start with an example prefix because this would not conflict with the behavior from the code browser.

With this occasion, we also decided to go through the list manually to review. This is not a terribly complicated issue except that we are talking about some couple of hundred methods scattered through dozens of classes.

Having to affect multiple pieces of code scattered throughout the system is not an atypical software development problem, and I find it odd at how little support there exists in typical IDEs for something like this. So, how do you keep track of something like this in Pharo?

Here is a variation of a script that we used to keep track of the second step of renaming the method names:

(Object withAllSubclasses flatCollectAsSet: [ :each |
     (Pragma allNamed: #gtExample in: each) ,
     (Pragma allNamed: #gtExample: in: each) ,
     (Pragma allNamed: #gtExampleFrom: in: each) ])
     select: [ :each | each selector beginsWith: 'example' ]

Inspecting the result in the inspector, reveals a small query-scoped browser that allows you to focus only on the task at hand and know precisely when you are finished.

This solution is terribly inexpensive. Essentially, it is a short query combined with some object inspection. The code involved is minimal, too. This is possible exactly because we turned the concept of an IDE on its head, and as a consequence many use cases that are otherwise seen as the exclusive realm of dedicated tools can be handled with compositions of modular and small ones.

Checking for uniformity in SVN from Pharo

In an effort to ease continuous delivery for a system, we needed to ensure that all installation projects (for various sites and customers) had a uniform structure. Specifically, after refactoring the package assembly part of the continuous delivery pipeline, we wanted to ensure that all installation projects had a configs/srv/deployments/ path in them.

To check this, we created a tiny script. First, we invoked the Windows command line to get the list of all installation names from Subversion and we dumped these in a installations.txt file:

WinProcess createAndWaitForProcess: 'cmd /c "svn list https://svn/svn/delivery/installations > installations.txt"'.

Afterwards, to check that each of these projects we traversed all the corresponding Subversion repositories. The simplest way we could think of was to simply check that the header of the http request is not an error (such as 404):

'installations.txt' asFileReference readStreamDo: [ :s |
     s contents lines select: [ :each |
          (ZnClient new
               url: 'https://svn/svn/delivery/installations/', each, 'trunk/configs/srv/deployments/';
               username: ‘username' password: ‘password';
               head;
               response) isError ] ].

We got some 80 such projects that needed to be redone (out of a couple of hundred). The whole exercise took less than 10 minutes and could be done with a stock Moose (or even Pharo in this case) distribution, but it was a useful test that guided a multi-hour work. At the end, we reran the same script to check that we are truly done. And we were done.

Scoping for a specific search category in GTSpotter

GTSpotter let’s you search flexibly for all sorts of objects, and the results are typically split into multiple search categories. In this post we take a quick look at scoping your search to a specific category only.

Let’s say that you want to search for some Collection* package. Typing Collec produces matches in multiple search categories, including classes, packages or implementors:

Using a hashed word filters the search for the category name. In our case, adding #pa retrieves only the desired packages:

Communicating Pharo 4.0

Pharo 4.0 is out.

One of the most prominent changes is the addition of the Glamorous Toolkit as part of the core distribution. Namely, Pharo ships with GTPlayground, GTInspector and GTSpotter.

These are not regular tools. Besides the interesting interaction features that they come with, these tools are moldable. They empower developers to extend them cheaply to match custom needs. And when we say cheap, we mean minutes cheap. In other words, we actually mean too cheap to matter. This is a major departure from traditional IDE concepts and we claim that moldable tools have a significant impact on development.

Ok, that is our claim. But, how could we communicate the importance and reach of these tools?

If moldability is a concept applicable and useful in many contexts, it should follow that it is also applicable and useful in many corners of the core Pharo system. Is it really so? Let's visualize this impact.

We start from the map of Pharo. The picture below shows a circular tree map of the Pharo classes nested in packages.

Of these, we highlight the classes that have at least on extension either for the GTInspector or for GTSpotter.

Given that not all classes in a package are equally important and used explicitly, it is often enough to extend the more prominent classes with custom inspection. Thus, as soon as one class is extended, we also highlight the package. The result can be seen below.

The full script that reproduces the above picture can be found here http://ws.stfx.eu/LYN3N20P3HFC (just paste the url in GTSpotter), and it can be run in Moose 5.1.

We have extensions in 112 classes spread in 45 packages (out of a total of 277 non-test packages). These are just the extensions that ship by default with Pharo. There exist other such extensions both for core classes or for domain specific classes that are packaged elsewhere.

Most of these extensions are simple presentations or search processors. While there are indeed some presentations that rely on more sophisticated visualization engines, it is not the fanciness of the presentation that is the most important. The power of the mechanism comes from the integration of these presentation in a continuous browsing or search workflow that opens new development possibilities. For example, the visualization from this post was created with the Roassal engine by using a playground and a preview in an embedded inspector.

Moldability is a far reaching concept, and we have only started to explore its possibilities.