On Wed, Aug 19, 2015 at 4:51 PM, Peter Kelly <pmke...@apache.org> wrote:
> Hi Gabriela, this looks like a good start.
>
Thanks, I was a bit worried that the macros would not be portable.
Then again, if we find that they are not, we can always underpin with
seperate code I guess (hope).
> A few suggestions come to mind:
>
> - I recommend defining a macro for each of the log levels, each of which
> invokes LOG_THIS. Having these separate macros (LOG_ERROR_MSG,
> LOG_WARNING_MSG, etc) will mean that for production builds we can
> conditionally compile such that these macros do nothing, which will result in
> faster execution. When debugging, they will be enabled so we can see the
> messages. For production build we may want to show only errors, but probably
> hide warnings, info etc.
Ok, I'll add that. I initially had that but thought it would be
possible to turn off if I parameterize it. Then again, if it ever
needs changing, a good find . -name ... macro will do the trick and
the dedicated macros also are a bit easier to read.
Out of (idle) interest: How much time are we actually saving on
execution though?
I'm asking in general, since we expect to run on handhelds.
Could we set an upper limit goal on execution time as a general target
to shoot for?
>
> - Later on, it might be worth us having macros or log parameters for
> different modules. For example when debugging the XML parser or hash table
> functions, it’ll be best to hide (possibly verbose and likely irrelevant) log
> output from other components. Thus for a test, someone might be converting
> .docx to .html, but only want to see messages relating to DFHashTable.
I had an idea like that, but it seemed a bit over complex However, it
might be a good start for this topic and maybe there is a better way
of doing the same thing. Or we can keep the simple macros and just
add another function later.
I've attached the original design, which I had pared down somewhat in
the initial presentation. Jan thought it was a bit more than we need
for now (and I agree with him here)
I also thought better of the file name to use, the host machine is
useful to know and it may even be desirable to add user to that list.
Then again, I also have to say that the file name that is generated is
quite the eyesore, and some people might prefer it to simply be called
Corinthia.log. So many ways of skinning a cat!
I still like the concept of the log groups in general, I often wish I
didn't have to comment out debug statements, and of course, every time
I delete them, I then find that I need them again. Also, something
like that could be useful for adhoc profiling, I describe that in the
footnotes of the attached document.
Note that the design contains some elements that are not really needed
and some I've removed (for example, we don't need stuff like
LOG_EMERG), but I've left them in for now.
>
> - I’d advise against strcat and even strncat, as well as using malloc with
> the sum of the length of strings you want to concatenate - this is very easy
> to get wrong. A simple solution is to allocate a sufficiently large string
> (e.g. 1024 characters) and then use snprintf.
Ok, will do that for now and later when this all works, I can plug in
the DFormatString.
Alternatively, DFFormatString will do the necessary work for you of
allocating enough memory and constructing a string with the specified
parameters. I realise your code doesn’t currently use DocFormats, but
you could take DFFormatString and copy it into your code, adapting it
as necessary.
>
> - Rather than placing the tar file in the repository as a single file, just
> extract it and have the individual files commited. This way we can track
> changes and easily make patches as we do with the other code, rather than
> having to continuously update the tar file each time.
Ok, will do that. I keep the dedicated makefile for now, once this
all runs (instead of wobbling along :-) I'll plug it into the main
Corinthia tree.
G,
>
> —
> Dr Peter M. Kelly
> pmke...@apache.org
>
> PGP key: http://www.kellypmk.net/pgp-key <http://www.kellypmk.net/pgp-key>
> (fingerprint 5435 6718 59F0 DD1F BFA0 5E46 2523 BAA1 44AE 2966)
>
>> On 18 Aug 2015, at 4:30 am, Gabriela Gibson <gabriela.gib...@gmail.com>
>> wrote:
>>
>> Hi,
>>
>> Jan kindly tasked me with making a logger for Corinthia and helped me
>> figure out what it needed initially.
>>
>> Currently it only produces a log file and uses a small combination of
>> macros to write out the file, line and function. It will acquire function
>> pointers for users to hook in their own output functions and other stuff
>> in the next iteration.
>>
>> However, whilst this still misses a lot of the spec, this is a good
>> time to take a look to see how this is all going and if what I
>> concocted here is portable, or even a good idea.
>>
>> Caveat: I have no clue why I keep getting the complaints from gcc,
>> it does compile, link and run in the end.[1]
>>
>> You can find it here:
>>
>> https://github.com/apache/incubator-corinthia/blob/master/experiments/logger/log_maker.tar
>>
>> Files:
>>
>> log_maker.h // header
>> log_maker.c // code for the log mechanism
>> useLogmaker.c // test code
>> Makefile
>>
>> You probably want to set the log directory to something useful, it's
>> currently set to tmp/foo/bar, in useLogmaker.c main: 25 in the line
>> set_log_dir("/tmp/foo/bar/");
>>
>> to build and run, it's
>>
>> $ make; ./logMaker
>>
>> After the program is completed, it shows a message giving the path and
>> name of the created log file.
>>
>> G
>>
>> [1] Output on my machine:
>>
>> gcc -ggdb -std=c99 -Wall -c -o useLogmaker.o useLogmaker.c
>> In file included from useLogmaker.c:1:0:
>> log_maker.h:26:12: warning: ‘global_log_level’ defined but not used
>> [-Wunused-variable]
>> static int global_log_level = LOG_WARNING;
>> ^
>> log_maker.h:28:12: warning: ‘log_level_initialised’ defined but not
>> used [-Wunused-variable]
>> static int log_level_initialised = 0;
>> ^
>> gcc -ggdb -std=c99 -Wall -c -o log_maker.o log_maker.c
>> log_maker.c: In function ‘log_msg_prefix’:
>> log_maker.c:183:5: warning: implicit declaration of function ‘dprintf’
>> [-Wimplicit-function-declaration]
>> dprintf(log_file_fd, "%s %s %s:%d %s() ", level_prefixes[level],
>> time_buf, filename, linenum, function);
>> ^
>> log_maker.c: In function ‘log_msg’:
>> log_maker.c:194:5: warning: implicit declaration of function
>> ‘vdprintf’ [-Wimplicit-function-declaration]
>> vdprintf(log_file_fd, fmt, argp);
>> ^
>> gcc -ggdb -std=c99 -Wall -o logMaker useLogmaker.o log_maker.o
>> Logfile created in /tmp/foo/bar/logMaker.musashi.20150813-182555
>>
>>
>> --
>> Visit my Coding Diary: http://gabriela-gibson.blogspot.com/
>
--
Visit my Coding Diary: http://gabriela-gibson.blogspot.com/
Corinthia log design
---------------------
After reading through a number of logging creations, my current idea
about this project is explained below. This is proposed as the starting
point for a discussion.
Use cases of the logging feature:
----------------------------------
We have the following requirements (that also overlap):
1: Standard operation
Default logging for all operations. May require separate files for
ERR, WARNING and INFO. For the output funcion, a ptr is provided
by the user.
2: Debugging/Tracing for selected parts of the code
We want specific API tracing detail (or other specified components)
in addition to standard logging. (see logging_groups)
3: API debugging
We need logging of args for input and output. This is required to
allow tracing of wrongly converted features. (see logging_groups)
Logfile handling:
-----------------
One log file which is appended per run/overwritten? (Jan, I'm not
sure here., I now designed for optional extra log files to be
named, and wonder if we should use the syslog model to avoid
massive files. If we overwrite, we must offer an append option, but
I've not written that into the design yet in this iteration.)
Appearance of log messages:
---------------------------
a) log level (as a leading character: D for debug, I for info, W, E...)
b) Complete Time ("%Y-%m-%d %H:%M:%S.%N")
c) file, line, function see [1]
d) explanatory message with option to record state of current variables
e) unique_id, which then allows the creating of logging groups
(Note: if we have this, then point c is superflous, since the
logging location can be found via TAG file or grep. and also
cuts down on compiled code size, which maybe nice to have for
things like Ios since I believe, space is at a premium there?)
Setup file:
-----------
Setup parameters for the logging service are provided by a set up
file, which is either the standard 'logsetup.conf' or is is passed as
a parameter at runtime if displayed as a commandline switch. A
runtime parameter overrides what is defined in the conf file and a
custom conf file can be selected at runtime with
--set-log-conf=path/to/file
Customisation variables:
* --with-std-debug=[(=|>|<) D|I|W|E|...] (turn on debugging)
Example: --with_std_debug='>E' turn on all levels greater and including E
--with-std-debug='<E' turn on all levels smaller and including E
* --with-api-debug=[(=|>|<) D|I|W|...] (limit all debug msg to the api dirs)
api-debug and std-debug are mutually exclusive. If no option is
given, --with-std-debug=D is assumed.
Optional:
* --with-color (see [2])
* --log-file-name=path/to/file
* logging_group group_name = log_level, func1, func2, ....
* logging_combo combo_name = log_level, group_name1, group_name_2,...,
combo_nameN,..., path=...]
Global Variables:
-----------------
(char *)(output_function)
This is either a user supplied function pointer set by
corinthia_set_output_function(...) or set by our native
corinthia_write_log(...)
const char* conf_file
Name of conf file. If not passed as a run_time parameter, the
default file is selected: corinthia.conf
const char* logfile_name
Name of log file to use. Default is corinthia.log, but it may
at times be desirable to produce a seperate log file.
(hashtable) log_id_collection
Hashtable of log_ids that are requested in the conf file. If
this is empty, every log message visisted is displayed if the log
level is a match. Populated at setup time.
int corinthia_log_level
The current log_level to use. Set via the conf file. Default is
'DEBUG'.
(from syslog.h, if we keep this shape, then it's one less thing to
keep in mind for devs since they are already familiar with this shape)
#define LOG_EMERG 0 /* system is unusable */
#define LOG_ALERT 1 /* action must be taken immediately */
#define LOG_CRIT 2 /* critical conditions */
#define LOG_ERR 3 /* error conditions */
#define LOG_WARNING 4 /* warning conditions */
#define LOG_NOTICE 5 /* normal but significant condition */
#define LOG_INFO 6 /* informational */
#define LOG_DEBUG 7 /* debug-level messages */
extra:
#define LOG_INDIVIDUAL 8 /* use the individual log levels of given
groups/combos */
Function calls:
-----------------------
void corinithia_open_log(const char *set_up_file)
If set_up_file is void, read inbuild file:
Populate the global variables with standard values:
output_function = fwrite(char *format, ...)
log_id_collection = NULL
log_level = DEBUG or commandline parameter supplied value
otherwise, parse and apply what is in the custom conf file.
void corinthia_set_output_function ((char *)(_output_function));
Use is optional, this allows the dev to pass a pointer to
their own fwrite(char *entry,...) function.
void corinthia_log_message(int log_level,
char *log_id,
const char *format, ...);
log_levels to match current syslog offering, with the
potential addition of 'performance' and perhaps, buildbot
specific levels if that is useful. The unique_id allows this
particular log message to be added to logging_group lists.
Checks the logging group/logging combo list as well as the
log_level to decide if it displays. Assembles the message
string to be shown and then calls the user supplied output
function.
void close_corinthia_log(void;
closes the current log file and does some housekeeping if the
file gets above n kb. TBD, probably best to use the classic
syslog model here.
char *set_log_group(char *group_name, char *fmt, ...)
Create a group of log entries (with their resp. log levels) as
defined in the conf file, of log messages we want to trigger
in this particular run. Populates char* log_ids_collection[].
char *set_log_combo(char *combo_name, char *fmt, ...)
Create a combo group of log entries (with their resp. log
levels) as defined in the conf file. Calls set_log_group to
build the call queue.
Suplemental external script:
----------------------------
corinthia_check_unique_log_id.sh
Run a grep across the code base and ensure that the
unique_id's in all log messages are unique. Also produces a
list of log messages and the location in the files. (with the
idea that this also gives a nice birds eye view of what log
message are available.)
What is this 'logging group' idea?
----------------------------------
Frequently we don't want to see every log message going, but just
a particular subset thereof. log_levels help a bit but even
filtering on levels can still produce a huge amounts of output.
In the actual logging function call, we would have one extra
parameter, which is a unique id that allows us to trigger
messaging on demand, using predefined values of 'logging_group' or
'logging_combo' as a selector.
This mechanism allows the creation of custom groups (useful for
test suites) and cuts down on log output, which allow coders to
select log messages that are only needed in particular situations,
and so facilitates easy tracing, without producing a veritable
haystack of log spam. This also keeps user bug reports and log
files to a managable size.
logging_groups/logging_combos are read from either the commandline
or a configuration file at compile time. Logmessage that are not
required do not get compiled in.
Definition:
Suppose we just want to have logging for a selection of log
functions, we then can define named lists:
logging_group group_name = log_level, func1, func2, ....
logging_combo combo_name = log_level, group_name1, group_name_2,...,
combo_nameN,..., path=...]
(where path just defines all log functions found in the files in
the given path, and all entries are optional, ie, a combo can just
be a collection or groups or combos, or path and a mix thereof)
Example:
logging_group ODF =
[log_level, group = ODF_func_foo_have_flurble, ODF_func_bar, ODF_func_baz]
logging_goup WORD = [log_level, WORD_func_foo_wibble, WORD_func_flibble]
logging_group consumers2 = [log_level, normalize_func_pt2, ...]
which can then be combined into a combo that is thene expanded
into a logging_group:
logging_combo lib1 = [log_level, path=['dir'|'file'],
path=..., combo = ODF, WORD, ..., group = ... ]
or a combination of existing groups and/or combos:
logging_combo trace_bug_123 = [log_level, comsumers2, lib1, Word]
where logging_combo expands to make a logging_logging and if a
log_level is given other than LOG_INDIVIDUAL, this overrides the
individual log levels set in the sub groups. This applies to
groups and combos.
A group or combo can be assigned a new log level by creating a new
group:
logging_combo new_combo = [log_level, old_combo]
This combined with unix facility 'ts' (timestamp input) can also
be used for adhoc profiling on a unix system.[3]
Other advantages are that debugging/logging runs can be archived,
shared, modfied and re-used easily and quickly; and that the
debugging process is expressed in an easy to read form, instead of
being distributed throughout the code without a central index.
Also, an index of debugging functions can easily be produced which
helps to visualise coverage and enables easy tracing.
External documentation:
-----------------------
[1] https://gcc.gnu.org/onlinedocs/cpp/Standard-Predefined-Macros.html
[2]
http://stackoverflow.com/questions/26070873/how-to-set-gcc-colors-in-gcc4-9-to-emit-colorizing-diagnostics-messages
alternatively, there is my color.h hack which can be seen here:
http://gabriela-gibson.blogspot.com/2015/05/put-some-colour-in-your-c-code.html
[3] Sample output: (see 'man ts' for details, this may require installation of
moreutils)
$ ./dftest -plain | ts -i "%.s"
0.000074 Test group: api
0.000465 one FAIL 1
equals 2
0.000113 two FAIL
Output mismatch
0.000077 three FAIL
Failed because I felt like it
0.000073 four PASS
0.000071 Test group: core.bdt
0.000067 Test group: core.css
0.000067 Test group: core.html
0.000069 Test group: core.lib
0.000066 sample PASS
0.000069 Test group: core.xml
0.000069 sample PASS
0.000068 Test group: latex
0.000068 Test group: odf
0.000067 sample PASS
0.000069 Test group: ooxml.word
0.000067 Test group: platform.os
0.000074 DFGetImageDimensions (gif) PASS
0.000068 DFGetImageDimensions (jpg) PASS
0.000070 DFGetImageDimensions (png) PASS
0.000070 DFInitOnce PASS
0.000070 DFMkdirIfAbsent PASS
0.000068 DFAddDirContents PASS
0.000068 Test group: platform.wrapper
0.000068 DFextZipOpen PASS
0.000069 DFextZipClose PASS
0.000068 DFextZipOpenNextFile PASS
0.000069 DFextZipCloseFile PASS
0.000068 DFextZipReadCurrentFile PASS
0.000068 DFextZipWriteCurrentFile PASS
