wine调试日志实现和实践

输出日志是一种很常见的调试方法,特别是诡异的多线程bug,随机崩溃等问题,在正确的地方输出日志缩小范围是最有效的方法。
其次对不熟悉的代码勤快打日志,可以很快熟悉代码的流程和作用;对于一个大型项目来说,一般都会先实现一套自己的日志函数:
一是方便开发人员轻松打日志,快速debug;二可以统一日志格式和存储,方便用户报告日志,所以wine也不例外,而且wine的实现非常简洁。
下面就详细总结一下。

wine的调试日志实现

调试通道 (debug channel)

wine定义了调试通道的概念来分类日志,将日志的记录和实际的输出分离,无需重新编译,就能灵活控制日志输出。

  • 每个调试通道有一个唯一的名字, 长度不超过14个有效字符, 一般一个模块至少定义了一个调试通道,比如 gdi32.dll模块,有一个名称叫gdi的调试通道.
  • 复杂的模块,为了细分日志定义了多个调试通道,比如 gdi32.dll模块,还有定义clipping,region,font,bitmap,print,bitblt等调试通道
  • 调试通道在代码里面来看实际是一个__wine_debug_channel 的结构体,刚好16个字节,非常符合 unix哲学的简单原则:
struct __wine_debug_channel
{
    unsigned char flags;
    char name[15];
};
  • 日志一次只发送给一个调试通道.

  • 代码里面增加一个新的调试通道:
    1) 包含 include/wine/debug.h
    2) 然后用WINE_DEFAULT_DEBUG_CHANNELWINE_DEFAULT_DEBUG_CHANNEL宏来声明

  • 要知道一个模块定义了哪些调试通道,只需这样搜索该模块的所有源码:git grep _DEBUG_CHANNEL

向调试通道发送日志

wine把日志分成了4个级别,从高到低依次是:fixme/err(or)/warn/trace,对应的提供了4个宏来输出不同级别的日志到调试通道:FIXME/WARN/ERR/TRACE, 用起来非常清晰,简单;

#define __WINE_DPRINTF(dbcl,dbch) \
  do { if(__WINE_GET_DEBUGGING(dbcl,(dbch))) { \
       struct __wine_debug_channel * const __dbch = (dbch); \
       const enum __wine_debug_class __dbcl = __WINE_DBCL##dbcl; \
       __WINE_DBG_LOG

#define __WINE_DBG_LOG(args...) \
    wine_dbg_log( __dbcl, __dbch, __FUNCTION__, args); } } while(0)

#define TRACE                 __WINE_DPRINTF(_TRACE,__wine_dbch___default)
#define TRACE_(ch)            __WINE_DPRINTF(_TRACE,&__wine_dbch_##ch)
#define TRACE_ON(ch)          __WINE_IS_DEBUG_ON(_TRACE,&__wine_dbch_##ch)

#define WARN                  __WINE_DPRINTF(_WARN,__wine_dbch___default)
#define WARN_(ch)             __WINE_DPRINTF(_WARN,&__wine_dbch_##ch)
#define WARN_ON(ch)           __WINE_IS_DEBUG_ON(_WARN,&__wine_dbch_##ch)

#define FIXME                 __WINE_DPRINTF(_FIXME,__wine_dbch___default)
#define FIXME_(ch)            __WINE_DPRINTF(_FIXME,&__wine_dbch_##ch)
#define FIXME_ON(ch)          __WINE_IS_DEBUG_ON(_FIXME,&__wine_dbch_##ch)

#define ERR                   __WINE_DPRINTF(_ERR,__wine_dbch___default)
#define ERR_(ch)              __WINE_DPRINTF(_ERR,&__wine_dbch_##ch)
#define ERR_ON(ch)            __WINE_IS_DEBUG_ON(_ERR,&__wine_dbch_##ch)

最终都是调用函数 wine_dbg_log 来打日志:

int wine_dbg_log( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
                  const char *func, const char *format, ... )
{
    int ret;
    va_list valist;

    if (!(__wine_dbg_get_channel_flags( channel ) & (1 << cls))) return -1;

    va_start(valist, format);
    ret = funcs.dbg_vlog( cls, channel, func, format, valist );
    va_end(valist);
    return ret;
}

其中的funcs.dbg_vlog 初始化时候指向 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 )

在wine线程创建成功后会 funcs.dbg_vlog 指向 ntdll/debugtools.c的

  static int NTDLL_dbg_vlog( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
                           const char *function, const char *format, va_list args )

运行前开启调试通道

这样的格式定义环境变量:
WINEDEBUG=[class][+/-]channel[,[class2][+/-]channel2]
其中:
* class是fixme,err,warn,trace这4个日志级别的一个单词,如果没有指定就开关所有的日志级别.
* channel就是要开关的调试通道的名称,all代表所有的通道.
* +就是开启指定调试通道的对应的日志级别.
* -就是关闭指定调试通道的对应的日志级别.

举例:

WINEDEBUG=warn+all
WINEDEBUG=warn+dll,+heap
WINEDEBUG=fixme-all,warn+cursor,+relay

如果没有定义WINEDEBUG环境变量, 发给每个调试通道的fixme和err级别的日志都会输出;wine默认同时开启运行的调试通道是256个,由这个宏 MAX_DEBUG_OPTIONS 决定 。
关键代码如下:

enum __wine_debug_class
{
    __WINE_DBCL_FIXME,
    __WINE_DBCL_ERR,
    __WINE_DBCL_WARN,
    __WINE_DBCL_TRACE,

    __WINE_DBCL_INIT = 7  /* lazy init flag, bit7 */
};

static unsigned char default_flags = (1 << __WINE_DBCL_ERR) | (1 <name, debug_options, nb_debug_options,
                                                    sizeof(debug_options[0]), cmp_name );
        if (opt) return opt->flags;
    }
    /* no option for this channel */
    if (channel->flags & (1 <flags = default_flags;
    return default_flags;
}

仅标记作用的调试通道

  • pid: 在每个日志的前面插入当前进程的ID号,格式: %04x
  • tid: 在每个日志的前面插入当前线程的ID号,格式: %04x
  • timestamp: 在每个日志的前面插入时间戳, 相对系统启动的时间, 单位秒,保留3位小数

特殊的高级的调试通道

  • seh: 记录所有的异常情况,快速定位程序崩溃地址。
0009:trace:seh:raise_exception code=c00002b5 flags=0 addr=0xc4194be ip=0c4194be tid=0009
0009:trace:seh:raise_exception  info[0]=00000000
0009:trace:seh:raise_exception  eax=00000006 ebx=0b6f4f58 ecx=08b44020 edx=0033d15c esi=0dfde520 edi=0df80020
0009:trace:seh:raise_exception  ebp=0033d0d0 esp=0033d0c0 cs=0023 ds=002b es=002b fs=0063 gs=006b flags=00210206
  • relay: 无需修改代码,记录程序调用wine实现的所有API的详细参数和返回值,
...
0017:Call KERNEL32.CreateFileA(7ea8e936 "CONIN$",c0000000,00000003,00000000,00000003,00000000,00000000) ret=7ea323fd
0017:Ret  KERNEL32.CreateFileA() retval=00000023 ret=7ea323fd
...
  • snoop: 无需修改代码,记录程序对第三方native模块的所有导出函数的调用参数和返回值。snoop是自己检查stack数据和反汇编来探测函数调用约定,参数和返回地址的,
    如果探测错了会影响程序的稳定,甚至导致程序崩溃,非常规情况下使用.
...
trace:snoop:SNOOP_SetupDLL hmod=0x4ae90000, name=gdiplus.dll
0043:CALL MSVCR100_CLR0400.wcscpy_s(04b7c808,0000000c,0033d188 L"gdiplus.dll") ret=79203d6b
0043:RET  MSVCR100_CLR0400.wcscpy_s() retval=00000000 ret=79203d6b
0043:CALL MSVCR100_CLR0400.memset(0033dc9c,00000000,00000010) ret=792bd727
0043:RET  MSVCR100_CLR0400.memset() retval=0033dc9c ret=792bd727
0043:CALL gdiplus.GdiplusStartup() ret=04b8e775
0043:RET  gdiplus.GdiplusStartup(03c00ae0,0033dc9c,0033dcec) retval=00000000 ret=04b8e775
...
0043:CALL gdiplus.GdipCreateFromHWND() ret=04b8e8b3
0043:RET  gdiplus.GdipCreateFromHWND(0004003a,0033e988) retval=00000000 ret=04b8e8b3
...

relay和snoop的缺点是记录的日志巨大导致程序反应非常慢,只能在没有任何思路,一筹莫展时使用。

运行中开关调试通道

  • 方法1, 运行任务管理器(wine taskmgr), 打开“进程”标签页,右键选中进程,在右键菜单里面选中“编辑调试频道”. 这个方法只能开关事先在WINEDEBUG环境变量里面列出的调试通道.

  • 方法2, winedbg里面attach指定的wine进程,然后用set命令:

    • set + channel 开启指定通道的所有fixme/err/warn/trace日志
    • set – channel 关闭指定通道的所有fixme/err/warn/trace日志
    • set class + channel 开启指定通道的fixme/err/warn/trace日志的一类 
    • set class – channel 关闭指定通道的fixme/err/warn/trace日志的一类
      winedbg的set命令也只能设置用WINEDEBUG已经开启了的调试通道.
      如果没有在WINEDEBUG里面定义的,就会提示: Unable to find debug channel xxx
  • 方法3, winedbg的attach指定的wine进程,手动修改debug_optionsnb_debug_options的数据:因为debug_options是按照调试通道名称字符串比较排序的,所以开启多个通道需要手动排序.
    这个方法适合运行程序时忘记设置WINEDEBUG,但是想查看某个调试通道日志的时候又不想重新运行程序的时候使用.

Wine-dbg>set + win
Unable to find debug channel win
Wine-dbg>p debug_options[0]
{flags=0, name=""}
Wine-dbg);set debug_options[0].flags=0xf
Wine-dbg>p debug_options[0]
{flags=f, name=""}
Wine-dbg>set debug_options[0].name[0]='w'
Wine-dbg>set debug_options[0].name[1]='i'
Wine-dbg>set debug_options[0].name[2]='n'
Wine-dbg>set debug_options[0].name[3]= 0
Wine-dbg>p debug_options[0]
{flags=f, name="楷n"}
Wine-dbg>p &debug_options[0]
0xf77092d0
Wine-dbg>x /s 0xf77092d1
win
Wine-dbg>p nb_debug_options
0
Wine-dbg>set nb_debug_options=1
  • 方法4,一般正式发布的libwine.so没有调试符号,就只能反汇编定位debug_optionsnb_debug_options的地址.

1) 先查询__wine_dbg_get_channel_flags的偏移, readelf -s libwine.so.1.0 | grep __wine_dbg :

   109: 00005110   206 FUNC    GLOBAL DEFAULT   12 __wine_dbg_set_channel_fl@@WINE_1.0
   166: 00005030   223 FUNC    GLOBAL DEFAULT   12 __wine_dbg_get_channel_fl@@WINE_1.0
   172: 00005390   253 FUNC    GLOBAL DEFAULT   12 __wine_dbg_set_functions@@WINE_1.0

2) 再查询libwine.so的基地址得到__wine_dbg_get_channel_flags的地址

Wine-dbg>info share
Module  Address         Debug info  Name (23 modules)
...
ELF f75d5000-f778c000   Dwarf           libwine.so.1                    @,/opt/cxoffice/bin/../lib/libwine.so.1
...

3) 接着看__wine_dbg_get_channel_flags反汇编:

Wine-dbg>disass 0xf75d5000+0x5030
0xf75da030 __wine_dbg_get_channel_flags in libwine.so.1: push ebp 
0xf75da031 __wine_dbg_get_channel_flags+0x1 in libwine.so.1: mov ebp, esp 
0xf75da033 __wine_dbg_get_channel_flags+0x3 in libwine.so.1: push edi 
0xf75da034 __wine_dbg_get_channel_flags+0x4 in libwine.so.1: push esi 
0xf75da035 __wine_dbg_get_channel_flags+0x5 in libwine.so.1: push ebx 
0xf75da036 __wine_dbg_get_channel_flags+0x6 in libwine.so.1: call 0xf75d81a0 
0xf75da03b __wine_dbg_get_channel_flags+0xb in libwine.so.1: add ebx, 0x19dfc5 
0xf75da041 __wine_dbg_get_channel_flags+0x11 in libwine.so.1: sub esp, 0x1c 
0xf75da044 __wine_dbg_get_channel_flags+0x14 in libwine.so.1: mov ecx, [ebx+0x134]  --> nb_debug_options
0xf75da04a __wine_dbg_get_channel_flags+0x1a in libwine.so.1: cmp ecx, 0xffffffff 
0xf75da04d __wine_dbg_get_channel_flags+0x1d in libwine.so.1: jz 0xf75da0f0 
0xf75da053 __wine_dbg_get_channel_flags+0x23 in libwine.so.1: test ecx, ecx 
0xf75da055 __wine_dbg_get_channel_flags+0x25 in libwine.so.1: jz 0xf75da0c0 
0xf75da057 __wine_dbg_get_channel_flags+0x27 in libwine.so.1: mov eax, [ebp+0x8] 
0xf75da05a __wine_dbg_get_channel_flags+0x2a in libwine.so.1: mov edi, ecx 
0xf75da05c __wine_dbg_get_channel_flags+0x2c in libwine.so.1: mov dword [ebp-0x1c], 0x0 
0xf75da063 __wine_dbg_get_channel_flags+0x33 in libwine.so.1: add eax, 0x1 
0xf75da066 __wine_dbg_get_channel_flags+0x36 in libwine.so.1: mov [ebp-0x24], eax 
0xf75da069 __wine_dbg_get_channel_flags+0x39 in libwine.so.1: lea eax, [ebx+0x260]  --> debug_options 
0xf75da06f __wine_dbg_get_channel_flags+0x3f in libwine.so.1: mov [ebp-0x28], eax 
0xf75da072 __wine_dbg_get_channel_flags+0x42 in libwine.so.1: jmp 0xf75da07f  __wine_dbg_get_channel_flags+0x4f in libwine.so.1
0xf75d3074 __wine_dbg_get_channel_flags+0x44 in libwine.so.1: lea esi, [esi] 
...
0xf75d81a0: mov ebx, [esp] 
0xf75d81a3: ret 

gcc习惯通过ebx寄存器来引用全局变量, 所以nb_debug_options的地址是: 0xf75d303b+0x19dfc5+0x134; debug_options的地址是: 0xf75d303b+0x19dfc5+0x260;然后参考方法2的set命令修改内存即可。

relay 实现原理

在 LoadLibrary 内部检查开启了relay通道并且是加载wine内建的dll, 就调用RELAY_SetupDLL解析dll的导出函数表(IMAGE_DIRECTORY_ENTRY_EXPORT),对导出表的AddressOfFunctions数组每个成员,先备份原始值,然后修改成可以跳到relay_call函数的hack函数地址, hack函数在faked PE模块里面, 固定的24个字节大小, 形式都是这样的:

0x7e7a4210: push esp 
0x7e7a4211: push 0x50000 
0x7e7a4216: call 0x7e7a6a40  __wine_spec_get_pc_thunk_eax in gdi32
0x7e7a421b: lea eax, [eax+0xadd31] 
0x7e7a4221: push eax 
0x7e7a4222: call dword [eax+0x4] --> relay_call 
0x7e7a4225: ret 0x14 

不同的API,变化的是里面的数字常量而已.在GetProcAddress 内部检查是否开启了relay通道,是就调用RELAY_GetProcAddress 返回 hack的函数地址.以user32模块的GetMenu举例, 返回的hack的GetMenu 函数:

FARPROC RELAY_GetProcAddress( HMODULE module, const IMAGE_EXPORT_DIRECTORY *exports,
                              DWORD exp_size, FARPROC proc, DWORD ordinal, const WCHAR *user )
{
    struct relay_private_data *data;
    const struct relay_descr *descr = (const struct relay_descr *)((const char *)exports + exp_size);

    if (descr->magic != RELAY_DESCR_MAGIC || !(data = descr->private)) return proc;  /* no relay data */
    if (!data->entry_points[ordinal].orig_func) return proc;  /* not a relayed function */
    if (check_from_module( debug_from_relay_includelist, debug_from_relay_excludelist, user ))
        return proc;  /* we want to relay it */
    return data->entry_points[ordinal].orig_func;
}              

Wine-dbg>disass proc
0x7e8d7cf0: push esp 
0x7e8d7cf1: push 0x10130 
0x7e8d7cf6: call 0x7e8dae44  __wine_spec_get_pc_thunk_eax in user32
0x7e8d7cfb: lea eax, [eax+0xd9fcd] 
0x7e8d7d01: push eax 
0x7e8d7d02: call dword [eax+0x4] 
0x7e8d7d05: ret 0x4 
Wine-dbg>p 0x7e8d7cfb+0xd9fcd+0x4             
0x7e9b1ccc
Wine-dbg>x /4x 0x7e9b1ccc
0x7e9b1ccc:  7bc76c2c 7bc77270 00124640 7e8d615d
Wine-dbg>disass 0x7bc76c2c
0x7bc76c2c relay_call in ntdll: push ebp 
0x7bc76c2d relay_call+0x1 in ntdll: mov ebp, esp 
0x7bc76c2f relay_call+0x3 in ntdll: push esi 
0x7bc76c30 relay_call+0x4 in ntdll: push edi 
0x7bc76c31 relay_call+0x5 in ntdll: push ecx 
0x7bc76c32 relay_call+0x6 in ntdll: push dword [ebp+0x10] 
0x7bc76c35 relay_call+0x9 in ntdll: push dword [ebp+0xc] 
0x7bc76c38 relay_call+0xc in ntdll: push dword [ebp+0x8] 
0x7bc76c3b relay_call+0xf in ntdll: call 0x7bc76835  relay_trace_entry [../wine_git/dlls/ntdll/relay.c:334] in ntdll
0x7bc76c40 relay_call+0x14 in ntdll: movzx ecx, byte [ebp+0xe] 
...

原始的GetMenu地址:

Wine-dbg>info local           
0x7bc772f4 RELAY_GetProcAddress+0x75: (0033eac8)
    HMODULE module=0x7e8d0000 (parameter [EBP+8])
    IMAGE_EXPORT_DIRECTORY* exports=0x7e9ad19c (parameter [EBP+12])
    DWORD exp_size=0x4b2c (parameter [EBP+16])
    FARPROC proc=0x7e8d7cf0 (parameter [EBP+20])
    DWORD ordinal=0x130 (parameter [EBP+24])
    WCHAR* user=0x0(nil) (parameter [EBP+28])
    struct relay_private_data* data=0x124640 (local [EBP-12])
    struct relay_descr* descr=0x7e9b1cc8 (local [EBP-16])
Wine-dbg>p *descr
{magic=0xdeb90001, relay_call=0x7bc76c2c, relay_call_regs=0x7bc77270,
    private=0x124640, entry_point_base="恌怲h", entry_point_offsets=0x7e9744f8, arg_types=0x7e975048}
Wine-dbg>x /14x 0x124640        
0x00124640:  7e8d0000 00000001 72657375 00003233
0x00124650:  00000000 00000000 00000000 00000000
0x00124660:  00000000 00000000 00000000 00000000
0x00124670:  7e913010 7e9aee17
Wine-dbg>x /10x 0x00124670+0x130*8
0x00124ff0:  7e928890 7e9b018c 7e92c6d0 7e9b0194
0x00125000:  7e927fc0 7e9b01a3 7e92cc30 7e9b01be
0x00125010:  7e92b680 7e9b01d3
Wine-dbg>x /10c 0x7e9b018c
0x7e9b018c:  G e t M e n u   G e
Wine-dbg>disass 0x7e928890
0x7e928890 GetMenu [../wine_git/dlls/user32/menu.c:4208] in user32: lea ecx, [esp+0x4] 
0x7e928894 GetMenu+0x4 [../wine_git/dlls/user32/menu.c:4208] in user32: and esp, 0xfffffff0 
0x7e928897 GetMenu+0x7 [../wine_git/dlls/user32/menu.c:4208] in user32: push dword [ecx-0x4] 
0x7e92889a GetMenu+0xa [../wine_git/dlls/user32/menu.c:4208] in user32: push ebp 
0x7e92889b GetMenu+0xb [../wine_git/dlls/user32/menu.c:4208] in user32: mov ebp, esp 
0x7e92889d GetMenu+0xd [../wine_git/dlls/user32/menu.c:4208] in user32: push edi 
0x7e92889e GetMenu+0xe [../wine_git/dlls/user32/menu.c:4208] in user32: push esi 
0x7e92889f GetMenu+0xf [../wine_git/dlls/user32/menu.c:4208] in user32: push ebx 
0x7e9288a0 GetMenu+0x10 [../wine_git/dlls/user32/menu.c:4208] in user32: push ecx 
0x7e9288a1 GetMenu+0x11 [../wine_git/dlls/user32/menu.c:4208] in user32: call 0x7e8d5b60  __x86.get_pc_thunk.bx in user32
...

relay_call里面调用relay_trace_entry/relay_trace_exit来记录函数的进和出,以及调用真实的API.

snoop的实现原理

  • 在 LoadLibrary 内部检查开启了snoop通道并且是加载native的dll,就调用 SNOOP_SetupDLL,解析dll的导出函数,对每个导出函数动态分配一块可读写和执行的hack内存.
  • 在 GetProcAddress 内部检查开启了snoop通道,就调用 SNOOP_GetProcAddress, 对hack内存填充一个可以跳到 SNOOP_Entry 函数的jmp指令, 然后返回把这个hack内存块的首地址.
  • SNOOP_Entry探测函数的返回地址/调用约定/调用参数,打印出来,然后把当前EIP设置成真实的导出函数,把返回地址设置SNOOP_Return.

用日志来解决实际的问题

先收集日志,然后重点看err:,fixme:, seh: 的日志,一般就是出问题的地方了.

3 条思考于 “wine调试日志实现和实践

  1. Pingback: Wine 开发系列之 —— 入门 – Deepin Tech Blog

发表评论

电子邮件地址不会被公开。 必填项已用*标注