Function / macro analysis of wine debug log output

First, a general observation shows that the declaration related to debug is in / include/wine/debug.h and is referenced by each module.

First look at the definition of debug class:

enum __wine_debug_class

    __WINE_DBCL_INIT = 7  /* lazy init flag */

At the same time, five kinds of log entry for FIXME ERR WARN TRACE MESSAGE are defined, all of which are macros:

#define TRACE                      WINE_TRACE
#define TRACE_(ch)                 WINE_TRACE_(ch)
#define TRACE_ON(ch)               WINE_TRACE_ON(ch)

#define WARN                       WINE_WARN
#define WARN_(ch)                  WINE_WARN_(ch)
#define WARN_ON(ch)                WINE_WARN_ON(ch)

#define FIXME                      WINE_FIXME
#define FIXME_(ch)                 WINE_FIXME_(ch)
#define FIXME_ON(ch)               WINE_FIXME_ON(ch)

#define ERR                        WINE_ERR
#define ERR_(ch)                   WINE_ERR_(ch)
#define ERR_ON(ch)                 WINE_ERR_ON(ch)

#define DPRINTF                    WINE_DPRINTF
#define MESSAGE                    WINE_MESSAGE

As you can see, these macros are redirected to the corresponding wine? XXX macro.


Wine? Message is relatively simple, and it is directly directed to the function wine? DBG? Printf:

#define WINE_DPRINTF               wine_dbg_printf
#define WINE_MESSAGE               wine_dbg_printf

/* varargs wrapper for funcs.dbg_vprintf */
int wine_dbg_printf( const char *format, ... )
    int ret;
    // valist comes from variables like
    va_list valist;

    va_start(valist, format);
    ret = funcs.dbg_vprintf( format, valist );
    return ret;

// What is funcs? Find the definition of funcs

static struct __wine_debug_functions funcs;

struct __wine_debug_functions
    char * (*get_temp_buffer)( size_t n );
    void   (*release_temp_buffer)( char *buffer, size_t n );
    const char * (*dbgstr_an)( const char * s, int n );
    const char * (*dbgstr_wn)( const WCHAR *s, int n );
    int (*dbg_vprintf)( const char *format, va_list args );
    int (*dbg_vlog)( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
                     const char *function, const char *format, va_list args );

// Where do these function pointers come from?

// Find a paragraph in / libs/debug.c

void __wine_dbg_set_functions( const struct __wine_debug_functions *new_funcs,
                               struct __wine_debug_functions *old_funcs, size_t size )
    if (old_funcs) memcpy( old_funcs, &funcs, min(sizeof(funcs),size) );
    if (new_funcs) memcpy( &funcs, new_funcs, min(sizeof(funcs),size) );

static struct __wine_debug_functions funcs =

// There is another section in / dlls/ntdll/debugtools.c for client to log

static const struct __wine_debug_functions funcs =

void debug_init(void)
    __wine_dbg_set_functions( &funcs, &default_funcs, sizeof(funcs) );

// In this paper, we ignore ntdll DBG vlog and only focus on default DBG vlog

static int default_dbg_vlog( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
                             const char *func, const char *format, va_list args )
    int ret = 0;

    if (cls < sizeof(debug_classes)/sizeof(debug_classes[0]))
        ret += wine_dbg_printf( "%s:%s:%s ", debug_classes[cls], channel->name, func );
    if (format)
        ret += funcs.dbg_vprintf( format, args );
    return ret;

// Find the debug classes

static const char * const debug_classes[] = { "fixme", "err", "warn", "trace" };

// It seems that the output log will first try to start with "< debug class >: < channel name >: < func name >"

// See wine? DBG? Printf first

/* varargs wrapper for funcs.dbg_vprintf */
int wine_dbg_printf( const char *format, ... )
    int ret;
    va_list valist;

    va_start(valist, format);
    ret = funcs.dbg_vprintf( format, valist );
    return ret;

// Funcs.dbg-vprintf is default-dbg-vprintf

/* default implementation of wine_dbg_vprintf */
static int default_dbg_vprintf( const char *format, va_list args )
    return vfprintf( stderr, format, args );

// At the end, vfprintf is the standard library function, where stderr is written, and the return value is the number of bytes written

Other wine

The structure of other win ﹣ XXX macros is the same. One of them can be analyzed. Take win ﹣ trace as an example:

#ifndef WINE_TRACE
#define WINE_TRACE                 __WINE_DPRINTF(_TRACE,__wine_dbch___default)
#define WINE_TRACE_(ch)            __WINE_DPRINTF(_TRACE,&__wine_dbch_##ch)
#define WINE_TRACE_ON(ch)          __WINE_IS_DEBUG_ON(_TRACE,&__wine_dbch_##ch)

First, analyze the content of dprintf:

#define __WINE_DPRINTF(dbcl,dbch) \
    (!__WINE_GET_DEBUGGING(dbcl,(dbch)) || \
     (wine_dbg_log(__WINE_DBCL##dbcl,(dbch),__FILE__,"%d: ",__LINE__) == -1)) ? \
     (void)0 : (void)wine_dbg_printf

// If two conditions have a false, then return 0, otherwise return wine_dbg_printf

// First look at condition 1. The definition of macro get debugging is

#define __WINE_GET_DEBUGGING(dbcl,dbch)  __WINE_GET_DEBUGGING##dbcl(dbch)

// By substituting dbcl (﹐ trace), a new macro is obtained. The macro definition is

#define __WINE_GET_DEBUGGING_TRACE(dbch) ((dbch)->flags & (1 << __WINE_DBCL_TRACE))

// This is to determine whether the TRACE binary bit is set in (DBCH) - > flags. Substituting the parameter DBCH (\\\\\\\\\\\\\

// Find the definition of "wine" DBCH "default

    static struct __wine_debug_channel __wine_dbch_##ch = { ~0, #ch }; \
    static struct __wine_debug_channel * const __wine_dbch___default = &__wine_dbch_##ch

// You can see that only one "wine" DBCH "channel can be declared, and one" wine "DBCH" channel will be declared at the same time

// Find the definition of "wine" debug "channel

struct __wine_debug_channel
    unsigned char flags;
    char name[15];

// We can see that it is mainly a data structure for storing flags

// Before this sentence, there is a win? Declare? Debug? Channel macro, which is where other channels are declared

    static struct __wine_debug_channel __wine_dbch_##ch = { ~0, #ch }

// Looking at condition 2, the definition of the function wine DBG log is

/* varargs wrapper for funcs.dbg_vlog */
int wine_dbg_log( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
                  const char *func, const char *format, ... )
    // Check whether the channel flag matches the current debug class
    if (!(__wine_dbg_get_channel_flags( channel ) & (1 << cls))) return -1;
    // The actual call is valist ['File ',' d: ','line']
    return funcs.dbg_vlog( cls, channel, func, format, valist );

// vfprintf is a standard library function, which returns the number of bytes written. Looking back all the way, we know that condition 2 is to check whether there is successful output of file and line information

Re analyze the content of "win" is "debug" on:

#define __WINE_IS_DEBUG_ON(dbcl,dbch) \
  (__WINE_GET_DEBUGGING##dbcl(dbch) && (__wine_dbg_get_channel_flags(dbch) & (1 << __WINE_DBCL##dbcl)))

// With previous experience, this is to check whether the current dbcl (TRACE) is set in ("> wine > DBCH > Default) - > flags and (DBCH) - > flags


In general, the linkage between the two is as follows:

if (TRACE_ON(channel_literal))
    TRACE(a, b, c, ...);

The default output stream is stderr.

Added by met0555 on Fri, 03 Jan 2020 01:41:34 +0200