Modifying debug/3 by using message_prefix_hook/2

Nice to know
1

Recently needed to check the corrdination of events for a web page and server. The server was created using SWI-Prolog and the client created using HTML and JavaScript. When trying to check/debug such code it is nice to see a combined and time sorted listing of the events from any source. debug/3 with :- set_prolog_flag(message_context, [time,thread]). would sovle this but wanted the date as part of the time and also the time based on UTC and not local time.

In reading the SWI-Prolog documenation found message_prefix_hook/2 but not many examples so here is one.

An example use in code.

Create a file named debug.pl

:- use_module(library(debug)).

:- debug(myapp(_)).

:- use_module(server).

Create a file named server.pl

Only code releated to message_prefix_hook/2 shown. Much more is needed to make this a working server.

:- module(server,[]).

:- multifile
    prolog:message_prefix_hook/2.

prolog:message_prefix_hook(utc_log_time,Prefix) :-
    get_time(Time_local),
    stamp_date_time(Time_local,Time_utc,'UTC'),
    format_time(string(Prefix),'%Y-%m-%d-%H-%M-%S-%3f',Time_utc).

:- set_prolog_flag(message_context, [utc_log_time,thread]).

foo(Bar) :-
    debug(myapp(foo),'foo entred',[]),

Example run

Welcome to SWI-Prolog (threaded, 64 bits, version 9.1.6)
...

?- working_directory(_,'C:/Users/Groot').
true.

?- [debug].
% Started server at http://localhost:8080/
true.

?-
% 2023-02-28-12-22-32-202 [Thread 10] foo entered
...

message_prefix_hook/2 can also be used to insert a constant value or change an existing context term.

This first examaple just inserts - Server - into every use of debug/3. The reason for doing this is that the client will likewise insert - Client - into the messages and when the two logs are combined and sorted, it will be eaiser to identify the source of the message.

prolog:message_prefix_hook(server,'- Server -').

The next example just pads the thread text so that the columns line up. Since message_prefix_hook/2 clauses are called first, any clause that fires will skip any further calls for the same context term.

prolog:message_prefix_hook(thread,Prefix) :-
    thread_self(Id0),
    (
        % If the thread has an alias use that as it should be unique
        thread_property(Id0,alias(Alias))
    ->
        format(string(Prefix), '[Thread ~|~w~` t~14+] ', [Alias])
    ;
        % Otherwise use the thread id but note that these can be recycled
        thread_property(Id0,id(Id))
    ->
        format(string(Prefix), '[Thread ~|~`0t~d~3+~` t~11+] ', [Id])
    ;
        fail % so that the default clause for context term can handle this.
    ).

Example of using all three.

:- set_prolog_flag(message_context, [utc_log_time,server,thread]).

% 2023-02-28-15-45-41-521 - Server - [Thread 010]

The corresponding JavaScript

function utcLogTime() {
  const now = new Date();
  const year = now.getUTCFullYear();
  const month = ('0' + (now.getUTCMonth() + 1)).slice(-2);
  const date = ('0' + now.getUTCDate()).slice(-2);
  const hours = ('0' + now.getUTCHours()).slice(-2);
  const minutes = ('0' + now.getUTCMinutes()).slice(-2);
  const seconds = ('0' + now.getUTCSeconds()).slice(-2);
  const milliseconds = ('00' + now.getUTCMilliseconds()).slice(-3);
  return `${year}-${month}-${date}-${hours}-${minutes}-${seconds}-${milliseconds}`;
}

Note: In JavaScript, the Date.now() method and the performance.now() method are both used to obtain the current time. However, both of these methods only provide accuracy up to the millisecond level.

The Date.now() method returns the number of milliseconds that have elapsed since January 1, 1970, 00:00:00 UTC, whereas the performance.now() method returns the number of milliseconds that have elapsed since the current page started to load.

Both of these methods are useful for measuring time intervals or calculating time differences, but they cannot provide a higher level of precision than milliseconds.

1 Like