A debugging session with Morphine

In this section we show a session illustrating Morphine facilities. The commands used in the following are described in the reference manual (see Part II page ). You can also get an on-line description of those commands by invoking the man/1 command within Morphine. Note that commands that moves to an event and print a trace line (like fget/1) have a corresponding command which moves to this event without printing any trace line (fget_np/1).

In the following example, the full names of the commands are used to ease the understanding. However, most of them have abbreviations which can be used to save typing. Whenever queries repeat part of previous ones, the corresponding abbreviations are used.

The trace queries typed in by the user are the goals following the Morphine prompt ([Morphine]:). All the rest is written by the system.

The analyzed program is the buggy mastermind program given in Appendix B. Here is what happens when we run the buggy mastermind program:

%mastermind
Enter a mastermind problem : mastermind(red, red, red, red, white).

The solution was found with 5 guesses.
The successive guesses were :
     1: blue blue blue blue blue (0 Bulls and 3 Cows).
     2: white white white white black (0 Bulls and 3 Cows).
     3: yellow yellow yellow yellow white (1 Bulls and 3 Cows).
     4: yellow gray gray gray gray (0 Bulls and 3 Cows).
     5: red red red red white (5 Bulls and 0 Cows).

The Tcl/TK output of this program is given in Figure 3. The numbers of cows is wrong; we call Morphine to understand why.

  

Figure 3: Board output of the buggy mastermind program

%Morphine 

[...]

Loading /home/swann/d01/lande/jahier/.morphine-rc...
ECLiPSe Constraint Logic Programming System [kernel]
Version 4.1.0, Copyright IC-Parc and ICL, Sun Feb 21 18:37 1999
[Morphine]:

To start the execution of the mastermind within Morphine, we invoke the run/1 command.

[Morphine]: run(mastermind).

Start debugging mastermind program.

Before starting to display trace lines, we way wonder what attributes are displayed (slot_dislay parameter). We can get that information with the print_displayed_attributes/0 command.

[Morphine]: print_displayed_attributes.

 port name(arg) goal_path

As we would like to display the chrono number too, we toggle that slot.

[Morphine]: toggle(chrono), print_displayed_attributes.

chrono:  port name(arg) goal_path

Now on, each trace line will display the chrono, port, name, args, and goal_path attributes. All the existing attributes are described in section 2.2 and can be retrieved on demand using the current/1 command.

The top level predicate that counts bulls and cows from a code and a submission is check_mastermind/4. Let us go to the event where this predicate first exits to see if it exits with sensible argument values.

We invoke the fget/1 command to move to the events where that predicate exits.

[Morphine]: fget(name = check_mastermind and port = exit).

Enter a mastermind problem :
 mastermind(red, red, red, red, white). 

1432557:  exit check_mastermind(mastermind(blue, blue, blue, blue, blue), 
  mastermind(red, red, red, red, white), 0, 3)

Note that fget has filtered aver one million trace events here. In order to determine more easily whether check_mastermind outputs correct values, we can use a little program which displays data in a user-friendly manner (useful with big or cryptic data). In this case, we can reuse the display_mastermind/4 predicate that is used in mastermind.m to display the mastermind boards. To gather the current values of the arguments, we simply use current/1 with the attributes args.

[Morphine]:current(args = [Guess, Code, Bulls, Cows]), 
        display_mastermind(Code, Guess, Bulls, Cows).

Code = mastermind(red, red, red, red, white)
Guess = mastermind(blue, blue, blue, blue, blue)
Bulls = 0
Cows = 3

The output of the call to display_mastermind is given in Figure 4.

  

Figure 4: Board output of display_mastermind/4

Indeed the number of cows is wrong. We can investigate source files thanks to the command listing/2 of the source scenario. Even simpler, when the current predicate is the one we want to source, we can use listing_current_procedure/0 (lcp/0) command. That is what we do here:

[Morphine]: listing_current_procedure.

:- pred check_mastermind(mastermind, mastermind, int, int).
:- mode check_mastermind(in, in, out, out) is det.
check_mastermind(Guess, Code, Bulls, Cows) :-
         count_bulls(Guess, Code, Bulls, Guess2, Code2),
         % Code2 and  Guess2 is the same as Code and Guess except that 
         % we have removed the well placed whatsits.
         count_cows(Guess2, Code2, Cows).

Since the bug symptom is a bad number of cows, the bug is probably inside the count_cows/2 predicate. Let us have a look at it.

[Morphine]: listing(mastermind_checker, count_cows).

:- pred count_cows(mastermind, mastermind, int).
:- mode count_cows(in, in, out) is det.
count_cows(Guess, Code, Cows) :-
        % Outputs the number of cows in the Guess.
        Guess = mastermind(G1, G2, G3, G4, G5),
        Code = mastermind(Color1, Color2, Color3, Color4, Color5),
        List1 = [G1, G2, G3, G4, G5],
        remove_cows_from_list(Color1, List1, List2),
        remove_cows_from_list(Color2, List2, List3),
        remove_cows_from_list(Color3, List3, List4),
        remove_cows_from_list(Color4, List4, List5),
        remove_cows_from_list(Color5, List5, List6),
        list__length(List6, M),
        Cows is 5 - M.

The only non-library predicate that is called within count_cows/2 is the predicate remove_cows_from_list/3. So we would like to check if this predicate outputs correct data. We want to go to the exit of the first call to remove_cows_from_list/3 that occurs inside count_cows/2. This can be translated in Morphine into the following request:

[Morphine]: fget([name = count_cows, port = call]), 
        fget([name = remove_cows_from_list, port = exit]), 
        current(depth = D).

1432614:  call count_cows(mastermind(hole, hole, hole, hole, blue), 
  mastermind(hole, hole, hole, hole, white), -)  

1432632:  exit remove_cows_from_list(hole, [], [])  
D = 14     More? (;) ;

1432633:  exit remove_cows_from_list(hole, [blue], [hole])   
D = 13     More? (;)

The goal remove_cows_from_list(Elt, ListIn, ListOut) is supposed to output in ListOut the list ListIn where all the occurrences of Elt have been removed. Here, the predicate remove_cows_from_list/3 which outputs the list [hole] should have output the list verb+[blue]+.

As hole is a special color, we could want to make sure that remove_cows_from_list/3 is also wrong with normal colors. We can filter out events where the first argument of remove_cows_from_list/3 is hole.

[Morphine]: fget_np([name = remove_cows_from_list, port = exit]),
        current(args = [X, -, -]), 
        X \= hole, 
        print_event.
        
1432724:  exit remove_cows_from_list(white, [], [])  
 
X = white     More? (;) ;
1432725:  exit remove_cows_from_list(white, [hole], [white])  

X = white     More? (;) 
1432726:  exit remove_cows_from_list(white, [hole, hole], [white, white])

That is not exactly what we were looking for. We would like to filter out events where the hole appears in the list of the second argument of remove_cows_from_list/3 too.

[Morphine]: fget_np([name = remove_cows_from_list, port = exit]), 
        current(args = [X, [Y], -]),
        X \= hole,
        Y \= hole,
        print_event.        
       
1434263:  exit remove_cows_from_list(black, [white], [black])  

X = black
Y = [white]
Z = white     More? (;)

Now we are definitely convinced that remove_cows_from_list/3 is buggy: here the answer should have been remove_cows_from_list(black, [white], [white]).

[Morphine]: listing_current_procedure.

:- pred remove_cows_from_list(color, list(color), list(color)).
:- mode remove_cows_from_list(in, in, out) is det.
% remove_cows_from_list(Elt, ListIn, ListOut) outputs in ListOut
% the list ListIn where all the occurrences of Elt has been removed.
remove_cows_from_list(_, [], []).
remove_cows_from_list(C, [X | Xs], ListOut) :-
        ( 
                C = X,
                C \= hole
         ->
                ListOut = Xs
        ;
                remove_cows_from_list(C, Xs, List),
                ListOut = [C | List]
        ).

Assuming that we still do not see where the bug is, we can do a breath-first trace of this predicate. to do that, we can define ourselves a zoom/1 command+ that will perform a breath-first trace.

[Morphine]: [user].
zoom(D) :-
         current(depth = D1), 
         D2 is D1 + 1, 
         fget_np([depth = [D1, D2]]),
         current(depth = D), 
         ( D == D2 ->  
                 current(port = P),
                 external(port = P) 
         ;   
                 true
         ),
         print_event.
 
external_port(call).
external_port(exit).
external_port(fail).
external_port(redo).
^d  
 user       compiled traceable 788 bytes in 0.00 seconds

Before starting the breath-first trace, we go to an `interesting' event namely: a call to remove_cows_from_list with first argument a color that is not a hole and second one a list containing one color that is not a hole.

[Morphine]: retry.
1364204:  det remove_cows_from_list(yellow, [white], -) [] 

[Morphine]: zoom(D).
1364215:  switch remove_cows_from_list(yellow, [white], -) [s1]

D = 23     More? (;) 
1364216:  else remove_cows_from_list(yellow, [white], -) [s1,c2e]

D = 23     More? (;) 
1364217:  call remove_cows_from_list(yellow, [], -)  

D = 24     More? (;) 
1364219:  exit remove_cows_from_list(yellow, [], [])  

D = 24     More? (;) 
1364220:  exit remove_cows_from_list(yellow, [white], [yellow])

Indeed, remove_cows_from_list should output [X | List] and not [C | List].