corinthia-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Peter Kelly <pmke...@apache.org>
Subject Re: [1/2] incubator-corinthia git commit: Logging feature update
Date Fri, 28 Aug 2015 05:58:36 GMT
Hi Gabriella, here’s my comments:

You’re on the right track with the separate log messages for different levels. This enables
us to conditionally compile the code such that, for example, only LOG_ERR_MSG and LOG_WARNING_MSG
messages are generated for production code, while all levels are generated for non-debug.

I’d keep the log level macros (LOG_ERR etc) as integers though, with errors as 0 and increasing
by 1 from there. The reason for using integers instead of strings for log levels is so you
can say “anything less than log level <n>”, i.e. maybe you want all information
except debugging info (level < LOG_DEBUG), or all notice messages and anything more serious
(level <= LOG_INFO). That is, the levels have an explicit ordering to them, and the choice
of what is displayed is based on a numeric comparison.

You asked in your previous mail about how much time is being saved. In general it will be
very minimal, though it’s possible if for some reason a logging message is added to a function
that is executed lots of times, or information that is passed to the log message takes a non-trivial
amount of time to compute (for example if a log contained a call to a function that computed
the total number of nodes in a document), then the saving would be worth it.

In general, you should avoid fixed-length buffers for strings like log_filename, logging_dir,
and log_symlink. It’s better to dynamically allocate memory for things like this where necessary,
using e.g. malloc/strdup/DFFormatString or whatever. For example inside set_log_dir, you would
call strdup to make a copy of the parameters, and then assign those copies logging_dir and
log_symlink, which would have the type char * instead of being arrays.

When specifying functions in a header like set_log_dir, include the parameter names. These
help to clarify what the function does to someone who is just looking through the header,
without having to look at the c file as well (e.g. there are two parameters to that function,
and just from the header I don’t know which one is dir and which one is sdir.

—
Dr Peter M. Kelly
pmkelly@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 23 Aug 2015, at 6:54 am, gbg@apache.org wrote:
> 
> Repository: incubator-corinthia
> Updated Branches:
>  refs/heads/master 2daa00087 -> e1dc6c9ab
> 
> 
> Logging feature update
> 
> Add dedicated general logging macros, set a symlink 'current.log', and
> allow local custom log macros with dedicated names for the log file.
> Remove the tar file and use snprintf instead strncat and strdup.
> 
> Todo:  plug in user defined output function pointer mechanism.
> 
>  * Makefile:
> 
>    Temporary way to compile the logger.  Usage:
>      $ make; ./logMaker
> 
>  * log_maker.c:
> 
>    Code for the logging functions.
> 
>    (#define): Add _GNU_SOURCE.
> 
>    (#include): Add "log_maker.h".
>                Add <assert.h>.
>                Add <error.h>.
>                Add <libgen.h>.
>                Add <stdarg.h>.
>                Add <stdio.h>.
>                Add <stdlib.h>.
>                Add <string.h>.
>                Add <time.h>.
>                Add <unistd.h>.
>                Add <errno.h>.
>                Add <dirent.h>.
>                Add <sys/types.h>.
>                Add <sys/stat.h>.
>                Add <fcntl.h>.
>      These are probably not all needed.
> 
>    (get_time_string): New function.
> 
>    (set_log_output_function): New function.  This is a stub.
> 
>    (log_init): New function.  Create the logfile name with host, time
>      and program name. Set a symlink 'current.log' into
>      ~/../incubator/.
> 
>    (set_log_dir): New function.  Set the directory in which to write
>      the individual logfiles and the location where the symlonk
>      should be created.
> 
>    (close_log): New function.  Close the file descriptor and inform
>      user about the location and name of the generated file.
> 
>    (log_msg_prefix): New function.  Create the prefix containing the
>      name of the log level, the file, line number and function name.
> 
>    (log_msg): New function. Write the log prefix and log message to
>      file.
> 
>  * log_maker.h:
> 
>    Header file for general inclusion so log_maker.c can be used.
> 
>    (#ifndef): Add LOG_MAKER_H.
>      Header guard.  Somehow #pragma once does not work for me.
> 
>    (#if): Add _MSC_VER.  Picked this up in the docs, apparently MSC
>      uses _sprintf instead.
> 
>    (#define):  Add LOG_ERR.
>                Add LOG_WARNING.
>                Add LOG_NOTICE.
>                Add LOG_INFO.
>                Add LOG_DEBUG.
>        These are all strings for now.  I can change it back to numbers, but
>        currently those strings are used to print out the log message titles.
> 
>    Global variables:
> 
>    (char): Add log_filename[filename_len].
> 
>    (int): Add log_file_fd.  File descriptor for log file.
> 
>    (static int log_level_initialised): Guard to prevent log_init from
>      being called twise.
> 
>    (char): Add logging_dir[filename_len].
> 
>    (char): Add log_symlink[filename_len].
> 
>    (LOG_THIS): New function.  Basic macro, called by every custom macro.
> 
>    Basic log macros for general usage:
> 
>    (LOG_ERROR_MSG): New function.
> 
>    (LOG_WARNING_MSG): New function.
> 
>    (LOG_NOTICE_MSG): New function.
> 
>    (LOG_INFO_MSG): New function.
> 
>    (LOG_DEBUG_MSG): New function.
> 
>    Prototypes for logmaker.c:
> 
>    (set_log_output_function): New function.
> 
>    (log_init): New function.
> 
>    (set_log_dir): New function.
> 
>    (set_log_level): New function.
> 
>    (close_log): New function.
> 
>    (log_msg_prefix): New function.
> 
>  * useLogmaker.c:
> 
>    Test code for log_maker.c
> 
>    (#include): Add "log_maker.h".
>                Add <stdio.h>.
>                Add <unistd.h>.
> 
>    (LOG_USE_LOGMAKER_MSG): New function.  This is a custom log macro
>      that only works for the local file.
> 
>    (function_one): New function.  Test every general macro.
> 
>    (function_two): New function.  Test base macro 'LOG_THIS' and test
>      locally defined macro.
> 
>    (main): New function.  Run tests.
> 
> 
> Project: http://git-wip-us.apache.org/repos/asf/incubator-corinthia/repo
> Commit: http://git-wip-us.apache.org/repos/asf/incubator-corinthia/commit/a507ec58
> Tree: http://git-wip-us.apache.org/repos/asf/incubator-corinthia/tree/a507ec58
> Diff: http://git-wip-us.apache.org/repos/asf/incubator-corinthia/diff/a507ec58
> 
> Branch: refs/heads/master
> Commit: a507ec5880d19f1ea09e328a8f19a98a419c0f17
> Parents: a24455b
> Author: Gabriela Gibson <gbg@apache.org>
> Authored: Sun Aug 23 00:53:55 2015 +0100
> Committer: Gabriela Gibson <gbg@apache.org>
> Committed: Sun Aug 23 00:53:55 2015 +0100
> 
> ----------------------------------------------------------------------
> experiments/logger/Makefile      |  14 +++
> experiments/logger/log_maker.c   | 155 ++++++++++++++++++++++++++++++++++
> experiments/logger/log_maker.h   |  47 +++++++++++
> experiments/logger/log_maker.tar | Bin 2321 -> 0 bytes
> experiments/logger/useLogmaker.c |  40 +++++++++
> 5 files changed, 256 insertions(+)
> ----------------------------------------------------------------------
> 
> 
> http://git-wip-us.apache.org/repos/asf/incubator-corinthia/blob/a507ec58/experiments/logger/Makefile
> ----------------------------------------------------------------------
> diff --git a/experiments/logger/Makefile b/experiments/logger/Makefile
> new file mode 100644
> index 0000000..9369702
> --- /dev/null
> +++ b/experiments/logger/Makefile
> @@ -0,0 +1,14 @@
> +objects = useLogmaker.o log_maker.o
> +CC = gcc
> +CFLAGS = -ggdb -std=c99 -Wall 
> +
> +logger: $(objects)
> +	$(CC) $(CFLAGS) -o logMaker $(objects)
> +
> +useLogmaker.o:  log_maker.h
> +
> +log_maker.o: log_maker.h
> +
> +.PHONY : clean
> +clean :
> +	rm logMaker $(objects)
> 
> http://git-wip-us.apache.org/repos/asf/incubator-corinthia/blob/a507ec58/experiments/logger/log_maker.c
> ----------------------------------------------------------------------
> diff --git a/experiments/logger/log_maker.c b/experiments/logger/log_maker.c
> new file mode 100644
> index 0000000..4e39ee5
> --- /dev/null
> +++ b/experiments/logger/log_maker.c
> @@ -0,0 +1,155 @@
> +#define _GNU_SOURCE 1
> +
> +#include "log_maker.h"
> +#include <assert.h>
> +#include <error.h>
> +#include <libgen.h>
> +#include <stdarg.h>
> +#include <stdio.h>
> +#include <stdlib.h>
> +#include <string.h>
> +#include <time.h>
> +#include <unistd.h>
> +#include <errno.h>
> +#include <dirent.h>
> +#include <sys/types.h>
> +#include <sys/stat.h>
> +#include <fcntl.h>
> +
> +
> +int get_time_string(char** time_buf, int time_buf_len) 
> +{
> +    time_t t;
> +    struct tm *tm_tmp;
> +
> +    memset(*time_buf, 0, time_buf_len);
> +
> +    t = time(NULL);
> +    tm_tmp = localtime(&t);
> +    if (NULL == tm_tmp) {
> +        // FIXME:  there is 'utassrt' but I'm not sure how to get ahold of it right
now.
> +        perror("localtime error");
> +        abort();
> +    }
> +
> +    strftime(*time_buf, time_buf_len, "%Y%m%d-%H%M%S", tm_tmp);
> +
> +    return strlen(*time_buf);
> +}
> +
> +void set_log_output_function(char* func)
> +{
> +    // TODO
> +}
> +
> +/* The format of file name is 
> +     <binary_name>.<hostname>.<date_string> 
> +   Note: Open question: is it worth also adding username to this
> +         string? 
> +*/
> +
> +
> +void log_init(void) 
> +{
> +    if (log_level_initialised)
> +        return;
> +
> +    int hostname_len = 80;
> +    char hostname_buf[hostname_len];
> +    gethostname((char*)hostname_buf, hostname_len);
> +
> +    char* progname = basename(getenv("_"));
> +
> +    int time_buf_len = 16;
> +    char *time_buf = malloc(time_buf_len);
> +
> +    get_time_string(&time_buf, time_buf_len);
> +    
> +    /* FIXME:
> + 
> +      Take DFFormatString and copy it into your code, adapting it as
> +      necessary.
> +
> +    */
> +    snprintf(log_filename, filename_len, "%s%s.%s.%s",
> +             logging_dir,progname,hostname_buf,time_buf);
> +
> +    log_file_fd = open(log_filename, 
> +                  O_CREAT | O_TRUNC | O_WRONLY, 
> +                  S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
> +
> +    if (log_file_fd == -1) {
> +        fprintf(stderr, "FATAL: couldn't open file descriptor\n");
> +        abort();
> +    }
> +
> +    symlink(log_filename, log_symlink);
> +
> +    free(time_buf);
> +    log_level_initialised = 1;
> +}
> +
> +
> +void set_log_dir(const char* dir, const char *sdir) 
> +{
> +    if (log_level_initialised) {
> +        fprintf(stderr, "Cannot reset logging level after initialisation\n");
> +        abort();
> +    }
> +
> +    errno = 0;
> +
> +    DIR* has_dir = opendir(dir);
> +
> +    int this_error = errno;
> +
> +    // check the actual log file dir
> +    if (has_dir) {
> +        closedir(has_dir);
> +        snprintf(logging_dir, filename_len, "%s", dir);
> +    }
> +    else {
> +        // FIXME
> +        perror(strerror(this_error));
> +        abort();
> +        return;
> +    }
> +
> +    // check the symlink, remove if it exists
> +    snprintf(log_symlink, filename_len, "%scurrent.log", sdir);
> +
> +    struct stat statbuf;
> +    
> +    if (-1 == lstat(log_symlink, &statbuf)) 
> +        return;
> +    else 
> +        unlink(log_symlink);
> +
> +    return;
> +}
> +
> +void close_log(void) 
> +{
> +    close(log_file_fd);
> +    printf("Logfile created in %s\nSee %s to view it\n", log_filename, log_symlink);
> +}
> +
> +void log_msg_prefix(char *level, char* filename, int linenum, const char* function)
> +{
> +    if (! log_level_initialised) {
> +        fprintf(stderr, "ERROR: Trying to log before initialisation is complete.\n");
> +        exit(1);
> +    }
> +    dprintf(log_file_fd, "%-15s %s:%d %s() ", level, filename, linenum, function);
> +}
> +
> +
> +void log_msg(char *level, char *fmt, ...)
> +{
> +    va_list argp;
> +    va_start(argp, fmt);
> +    assert(log_file_fd > -1);
> +    vdprintf(log_file_fd, fmt, argp);
> +    va_end(argp);
> + }
> +
> 
> http://git-wip-us.apache.org/repos/asf/incubator-corinthia/blob/a507ec58/experiments/logger/log_maker.h
> ----------------------------------------------------------------------
> diff --git a/experiments/logger/log_maker.h b/experiments/logger/log_maker.h
> new file mode 100644
> index 0000000..624120a
> --- /dev/null
> +++ b/experiments/logger/log_maker.h
> @@ -0,0 +1,47 @@
> +#ifndef LOG_MAKER_H
> +#define LOG_MAKER_H
> +
> +#if _MSC_VER
> +#define snprintf _snprintf
> +#endif
> +
> +#define LOG_ERR         "ERROR"
> +#define LOG_WARNING     "WARN"
> +#define LOG_NOTICE      "NOTICE"
> +#define LOG_INFO        "INFO"
> +#define LOG_DEBUG       "DEBUG"
> +
> +
> +// TODO
> +void set_log_output_function(char* func);
> +
> +void log_init(void);
> +void set_log_dir(const char*, const char*);
> +void set_log_level(int level);
> +void close_log(void);
> +
> +void log_msg_prefix(char* level, char* filename, int linenum, const char* function);
> +void log_msg(char* level, char *msg, ...);
> +
> +#define filename_len 1024
> +char log_filename[filename_len];
> +int log_file_fd;
> +
> +static int log_level_initialised = 0;
> +
> +char logging_dir[filename_len];
> +char log_symlink[filename_len];
> +
> +#define LOG_THIS(level, msg, ...) do {                                \
> +        log_msg_prefix(level, __FILE__, __LINE__, __FUNCTION__);      \
> +        log_msg(level, msg, __VA_ARGS__);                             \
> +    } while (0)
> +
> +
> +#define LOG_ERROR_MSG(msg, ...) LOG_THIS(LOG_ERR, msg, __VA_ARGS__);
> +#define LOG_WARNING_MSG(msg, ...) LOG_THIS(LOG_WARNING, msg, __VA_ARGS__);
> +#define LOG_NOTICE_MSG(msg, ...) LOG_THIS(LOG_NOTICE, msg, __VA_ARGS__);
> +#define LOG_INFO_MSG(msg, ...) LOG_THIS(LOG_INFO, msg, __VA_ARGS__);
> +#define LOG_DEBUG_MSG(msg, ...) LOG_THIS(LOG_DEBUG, msg, __VA_ARGS__);
> +
> +#endif /* LOG_MAKER_H_H */
> 
> http://git-wip-us.apache.org/repos/asf/incubator-corinthia/blob/a507ec58/experiments/logger/log_maker.tar
> ----------------------------------------------------------------------
> diff --git a/experiments/logger/log_maker.tar b/experiments/logger/log_maker.tar
> deleted file mode 100644
> index b53154e..0000000
> Binary files a/experiments/logger/log_maker.tar and /dev/null differ
> 
> http://git-wip-us.apache.org/repos/asf/incubator-corinthia/blob/a507ec58/experiments/logger/useLogmaker.c
> ----------------------------------------------------------------------
> diff --git a/experiments/logger/useLogmaker.c b/experiments/logger/useLogmaker.c
> new file mode 100644
> index 0000000..a9e2c3b
> --- /dev/null
> +++ b/experiments/logger/useLogmaker.c
> @@ -0,0 +1,40 @@
> +#include "log_maker.h"
> +#include <stdio.h>
> +#include <unistd.h>
> +
> +#define LOG_USE_LOGMAKER_MSG(msg, ...) LOG_THIS("LOG_MAKER", msg, __VA_ARGS__);
> +
> +void function_one(void)
> +{
> +    LOG_THIS(LOG_WARNING,"LOG_THIS = %d, %d, %d,%d, %d, %d, %d, %d, %d, %d\n",
> +             1,2,3,4,5,6,7,8,9,10);
> +    LOG_ERROR_MSG("this is a LOG_ERROR_MSG = %d\n",1);
> +    LOG_WARNING_MSG("this is a LOG_WARNING_MSG = %d\n",2);
> +    LOG_NOTICE_MSG("this is a LOG_NOTICE_MSG = %d\n",3);
> +    LOG_INFO_MSG("this is a LOG_INFO_MSG = %d\n",4);
> +    LOG_DEBUG_MSG("this is a LOG_DEBUG_MSG = %d\n",5);
> +    return;
> +}
> +
> +void function_two(void)
> +{
> +    LOG_THIS(LOG_NOTICE,"variable two = %d, %d, %d,%d, %d, %d, %d, %d, %d, %d "
> +                  "%d, %d, %d,%d, %d, %d, %d, %d, %d, %d\n", 
> +                  1,2,3,4,5,6,7,8,9,10,
> +                  1,2,3,4,5,6,7,8,9,10);
> +    LOG_USE_LOGMAKER_MSG("this is a LOG_USE_LOGMAKER_MSG = %s\n","LOG_MAKER");
> +    return;
> +}
> +
> +int main(int argc, char *argv[])
> +{
> +    // set_log_level(LOG_DEBUG);
> +    set_log_dir("/tmp/foo/bar/","/home/g/cor-logs/incubator-corinthia/experiments/logger/");
> +    log_init();
> +
> +    function_one();
> +    function_two();
> +
> +    close_log();
> +    return 0;
> +}
> 


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message