1 % (c) 2009-2022 Lehrstuhl fuer Softwaretechnik und Programmiersprachen,
2 % Heinrich Heine Universitaet Duesseldorf
3 % This software is licenced under EPL 1.0 (http://www.eclipse.org/org/documents/epl-v10.html)
4
5 :- module(logger, [set_log_file/1, get_log_file/1, set_logging_mode/1,
6 writeln_log/1,
7 writeln_log_time/1,
8 write_xml_element_to_log/2,
9 write_prolog_term_as_xml_to_log/1,
10 write_bstate_to_log/1, write_bstate_to_log/2,
11 start_xml_group_in_log/1, start_xml_group_in_log/3,
12 stop_xml_group_in_log/1, stop_xml_group_in_log_no_statistics/1,
13 close_all_xml_groups_in_log_until/1,
14 logging_is_enabled/0,
15 read_xml_log_file/2]).
16
17 :- use_module(module_information).
18
19 :- module_info(group,infrastructure).
20 :- module_info(description,'This module is responsible for (xml and prolog) logging.').
21
22
23 :- use_module(self_check).
24 :- use_module(error_manager).
25 :- use_module(probsrc(xml_prob),[xml_parse/3, xml_parse/2]).
26 :- use_module(library(lists)).
27
28 :- set_prolog_flag(double_quotes, codes).
29
30 :- dynamic logfile/1.
31 set_log_file(F) :- retractall(logfile(_)), assertz(logfile(F)).
32 get_log_file(F) :- logfile(F).
33
34 :- dynamic logging_mode/1.
35 logging_mode(prolog).
36 % valid modes: prolog and xml
37 set_logging_mode(Mode) :- retractall(logging_mode(_)), assertz(logging_mode(Mode)),
38 (Mode=xml -> format_log_header(reset,'<?xml version="1.0" encoding="UTF-8"?>~n',[]) ; true).
39
40 % TO DO: use:
41 %get_preference(xml_encoding,EncodingPref),
42
43 logging_is_enabled :- logfile(_),!.
44
45 prolog_log_file(F) :- logfile(F), logging_mode(prolog).
46
47 reset_logger :- retractall(open_xml_group(_,_)),
48 retractall(logfile(_)), set_logging_mode(prolog).
49
50 % TO DO: try and move most writeln_log calls to write_xml_element_to_log format
51 writeln_log(Term) :-
52 (prolog_log_file(F)
53 -> open(F,append,S,[encoding(utf8)]),
54 write_term(S,Term,[quoted(true)]), write(S,'.'),nl(S),
55 close(S)
56 ; true
57 ).
58
59 open_logfile(Stream) :- logfile(F), open(F,append,Stream,[encoding(utf8)]).
60
61 format_log(FormatString,Args) :- %format(FormatString,Args),nl,
62 (logfile(F)
63 -> open(F,append,S,[encoding(utf8)]),
64 format(S,FormatString,Args),
65 close(S)
66 ; true
67 ).
68
69 writeln_log_time(Term) :-
70 (prolog_log_file(_) ->
71 statistics(runtime,[Time,_]),
72 statistics(walltime,[WTime,_]),
73 statistics(memory_used,M), MB is M / 1000000, % used instead of deprecated 1048576
74 Term=..[H|Args],
75 append(Args,[Time,WTime,mb(MB)],NArgs),
76 NT =.. [H|NArgs],
77 writeln_log(NT)
78 ; true).
79
80 :- use_module(library(file_systems),[file_exists/1]).
81 format_log_header(reset,FormatString,Args) :- !, % reset means we want to start with a fresh log file
82 (logfile(F)
83 -> open(F,write,S,[encoding(utf8)]),
84 format(S,FormatString,Args),
85 close(S)
86 ; true
87 ).
88 format_log_header(_,FormatString,Args) :-
89 % like format_log, but only writes if the file does not exist yet
90 (logfile(F), \+ file_exists(F)
91 -> open(F,append,S,[encoding(utf8)]),
92 format(S,FormatString,Args),
93 close(S)
94 ; true
95 ).
96
97 :- assert_must_succeed((logger:xml_encode_text("b<>c",R),R=="b<>c")).
98 xml_encode_text(Codes,Res) :- XML = xml([],[pcdata(Codes)]), xml_parse(Encoded,XML),!,Res=Encoded.
99 xml_encode_text(Codes,Encoded) :- format(user_error,'Could not encode for XML: ~s~n',[Codes]),
100 Encoded=Codes.
101 % we could also use xml:pcdata_generation(Codes, Encoded, []).
102
103
104
105 :- assert_must_succeed((logger:xml_encode_element(check_goal,[true/1],R),R=="<check_goal true=\"1\" />")).
106 xml_encode_element(Tag,Attributes,Encoded2) :-
107 maplist(prepare_attribute,Attributes,XMLAttr),
108 XML = xml([],[element(Tag,XMLAttr,[])]),
109 xml_parse(Encoded,XML),
110 peel_off_leading_newline(Encoded,Encoded2).
111
112 peel_off_leading_newline([10|T],R) :- !, peel_off_leading_newline(T,R).
113 peel_off_leading_newline([13|T],R) :- !, peel_off_leading_newline(T,R).
114 peel_off_leading_newline(R,R).
115
116 % write a tag with attributes to the log file
117 write_xml_element_to_log(_,_) :- \+ logfile(_), !.
118 write_xml_element_to_log(Tag,Attributes) :- logging_mode(xml),!,
119 (xml_encode_element(Tag,Attributes,Encoded) -> true
120 ; add_internal_error('Could not encode xml: ',Tag),
121 Encoded = "<error/>"
122 ),
123 indent_log(WS),
124 format_log("~s~s~n",[WS,Encoded]).
125 write_xml_element_to_log(Tag,Attributes) :-
126 Term =.. [Tag,Attributes],
127 format_log("~w.~n",[Term]).
128
129 % write a Prolog Term either as Prolog Term in Prolog mode or in nested XML form
130 %write_term_to_log(Term) :- logging_mode(xml),!,
131 % write_prolog_term_as_xml_to_log(Term).
132 %write_term_to_log(Term) :- writeln_log(Term).
133
134 write_prolog_term_as_xml_to_log(A) :- number(A),!,
135 indent_log(WS),
136 format_log("~s<number>~w</number>~n",[WS,A]).
137 write_prolog_term_as_xml_to_log(A) :- var(A),!,
138 indent_log(WS),
139 format_log("~s<variable>~w</variable>~n",[WS,A]).
140 write_prolog_term_as_xml_to_log(A) :- atomic(A),!, convert_to_codes(A,Codes),
141 xml_encode_text(Codes,Encoded),
142 indent_log(WS),
143 ? (is_a_file_path(Encoded) -> format_log("~s<path>~s</path>~n",[WS,Encoded])
144 ; format_log("~s<atom>~s</atom>~n",[WS,Encoded])).
145 write_prolog_term_as_xml_to_log(A/B) :- !,
146 start_xml_group_in_log(bind),
147 write_prolog_term_as_xml_to_log(A),
148 write_prolog_term_as_xml_to_log(B),
149 stop_xml_group_in_log_no_statistics(bind).
150 write_prolog_term_as_xml_to_log([H|T]) :- !, % Note: we assume we have a proper list !
151 start_xml_group_in_log(list),
152 maplist(write_prolog_term_as_xml_to_log,[H|T]),
153 stop_xml_group_in_log_no_statistics(list).
154 write_prolog_term_as_xml_to_log(T) :- T =.. [Functor|Args],
155 %TO DO, something like: escape / xml_encode_text(Functor,EFunc),
156 encode_functor(Functor,XML_Functor),
157 start_xml_group_in_log(XML_Functor),
158 maplist(write_prolog_term_as_xml_to_log,Args),
159 stop_xml_group_in_log_no_statistics(XML_Functor).
160
161 encode_functor('-',R) :- !, R='prolog-'.
162 encode_functor(X,X).
163
164 write_bstate_to_log(State) :- write_bstate_to_log(State,'').
165
166 % in response to logxml_write_vars
167 write_bstate_to_log(State,Prefix) :- logging_mode(xml),!,
168 start_xml_group_in_log(state),
169 atom_codes(Prefix,PrefixCodes),
170 (State=root -> start_xml_group_in_log(root), stop_xml_group_in_log_no_statistics(root)
171 ; maplist(write_b_binding_as_xml_to_log(PrefixCodes),State) -> true
172 ; add_internal_error('Could not write state to xml logfile: ',write_bstate_to_log(State))),
173 stop_xml_group_in_log_no_statistics(state).
174 write_bstate_to_log(_,_Prefix).
175
176 write_b_binding_as_xml_to_log(Prefix,bind(VarName,Value)) :-
177 atom_codes(VarName,Codes),
178 append(Prefix,_,Codes), % check that variable name starts with prefix
179 !,
180 start_xml_group_in_log(variable,name,VarName), % Not: already escapes for XML;
181 % TODO: distinguish between constants/variables
182 xml_write_b_value_to_log(Value),
183 stop_xml_group_in_log_no_statistics(variable).
184 write_b_binding_as_xml_to_log(_,_).
185
186 xml_write_b_value_to_log(Value) :-
187 open_logfile(Stream),
188 indent_log(WS),format(Stream,'~s ',[WS]),
189 xml_write_b_value(Value,Stream),
190 format(Stream,'~n',[]),
191 close(Stream).
192
193 :- use_module(probsrc(custom_explicit_sets),[expand_custom_set_to_list/2]).
194 :- use_module(probsrc(translate),[translate_bvalue_to_codes/2]).
195 xml_write_b_value_map(Stream,O) :- xml_write_b_value(O,Stream).
196 xml_write_b_value(Var,Stream) :- var(Var),!,
197 add_internal_error('Illegal variable value:',xml_write_b_value(Var,Stream)),
198 format(Stream,'<value>~w</value>',[Var]).
199 xml_write_b_value((Fst,Snd),Stream) :- !,
200 write(Stream,'<pair><fst>'),
201 xml_write_b_value(Fst,Stream),
202 write(Stream,'</fst><snd>'),
203 xml_write_b_value(Snd,Stream),
204 write(Stream,'</snd></pair> ').
205 xml_write_b_value([],Stream) :- !,write(Stream,'<empty_set></empty_set> ').
206 xml_write_b_value(CS,Stream) :- custom_set_to_expand(CS),!,
207 expand_custom_set_to_list(CS,Elements),
208 write(Stream,'<set>'),
209 maplist(xml_write_b_value_map(Stream),Elements),
210 write(Stream,'</set> ').
211 xml_write_b_value([H|T],Stream) :- !,
212 write(Stream,'<set>'),
213 maplist(xml_write_b_value_map(Stream),[H|T]),
214 write(Stream,'</set> ').
215 xml_write_b_value(rec(Fields),Stream) :- !,
216 write(Stream,'<record>'),
217 maplist(xml_write_b_field_value(Stream),Fields),
218 write(Stream,'</record> ').
219 xml_write_b_value(string(S),Stream) :- !,
220 atom_codes(S,Codes),
221 xml_encode_text(Codes,Encoded),
222 format(Stream,'<string>~s</string>',[Encoded]).
223 xml_write_b_value(int(N),Stream) :- !,
224 format(Stream,'<integer>~w</integer>',[N]).
225 xml_write_b_value(pred_true,Stream) :- !,
226 format(Stream,'<bool>TRUE</bool>',[]).
227 xml_write_b_value(pred_false,Stream) :- !,
228 format(Stream,'<bool>FALSE</bool>',[]).
229 xml_write_b_value(fd(Nr,Type),Stream) :- !,
230 translate_bvalue_to_codes(fd(Nr,Type),SValue),
231 format(Stream,"<enum type=\"~w\" nr=\"~w\">~s</enum>",[Type,Nr,SValue]).
232 xml_write_b_value(Value,Stream) :-
233 is_custom_explicit_set(Value,xml_write),
234 is_interval_closure(Value,Low,Up),
235 !,
236 write(Stream,'<interval_set><from>'),
237 xml_write_b_value(int(Low),Stream),
238 write(Stream,'</from><to>'),
239 xml_write_b_value(int(Up),Stream),
240 write(Stream,'</to></interval_set>').
241 xml_write_b_value(Value,Stream) :- % other value, freetype, freeval, closure, ...
242 is_custom_explicit_set(Value,xml_write),
243 !,
244 translate_bvalue_to_codes(Value,SValue),
245 xml_encode_text(SValue,Encoded),
246 format(Stream,'<symbolic_set>~s</symbolic_set>',[Encoded]).
247 xml_write_b_value(Value,Stream) :- % other value freeval, ...
248 translate_bvalue_to_codes(Value,SValue),
249 xml_encode_text(SValue,Encoded),
250 format(Stream,'<value>~s</value>',[Encoded]).
251 % TO DO: check if there are uncovered values, e.g., freeval(ID,Case,Value)
252
253 :- use_module(custom_explicit_sets,[is_interval_closure/3,
254 is_custom_explicit_set/2, dont_expand_this_explicit_set/2]).
255 custom_set_to_expand(avl_set(_)).
256 custom_set_to_expand(CS) :- nonvar(CS),
257 is_custom_explicit_set(CS,xml_write),
258 \+ dont_expand_this_explicit_set(CS,1000).
259
260 xml_write_b_field_value(Stream,field(Name,Val)) :-
261 atom_codes(Name,Codes), xml_attribute_escape(Codes,Encoded),
262 format(Stream,'<field name=\"~s\">',[Encoded]),
263 xml_write_b_value(Val,Stream), write(Stream,'</field>').
264
265 % ---------------------------
266
267 :- use_module(tools,[host_platform/1]).
268 ?is_a_file_path(Codes) :- member(47,Codes).
269 is_a_file_path(Codes) :- host_platform(windows), member(92,Codes). % windows
270
271 prepare_attribute('='(Tag,Atom),'='(Tag,Codes)) :- convert_to_codes(Atom,Codes).
272 prepare_attribute('/'(Tag,Atom),'='(Tag,Codes)) :- convert_to_codes(Atom,Codes).
273
274 :- use_module(library(codesio),[write_to_codes/2]).
275 convert_to_codes(V,Codes) :- var(V),!,Codes="_".
276 convert_to_codes([H|T],Codes) :- number(H),!, Codes=[H|T].
277 convert_to_codes(N,Codes) :- number(N),!, number_codes(N,Codes).
278 convert_to_codes(A,Codes) :- atom(A),!,atom_codes(A,Codes).
279 convert_to_codes(A,Codes) :- write_to_codes(A,Codes).
280
281 :- dynamic open_xml_group/2, nesting_level/1.
282 nesting_level(0).
283 update_nesting_level(X) :- retract(nesting_level(Y)),
284 New is Y+X, assertz(nesting_level(New)).
285
286 space(32).
287 indent_log(WS) :- nesting_level(Lvl), length(WS,Lvl),
288 maplist(space,WS).
289
290 ?check_and_generate_group_stats(Group,Stats) :- open_xml_group(A,_),!,
291 (A=Group
292 -> retract(open_xml_group(Group,WTimeStart)),
293 (Stats=no_statistics -> true
294 ; statistics(walltime,[WTimeEnd,_]),
295 Delta is WTimeEnd - WTimeStart,
296 statistics(memory_used,M),
297 write_xml_element_to_log(statistics,[walltime/Delta,walltime_since_start/WTimeEnd,memory_used/M])
298 ),
299 update_nesting_level(-1)
300 ; add_internal_error('XML closing tag mismatch: ', Group/A),
301 stop_xml_group_in_log(A,Stats), % close offending group and try again
302 check_and_generate_group_stats(Group,Stats)
303 ).
304 check_and_generate_group_stats(Group,_) :-
305 add_internal_error('XML closing tag error, no tag open: ', Group).
306
307 start_xml_group_in_log(Group) :- logging_mode(xml),!,
308 statistics(walltime,[WTime,_]),
309 indent_log(WS),
310 asserta(open_xml_group(Group,WTime)),
311 update_nesting_level(1),
312 format_log("~s<~w>~n",[WS,Group]).
313 start_xml_group_in_log(_).
314
315 :- use_module(tools, [xml_attribute_escape/2]). % attribute values have a less stringent encoding than xml_encode_text
316 % we currently only support a single attribute and value
317 start_xml_group_in_log(_,_,_) :- \+ logging_mode(xml),!.
318 start_xml_group_in_log(Group,Attr,Value) :-
319 statistics(walltime,[WTime,_]),
320 indent_log(WS),
321 asserta(open_xml_group(Group,WTime)),
322 update_nesting_level(1),
323 convert_to_codes(Value,ValueC),
324 xml_attribute_escape(ValueC,EValueC),
325 format_log("~s<~w ~w=\"~s\">~n",[WS,Group,Attr,EValueC]),!.
326 start_xml_group_in_log(Group,Attr,Value) :-
327 add_internal_error('Call failed: ', start_xml_group_in_log(Group,Attr,Value)).
328
329 stop_xml_group_in_log(_,_) :- \+ logging_mode(xml),!.
330 stop_xml_group_in_log(Group,Stats) :-
331 check_and_generate_group_stats(Group,Stats),
332 indent_log(WS),
333 format_log("~s</~w>~n",[WS,Group]),!.
334 stop_xml_group_in_log(Group,Stats) :-
335 add_internal_error('Call failed: ', stop_xml_group_in_log(Group,Stats)).
336
337
338 stop_xml_group_in_log(Group) :- stop_xml_group_in_log(Group,statistics).
339 stop_xml_group_in_log_no_statistics(Group) :- stop_xml_group_in_log(Group,no_statistics).
340
341 % call if you need to prematurely exit probcli
342 %close_all_xml_groups_in_log :- close_all_xml_groups_in_log_until('probcli-run').
343 close_all_xml_groups_in_log_until(Until) :- open_xml_group(Group,_), Until \== Group,
344 !,
345 stop_xml_group_in_log(Group),
346 close_all_xml_groups_in_log_until(Until).
347 close_all_xml_groups_in_log_until(_).
348
349
350
351 :- use_module(tools, [safe_read_string_from_file/3]).
352 :- use_module(debug, [formatsilent/2]).
353
354 read_xml_log_file(File,[errors/NrErrors,warnings/NrWarnings,expected_errors/NrExpErrors]) :-
355 Encoding=auto, % (must be "auto", "UTF-8", "UTF-16", "ISO-8859-1",...)
356 statistics(walltime,_),
357 absolute_file_name(File,AFile),
358 safe_read_string_from_file(AFile,Encoding,Codes),
359 (xml_parse(Codes,xml(_Atts,Content),[format(true)]) -> true
360 ; add_error(read_xml,'Converting file contents to XML failed: ',AFile),fail),
361 statistics(walltime,[_,W2]),
362 formatsilent('% Walltime ~w ms to parse and convert XML in ~w~n',[W2,AFile]),
363 Content = [element('probcli-run',[],InnerContent)|_],
364 check_log(InnerContent,0),
365 member(element('probcli-errors',[errors=EC,warnings=WC|TErrs],[]),InnerContent),
366 number_codes(NrErrors,EC),
367 number_codes(NrWarnings,WC),
368 (member(expected_errors=ExpE,TErrs),number_codes(NrExpErrors,ExpE) -> true ; NrExpErrors=0).
369
370 %extract_xml_log_file([element('probcli-run',[],Cont],Entries) :-
371 %extract_entry(element(Name,Attrs,Content)
372
373 extract_attribute(Attr=Codes,Attr=Atom) :- atom_codes(Atom,Codes).
374
375 % TO DO: extract interesting information, e.g., for test_runner
376 check_log([],_) :- !.
377 check_log([H|T],Level) :- !, L1 is Level+1, check_log(H,L1),
378 check_log(T,Level).
379 check_log(element(Name,Attrs,Cont),Level) :- maplist(extract_attribute,Attrs,EAttrs),
380 !,
381 indentws(Level), format('<~w ~w>~n',[Name,EAttrs]),
382 L1 is Level + 1,
383 check_log(Cont,L1).
384 check_log(pcdata(L),Level) :- !, indentws(Level), format('~s~n',[L]).
385 check_log(X,Level) :- indentws(Level),print(X),nl.
386
387 indentws(0) :- !.
388 indentws(X) :- X>0, print(' '), X1 is X-1, indentws(X1).
389
390 /*
391 <?xml version="1.0" encoding="ASCII"?>
392
393 | ?- xml_parse("<PT ID=\"2\" stID=\"3\"/>",R).
394 R = xml([],[element('PT',['ID'=[50],stID=[51]],[])]) ?
395
396 <PointsTelegram elementID="W90" stationID="FR" interlockingID="FR" interlockingElementID="W90"/>
397
398
399 */
400
401 % -------------------------------------------
402
403 :- use_module(eventhandling,[register_event_listener/3]).
404 :- register_event_listener(reset_prob,reset_logger,
405 'Reset Logger just like after starup_prob').
406