由可变参数引起的崩溃
一. 问题描述
前面写过一篇关于打印日志时，日志内容中包含float数据就会崩溃的文章R6002 floating point support not loaded，今天又遇到了打印日志崩溃的情况，定位到这次还是崩溃在StringCchVPrintfA这个函数。这是个系统API的崩溃，遇到系统API的崩溃当然是先排查调用方式是否有问题，然后排查参数数据是否有问题，最后才排查API是否有BUG。
二. 问题分析
这个API很熟悉，通过可变参数格式化字符串的API，函数原型如下：
HRESULT StringCchVPrintf(
_Out_ LPTSTR pszDest,
_In_ size_t cchDest,
_In_ LPCTSTR pszFormat,
_In_ va_list argList
);
确定调用方式没问题之后，分析传入的参数数据是否有问题。
首先怀疑的是pszDest，cchDest参数是否传错了，导致访问了非法的内存区域，仔细核对之后也没有传错，缓冲区够用呢。
argList参数的用法也没啥问题，一直这么使用的。
最后只剩下pszFormat参数了，打印其值如下：
select * from netbar_member where memberName like '滭jj';
看到这个包含乱码的串，心里基本确定问题就出在pszFormat上面了。
打印日志的代码简化后如下：
std::string strName = "sjj";
TraceMsg("select * from netbar_member where memberName like '%%%s%%';", strName.c_str());
一个简单的模糊查询SQL，本想打印如下输出:
select * from netbar_member where memberName like '%sjj%';
对比%%%s%%和滭jj，发现本该存在的前后2个%不见了，sjj中的s也不见了。该日志对比其他日志，特殊之处在于输出了%号，刚好%s又是可以输出地址空间内容的。猜测是输出%时转义引起的，导致%s输出了其他地址空间的内容，运气好能输出乱码，运气不好直接非法访问，程序崩溃。
TraceMsg函数调用伪代码：
TraceMsg(const char* lpFormat, ...);
|
|
\ /
Log_Message(const char* lpFormat, ...);
|
|
\ /
LogToFile(const char* lpFormat, ....);
一条日志经过了3次格式化，虽然性能不高，但问题也不大，不至于乱码和崩溃。
分析函数调用的参数，参数数据如下：
TraceMsg("select * from netbar_member where memberName like '%%%s%%';", "sjj");
|
|
\ /
Log_Message("select * from netbar_member where memberName like '%sjj%';");
|
|
\ /
LogToFile("select * from netbar_member where memberName like '滭jj';");
看到这里终于明白了，TraceMsg传递给Log_Message函数的lpFormat参数为：
select * from netbar_member where memberName like '%sjj%';，这个memberName比较特殊，刚好ssj中的s和%组合成了一个有效的%s。
由于调用Log_Message时未给...可变参数传值，默认会根据lpFormat参数的地址来取一个地址让%s进行输出。具体计算方式参考va_start宏定义:
#define va_start _crt_va_start
#define _crt_va_start(ap,v) ( ap = (va_list)_ADDRESSOF(v) + _INTSIZEOF(v) )
这个地址的内容是未知的，所以就可能出现乱码或崩溃。
三. 解决方案
仔细想想，发现问题其实出在函数Log_Message把select * from netbar_member where memberName like '%sjj%' 作为了StringCchVPrintfA函数的pszFormat参数。
其实程序想要的是原样输出该串，%sjj% 中的%和s只是碰巧在一起了，再次充当了%s的角色。
原样输出还不简单：
Log_Message("%s", "select * from netbar_member where memberName like '%sjj%';");
这样不就OK了么，哈哈。
四. 验证
为了验证这个问题，写了一个小程序，多次嵌套格式化字符串。在DbgView中，可以看到输出的内容不是预期的：select * from netbar_member where memberName like '%sjj%';。
#include <windows.h>
#include <tchar.h>
#include <strsafe.h>
#include <string>
void TraceMsg1(const char *lpFormat, ...);
void TraceMsg2(const char *lpFormat, ...);
void TraceMsg3(const char *lpFormat, ...);
void TraceMsg1(const char *lpFormat, ...) {
if (!lpFormat)
return;
OutputDebugStringA(lpFormat);
OutputDebugStringA("\n");
char pMsgBuffer[512] = { 0 };
va_list arglist;
va_start(arglist, lpFormat);
StringCchVPrintfA(pMsgBuffer, 512, lpFormat, arglist);
va_end(arglist);
TraceMsg2(pMsgBuffer); // 改成这样程序正常：TraceMsg2("%s", pMsgBuffer);
}
void TraceMsg2(const char *lpFormat, ...) {
if (!lpFormat)
return;
OutputDebugStringA(lpFormat);
OutputDebugStringA("\n");
char pMsgBuffer[512] = { 0 };
va_list arglist;
va_start(arglist, lpFormat);
StringCchVPrintfA(pMsgBuffer, 512, lpFormat, arglist);
va_end(arglist);
TraceMsg3(pMsgBuffer); // 改成这样程序正常：TraceMsg3("%s", pMsgBuffer);
}
void TraceMsg3(const char *lpFormat, ...) {
if (!lpFormat)
return;
OutputDebugStringA(lpFormat);
OutputDebugStringA("\n");
char pMsgBuffer[512] = { 0 };
va_list arglist;
va_start(arglist, lpFormat);
StringCchVPrintfA(pMsgBuffer, 512, lpFormat, arglist);
va_end(arglist);
OutputDebugStringA(pMsgBuffer);
}
int _tmain(int argc, _TCHAR* argv[])
{
std::string strName = "sjj";
TraceMsg1("select * from netbar_member where memberName like '%%%s%%';", strName.c_str());
getchar();
return 0;
}
五. 总结
在调用StringCchVPrintf、vsprintf、vswprintf、_vstprintf、printf这样的一系列函数输出固定字符串时，一定不要将固定字符串传入到pszFormat参数，如：
StringCchVPrintf(szBuf, 512, "我想输出单纯的%s，我是错误的格式示范"); // 错误的
这个时候，单纯的%s中的%s已经不在单纯。
正确的做法是：
StringCchVPrintf(szBuf, 512, "%s", "我想输出单纯的%s，我是正确的格式示范");
同理，这样的调用也是错误的、危险的：
std::string strInfo = GetInfo();
printf(strInfo.c_str());
