Wine开发系列——如何使用Wine日志调试问题

输出调试日志是调试程序的一种常见方法，尤其是处理那些难以捉摸的多线程错误、随机崩溃等问题时。通过在合适的位置输出调试日志，可以帮助我们更快地定位问题所在。对于不熟悉的代码，经常打日志也有助于快速理解代码的执行流程和功能。在大型项目中，通常会先实现一套自己的调试日志框架，主要有两个目的：

• 统一日志风格和存储：确保日志格式一致，并且有统一的存储方式，这有助于用户更容易地报告问题。
• 方便开发人员：开发人员能够轻松地记录日志，从而快速调试问题。

Wine 项目也不例外，它也实现了一套自己的日志系统。这套系统非常简洁，下面我们就来详细介绍。

Wine 的调试日志实现

调试通道（debug channel）Wine 定义了调试通道的概念来分类日志，将日志的记录和实际的输出分离，无需重新编译 Wine，就能动态地灵活控制 Wine 运行时的日志输出。

• 每个调试通道有一个唯一的名字, 长度不超过14个可见的 ASCII 字符， 一般一个模块至少定义了一个调试通道，比如 gdi32.dll 模块，有一个名称叫 gdi 的调试通道。
• 复杂的模块，为了细分日志定义了多个调试通道，比如 gdi32.dll 模块，还定义了clipping、region、font、bitmap、print、bitblt 等调试通道。
• 调试通道在代码里面来看实际是一个__wine_debug_channel 的结构体，刚好16个字节，非常符合 UNIX 简单原则的哲学理念：

struct__wine_debug_channel { unsignedcharflags; charname[15]; };1. 包含 include/wine/debug.h ；2. 然后用WINE_DEFAULT_DEBUG_CHANNEL或WINE_DEFAULT_DEBUG_CHANNEL宏来声明。

• 日志一次只发送给一个调试通道。
• 代码里增加一个新的调试通道，非常简单：
• 要知道一个模块定义了哪些调试通道，只需这样搜索该模块的所有源码:git grep _DEBUG_CHANNEL 。

向调试通道发送日志Wine 把日志分成了4个级别，从高到低依次是：fixme/ err(or)/ warn/ trace，对应的提供了4个宏来输出不同级别的日志到调试通道：FIXME/ ERR/WARN/ TRACE，非常简单、清晰。

#define__WINE_DPRINTF(dbcl,dbch) do{if(__WINE_GET_DEBUGGING(dbcl,(dbch))){ struct__wine_debug_channel*const__dbch=(dbch); constenum__wine_debug_class__dbcl=__WINE_DBCL##dbcl; __WINE_DBG_LOG #define__WINE_DBG_LOG(args...) wine_dbg_log(__dbcl,__dbch,__FUNCTION__,args);}}while(0) #defineTRACE__WINE_DPRINTF(_TRACE,__wine_dbch___default) #defineTRACE_(ch)__WINE_DPRINTF(_TRACE,&__wine_dbch_##ch) #defineTRACE_ON(ch)__WINE_IS_DEBUG_ON(_TRACE,&__wine_dbch_##ch) #defineWARN__WINE_DPRINTF(_WARN,__wine_dbch___default) #defineWARN_(ch)__WINE_DPRINTF(_WARN,&__wine_dbch_##ch) #defineWARN_ON(ch)__WINE_IS_DEBUG_ON(_WARN,&__wine_dbch_##ch) #defineFIXME__WINE_DPRINTF(_FIXME,__wine_dbch___default) #defineFIXME_(ch)__WINE_DPRINTF(_FIXME,&__wine_dbch_##ch) #defineFIXME_ON(ch)__WINE_IS_DEBUG_ON(_FIXME,&__wine_dbch_##ch) #defineERR__WINE_DPRINTF(_ERR,__wine_dbch___default) #defineERR_(ch)__WINE_DPRINTF(_ERR,&__wine_dbch_##ch) #defineERR_ON(ch)__WINE_IS_DEBUG_ON(_ERR,&__wine_dbch_##ch)最终都是调用函数 wine_dbg_log 来打日志：

intwine_dbg_log(enum__wine_debug_classcls,struct__wine_debug_channel*channel, constchar*func,constchar*format,...) { intret; va_listvalist; 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); returnret; }其中的 funcs.dbg_vlog 初始化时会指向 default_dbg_vlog：

staticintdefault_dbg_vlog(enum__wine_debug_classcls,struct__wine_debug_channel*channel, constchar*func,constchar*format,va_listargs)在Wine线程创建成功后 funcs.dbg_vlog 会指向 ntdll/debugtools.c 的

staticintNTDLL_dbg_vlog(enum__wine_debug_classcls,struct__wine_debug_channel*channel, constchar*function,constchar*format,va_listargs)

程序运行前开启调试通道

用这样的格式定义环境变量：WINEDEBUG=[class][+/-]channel[,[class2][+/-]channel2]

其中：

• class：是代表 fixme/ err/ warn/ trace 这４个日志级别的一个单词，如果没有指定就开关所有的日志级别。

• 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/*lazyinitflag,bit7*/ }; staticunsignedchardefault_flags=(1<< __WINE_DBCL_ERR) | (1 if(opt)returnopt->flags; } /*nooptionforthischannel*/ if(channel->flags&(1returndefault_flags; }

仅标记作用的调试通道

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

比较特殊的高级调试通道

• seh：记录所有的异常情况，快速定位程序崩溃地址。

0009seh:raise_exceptioncode=c00002b5flags=0addr=0xc4194beip=0c4194betid=0009 0009seh:raise_exceptioninfo[0]=00000000 0009seh:raise_exceptioneax=00000006ebx=0b6f4f58ecx=08b44020edx=0033d15cesi=0dfde520edi=0df80020 0009seh:raise_exceptionebp=0033d0d0esp=0033d0c0cs=0023ds=002bes=002bfs=0063gs=006bflags=00210206

• relay：无需修改代码，记录程序调用 Wine 实现的所有 API 的详细参数和返回值。

... 0017:CallKERNEL32.CreateFileA(7ea8e936"CONIN$",c0000000,00000003,00000000,00000003,00000000,00000000)ret=7ea323fd 0017:RetKERNEL32.CreateFileA()retval=00000023ret=7ea323fd ...

• snoop：无需修改代码，记录程序对第三方 native 模块的所有导出函数的调用参数和返回值。Snoop 是自己检查 stack 数据和反汇编来探测函数调用约定、参数和返回地址的，如果探测错了会影响程序的稳定，甚至导致程序崩溃，建议仅在非常规情况下使用。

... traceSNOOP_SetupDLLhmod=0x4ae90000,name=gdiplus.dll 0043:CALLMSVCR100_CLR0400.wcscpy_s(04b7c808,0000000c,0033d188L"gdiplus.dll")ret=79203d6b 0043:RETMSVCR100_CLR0400.wcscpy_s()retval=00000000ret=79203d6b 0043:CALLMSVCR100_CLR0400.memset(0033dc9c,00000000,00000010)ret=792bd727 0043:RETMSVCR100_CLR0400.memset()retval=0033dc9cret=792bd727 0043:CALLgdiplus.GdiplusStartup()ret=04b8e775 0043:RETgdiplus.GdiplusStartup(03c00ae0,0033dc9c,0033dcec)retval=00000000ret=04b8e775 ... 0043:CALLgdiplus.GdipCreateFromHWND()ret=04b8e8b3 0043:RETgdiplus.GdipCreateFromHWND(0004003a,0033e988)retval=00000000ret=04b8e8b3 ...Relay 和 snoop 的缺点是记录的日志巨大导致程序反应非常慢，只建议在没有任何思路、一筹莫展时使用。

程序运行中动态开关调试通道1. set + channel：开启指定通道的所有 fixme/ err/ warn/ trace 日志。2. set - channel：关闭指定通道的所有 fixme/ err/ warn/ trace 日志。3. set class + channel：开启指定通道的fixme/ err/ warn/ trace日志中的某一类。class 替换为fixme/ err/ warn/ trace这4个单词中的任意一个。4. set class - channel：关闭指定通道的fixme/ err/ warn/ trace日志中的某一类。Winedbg 的 set 命令也只能设置在WINEDEBUG已经开启了的调试通道。如果没有在WINEDEBUG里面定义的，就会提示: Unable to find debug channel xxx 。

• 方法1：运行任务管理器(wine taskmgr)，打开“进程”标签页，右键选中进程，在右键菜单里面选中“编辑调试频道”。这个方法只能开关事先在WINEDEBUG环境变量里面列出的调试通道。
• 方法2：在 Winedbg 里 attach 指定的 Wine 进程，然后用 set 命令：
• 方法3：在Winedbg 里attach 指定的 Wine 进程，手动修改debug_options和nb_debug_options的数据。因为debug_options是按照调试通道名称字符串比较排序的，所以开启多个通道需要手动排序。这个方法适合运行程序时忘记设置WINEDEBUG，但是想查看某个调试通道日志时又不想重新运行程序的时候使用。

Wine-dbg>set+win Unabletofinddebugchannelwin Wine-dbg>pdebug_options[0] {flags=0,name=""} Wine-dbg);setdebug_options[0].flags=0xf Wine-dbg>pdebug_options[0] {flags=f,name=""} Wine-dbg>setdebug_options[0].name[0]='w' Wine-dbg>setdebug_options[0].name[1]='i' Wine-dbg>setdebug_options[0].name[2]='n' Wine-dbg>setdebug_options[0].name[3]=0 Wine-dbg>pdebug_options[0] {flags=f,name="楷n"} Wine-dbg>p&debug_options[0] 0xf77092d0 Wine-dbg>x/s0xf77092d1 win Wine-dbg>pnb_debug_options 0 Wine-dbg>setnb_debug_options=1

• 方法4：一般正式发布的 libwine.so 没有调试符号，就只能反汇编定位debug_options和nb_debug_options的地址。

1. 先查询 __wine_dbg_get_channel_flags 的偏移，readelf -s libwine.so.1.0 | grep __wine_dbg ：

109:00005110206FUNCGLOBALDEFAULT12__wine_dbg_set_channel_fl@@WINE_1.0 166:00005030223FUNCGLOBALDEFAULT12__wine_dbg_get_channel_fl@@WINE_1.0 172:00005390253FUNCGLOBALDEFAULT12__wine_dbg_set_functions@@WINE_1.0

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

Wine-dbg>infoshare ModuleAddressDebuginfoName(23modules) ... ELFf75d5000-f778c000Dwarflibwine.so.1@,/opt/cxoffice/bin/../lib/libwine.so.1 ...

3. 接着看 __wine_dbg_get_channel_flags 反汇编：

Wine-dbg>disass0xf75d5000+0x5030 0xf75da030__wine_dbg_get_channel_flagsinlibwine.so.1:pushebp 0xf75da031__wine_dbg_get_channel_flags+0x1inlibwine.so.1:movebp,esp 0xf75da033__wine_dbg_get_channel_flags+0x3inlibwine.so.1:pushedi 0xf75da034__wine_dbg_get_channel_flags+0x4inlibwine.so.1:pushesi 0xf75da035__wine_dbg_get_channel_flags+0x5inlibwine.so.1:pushebx 0xf75da036__wine_dbg_get_channel_flags+0x6inlibwine.so.1:call0xf75d81a0 0xf75da03b__wine_dbg_get_channel_flags+0xbinlibwine.so.1:addebx,0x19dfc5 0xf75da041__wine_dbg_get_channel_flags+0x11inlibwine.so.1:subesp,0x1c 0xf75da044__wine_dbg_get_channel_flags+0x14inlibwine.so.1:movecx,[ebx+0x134]-->nb_debug_options 0xf75da04a__wine_dbg_get_channel_flags+0x1ainlibwine.so.1:cmpecx,0xffffffff 0xf75da04d__wine_dbg_get_channel_flags+0x1dinlibwine.so.1:jz0xf75da0f0 0xf75da053__wine_dbg_get_channel_flags+0x23inlibwine.so.1:testecx,ecx 0xf75da055__wine_dbg_get_channel_flags+0x25inlibwine.so.1:jz0xf75da0c0 0xf75da057__wine_dbg_get_channel_flags+0x27inlibwine.so.1:moveax,[ebp+0x8] 0xf75da05a__wine_dbg_get_channel_flags+0x2ainlibwine.so.1:movedi,ecx 0xf75da05c__wine_dbg_get_channel_flags+0x2cinlibwine.so.1:movdword[ebp-0x1c],0x0 0xf75da063__wine_dbg_get_channel_flags+0x33inlibwine.so.1:addeax,0x1 0xf75da066__wine_dbg_get_channel_flags+0x36inlibwine.so.1:mov[ebp-0x24],eax 0xf75da069__wine_dbg_get_channel_flags+0x39inlibwine.so.1:leaeax,[ebx+0x260]-->debug_options 0xf75da06f__wine_dbg_get_channel_flags+0x3finlibwine.so.1:mov[ebp-0x28],eax 0xf75da072__wine_dbg_get_channel_flags+0x42inlibwine.so.1:jmp0xf75da07f__wine_dbg_get_channel_flags+0x4finlibwine.so.1 0xf75d3074__wine_dbg_get_channel_flags+0x44inlibwine.so.1:leaesi,[esi] ... 0xf75d81a0:movebx,[esp] 0xf75d81a3:retGCC 习惯通过 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:pushesp 0x7e7a4211:push0x50000 0x7e7a4216:call0x7e7a6a40__wine_spec_get_pc_thunk_eaxingdi32 0x7e7a421b:leaeax,[eax+0xadd31] 0x7e7a4221:pusheax 0x7e7a4222:calldword[eax+0x4]-->relay_call 0x7e7a4225:ret0x14不同的 API 变化的只是里面的数字常量。在 GetProcAddress 内部检查是否开启了 relay 通道，如已开启就调用 RELAY_GetProcAddress 返回 hack 的函数地址。以 user32 模块的GetMenu 举例，返回的 hack 的 GetMenu 函数如下：

FARPROCRELAY_GetProcAddress(HMODULEmodule,constIMAGE_EXPORT_DIRECTORY*exports, DWORDexp_size,FARPROCproc,DWORDordinal,constWCHAR*user) { structrelay_private_data*data; conststructrelay_descr*descr=(conststructrelay_descr*)((constchar*)exports+exp_size); if(descr->magic!=RELAY_DESCR_MAGIC||!(data=descr->private))returnproc;/*norelaydata*/ if(!data->entry_points[ordinal].orig_func)returnproc;/*notarelayedfunction*/ if(check_from_module(debug_from_relay_includelist,debug_from_relay_excludelist,user)) returnproc;/*wewanttorelayit*/ returndata->entry_points[ordinal].orig_func; } Wine-dbg>disassproc 0x7e8d7cf0:pushesp 0x7e8d7cf1:push0x10130 0x7e8d7cf6:call0x7e8dae44__wine_spec_get_pc_thunk_eaxinuser32 0x7e8d7cfb:leaeax,[eax+0xd9fcd] 0x7e8d7d01:pusheax 0x7e8d7d02:calldword[eax+0x4] 0x7e8d7d05:ret0x4 Wine-dbg>p0x7e8d7cfb+0xd9fcd+0x4 0x7e9b1ccc Wine-dbg>x/4x0x7e9b1ccc 0x7e9b1ccc:7bc76c2c7bc77270001246407e8d615d Wine-dbg>disass0x7bc76c2c 0x7bc76c2crelay_callinntdll:pushebp 0x7bc76c2drelay_call+0x1inntdll:movebp,esp 0x7bc76c2frelay_call+0x3inntdll:pushesi 0x7bc76c30relay_call+0x4inntdll:pushedi 0x7bc76c31relay_call+0x5inntdll:pushecx 0x7bc76c32relay_call+0x6inntdll:pushdword[ebp+0x10] 0x7bc76c35relay_call+0x9inntdll:pushdword[ebp+0xc] 0x7bc76c38relay_call+0xcinntdll:pushdword[ebp+0x8] 0x7bc76c3brelay_call+0xfinntdll:call0x7bc76835relay_trace_entry[../wine_git/dlls/ntdll/relay.c:334]inntdll 0x7bc76c40relay_call+0x14inntdll:movzxecx,byte[ebp+0xe] ...原始的 GetMenu 地址：

Wine-dbg>infolocal 0x7bc772f4RELAY_GetProcAddress+0x75:(0033eac8) HMODULEmodule=0x7e8d0000(parameter[EBP+8]) IMAGE_EXPORT_DIRECTORY*exports=0x7e9ad19c(parameter[EBP+12]) DWORDexp_size=0x4b2c(parameter[EBP+16]) FARPROCproc=0x7e8d7cf0(parameter[EBP+20]) DWORDordinal=0x130(parameter[EBP+24]) WCHAR*user=0x0(nil)(parameter[EBP+28]) structrelay_private_data*data=0x124640(local[EBP-12]) structrelay_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/14x0x124640 0x00124640:7e8d0000000000017265737500003233 0x00124650:00000000000000000000000000000000 0x00124660:00000000000000000000000000000000 0x00124670:7e9130107e9aee17 Wine-dbg>x/10x0x00124670+0x130*8 0x00124ff0:7e9288907e9b018c7e92c6d07e9b0194 0x00125000:7e927fc07e9b01a37e92cc307e9b01be 0x00125010:7e92b6807e9b01d3 Wine-dbg>x/10c0x7e9b018c 0x7e9b018c:GetMenuGe Wine-dbg>disass0x7e928890 0x7e928890GetMenu[../wine_git/dlls/user32/menu.c:4208]inuser32:leaecx,[esp+0x4] 0x7e928894GetMenu+0x4[../wine_git/dlls/user32/menu.c:4208]inuser32:andesp,0xfffffff0 0x7e928897GetMenu+0x7[../wine_git/dlls/user32/menu.c:4208]inuser32:pushdword[ecx-0x4] 0x7e92889aGetMenu+0xa[../wine_git/dlls/user32/menu.c:4208]inuser32:pushebp 0x7e92889bGetMenu+0xb[../wine_git/dlls/user32/menu.c:4208]inuser32:movebp,esp 0x7e92889dGetMenu+0xd[../wine_git/dlls/user32/menu.c:4208]inuser32:pushedi 0x7e92889eGetMenu+0xe[../wine_git/dlls/user32/menu.c:4208]inuser32:pushesi 0x7e92889fGetMenu+0xf[../wine_git/dlls/user32/menu.c:4208]inuser32:pushebx 0x7e9288a0GetMenu+0x10[../wine_git/dlls/user32/menu.c:4208]inuser32:pushecx 0x7e9288a1GetMenu+0x11[../wine_git/dlls/user32/menu.c:4208]inuser32:call0x7e8d5b60__x86.get_pc_thunk.bxinuser32 ...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: 的日志，一般能从中找到问题的相关线索。