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_FIXME,
    __WINE_DBCL_ERR,
    __WINE_DBCL_WARN,
    __WINE_DBCL_TRACE,

    __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

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 );
    va_end(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 =
{
    get_temp_buffer,
    release_temp_buffer,
    default_dbgstr_an,
    default_dbgstr_wn,
    default_dbg_vprintf,
    default_dbg_vlog
};

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

static const struct __wine_debug_functions funcs =
{
    get_temp_buffer,
    release_temp_buffer,
    NTDLL_dbgstr_an,
    NTDLL_dbgstr_wn,
    NTDLL_dbg_vprintf,
    NTDLL_dbg_vlog
};

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 );
    va_end(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)
#endif
#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

#define WINE_DEFAULT_DEBUG_CHANNEL(ch) \
    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

#define WINE_DECLARE_DEBUG_CHANNEL(ch) \
    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

summary

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