A customer was looking for assistance in debugging a crash\nin their product.\nThe stack trace looked like this:\n<\/p>\n
\nntdll!_woutput_l+0x356\nntdll!_vsnwprintf_l+0x81\nntdll!_vsnwprintf+0x11\nntdll!RtlStringVPrintfWorkerW+0x3c\nntdll!RtlStringCchPrintfExW+0xa8\nntdll!RtlFormatMessageEx+0x324\nKERNELBASE!BaseDllFormatMessage+0x18e\nKERNELBASE!FormatMessageW+0x37\ncontoso!FormatWithFallbackLanguage+0x8a\ncontoso!RecordFailure+0x56\n<\/pre>\n\nThe string being formatted is\n
There was an error processing the object '%1'.<\/code>,\nand the insertion is a long (but valid) string.\nA unit test which passes a similarly long object name to\nRecordFailure<\/code> does not crash.\n<\/p>\n\nWhat is the problem?\nThere are clues in the stack trace.\n<\/p>\n
\nThe natural place to start is the function that calls\n
FormatMessage<\/code> to see what parameters are\nbeing passed in.\nAnd that’s where you see something strange:\n<\/p>\n\n\/\/ Code in italics is wrong\nBOOL FormatWithFallbackLanguage(\n DWORD dwMessageId, PCTSTR pszBuffer, SIZE_T cchBuffer, ...)\n{\n va_list ap;\n va_start(ap, cchBuffer);\n \/\/ Format from the user's preferred language.\n DWORD cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_preferredLangId,\n pszBuffer, cchBuffer, &ap);\n \/\/ If that didn't work, then use the fallback language.\n if (cchResult == 0) {\n cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_fallbackLangId,\n pszBuffer, cchBuffer, &ap);\n }\n va_end(ap);\n return cchResult != 0;\n}<\/i>\n<\/pre>\n\n(The clue in the stack trace was the word\nfallback<\/i> in the function name,\nwhich suggests that if the formatting attempt fails,\nit’ll try again some other way.)\n<\/p>\n
\nThe purpose of this function is to format the message\nusing the specified message ID,\nfirst looking in the preferred language message table,\nand if that fails, by looking in the fallback language\nmessage table.\n<\/p>\n
\nThe crash occurred on the second call to\n
FormatMessage<\/code>.\nThe customer said,\n“I’m guessing that the parameters being passed to\nFormatMessage<\/code>\nmay be causing this,\nbut I’m not sure how to proceed.\nCan you provide pointers for further investigation?”\n<\/p>\n\nThe bug is that code is reusing the\n
ap<\/code> parameter without resetting it.\nThe documentation for\nFormatMessage<\/code> says\nabout theArguments<\/code> parameter:\n<\/p>\n\nThe state of the va_list<\/b> argument is undefined\nupon return from the function.\nTo use the va_list<\/b> again,\ndestroy the variable argument list pointer using va_end<\/b>\nand reinitialize it with va_start<\/b>.\n<\/p><\/blockquote>\n
\nThe function\n
FormatWithFallbackLanguage<\/code>\ncallsFormatMessage<\/code>, which consumes\nand renders unusable theap<\/code> variable.\nIf the first format attempt fails,\nthe code passes the same (now invalid)\nva_list<\/code> to a second\nFormatMessage<\/code>,\nwhich is now operating on undefined data and is\ntherefore within its rights to crash.\n<\/p>\n\nIn practice, what happens is that the\n
FormatMessage<\/code> function calls\nva_arg<\/code> on the\nva_list<\/code> to extract the insertions,\nand sinceva_list<\/code>s are single-use,\nthat pretty much renders it useless for anything else.\nIf you want to walk the parameters a second time,\nyou need to clean up theva_list<\/code>\nand then reinitialize it.\n<\/p>\n\nBOOL FormatWithFallbackLanguage(\n DWORD dwMessageId, PCTSTR pszBuffer, SIZE_T cchBuffer, ...)\n{\n va_list ap;\n va_start(ap, cchBuffer);\n \/\/ Format from the user's preferred language.\n DWORD cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_preferredLangId,\n pszBuffer, cchBuffer, &ap);\n \/\/ If that didn't work, then use the fallback language.\n if (cchResult == 0) {\n va_end(ap);\n va_start(ap, cchBuffer);<\/font>\n cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_fallbackLangId,\n pszBuffer, cchBuffer, &ap);\n }\n va_end(ap);\n return cchResult != 0;\n}\n<\/pre>\n\nBy ending the old argument list and restarting it,\nthe second call to\n
FormatMessage<\/code> has the correct starting point\nfor extracting the variadic parameters.\nAn alternate (and in my opinion better) way to fix the bug\nwould be\n<\/p>\n\nBOOL FormatWithFallbackLanguage(\n DWORD dwMessageId, PCTSTR pszBuffer, SIZE_T cchBuffer, ...)\n{\n va_list ap;\n \/\/ Format from the user's preferred language.\n va_start(ap, cchBuffer);<\/font>\n DWORD cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_preferredLangId,\n pszBuffer, cchBuffer, &ap);\n va_end(ap);<\/font>\n \/\/ If that didn't work, then use the fallback language.\n if (cchResult == 0) {\n va_start(ap, cchBuffer);<\/font>\n cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_fallbackLangId,\n pszBuffer, cchBuffer, &ap);\n va_end(ap);<\/font>\n }\n return cchResult != 0;\n}\n<\/pre>\n\nThis avoids the “magic switcheroo” and more clearly\nscopes the region of validity of the
ap<\/code>\nvariable to “solely for the purpose of the\nFormatMessage<\/code> function.”\n<\/p>\n\nBonus chatter<\/b>:\nSuppose the
FormatWithFallbackLanguage<\/code>\naccepted ava_list<\/code> parameter directly.\nYou might be tempted to implement it like this:\n<\/p>\n\n\/\/ code in italics is wrong\nBOOL FormatWithFallbackLanguage(\n DWORD dwMessageId, PCTSTR pszBuffer, SIZE_T cchBuffer, va_list ap)\n{\n va_list apOriginal = ap;\n \/\/ Format from the user's preferred language.\n DWORD cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_preferredLangId,\n pszBuffer, cchBuffer, &ap);\n \/\/ If that didn't work, then use the fallback language.\n if (cchResult == 0) {\n cchResult = FormatMessage(\n FORMAT_MESSAGE_FROM_HMODULE,\n g_hinst, dwMessageId, g_fallbackLangId,\n pszBuffer, cchBuffer, &apOriginal);\n }\n return cchResult != 0;\n}<\/i>\n<\/pre>\n\nThis is not legal because a
va_list<\/code> is not\ndirectly copyable.\nSome architectures have rather complicated calling conventions\nthat entail memory allocation in order to enumerate the parameters\npassed to variadic functions,\nand a bitwise copy will not respect those complexities.\nYou have to use theva_copy<\/code> macro to make a copy\nof ava_list<\/code>.\n<\/p>\n\nExercise<\/b>:\nHow did this error elude unit testing?\n<\/p>\n
\nExercise<\/b>:\nWhat else can go wrong in this function?<\/p>\n","protected":false},"excerpt":{"rendered":"
A customer was looking for assistance in debugging a crash in their product. The stack trace looked like this: ntdll!_woutput_l+0x356 ntdll!_vsnwprintf_l+0x81 ntdll!_vsnwprintf+0x11 ntdll!RtlStringVPrintfWorkerW+0x3c ntdll!RtlStringCchPrintfExW+0xa8 ntdll!RtlFormatMessageEx+0x324 KERNELBASE!BaseDllFormatMessage+0x18e KERNELBASE!FormatMessageW+0x37 contoso!FormatWithFallbackLanguage+0x8a contoso!RecordFailure+0x56 The string being formatted is There was an error processing the object ‘%1’., and the insertion is a long (but valid) string. A unit test which […]<\/p>\n","protected":false},"author":1069,"featured_media":111744,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[25],"class_list":["post-2663","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"
A customer was looking for assistance in debugging a crash in their product. The stack trace looked like this: ntdll!_woutput_l+0x356 ntdll!_vsnwprintf_l+0x81 ntdll!_vsnwprintf+0x11 ntdll!RtlStringVPrintfWorkerW+0x3c ntdll!RtlStringCchPrintfExW+0xa8 ntdll!RtlFormatMessageEx+0x324 KERNELBASE!BaseDllFormatMessage+0x18e KERNELBASE!FormatMessageW+0x37 contoso!FormatWithFallbackLanguage+0x8a contoso!RecordFailure+0x56 The string being formatted is There was an error processing the object ‘%1’., and the insertion is a long (but valid) string. A unit test which […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/2663","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/users\/1069"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/comments?post=2663"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/2663\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media\/111744"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media?parent=2663"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=2663"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=2663"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}