1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
|
% !TeX root = ../arara-manual.tex
\chapter{Logging}
\label{chap:logging}
The logging feature of \arara, as discussed earlier on, is activated through either the \opbox{{-}log} command line option (Section~\ref{sec:options}, on page~\pageref{sec:options}) or the equivalent key in the configuration file (Section~\ref{sec:basicstructure}, on page~\pageref{sec:basicstructure}). This chapter covers the basic structure of a typical log file provided by our tool, including the important blocks that can be used to identify potential issues. The following example is used to illustrate this feature:
\begin{ncodebox}{Source file}{teal}{\icnote}{white}{doc12.tex}
% arara: pdftex
% arara: clean: { extensions: [ log ] }
Hello world.
\bye
\end{ncodebox}
When running our tool on the previous example with the \opbox{{-}log} command line option (otherwise, the logging framework will not provide a file at all), we will obtain the expected \rbox{arara.log} log file containing the most significant events that happened during this particular execution, as well as details regarding the underlying operating system. The contents of this file are discussed below. Note that timestamps were deliberated removed from the log entries in order to declutter the output, and line breaks were included in order to easily spot each entry.
\section{System information}
\label{sec:systeminformation}
The very first entry to appear in the log file is the current version of \arara\ followed by a revision number. The revision number acts as a counter for the last review on the major version. The counter starts at 1 to denote the first release in the version 4.0 series. The revision number is also important to indicate possible new features introduced later on, in the application.
\begin{codebox}{Log file}{teal}{\icnote}{white}
Welcome to arara 4.0 (revision 1)!
\end{codebox}
The following entries in the log file are the absolute path of the current deployment of \arara\ (line 1), details about the current Java virtual machine (namely, vendor and absolute path, in lines 2 and 3, respectively), the underlying operating system information (namely, system name, architecture and eventually the kernel version, in line 4), home and working directories (lines 5 and 6, respectively), and the absolute path of the applied configuration file, if any (line 7). This block is very important to help with tracking possible issues related to the underlying operating system and the tool configuration itself.
\begin{codebox}{Log file}{teal}{\icnote}{white}
::: arara @ /opt/paulo/arara
::: Java 1.8.0_171, Oracle Corporation
::: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.171-4.b10.fc28.x86_64/jre
::: Linux, amd64, 4.16.12-300.fc28.x86_64
::: user.home @ /home/paulo
::: user.dir @ /home/paulo/Documents
::: CF @ [none]
\end{codebox}
\begin{messagebox}{A privacy note}{araracolour}{\icok}{white}
\setlength{\parskip}{1em}
I understand that the previous entries containing information about the underlying operating system might pose as a privacy threat to some users. However, it is worth noting that \arara\ does not share any sensitive information about your system, as entries are listed in the log file for debugging purposes only, locally in your computer.
From experience, these entries greatly help our users to track down errors in the execution, as well as learning more about the underlying operating system. However, be mindful of sharing your log file! Since the log file contains structured blocks, it is highly advisable to selectively choose the ones relevant to the current discussion.
\end{messagebox}
It is important to observe that localized messages are also applied to the log file. If a language other than English is selected, either through the \opbox{{-}language} command line option or the equivalent key in the configuration file, the logging framework will honour the current setting and entries will be available in the specified language. Having a log file in your own language might mitigate the traumatic experience of error tracking for \TeX\ newbies.
\section{Directive extraction}
\label{sec:directiveextraction}
The following block in the log file refers to file information and directive extraction. First, as with the terminal output counterpart, the tool will display details about the file being processed, including size and modification status:
\begin{codebox}{Log file}{teal}{\icnote}{white}
Processing 'doc12.tex' (size: 74 bytes, last modified:
06/02/2018 05:36:40), please wait.
\end{codebox}
The next entries refer to finding potential directive patterns in the code, including multiline support. All matching patterns contain the corresponding line numbers. Note that these numbers might refer to incorrect lines in the code if the \opbox{{-}preamble} command line option is used.
\begin{codebox}{Log file}{teal}{\icnote}{white}
I found a potential pattern in line 1: pdftex
I found a potential pattern in line 2: clean: { extensions: [ log ] }
\end{codebox}
When all matching patterns are collected from the code in the previous phase, \arara\ composes the directives accordingly, including potential parameters and conditionals. Observe that all directives have an associated list of line numbers from which they were originally composed. This phase is known as \emph{directive extraction}.
\begin{codebox}{Log file}{teal}{\icnote}{white}
I found a potential directive: Directive: { identifier: pdftex,
parameters: {}, conditional: { NONE }, lines: [1] }
I found a potential directive: Directive: { identifier: clean,
parameters: {extensions=[log]}, conditional: { NONE }, lines: [2] }
\end{codebox}
In this phase, directives are correctly extracted and composed, but are yet to be validated regarding invalid or reserved parameter keys. The tool then proceeds to validate parameters and normalize such directives.
\section{Directive normalization}
\label{sec:directivenormalization}
Once all directives are properly composed, the tool checks for potential inconsistencies, such as invalid or reserved parameter keys. Then all directives are validated and internally mapped with special parameters, as previously described in Section~\ref{sec:directivenormalization}, on page~\pageref{sec:directivenormalization}.
\begin{codebox}{Log file}{teal}{\icnote}{white}
All directives were validated. We are good to go.
\end{codebox}
After validation, all directives are listed in a special block in the log file, including potential parameters and conditionals. This phase is known as \emph{directive normalization}. Note that the special parameters are already included, regardless of the directive type. This particular block can be used specially for debugging purposes, since it contains all details regarding directives.
\begin{codebox}{Log file}{teal}{\icnote}{white}
-------------------------- DIRECTIVES ---------------------------
Directive: { identifier: pdftex, parameters:
{reference=/home/paulo/Documents/doc12.tex,
file=doc12.tex}, conditional: { NONE }, lines: [1] }
Directive: { identifier: clean, parameters: {extensions=[log],
file=doc12.tex, reference=/home/paulo/Documents/doc12.tex},
conditional: { NONE }, lines: [2] }
-----------------------------------------------------------------
\end{codebox}
Note, however, that potential errors in directive conditionals, as well as similar inconsistencies in the corresponding rules, can only be caught at runtime. The next phase covers proper interpretation based on the provided directives.
\section{Rule interpretation}
\label{sec:ruleinterpretation}
Once all directives are normalized, \arara\ proceeds to interpret the potential conditionals, if any, and the corresponding rules. Note that, when available, the conditional type dictates whether the rule should be interpreted first or not. For each rule, the tool informs the identifier and the absolute path of the corresponding \gls{YAML} file. In this specific scenario, the rule is part of the default rule pack released with our tool:
\begin{codebox}{Log file}{teal}{\icnote}{white}
I am ready to interpret rule 'pdftex'.
Rule location: '/opt/paulo/arara/rules'
\end{codebox}
For each task (or subtask, as it is part of a rule task) defined in the rule context, \arara\ will interpret it and return the corresponding system command. The return types can be found in Section~\ref{sec:rule}, on page~\pageref{sec:rule}. In this specific scenario, there is just one task associated with the \rbox{pdftex} rule. Both task name and system command are shown:
\begin{codebox}{Log file}{teal}{\icnote}{white}
I am ready to interpret task 'PDFTeX engine' from rule 'PDFTeX'.
System command: [ pdftex, doc12.tex ]
\end{codebox}
After proper task interpretation, the underlying execution library of \arara\ executes the provided system command and includes the output from both output and error streams in an \emph{output buffer} block inside the log file.
\begin{codebox}{Log file}{teal}{\icnote}{white}
---------------------- BEGIN OUTPUT BUFFER ----------------------
This is pdfTeX, Version 3.14159265-2.6-1.40.19 (TeX Live 2018)
(preloaded format=pdftex)
restricted \write18 enabled.
entering extended mode
(./doc12.tex [1{/usr/local/texlive/2018/texmf-var/fonts/map/
pdftex/updmap/pdfte
x.map}] )</usr/local/texlive/2018/texmf-dist/fonts/type1/
public/amsfonts/cm/cmr
10.pfb>
Output written on doc12.pdf (1 page, 11849 bytes).
Transcript written on doc12.log.
----------------------- END OUTPUT BUFFER -----------------------
\end{codebox}
Observe that the above output buffer block contains the relevant information about the \rbox{pdftex} execution on the provided file. It is possible to write a shell script to extract these blocks from the log file, as a means to provide individual information on each execution. Finally, the task result is shown:
\begin{codebox}{Log file}{teal}{\icnote}{white}
Task result: SUCCESS
\end{codebox}
The execution proceeds to the next directive in the list and then interprets the \rbox{clean} rule. The same steps previously described are applied in this scenario. Also note that the output buffer block is deliberately empty due to the nature of the underlying system command, as removal commands such as \rbox{rm} do not provide output at all when successful.
\begin{codebox}{Log file}{teal}{\icnote}{white}
I am ready to interpret rule 'clean'.
Rule location: '/opt/paulo/arara/rules'
I am ready to interpret task 'Cleaning feature' from rule 'Clean'.
System command: [ rm, -f, doc12.log ]
---------------------- BEGIN OUTPUT BUFFER ----------------------
----------------------- END OUTPUT BUFFER -----------------------
Task result: SUCCESS
\end{codebox}
\begin{messagebox}{Empty output buffer}{attentioncolour}{\icattention}{black}
If the system command is simply a boolean value, the corresponding block will remain empty. Also note that not all commands from the underlying operating system path provide proper stream output, so the output buffer block might be empty in certain corner scenarios. This is the case, for example, of the provided \rbox{clean} rule.
\end{messagebox}
Finally, as the last entry in the log file, the tool shows the execution time, in seconds. As previously mentioned, the execution time has a very simple precision and should not be considered for command profiling.
\begin{codebox}{Log file}{teal}{\icnote}{white}
Total: 0.33 seconds
\end{codebox}
The logging feature provides a consistent framework for event recording. It is highly recommended to include at least the \opbox{{-}log} command line option (or enable it in the configuration file) in your typical automation workflow, as relevant information is gathered into a single consolidated report.
|
