On Wed, Dec 17, 2008 at 04:21:48PM +0000, Daniel P. Berrange wrote:

On Wed, Dec 17, 2008 at 04:12:20PM +0100, Daniel Veillard wrote:

...

diff -u -r1.1 logging.h --- src/logging.h 6 Nov 2008 16:36:07 -0000 1.1 +++ src/logging.h 17 Dec 2008 14:25:57 -0000 @@ -30,16 +30,87 @@ * defined at runtime of from the libvirt daemon configuration file */ #ifdef ENABLE_DEBUG -extern int debugFlag; #define VIR_DEBUG(category, fmt,...) \ - do { if (debugFlag) fprintf (stderr, "DEBUG: %s: %s (" fmt ")\n", category, __func__, __VA_ARGS__); } while (0) + virLogMessage(category, VIR_LOG_DEBUG, 0, fmt, __VA_ARGS__) +#define VIR_INFO(category, fmt,...) \ + virLogMessage(category, VIR_LOG_INFO, 0, fmt, __VA_ARGS__) +#define VIR_WARN(category, fmt,...) \ + virLogMessage(category, VIR_LOG_WARN, 0, fmt, __VA_ARGS__) +#define VIR_ERROR(category, fmt,...) \ + virLogMessage(category, VIR_LOG_ERROR, 0, fmt, __VA_ARGS__) #else #define VIR_DEBUG(category, fmt,...) \ do { } while (0) +#define VIR_INFO(category, fmt,...) \ + do { } while (0) +#define VIR_WARN(category, fmt,...) \ + do { } while (0) +#define VIR_ERROR(category, fmt,...) \ + do { } while (0) #endif /* !ENABLE_DEBUG */

#define DEBUG(fmt,...) VIR_DEBUG(__FILE__, fmt, __VA_ARGS__) #define DEBUG0(msg) VIR_DEBUG(__FILE__, "%s", msg) +#define INFO(fmt,...) VIR_INFO(__FILE__, fmt, __VA_ARGS__) +#define INFO0(msg) VIR_INFO(__FILE__, "%s", msg) +#define WARN(fmt,...) VIR_WARN(__FILE__, fmt, __VA_ARGS__) +#define WARN0(msg) VIR_WARN(__FILE__, "%s", msg) +#define ERROR(fmt,...) VIR_ERROR(__FILE__, fmt, __VA_ARGS__) +#define ERROR0(msg) VIR_ERROR(__FILE__, "%s", msg)

I think we should add a prefix to the filename to give a little scope to the namespace. This would let people use non-filename based namespaces without risk of clashing, eg, perhaps

#define ERROR(fmt,...) VIR_ERROR("file." __FILE__, fmt, __VA_ARGS__)

thus turning into file.libvirt.c

okay, I understand the need for namespacing, I think more specific filters might be defined when registering the filters rules, but that's somewhat orthogonal. Note that some of the logging in qemud/ bypasses those macros so the fix needs to be propagated there.

...

+/** + * virLogOutputFunc: + * @data: extra output logging data + * @category: the category for the message + * @priority: the priority for the message + * @msg: the message to log, preformatted and zero terminated + * @len: the lenght of the message in bytes without the terminating zero + * + * Callback function used to output messages + * + * Returns the number of bytes written or -1 in case of error + */ +typedef int (*virLogOutputFunc) (void *data, const char *category, + int priority, const char *str, int len);

I have a preference for 'void *data' parameters to callbacks being at end of the param list.

I have no strong preference about this, no problem :-)

...

+extern int virLogStartup(void); +extern int virLogReset(void); +extern void virLogShutdown(void); +extern int virLogParseFilters(const char *filters); +extern int virLogParseOutputs(const char *output); +extern void virLogMessage(const char *category, int priority, int flags, + const char *fmt, ...) ATTRIBUTE_FORMAT(printf, 4, 5);

I think it would be a good idea to have virLogMesage take a function name, and line number too. Likewise for the virLogOutputFunc() function.

The VIR_ERROR/WARN/INFO/DEBUG macros would automatically include the __func__ and __line__ macros. eg

#define VIR_INFO(category, fmt,...) \ virLogMessage(category, __func__, __line__, VIR_LOG_INFO, 0, fmt, __VA_ARGS__)

So when we process the 'char fmt,....' into an actual string we could have some flag to turn on/off inclusion of the function & line data.

Cole did a similar thing for error reporting internal APIs when he added this to virterror_internal.h:

void virReportErrorHelper(virConnectPtr conn, int domcode, int errcode, const char *filename, const char *funcname, long long linenr, const char *fmt, ...) ATTRIBUTE_FORMAT(printf, 7, 8);

Though, the actual implementation currently ignores filename, funcname and linenr.

I will channel the informations via virRaiseError by extending its arguments, but since there is a lot of places where we call virRaiseError I will make this as a separate patch later.

...

+ +/* + * Macro used to format the message as a string in virLogMessage + * and borrowed from libxml2 (also used in virRaiseError) + */ +#define VIR_GET_VAR_STR(msg, str) { \ + int size, prev_size = -1; \ + int chars; \ + char *larger; \ + va_list ap; \ + \ + str = (char *) malloc(150); \ + if (str != NULL) { \ + \ + size = 150; \ + \ + while (1) { \ + va_start(ap, msg); \ + chars = vsnprintf(str, size, msg, ap); \ + va_end(ap); \ + if ((chars > -1) && (chars < size)) { \ + if (prev_size == chars) { \ + break; \ + } else { \ + prev_size = chars; \ + } \ + } \ + if (chars > -1) \ + size += chars + 1; \ + else \ + size += 100; \ + if ((larger = (char *) realloc(str, size)) == NULL) { \ + break; \ + } \ + str = larger; \ + }} \ +}

Wonder if we should make this use virBuffer instead of char/malloc/realloc. Could then add this definition to buf.h and share it between the logging & error routines.

yeah it's duplicated in a few places

...

+static const char *virLogPriorityString(virLogPriority lvl) { + switch (lvl) { + case VIR_LOG_DEBUG: + return("debug"); + case VIR_LOG_INFO: + return("info"); + case VIR_LOG_WARN: + return("warning"); + case VIR_LOG_ERROR: + return("error"); + } + return("unknown"); +} + +static int virLogInitialized = 0; + +/** + * virLogStartup: + * + * Initialize the logging module + * + * Returns 0 if successful, and -1 in case or error + */ +int virLogStartup(void) { + if (virLogInitialized) + return(-1); + virLogInitialized = 1;

Strictly speaking we should use pthread_once() for such initializations, or an atomic test-and-set operation.

Well except that I try to allow virLogStartup() to be called again after virLogShutdown. In general as soon as we are threading trying to support asynchronous iunitialization at usage time becomes quickly very very messy e.g. with late bindind/dlopen'ing

...

+ /* + * serialize the error message, add level and timestamp + */ + VIR_GET_VAR_STR(fmt, str); + if (str == NULL) + return; + gettimeofday(&cur_time, NULL); + localtime_r(&cur_time.tv_sec, &time_info); + + if (asprintf(&msg, "%02d:%02d:%02d.%03d: %s : %s\n", + time_info.tm_hour, time_info.tm_min, + time_info.tm_sec, (int) cur_time.tv_usec / 1000, + virLogPriorityString(priority), str) < 0) {

This would be the place where we'd add in (optional) inclusion of the function name & line number data.

I think it makes sense only for debugging logs, so I'm tempted to only output filename:linenr this if the priority is VIR_LOG_DEBUG and the filename is not NULL. Also note that the virLogOutputFunc callbacks will then get the file and line in the string but also as a parameter, but that may be useful for further filtering or completing the string in case of non debug output.

...

+ +#define IS_SPACE(cur) \ + ((*cur == ' ') || (*cur == '\t') || (*cur == '\n') || \ + (*cur == '\r') || (*cur == '\\'))

GNULIB already provides this with c_isspace() - unless we really need the check for '\\' too ?

Well that correspond to the space definition used in virSkipSpaces and it's IMHO better to keep them coherent to avoid silly problems :-)

All basically looks good to me.

Okay, thanks, Daniel -- Daniel Veillard | libxml Gnome XML XSLT toolkit http://xmlsoft.org/ daniel@veillard.com | Rpmfind RPM search engine http://rpmfind.net/ http://veillard.com/ | virtualization library http://libvirt.org/