Debugging

The Logtalk distribution includes a command-line debugger tool implemented as a Logtalk application using the debugging API. It can be loaded at the top-level interpreter by typing:

| ?- logtalk_load(debugger(loader)).

It can also be loaded automatically at startup time by using a settings file.

The debugger tool includes the debugging features found in traditional Prolog debuggers. There are some differences, however, between the usual implementation of Prolog debuggers and the current implementation of the Logtalk debugger that you should be aware. First, unlike most Prolog debuggers, the Logtalk debugger is not a built-in feature but a regular Logtalk application using documented debugging hook predicates. This translates to a different, although similar, set of debugging features when compared with some of the more sophisticated Prolog debuggers. Second, debugging is only possible for entities compiled in debug mode. When compiling an entity in debug mode, Logtalk decorates clauses with source information to allow tracing of the goal execution. Third, the tool provides several types of breakpoints (for pausing and interacting with the debugger) and also log points while most Prolog systems are limited to traditional predicate spy points.

Compiling source files in debug mode

Compilation of source files in debug mode is controlled by the debug compiler flag. The default value for this flag, usually off, is defined in the adapter files. Its default value may be changed globally at runtime by calling:

| ?- set_logtalk_flag(debug, on).

Implicitly, this goal also turns off the optimize flag. In alternative, if we want to compile only some source files in debug mode, we may instead write:

| ?- logtalk_load([file1, file2, ...], [debug(on)]).

The logtalk_make/1 built-in predicate can also be used to recompile all loaded files (that were compiled without using explicit values for the debug and optimize compiler flags in a logtalk_load/2 call or in a loader file file, if used) in debug mode:

| ?- logtalk_make(debug).

With most backend Prolog compilers, the {+d} top-level shortcut can also be used. After debugging, the files can be recompiled in normal or optimized mode using, respectively, the {+n} or {+o} top-level shortcuts.

Warning

The clean compiler flag should be turned on whenever the debug flag is turned on at runtime. This is necessary because debug code would not be generated for files previously compiled in normal or optimized mode if there are no changes to the source files.

After loading the debugger, we may check (or enumerate by backtracking), all loaded entities compiled in debug mode as follows:

| ?- debugger::debugging(Entity).

To compile only a specific entity in debug mode, use the set_logtalk_flag/2 directive inside the entity. To compile all entities in a source file in debug mode, use the set_logtalk_flag/2 directive at the beginning of the file.

Procedure box model

Logtalk uses a procedure box model similar to those found on most Prolog systems. The traditional Prolog procedure box model defines four ports (call, exit, redo, and fail) for describing control flow when calling a predicate:

call
predicate call
exit
success of a predicate call
redo
backtracking into a predicate
fail
failure of a predicate call

Logtalk, as found on some recent Prolog systems, adds a port for dealing with exceptions thrown when calling a predicate:

exception
predicate call throws an exception

In addition to the ports described above, Logtalk adds two more ports, fact and rule, which show the result of the unification of a goal with, respectively, a fact and a rule head:

fact
unification success between a goal and a fact
rule
unification success between a goal and a rule head

Following Prolog tradition, the user may define for which ports the debugger should pause for user interaction by specifying a list of leashed ports. Unleashed ports are just printed with no pause for user interaction when tracing. For example:

| ?- debugger::leash([call, exit, fail]).

Alternatively, the user may use an atom abbreviation for a pre-defined set of ports. For example:

| ?- debugger::leash(loose).

The abbreviations defined in Logtalk are similar to those defined on some Prolog compilers:

none
[]
loose
[fact, rule, call]
half
[fact, rule, call, redo]
tight
[fact, rule, call, redo, fail, exception]
full
[fact, rule, call, exit, redo, fail, exception]

By default, the debugger pauses at every port for user interaction.

Activating the debugger

The debuggerp::trace/0 and debuggerp::debug/0 predicates implicitly select the debugger tool as the active debug handler. If you have additional debug handlers loaded (e.g. the ports_profiler tool), those would no longer be active (there can be only one active debug handler at any given time). The debuggerp::nodebug/0 predicate implicitly deselects the debugger tool as the active debug handler.

Defining breakpoints

The debugger tool provides the following breakpoint types where the debugger pauses at a leashed port for user interaction:

  • Predicate breakpoints

    Traditional Prolog spy points defined using a predicate (or a non-terminal) indicator.

  • Clause breakpoints

    Defined using the location of a clause.

  • Conditional breakpoints

    Defined using the location of a clause and a condition for pausing.

  • Hit count breakpoints

    Defined using the location of a clause and an unification count expression as a condition for pausing.

  • Triggered breakpoints

    Defined using the location of a clause and another breakpoint that must be hit first as a condition for pausing.

  • Context breakpoints

    Defined using execution context and goal templates as a condition for pausing.

Clause breakpoints are checked when the current goal successfully unifies with a clause head. To simplify their definition, these are specified using the entity identifier instead of the file name (as all entities share a single namespace, an entity can only be defined in a single file) and the first line number of the clause head. But note that only some Prolog backends provide accurate source file term line numbers. Check the debugger tool documentation for details.

Defining predicate and clause breakpoints

Predicate and clause breakpoints can be defined using the debugger spy/1 predicate. The argument can be a predicate indicator (Name/Arity), a non-terminal indicator (Name//Arity), a clause location (expressed as an Entity-Line pair), or a list of breakpoints. For example:

| ?- debugger::spy(person-42).

All specified breakpoints added.
yes

| ?- debugger::spy(foo/2).

All specified breakpoints added.
yes

| ?- debugger::spy([foo/4, bar//1, agent-99]).

All specified breakpoints added.
yes

Note that setting a clause breakpoint implicitly removes any existing conditional breakpoint, triggered breakpoint, or log point for the same clause.

Unconditional clause and predicate breakpoints can be removed by using the debugger nospy/1 predicate. The argument can also be a list of breakpoints or a non-instantiated variable in which case all breakpoints will be removed. For example:

| ?- debugger::nospy(_).

All matching predicate and clause breakpoints removed.
yes

Defining conditional breakpoints

Conditional clause breakpoints are specified using the debugger spy/3 predicate. The condition can be a lambda expression, an unification count expression (see next section), or another breakpoint (see next section).

The supported lambda expressions are [Count, N, Goal]>>Condition and [Goal]>>Condition where Count is the unification count, N is the goal invocation number, and Goal is the goal that unified with the clause head; Condition is called in the context of the user pseudo-object and must not have any side effects. Some examples:

| ?- debugger::spy(planet, 76, [weight(m1,_)]>>true).

Conditional breakpoint added.
yes

Note that setting a conditional breakpoint will remove any existing clause breakpoint or log point for the same location.

Conditional breakpoints can be removed by using the debugger nospy/3 predicate. For example:

| ?- debugger::nospy(planet, _, _).

All matching conditional breakpoints removed.
yes

Defining hit count breakpoints

Conditional clause breakpoints that depend on the unification count are known as hit count clause breakpoints. The debugger pauses at a hit count breakpoint depending an unification count expression:

  • >(Count) - break when the unification count is greater than Count

  • >=(Count) - break when the unification count is greater than or equal to Count

  • =:=(Count) - break when the unification count is equal to Count

  • =<(Count) - break when the unification count is less than or equal to Count

  • <(Count) - break when the unification count is less than Count

  • mod(M) - break when the unification count modulo M is zero

  • Count - break when the unification count is greater than or equal to Count

For example:

?- debugger::spy(planet, 41, =<(2)).

Conditional breakpoint added. yes

Defining triggered breakpoints

Conditional clause breakpoints that depend on other clause breakpoint or on a log point are known as triggered clause breakpoints. The debugger only pauses at a triggered breakpoint if the clause breakpoint or log point it depends on is hit first. For example:

| ?- debugger::spy(mars, 98, planet-76).

Triggered breakpoint added.
yes

In this case, the debugger will break for user interaction at the unification port for the clause in the source file defining the mars object at line 98 if and only if the debugger stoped earlier at the unification port for the clause in the source file defining the planet category at line 76.

The debugger prints a ^ character at the beginning of the line for easy recognition of triggered breakpoints.

Defining context breakpoints

A context breakpoint is a tuple describing a message execution context and a goal:

(Sender, This, Self, Goal)

The debugger pauses for user interaction whenever the breakpoint goal and execution context subsumes the goal currently being executed and its execution context. The user may establish any number of context breakpoints as necessary. For example, in order to call the debugger whenever a predicate defined on an object named foo is called we may define the following context breakpoint:

| ?- debugger::spy(_, foo, _, _).

Spy point set.
yes

For example, we can spy all calls to a foo/2 predicate with a bar atom in the second argument by setting the condition:

| ?- debugger::spy(_, _, _, foo(_, bar)).

Spy point set.
yes

The debugger nospy/4 predicate may be used to remove all matching breakpoints. For example, the call:

| ?- debugger::nospy(_, _, foo, _).

All matching context breakpoints removed.
yes

will remove all context breakpoints where the value of self is the atom foo.

Removing all breakpoints

We can remove all breakpoints by using the debugger nospyall/0 predicate:

| ?- debugger::nospyall.

All breakpoints removed.
yes

There’s also a reset/0 predicate that can be used to reset the debugger to its default settings and delete all defined breakpoints and log points.

Defining log points

Logtalk log points are similar to breakpoints and thus the line number must correspond to the first line of an entity clause. When the debugger reaches a log point, it prints a log message and continues without halting execution for taking a port command. When the log message is an empty atom, the default port output message is printed. When the log message starts with a % character, the default port output message is printed followed by the log message. In these two cases, the debugger prints a @ character at the beginning of the line for easy recognition of log points output. When the log message is neither empty or starts with a % character, the log message is printed instead of the default port output message. In this case, the message can contain $KEYWORD placeholders that are expanded at runtime. The valid keywords are:

  • PORT

  • ENTITY

  • CLAUSE_NUMBER

  • FILE

  • LINE

  • UNIFICATION_COUNT

  • INVOCATION_NUMBER

  • GOAL

  • PREDICATE

  • EXECUTION_CONTEXT

  • SENDER

  • THIS

  • SELF

  • METACALL_CONTEXT

  • COINDUCTION_STACK

  • THREAD

Log points are defined using the log/3 predicate. For example:

| ?- debugger::log(agent, 99, '% At the secret headquarters!').
     Log point added.
yes

| ?- debugger::log(loop, 42, 'Message $PREDICATE from $SENDER at thread $THREAD').
     Log point added.
yes

Predicates logging/3 and nolog/3 can be used to, respectively, query and remove log points. There’s also a nologall/0 predicate that removes all log points.

Note that setting a log point will remove any existing clause breakpoint for the same location.

Tracing program execution

Logtalk allows tracing of execution for all objects compiled in debug mode. To start the debugger in trace mode, write:

| ?- debugger::trace.

yes

Next, type the query to be debugged. For examples, using the family example in the Logtalk distribution compiled for debugging:

| ?- addams::sister(Sister, Sibling).
     Call: (1) sister(_1082,_1104) ?
     Rule: (1) sister(_1082,_1104) ?
     Call: (2) ::female(_1082) ?
     Call: (3) female(_1082) ?
     Fact: (3) female(morticia) ?
    *Exit: (3) female(morticia) ?
    *Exit: (2) ::female(morticia) ?
    ...

While tracing, the debugger will pause for user input at each leashed port, printing an informative message. Each trace line starts with the port, followed by the goal invocation number, followed by the goal. The invocation numbers are unique and allows us to correlate the ports used for a goal. In the output above, you can see for example that the goal ::female(_1082) succeeds with the answer ::female(morticia). The debugger also provides determinism information by prefixing the exit port with a * character when a call succeeds with choice-points pending, thus indicating that there might be alternative solutions for the goal.

Note that breakpoints are ignored when tracing. But when a breakpoint is set for the current predicate or clause, the debugger prints, before the port name and number, a + character for predicate breakpoints, a # character for clause breakpoints, a ? character for conditional clause breakpoints, a ^ for triggered breakpoints, and a * character for context breakpoints. For example:

| ?- debugger::spy(female/2).

yes

| ?- addams::sister(Sister, Sibling).
     Call: (1) sister(_1078,_1100) ?
     Rule: (1) sister(_1078,_1100) ?
     Call: (2) ::female(_1078) ?
  +  Call: (3) female(_1078) ?

To stop tracing (but still allowing the debugger to pause at the defined breakpoints), write:

| ?- debugger::notrace.

yes

Debugging using breakpoints

Tracing a program execution may generate large amounts of debugging data. Debugging using breakpoints allows the user to concentrate in specific points of the code. To start a debugging session using breakpoints points, write:

| ?- debugger::debug.

yes

For example, assuming the predicate breakpoint we set in the previous section on the female/1 predicate:

| ?- addams::sister(Sister, Sibling).
  +  Call: (3) female(_1078) ?

To stop the debugger, write:

| ?- debugger::nodebug.

yes

Note that stopping the debugger does not remove any defined breakpoints or and log points.

Debugging commands

The debugger pauses for user interaction at leashed ports when tracing and when hitting a breakpoint. The following commands are available:

c — creep

go on; you may use the spacebar, return, or enter keys in alternative

l — leap

continues execution until the next breakpoint is found

s — skip

skips tracing for the current goal; valid at call, redo, and unification ports

S - Skip

similar to skip but displaying all intermediate ports unleashed

q — quasi-skip

skips tracing until returning to the current goal or reaching a breakpoint; valid at call and redo ports

r — retry

retries the current goal but side-effects are not undone; valid at the fail port

j — jump

reads invocation number and continues execution until a port is reached for that number

z — zap

reads either a port name and continues execution until that port is reached or a negated port name and continues execution until a port other than the negated port is reached

i — ignore

ignores goal, assumes that it succeeded; valid at call and redo ports

f — fail

forces backtracking; may also be used to convert an exception into a failure

n — nodebug

turns off debugging

N — notrace

turns off tracing

@ — command; ! can be used in alternative

reads and executes a query

b — break

suspends execution and starts new interpreter; type end_of_file to terminate

a — abort

returns to top level interpreter

Q — quit

quits Logtalk

p — print

writes current goal using the print/1 predicate if available

d — display

writes current goal without using operator notation

w — write

writes current goal quoting atoms if necessary

$ — dollar

outputs the compiled form of the current goal (for low-level debugging)

x — context

prints execution context

. — file

prints file, entity, predicate, and line number information at an unification port

e — exception

prints exception term thrown by the current goal

E — raise exception

reads and throws an exception term

= — debugging

prints debugging information

< — write depth

sets the write term depth (set to 0 to reset)

* — add

adds a context breakpoint for the current goal

/ — remove

removes a context breakpoint for the current goal

+ — add

adds a predicate breakpoint for the current goal

- — remove

removes a predicate breakpoint for the current goal

# — add

adds a breakpoint for the current clause

| — remove

removes a breakpoint for the current clause

h — condensed help

prints list of command options

? — extended help

prints list of command options

Customizing term writing

Debugging complex applications often requires customizing term writing. The available options are limiting the writing depth of large compound terms and using the p command at a leashed port. This command uses the format/3 de facto standard predicate with the ~p formatting option to delegate writing the term to the print/1 predicate. But note that some backends don’t support this formatting option.

Term write depth

The terms written by the debugger can be quite large depending on the application being debugged. As described in the previous section, the debugger accepts the < command to set the maximum write term depth for compound terms. This commmand requires that the used backend Prolog compiler supports the non-standard but common max_depth/1 option for the write_term/3 predicate. When the compound term being written is deeply nested, the sub-terms are only written up to the specified depth with the omitted sub-terms replaced usually by .... For example:

| ?- write_term([0,1,2,3,4,5,6,7,8,9], [max_depth(5)]).

[0,1,2,3,4|...]
yes

The default maximum depth depends on the backend. To print compound terms without a depth limit, set it explicitly to zero if necessary.

Custom term writing

The implicit use of the traditional print/1 predicate (using the p command) and the portray/1 user-defined hook predicate requires backend Prolog compiler support for these predicates. See the documentation of the backend you intend to use for details. As an example, assuming the following portray/1 definition:

portray(e(V1,V2)) :-
    format('~q ---> ~q~n', [V1,V2]).

Calling the print/1 predicate with e.g. a e(x1,x7) compound term argument will output:

| ?- print(e(x1,x7)).

x1 ---> x7
yes

Context-switching calls

Logtalk provides a control construct, (<<)/2, which allows the execution of a query within the context of an object. Common debugging uses include checking an object local predicates (e.g. predicates representing internal dynamic state) and sending a message from within an object. This control construct may also be used to write unit tests.

Consider the following toy example:

:- object(broken).

    :- public(a/1).

    a(A) :- b(A, B), c(B).
    b(1, 2). b(2, 4). b(3, 6).
    c(3).

:- end_object.

Something is wrong when we try the object public predicate, a/1:

| ?- broken::a(A).

no

For helping diagnosing the problem, instead of compiling the object in debug mode and doing a trace of the query to check the clauses for the non-public predicates, we can instead simply type:

| ?- broken << c(C).

C = 3
yes

The (<<)/2 control construct works by switching the execution context to the object in the first argument and then compiling and executing the second argument within that context:

| ?- broken << (self(Self), sender(Sender), this(This)).

Self = broken
Sender = broken
This = broken

yes

As exemplified above, the (<<)/2 control construct allows you to call an object local and private predicates. However, it is important to stress that we are not bypassing or defeating an object predicate scope directives. The calls take place within the context of the specified object, not within the context of the object making the (<<)/2 call. Thus, the (<<)/2 control construct implements a form of execution-context switching.

The availability of the (<<)/2 control construct is controlled by the context_switching_calls compiler flag (its default value is defined in the adapter files of the backend Prolog compilers).

Debugging messages

Calls to the logtalk::print_message/3 predicate where the message kind is either debug or debug(Group) are only printed, by default, when the debug flag is turned on. Moreover, these calls are suppressed by the compiler when the optimize flag is turned on. Note that actual printing of debug messages does not require compiling the code in debug mode, only turning on the debug flag.

Meta-messages

To avoid having to define message_tokens//2 grammar rules for translating each and every debug message, Logtalk provides default tokenization for seven meta-messages that cover the most common cases:

@Message

By default, the message is printed as passed to the write/1 predicate followed by a newline.

Key-Value

By default, the message is printed as Key: Value followed by a newline. The key is printed as passed to the write/1 predicate while the value is printed as passed to the writeq/1 predicate.

Format+Arguments

By default, the message is printed as passed to the format/2 predicate.

List

By default, the list items are printed indented one per line. The items are preceded by a dash and can be @Message, Key-Value, or Format+Arguments messages. If that is not the case, the item is printed as passed to the writeq/1 predicate.

Title::List

By default, the title is printed followed by a newline and the indented list items, one per line. The items are printed as in the List meta message.

[Stream,Prefix]>>Goal

By default, call user-defined printing Goal in the context of user. The use of a lambda expression allows passing the message stream and prefix. Printing the prefix is delegated to the goal.

[Stream]>>Goal

By default, call user-defined printing Goal in the context of user. The use of a lambda expression allows passing the message stream.

Some simple examples of using these meta-messages:

| ?- logtalk::print_message(debug, core, @'Phase 1 completed').
yes

| ?- logtalk::print_message(debug, core, [Stream]>>write(Stream,foo)).
yes

| ?- set_logtalk_flag(debug, on).
yes

| ?- logtalk::print_message(debug, core, [Stream]>>write(Stream,foo)).
foo
yes

| ?- logtalk::print_message(debug, core, @'Phase 1 completed').
>>> Phase 1 completed
yes

| ?- logtalk::print_message(debug, core, answer-42).
>>> answer: 42
yes

| ?- logtalk::print_message(debug, core, 'Position: <~d,~d>'+[42,23]).
>>> Position: <42,23>
yes

| ?- logtalk::print_message(debug, core, [arthur,ford,marvin]).
>>> - arthur
>>> - ford
>>> - marvin
yes

| ?- logtalk::print_message(debug, core, names::[arthur,ford,marvin]).
>>> names:
>>> - arthur
>>> - ford
>>> - marvin
yes

The >>> prefix is the default message prefix for debug messages. It can be redefined using the logtalk::message_prefix_stream/4 hook predicate. For example:

:- multifile(logtalk::message_prefix_stream/4).
:- dynamic(logtalk::message_prefix_stream/4).

logtalk::message_prefix_stream(debug, core, '(dbg) ', user_error).

Selective printing of debug messages

By default, all debug messages are either printed or skipped, depending on the debug and optimize flags. When the code is not compiled in optimal mode, the debug_messages tool allows selectively enabling of debug messages per component and per debug group. For example, to enable all debug and debug(Group) messages for the parser component:

% upon loading the tool, all messages are disabled by default:
| ?- logtalk_load(debug_messages(loader)).
...

% enable both debug and debug(_) messages:
| ?- debug_messages::enable(parser).
yes

To enable only debug(tokenization) messages for the parser component:

% first disable any and all enabled messages:
| ?- debug_messages::disable(parser).
yes

% enable only debug(tokenization) messages:
| ?- debug_messages::enable(parser, tokenization).
yes

See the tool documentation for more details.

Using the term-expansion mechanism for debugging

Debugging messages only output information by default. These messages can, however, be intercepted to perform other actions. An alternative is to use instead the term-expansion mechanism for conditional compilation of debugging goals. For example, the hook_objects library provides a print_goal_hook object that simplifies printing entity goals before or after calling them by simply prefixing them with an operator. See the library and hook object documentation for details. You can also define your own specialized hook objects for custom debugging tasks.

Ports profiling

The Logtalk distribution includes a ports_profiler tool based on the same procedure box model described above. This tool is specially useful for debugging performance issues (e.g. due to lack of determinism or unexpected backtracking). See the tool documentation for details.

Debug and trace events

The debugging API defines two multifile predicates, logtalk::trace_event/2 and logtalk::debug_handler/3 for handiling trace and debug events. It also provides a logtalk::debug_handler/1 multifile predicate that allows an object (or a category) to declare itself as a debug handler provider. The Logtalk debugger and ports_profiler tools are regular applications thar are implemented using this API, which can also be used to implement alternative or new debugging related tools. See the API documentation for details and the source code of the debugger and ports_profiler tools for usage examples.

To define a new debug handler provider, add (to an object or category) clauses for the debug_handler/1 and debug_handler/3 predicates. For example:

% declare my_debug_handler as a debug handler provider
:- multifile(logtalk::debug_handler/1).
logtalk::debug_handler(my_debug_handler).

% handle debug events
:- multifile(logtalk::debug_handler/3).
logtalk::debug_handler(my_debug_handler, Event, ExCtx) :-
    debug_handler(Event, ExCtx).

debug_handler(fact(Entity,Fact,Clause,File,Line), ExCtx) :-
    ...
debug_handler(rule(Entity,Head,Clause,File,Line), ExCtx) :-
    ...
debug_handler(top_goal(Goal, TGoal), ExCtx) :-
    ...
debug_handler(goal(Goal, TGoal), ExCtx) :-
    ...

Your debug handler provider should also either automatically call the logtalk::activate_debug_handler/1 and logtalk::deactivate_debug_handler/0 predicate or provide public predicates to simplify calling these predicates. For example:

:- public(start/0).
start :-
   logtalk::activate_debug_handler(my_debug_handler).

:- public(stop/0).
stop :-
   logtalk::deactivate_debug_handler.

If you only need to define a trace event handler, then simply define clauses for the logtalk::trace_event/2 multifile predicate:

:- multifile(logtalk::trace_event/2).
:- dynamic(logtalk::trace_event/2).

% the Logtalk runtime calls all defined logtalk::trace_event/2 hooks using
% a failure-driven loop; thus we don't have to worry about handling all
% events or failing after handling an event to give other hooks a chance
logtalk::trace_event(fact(Entity, Fact, N, _, _), _) :-
    ...
logtalk::trace_event(rule(Entity, Head, N, _, _), _) :-
    ...